I have an issue with a Trixbox Pro 2.6.1 system running asterisk-1.4.22-4. Free PBX Version is 2.5
I have had issues with this box, since almost day one. In attempts to resolve them, I have installed some updates, disabled some features, implemented some workarounds (like a cron job running every 10 minutes that performs /usr/sbin/asterisk -R -x “module reload”
Today I am dealing with an issue that I believe I have seen in the past, but not for at least 6 months. That doesn’t mean that it hasn’t happened in 6 months. But I don’t think it has, because I’ve been keeping a daily watch on filesystem freespace, which directly correlates with this problem.
So here were the initial symptoms reported by the users:
- On the afternoon of June 1, users of the phone system started reporting hearing an echo. I was busy, and didn’t look at the system that day.
- Mid-morning, June 2, users of the phone system called my office and reported that incoming calls were not ringing into their phone system.
Here are the troubleshooting steps I have taken:
- Somwhere between June 1 afternoon, and June 2 morning, I told asterisk to stop accepting new calls, and restart when all current calls had completed (this was done by using the Trixbox Menu: System > System Maint - Then the “Reset Soon” button.
- On June 2 in the morning I received my daily logwatch email and noticed that free space on the filesystem was lower than it typically had been every day for the past several months that I’d been watching this. I logged into the system in the morning and saw that I probably still had several hours before the filesystem would fill up. I also saw that CPU usage didn’t seem to be exceedingly high, as I was expecting. I determined to take care of a few other things, and investigate the issue further in a few hours.
- It wasn’t too long later that day (a few hours), that I received a phone call from the users of the system, reporting that inbound calls were not ringing in. I had not yet returned to the issue, so at that point, I immediately called into their system, and got the message from their TelCo that I always get when the PRI calls are not making it into the phone system. I then logged into the system remotely, and saw that the asterisk daemon was still running. This seemed odd to me, because the asterisk daemon has been dead (not running) probably every single other time that the TelCo has played the message regarding the PRI not being able to complete the calls. At this time, I stopped asterisk by amportal stop. Then started it again with amportal start.
- No problems noticed or reported since then.
- Today I removed the cronjob of: */10 * * * * /usr/sbin/asterisk -R -x "module reload"
○ This was a band-aid for some problem of the past. But I think I am tired of band-aids on this system, and ready for permanent and clear fixes.
Now for the investigation of the root cause of the issue:
- It is pretty clear to me that the issue is surrounding the Asterisk cmd Directory (a.k.a. Directory Command): /var/lib/asterisk/agi-bin/directory
- This is because after whatever happens happens, the following 4 lines fill my asterisk/full log file, until I stop the asterisk daemon, or until the filesystem is full:
[Jun 1 13:30:40] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:44] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:44] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:44] WARNING[13160] file.c: Failed to write frame - There is a post here: http://www.freepbx.org/forum/freepbx/beta-program-issues/loop-when-the-call-is-not-answered-by-the-extension that describes the same symptoms, and says it is caused when a call is not answered, and the extension called does not have VM setup. I am not an expert at reading the asterisk/full log file, but that scenario sounds very likely for me too. I do know that the extension involved in the issue does not have VM setup, and it is very possible and they didn’t answer a call.
- Just FYI, the vast majority of calls that would ring to the extensions having this issue, get there by means of a queue, which these extensions are assigned to. The queue extension number is 698.
Here’s my plan from this point:
- Post excerpts of my asterisk/full log files for people who know more than me to analyze.
- If we don’t come up with a solution within approximately 1 week’s time, then I’ll probably resort to just disabling the asterisk directory app, which seemed to fix the issue for another user in the above thread (I know, another band-aid).
I greatly appreciate any input and expertise that others can lend. And if you can’t, thanks for at least taking the time to read my post.
Log file excerpts are posted below.
Thanks,
Doug
Here’s an excerpt from asterisk/full, right when the problem started, showing only the log lines with the PID that seems to be involved in the issue:
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jun 1 13:29:59] VERBOSE[13160] logger.c: recordingcheck|20100601-132958|1275420598.110516: Inbound recording not enabled
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – AGI Script recordingcheck completed, returning 0
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: AGI
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-record-enable:5] MacroExit(“Local/605@from-internal-5500,2”, “”) in new stack
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: Macro
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:9] Macro(“Local/605@from-internal-5500,2”, “dial||trM(auto-blkvm)|605”) in new stack
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-dial:1] GotoIf(“Local/605@from-internal-5500,2”, “0?dial”) in new stack
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: GotoIf
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-dial:2] SetMusicOnHold(“Local/605@from-internal-5500,2”, “default”) in new stack
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: SetMusicOnHold
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-dial:3] AGI(“Local/605@from-internal-5500,2”, “dialparties.agi”) in new stack
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jun 1 13:29:59] VERBOSE[13160] logger.c: dialparties.agi: Starting New Dialparties.agi
[Jun 1 13:29:59] VERBOSE[13160] logger.c: dialparties.agi: Caller ID name is ‘5057010275’ number is ‘5057010275’
[Jun 1 13:29:59] VERBOSE[13160] logger.c: dialparties.agi: Methodology of ring is ‘none’
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Added extension 605 to extension map
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Extension 605 cf is disabled
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Extension 605 do not disturb is disabled
[Jun 1 13:29:59] VERBOSE[13160] logger.c: dialparties.agi: Extension 605 has ExtensionState: 0
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Checking CW and CFB status for extension 605
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: dbset CALLTRACE/605 to 5057010275
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Filtered ARG3: 605
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – AGI Script dialparties.agi completed, returning 0
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: AGI
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-dial:7] Dial(“Local/605@from-internal-5500,2”, “SIP/605||trM(auto-blkvm)”) in new stack
[Jun 1 13:29:59] WARNING[13160] rtp.c: Unable to set TOS to 184
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Called 605
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – SIP/605-1513f5b0 is ringing
[Jun 1 13:30:05] VERBOSE[13160] logger.c: – SIP/605-1513f5b0 answered Local/605@from-internal-5500,2
[Jun 1 13:30:05] VERBOSE[13160] logger.c: – Executing [s@macro-auto-blkvm:1] Set(“SIP/605-1513f5b0”, “__MACRO_RESULT=”) in new stack
[Jun 1 13:30:05] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:30:05] VERBOSE[13160] logger.c: – Executing [s@macro-auto-blkvm:2] DBdel(“SIP/605-1513f5b0”, “BLKVM/698/Zap/1-1”) in new stack
[Jun 1 13:30:05] VERBOSE[13160] logger.c: – DBdel: family=BLKVM, key=698/Zap/1-1
[Jun 1 13:30:05] DEBUG[13160] app_macro.c: Executed application: dbDel
[Jun 1 13:30:05] DEBUG[13160] app_dial.c: Macro exited with status 0
[Jun 1 13:30:19] VERBOSE[13160] logger.c: – Started music on hold, class ‘default’, on Local/605@from-internal-5500,2
[Jun 1 13:30:19] VERBOSE[13160] logger.c: – <SIP/605-1513f5b0> Playing ‘pbx-transfer’ (language ‘en’)
[Jun 1 13:30:20] VERBOSE[13160] logger.c: – Stopped music on hold on Local/605@from-internal-5500,2
[Jun 1 13:30:20] DEBUG[13160] app_macro.c: Executed application: Dial
[Jun 1 13:30:20] VERBOSE[13160] logger.c: == Channel ‘Local/605@from-internal-5500,2’ jumping out of macro ‘dial’
[Jun 1 13:30:20] DEBUG[13160] app_macro.c: Executed application: Macro
[Jun 1 13:30:20] VERBOSE[13160] logger.c: == Channel ‘Local/605@from-internal-5500,2’ jumping out of macro ‘exten-vm’
[Jun 1 13:30:20] VERBOSE[13160] logger.c: – Executing [#@from-internal-xfer:1] Answer(“Local/605@from-internal-5500,2”, “”) in new stack
[Jun 1 13:30:20] VERBOSE[13160] logger.c: – Executing [#@from-internal-xfer:2] Wait(“Local/605@from-internal-5500,2”, “1”) in new stack
[Jun 1 13:30:21] VERBOSE[13160] logger.c: – Executing [#@from-internal-xfer:3] AGI(“Local/605@from-internal-5500,2”, “directory|default|from-did-direct|l”) in new stack
[Jun 1 13:30:21] VERBOSE[13160] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/directory
[Jun 1 13:30:21] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:38] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:40] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:44] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:44] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:44] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:44] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:45] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
Here’s an except from the same period that is the complete asterisk/full log (not filtered by the single PID). As you can see, the “module reload” occurred right at 13:30:01, as it was scheduled to run every 10 minutes. I don’t know whether this would be related to the problem :
[Jun 1 13:29:53] VERBOSE[13156] logger.c: == Spawn extension (macro-hangupcall, s, 11) exited non-zero on ‘Local/606@from-internal-402e,2’
[Jun 1 13:29:53] VERBOSE[32156] logger.c: Extension Changed 606[ext-local] new state Idle for Notify User 611
[Jun 1 13:29:53] VERBOSE[32156] logger.c: Extension Changed 606[ext-local] new state Idle for Notify User 610
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [605@from-internal:1] Macro(“Local/605@from-internal-5500,2”, “exten-vm|novm|605”) in new stack
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:1] Macro(“Local/605@from-internal-5500,2”, “user-callerid”) in new stack
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-user-callerid:1] Set(“Local/605@from-internal-5500,2”, “AMPUSER=5057010275”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-user-callerid:2] GotoIf(“Local/605@from-internal-5500,2”, “1?report”) in new stack
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Goto (macro-user-callerid,s,11)
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: GotoIf
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-user-callerid:11] GotoIf(“Local/605@from-internal-5500,2”, “0?continue”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: GotoIf
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-user-callerid:12] Set(“Local/605@from-internal-5500,2”, “__TTL=63”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-user-callerid:13] GotoIf(“Local/605@from-internal-5500,2”, “1?continue”) in new stack
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Goto (macro-user-callerid,s,20)
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: GotoIf
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-user-callerid:20] NoOp(“Local/605@from-internal-5500,2”, “Using CallerID “5057010275” <5057010275>”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Noop
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Macro
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:2] Set(“Local/605@from-internal-5500,2”, “RingGroupMethod=none”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:3] Set(“Local/605@from-internal-5500,2”, “VMBOX=novm”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:4] Set(“Local/605@from-internal-5500,2”, “EXTTOCALL=605”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:29:58] DEBUG[13160] func_db.c: DB: CFU/605 not found in database.
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:5] Set(“Local/605@from-internal-5500,2”, “CFUEXT=”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:29:58] DEBUG[13160] func_db.c: DB: CFB/605 not found in database.
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:6] Set(“Local/605@from-internal-5500,2”, “CFBEXT=”) in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:7] Set(“Local/605@from-internal-5500,2”, “RT=”"") in new stack
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:8] Macro(“Local/605@from-internal-5500,2”, “record-enable|605|IN”) in new stack
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-record-enable:1] GotoIf(“Local/605@from-internal-5500,2”, “1?check”) in new stack
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Goto (macro-record-enable,s,4)
[Jun 1 13:29:58] DEBUG[13160] app_macro.c: Executed application: GotoIf
[Jun 1 13:29:58] VERBOSE[13160] logger.c: – Executing [s@macro-record-enable:4] AGI(“Local/605@from-internal-5500,2”, “recordingcheck|20100601-132958|1275420598.110516”) in new stack
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
[Jun 1 13:29:59] VERBOSE[13160] logger.c: recordingcheck|20100601-132958|1275420598.110516: Inbound recording not enabled
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – AGI Script recordingcheck completed, returning 0
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: AGI
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-record-enable:5] MacroExit(“Local/605@from-internal-5500,2”, “”) in new stack
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: Macro
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-exten-vm:9] Macro(“Local/605@from-internal-5500,2”, “dial||trM(auto-blkvm)|605”) in new stack
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-dial:1] GotoIf(“Local/605@from-internal-5500,2”, “0?dial”) in new stack
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: GotoIf
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-dial:2] SetMusicOnHold(“Local/605@from-internal-5500,2”, “default”) in new stack
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: SetMusicOnHold
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-dial:3] AGI(“Local/605@from-internal-5500,2”, “dialparties.agi”) in new stack
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
[Jun 1 13:29:59] VERBOSE[13160] logger.c: dialparties.agi: Starting New Dialparties.agi
[Jun 1 13:29:59] VERBOSE[13163] logger.c: == Parsing ‘/etc/asterisk/manager.conf’: [Jun 1 13:29:59] VERBOSE[13163] logger.c: Found
[Jun 1 13:29:59] VERBOSE[13163] logger.c: == Parsing ‘/etc/asterisk/manager_additional.conf’: [Jun 1 13:29:59] VERBOSE[13163] logger.c: Found
[Jun 1 13:29:59] VERBOSE[13163] logger.c: == Parsing ‘/etc/asterisk/manager_custom.conf’: [Jun 1 13:29:59] VERBOSE[13163] logger.c: Found
[Jun 1 13:29:59] VERBOSE[13163] logger.c: == Manager ‘admin’ logged on from 127.0.0.1
[Jun 1 13:29:59] VERBOSE[13160] logger.c: dialparties.agi: Caller ID name is ‘5057010275’ number is ‘5057010275’
[Jun 1 13:29:59] VERBOSE[13160] logger.c: dialparties.agi: Methodology of ring is ‘none’
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Added extension 605 to extension map
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Extension 605 cf is disabled
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Extension 605 do not disturb is disabled
[Jun 1 13:29:59] VERBOSE[13160] logger.c: dialparties.agi: Extension 605 has ExtensionState: 0
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Checking CW and CFB status for extension 605
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: dbset CALLTRACE/605 to 5057010275
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – dialparties.agi: Filtered ARG3: 605
[Jun 1 13:29:59] VERBOSE[13163] logger.c: == Manager ‘admin’ logged off from 127.0.0.1
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – AGI Script dialparties.agi completed, returning 0
[Jun 1 13:29:59] DEBUG[13160] app_macro.c: Executed application: AGI
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Executing [s@macro-dial:7] Dial(“Local/605@from-internal-5500,2”, “SIP/605||trM(auto-blkvm)”) in new stack
[Jun 1 13:29:59] WARNING[13160] rtp.c: Unable to set TOS to 184
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – Called 605
[Jun 1 13:29:59] VERBOSE[32156] logger.c: Extension Changed 605[ext-local] new state Ringing for Notify User 611
[Jun 1 13:29:59] VERBOSE[32156] logger.c: Extension Changed 605[ext-local] new state Ringing for Notify User 610
[Jun 1 13:29:59] VERBOSE[13147] logger.c: – Local/605@from-internal-5500,1 is ringing
[Jun 1 13:29:59] VERBOSE[13160] logger.c: – SIP/605-1513f5b0 is ringing
[Jun 1 13:30:01] VERBOSE[32154] logger.c: – Remote UNIX connection
…
3516 lines of logging relating to the “module reload”. All of which had a timestamp of [Jun 1 13:30:01]
…
[Jun 1 13:30:02] VERBOSE[13168] logger.c: – Remote UNIX connection disconnected
[Jun 1 13:30:05] VERBOSE[13160] logger.c: – SIP/605-1513f5b0 answered Local/605@from-internal-5500,2
[Jun 1 13:30:05] VERBOSE[13160] logger.c: – Executing [s@macro-auto-blkvm:1] Set(“SIP/605-1513f5b0”, “__MACRO_RESULT=”) in new stack
[Jun 1 13:30:05] DEBUG[13160] app_macro.c: Executed application: Set
[Jun 1 13:30:05] VERBOSE[13160] logger.c: – Executing [s@macro-auto-blkvm:2] DBdel(“SIP/605-1513f5b0”, “BLKVM/698/Zap/1-1”) in new stack
[Jun 1 13:30:05] VERBOSE[13160] logger.c: – DBdel: family=BLKVM, key=698/Zap/1-1
[Jun 1 13:30:05] VERBOSE[32156] logger.c: Extension Changed 605[ext-local] new state InUse for Notify User 611
[Jun 1 13:30:05] VERBOSE[32156] logger.c: Extension Changed 605[ext-local] new state InUse for Notify User 610
[Jun 1 13:30:05] DEBUG[13160] app_macro.c: Executed application: dbDel
[Jun 1 13:30:05] DEBUG[13160] app_dial.c: Macro exited with status 0
[Jun 1 13:30:05] DEBUG[13147] app_queue.c: Dunno what to do with control type -1
[Jun 1 13:30:05] VERBOSE[13147] logger.c: – Local/605@from-internal-5500,1 answered Zap/1-1
[Jun 1 13:30:05] DEBUG[13147] chan_zap.c: Set option TONE VERIFY, mode: MUTECONF(1) on Zap/1-1
[Jun 1 13:30:05] VERBOSE[13147] logger.c: – Stopped music on hold on Zap/1-1
[Jun 1 13:30:05] WARNING[13147] app_queue.c: The device state of this queue member, Local/605@from-internal/n, is still ‘Not in Use’ when it probably should not be! Please check UPGRADE.txt for correct configuration settings.
[Jun 1 13:30:19] VERBOSE[13160] logger.c: – Started music on hold, class ‘default’, on Local/605@from-internal-5500,2
[Jun 1 13:30:19] VERBOSE[13160] logger.c: – <SIP/605-1513f5b0> Playing ‘pbx-transfer’ (language ‘en’)
[Jun 1 13:30:20] VERBOSE[13160] logger.c: – Stopped music on hold on Local/605@from-internal-5500,2
[Jun 1 13:30:20] DEBUG[13160] app_macro.c: Executed application: Dial
[Jun 1 13:30:20] VERBOSE[13160] logger.c: == Channel ‘Local/605@from-internal-5500,2’ jumping out of macro ‘dial’
[Jun 1 13:30:20] DEBUG[13160] app_macro.c: Executed application: Macro
[Jun 1 13:30:20] VERBOSE[13160] logger.c: == Channel ‘Local/605@from-internal-5500,2’ jumping out of macro ‘exten-vm’
[Jun 1 13:30:20] VERBOSE[13160] logger.c: – Executing [#@from-internal-xfer:1] Answer(“Local/605@from-internal-5500,2”, “”) in new stack
[Jun 1 13:30:20] VERBOSE[13160] logger.c: – Executing [#@from-internal-xfer:2] Wait(“Local/605@from-internal-5500,2”, “1”) in new stack
[Jun 1 13:30:20] VERBOSE[32156] logger.c: Extension Changed 605[ext-local] new state Idle for Notify User 611
[Jun 1 13:30:20] VERBOSE[32156] logger.c: Extension Changed 605[ext-local] new state Idle for Notify User 610
[Jun 1 13:30:21] VERBOSE[13160] logger.c: – Executing [#@from-internal-xfer:3] AGI(“Local/605@from-internal-5500,2”, “directory|default|from-did-direct|l”) in new stack
[Jun 1 13:30:21] VERBOSE[13160] logger.c: – Launched AGI Script /var/lib/asterisk/agi-bin/directory
[Jun 1 13:30:21] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:28] WARNING[32158] rtp.c: Unable to set TOS to 184
[Jun 1 13:30:28] NOTICE[32158] chan_sip.c: Call from ‘605’ to extension ‘172.18.0.50’ rejected because extension not found.
[Jun 1 13:30:38] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:40] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:44] VERBOSE[32162] logger.c: – Channel 0/1, span 1 got hangup request, cause 16
[Jun 1 13:30:44] VERBOSE[13147] logger.c: == Spawn extension (ext-queues, 698, 12) exited non-zero on ‘Zap/1-1’
[Jun 1 13:30:44] DEBUG[13147] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/1-1
[Jun 1 13:30:44] DEBUG[13147] chan_zap.c: Not yet hungup… Calling hangup once with icause, and clearing call
[Jun 1 13:30:44] DEBUG[13147] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
[Jun 1 13:30:44] VERBOSE[13147] logger.c: – Hungup ‘Zap/1-1’
[Jun 1 13:30:44] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:44] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:44] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:44] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:45] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:45] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:45] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:45] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:45] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:45] VERBOSE[13160] logger.c: – <Local/605@from-internal-5500,2> Playing ‘dir-intro’ (language ‘en’)
[Jun 1 13:30:45] VERBOSE[13160] logger.c: – Playing ‘dir-nomatch’ (escape_digits=) (sample_offset 0)
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame
[Jun 1 13:30:45] WARNING[13160] file.c: Failed to write frame