[asterisk-bugs] [JIRA] (ASTERISK-20486) MeetMe Unable to write frame to channel after SIP channel hangs up.
Johan Wilfer (JIRA)
noreply at issues.asterisk.org
Sun Nov 11 11:48:21 CST 2012
[ https://issues.asterisk.org/jira/browse/ASTERISK-20486?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=199550#comment-199550 ]
Johan Wilfer commented on ASTERISK-20486:
-----------------------------------------
Okay, I have now tested the new patch. I run the setup described in the description in ASTERISK-19949.
tested asterisk-1.8.17.0 (unpatched): CLI spawns WARNINGS in a loop
tested asterisk-1.8.17.0 (patched meetme_hangup_patch_ASTERISK-20486_v3.diff): No warnings.
tested asterisk-1.8.19.0-rc1 (unpatched): CLI spawns WARNINGS in a loop
tested asterisk-1.8.19.0-rc1 (patched meetme_hangup_patch_ASTERISK-20486_v3.diff): No warnings.
Also, this patch has a lot of similarity with https://issues.asterisk.org/jira/secure/attachment/43067/meetme-hangup-trunk-360459.patch which I've been using for about five months now and it has worked perfectly. Good work in trackning down why this happened! Thank you Jonathan!
> MeetMe Unable to write frame to channel after SIP channel hangs up.
> -------------------------------------------------------------------
>
> Key: ASTERISK-20486
> URL: https://issues.asterisk.org/jira/browse/ASTERISK-20486
> Project: Asterisk
> Issue Type: Bug
> Security Level: None
> Components: Applications/app_meetme, Channels/chan_sip/General
> Affects Versions: 1.8.16.0
> Environment: I have two asterisk boxes. One is running asterisk 1.4.43. It is acting like a test carrier. The other box is running 1.8.16.0 and is placing calls to the test carrier and routing them to MeetMe conferences.
> Reporter: Michael Cargile
> Attachments: asterisk-20486-ref-leak.diff, meetme_hangup_patch_ASTERISK-20486.diff, meetme_hangup_patch_ASTERISK-20486_v3.diff, refs.gz, refs-with-patch, refs-with-patch.gz, timer_patch_ASTERISK-20486.diff
>
>
> Basically it looks like in some instances MeetMe is still trying to pass frames to a channel that should have hung up. If you look the caller id name which we use as a Unique ID matches the caller id name in the BYE event before this error. It looks like it is generating about 50 errors per second for one of these calls. I am not sure if this is a SIP issue, or a MeetMe issue. I think this might be related to this issue:
> ASTERISK-19594
> but that one has already been closed.
> Output from AGI script called before getting into the MeetMe conference to show the channel as well as the calleridname (which we use to keep track of the call):
> {noformat}
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi|AGI Environment Dump:
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- accountcode =
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- arg_1 = NORMAL-----LB
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- callerid = 8633939330
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- calleridname = V9281514180000238212
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- callingani2 = 0
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- callingpres = 0
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- callingtns = 0
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- callington = 0
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- channel = SIP/testcarrier-00017f4b
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- context = default
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- dnid = unknown
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- enhanced = 0.0
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- extension = 8368
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- language = en
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- priority = 3
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- rdnis = unknown
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- request = agi-VDAD_ALL_outbound.agi
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- threadid = -1268466832
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- type = SIP
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- uniqueid = 1348859661.314636
> 2012-09-28 15:14:33|agi-VDAD_ALL_outbound.agi| -- version = 1.8.16.0
> {noformat}
> Asterisk CLI output with SIP debugging enabled:
> {noformat}
> [Sep 28 15:14:35] -- Executing [8600058 at default:1] MeetMe("SIP/testcarrier-00017f4b", "8600058,F") in new stack
> [Sep 28 15:14:35] == Parsing '/etc/asterisk/meetme.conf': [Sep 28 15:14:35] == Found
> [Sep 28 15:14:35] == Parsing '/etc/asterisk/meetme-vicidial.conf': [Sep 28 15:14:35] == Found
> [Sep 28 15:14:35] -- Created MeetMe conference 1022 for conference '8600058'
> [Sep 28 15:14:35] -- <SIP/testcarrier-00017f4b> Playing 'conf-onlyperson.gsm' (language 'en')
> ...
> [Sep 28 15:14:38]
> <--- Transmitting (NAT) to 192.168.198.14:5060 --->
> SIP/2.0 200 OK
> Via: SIP/2.0/UDP 192.168.198.14:5060;branch=z9hG4bK099f4e9c;received=192.168.198.14;rport=5060
> From: <sip:9999024387 at 192.168.198.14>;tag=as657a2bf3
> To: "V9281514180000238212" <sip:8633939330 at 192.168.198.15>;tag=as4bc64123
> Call-ID: 05a3c6f264fb72905243ca216bb0eba2 at 192.168.198.15:5060
> CSeq: 102 BYE
> Server: Asterisk PBX 1.8.16.0
> Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH
> Supported: replaces, timer
> Content-Length: 0
> ...
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:39] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> ...
> [Sep 28 15:14:45] WARNING[3688]: app_meetme.c:3678 conf_run: Unable to write frame to channel SIP/testcarrier-00017f4b
> [Sep 28 15:14:45] WARNING[8004]: chan_sip.c:3918 __sip_autodestruct: Autodestruct on dialog '05a3c6f264fb72905243ca216bb0eba2 at 192.168.198.15:5060' with owner in place (Method: BYE). Rescheduling destruc
> tion for 10000 ms
> [Sep 28 15:14:45] -- Hungup 'DAHDI/pseudo-753634465'
> [Sep 28 15:14:45] == Spawn extension (default, 8600058, 1) exited non-zero on 'SIP/testcarrier-00017f4b'
> [Sep 28 15:14:45] -- Executing [h at default:1] AGI("SIP/testcarrier-00017f4b", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----111---------------") in new stack
> {noformat}
> 1.8 extension.conf
> {noformat}
> ; global varibale for carrier
> TESTSIPTRUNK = SIP/testcarrier
> ; Outbound dial to test carrier
> exten => _91999NXXXXXX,1,AGI(agi://127.0.0.1:4577/call_log)
> exten => _91999NXXXXXX,2,Dial(${TESTSIPTRUNK}/${EXTEN:2},,To)
> exten => _91999NXXXXXX,3,Hangup
> ; agent connection
> exten => _999999999999,1,AGI(agi://127.0.0.1:4577/call_log)
> exten => _999999999999,2,Dial(${TESTSIPTRUNK}/${EXTEN},,To)
> exten => _999999999999,3,Hangup
> ; routing extension
> exten => 8368,1,Playback(sip-silence)
> exten => 8368,n,AGI(agi://127.0.0.1:4577/call_log)
> exten => 8368,n,AGI(agi-VDAD_ALL_outbound.agi,NORMAL-----LB)
> exten => 8368,n,AGI(agi-VDAD_ALL_outbound.agi,NORMAL-----LB)
> exten => 8368,n,Hangup()
> ; meetme conference extensions
> exten => _86000[5-9]X,1,Meetme(${EXTEN},F)
> exten => _86000[5-9]X,n,Hangup()
> exten => _8600[1-2]XX,1,Meetme(${EXTEN},F)
> exten => _8600[1-2]XX,n,Hangup()
> {noformat}
> 1.4 extension.conf
> {noformat}
> ; PERFORMANCE TESTING
> exten => _999XXXXXX1,1,Answer
> exten => _999XXXXXX1,2,Wait(2)
> exten => _999XXXXXX1,3,Playback(vicidial-welcome)
> exten => _999XXXXXX1,4,Hangup
> exten => _999XX11112,1,Wait(2)
> exten => _999XX11112,2,Answer
> exten => _999XX11112,3,Playback(ss-noservice)
> exten => _999XX11112,4,Playback(vm-goodbye)
> exten => _999XX11112,5,Hangup
> exten => _999XX18112,1,Wait(2)
> exten => _999XX18112,2,Answer
> exten => _999XX18112,3,Playback(vtiger-fax)
> exten => _999XX18112,4,Playback(vtiger-fax)
> exten => _999XX18112,5,Hangup
> exten => _999XX19112,1,Wait(2)
> exten => _999XX19112,2,Answer
> exten => _999XX19112,3,Playback(vtiger-email)
> exten => _999XX19112,4,Playback(vtiger-email)
> exten => _999XX19112,5,Hangup
> exten => _999XXXX112,1,Wait(5)
> exten => _999XXXX112,2,Answer
> exten => _999XXXX112,3,Playback(demo-instruct)
> exten => _999XXXX112,4,Playback(demo-instruct)
> exten => _999XXXX112,5,Hangup
> exten => _999XXXXXX2,1,Wait(8)
> exten => _999XXXXXX2,2,Answer
> exten => _999XXXXXX2,3,Playback(demo-instruct)
> exten => _999XXXXXX2,4,Hangup
> exten => _999XXXXXX3,1,Set(PRI_CAUSE=1)
> exten => _999XXXXXX3,2,Hangup
> exten => _999XXXXXX4,1,Set(PRI_CAUSE=27)
> exten => _999XXXXXX4,2,Hangup
> exten => _999XXXXXX5,1,Wait(60)
> exten => _999XXXXXX5,2,Hangup
> exten => _999XXXXXX6,1,Wait(10)
> exten => _999XXXXXX6,2,Answer
> exten => _999XXXXXX6,3,Playback(demo-instruct)
> exten => _999XXXXXX6,4,Hangup
> exten => _999XXXXXX7,1,Wait(12)
> exten => _999XXXXXX7,2,Answer
> exten => _999XXXXXX7,3,Playback(demo-enterkeywords)
> exten => _999XXXXXX7,4,Hangup
> exten => _999XXXXXX8,1,Set(PRI_CAUSE=17)
> exten => _999XXXXXX8,2,Hangup
> exten => _999XXXXXX9,1,Wait(6)
> exten => _999XXXXXX9,2,Answer
> exten => _999XXXXXX9,3,Playback(demo-abouttotry)
> exten => _999XXXXXX9,4,Hangup
> exten => _999XXXXXX0,1,Wait(5)
> exten => _999XXXXXX0,2,Answer
> exten => _999XXXXXX0,3,Playback(vm-goodbye)
> exten => _999XXXXXX0,4,Hangup
> ; agent playback
> exten => 99999999999,1,Answer
> exten => 99999999999,2,Playback(conf)
> exten => 99999999999,3,Playback(conf)
> exten => 99999999999,4,Playback(conf)
> exten => 99999999999,5,Playback(conf)
> exten => 99999999999,6,Playback(conf)
> exten => 99999999999,7,Playback(conf)
> exten => 99999999999,8,Playback(conf)
> exten => 99999999999,9,Playback(conf)
> exten => 99999999999,10,Playback(conf)
> exten => 99999999999,11,Playback(conf)
> exten => 99999999999,12,Playback(conf)
> exten => 99999999999,13,Playback(conf)
> exten => 99999999999,14,Hangup
> {noformat}
> 1.8 sip.conf
> {noformat}
> [testcarrier]
> type=peer
> context=trunkinbound
> usecallerid=yes
> trustrpid=yes
> sendrpid=yes
> host=192.168.198.14
> qualify=yes
> insecure=port,invite
> disallow=all
> allow=ulaw
> dtmfmode=RFC2833
> {noformat}
> 1.4 sip.conf
> {noformat}
> [testcarrier]
> type=peer
> context=trunkinbound
> usecallerid=yes
> trustrpid=yes
> sendrpid=yes
> host=192.168.198.15
> qualify=yes
> insecure=port,invite
> disallow=all
> allow=ulaw
> dtmfmode=RFC2833
> {noformat}
> System in question is being used to port the Vicidial Call Center Suite over to Asterisk 1.8. It is currently operating in test mode.
> In test mode agents are simulated by originating a call with a Local channel. The local channel is pointed at the 999999999999 extension which routes through to the 1.4 test carrier. On the test carrier the call ends up in an extension that plays classical music for 12 hours. The extension for the originated call is one of the meetme conferences. This calls stays there throughout the test.
> Outbound calls are originated as a Local channel as well. The Local channel is pointed at the 91999NXXXXXX extension depending on the "phone number" being dialed. This routed through to the 1.4 test carrier where depending on what "phone number" was dialed different things happen. The extension for the originated call is the 8368. This extension first plays sip-silence which is a 40ms sound file of nothing. This gives the Local channel a chance to optimize out as this is only done during processing of audio frames and Vicidial was written at a time when Asterisk had issues routing Local channels so refuses to do so. Next the call is logged in Vicidial with the call_log AGI and then goes into the outbound routing AGI. There it finds an agent that is available to take the call and then transfers the call to the MeetMe conference that is associated with that agent.
> As stated this error pops up occasionally. With five 'agents' logged in and about 15 'calls' being attempted at any given time it tends to take about 15 to 30 minutes before this pops up. If I up the number of 'agent' and 'calls' it can take as little as five minutes.
> CLI output after applying the timer and meetme patch passed through a grep filter to get just the warnings:
> {noformat}
> dev-dial2:~ # asterisk -r | grep WARN
> [Nov 7 12:30:17] WARNING[7727]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-000000df
> [Nov 7 12:34:32] WARNING[11859]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-00000251
> [Nov 7 12:37:41] WARNING[14182]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-00000312
> [Nov 7 12:46:45] WARNING[23962]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-00000631
> [Nov 7 12:48:51] WARNING[24887]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-00000681
> {noformat}
> Full CLI output after timer and meetme patches applied:
> {noformat}
> [Nov 7 12:30:15] -- <SIP/testcarrier-000000ee>AGI Script agi-VDAD_ALL_outbound.agi completed, returning 0
> [Nov 7 12:30:15] -- Executing [192*168*198*015*8600060 at default:1] Goto("SIP/testcarrier-000000ee", "default,8600060,1") in new stack
> [Nov 7 12:30:15] -- Goto (default,8600060,1)
> [Nov 7 12:30:15] -- Executing [8600060 at default:1] MeetMe("SIP/testcarrier-000000ee", "8600060,F") in new stack
> [Nov 7 12:30:15] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:30:15] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:30:15] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:30:16] -- <Local/919999003312 at default-000000ee;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----8-----0 completed, returning 0
> [Nov 7 12:30:16] == Spawn extension (default, 919999003312, 2) exited non-zero on 'Local/919999003312 at default-000000ee;2'
> [Nov 7 12:30:17] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:30:17] WARNING[7727]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-000000df
> [Nov 7 12:30:17] == Spawn extension (default, 8600059, 1) exited non-zero on 'SIP/testcarrier-000000df'
> [Nov 7 12:30:17] -- Executing [h at default:1] AGI("SIP/testcarrier-000000df", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:30:18] -- <SIP/testcarrier-000000df>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
> [Nov 7 12:30:19] -- SIP/testcarrier-000000fc answered Local/919999000612 at default-000000fc;2
> [Nov 7 12:30:19] > Channel Local/919999000612 at default-000000fc;1 was answered.
> [Nov 7 12:30:19] -- Executing [8368 at default:1] Playback("Local/919999000612 at default-000000fc;1", "sip-silence") in new stack
> [Nov 7 12:30:19] -- <Local/919999000612 at default-000000fc;1> Playing 'sip-silence.gsm' (language 'en')
> [Nov 7 12:30:19] -- Executing [8368 at default:2] AGI("Local/919999000612 at default-000000fc;1", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:30:19] -- Executing [h at default:1] AGI("Local/919999000612 at default-000000fc;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----8-----0") in new stack
> [Nov 7 12:30:19] -- <SIP/testcarrier-000000fc>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:30:19] -- Executing [8368 at default:3] AGI("SIP/testcarrier-000000fc", "agi-VDAD_ALL_outbound.agi,NORMAL-----LB") in new stack
> [Nov 7 12:30:19] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi
> [Nov 7 12:30:19] -- SIP/testcarrier-000000ef answered Local/919999054327 at default-000000ef;2
> [Nov 7 12:30:19] > Channel Local/919999054327 at default-000000ef;1 was answered.
> [Nov 7 12:30:19] -- Executing [8368 at default:1] Playback("Local/919999054327 at default-000000ef;1", "sip-silence") in new stack
> [Nov 7 12:30:19] -- <Local/919999054327 at default-000000ef;1> Playing 'sip-silence.gsm' (language 'en')
> [Nov 7 12:30:19] -- Executing [8368 at default:2] AGI("Local/919999054327 at default-000000ef;1", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:30:19] -- Executing [h at default:1] AGI("Local/919999054327 at default-000000ef;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----12-----0") in new stack
> [Nov 7 12:30:19] -- <SIP/testcarrier-000000ef>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:30:19] -- Executing [8368 at default:3] AGI("SIP/testcarrier-000000ef", "agi-VDAD_ALL_outbound.agi,NORMAL-----LB") in new stack
> ...
> [Nov 7 12:34:32] -- Executing [919999056546 at default:1] AGI("Local/919999056546 at default-00000261;2", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:34:32] -- <Local/919999056546 at default-00000261;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:34:32] -- Executing [919999056546 at default:2] Dial("Local/919999056546 at default-00000261;2", "SIP/testcarrier/9999056546,,To") in new stack
> [Nov 7 12:34:32] == Using SIP RTP CoS mark 5
> [Nov 7 12:34:32] -- Called SIP/testcarrier/9999056546
> [Nov 7 12:34:32] == Manager 'sendcron' logged on from 127.0.0.1
> [Nov 7 12:34:32] -- Executing [919999025898 at default:1] AGI("Local/919999025898 at default-00000262;2", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:34:32] -- <Local/919999025898 at default-00000262;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:34:32] -- Executing [919999025898 at default:2] Dial("Local/919999025898 at default-00000262;2", "SIP/testcarrier/9999025898,,To") in new stack
> [Nov 7 12:34:32] == Using SIP RTP CoS mark 5
> [Nov 7 12:34:32] -- Called SIP/testcarrier/9999025898
> [Nov 7 12:34:32] -- Got SIP response 603 "Declined" back from 192.168.198.14:5060
> [Nov 7 12:34:32] -- SIP/testcarrier-00000262 is busy
> [Nov 7 12:34:32] == Everyone is busy/congested at this time (1:1/0/0)
> [Nov 7 12:34:32] -- Executing [919999025898 at default:3] Hangup("Local/919999025898 at default-00000262;2", "") in new stack
> [Nov 7 12:34:32] == Spawn extension (default, 919999025898, 3) exited non-zero on 'Local/919999025898 at default-00000262;2'
> [Nov 7 12:34:32] -- Executing [h at default:1] AGI("Local/919999025898 at default-00000262;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY----------") in new stack
> [Nov 7 12:34:32] -- <Local/919999058508 at default-00000257;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:34:32] -- <Local/919999036624 at default-00000258;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:34:32] == Spawn extension (default, 8600069, 1) exited non-zero on 'SIP/testcarrier-0000024c'
> [Nov 7 12:34:32] -- Executing [h at default:1] AGI("SIP/testcarrier-0000024c", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:34:32] WARNING[11859]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-00000251
> [Nov 7 12:34:32] == Spawn extension (default, 8600070, 1) exited non-zero on 'SIP/testcarrier-00000251'
> [Nov 7 12:34:32] -- Executing [h at default:1] AGI("SIP/testcarrier-00000251", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:34:33] -- <Local/919999049964 at default-0000025c;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:34:33] == Spawn extension (default, 8600054, 1) exited non-zero on 'SIP/testcarrier-00000202'
> [Nov 7 12:34:33] -- Executing [h at default:1] AGI("SIP/testcarrier-00000202", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:34:33] -- <Local/919999025898 at default-00000262;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:34:33] -- <SIP/testcarrier-0000024c>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
> [Nov 7 12:34:34] -- <SIP/testcarrier-00000251>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
> [Nov 7 12:34:34] -- <SIP/testcarrier-00000202>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
> [Nov 7 12:34:34] == Spawn extension (default, 919999010855, 2) exited non-zero on 'Local/919999010855 at default-0000022e;2'
> [Nov 7 12:34:34] -- Executing [h at default:1] AGI("Local/919999010855 at default-0000022e;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------") in new stack
> [Nov 7 12:34:34] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:34:34] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:34:34] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:34:35] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:34:35] == Manager 'sendcron' logged on from 127.0.0.1
> [Nov 7 12:34:35] -- Executing [919999039607 at default:1] AGI("Local/919999039607 at default-00000263;2", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:34:35] -- <Local/919999039607 at default-00000263;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:34:35] -- Executing [919999039607 at default:2] Dial("Local/919999039607 at default-00000263;2", "SIP/testcarrier/9999039607,,To") in new stack
> ...
> [Nov 7 12:37:38] -- Got SIP response 603 "Declined" back from 192.168.198.14:5060
> [Nov 7 12:37:38] -- SIP/testcarrier-00000360 is busy
> [Nov 7 12:37:38] == Everyone is busy/congested at this time (1:1/0/0)
> [Nov 7 12:37:38] -- Executing [919999036794 at default:3] Hangup("Local/919999036794 at default-00000360;2", "") in new stack
> [Nov 7 12:37:38] == Spawn extension (default, 919999036794, 3) exited non-zero on 'Local/919999036794 at default-00000360;2'
> [Nov 7 12:37:38] -- Executing [h at default:1] AGI("Local/919999036794 at default-00000360;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY----------") in new stack
> [Nov 7 12:37:38] == Spawn extension (default, 8600064, 1) exited non-zero on 'SIP/testcarrier-0000030e'
> [Nov 7 12:37:38] -- Executing [h at default:1] AGI("SIP/testcarrier-0000030e", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:37:39] -- <Local/919999041574 at default-0000035a;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:37:39] -- <SIP/testcarrier-0000030e>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
> [Nov 7 12:37:39] -- <Local/919999019583 at default-0000035e;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:37:39] -- <Local/919999038488 at default-0000035f;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:37:39] -- <Local/919999036794 at default-00000360;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:37:41] WARNING[14182]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-00000312
> [Nov 7 12:37:41] == Spawn extension (default, 8600055, 1) exited non-zero on 'SIP/testcarrier-00000312'
> [Nov 7 12:37:41] -- Executing [h at default:1] AGI("SIP/testcarrier-00000312", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:37:41] == Spawn extension (default, 8600068, 1) exited non-zero on 'SIP/testcarrier-00000315'
> [Nov 7 12:37:41] -- Executing [h at default:1] AGI("SIP/testcarrier-00000315", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:37:41] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:37:41] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:37:41] == Manager 'sendcron' logged on from 127.0.0.1
> [Nov 7 12:37:41] -- Executing [919999041872 at default:1] AGI("Local/919999041872 at default-00000361;2", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:37:41] -- <Local/919999041872 at default-00000361;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:37:41] -- Executing [919999041872 at default:2] Dial("Local/919999041872 at default-00000361;2", "SIP/testcarrier/9999041872,,To") in new stack
> [Nov 7 12:37:41] == Using SIP RTP CoS mark 5
> [Nov 7 12:37:41] -- Called SIP/testcarrier/9999041872
> [Nov 7 12:37:41] == Manager 'sendcron' logged on from 127.0.0.1
> [Nov 7 12:37:41] -- Executing [919999024382 at default:1] AGI("Local/919999024382 at default-00000362;2", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:37:41] -- <Local/919999024382 at default-00000362;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:37:41] -- Executing [919999024382 at default:2] Dial("Local/919999024382 at default-00000362;2", "SIP/testcarrier/9999024382,,To") in new stack
> ...
> [Nov 7 12:46:45] == Spawn extension (default, 8600066, 1) exited non-zero on 'SIP/testcarrier-0000062d'
> [Nov 7 12:46:45] -- Executing [h at default:1] AGI("SIP/testcarrier-0000062d", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:46:45] -- <Local/919999023730 at default-0000062d;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----0 completed, returning 0
> [Nov 7 12:46:45] == Spawn extension (default, 919999023730, 2) exited non-zero on 'Local/919999023730 at default-0000062d;2'
> [Nov 7 12:46:45] WARNING[23962]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-00000631
> [Nov 7 12:46:45] == Spawn extension (default, 8600075, 1) exited non-zero on 'SIP/testcarrier-00000631'
> [Nov 7 12:46:45] -- Executing [h at default:1] AGI("SIP/testcarrier-00000631", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:46:45] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:46:45] == Spawn extension (default, 919999022935, 2) exited non-zero on 'Local/919999022935 at default-0000060b;2'
> [Nov 7 12:46:45] -- Executing [h at default:1] AGI("Local/919999022935 at default-0000060b;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------") in new stack
> [Nov 7 12:46:45] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:46:45] -- Executing [h at default:1] AGI("Local/919999021501 at default-00000642;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----2-----2") in new stack
> [Nov 7 12:46:45] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:46:45] == Spawn extension (default, 919999031375, 2) exited non-zero on 'Local/919999031375 at default-0000060d;2'
> [Nov 7 12:46:45] -- Executing [h at default:1] AGI("Local/919999031375 at default-0000060d;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0-----CANCEL----------") in new stack
> [Nov 7 12:46:45] -- <Local/919999040000 at default-00000631;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----5-----0 completed, returning 0
> [Nov 7 12:46:45] == Spawn extension (default, 919999040000, 2) exited non-zero on 'Local/919999040000 at default-00000631;2'
> [Nov 7 12:46:45] -- Executing [h at default:1] AGI("Local/919999057221 at default-00000644;2", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----16-----ANSWER-----2-----2") in new stack
> [Nov 7 12:46:45] == Manager 'sendcron' logged off from 127.0.0.1
> [Nov 7 12:46:45] -- SIP/testcarrier-00000633 answered Local/919999025549 at default-00000633;2
> [Nov 7 12:46:45] > Channel Local/919999025549 at default-00000633;1 was answered.
> [Nov 7 12:46:45] -- Executing [8368 at default:1] Playback("Local/919999025549 at default-00000633;1", "sip-silence") in new stack
> ...
> [Nov 7 12:48:50] == Manager 'sendcron' logged on from 127.0.0.1
> [Nov 7 12:48:50] -- Executing [919999006037 at default:1] AGI("Local/919999006037 at default-000006f6;2", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:48:50] -- <Local/919999006037 at default-000006f6;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:48:50] -- Executing [919999006037 at default:2] Dial("Local/919999006037 at default-000006f6;2", "SIP/testcarrier/9999006037,,To") in new stack
> [Nov 7 12:48:50] == Using SIP RTP CoS mark 5
> [Nov 7 12:48:50] -- Called SIP/testcarrier/9999006037
> [Nov 7 12:48:50] == Manager 'sendcron' logged on from 127.0.0.1
> [Nov 7 12:48:50] -- Executing [919999037520 at default:1] AGI("Local/919999037520 at default-000006f7;2", "agi://127.0.0.1:4577/call_log") in new stack
> [Nov 7 12:48:50] -- <Local/919999037520 at default-000006f7;2>AGI Script agi://127.0.0.1:4577/call_log completed, returning 0
> [Nov 7 12:48:50] -- Executing [919999037520 at default:2] Dial("Local/919999037520 at default-000006f7;2", "SIP/testcarrier/9999037520,,To") in new stack
> [Nov 7 12:48:50] == Using SIP RTP CoS mark 5
> [Nov 7 12:48:50] -- Called SIP/testcarrier/9999037520
> [Nov 7 12:48:50] == Spawn extension (default, 8600064, 1) exited non-zero on 'SIP/testcarrier-0000067a'
> [Nov 7 12:48:50] -- Executing [h at default:1] AGI("SIP/testcarrier-0000067a", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:48:50] == Spawn extension (default, 8600068, 1) exited non-zero on 'SIP/testcarrier-0000067c'
> [Nov 7 12:48:50] -- Executing [h at default:1] AGI("SIP/testcarrier-0000067c", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:48:50] -- <Local/919999057448 at default-000006ee;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:48:50] -- <Local/919999010774 at default-000006ef;2>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----21-----BUSY---------- completed, returning 0
> [Nov 7 12:48:51] WARNING[24887]: app_meetme.c:3778 conf_run: Unable to write frame to channel SIP/testcarrier-00000681
> [Nov 7 12:48:51] == Spawn extension (default, 8600062, 1) exited non-zero on 'SIP/testcarrier-00000681'
> [Nov 7 12:48:51] -- Executing [h at default:1] AGI("SIP/testcarrier-00000681", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:48:51] -- <SIP/testcarrier-0000067a>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
> [Nov 7 12:48:51] == Spawn extension (default, 8600059, 1) exited non-zero on 'SIP/testcarrier-00000683'
> [Nov 7 12:48:51] -- Executing [h at default:1] AGI("SIP/testcarrier-00000683", "agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0---------------") in new stack
> [Nov 7 12:48:51] -- <Local/919999039611 at default-000006f3;1>AGI Script agi-VDAD_ALL_outbound.agi completed, returning 0
> [Nov 7 12:48:51] -- Executing [8368 at default:4] AGI("Local/919999039611 at default-000006f3;1", "agi-VDAD_ALL_outbound.agi,NORMAL-----LB") in new stack
> [Nov 7 12:48:51] -- Launched AGI Script /var/lib/asterisk/agi-bin/agi-VDAD_ALL_outbound.agi
> [Nov 7 12:48:51] -- <SIP/testcarrier-0000067c>AGI Script agi://127.0.0.1:4577/call_log--HVcauses--PRI-----NODEBUG-----0--------------- completed, returning 0
> {noformat}
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
More information about the asterisk-bugs
mailing list