rendered paste bodyApr 10 10:49:27 VERBOSE[3518] logger.c: -- Accepting call from '636230XXXX' to '6612' on channel 0/12, span 1
Apr 10 10:49:27 DEBUG[3518] chan_zap.c: No echo cancellation requested
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Macro("Zap/12-1", "exten-vm|6612|6612") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Macro("Zap/12-1", "user-callerid") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is 'XXXXXX,ANNE & B'
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is '636230XXXX'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing NoOp("Zap/12-1", "user-callerid: XXXXXX,ANNE & B 636230XXXX") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '0'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing GotoIf("Zap/12-1", "0?report") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Not taking any branch
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '0'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing GotoIf("Zap/12-1", "0?start") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Not taking any branch
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is '636230XXXX'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "REALCALLERIDNUM=636230XXXX") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing NoOp("Zap/12-1", "REALCALLERIDNUM is 636230XXXX") in new stack
Apr 10 10:49:27 DEBUG[12438] db.c: Unable to find key '636230XXXX/user' in family 'DEVICE'
Apr 10 10:49:27 DEBUG[12438] func_db.c: DB: DEVICE/636230XXXX/user not found in database.
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is ''
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "AMPUSER=") in new stack
Apr 10 10:49:27 DEBUG[12438] db.c: Unable to find key '/cidname' in family 'AMPUSER'
Apr 10 10:49:27 DEBUG[12438] func_db.c: DB: AMPUSER//cidname not found in database.
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is ''
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "AMPUSERCIDNAME=") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '1'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing GotoIf("Zap/12-1", "1?report") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Goto (macro-user-callerid,s,11)
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing NoOp("Zap/12-1", "TTL: ARG1: 6612") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '0'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing GotoIf("Zap/12-1", "0?continue") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Not taking any branch
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '1'
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '-1'
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is '64'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "_TTL=64") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '1'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing GotoIf("Zap/12-1", "1?continue") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Goto (macro-user-callerid,s,21)
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is '"XXXXXX,ANNE & B" <636230XXXX>'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing NoOp("Zap/12-1", "Using CallerID "XXXXXX,ANNE & B" <636230XXXX>") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "FROMCONTEXT=exten-vm") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "VMBOX=6612") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "EXTTOCALL=6612") in new stack
Apr 10 10:49:27 DEBUG[12438] db.c: Unable to find key '6612' in family 'CFU'
Apr 10 10:49:27 DEBUG[12438] func_db.c: DB: CFU/6612 not found in database.
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is ''
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "CFUEXT=") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '1'
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '0'
Apr 10 10:49:27 DEBUG[12438] pbx.c: Expression result is '1'
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is '15'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Set("Zap/12-1", "RT=15") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Macro("Zap/12-1", "record-enable|6612|IN") in new stack
Apr 10 10:49:27 DEBUG[12438] pbx.c: Function result is '0'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing GotoIf("Zap/12-1", "0 > 0?2:4") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Goto (macro-record-enable,s,4)
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing DeadAGI("Zap/12-1", "recordingcheck|20070410-104927|1176220167.11234") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Apr 10 10:49:27 DEBUG[3528] chan_sip.c: Auto destroying call '8e69b678768bdfc3469914a1f6cafe78@192.168.1.134'
Apr 10 10:49:27 DEBUG[3528] chan_sip.c: Auto destroying call '7df4ef251ed553906fb1dc524c3dfec3@192.168.1.142'
Apr 10 10:49:27 VERBOSE[12438] logger.c: recordingcheck|20070410-104927|1176220167.11234: Inbound recording enabled.
Apr 10 10:49:27 VERBOSE[12438] logger.c: recordingcheck|20070410-104927|1176220167.11234: CALLFILENAME=IN6612-20070410-104927-1176220167.11234
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- AGI Script recordingcheck completed, returning 0
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing MixMonitor("Zap/12-1", "IN6612-20070410-104927-1176220167.11234.wav") in new stack
Apr 10 10:49:27 DEBUG[12438] channel.c: Spy MixMonitor added to channel Zap/12-1
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing Macro("Zap/12-1", "dial|15|trwW|6612") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Executing DeadAGI("Zap/12-1", "dialparties.agi") in new stack
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi
Apr 10 10:49:27 VERBOSE[12441] logger.c: == Begin MixMonitor Recording Zap/12-1
Apr 10 10:49:27 VERBOSE[12438] logger.c: dialparties.agi: Starting New Dialparties.agi
Apr 10 10:49:27 VERBOSE[12438] logger.c: dialparties.agi: priority is 1
Apr 10 10:49:27 VERBOSE[12438] logger.c: dialparties.agi: Caller ID name is 'XXXXXX,ANNE & B' number is '636230XXXX'
Apr 10 10:49:27 VERBOSE[12438] logger.c: dialparties.agi: Methodology of ring is 'none'
Apr 10 10:49:27 VERBOSE[12438] logger.c: > dialparties.agi: USE_CONFIRMATION: 'FALSE'
Apr 10 10:49:27 VERBOSE[12438] logger.c: > dialparties.agi: RINGGROUP_INDEX: ''
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- dialparties.agi: Added extension 6612 to extension map
Apr 10 10:49:27 DEBUG[12438] db.c: Unable to find key '6612' in family 'CF'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- dialparties.agi: Extension 6612 cf is disabled
Apr 10 10:49:27 DEBUG[12438] db.c: Unable to find key '6612' in family 'DND'
Apr 10 10:49:27 VERBOSE[12438] logger.c: -- dialparties.agi: Extension 6612 do not disturb is disabled
Apr 10 10:49:27 DEBUG[12438] db.c: Unable to find key '6612' in family 'CFB'
Apr 10 10:49:27 DEBUG[12438] db.c: Unable to find key '6612' in family 'CFU'
Apr 10 10:49:27 VERBOSE[12438] logger.c: > dialparties.agi: extnum: 6612
Apr 10 10:49:27 VERBOSE[12438] logger.c: > dialparties.agi: exthascw: 1
Apr 10 10:49:27 VERBOSE[12438] logger.c: > dialparties.agi: exthascfb: 0
Apr 10 10:49:27 VERBOSE[12438] logger.c: > dialparties.agi: extcfb:
Apr 10 10:49:27 VERBOSE[12438] logger.c: > dialparties.agi: exthascfu: 0
Apr 10 10:49:27 VERBOSE[12438] logger.c: > dialparties.agi: extcfu:
Apr 10 10:49:28 VERBOSE[12438] logger.c: -- dialparties.agi: dbset CALLTRACE/6612 to 636230XXXX
Apr 10 10:49:28 VERBOSE[12438] logger.c: -- AGI Script dialparties.agi completed, returning 0
Apr 10 10:49:28 VERBOSE[12438] logger.c: -- Executing Dial("Zap/12-1", "SIP/6612|15|trwW") in new stack
Apr 10 10:49:28 DEBUG[12438] chan_sip.c: Setting NAT on RTP to 524288
Apr 10 10:49:28 DEBUG[12438] acl.c: ##### Testing 192.168.1.144 with 192.168.1.0
Apr 10 10:49:28 DEBUG[12438] chan_sip.c: Outgoing Call for 6612
Apr 10 10:49:28 VERBOSE[12438] logger.c: -- Called 6612
Apr 10 10:49:28 DEBUG[12438] chan_zap.c: Requested indication 3 on channel Zap/12-1
Apr 10 10:49:28 DEBUG[12438] channel.c: Building translator from ulaw to SLINEAR for spies on channel Zap/12-1
Apr 10 10:49:28 DEBUG[3528] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7c7a5c066d705505186cc4a85d23892e@192.168.1.250' Request 102: Found
Apr 10 10:49:28 DEBUG[3528] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7c7a5c066d705505186cc4a85d23892e@192.168.1.250' Request 102: Found
Apr 10 10:49:28 DEBUG[3528] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '7c7a5c066d705505186cc4a85d23892e@192.168.1.250' Request 102: Found
Apr 10 10:49:28 VERBOSE[12438] logger.c: -- SIP/6612-086e2e18 is ringing
Apr 10 10:49:28 DEBUG[3518] chan_zap.c: Queuing frame from PRI_EVENT_PROGRESS on channel 0/8 span 1
Apr 10 10:49:28 VERBOSE[12431] logger.c: -- Zap/8-1 is making progress passing it to SIP/6609-b7751e30
Apr 10 10:49:28 DEBUG[3528] chan_sip.c: Auto destroying call 'cc5ae228cd72edc046378b5595872cd5@192.168.1.140'
Apr 10 10:49:28 DEBUG[3518] chan_zap.c: No echo cancellation requested
Apr 10 10:49:28 VERBOSE[12431] logger.c: -- Zap/8-1 answered SIP/6609-b7751e30
Apr 10 10:49:29 DEBUG[3528] chan_sip.c: Stopping retransmission on 'b4e2ab1e41f822324c24014743ae76d0@192.168.1.70' of Response 590582078: Match Found
Apr 10 10:49:31 DEBUG[3528] acl.c: ##### Testing 192.168.1.144 with 192.168.1.0
Apr 10 10:49:31 DEBUG[3528] chan_sip.c: Stopping retransmission on '22c17986527c66be1ca574f66b385b13@192.168.1.250' of Request 102: Match Found
Apr 10 10:49:33 DEBUG[3528] chan_sip.c: Auto destroying call 'd7788ceb023e009c24b650a42a4d0ba9@192.168.1.105'
Apr 10 10:49:33 DEBUG[3528] acl.c: ##### Testing 192.168.1.105 with 192.168.1.0
Apr 10 10:49:33 DEBUG[3528] chan_sip.c: Stopping retransmission on '00084b481b589bfc76055c067fd0c65a@192.168.1.250' of Request 102: Match Found
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1206' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1212' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1205' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1204' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1210' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1207' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1203' to 60 seconds (requested 300)
Apr 10 10:49:35 VERBOSE[3519] logger.c: -- Channel 0/9, span 2 got hangup request
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: No echo cancellation requested
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: No echo cancellation requested
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Unlinking slave 11 from 33
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Removed 23 from conference 9/33
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Removed 37 from conference 9/11
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Updated conferencing on 33, with 0 conference users
Apr 10 10:49:35 DEBUG[12250] channel.c: Returning from native bridge, channels: Zap/33-1, Zap/11-1
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/11-1
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Hangup: channel: 11 index = 0, normal = 23, callwait = -1, thirdcall = -1
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/11-1
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Updated conferencing on 11, with 0 conference users
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/11-1
Apr 10 10:49:35 VERBOSE[12250] logger.c: -- Hungup 'Zap/11-1'
Apr 10 10:49:35 DEBUG[12250] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Apr 10 10:49:35 VERBOSE[12250] logger.c: == Spawn extension (custom-to-from-alcatel, 14174488240, 1) exited non-zero on 'Zap/33-1'
Apr 10 10:49:35 DEBUG[12250] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Apr 10 10:49:35 DEBUG[12250] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-04-10 10:46:42','\"Main Fax\" <3142059744>','3142059744','14174488240','custom-to-from-alcatel', 'Zap/33-1','Zap/11-1','Dial','Zap/g0/14174488240',173,168,'ANSWERED',3,'','1176220002.11223')
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/33-1
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Hangup: channel: 33 index = 0, normal = 37, callwait = -1, thirdcall = -1
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/33-1
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Updated conferencing on 33, with 0 conference users
Apr 10 10:49:35 DEBUG[12250] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/33-1
Apr 10 10:49:35 VERBOSE[12250] logger.c: -- Hungup 'Zap/33-1'
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1214' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1211' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1215' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1213' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1209' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1208' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1201' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1202' to 60 seconds (requested 300)
Apr 10 10:49:35 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1200' to 60 seconds (requested 300)
Apr 10 10:49:36 DEBUG[3528] acl.c: ##### Testing 192.168.1.125 with 192.168.1.0
Apr 10 10:49:37 DEBUG[3528] chan_sip.c: Acked pending invite 102
Apr 10 10:49:37 DEBUG[3528] chan_sip.c: Stopping retransmission on '7c7a5c066d705505186cc4a85d23892e@192.168.1.250' of Request 102: Match Found
Apr 10 10:49:37 DEBUG[3528] chan_sip.c: build_route: Contact hop: <sip:6612@192.168.1.144>
Apr 10 10:49:37 VERBOSE[12438] logger.c: -- SIP/6612-086e2e18 answered Zap/12-1
Apr 10 10:49:37 DEBUG[12438] chan_zap.c: Requested indication -1 on channel Zap/12-1
Apr 10 10:49:37 DEBUG[12438] channel.c: Building translator from ulaw to SLINEAR for spies on channel Zap/12-1
Apr 10 10:49:39 DEBUG[3528] acl.c: ##### Testing 192.168.17.59 with 192.168.1.0
Apr 10 10:49:39 DEBUG[3528] chan_sip.c: Target address 192.168.17.59 is not local, substituting externip
Apr 10 10:49:41 DEBUG[3528] chan_sip.c: Auto destroying call '6ee99e0f98baded875aa75bdfb5d674f@192.168.1.144'
Apr 10 10:49:44 DEBUG[3528] acl.c: ##### Testing 192.168.17.59 with 192.168.1.0
Apr 10 10:49:44 DEBUG[3528] chan_sip.c: Target address 192.168.17.59 is not local, substituting externip
Apr 10 10:49:44 DEBUG[3528] chan_sip.c: Stopping retransmission on '3367fd1f5d78c8e034860c7262720087@65.23.24.2' of Request 102: Match Found
Apr 10 10:49:45 DEBUG[3528] acl.c: ##### Testing 192.168.1.130 with 192.168.1.0
Apr 10 10:49:46 DEBUG[3528] acl.c: ##### Testing 192.168.17.59 with 192.168.1.0
Apr 10 10:49:46 DEBUG[3528] chan_sip.c: Target address 192.168.17.59 is not local, substituting externip
Apr 10 10:49:46 DEBUG[3528] chan_sip.c: Stopping retransmission on '076c1f151e18faa47f37d4aa4b6f5a4a@65.23.24.2' of Request 102: Match Found
Apr 10 10:49:47 DEBUG[3528] acl.c: ##### Testing 192.168.17.53 with 192.168.1.0
Apr 10 10:49:47 DEBUG[3528] chan_sip.c: Target address 192.168.17.53 is not local, substituting externip
Apr 10 10:49:48 DEBUG[3528] chan_sip.c: Stopping retransmission on '4d3bc83e43798cae18f753fe2c8c21b5@65.23.24.2' of Request 102: Match Found
Apr 10 10:49:48 DEBUG[12367] channel.c: Didn't get a frame from channel: SIP/6607-b7757670
Apr 10 10:49:48 DEBUG[12367] channel.c: Bridge stops bridging channels SIP/6607-b7757670 and Zap/10-1
Apr 10 10:49:48 DEBUG[12367] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/10-1
Apr 10 10:49:48 DEBUG[12367] chan_zap.c: Hangup: channel: 10 index = 0, normal = 22, callwait = -1, thirdcall = -1
Apr 10 10:49:48 DEBUG[12367] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Apr 10 10:49:48 DEBUG[12367] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/10-1
Apr 10 10:49:48 DEBUG[12367] chan_zap.c: Updated conferencing on 10, with 0 conference users
Apr 10 10:49:48 DEBUG[12367] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/10-1
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Hungup 'Zap/10-1'
Apr 10 10:49:48 DEBUG[12367] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Apr 10 10:49:48 VERBOSE[12367] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/6607-b7757670' in macro 'dialout-trunk'
Apr 10 10:49:48 VERBOSE[12367] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/6607-b7757670'
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Executing Macro("SIP/6607-b7757670", "hangupcall") in new stack
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Executing ResetCDR("SIP/6607-b7757670", "w") in new stack
Apr 10 10:49:48 DEBUG[12367] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Apr 10 10:49:48 DEBUG[12367] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-04-10 10:48:05','\"Donna XX\" <5555555555>','5555555555','96365555555','from-internal', 'SIP/6607-b7757670','Zap/10-1','ResetCDR','w',103,95,'ANSWERED',3,'','1176220085.11230')
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Executing NoCDR("SIP/6607-b7757670", "") in new stack
Apr 10 10:49:48 NOTICE[12367] cdr.c: CDR on channel 'SIP/6607-b7757670' not posted
Apr 10 10:49:48 NOTICE[12367] cdr.c: CDR on channel 'SIP/6607-b7757670' lacks end
Apr 10 10:49:48 DEBUG[12367] pbx.c: Expression result is '1'
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Executing GotoIf("SIP/6607-b7757670", "1?skiprg") in new stack
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Goto (macro-hangupcall,s,6)
Apr 10 10:49:48 DEBUG[12367] pbx.c: Expression result is '1'
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Executing GotoIf("SIP/6607-b7757670", "1?theend") in new stack
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Goto (macro-hangupcall,s,9)
Apr 10 10:49:48 VERBOSE[12367] logger.c: -- Executing Wait("SIP/6607-b7757670", "5") in new stack
Apr 10 10:49:48 VERBOSE[12367] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/6607-b7757670' in macro 'hangupcall'
Apr 10 10:49:48 VERBOSE[12367] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/6607-b7757670'
Apr 10 10:49:48 DEBUG[12367] chan_sip.c: update_call_counter(6607) - decrement call limit counter
Apr 10 10:49:49 DEBUG[3528] acl.c: ##### Testing 192.168.1.131 with 192.168.1.0
Apr 10 10:49:49 DEBUG[3528] acl.c: ##### Testing 192.168.1.130 with 192.168.1.0
Apr 10 10:49:49 DEBUG[3528] chan_sip.c: Stopping retransmission on '7498e8731afaa4ab079691fa7f816dbf@192.168.1.250' of Request 102: Match Found
Apr 10 10:49:51 DEBUG[3528] chan_sip.c: Auto destroying call '917d85032f34a0f43ae7ba7ec6046fa2@192.168.1.125'
Apr 10 10:49:51 DEBUG[3528] acl.c: ##### Testing 192.168.1.131 with 192.168.1.0
Apr 10 10:49:51 DEBUG[3528] chan_sip.c: Stopping retransmission on '10451f9b3b393999497dbd621e1f02f0@192.168.1.250' of Request 102: Match Found
Apr 10 10:49:51 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:49:51 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:49:52 DEBUG[12431] channel.c: Didn't get a frame from channel: SIP/6609-b7751e30
Apr 10 10:49:52 DEBUG[12431] channel.c: Bridge stops bridging channels SIP/6609-b7751e30 and Zap/8-1
Apr 10 10:49:52 DEBUG[12431] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/8-1
Apr 10 10:49:52 DEBUG[12431] chan_zap.c: Hangup: channel: 8 index = 0, normal = 20, callwait = -1, thirdcall = -1
Apr 10 10:49:52 DEBUG[12431] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Apr 10 10:49:52 DEBUG[12431] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/8-1
Apr 10 10:49:52 DEBUG[12431] chan_zap.c: Updated conferencing on 8, with 0 conference users
Apr 10 10:49:52 DEBUG[12431] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/8-1
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Hungup 'Zap/8-1'
Apr 10 10:49:52 DEBUG[12431] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Apr 10 10:49:52 VERBOSE[12431] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/6609-b7751e30' in macro 'dialout-trunk'
Apr 10 10:49:52 VERBOSE[12431] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/6609-b7751e30'
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Executing Macro("SIP/6609-b7751e30", "hangupcall") in new stack
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Executing ResetCDR("SIP/6609-b7751e30", "w") in new stack
Apr 10 10:49:52 DEBUG[12431] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Apr 10 10:49:52 DEBUG[12431] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-04-10 10:49:25','\"Johanna XX\" <314392xxxx>','314392xxxx','9520xxxx','from-internal', 'SIP/6609-b7751e30','Zap/8-1','ResetCDR','w',27,24,'ANSWERED',3,'','1176220165.11232')
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Executing NoCDR("SIP/6609-b7751e30", "") in new stack
Apr 10 10:49:52 NOTICE[12431] cdr.c: CDR on channel 'SIP/6609-b7751e30' not posted
Apr 10 10:49:52 NOTICE[12431] cdr.c: CDR on channel 'SIP/6609-b7751e30' lacks end
Apr 10 10:49:52 DEBUG[12431] pbx.c: Expression result is '1'
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Executing GotoIf("SIP/6609-b7751e30", "1?skiprg") in new stack
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Goto (macro-hangupcall,s,6)
Apr 10 10:49:52 DEBUG[12431] pbx.c: Expression result is '1'
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Executing GotoIf("SIP/6609-b7751e30", "1?theend") in new stack
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Goto (macro-hangupcall,s,9)
Apr 10 10:49:52 VERBOSE[12431] logger.c: -- Executing Wait("SIP/6609-b7751e30", "5") in new stack
Apr 10 10:49:52 VERBOSE[12431] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/6609-b7751e30' in macro 'hangupcall'
Apr 10 10:49:52 VERBOSE[12431] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/6609-b7751e30'
Apr 10 10:49:52 DEBUG[12431] chan_sip.c: update_call_counter(6609) - decrement call limit counter
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 2, historicms 2, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 2, historicms 2, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 2, historicms 2, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 2, historicms 2, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 4, historicms 4, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 4, historicms 4, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 4, historicms 4, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 4, historicms 4, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 4, historicms 4, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 4, historicms 4, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 4, historicms 4, maxms 2000
Apr 10 10:49:52 DEBUG[3527] chan_iax2.c: Peer lastms 4, historicms 4, maxms 2000
Apr 10 10:49:55 DEBUG[3528] chan_sip.c: Auto destroying call 'a517f56ccc24ef33f77b62fcb42db4be@192.168.17.59'
Apr 10 10:49:57 DEBUG[3528] acl.c: ##### Testing 192.168.1.139 with 192.168.1.0
Apr 10 10:49:57 DEBUG[3528] acl.c: ##### Testing 192.168.1.124 with 192.168.1.0
Apr 10 10:49:58 DEBUG[3528] acl.c: ##### Testing 192.168.1.141 with 192.168.1.0
Apr 10 10:49:59 DEBUG[3528] acl.c: ##### Testing 192.168.1.95 with 192.168.1.0
Apr 10 10:49:59 DEBUG[3528] chan_sip.c: Stopping retransmission on '4953914d620df01f47691eeb1f31f1ee@192.168.1.250' of Request 102: Match Found
Apr 10 10:49:59 DEBUG[3528] acl.c: ##### Testing 192.168.17.53 with 192.168.1.0
Apr 10 10:49:59 DEBUG[3528] chan_sip.c: Target address 192.168.17.53 is not local, substituting externip
Apr 10 10:50:00 DEBUG[3528] chan_sip.c: Auto destroying call 'afc3732a639efdd863e03f0410c61698@192.168.1.130'
Apr 10 10:50:00 DEBUG[3528] acl.c: ##### Testing 192.168.1.139 with 192.168.1.0
Apr 10 10:50:00 DEBUG[3528] chan_sip.c: Stopping retransmission on '53821e7c0e9e13571c366eef46743f7e@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:02 DEBUG[3528] acl.c: ##### Testing 192.168.1.124 with 192.168.1.0
Apr 10 10:50:02 DEBUG[3528] chan_sip.c: Stopping retransmission on '70db054c5fd3d8306a2547106a7c11f6@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:04 DEBUG[3528] acl.c: ##### Testing 192.168.1.141 with 192.168.1.0
Apr 10 10:50:04 DEBUG[3528] chan_sip.c: Auto destroying call '4544d9086c7efad437d391a83ed8632a@192.168.1.131'
Apr 10 10:50:04 DEBUG[3528] chan_sip.c: Stopping retransmission on '625633747d50d81f04e76a1a0468d7d9@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:04 DEBUG[3528] acl.c: ##### Testing 192.168.1.98 with 192.168.1.0
Apr 10 10:50:04 DEBUG[3528] chan_sip.c: Stopping retransmission on '01f3ac9d3d2ce63606aaa39924c9a689@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:06 DEBUG[3528] acl.c: ##### Testing 192.168.1.70 with 192.168.1.0
Apr 10 10:50:06 DEBUG[3528] chan_sip.c: Setting NAT on RTP to 524288
Apr 10 10:50:06 DEBUG[3528] chan_sip.c: Stopping retransmission on 'fe33db85bc360a772aade612b18436f6@192.168.1.70' of Response 1417328659: Match Found
Apr 10 10:50:06 DEBUG[3528] chan_sip.c: Setting NAT on RTP to 524288
Apr 10 10:50:06 DEBUG[3528] chan_sip.c: Checking SIP call limits for device 6609
Apr 10 10:50:06 DEBUG[3528] chan_sip.c: build_route: Contact hop: sip:6609@192.168.1.70
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Macro("SIP/6609-b7754a50", "dialout-trunk|1|18664506891|") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "DIAL_TRUNK=1") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "_NODEST=") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "DIAL_NUMBER=18664506891") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "ROUTE_PASSWD=") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "DIAL_TRUNK_OPTIONS=trwW") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Expression result is '1'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "1?noauth") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Goto (macro-dialout-trunk,s,8)
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "GROUP()=OUT_1") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Macro("SIP/6609-b7754a50", "user-callerid|SKIPTTL") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is 'device'
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is '6609'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing NoOp("SIP/6609-b7754a50", "user-callerid: device 6609") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Expression result is '0'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "0?report") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Not taking any branch
Apr 10 10:50:06 DEBUG[12625] pbx.c: Expression result is '0'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "0?start") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Not taking any branch
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is '6609'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "REALCALLERIDNUM=6609") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing NoOp("SIP/6609-b7754a50", "REALCALLERIDNUM is 6609") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is '6609'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "AMPUSER=6609") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is 'Johanna XX'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "AMPUSERCIDNAME=Johanna XX") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Expression result is '0'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "0?report") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Not taking any branch
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "CALLERID(all)=Johanna XX <6609>") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is '6609'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "REALCALLERIDNUM=6609") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing NoOp("SIP/6609-b7754a50", "TTL: ARG1: SKIPTTL") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Expression result is '1'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "1?continue") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Goto (macro-user-callerid,s,21)
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is '"Johanna XX" <6609>'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing NoOp("SIP/6609-b7754a50", "Using CallerID "Johanna XX" <6609>") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is '6609'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing Macro("SIP/6609-b7754a50", "record-enable|6609|OUT") in new stack
Apr 10 10:50:06 DEBUG[12625] pbx.c: Function result is '0'
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "0 > 0?2:4") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Goto (macro-record-enable,s,4)
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Executing DeadAGI("SIP/6609-b7754a50", "recordingcheck|20070410-105006|1176220206.11236") in new stack
Apr 10 10:50:06 VERBOSE[12625] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck
Apr 10 10:50:07 VERBOSE[12625] logger.c: recordingcheck|20070410-105006|1176220206.11236: Outbound recording not enabled
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- AGI Script recordingcheck completed, returning 0
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing NoOp("SIP/6609-b7754a50", "No recording needed") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '0'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "0?skipoutcid") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Not taking any branch
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "DIAL_TRUNK_OPTIONS=wW") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Macro("SIP/6609-b7754a50", "outbound-callerid|1") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '1'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "1?start") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Goto (macro-outbound-callerid,s,3)
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing NoOp("SIP/6609-b7754a50", "REALCALLERIDNUM is 6609") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '1'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "1?normcid") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Goto (macro-outbound-callerid,s,9)
Apr 10 10:50:07 DEBUG[12625] pbx.c: Function result is '"Johanna XX" <3143926609>'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "USEROUTCID="Johanna XX" <3143926609>") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Function result is '"Frontier Mortgage" <3142052900>'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "EMERGENCYCID="Frontier Mortgage" <3142052900>") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "TRUNKOUTCID=") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '1'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "1?trunkcid") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Goto (macro-outbound-callerid,s,16)
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '1'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "1?usercid") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Goto (macro-outbound-callerid,s,18)
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '0'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "0?report") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Not taking any branch
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "CALLERID(all)="Johanna XX" <3143926609>") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Function result is 'Johanna XX'
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '1'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "1?report:hidecid") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Goto (macro-outbound-callerid,s,22)
Apr 10 10:50:07 DEBUG[12625] pbx.c: Function result is '"Johanna XX" <3143926609>'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing NoOp("SIP/6609-b7754a50", "CallerID set to "Johanna XX" <3143926609>") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '1'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "1?nomax") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Goto (macro-dialout-trunk,s,16)
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing DeadAGI("SIP/6609-b7754a50", "fixlocalprefix") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Launched AGI Script /var/lib/asterisk/agi-bin/fixlocalprefix
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- AGI Script fixlocalprefix completed, returning 0
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "OUTNUM=18664506891") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Function result is 'ZAP/g0'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Set("SIP/6609-b7754a50", "custom=ZAP/g0") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Expression result is '0'
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing GotoIf("SIP/6609-b7754a50", "0?customtrunk") in new stack
Apr 10 10:50:07 DEBUG[12625] pbx.c: Not taking any branch
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Executing Dial("SIP/6609-b7754a50", "ZAP/g0/18664506891|300|wW") in new stack
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Requested transfer capability: 0x00 - SPEECH
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Called g0/18664506891
Apr 10 10:50:07 DEBUG[3518] chan_zap.c: Queuing frame from PRI_EVENT_PROCEEDING on channel 0/8 span 1
Apr 10 10:50:07 VERBOSE[12625] logger.c: -- Zap/8-1 is proceeding passing it to SIP/6609-b7754a50
Apr 10 10:50:07 DEBUG[3528] acl.c: ##### Testing 192.168.1.148 with 192.168.1.0
Apr 10 10:50:08 DEBUG[3528] chan_sip.c: Stopping retransmission on '027bf6024bcf87502ddd776f7546965b@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:08 DEBUG[3528] acl.c: ##### Testing 192.168.17.53 with 192.168.1.0
Apr 10 10:50:08 DEBUG[3528] chan_sip.c: Target address 192.168.17.53 is not local, substituting externip
Apr 10 10:50:08 DEBUG[3528] chan_sip.c: Stopping retransmission on '49b60780471091960fda75f64b02191e@65.23.24.2' of Request 102: Match Found
Apr 10 10:50:08 DEBUG[3518] chan_zap.c: Queuing frame from PRI_EVENT_PROGRESS on channel 0/8 span 1
Apr 10 10:50:08 VERBOSE[12625] logger.c: -- Zap/8-1 is making progress passing it to SIP/6609-b7754a50
Apr 10 10:50:09 DEBUG[3528] acl.c: ##### Testing 192.168.1.125 with 192.168.1.0
Apr 10 10:50:09 DEBUG[3528] chan_sip.c: Stopping retransmission on '105692e04cbd9adc221bf6d724067487@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:10 DEBUG[3528] acl.c: ##### Testing 192.168.1.131 with 192.168.1.0
Apr 10 10:50:10 DEBUG[3528] chan_sip.c: Stopping retransmission on '315fda92657704a653344fa7358a831c@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:10 DEBUG[3528] acl.c: ##### Testing 192.168.1.127 with 192.168.1.0
Apr 10 10:50:10 DEBUG[3528] chan_sip.c: Stopping retransmission on '205167b211fff4b513f3a15251208789@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:10 DEBUG[3528] acl.c: ##### Testing 192.168.1.94 with 192.168.1.0
Apr 10 10:50:10 DEBUG[3528] chan_sip.c: Stopping retransmission on '69827047614463670ca270975da2aec1@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.138 with 192.168.1.0
Apr 10 10:50:11 DEBUG[3528] chan_sip.c: Stopping retransmission on '387b3fd72dc1d632423a5e7b4a2807bb@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.124 with 192.168.1.0
Apr 10 10:50:11 DEBUG[3528] chan_sip.c: Stopping retransmission on '3e47860609499f2427cdd6bf54f021b1@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:11 DEBUG[3518] chan_zap.c: No echo cancellation requested
Apr 10 10:50:11 VERBOSE[12625] logger.c: -- Zap/8-1 answered SIP/6609-b7754a50
Apr 10 10:50:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.134 with 192.168.1.0
Apr 10 10:50:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.137 with 192.168.1.0
Apr 10 10:50:11 DEBUG[3528] chan_sip.c: Stopping retransmission on '546cea20694e63f35e03b5f63cde4f09@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:11 DEBUG[3528] chan_sip.c: Stopping retransmission on '36e6ed1a69c2485621850dab5db0aada@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:11 DEBUG[3528] chan_sip.c: Stopping retransmission on 'fe33db85bc360a772aade612b18436f6@192.168.1.70' of Response 1417328660: Match Found
Apr 10 10:50:12 DEBUG[3528] acl.c: ##### Testing 192.168.1.130 with 192.168.1.0
Apr 10 10:50:12 DEBUG[3528] chan_sip.c: Stopping retransmission on '3d8b6ca9155697cb11eb69765d54aa60@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:12 DEBUG[3528] chan_sip.c: Auto destroying call 'c5f361b263dfb8bc832381b4f087b3a2@192.168.1.139'
Apr 10 10:50:12 DEBUG[3528] acl.c: ##### Testing 192.168.1.142 with 192.168.1.0
Apr 10 10:50:12 DEBUG[3528] chan_sip.c: Auto destroying call '8bf36f21532187fe8fd9082970a8df69@192.168.1.124'
Apr 10 10:50:12 DEBUG[3528] chan_sip.c: Stopping retransmission on '7fbff88c4685607e719745af2f87694d@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:12 DEBUG[3528] acl.c: ##### Testing 192.168.1.139 with 192.168.1.0
Apr 10 10:50:12 DEBUG[3528] chan_sip.c: Stopping retransmission on '04be263d0bfc7c3c5f9a0e3846239bd0@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:12 DEBUG[3528] acl.c: ##### Testing 192.168.1.70 with 192.168.1.0
Apr 10 10:50:12 DEBUG[3528] chan_sip.c: Stopping retransmission on '0ff5e3d52e3ebf685c54945b7621cdcf@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:13 DEBUG[3528] acl.c: ##### Testing 192.168.1.144 with 192.168.1.0
Apr 10 10:50:13 DEBUG[3528] chan_sip.c: Stopping retransmission on '00334a270668443940978c8a73e08025@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:13 DEBUG[3528] chan_sip.c: Auto destroying call '69cba4ebf4864e10872807a72f682739@192.168.1.141'
Apr 10 10:50:15 DEBUG[3528] chan_sip.c: Auto destroying call 'e3b53ddfb5a7df5caf9e8fe0fa50d604@192.168.17.53'
Apr 10 10:50:15 DEBUG[3528] acl.c: ##### Testing 192.168.1.141 with 192.168.1.0
Apr 10 10:50:15 DEBUG[12625] channel.c: Got DTMF on channel (SIP/6609-b7754a50)
Apr 10 10:50:15 DEBUG[12625] channel.c: Bridge stops bridging channels SIP/6609-b7754a50 and Zap/8-1
Apr 10 10:50:15 DEBUG[12625] res_features.c: Feature interpret: chan=SIP/6609-b7754a50, peer=Zap/8-1, sense=1, features=16
Apr 10 10:50:15 DEBUG[3528] chan_sip.c: Stopping retransmission on '2346434032ac117d54767cfb09c12426@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:15 DEBUG[3527] chan_iax2.c: Peer lastms 762, historicms 762, maxms 2000
Apr 10 10:50:16 DEBUG[12625] chan_zap.c: Exception on 20, channel 8
Apr 10 10:50:16 DEBUG[12625] chan_zap.c: Got event Dial Complete(9) on channel 8 (index 0)
Apr 10 10:50:16 DEBUG[12625] chan_zap.c: No echo cancellation requested
Apr 10 10:50:16 DEBUG[3528] acl.c: ##### Testing 192.168.1.140 with 192.168.1.0
Apr 10 10:50:16 DEBUG[3528] chan_sip.c: Stopping retransmission on '7d629bdd1ebf1d3f5ce9bf9243ba0613@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:16 DEBUG[3528] acl.c: ##### Testing 192.168.1.126 with 192.168.1.0
Apr 10 10:50:16 DEBUG[3528] chan_sip.c: Stopping retransmission on '61a0ac6c6e0101d336b3a2503e3483e5@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:16 DEBUG[3528] acl.c: ##### Testing 192.168.1.129 with 192.168.1.0
Apr 10 10:50:16 DEBUG[3528] chan_sip.c: Stopping retransmission on '045742c21c8e0377526b3b276fa4f150@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:17 DEBUG[3528] acl.c: ##### Testing 192.168.1.148 with 192.168.1.0
Apr 10 10:50:17 DEBUG[3528] acl.c: ##### Testing 192.168.1.137 with 192.168.1.0
Apr 10 10:50:22 DEBUG[3528] acl.c: ##### Testing 192.168.1.148 with 192.168.1.0
Apr 10 10:50:22 DEBUG[3528] chan_sip.c: Stopping retransmission on '77ce72527801bc797e6a00b23f018d3d@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:24 DEBUG[3528] acl.c: ##### Testing 192.168.1.138 with 192.168.1.0
Apr 10 10:50:26 DEBUG[3528] acl.c: ##### Testing 192.168.1.137 with 192.168.1.0
Apr 10 10:50:26 DEBUG[3528] chan_sip.c: Stopping retransmission on '114f947265c6116d6f8735931f6e411f@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1206' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1212' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1205' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1204' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1210' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1207' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1203' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1214' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1211' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1215' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1213' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1209' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1208' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1201' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1202' to 60 seconds (requested 300)
Apr 10 10:50:30 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1200' to 60 seconds (requested 300)
Apr 10 10:50:32 DEBUG[3528] chan_sip.c: Auto destroying call '0845c71d497335a28f66ec309174ac2f@192.168.1.148'
Apr 10 10:50:32 DEBUG[3528] chan_sip.c: Auto destroying call '3189050da29b57f266ea465194a60449@192.168.1.137'
Apr 10 10:50:33 DEBUG[3528] acl.c: ##### Testing 192.168.1.105 with 192.168.1.0
Apr 10 10:50:34 DEBUG[3528] chan_sip.c: Stopping retransmission on '437529d356be0191249cf7d2773a1450@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:35 DEBUG[3528] acl.c: ##### Testing 192.168.1.138 with 192.168.1.0
Apr 10 10:50:35 DEBUG[3528] chan_sip.c: Stopping retransmission on '778282004ff4712e636c227f06d9b7a5@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:39 DEBUG[3528] chan_sip.c: Auto destroying call '0e33d771f6bd982685d48795c519ba1d@192.168.1.138'
Apr 10 10:50:43 DEBUG[3528] acl.c: ##### Testing 192.168.1.129 with 192.168.1.0
Apr 10 10:50:44 DEBUG[3528] acl.c: ##### Testing 192.168.1.98 with 192.168.1.0
Apr 10 10:50:45 DEBUG[3528] acl.c: ##### Testing 192.168.1.127 with 192.168.1.0
Apr 10 10:50:46 DEBUG[3528] acl.c: ##### Testing 192.168.1.129 with 192.168.1.0
Apr 10 10:50:46 DEBUG[3528] chan_sip.c: Stopping retransmission on '5d02d9e171045ec8086d38f85a24558d@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:46 DEBUG[3528] acl.c: ##### Testing 192.168.1.131 with 192.168.1.0
Apr 10 10:50:46 DEBUG[3528] chan_sip.c: Setting NAT on RTP to 524288
Apr 10 10:50:46 DEBUG[3528] chan_sip.c: Stopping retransmission on 'cee293ef2358df109559aa0936dd69b5@192.168.1.131' of Response 1300216081: Match Found
Apr 10 10:50:46 DEBUG[3528] chan_sip.c: Setting NAT on RTP to 524288
Apr 10 10:50:46 DEBUG[3528] chan_sip.c: Checking SIP call limits for device 6627
Apr 10 10:50:46 DEBUG[3528] chan_sip.c: build_route: Contact hop: sip:6627@192.168.1.131
Apr 10 10:50:46 VERBOSE[12809] logger.c: -- Executing Answer("SIP/6627-b774c8c0", "") in new stack
Apr 10 10:50:46 VERBOSE[12809] logger.c: -- Executing Wait("SIP/6627-b774c8c0", "1") in new stack
Apr 10 10:50:46 DEBUG[3528] acl.c: ##### Testing 192.168.17.59 with 192.168.1.0
Apr 10 10:50:46 DEBUG[3528] chan_sip.c: Target address 192.168.17.59 is not local, substituting externip
Apr 10 10:50:47 DEBUG[3528] chan_sip.c: Stopping retransmission on '54ea3ed137eb1f7377d5bfa77b7a65ef@65.23.24.2' of Request 102: Match Found
Apr 10 10:50:47 DEBUG[3528] chan_sip.c: Stopping retransmission on 'cee293ef2358df109559aa0936dd69b5@192.168.1.131' of Response 1300216082: Match Found
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Macro("SIP/6627-b774c8c0", "user-callerid|") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is 'device'
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is '6627'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing NoOp("SIP/6627-b774c8c0", "user-callerid: device 6627") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Expression result is '0'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing GotoIf("SIP/6627-b774c8c0", "0?report") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Not taking any branch
Apr 10 10:50:47 DEBUG[12809] pbx.c: Expression result is '0'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing GotoIf("SIP/6627-b774c8c0", "0?start") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Not taking any branch
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is '6627'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Set("SIP/6627-b774c8c0", "REALCALLERIDNUM=6627") in new stack
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing NoOp("SIP/6627-b774c8c0", "REALCALLERIDNUM is 6627") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is '6627'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Set("SIP/6627-b774c8c0", "AMPUSER=6627") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is 'Kadi Williams'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Set("SIP/6627-b774c8c0", "AMPUSERCIDNAME=Kadi Williams") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Expression result is '0'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing GotoIf("SIP/6627-b774c8c0", "0?report") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Not taking any branch
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Set("SIP/6627-b774c8c0", "CALLERID(all)=Kadi Williams <6627>") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is '6627'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Set("SIP/6627-b774c8c0", "REALCALLERIDNUM=6627") in new stack
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing NoOp("SIP/6627-b774c8c0", "TTL: ARG1: ") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Expression result is '0'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing GotoIf("SIP/6627-b774c8c0", "0?continue") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Not taking any branch
Apr 10 10:50:47 DEBUG[12809] pbx.c: Expression result is '1'
Apr 10 10:50:47 DEBUG[12809] pbx.c: Expression result is '-1'
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is '64'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Set("SIP/6627-b774c8c0", "_TTL=64") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Expression result is '1'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing GotoIf("SIP/6627-b774c8c0", "1?continue") in new stack
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Goto (macro-user-callerid,s,21)
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is '"Kadi Williams" <6627>'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing NoOp("SIP/6627-b774c8c0", "Using CallerID "Kadi Williams" <6627>") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is '6627'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Macro("SIP/6627-b774c8c0", "get-vmcontext|6627") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is 'default'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing Set("SIP/6627-b774c8c0", "VMCONTEXT=default") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Expression result is '0'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing GotoIf("SIP/6627-b774c8c0", "0?200:300") in new stack
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Goto (macro-get-vmcontext,s,300)
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing NoOp("SIP/6627-b774c8c0", "") in new stack
Apr 10 10:50:47 DEBUG[12809] pbx.c: Function result is '6627'
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Executing VoiceMailMain("SIP/6627-b774c8c0", "6627@default") in new stack
Apr 10 10:50:47 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:50:47 VERBOSE[12809] logger.c: -- Playing 'vm-password' (language 'en')
Apr 10 10:50:48 DEBUG[3528] acl.c: ##### Testing 192.168.17.53 with 192.168.1.0
Apr 10 10:50:48 DEBUG[3528] chan_sip.c: Target address 192.168.17.53 is not local, substituting externip
Apr 10 10:50:48 DEBUG[3528] acl.c: ##### Testing 192.168.1.127 with 192.168.1.0
Apr 10 10:50:48 DEBUG[3528] chan_sip.c: Stopping retransmission on '781457072d00f13d3458c6992b558d46@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:48 DEBUG[3528] chan_sip.c: Stopping retransmission on '41c6730d251331113f139166174875a0@65.23.24.2' of Request 102: Match Found
Apr 10 10:50:48 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:49 DEBUG[3528] acl.c: ##### Testing 192.168.1.70 with 192.168.1.0
Apr 10 10:50:51 DEBUG[12809] app.c: Locked path '/var/spool/asterisk/voicemail/default/6627/Old'
Apr 10 10:50:51 DEBUG[12809] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/6627/Old'
Apr 10 10:50:51 DEBUG[12809] app.c: Locked path '/var/spool/asterisk/voicemail/default/6627/Old'
Apr 10 10:50:51 DEBUG[12809] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/6627/Old'
Apr 10 10:50:51 DEBUG[12809] app.c: Locked path '/var/spool/asterisk/voicemail/default/6627/INBOX'
Apr 10 10:50:51 DEBUG[12809] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/6627/INBOX'
Apr 10 10:50:51 DEBUG[12809] app.c: Locked path '/var/spool/asterisk/voicemail/default/6627/INBOX'
Apr 10 10:50:51 DEBUG[12809] app.c: Unlocked path '/var/spool/asterisk/voicemail/default/6627/INBOX'
Apr 10 10:50:51 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:50:51 VERBOSE[12809] logger.c: -- Playing 'vm-youhave' (language 'en')
Apr 10 10:50:51 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:51 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 1, historicms 1, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 1, historicms 1, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 1, historicms 1, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 1, historicms 1, maxms 2000
Apr 10 10:50:52 DEBUG[3527] chan_iax2.c: Peer lastms 1, historicms 1, maxms 2000
Apr 10 10:50:52 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:50:52 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:52 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:52 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:50:52 VERBOSE[12809] logger.c: -- Playing 'digits/5' (language 'en')
Apr 10 10:50:53 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:50:53 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:53 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:53 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:50:53 VERBOSE[12809] logger.c: -- Playing 'vm-INBOX' (language 'en')
Apr 10 10:50:53 DEBUG[3528] acl.c: ##### Testing 192.168.1.126 with 192.168.1.0
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:50:54 VERBOSE[12809] logger.c: -- Playing 'vm-messages' (language 'en')
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:50:54 VERBOSE[12809] logger.c: -- Playing 'vm-first' (language 'en')
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:54 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:50:54 VERBOSE[12809] logger.c: -- Playing 'vm-message' (language 'en')
Apr 10 10:50:55 DEBUG[3528] acl.c: ##### Testing 192.168.1.126 with 192.168.1.0
Apr 10 10:50:55 DEBUG[3528] acl.c: ##### Testing 192.168.1.70 with 192.168.1.0
Apr 10 10:50:55 DEBUG[3528] chan_sip.c: Stopping retransmission on '3aabd59714c23fd521bab7756cc6f7bb@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:55 DEBUG[3528] chan_sip.c: Stopping retransmission on '6281b7e25dbe0bdd3ec071450f4a0c40@192.168.1.250' of Request 102: Match Found
Apr 10 10:50:55 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:50:55 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:55 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:50:55 VERBOSE[12809] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0000.txt': Apr 10 10:50:55 VERBOSE[12809] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0000.txt': Found
Apr 10 10:50:55 DEBUG[12809] app_voicemail.c: VM-Duration: duration is: 50 seconds converted to: 0 minutes
Apr 10 10:50:55 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:50:55 VERBOSE[12809] logger.c: -- Playing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0000' (language 'en')
Apr 10 10:50:57 DEBUG[3528] acl.c: ##### Testing 192.168.1.134 with 192.168.1.0
Apr 10 10:50:57 DEBUG[3528] acl.c: ##### Testing 192.168.1.142 with 192.168.1.0
Apr 10 10:50:58 DEBUG[29525] manager.c: Manager received command 'Command'
Apr 10 10:50:58 DEBUG[29525] manager.c: Manager received command 'Command'
Apr 10 10:50:58 DEBUG[29525] manager.c: Manager received command 'Command'
Apr 10 10:50:58 DEBUG[3528] acl.c: ##### Testing 192.168.1.140 with 192.168.1.0
Apr 10 10:50:58 DEBUG[3528] chan_sip.c: Auto destroying call '4e90f2d4d74df2e8be5d4f1ae215d6db@192.168.1.129'
Apr 10 10:50:59 DEBUG[3528] chan_sip.c: Auto destroying call 'a836e7e7cf68d21391715154429acc57@192.168.1.98'
Apr 10 10:50:59 DEBUG[3528] acl.c: ##### Testing 192.168.1.95 with 192.168.1.0
Apr 10 10:50:59 DEBUG[3528] chan_sip.c: Stopping retransmission on '039e14cc3c6dbbe408e872c14aaee5cf@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:00 DEBUG[3528] chan_sip.c: Auto destroying call '378de9a7fa4c0375b1fd4a7ac4203d66@192.168.1.127'
Apr 10 10:51:00 DEBUG[3528] acl.c: ##### Testing 192.168.1.142 with 192.168.1.0
Apr 10 10:51:00 DEBUG[3528] chan_sip.c: Stopping retransmission on '57b3748b2361e0d90317a1227b2bf82a@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:01 DEBUG[3528] acl.c: ##### Testing 192.168.1.140 with 192.168.1.0
Apr 10 10:51:01 DEBUG[3528] chan_sip.c: Stopping retransmission on '682ff619778acee95f6bb3ec4dd38e0b@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:02 DEBUG[3528] acl.c: ##### Testing 192.168.1.134 with 192.168.1.0
Apr 10 10:51:02 DEBUG[3528] chan_sip.c: Stopping retransmission on '0855f4bc0b4211052ad9099c6584df34@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:03 DEBUG[3528] acl.c: ##### Testing 192.168.1.105 with 192.168.1.0
Apr 10 10:51:04 DEBUG[3528] acl.c: ##### Testing 192.168.1.98 with 192.168.1.0
Apr 10 10:51:04 DEBUG[3528] chan_sip.c: Auto destroying call 'b48bd5b2da945af736c7c446cd84913a@192.168.1.70'
Apr 10 10:51:04 DEBUG[3528] chan_sip.c: Stopping retransmission on '365e6489141c706652dce1ab6226edeb@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:05 DEBUG[3528] acl.c: ##### Testing 192.168.1.105 with 192.168.1.0
Apr 10 10:51:06 DEBUG[3528] chan_sip.c: Stopping retransmission on '15e47c9819da4a4015a5d7900cebcacf@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:08 DEBUG[3528] acl.c: ##### Testing 192.168.1.148 with 192.168.1.0
Apr 10 10:51:08 DEBUG[3528] chan_sip.c: Stopping retransmission on '645cd8ee2f0bbebd1ecdd59d4da37de4@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:08 DEBUG[3528] chan_sip.c: Auto destroying call '4d3be638714f87d481544b8e7c500f4c@192.168.1.126'
Apr 10 10:51:09 DEBUG[3528] acl.c: ##### Testing 192.168.1.125 with 192.168.1.0
Apr 10 10:51:10 DEBUG[3528] chan_sip.c: Stopping retransmission on '66224ec4614e46ee097b30556600e055@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:10 DEBUG[3528] acl.c: ##### Testing 192.168.1.131 with 192.168.1.0
Apr 10 10:51:10 DEBUG[3528] chan_sip.c: Stopping retransmission on '7a98188d617d2c8b579847dd076dc42a@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:10 DEBUG[3528] acl.c: ##### Testing 192.168.1.127 with 192.168.1.0
Apr 10 10:51:10 DEBUG[3528] chan_sip.c: Stopping retransmission on '080c0413240dda912cd6a8cb7f6948a1@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:10 DEBUG[3528] acl.c: ##### Testing 192.168.1.94 with 192.168.1.0
Apr 10 10:51:10 DEBUG[3528] chan_sip.c: Stopping retransmission on '17de62867a0550725b6e26b941dd5d3a@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.144 with 192.168.1.0
Apr 10 10:51:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.138 with 192.168.1.0
Apr 10 10:51:11 DEBUG[3528] chan_sip.c: Stopping retransmission on '4d0674913c0ecfb457776530767e0f78@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.124 with 192.168.1.0
Apr 10 10:51:11 DEBUG[3528] chan_sip.c: Stopping retransmission on '2222d6a9283f799e1034d1db4fdd9ea4@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.134 with 192.168.1.0
Apr 10 10:51:11 DEBUG[3528] acl.c: ##### Testing 192.168.1.137 with 192.168.1.0
Apr 10 10:51:11 DEBUG[3528] chan_sip.c: Stopping retransmission on '38f5b3432693c4d57c61cc8049baa315@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:11 DEBUG[3528] chan_sip.c: Stopping retransmission on '2236c839145bb36e11c2afa83a02b57e@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:12 DEBUG[3528] acl.c: ##### Testing 192.168.1.130 with 192.168.1.0
Apr 10 10:51:12 DEBUG[3528] chan_sip.c: Stopping retransmission on '55b420e77c5e202d76e4cc1a27c9dc8f@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:12 DEBUG[3528] chan_sip.c: Auto destroying call '8e69b678768bdfc3469914a1f6cafe78@192.168.1.134'
Apr 10 10:51:12 DEBUG[3528] acl.c: ##### Testing 192.168.1.142 with 192.168.1.0
Apr 10 10:51:12 DEBUG[3528] chan_sip.c: Stopping retransmission on '6e8e877e14d5c29104f6cc070afc5215@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:12 DEBUG[3528] acl.c: ##### Testing 192.168.1.139 with 192.168.1.0
Apr 10 10:51:12 DEBUG[3528] chan_sip.c: Stopping retransmission on '4e0e3e6b2000b410565002a23bab0ff2@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:12 DEBUG[3528] chan_sip.c: Auto destroying call '7df4ef251ed553906fb1dc524c3dfec3@192.168.1.142'
Apr 10 10:51:12 DEBUG[3528] acl.c: ##### Testing 192.168.1.70 with 192.168.1.0
Apr 10 10:51:13 DEBUG[3528] chan_sip.c: Stopping retransmission on '20e14f1c53c99b616cd4366b672d1862@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:13 DEBUG[3528] acl.c: ##### Testing 192.168.1.144 with 192.168.1.0
Apr 10 10:51:13 DEBUG[3528] chan_sip.c: Stopping retransmission on '7d338bdd73b2b97464c9ff98375e7247@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:13 DEBUG[3528] chan_sip.c: Auto destroying call 'cc5ae228cd72edc046378b5595872cd5@192.168.1.140'
Apr 10 10:51:15 DEBUG[3528] acl.c: ##### Testing 192.168.1.141 with 192.168.1.0
Apr 10 10:51:15 DEBUG[3528] chan_sip.c: Stopping retransmission on '469131ac0e58cc355e2c6ad2520de400@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:16 DEBUG[3528] acl.c: ##### Testing 192.168.1.140 with 192.168.1.0
Apr 10 10:51:16 DEBUG[3528] chan_sip.c: Stopping retransmission on '3ae5b3b727b111222c5ad1132b09e177@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:16 DEBUG[3528] acl.c: ##### Testing 192.168.1.126 with 192.168.1.0
Apr 10 10:51:16 DEBUG[3528] chan_sip.c: Stopping retransmission on '032dfae42e0a1d490e6be78c313f247e@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:16 DEBUG[3527] chan_iax2.c: Peer lastms 846, historicms 846, maxms 2000
Apr 10 10:51:16 DEBUG[3528] acl.c: ##### Testing 192.168.1.129 with 192.168.1.0
Apr 10 10:51:16 DEBUG[3528] chan_sip.c: Stopping retransmission on '43ffa1d203d394b11573e8610ca238ad@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:18 DEBUG[11813] channel.c: Didn't get a frame from channel: SIP/6630-b7747080
Apr 10 10:51:18 DEBUG[11813] channel.c: Bridge stops bridging channels SIP/6630-b7747080 and Zap/9-1
Apr 10 10:51:18 DEBUG[11813] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/9-1
Apr 10 10:51:18 DEBUG[11813] chan_zap.c: Hangup: channel: 9 index = 0, normal = 21, callwait = -1, thirdcall = -1
Apr 10 10:51:18 DEBUG[11813] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Apr 10 10:51:18 DEBUG[11813] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/9-1
Apr 10 10:51:18 DEBUG[11813] chan_zap.c: Updated conferencing on 9, with 0 conference users
Apr 10 10:51:18 DEBUG[11813] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/9-1
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Hungup 'Zap/9-1'
Apr 10 10:51:18 DEBUG[11813] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Apr 10 10:51:18 VERBOSE[11813] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/6630-b7747080' in macro 'dialout-trunk'
Apr 10 10:51:18 VERBOSE[11813] logger.c: == Spawn extension (macro-dialout-trunk, s, 20) exited non-zero on 'SIP/6630-b7747080'
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Executing Macro("SIP/6630-b7747080", "hangupcall") in new stack
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Executing ResetCDR("SIP/6630-b7747080", "w") in new stack
Apr 10 10:51:18 DEBUG[11813] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Apr 10 10:51:18 DEBUG[11813] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-04-10 10:44:20','\"Matt XX\" <314392xxxx>','314392xxxx','9267xxxx','from-internal', 'SIP/6630-b7747080','Zap/9-1','ResetCDR','w',418,408,'ANSWERED',3,'','1176219860.11209')
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Executing NoCDR("SIP/6630-b7747080", "") in new stack
Apr 10 10:51:18 NOTICE[11813] cdr.c: CDR on channel 'SIP/6630-b7747080' not posted
Apr 10 10:51:18 NOTICE[11813] cdr.c: CDR on channel 'SIP/6630-b7747080' lacks end
Apr 10 10:51:18 DEBUG[11813] pbx.c: Expression result is '1'
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Executing GotoIf("SIP/6630-b7747080", "1?skiprg") in new stack
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Goto (macro-hangupcall,s,6)
Apr 10 10:51:18 DEBUG[11813] pbx.c: Expression result is '1'
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Executing GotoIf("SIP/6630-b7747080", "1?theend") in new stack
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Goto (macro-hangupcall,s,9)
Apr 10 10:51:18 VERBOSE[11813] logger.c: -- Executing Wait("SIP/6630-b7747080", "5") in new stack
Apr 10 10:51:18 VERBOSE[11813] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/6630-b7747080' in macro 'hangupcall'
Apr 10 10:51:18 VERBOSE[11813] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'SIP/6630-b7747080'
Apr 10 10:51:18 DEBUG[11813] chan_sip.c: update_call_counter(6630) - decrement call limit counter
Apr 10 10:51:18 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:18 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:18 VERBOSE[12809] logger.c: -- Playing 'vm-deleted' (language 'en')
Apr 10 10:51:18 DEBUG[3528] chan_sip.c: Auto destroying call 'd7788ceb023e009c24b650a42a4d0ba9@192.168.1.105'
Apr 10 10:51:19 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:19 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:19 VERBOSE[12809] logger.c: -- Playing 'vm-message' (language 'en')
Apr 10 10:51:20 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:51:20 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:20 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:20 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:20 VERBOSE[12809] logger.c: -- Playing 'digits/2' (language 'en')
Apr 10 10:51:21 DEBUG[3528] acl.c: ##### Testing 192.168.1.125 with 192.168.1.0
Apr 10 10:51:21 DEBUG[3528] acl.c: ##### Testing 192.168.1.144 with 192.168.1.0
Apr 10 10:51:21 DEBUG[3528] chan_sip.c: Stopping retransmission on '3a090e1d4a8c658f01a381d6351c6a9e@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:21 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:51:21 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:21 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:21 VERBOSE[12809] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0001.txt': Apr 10 10:51:21 VERBOSE[12809] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0001.txt': Found
Apr 10 10:51:21 DEBUG[12809] app_voicemail.c: VM-Duration: duration is: 23 seconds converted to: 0 minutes
Apr 10 10:51:21 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:21 VERBOSE[12809] logger.c: -- Playing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0001' (language 'en')
Apr 10 10:51:25 DEBUG[3528] acl.c: ##### Testing 192.168.17.59 with 192.168.1.0
Apr 10 10:51:25 DEBUG[3528] chan_sip.c: Target address 192.168.17.59 is not local, substituting externip
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1206' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1212' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1205' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1204' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1210' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1207' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1203' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1214' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1211' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1215' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1213' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1209' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1208' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1201' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1202' to 60 seconds (requested 300)
Apr 10 10:51:25 NOTICE[3527] chan_iax2.c: Restricting registration for peer '1200' to 60 seconds (requested 300)
Apr 10 10:51:26 DEBUG[3528] chan_sip.c: Auto destroying call '6ee99e0f98baded875aa75bdfb5d674f@192.168.1.144'
Apr 10 10:51:30 DEBUG[3528] acl.c: ##### Testing 192.168.1.130 with 192.168.1.0
Apr 10 10:51:34 DEBUG[3528] acl.c: ##### Testing 192.168.1.105 with 192.168.1.0
Apr 10 10:51:34 DEBUG[3528] acl.c: ##### Testing 192.168.17.59 with 192.168.1.0
Apr 10 10:51:34 DEBUG[3528] chan_sip.c: Target address 192.168.17.59 is not local, substituting externip
Apr 10 10:51:34 DEBUG[3528] chan_sip.c: Stopping retransmission on '0dc09e7d7d9731365bfc4b6d4f372835@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:34 DEBUG[3528] acl.c: ##### Testing 192.168.1.131 with 192.168.1.0
Apr 10 10:51:34 DEBUG[3528] chan_sip.c: Stopping retransmission on '3940b1127d364dd50f3a2903413eb841@65.23.24.2' of Request 102: Match Found
Apr 10 10:51:36 DEBUG[3528] chan_sip.c: Auto destroying call '917d85032f34a0f43ae7ba7ec6046fa2@192.168.1.125'
Apr 10 10:51:38 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:38 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:38 VERBOSE[12809] logger.c: -- Playing 'vm-first' (language 'en')
Apr 10 10:51:39 DEBUG[3528] acl.c: ##### Testing 192.168.1.130 with 192.168.1.0
Apr 10 10:51:39 DEBUG[3528] chan_sip.c: Stopping retransmission on '2a5964954c750a265b64e6235181da82@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:39 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:51:39 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:39 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:39 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:39 VERBOSE[12809] logger.c: -- Playing 'vm-message' (language 'en')
Apr 10 10:51:40 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:51:40 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:40 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:40 VERBOSE[12809] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0000.txt': Apr 10 10:51:40 VERBOSE[12809] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0000.txt': Found
Apr 10 10:51:40 DEBUG[12809] app_voicemail.c: VM-Duration: duration is: 50 seconds converted to: 0 minutes
Apr 10 10:51:40 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:40 VERBOSE[12809] logger.c: -- Playing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0000' (language 'en')
Apr 10 10:51:40 DEBUG[3528] chan_sip.c: Auto destroying call 'a517f56ccc24ef33f77b62fcb42db4be@192.168.17.59'
Apr 10 10:51:41 DEBUG[3528] acl.c: ##### Testing 192.168.1.131 with 192.168.1.0
Apr 10 10:51:41 DEBUG[3528] chan_sip.c: Stopping retransmission on '0664ffff38b4f67a5eb7a669698455f0@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:42 DEBUG[3528] acl.c: ##### Testing 192.168.1.139 with 192.168.1.0
Apr 10 10:51:42 DEBUG[3528] acl.c: ##### Testing 192.168.1.124 with 192.168.1.0
Apr 10 10:51:43 DEBUG[3528] acl.c: ##### Testing 192.168.1.141 with 192.168.1.0
Apr 10 10:51:45 DEBUG[3528] chan_sip.c: Auto destroying call 'afc3732a639efdd863e03f0410c61698@192.168.1.130'
Apr 10 10:51:45 DEBUG[3528] acl.c: ##### Testing 192.168.17.53 with 192.168.1.0
Apr 10 10:51:45 DEBUG[3528] chan_sip.c: Target address 192.168.17.53 is not local, substituting externip
Apr 10 10:51:46 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:46 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:46 VERBOSE[12809] logger.c: -- Playing 'vm-message' (language 'en')
Apr 10 10:51:47 DEBUG[3528] acl.c: ##### Testing 192.168.17.59 with 192.168.1.0
Apr 10 10:51:47 DEBUG[3528] chan_sip.c: Target address 192.168.17.59 is not local, substituting externip
Apr 10 10:51:47 DEBUG[3528] acl.c: ##### Testing 192.168.17.53 with 192.168.1.0
Apr 10 10:51:47 DEBUG[3528] chan_sip.c: Target address 192.168.17.53 is not local, substituting externip
Apr 10 10:51:47 DEBUG[3528] chan_sip.c: Stopping retransmission on '3cef0bb9507b39bf0bb878e773508923@65.23.24.2' of Request 102: Match Found
Apr 10 10:51:47 DEBUG[3528] chan_sip.c: Stopping retransmission on '549a50a51f311c8e17d205bf1eded67d@65.23.24.2' of Request 102: Match Found
Apr 10 10:51:47 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:51:47 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:47 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:47 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:47 VERBOSE[12809] logger.c: -- Playing 'digits/2' (language 'en')
Apr 10 10:51:48 DEBUG[12809] channel.c: Scheduling timer at 145 sample intervals
Apr 10 10:51:48 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:48 DEBUG[12809] channel.c: Scheduling timer at 0 sample intervals
Apr 10 10:51:48 VERBOSE[12809] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0001.txt': Apr 10 10:51:48 VERBOSE[12809] logger.c: == Parsing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0001.txt': Found
Apr 10 10:51:48 DEBUG[12809] app_voicemail.c: VM-Duration: duration is: 23 seconds converted to: 0 minutes
Apr 10 10:51:48 DEBUG[12809] channel.c: Scheduling timer at 160 sample intervals
Apr 10 10:51:48 VERBOSE[12809] logger.c: -- Playing '/var/spool/asterisk/voicemail/default/6627/INBOX/msg0001' (language 'en')
Apr 10 10:51:48 DEBUG[3528] acl.c: ##### Testing 192.168.17.53 with 192.168.1.0
Apr 10 10:51:48 DEBUG[3528] chan_sip.c: Target address 192.168.17.53 is not local, substituting externip
Apr 10 10:51:48 DEBUG[3528] chan_sip.c: Stopping retransmission on '0b848e605517d88262aac4767411451b@65.23.24.2' of Request 102: Match Found
Apr 10 10:51:49 DEBUG[3528] chan_sip.c: Auto destroying call '4544d9086c7efad437d391a83ed8632a@192.168.1.131'
Apr 10 10:51:50 DEBUG[3528] acl.c: ##### Testing 192.168.1.139 with 192.168.1.0
Apr 10 10:51:50 DEBUG[3528] chan_sip.c: Stopping retransmission on '5889b5b233ee9bd50570765738106fe7@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:51 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:51 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3527] chan_iax2.c: Peer lastms 3, historicms 3, maxms 2000
Apr 10 10:51:52 DEBUG[3528] acl.c: ##### Testing 192.168.1.124 with 192.168.1.0
Apr 10 10:51:52 DEBUG[3528] chan_sip.c: Stopping retransmission on '50d493132f8c397c19108f6c44c0072b@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:54 DEBUG[3528] acl.c: ##### Testing 192.168.1.141 with 192.168.1.0
Apr 10 10:51:54 DEBUG[3528] chan_sip.c: Stopping retransmission on '2faa0d5a04ed2e0223cb78826a7157ac@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:57 DEBUG[3528] chan_sip.c: Auto destroying call 'c5f361b263dfb8bc832381b4f087b3a2@192.168.1.139'
Apr 10 10:51:57 DEBUG[3528] chan_sip.c: Auto destroying call '8bf36f21532187fe8fd9082970a8df69@192.168.1.124'
Apr 10 10:51:58 DEBUG[3528] chan_sip.c: Auto destroying call '69cba4ebf4864e10872807a72f682739@192.168.1.141'
Apr 10 10:51:59 DEBUG[3528] acl.c: ##### Testing 192.168.1.95 with 192.168.1.0
Apr 10 10:51:59 DEBUG[3528] chan_sip.c: Stopping retransmission on '68fdca6a25ecd62376680fe3022088ca@192.168.1.250' of Request 102: Match Found
Apr 10 10:51:59 DEBUG[12438] channel.c: Didn't get a frame from channel: SIP/6612-086e2e18
Apr 10 10:51:59 DEBUG[12438] channel.c: Bridge stops bridging channels Zap/12-1 and SIP/6612-086e2e18
Apr 10 10:51:59 DEBUG[12438] chan_sip.c: update_call_counter(6612) - decrement call limit counter
Apr 10 10:51:59 DEBUG[12438] app_dial.c: Exiting with DIALSTATUS=ANSWER.
Apr 10 10:51:59 VERBOSE[12438] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Zap/12-1' in macro 'dial'
Apr 10 10:51:59 VERBOSE[12438] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Zap/12-1' in macro 'exten-vm'
Apr 10 10:51:59 VERBOSE[12438] logger.c: == Spawn extension (macro-dial, s, 10) exited non-zero on 'Zap/12-1'
Apr 10 10:51:59 VERBOSE[12438] logger.c: -- Executing Macro("Zap/12-1", "hangupcall") in new stack
Apr 10 10:51:59 VERBOSE[12438] logger.c: -- Executing ResetCDR("Zap/12-1", "w") in new stack
Apr 10 10:51:59 DEBUG[12438] cdr_addon_mysql.c: cdr_mysql: inserting a CDR record.
Apr 10 10:51:59 DEBUG[12438] cdr_addon_mysql.c: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-04-10 10:49:27','\"XXXXXX,ANNE & B\" <636230XXXX>','636230XXXX','6612','from-pstn', 'Zap/12-1','SIP/6612-086e2e18','ResetCDR','w',152,142,'ANSWERED',3,'','1176220167.11234')
Apr 10 10:51:59 VERBOSE[12438] logger.c: -- Executing NoCDR("Zap/12-1", "") in new stack
Apr 10 10:51:59 NOTICE[12438] cdr.c: CDR on channel 'Zap/12-1' not posted
Apr 10 10:51:59 NOTICE[12438] cdr.c: CDR on channel 'Zap/12-1' lacks end
Apr 10 10:51:59 DEBUG[12438] pbx.c: Expression result is '1'
Apr 10 10:51:59 VERBOSE[12438] logger.c: -- Executing GotoIf("Zap/12-1", "1?skiprg") in new stack
Apr 10 10:51:59 VERBOSE[12438] logger.c: -- Goto (macro-hangupcall,s,6)
Apr 10 10:51:59 DEBUG[12438] pbx.c: Expression result is '1'
Apr 10 10:51:59 VERBOSE[12438] logger.c: -- Executing GotoIf("Zap/12-1", "1?theend") in new stack
Apr 10 10:51:59 VERBOSE[12438] logger.c: -- Goto (macro-hangupcall,s,9)
Apr 10 10:51:59 VERBOSE[12438] logger.c: -- Executing Wait("Zap/12-1", "5") in new stack
Apr 10 10:52:00 DEBUG[3528] chan_sip.c: Auto destroying call 'e3b53ddfb5a7df5caf9e8fe0fa50d604@192.168.17.53'
Apr 10 10:52:02 VERBOSE[3518] logger.c: -- Channel 0/12, span 1 got hangup request
Apr 10 10:52:02 VERBOSE[12438] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'Zap/12-1' in macro 'hangupcall'
Apr 10 10:52:02 VERBOSE[12438] logger.c: == Spawn extension (macro-hangupcall, s, 9) exited non-zero on 'Zap/12-1'
Apr 10 10:52:02 DEBUG[12438] channel.c: Spy MixMonitor removed from channel Zap/12-1
Apr 10 10:52:02 DEBUG[12438] chan_zap.c: Set option AUDIO MODE, value: ON(1) on Zap/12-1
Apr 10 10:52:02 DEBUG[12438] chan_zap.c: Hangup: channel: 12 index = 0, normal = 24, callwait = -1, thirdcall = -1
Apr 10 10:52:02 DEBUG[12438] chan_zap.c: Not yet hungup... Calling hangup once with icause, and clearing call
Apr 10 10:52:02 DEBUG[12438] chan_zap.c: Set option TDD MODE, value: OFF(0) on Zap/12-1
Apr 10 10:52:02 DEBUG[12438] chan_zap.c: Updated conferencing on 12, with 0 conference users
Apr 10 10:52:02 DEBUG[12438] chan_zap.c: Set option AUDIO MODE, value: OFF(0) on Zap/12-1
Apr 10 10:52:02 VERBOSE[12438] logger.c: -- Hungup 'Zap/12-1'
Apr 10 10:52:02 VERBOSE[12441] logger.c: == End MixMonitor Recording Zap/12-1