[Aug 24 08:04:48] VERBOSE[5391] config.c: == Parsing '/usr/local/asterisk/etc/asterisk/logger.conf': [Aug 24 08:04:48] DEBUG[5391] config.c: Parsing /usr/local/asterisk/etc/asterisk/logger.conf [Aug 24 08:04:48] VERBOSE[5391] config.c: == Found [Aug 24 08:04:48] VERBOSE[5391] logger.c: Asterisk Queue Logger restarted [Aug 24 08:04:50] DEBUG[5030] chan_iax2.c: ip callno count decremented to 2 for 192.168.25.1 [Aug 24 08:05:06] DEBUG[5027] res_pktccops.c: COPS: got from CASA-C3000: Header: versflag=0x10 opcode=9 clienttype=0x0000 msglength=8 [Aug 24 08:05:06] DEBUG[5027] res_pktccops.c: COPS: Keepalive Request got echoing back CASA-C3000 [Aug 24 08:05:06] DEBUG[5027] res_pktccops.c: COPS: sending opcode: 9 len: 8 [Aug 24 08:05:10] DEBUG[5036] chan_iax2.c: Determining if address 192.168.25.1 with username system-server-link requires calltoken validation. Optional = 0 calltoken_required = 3 [Aug 24 08:05:10] DEBUG[5036] chan_iax2.c: ip callno count incremented to 3 for 192.168.25.1 [Aug 24 08:05:10] VERBOSE[5038] chan_iax2.c: -- Accepting AUTHENTICATED call from 192.168.25.1: > requested format = ulaw, > requested prefs = (ulaw|g726aal2|gsm), > actual format = g722, > host prefs = (g722), > priority = mine [Aug 24 08:05:10] DEBUG[5394] pbx.c: Launching 'Dial' [Aug 24 08:05:10] VERBOSE[5394] pbx.c: -- Executing [401@default:1] Dial("IAX2/system-server-link-28", "MGCP/aaln/1@0005ca7b7c5.localnet.dsl") in new stack [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/1@0005ca7b7c5.localnet.dsl-1 [Aug 24 08:05:10] VERBOSE[5394] chan_mgcp.c: -- MGCP mgcp_request(aaln/1@0005ca7b7c5.localnet.dsl) [Aug 24 08:05:10] VERBOSE[5394] chan_mgcp.c: -- MGCP cw: 0, dnd: 0, so: 0, sno: 0 [Aug 24 08:05:10] VERBOSE[5394] chan_mgcp.c: -- MGCP mgcp_new(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) created in state: Down [Aug 24 08:05:10] DEBUG[5394] rtp_engine.c: Can't find native functions for channel 'IAX2/system-server-link-28' [Aug 24 08:05:10] DEBUG[5394] rtp_engine.c: Seeded SDP of 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1' with that of 'IAX2/system-server-link-28' [Aug 24 08:05:10] DEBUG[5394] channel.c: Not copying variable DIALEDTIME. [Aug 24 08:05:10] DEBUG[5394] channel.c: Not copying variable ANSWEREDTIME. [Aug 24 08:05:10] DEBUG[5394] channel.c: Not copying variable DIALEDPEERNAME. [Aug 24 08:05:10] DEBUG[5394] channel.c: Not copying variable DIALEDPEERNUMBER. [Aug 24 08:05:10] DEBUG[5394] channel.c: Not copying variable DIALSTATUS. [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: MGCP mgcp_call(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: MGCP default ring [Aug 24 08:05:10] DEBUG[5021] devicestate.c: No provider found, checking channel drivers for MGCP - aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 08:05:10] DEBUG[5394] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x85bfbc0' [Aug 24 08:05:10] DEBUG[5394] res_rtp_asterisk.c: Allocated port 12388 for RTP instance '0x85bfbc0' [Aug 24 08:05:10] DEBUG[5394] rtp_engine.c: RTP instance '0x85bfbc0' is setup and ready to go [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Creating connection for aaln/1@0005ca7b7c5.localnet.dsl-1 in cxmode: recvonly callid: 148d400a4f246694 [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: We're at 192.168.25.3 port 12388 [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Answering with capability ulaw [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Slow sequence is 0 [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Posting Request: CRCX 12 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 C: 148d400a4f246694 L: e:on, s:off, p:20, a:PCMU M: recvonly X: 4f246694 v=0 o=root 5015 5015 IN IP4 192.168.25.3 s=session c=IN IP4 192.168.25.3 t=0 0 m=audio 12388 RTP/AVP 0 a=rtpmap:0 PCMU/8000 to 10.67.90.13:2427 [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: MGCP Asked to indicate tone: L/rg,L/ci(08/24/08/05,133,133) on aaln/1@0005ca7b7c5.localnet.dsl-1 in cxmode: recvonly [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Slow sequence is 0 [Aug 24 08:05:10] DEBUG[5394] chan_mgcp.c: Posting Request: RQNT 13 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 X: 2cce90d2 R: L/hd(N) S: L/rg,L/ci(08/24/08/05,133,133) to 10.67.90.13:2427 [Aug 24 08:05:10] DEBUG[5021] devicestate.c: Changing state for MGCP/aaln/1@0005ca7b7c5.localnet.dsl - state 6 (Ringing) [Aug 24 08:05:10] VERBOSE[5394] app_dial.c: -- Called aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 08:05:10] DEBUG[5021] devicestate.c: device 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl' state '6' [Aug 24 08:05:10] DEBUG[5060] app_queue.c: Device 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Aug 24 08:05:10] DEBUG[5394] channel.c: Set channel MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1 to read format slin [Aug 24 08:05:10] DEBUG[5394] channel.c: Set channel IAX2/system-server-link-28 to write format slin [Aug 24 08:05:10] DEBUG[5394] channel.c: Set channel IAX2/system-server-link-28 to read format slin [Aug 24 08:05:10] DEBUG[5394] channel.c: Set channel MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1 to write format slin [Aug 24 08:05:11] DEBUG[5048] chan_mgcp.c: Retransmitting #1 transaction 12 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:11] DEBUG[5048] chan_mgcp.c: Retransmitting #1 transaction 13 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:12] DEBUG[5048] chan_mgcp.c: Retransmitting #2 transaction 12 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:12] DEBUG[5048] chan_mgcp.c: Retransmitting #2 transaction 13 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:13] DEBUG[5048] chan_mgcp.c: Retransmitting #3 transaction 12 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:13] DEBUG[5048] chan_mgcp.c: Retransmitting #3 transaction 13 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:14] DEBUG[5048] chan_mgcp.c: Retransmitting #4 transaction 12 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:14] DEBUG[5048] chan_mgcp.c: Retransmitting #4 transaction 13 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:15] DEBUG[5048] chan_mgcp.c: Retransmitting #5 transaction 12 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:15] DEBUG[5048] chan_mgcp.c: Retransmitting #5 transaction 13 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:16] NOTICE[5048] chan_mgcp.c: Transaction 12 timed out [Aug 24 08:05:16] NOTICE[5048] chan_mgcp.c: DLCX for all connections on 0005ca7b7c5.localnet.dsl due to error 406 [Aug 24 08:05:16] DEBUG[5048] chan_mgcp.c: Delete connection aaln/1@0005ca7b7c5.localnet.dsl-1 with new mode: recvonly on callid: 148d400a4f246694 [Aug 24 08:05:16] DEBUG[5048] chan_mgcp.c: Slow sequence is 0 [Aug 24 08:05:16] DEBUG[5048] chan_mgcp.c: Posting Request: DLCX 14 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 C: 148d400a4f246694 X: 4f246694 to 10.67.90.13:2427 [Aug 24 08:05:16] NOTICE[5048] chan_mgcp.c: Terminating on result 406 from aaln/1@0005ca7b7c5.localnet.dsl-1 [Aug 24 08:05:16] DEBUG[5394] channel.c: Hanging up channel 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1' [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: mgcp_hangup(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: MGCP mgcp_hangup(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) on aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: MGCP Asked to indicate tone: on aaln/1@0005ca7b7c5.localnet.dsl-1 in cxmode: recvonly [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: Slow sequence is 0 [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: Queueing Request: RQNT 15 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 X: 2cce90d2 R: L/hd(N) to 10.67.90.13:2427 [Aug 24 08:05:16] DEBUG[5394] rtp_engine.c: Destroyed RTP instance '0x85bfbc0' [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: MGCP mgcp_hangup(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) on aaln/1@0005ca7b7c5.localnet.dsl set vmwi(-) [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: MGCP Asked to indicate tone: L/vmwi(-) on aaln/1@0005ca7b7c5.localnet.dsl-1 in cxmode: inactive [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: Slow sequence is 0 [Aug 24 08:05:16] DEBUG[5394] chan_mgcp.c: Queueing Request: RQNT 16 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 X: 2cce90d2 R: L/hd(N) S: L/vmwi(-) to 10.67.90.13:2427 [Aug 24 08:05:16] VERBOSE[5394] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1) [Aug 24 08:05:16] DEBUG[5394] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [Aug 24 08:05:16] VERBOSE[5394] pbx.c: -- Auto fallthrough, channel 'IAX2/system-server-link-28' status is 'CHANUNAVAIL' [Aug 24 08:05:16] DEBUG[5021] devicestate.c: No provider found, checking channel drivers for MGCP - aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 08:05:16] DEBUG[5021] devicestate.c: Changing state for MGCP/aaln/1@0005ca7b7c5.localnet.dsl - state 0 (Unknown) [Aug 24 08:05:16] DEBUG[5021] devicestate.c: device 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl' state '0' [Aug 24 08:05:16] DEBUG[5021] devicestate.c: No provider found, checking channel drivers for IAX2 - system-server-link [Aug 24 08:05:16] DEBUG[5021] chan_iax2.c: Checking device state for device system-server-link [Aug 24 08:05:16] DEBUG[5021] chan_iax2.c: iax2_devicestate: Found peer. What's device state of system-server-link? addr=18458816, defaddr=0 maxms=2000, lastms=6 [Aug 24 08:05:16] DEBUG[5021] devicestate.c: Changing state for IAX2/system-server-link - state 2 (In use) [Aug 24 08:05:16] DEBUG[5021] devicestate.c: device 'IAX2/system-server-link' state '2' [Aug 24 08:05:16] DEBUG[5060] app_queue.c: Device 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Aug 24 08:05:16] DEBUG[5060] app_queue.c: Device 'IAX2/system-server-link' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Aug 24 08:05:16] DEBUG[5031] chan_iax2.c: Immediately destroying 28, having received hangup [Aug 24 08:05:16] DEBUG[5394] channel.c: Soft-Hanging up channel 'IAX2/system-server-link-28' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Launching 'Hangup' [Aug 24 08:05:16] VERBOSE[5394] pbx.c: -- Executing [h@default:1] Hangup("IAX2/system-server-link-28", "") in new stack [Aug 24 08:05:16] DEBUG[5394] pbx.c: Spawn extension (default,h,1) exited non-zero on 'IAX2/system-server-link-28' [Aug 24 08:05:16] VERBOSE[5394] pbx.c: == Spawn extension (default, h, 1) exited non-zero on 'IAX2/system-server-link-28' [Aug 24 08:05:16] DEBUG[5394] channel.c: Hanging up channel 'IAX2/system-server-link-28' [Aug 24 08:05:16] DEBUG[5394] chan_iax2.c: We're hanging up IAX2/system-server-link-28 now... [Aug 24 08:05:16] DEBUG[5394] chan_iax2.c: Really destroying IAX2/system-server-link-28 now... [Aug 24 08:05:16] DEBUG[5394] chan_iax2.c: schedule decrement of callno used for 192.168.25.1 in 60 seconds [Aug 24 08:05:16] VERBOSE[5394] chan_iax2.c: -- Hungup 'IAX2/system-server-link-28' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is '2010-08-24 08:05:10' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is '"133" <133>' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is 'default' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is 'IAX2/system-server-link-28' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is 'Dial' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is '6' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is '0' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is 'NO ANSWER' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is 'DOCUMENTATION' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is '(null)' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is '1282629910.2' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is '(null)' [Aug 24 08:05:16] DEBUG[5394] pbx.c: Function result is '(null)' [Aug 24 08:05:16] DEBUG[5394] cdr_sqlite3_custom.c: About to log: INSERT INTO cdr (calldate,clid,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield,test) VALUES ('2010-08-24 08:05:10','"133" <133>','default','IAX2/system-server-link-28','MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1','Dial','MGCP/aaln/1@0005ca7b7c5.localnet.dsl','6','0','NO ANSWER','DOCUMENTATION','','1282629910.2','','') [Aug 24 08:05:16] DEBUG[5021] devicestate.c: No provider found, checking channel drivers for IAX2 - system-server-link [Aug 24 08:05:16] DEBUG[5021] chan_iax2.c: Checking device state for device system-server-link [Aug 24 08:05:16] DEBUG[5021] chan_iax2.c: iax2_devicestate: Found peer. What's device state of system-server-link? addr=18458816, defaddr=0 maxms=2000, lastms=6 [Aug 24 08:05:16] DEBUG[5021] devicestate.c: Changing state for IAX2/system-server-link - state 0 (Unknown) [Aug 24 08:05:16] DEBUG[5021] devicestate.c: device 'IAX2/system-server-link' state '0' [Aug 24 08:05:16] DEBUG[5060] app_queue.c: Device 'IAX2/system-server-link' changed to state '0' (Unknown) but we don't care because they're not a member of any queue. [Aug 24 08:05:17] DEBUG[5048] chan_mgcp.c: Posting Queued Request: RQNT 15 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 X: 2cce90d2 R: L/hd(N) to 10.67.90.13:2427 [Aug 24 08:05:17] NOTICE[5048] chan_mgcp.c: Transaction 13 timed out [Aug 24 08:05:18] DEBUG[5048] chan_mgcp.c: Retransmitting #1 transaction 14 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:18] DEBUG[5048] chan_mgcp.c: Retransmitting #1 transaction 15 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:19] DEBUG[5048] chan_mgcp.c: Retransmitting #2 transaction 14 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:19] DEBUG[5048] chan_mgcp.c: Retransmitting #2 transaction 15 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:20] DEBUG[5048] chan_mgcp.c: Retransmitting #3 transaction 14 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:20] DEBUG[5048] chan_mgcp.c: Retransmitting #3 transaction 15 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:21] DEBUG[5048] chan_mgcp.c: Retransmitting #4 transaction 14 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:21] DEBUG[5048] chan_mgcp.c: Retransmitting #4 transaction 15 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:22] DEBUG[5048] chan_mgcp.c: Retransmitting #5 transaction 14 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:22] DEBUG[5048] chan_mgcp.c: Retransmitting #5 transaction 15 on [0005ca7b7c5.localnet.dsl] [Aug 24 08:05:23] VERBOSE[5048] chan_mgcp.c: -- No command found on [0005ca7b7c5.localnet.dsl] for transaction 14. Ignoring... [Aug 24 08:05:24] VERBOSE[5048] chan_mgcp.c: -- No command found on [0005ca7b7c5.localnet.dsl] for transaction 15. Ignoring... [Aug 24 08:05:30] DEBUG[5030] chan_iax2.c: ip callno count decremented to 2 for 192.168.25.1 [Aug 24 08:05:30] DEBUG[5036] chan_iax2.c: ip callno count incremented to 3 for 192.168.25.1 [Aug 24 08:05:30] DEBUG[5038] chan_iax2.c: schedule decrement of callno used for 192.168.25.1 in 60 seconds [Aug 24 08:05:30] DEBUG[5038] chan_iax2.c: Peer system-server-link: got pong, lastms 5, historicms 5, maxms 2000 [Aug 24 08:05:30] DEBUG[5039] chan_iax2.c: Allocate call number [Aug 24 08:05:30] DEBUG[5039] chan_iax2.c: ip callno count incremented to 4 for 192.168.25.1 [Aug 24 08:05:30] DEBUG[5039] chan_iax2.c: Registration created on call 1658 [Aug 24 08:05:30] DEBUG[5037] chan_iax2.c: schedule decrement of callno used for 192.168.25.1 in 60 seconds [Aug 24 08:05:52] VERBOSE[5391] asterisk.c: -- Remote UNIX connection disconnected