Thanks for the reply.
I can replicate the problem. We have moved her to a Polycom 601 and it has not helped. It occurs on all extensions, and is very sporadic. Sometimes it will happen each time, sometimes it will take 5-10 tries.
Here is what I’ve found in testing:
- The caller is disconnected while they are being connected to voicemail. I know this since we ring the phone for 15 seconds, and that is how long the phone rings before dropping.
- We have a DID for her, and this does not occur while using that. The issue only occurs when one of the main numbers is dialed and 0 for operator is pressed.
- A ‘full’ log of one of the dropped calls is here.
[quote]2006/1/13
Jan 13 17:48:37 VERBOSE[1962]: – Executing SetVar(“Zap/1-1”, “FROM_DID=YYYYYYYYYY”) in new stack
Jan 13 17:48:37 VERBOSE[1962]: – Accepting call from ‘XXXXXXXXXX’ to ‘YYYYYYYYYY’ on channel 0/1, span 1
Jan 13 17:48:37 DEBUG[1962]: Enabled echo cancellation on channel 1
Jan 13 17:48:37 VERBOSE[1962]: – Executing Goto(“Zap/1-1”, “aa_1|s|1”) in new stack
Jan 13 17:48:37 VERBOSE[1962]: – Goto (aa_1,s,1)
Jan 13 17:48:37 WARNING[1962]: ast_yyerror(): syntax error: syntax error; Input:
Jan 13 17:48:37 DEBUG[1962]: Expression is '0’
Jan 13 17:48:37 VERBOSE[1962]: – Executing GotoIf(“Zap/1-1”, “0?4”) in new stack
Jan 13 17:48:37 DEBUG[1962]: Not taking any branch
Jan 13 17:48:37 VERBOSE[1962]: – Executing Answer(“Zap/1-1”, “”) in new stack
Jan 13 17:48:37 VERBOSE[1962]: – Executing Wait(“Zap/1-1”, “1”) in new stack
Jan 13 17:48:38 VERBOSE[1962]: – Executing SetVar(“Zap/1-1”, “DIR-CONTEXT=general”) in new stack
Jan 13 17:48:38 VERBOSE[1962]: – Executing DigitTimeout(“Zap/1-1”, “3”) in new stack
Jan 13 17:48:38 VERBOSE[1962]: – Set Digit Timeout to 3
Jan 13 17:48:38 VERBOSE[1962]: – Executing ResponseTimeout(“Zap/1-1”, “7”) in new stack
Jan 13 17:48:38 VERBOSE[1962]: – Set Response Timeout to 7
Jan 13 17:48:38 VERBOSE[1962]: – Executing BackGround(“Zap/1-1”, “custom/aa_1”) in new stack
Jan 13 17:48:38 DEBUG[1962]: Scheduling timer at 160 sample intervals
Jan 13 17:48:38 VERBOSE[1962]: – Playing ‘custom/aa_1’ (language ‘en’)
Jan 13 17:48:39 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:39 DEBUG[1962]: Stopping retransmission on ‘74aabd2d177e4f8511dcbb9002612293@’ of Request 102: Found
Jan 13 17:48:40 DEBUG[1962]: Auto destroying call 'd4b9a150-271eadca-6eeb5899@192.168.10.85’
Jan 13 17:48:41 DEBUG[1962]: Exception on 15, channel 1
Jan 13 17:48:41 DEBUG[1962]: Got event Event 131120(131120) on channel 1 (index 0)
Jan 13 17:48:41 DEBUG[1962]: DTMF Down '0’
Jan 13 17:48:41 DEBUG[1962]: Exception on 15, channel 1
Jan 13 17:48:41 DEBUG[1962]: Got event Event 262192(262192) on channel 1 (index 0)
Jan 13 17:48:41 DEBUG[1962]: Pulse dial '0’
Jan 13 17:48:41 DEBUG[1962]: Scheduling timer at 0 sample intervals
Jan 13 17:48:41 DEBUG[1962]: Oooh, got something to jump out with (‘0’)!
Jan 13 17:48:41 VERBOSE[1962]: == CDR updated on Zap/1-1
Jan 13 17:48:41 VERBOSE[1962]: – Executing Goto(“Zap/1-1”, “ext-group|0|1”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (ext-group,0,1)
Jan 13 17:48:41 VERBOSE[1962]: – Executing Macro(“Zap/1-1”, “rg-group|45||216#”) in new stack
Jan 13 17:48:41 WARNING[1962]: ast_yyerror(): syntax error: syntax error; Input:
Jan 13 17:48:41 DEBUG[1962]: Expression is '0’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Zap/1-1”, “0?3:2”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-rg-group,s,2)
Jan 13 17:48:41 VERBOSE[1962]: – Executing SetCIDName(“Zap/1-1”, “XXXXXXXXXX”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing SetVar(“Zap/1-1”, “RGPREFIX=”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing SetCIDName(“Zap/1-1”, “XXXXXXXXXX”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing SetVar(“Zap/1-1”, “RecordMethod=Group”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing Macro(“Zap/1-1”, “record-enable|0|Group”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Zap/1-1”, “0 > 0?2:4”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,4)
Jan 13 17:48:41 DEBUG[1962]: Expression is '0’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Zap/1-1”, “0?5:8”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,8)
Jan 13 17:48:41 DEBUG[1962]: Expression is '1’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Zap/1-1”, “1?9:12”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,9)
Jan 13 17:48:41 VERBOSE[1962]: – Executing AGI(“Zap/1-1”, “recordingcheck”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Jan 13 17:48:41 DEBUG[1962]: Unable to find key ‘216#’ in family 'RECORD-IN’
Jan 13 17:48:41 VERBOSE[1962]: – AGI Script recordingcheck completed, returning 0
Jan 13 17:48:41 VERBOSE[1962]: – Executing SetVar(“Zap/1-1”, “CALLFILENAME=g0-20060113-174841-1137192517.1020”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing Goto(“Zap/1-1”, “s|14”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,14)
Jan 13 17:48:41 DEBUG[1962]: Expression is '0’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Zap/1-1”, “0?15:99”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,99)
Jan 13 17:48:41 VERBOSE[1962]: – Executing NoOp(“Zap/1-1”, “NO RECORDING NEEDED”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing Macro(“Zap/1-1”, “dial|45|tr|216#”) in new stack
Jan 13 17:48:41 DEBUG[1962]: Expression is '1’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Zap/1-1”, “1?4:2”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-dial,s,4)
Jan 13 17:48:41 VERBOSE[1962]: – Executing AGI(“Zap/1-1”, “dialparties.agi”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: request = dialparties.agi
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: priority = 4
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: extension = s
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: language = en
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: accountcode =
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: uniqueid = 1137192517.1020
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: channel = Zap/1-1
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: callerid = XXXXXXXXXX
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: context = macro-dial
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: type = Zap
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: rdnis = unknown
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: enhanced = 0.0
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: dnid = YYYYYYYYYY
Jan 13 17:48:41 VERBOSE[1962]: dialparties.agi: Caller ID name is ‘XXXXXXXXXX’ number is 'XXXXXXXXXX’
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: Added extension 216# to extension map
Jan 13 17:48:41 DEBUG[1962]: Unable to find key ‘216#’ in family 'CF’
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: Extension 216# cf is disabled
Jan 13 17:48:41 DEBUG[1962]: Manager received command 'Login’
Jan 13 17:48:41 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager.conf’: Jan 13 17:48:41 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager.conf’: Found
Jan 13 17:48:41 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager_custom.conf’: Jan 13 17:48:41 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager_custom.conf’: Found
Jan 13 17:48:41 WARNING[1962]: Unknown directive ‘permit=192.168.1.0/255.255.255.0’ at line 18 of manager_custom.conf
Jan 13 17:48:41 DEBUG[1962]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Jan 13 17:48:41 DEBUG[1962]: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Jan 13 17:48:41 DEBUG[1962]: ##### Testing 127.0.0.1 with 0.0.0.0
Jan 13 17:48:41 DEBUG[1962]: ##### Testing 127.0.0.1 with 127.0.0.0
Jan 13 17:48:41 VERBOSE[1962]: == Manager ‘admin’ logged on from 127.0.0.1
Jan 13 17:48:41 DEBUG[1962]: Manager received command 'command’
Jan 13 17:48:41 DEBUG[1962]: Manager received command ''
Jan 13 17:48:41 DEBUG[1962]: Manager received command 'Logoff’
Jan 13 17:48:41 VERBOSE[1962]: == Manager ‘admin’ logged off from 127.0.0.1
Jan 13 17:48:41 VERBOSE[1962]: dialparties.agi: Dial string is Local/216@from-internal|45|tr
Jan 13 17:48:41 VERBOSE[1962]: – AGI Script dialparties.agi completed, returning 0
Jan 13 17:48:41 VERBOSE[1962]: – Executing Dial(“Zap/1-1”, “Local/216@from-internal|45|tr”) in new stack
Jan 13 17:48:41 DEBUG[1962]: SIMPLE DIAL (NO URL)
Jan 13 17:48:41 VERBOSE[1962]: – Executing Macro(“Local/216@from-internal-e462,2”, “exten-vm|216@default|216”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing SetVar(“Local/216@from-internal-e462,2”, “FROMCONTEXT=exten-vm”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing Macro(“Local/216@from-internal-e462,2”, “record-enable|216|IN”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Local/216@from-internal-e462,2”, “0 > 0?2:4”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,4)
Jan 13 17:48:41 DEBUG[1962]: Expression is '0’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Local/216@from-internal-e462,2”, “0?5:8”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,8)
Jan 13 17:48:41 DEBUG[1962]: Expression is '0’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Local/216@from-internal-e462,2”, “0?9:12”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,12)
Jan 13 17:48:41 VERBOSE[1962]: – Executing DBget(“Local/216@from-internal-e462,2”, “RecEnable=RECORD-IN/216”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – DBget: varname=RecEnable, family=RECORD-IN, key=216
Jan 13 17:48:41 VERBOSE[1962]: – DBget: set variable RecEnable to DISABLED
Jan 13 17:48:41 VERBOSE[1962]: – Executing SetVar(“Local/216@from-internal-e462,2”, “CALLFILENAME=20060113-174841-1137192521.1022”) in new stack
Jan 13 17:48:41 DEBUG[1962]: Expression is '0’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Local/216@from-internal-e462,2”, “0?15:99”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-record-enable,s,99)
Jan 13 17:48:41 VERBOSE[1962]: – Executing NoOp(“Local/216@from-internal-e462,2”, “NO RECORDING NEEDED”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing Macro(“Local/216@from-internal-e462,2”, “dial|15|tr|216”) in new stack
Jan 13 17:48:41 DEBUG[1962]: Expression is '0’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Local/216@from-internal-e462,2”, “0?4:2”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-dial,s,2)
Jan 13 17:48:41 WARNING[1962]: ast_yyerror(): syntax error: syntax error; Input:
Jan 13 17:48:41 DEBUG[1962]: Expression is '0’
Jan 13 17:48:41 VERBOSE[1962]: – Executing GotoIf(“Local/216@from-internal-e462,2”, “0?4:3”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Goto (macro-dial,s,3)
Jan 13 17:48:41 VERBOSE[1962]: – Executing SetCIDName(“Local/216@from-internal-e462,2”, “XXXXXXXXXX”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Executing AGI(“Local/216@from-internal-e462,2”, “dialparties.agi”) in new stack
Jan 13 17:48:41 VERBOSE[1962]: – Called 216@from-internal
Jan 13 17:48:41 VERBOSE[1962]: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: request = dialparties.agi
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: priority = 4
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: extension = s
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: language = en
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: accountcode =
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: uniqueid = 1137192521.1022
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: channel = Local/216@from-internal-e462,2
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: callerid = XXXXXXXXXX
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: context = macro-dial
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: type = Local
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: rdnis = unknown
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: enhanced = 0.0
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: dnid = unknown
Jan 13 17:48:41 VERBOSE[1962]: dialparties.agi: Caller ID name is ‘XXXXXXXXXX’ number is 'XXXXXXXXXX’
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: Added extension 216 to extension map
Jan 13 17:48:41 DEBUG[1962]: Unable to find key ‘216’ in family 'CF’
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: Extension 216 cf is disabled
Jan 13 17:48:41 DEBUG[1962]: Unable to find key ‘216’ in family 'DND’
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: Extension 216 do not disturb is disabled
Jan 13 17:48:41 DEBUG[1962]: Manager received command 'Login’
Jan 13 17:48:41 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager.conf’: Jan 13 17:48:41 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager.conf’: Found
Jan 13 17:48:41 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager_custom.conf’: Jan 13 17:48:41 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager_custom.conf’: Found
Jan 13 17:48:41 WARNING[1962]: Unknown directive ‘permit=192.168.1.0/255.255.255.0’ at line 18 of manager_custom.conf
Jan 13 17:48:41 DEBUG[1962]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Jan 13 17:48:41 DEBUG[1962]: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Jan 13 17:48:41 DEBUG[1962]: ##### Testing 127.0.0.1 with 0.0.0.0
Jan 13 17:48:41 DEBUG[1962]: ##### Testing 127.0.0.1 with 127.0.0.0
Jan 13 17:48:41 VERBOSE[1962]: == Manager ‘admin’ logged on from 127.0.0.1
Jan 13 17:48:41 DEBUG[1962]: Manager received command 'command’
Jan 13 17:48:41 DEBUG[1962]: Manager received command ''
Jan 13 17:48:41 DEBUG[1962]: Manager received command 'Logoff’
Jan 13 17:48:41 VERBOSE[1962]: == Manager ‘admin’ logged off from 127.0.0.1
Jan 13 17:48:41 DEBUG[1962]: Unable to find key ‘216’ in family 'CW’
Jan 13 17:48:41 VERBOSE[1962]: dialparties.agi: Extension 216 has call waiting disabled
Jan 13 17:48:41 VERBOSE[1962]: – dialparties.agi: DbSet CALLTRACE/216 to XXXXXXXXXX
Jan 13 17:48:41 VERBOSE[1962]: dialparties.agi: Dial string is SIP/216|15|tr
Jan 13 17:48:41 VERBOSE[1962]: – AGI Script dialparties.agi completed, returning 0
Jan 13 17:48:41 VERBOSE[1962]: – Executing Dial(“Local/216@from-internal-e462,2”, “SIP/216|15|tr”) in new stack
Jan 13 17:48:41 DEBUG[1962]: SIMPLE DIAL (NO URL)
Jan 13 17:48:41 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:41 DEBUG[1962]: Outgoing Call for 216
Jan 13 17:48:41 DEBUG[1962]: Call from user ‘216’ is 1 out of 0
Jan 13 17:48:41 VERBOSE[1962]: – Called 216
Jan 13 17:48:41 VERBOSE[1962]: – Local/216@from-internal-e462,1 is ringing
Jan 13 17:48:41 DEBUG[1962]: (Provisional) Stopping retransmission (but retaining packet) on ‘2bf0452649de36d754e52f9e1a6de9b7@’ Request 102: Found
Jan 13 17:48:42 DEBUG[1962]: (Provisional) Stopping retransmission (but retaining packet) on ‘2bf0452649de36d754e52f9e1a6de9b7@’ Request 102: Found
Jan 13 17:48:42 VERBOSE[1962]: – SIP/216-1a67 is ringing
Jan 13 17:48:42 VERBOSE[1962]: – Local/216@from-internal-e462,1 is ringing
Jan 13 17:48:42 DEBUG[1962]: Auto destroying call 'aa0c8fc7-7a3a8f01-f9752416@192.168.10.30’
Jan 13 17:48:44 DEBUG[1962]: Acked pending invite 102
Jan 13 17:48:44 DEBUG[1962]: Stopping retransmission on ‘2bf0452649de36d754e52f9e1a6de9b7@’ of Request 102: Found
Jan 13 17:48:44 DEBUG[1962]: build_route: Contact hop: sip:216@192.168.10.36
Jan 13 17:48:44 VERBOSE[1962]: – SIP/216-1a67 answered Local/216@from-internal-e462,2
Jan 13 17:48:44 VERBOSE[1962]: – Local/216@from-internal-e462,1 answered Zap/1-1
Jan 13 17:48:44 DEBUG[1962]: Ooh, format changed from unknown to ulaw
Jan 13 17:48:45 DEBUG[1962]: Auto destroying call '6edc3bd6-557e230c-d17537d5@192.168.10.66’
Jan 13 17:48:45 VERBOSE[1962]: – Started music on hold, class ‘default’, on Local/216@from-internal-e462,2
Jan 13 17:48:45 DEBUG[1962]: Scheduling timer at 160 sample intervals
Jan 13 17:48:45 DEBUG[1962]: Generator got voice, switching to phase locked mode
Jan 13 17:48:45 DEBUG[1962]: Scheduling timer at 0 sample intervals
Jan 13 17:48:45 DEBUG[1962]: Stopping retransmission on ‘2bf0452649de36d754e52f9e1a6de9b7@’ of Response 1: Found
Jan 13 17:48:47 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:47 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:47 DEBUG[1962]: Stopping retransmission on ‘365d592156b389c2079c9374624d9e47@’ of Request 102: Found
Jan 13 17:48:47 DEBUG[1962]: Stopping retransmission on ‘1d3f42e4661d91d75aee331d14c373fe@’ of Request 102: Found
Jan 13 17:48:49 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:49 DEBUG[1962]: Stopping retransmission on ‘28eb9afd39c803a10a66ac596335086a@’ of Request 102: Found
Jan 13 17:48:54 DEBUG[1962]: Auto destroying call '76134441-6e9c907b-7890bc78@192.168.10.72’
Jan 13 17:48:58 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:58 DEBUG[1962]: Stopping retransmission on ‘faa6270-86a65e8a-2acaaa81@192.168.10.36’ of Response 1: Found
Jan 13 17:48:58 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:58 DEBUG[1962]: Check for res for 216
Jan 13 17:48:58 DEBUG[1962]: Call from user ‘216’ is 2 out of 0
Jan 13 17:48:58 DEBUG[1962]: build_route: Contact hop: sip:216@192.168.10.36
Jan 13 17:48:58 VERBOSE[1962]: – Executing Macro(“SIP/216-11db”, “exten-vm|260@default|260”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Executing SetVar(“SIP/216-11db”, “FROMCONTEXT=exten-vm”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Executing Macro(“SIP/216-11db”, “record-enable|260|IN”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Executing GotoIf(“SIP/216-11db”, “0 > 0?2:4”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Goto (macro-record-enable,s,4)
Jan 13 17:48:58 DEBUG[1962]: Expression is '0’
Jan 13 17:48:58 VERBOSE[1962]: – Executing GotoIf(“SIP/216-11db”, “0?5:8”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Goto (macro-record-enable,s,8)
Jan 13 17:48:58 DEBUG[1962]: Expression is '0’
Jan 13 17:48:58 VERBOSE[1962]: – Executing GotoIf(“SIP/216-11db”, “0?9:12”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Goto (macro-record-enable,s,12)
Jan 13 17:48:58 VERBOSE[1962]: – Executing DBget(“SIP/216-11db”, “RecEnable=RECORD-IN/260”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – DBget: varname=RecEnable, family=RECORD-IN, key=260
Jan 13 17:48:58 VERBOSE[1962]: – DBget: set variable RecEnable to DISABLED
Jan 13 17:48:58 VERBOSE[1962]: – Executing SetVar(“SIP/216-11db”, “CALLFILENAME=20060113-174858-1137192538.1024”) in new stack
Jan 13 17:48:58 DEBUG[1962]: Expression is '0’
Jan 13 17:48:58 VERBOSE[1962]: – Executing GotoIf(“SIP/216-11db”, “0?15:99”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Goto (macro-record-enable,s,99)
Jan 13 17:48:58 VERBOSE[1962]: – Executing NoOp(“SIP/216-11db”, “NO RECORDING NEEDED”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Executing Macro(“SIP/216-11db”, “dial|15|tr|260”) in new stack
Jan 13 17:48:58 DEBUG[1962]: Expression is '0’
Jan 13 17:48:58 VERBOSE[1962]: – Executing GotoIf(“SIP/216-11db”, “0?4:2”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Goto (macro-dial,s,2)
Jan 13 17:48:58 WARNING[1962]: ast_yyerror(): syntax error: syntax error; Input:
Jan 13 17:48:58 DEBUG[1962]: Expression is '0’
Jan 13 17:48:58 VERBOSE[1962]: – Executing GotoIf(“SIP/216-11db”, “0?4:3”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Goto (macro-dial,s,3)
Jan 13 17:48:58 VERBOSE[1962]: – Executing SetCIDName(“SIP/216-11db”, “Dottie Clark”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Executing AGI(“SIP/216-11db”, “dialparties.agi”) in new stack
Jan 13 17:48:58 VERBOSE[1962]: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: request = dialparties.agi
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: priority = 4
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: extension = s
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: language = en
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: accountcode =
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: uniqueid = 1137192538.1024
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: channel = SIP/216-11db
Jan 13 17:48:59 VERBOSE[1962]: dialparties.agi: callerid = Dottie
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: context = macro-dial
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: type = SIP
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: rdnis = unknown
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: enhanced = 0.0
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: dnid = 260
Jan 13 17:48:59 VERBOSE[1962]: dialparties.agi: Caller ID name is ‘Dottie Clark’ number is '216’
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: Added extension 260 to extension map
Jan 13 17:48:59 DEBUG[1962]: Unable to find key ‘260’ in family 'CF’
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: Extension 260 cf is disabled
Jan 13 17:48:59 DEBUG[1962]: Unable to find key ‘260’ in family 'DND’
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: Extension 260 do not disturb is disabled
Jan 13 17:48:59 DEBUG[1962]: Manager received command 'Login’
Jan 13 17:48:59 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager.conf’: Jan 13 17:48:59 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager.conf’: Found
Jan 13 17:48:59 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager_custom.conf’: Jan 13 17:48:59 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager_custom.conf’: Found
Jan 13 17:48:59 WARNING[1962]: Unknown directive ‘permit=192.168.1.0/255.255.255.0’ at line 18 of manager_custom.conf
Jan 13 17:48:59 DEBUG[1962]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Jan 13 17:48:59 DEBUG[1962]: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Jan 13 17:48:59 DEBUG[1962]: ##### Testing 127.0.0.1 with 0.0.0.0
Jan 13 17:48:59 DEBUG[1962]: ##### Testing 127.0.0.1 with 127.0.0.0
Jan 13 17:48:59 VERBOSE[1962]: == Manager ‘admin’ logged on from 127.0.0.1
Jan 13 17:48:59 DEBUG[1962]: Manager received command ‘command’
Jan 13 17:48:59 DEBUG[1962]: Manager received command ‘‘
Jan 13 17:48:59 DEBUG[1962]: Manager received command ‘Logoff’
Jan 13 17:48:59 VERBOSE[1962]: == Manager ‘admin’ logged off from 127.0.0.1
Jan 13 17:48:59 DEBUG[1962]: Unable to find key ‘260’ in family ‘CW’
Jan 13 17:48:59 VERBOSE[1962]: dialparties.agi: Extension 260 has call waiting disabled
Jan 13 17:48:59 VERBOSE[1962]: – dialparties.agi: DbSet CALLTRACE/260 to 216
Jan 13 17:48:59 VERBOSE[1962]: dialparties.agi: Dial string is SIP/260|15|tr
Jan 13 17:48:59 VERBOSE[1962]: – AGI Script dialparties.agi completed, returning 0
Jan 13 17:48:59 VERBOSE[1962]: – Executing Dial(“SIP/216-11db”, “SIP/260|15|tr”) in new stack
Jan 13 17:48:59 DEBUG[1962]: SIMPLE DIAL (NO URL)
Jan 13 17:48:59 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:59 DEBUG[1962]: Outgoing Call for 260
Jan 13 17:48:59 DEBUG[1962]: Call from user ‘260’ is 1 out of 0
Jan 13 17:48:59 VERBOSE[1962]: – Called 260
Jan 13 17:48:59 DEBUG[1962]: (Provisional) Stopping retransmission (but retaining packet) on ‘6f5594587c2aa9630cb8c2fe0f22c018@’ Request 102: Found
Jan 13 17:48:59 DEBUG[1962]: (Provisional) Stopping retransmission (but retaining packet) on ‘6f5594587c2aa9630cb8c2fe0f22c018@’ Request 102: Found
Jan 13 17:48:59 VERBOSE[1962]: – SIP/260-d72a is ringing
Jan 13 17:48:59 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:59 DEBUG[1962]: Stopping retransmission on ‘2dabe63c1baf70ba43f2b1f93455f0fc@’ of Request 102: Found
Jan 13 17:48:59 DEBUG[1962]: Auto destroying call ‘ecf95b90-9b9d0726-6e7f50b7@192.168.10.68’
Jan 13 17:48:59 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:48:59 DEBUG[1962]: Stopping retransmission on ‘6e5770562da4aa143e839a485dad04ae@’ of Request 102: Found
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-01-13 17:48:37’,’“XXXXXXXXXX” ‘,‘XXXXXXXXXX’,‘0’,‘ext-group’, ‘Zap/1-1’,‘Local/216@from-internal-e462,1’,‘Dial’,‘Local/216@from-internal|45|tr’,37,37,‘ANSWERED’,3,’’)
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-01-13 17:48:58’,’“XXXXXXXXXX” ‘,‘XXXXXXXXXX’,‘260’,‘from-internal’, ‘SIP/216-11db’,‘SIP/260-d72a’,‘ResetCDR’,‘w’,16,0,‘NO ANSWER’,3,’’)
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-01-13 17:48:41’,’“XXXXXXXXXX” ‘,‘XXXXXXXXXX’,‘260’,‘from-internal’, ‘Local/216@from-internal-e462,2’,‘SIP/216-1a67’,‘ResetCDR’,‘w’,33,30,‘ANSWERED’,3,’’)
Jan 13 17:49:00 DEBUG[1962]: We found a REFER!
Jan 13 17:49:00 DEBUG[1962]: Assigning Replace-Call-ID Info faa6270-86a65e8a-2acaaa81@192.168.10.36 to REPLACE_CALL_ID
Jan 13 17:49:00 DEBUG[1962]: 202 Accepted (supervised)
Jan 13 17:49:00 VERBOSE[1962]: – Stopped music on hold on Local/216@from-internal-e462,2
Jan 13 17:49:00 DEBUG[1962]: Scheduling timer at 0 sample intervals
Jan 13 17:49:00 DEBUG[1962]: Planning to masquerade Local/216@from-internal-e462,2 into the structure of SIP/216-11db
Jan 13 17:49:00 DEBUG[1962]: Done planning to masquerade SIP/216-11db into the structure of Local/216@from-internal-e462,2
Jan 13 17:49:00 DEBUG[1962]: Actually Masquerading Local/216@from-internal-e462,2(6) into the structure of SIP/216-11db(4)
Jan 13 17:49:00 DEBUG[1962]: Got clone lock on ‘Local/216@from-internal-e462,2’ at 0x98fe9b8
Jan 13 17:49:00 DEBUG[1962]: update_user_counter(216) - decrement inUse counter
Jan 13 17:49:00 DEBUG[1962]: Putting channel Local/216@from-internal-e462,2 in 4/4 formats
Jan 13 17:49:00 DEBUG[1962]: Released clone lock on 'SIP/216-11db’
Jan 13 17:49:00 DEBUG[1962]: Done Masquerading Local/216@from-internal-e462,2 (6)
Jan 13 17:49:00 DEBUG[1962]: Didn’t get a frame from channel: SIP/216-11db
Jan 13 17:49:00 DEBUG[1962]: Bridge stops bridging channels SIP/216-11db and SIP/216-1a67
Jan 13 17:49:00 DEBUG[1962]: update_user_counter(216) - decrement inUse counter
Jan 13 17:49:00 DEBUG[1962]: Exiting with DIALSTATUS=ANSWER.
Jan 13 17:49:00 VERBOSE[1962]: == Spawn extension (macro-dial, s, 10) exited non-zero on ‘SIP/216-11db’ in macro 'dial’
Jan 13 17:49:00 VERBOSE[1962]: == Spawn extension (macro-exten-vm, s, 3) exited non-zero on ‘SIP/216-11db’ in macro 'exten-vm’
Jan 13 17:49:00 VERBOSE[1962]: == Spawn extension (from-internal, 216, 1) exited non-zero on 'SIP/216-11db’
Jan 13 17:49:00 VERBOSE[1962]: – Executing Macro(“SIP/216-11db”, “hangupcall”) in new stack
Jan 13 17:49:00 VERBOSE[1962]: – Executing ResetCDR(“SIP/216-11db”, “w”) in new stack
Jan 13 17:49:00 VERBOSE[1962]: – Executing NoCDR(“SIP/216-11db”, “”) in new stack
Jan 13 17:49:00 VERBOSE[1962]: – Executing Wait(“SIP/216-11db”, “5”) in new stack
Jan 13 17:49:00 VERBOSE[1962]: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/216-11db’ in macro 'hangupcall’
Jan 13 17:49:00 VERBOSE[1962]: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/216-11db’
Jan 13 17:49:00 DEBUG[1962]: Stopping retransmission on ‘2bf0452649de36d754e52f9e1a6de9b7@’ of Request 103: Found
Jan 13 17:49:00 DEBUG[1962]: Stopping retransmission on ‘2bf0452649de36d754e52f9e1a6de9b7@’ of Request 104: Found
Jan 13 17:49:00 DEBUG[1962]: Auto destroying call 'a98fa736-32e80dc0-59b7139b@192.168.10.73’
Jan 13 17:49:00 DEBUG[1962]: Stopping retransmission on ‘faa6270-86a65e8a-2acaaa81@192.168.10.36’ of Response 2: Found
Jan 13 17:49:01 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:01 DEBUG[1962]: Stopping retransmission on ‘0c3f7d4f0a679b653cfe50533a968027@’ of Request 102: Found
Jan 13 17:49:04 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:04 DEBUG[1962]: Stopping retransmission on ‘0f1324cb4493305f60c6a9b17be2e992@’ of Request 102: Found
Jan 13 17:49:05 DEBUG[1962]: Auto destroying call 'b8db4ca3-289fa54d-bcbe489c@192.168.10.36’
Jan 13 17:49:06 DEBUG[1962]: Auto destroying call '88424970-ef44167a-ef9a5117@192.168.10.41’
Jan 13 17:49:12 DEBUG[1962]: Auto destroying call 'aa0c8fc7-7a3a8f01-f9752416@192.168.10.30’
Jan 13 17:49:13 DEBUG[1962]: Manager received command 'Command’
Jan 13 17:49:13 DEBUG[1962]: Manager received command ‘Command’
Jan 13 17:49:14 VERBOSE[1962]: – Nobody picked up in 15000 ms
Jan 13 17:49:14 DEBUG[1962]: update_user_counter(260) - decrement outUse counter
Jan 13 17:49:14 DEBUG[1962]: Got a FRAME_CONTROL (-1) frame on channel Local/216@from-internal-e462,1
Jan 13 17:49:14 DEBUG[1962]: Bridge stops bridging channels Zap/1-1 and Local/216@from-internal-e462,1
Jan 13 17:49:14 DEBUG[1962]: Read from Local/216@from-internal-e462,1 (4,-1)
Jan 13 17:49:14 DEBUG[1962]: Exiting with DIALSTATUS=NOANSWER.
Jan 13 17:49:14 DEBUG[1962]: Expression is ‘1’
Jan 13 17:49:14 VERBOSE[1962]: – Executing GotoIf(“Local/216@from-internal-e462,2”, “1?s-NOANSWER|1”) in new stack
Jan 13 17:49:14 VERBOSE[1962]: – Goto (macro-exten-vm,s-NOANSWER,1)
Jan 13 17:49:14 VERBOSE[1962]: – Executing Congestion(“Local/216@from-internal-e462,2”, “”) in new stack
Jan 13 17:49:14 DEBUG[1962]: Got a FRAME_CONTROL (8) frame on channel Local/216@from-internal-e462,1
Jan 13 17:49:14 DEBUG[1962]: Bridge stops bridging channels Zap/1-1 and Local/216@from-internal-e462,1
Jan 13 17:49:14 DEBUG[1962]: Exiting with DIALSTATUS=ANSWER.
Jan 13 17:49:14 VERBOSE[1962]: == Spawn extension (macro-exten-vm, s-NOANSWER, 1) exited non-zero on ‘Local/216@from-internal-e462,2’ in macro ‘exten-vm’
Jan 13 17:49:14 VERBOSE[1962]: == Spawn extension (macro-dial, s, 10) exited non-zero on ‘Zap/1-1’ in macro ‘dial’
Jan 13 17:49:14 VERBOSE[1962]: == Spawn extension (from-internal, 260, 1) exited non-zero on ‘Local/216@from-internal-e462,2’
Jan 13 17:49:14 VERBOSE[1962]: == Spawn extension (macro-rg-group, s, 7) exited non-zero on ‘Zap/1-1’ in macro ‘rg-group’
Jan 13 17:49:14 VERBOSE[1962]: – Executing Macro(“Local/216@from-internal-e462,2”, “hangupcall”) in new stack
Jan 13 17:49:14 VERBOSE[1962]: == Spawn extension (ext-group, 0, 1) exited non-zero on ‘Zap/1-1’
Jan 13 17:49:14 VERBOSE[1962]: – Executing ResetCDR(“Local/216@from-internal-e462,2”, “w”) in new stack
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: inserting a CDR record.
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-01-13 17:48:37’,’“XXXXXXXXXX” ‘,‘XXXXXXXXXX’,‘0’,‘ext-group’, ‘Zap/1-1’,‘Local/216@from-internal-e462,1’,‘Dial’,‘Local/216@from-internal|45|tr’,37,37,‘ANSWERED’,3,’’)
Jan 13 17:49:14 DEBUG[1962]: Set option AUDIO MODE, value: ON(1) on Zap/1-1
Jan 13 17:49:14 DEBUG[1962]: Hangup: channel: 1 index = 0, normal = 15, callwait = -1, thirdcall = -1
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: inserting a CDR record.
Jan 13 17:49:14 DEBUG[1962]: Not yet hungup… Calling hangup once with icause, and clearing call
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-01-13 17:48:58’,’“XXXXXXXXXX” ‘,‘XXXXXXXXXX’,‘260’,‘from-internal’, ‘SIP/216-11db’,‘SIP/260-d72a’,‘ResetCDR’,‘w’,16,0,‘NO ANSWER’,3,’’)
Jan 13 17:49:14 DEBUG[1962]: disabled echo cancellation on channel 1
Jan 13 17:49:14 DEBUG[1962]: Set option TDD MODE, value: OFF(0) on Zap/1-1
Jan 13 17:49:14 DEBUG[1962]: Updated conferencing on 1, with 0 conference users
Jan 13 17:49:14 DEBUG[1962]: Set option AUDIO MODE, value: OFF(0) on Zap/1-1
Jan 13 17:49:14 DEBUG[1962]: disabled echo cancellation on channel 1
Jan 13 17:49:14 VERBOSE[1962]: – Hungup ‘Zap/1-1’
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: inserting a CDR record.
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-01-13 17:48:41’,’“XXXXXXXXXX” ‘,‘XXXXXXXXXX’,‘260’,‘from-internal’, ‘Local/216@from-internal-e462,2’,‘SIP/216-1a67’,‘ResetCDR’,‘w’,33,30,‘ANSWERED’,3,’’)
Jan 13 17:49:14 WARNING[1962]: CDR on channel ‘Local/216@from-internal-e462,2’ already posted
Jan 13 17:49:14 WARNING[1962]: CDR on channel ‘Local/216@from-internal-e462,2’ already started
Jan 13 17:49:14 WARNING[1962]: CDR on channel ‘Local/216@from-internal-e462,2’ already posted
Jan 13 17:49:14 WARNING[1962]: CDR on channel ‘Local/216@from-internal-e462,2’ already posted
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: inserting a CDR record.
Jan 13 17:49:14 DEBUG[1962]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-01-13 17:49:14’,’“XXXXXXXXXX” ‘,‘XXXXXXXXXX’,‘260’,‘from-internal’, ‘Local/216@from-internal-e462,2’,‘SIP/216-1a67’,‘ResetCDR’,‘w’,0,30,‘ANSWERED’,3,’’)
Jan 13 17:49:14 VERBOSE[1962]: – Executing NoCDR(“Local/216@from-internal-e462,2”, “”) in new stack
Jan 13 17:49:14 WARNING[1962]: CDR on channel ‘SIP/216-11db’ not posted
Jan 13 17:49:14 WARNING[1962]: CDR on channel ‘SIP/216-11db’ lacks end
Jan 13 17:49:14 WARNING[1962]: CDR on channel ‘Local/216@from-internal-e462,2’ not posted
Jan 13 17:49:14 WARNING[1962]: CDR on channel ‘Local/216@from-internal-e462,2’ lacks end
Jan 13 17:49:14 VERBOSE[1962]: – Executing Wait(“Local/216@from-internal-e462,2”, “5”) in new stack
Jan 13 17:49:14 DEBUG[1962]: Acked pending invite 102
Jan 13 17:49:14 DEBUG[1962]: Stopping retransmission on ‘6f5594587c2aa9630cb8c2fe0f22c018@’ of Request 102: Found
Jan 13 17:49:14 DEBUG[1962]: Stopping retransmission on ‘6f5594587c2aa9630cb8c2fe0f22c018@’ of Request 102: Found
Jan 13 17:49:15 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:15 DEBUG[1962]: Stopping retransmission on ‘209f991823504e3b70b6722a1cba17c7@’ of Request 102: Found
Jan 13 17:49:15 DEBUG[1962]: Auto destroying call '6edc3bd6-557e230c-d17537d5@192.168.10.66’
Jan 13 17:49:19 VERBOSE[1962]: – Executing Hangup(“Local/216@from-internal-e462,2”, “”) in new stack
Jan 13 17:49:19 VERBOSE[1962]: == Spawn extension (macro-hangupcall, s, 4) exited non-zero on ‘Local/216@from-internal-e462,2’ in macro 'hangupcall’
Jan 13 17:49:19 VERBOSE[1962]: == Spawn extension (from-internal, h, 1) exited non-zero on 'Local/216@from-internal-e462,2’
Jan 13 17:49:20 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:20 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:20 DEBUG[1962]: Stopping retransmission on ‘41e6e2580b708e902b900ad316a700a6@’ of Request 102: Found
Jan 13 17:49:20 DEBUG[1962]: Stopping retransmission on ‘17f3d6b24969a354178a214a22018d96@’ of Request 102: Found
Jan 13 17:49:21 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:21 DEBUG[1962]: Stopping retransmission on ‘4e1b5c2416fd4ea12058562b4bae54c2@’ of Request 102: Found
Jan 13 17:49:22 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:22 DEBUG[1962]: Stopping retransmission on ‘5c1eb340075d35232e8fd48c6b7eaabb@’ of Request 102: Found
Jan 13 17:49:24 DEBUG[1962]: Auto destroying call '76134441-6e9c907b-7890bc78@192.168.10.72’
Jan 13 17:49:27 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:27 DEBUG[1962]: Stopping retransmission on ‘40c3dfc5cbd70669@192.168.10.80’ of Response 39622: Found
Jan 13 17:49:27 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:27 DEBUG[1962]: Check for res for 260
Jan 13 17:49:27 DEBUG[1962]: Call from user ‘260’ is 1 out of 0
Jan 13 17:49:27 DEBUG[1962]: build_route: Contact hop: sip:260@192.168.10.80
Jan 13 17:49:27 VERBOSE[1962]: – Executing Macro(“SIP/260-a77e”, “exten-vm|216@default|216”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Executing SetVar(“SIP/260-a77e”, “FROMCONTEXT=exten-vm”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Executing Macro(“SIP/260-a77e”, “record-enable|216|IN”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Executing GotoIf(“SIP/260-a77e”, “0 > 0?2:4”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Goto (macro-record-enable,s,4)
Jan 13 17:49:27 DEBUG[1962]: Expression is '0’
Jan 13 17:49:27 VERBOSE[1962]: – Executing GotoIf(“SIP/260-a77e”, “0?5:8”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Goto (macro-record-enable,s,8)
Jan 13 17:49:27 DEBUG[1962]: Expression is '0’
Jan 13 17:49:27 VERBOSE[1962]: – Executing GotoIf(“SIP/260-a77e”, “0?9:12”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Goto (macro-record-enable,s,12)
Jan 13 17:49:27 VERBOSE[1962]: – Executing DBget(“SIP/260-a77e”, “RecEnable=RECORD-IN/216”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – DBget: varname=RecEnable, family=RECORD-IN, key=216
Jan 13 17:49:27 VERBOSE[1962]: – DBget: set variable RecEnable to DISABLED
Jan 13 17:49:27 VERBOSE[1962]: – Executing SetVar(“SIP/260-a77e”, “CALLFILENAME=20060113-174927-1137192567.1026”) in new stack
Jan 13 17:49:27 DEBUG[1962]: Expression is '0’
Jan 13 17:49:27 VERBOSE[1962]: – Executing GotoIf(“SIP/260-a77e”, “0?15:99”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Goto (macro-record-enable,s,99)
Jan 13 17:49:27 VERBOSE[1962]: – Executing NoOp(“SIP/260-a77e”, “NO RECORDING NEEDED”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Executing Macro(“SIP/260-a77e”, “dial|15|tr|216”) in new stack
Jan 13 17:49:27 DEBUG[1962]: Expression is '0’
Jan 13 17:49:27 VERBOSE[1962]: – Executing GotoIf(“SIP/260-a77e”, “0?4:2”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Goto (macro-dial,s,2)
Jan 13 17:49:27 WARNING[1962]: ast_yyerror(): syntax error: syntax error; Input:
Jan 13 17:49:27 DEBUG[1962]: Expression is '0’
Jan 13 17:49:27 VERBOSE[1962]: – Executing GotoIf(“SIP/260-a77e”, “0?4:3”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Goto (macro-dial,s,3)
Jan 13 17:49:27 VERBOSE[1962]: – Executing SetCIDName(“SIP/260-a77e”, “John Doe”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Executing AGI(“SIP/260-a77e”, “dialparties.agi”) in new stack
Jan 13 17:49:27 VERBOSE[1962]: – Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: request = dialparties.agi
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: priority = 4
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: extension = s
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: language = en
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: accountcode =
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: uniqueid = 1137192567.1026
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: channel = SIP/260-a77e
Jan 13 17:49:27 VERBOSE[1962]: dialparties.agi: callerid = Josh
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: context = macro-dial
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: type = SIP
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: rdnis = unknown
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: enhanced = 0.0
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: dnid = 216
Jan 13 17:49:27 VERBOSE[1962]: dialparties.agi: Caller ID name is ‘John Doe’ number is '260’
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: Added extension 216 to extension map
Jan 13 17:49:27 DEBUG[1962]: Unable to find key ‘216’ in family 'CF’
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: Extension 216 cf is disabled
Jan 13 17:49:27 DEBUG[1962]: Unable to find key ‘216’ in family 'DND’
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: Extension 216 do not disturb is disabled
Jan 13 17:49:27 DEBUG[1962]: Manager received command 'Login’
Jan 13 17:49:27 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager.conf’: Jan 13 17:49:27 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager.conf’: Found
Jan 13 17:49:27 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager_custom.conf’: Jan 13 17:49:27 VERBOSE[1962]: == Parsing ‘/etc/asterisk/manager_custom.conf’: Found
Jan 13 17:49:27 WARNING[1962]: Unknown directive ‘permit=192.168.1.0/255.255.255.0’ at line 18 of manager_custom.conf
Jan 13 17:49:27 DEBUG[1962]: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer
Jan 13 17:49:27 DEBUG[1962]: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer
Jan 13 17:49:27 DEBUG[1962]: ##### Testing 127.0.0.1 with 0.0.0.0
Jan 13 17:49:27 DEBUG[1962]: ##### Testing 127.0.0.1 with 127.0.0.0
Jan 13 17:49:27 VERBOSE[1962]: == Manager ‘admin’ logged on from 127.0.0.1
Jan 13 17:49:27 DEBUG[1962]: Manager received command 'command’
Jan 13 17:49:27 DEBUG[1962]: Manager received command ''
Jan 13 17:49:27 DEBUG[1962]: Manager received command 'Logoff’
Jan 13 17:49:27 VERBOSE[1962]: == Manager ‘admin’ logged off from 127.0.0.1
Jan 13 17:49:27 DEBUG[1962]: Unable to find key ‘216’ in family 'CW’
Jan 13 17:49:27 VERBOSE[1962]: dialparties.agi: Extension 216 has call waiting disabled
Jan 13 17:49:27 VERBOSE[1962]: – dialparties.agi: DbSet CALLTRACE/216 to 260
Jan 13 17:49:27 VERBOSE[1962]: dialparties.agi: Dial string is SIP/216|15|tr
Jan 13 17:49:27 VERBOSE[1962]: – AGI Script dialparties.agi completed, returning 0
Jan 13 17:49:27 VERBOSE[1962]: – Executing Dial(“SIP/260-a77e”, “SIP/216|15|tr”) in new stack
Jan 13 17:49:27 DEBUG[1962]: SIMPLE DIAL (NO URL)
Jan 13 17:49:27 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:27 DEBUG[1962]: Outgoing Call for 216
Jan 13 17:49:27 DEBUG[1962]: Call from user ‘216’ is 1 out of 0
Jan 13 17:49:27 VERBOSE[1962]: – Called 216
Jan 13 17:49:28 DEBUG[1962]: (Provisional) Stopping retransmission (but retaining packet) on ‘13eb6b783e6f98512050b5c22079b26e@’ Request 102: Found
Jan 13 17:49:28 DEBUG[1962]: (Provisional) Stopping retransmission (but retaining packet) on ‘13eb6b783e6f98512050b5c22079b26e@’ Request 102: Found
Jan 13 17:49:28 VERBOSE[1962]: – SIP/216-4b92 is ringing
Jan 13 17:49:29 DEBUG[1962]: Auto destroying call 'ecf95b90-9b9d0726-6e7f50b7@192.168.10.68’
Jan 13 17:49:29 DEBUG[1962]: Auto destroying call 'd4b9a150-271eadca-6eeb5899@192.168.10.85’
Jan 13 17:49:30 DEBUG[1962]: Acked pending invite 102
Jan 13 17:49:30 DEBUG[1962]: Stopping retransmission on ‘13eb6b783e6f98512050b5c22079b26e@’ of Request 102: Found
Jan 13 17:49:30 DEBUG[1962]: build_route: Contact hop: sip:216@192.168.10.36
Jan 13 17:49:30 VERBOSE[1962]: – SIP/216-4b92 answered SIP/260-a77e
Jan 13 17:49:30 VERBOSE[1962]: – Attempting native bridge of SIP/260-a77e and SIP/216-4b92
Jan 13 17:49:30 DEBUG[1962]: Stopping retransmission on ‘40c3dfc5cbd70669@192.168.10.80’ of Response 39623: Found
Jan 13 17:49:30 DEBUG[1962]: Ooh, format changed from unknown to ulaw
Jan 13 17:49:30 DEBUG[1962]: Auto destroying call ‘a98fa736-32e80dc0-59b7139b@192.168.10.73’
Jan 13 17:49:30 DEBUG[1962]: Ooh, format changed from unknown to ulaw
Jan 13 17:49:33 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:33 DEBUG[1962]: Stopping retransmission on ‘460218d5763ce11035a4032c655c2c3e@’ of Request 102: Found
Jan 13 17:49:34 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:34 DEBUG[1962]: Stopping retransmission on ‘6cadf6fd699add52081bcc5372baed4a@’ of Request 102: Found
Jan 13 17:49:35 DEBUG[1962]: Didn’t get a frame from channel: SIP/216-4b92
Jan 13 17:49:35 DEBUG[1962]: Bridge stops bridging channels SIP/260-a77e and SIP/216-4b92
Jan 13 17:49:35 DEBUG[1962]: update_user_counter(216) - decrement outUse counter
Jan 13 17:49:35 DEBUG[1962]: Exiting with DIALSTATUS=ANSWER.
Jan 13 17:49:35 VERBOSE[1962]: == Spawn extension (macro-dial, s, 10) exited non-zero on ‘SIP/260-a77e’ in macro ‘dial’
Jan 13 17:49:35 VERBOSE[1962]: == Spawn extension (macro-exten-vm, s, 3) exited non-zero on ‘SIP/260-a77e’ in macro ‘exten-vm’
Jan 13 17:49:35 VERBOSE[1962]: == Spawn extension (from-internal, 216, 1) exited non-zero on ‘SIP/260-a77e’
Jan 13 17:49:35 VERBOSE[1962]: – Executing Macro(“SIP/260-a77e”, “hangupcall”) in new stack
Jan 13 17:49:35 VERBOSE[1962]: – Executing ResetCDR(“SIP/260-a77e”, “w”) in new stack
Jan 13 17:49:35 DEBUG[1962]: cdr_mysql: inserting a CDR record.
Jan 13 17:49:35 DEBUG[1962]: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode) VALUES (‘2006-01-13 17:49:27’,’“John Doe” <260>’,‘260’,‘216’,‘from-internal’, ‘SIP/260-a77e’,‘SIP/216-4b92’,‘ResetCDR’,‘w’,8,5,‘ANSWERED’,3,’’)
Jan 13 17:49:35 VERBOSE[1962]: – Executing NoCDR(“SIP/260-a77e”, “”) in new stack
Jan 13 17:49:35 WARNING[1962]: CDR on channel ‘SIP/260-a77e’ not posted
Jan 13 17:49:35 WARNING[1962]: CDR on channel ‘SIP/260-a77e’ lacks end
Jan 13 17:49:35 VERBOSE[1962]: – Executing Wait(“SIP/260-a77e”, “5”) in new stack
Jan 13 17:49:35 DEBUG[1962]: Auto destroying call 'b8db4ca3-289fa54d-bcbe489c@192.168.10.36’
Jan 13 17:49:35 VERBOSE[1962]: == Spawn extension (macro-hangupcall, s, 3) exited non-zero on ‘SIP/260-a77e’ in macro 'hangupcall’
Jan 13 17:49:35 VERBOSE[1962]: == Spawn extension (from-internal, h, 1) exited non-zero on 'SIP/260-a77e’
Jan 13 17:49:35 DEBUG[1962]: update_user_counter(260) - decrement inUse counter
Jan 13 17:49:36 DEBUG[1962]: Auto destroying call '88424970-ef44167a-ef9a5117@192.168.10.41’
Jan 13 17:49:37 DEBUG[1962]: Setting NAT on RTP to 0
Jan 13 17:49:37 DEBUG[1962]: Stopping retransmission on ‘33b6746613b4411a714b3be249274adf@’ of Request 102: Found[/quote]
I’ll post more information if I can think of any. Right now it seems like a conf misconfiguration error somewhere. Ideas?