Transferred Calls Lost


#1

I’m doing some research on a problem I’ve been seeing in the office. We have a receptionist set up to receive calls on a few numbers. Sporadically, she will receive a call, and forward it to another extension where it will ring twice then disconnect.

We have replaced her phone several times (Grandstream GXP-2000) and the problem keeps coming back. She is also following the correct transfer procedure in the manual. She is the only one having this problem, though she is probably the heaviest user of the transfer function. We are running Asterisk@Home v1.5 on Asterisk v1.0.9.

Any ideas or other information I could provide to help troubleshoot this? Any ideas on what this could be?


#2

Can you replicate the problem? If not turn on debugging and wait for it to happen again. Does it happen with any extension that the receptionist transfers to?


#3

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?


#4

I’ve had this problem too. Try using the attended transfer mode, by hit # to initiate transfers

rgds