[Aug 24 07:57:17] VERBOSE[5289] logger.c: Asterisk Queue Logger restarted [Aug 24 07:57:20] DEBUG[5030] chan_iax2.c: ip callno count decremented to 2 for 192.168.25.1 [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: MGCP read: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 RM: disconnected from 10.67.90.13:2427 [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Header: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 (58) [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Header: RM: disconnected (16) [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Verb: 'RSIP', Identifier: '4104', Endpoint: 'aaln/*@0005ca7b7c5.localnet.dsl', Version: 'MGCP 1.0' [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: 2 headers, 0 lines [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Searching on aaln/*@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/*@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Handling request 'RSIP' on aaln/*@0005ca7b7c5.localnet.dsl [Aug 24 07:57:24] VERBOSE[5048] chan_mgcp.c: -- Resetting interface aaln/2@0005ca7b7c5.localnet.dsl [Aug 24 07:57:24] VERBOSE[5048] chan_mgcp.c: -- Resetting interface aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 07:57:24] DEBUG[5048] chan_mgcp.c: Transmitting: 200 4104 OK to 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: MGCP read: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 RM: disconnected from 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 (58) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RM: disconnected (16) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Verb: 'RSIP', Identifier: '4104', Endpoint: 'aaln/*@0005ca7b7c5.localnet.dsl', Version: 'MGCP 1.0' [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: 2 headers, 0 lines [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/*@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/*@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Retransmitting: 200 4104 OK to 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: MGCP read: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 RM: disconnected from 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 (58) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RM: disconnected (16) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Verb: 'RSIP', Identifier: '4104', Endpoint: 'aaln/*@0005ca7b7c5.localnet.dsl', Version: 'MGCP 1.0' [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: 2 headers, 0 lines [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/*@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/*@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Retransmitting: 200 4104 OK to 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: MGCP read: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 RM: disconnected from 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 (58) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RM: disconnected (16) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Verb: 'RSIP', Identifier: '4104', Endpoint: 'aaln/*@0005ca7b7c5.localnet.dsl', Version: 'MGCP 1.0' [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: 2 headers, 0 lines [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/*@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/*@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Retransmitting: 200 4104 OK to 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: MGCP read: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 RM: disconnected from 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 (58) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RM: disconnected (16) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Verb: 'RSIP', Identifier: '4104', Endpoint: 'aaln/*@0005ca7b7c5.localnet.dsl', Version: 'MGCP 1.0' [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: 2 headers, 0 lines [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/*@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/*@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Retransmitting: 200 4104 OK to 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: MGCP read: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 RM: disconnected from 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 (58) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RM: disconnected (16) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Verb: 'RSIP', Identifier: '4104', Endpoint: 'aaln/*@0005ca7b7c5.localnet.dsl', Version: 'MGCP 1.0' [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: 2 headers, 0 lines [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/*@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/*@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Retransmitting: 200 4104 OK to 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: MGCP read: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 RM: disconnected from 10.67.90.13:2427 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 (58) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Header: RM: disconnected (16) [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Verb: 'RSIP', Identifier: '4104', Endpoint: 'aaln/*@0005ca7b7c5.localnet.dsl', Version: 'MGCP 1.0' [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: 2 headers, 0 lines [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Searching on aaln/*@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/*@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:57:25] DEBUG[5048] chan_mgcp.c: Retransmitting: 200 4104 OK to 10.67.90.13:2427 [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: MGCP read: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 RM: disconnected from 10.67.90.13:2427 [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: Header: RSIP 4104 aaln/*@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 (58) [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: Header: RM: disconnected (16) [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: Verb: 'RSIP', Identifier: '4104', Endpoint: 'aaln/*@0005ca7b7c5.localnet.dsl', Version: 'MGCP 1.0' [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: 2 headers, 0 lines [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: Searching on aaln/*@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/*@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:57:26] DEBUG[5048] chan_mgcp.c: Retransmitting: 200 4104 OK to 10.67.90.13:2427 [Aug 24 07:57:30] DEBUG[5030] chan_iax2.c: ip callno count decremented to 1 for 192.168.25.1 [Aug 24 07:57:30] DEBUG[5032] chan_iax2.c: ip callno count incremented to 2 for 192.168.25.1 [Aug 24 07:57:30] DEBUG[5031] chan_iax2.c: schedule decrement of callno used for 192.168.25.1 in 60 seconds [Aug 24 07:57:30] DEBUG[5031] chan_iax2.c: Peer system-server-link: got pong, lastms 6, historicms 6, maxms 2000 [Aug 24 07:57:34] DEBUG[5027] res_pktccops.c: COPS: got from CASA-C3000: Header: versflag=0x10 opcode=9 clienttype=0x0000 msglength=8 [Aug 24 07:57:34] DEBUG[5027] res_pktccops.c: COPS: Keepalive Request got echoing back CASA-C3000 [Aug 24 07:57:34] DEBUG[5027] res_pktccops.c: COPS: sending opcode: 9 len: 8 [Aug 24 07:58:00] DEBUG[5034] chan_iax2.c: Allocate call number [Aug 24 07:58:00] DEBUG[5034] chan_iax2.c: ip callno count incremented to 3 for 192.168.25.1 [Aug 24 07:58:00] DEBUG[5034] chan_iax2.c: Registration created on call 11509 [Aug 24 07:58:00] DEBUG[5035] chan_iax2.c: schedule decrement of callno used for 192.168.25.1 in 60 seconds [Aug 24 07:58:04] DEBUG[5027] res_pktccops.c: COPS: got from CASA-C3000: Header: versflag=0x10 opcode=9 clienttype=0x0000 msglength=8 [Aug 24 07:58:04] DEBUG[5027] res_pktccops.c: COPS: Keepalive Request got echoing back CASA-C3000 [Aug 24 07:58:04] DEBUG[5027] res_pktccops.c: COPS: sending opcode: 9 len: 8 [Aug 24 07:58:05] DEBUG[5318] pbx.c: Launching 'Dial' [Aug 24 07:58:05] VERBOSE[5318] pbx.c: -- Executing [401@default:1] Dial("ALSA/default", "MGCP/aaln/1@0005ca7b7c5.localnet.dsl") in new stack [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Searching on aaln/2@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Searching on aaln/1@0005ca7b7c5.localnet.dsl for subchannel [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Coundn't determine subchannel, assuming current master aaln/1@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:58:05] VERBOSE[5318] chan_mgcp.c: -- MGCP mgcp_request(aaln/1@0005ca7b7c5.localnet.dsl) [Aug 24 07:58:05] VERBOSE[5318] chan_mgcp.c: -- MGCP cw: 0, dnd: 0, so: 0, sno: 0 [Aug 24 07:58:05] VERBOSE[5318] chan_mgcp.c: -- MGCP mgcp_new(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) created in state: Down [Aug 24 07:58:05] DEBUG[5318] rtp_engine.c: Can't find native functions for channel 'ALSA/default' [Aug 24 07:58:05] DEBUG[5318] rtp_engine.c: Seeded SDP of 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1' with that of 'ALSA/default' [Aug 24 07:58:05] DEBUG[5318] channel.c: Not copying variable DIALEDTIME. [Aug 24 07:58:05] DEBUG[5318] channel.c: Not copying variable ANSWEREDTIME. [Aug 24 07:58:05] DEBUG[5318] channel.c: Not copying variable DIALEDPEERNAME. [Aug 24 07:58:05] DEBUG[5318] channel.c: Not copying variable DIALEDPEERNUMBER. [Aug 24 07:58:05] DEBUG[5318] channel.c: Not copying variable DIALSTATUS. [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: MGCP mgcp_call(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: MGCP default ring [Aug 24 07:58:05] DEBUG[5021] devicestate.c: No provider found, checking channel drivers for MGCP - aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 07:58:05] DEBUG[5318] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xaf5bd438' [Aug 24 07:58:05] DEBUG[5318] res_rtp_asterisk.c: Allocated port 17134 for RTP instance '0xaf5bd438' [Aug 24 07:58:05] DEBUG[5318] rtp_engine.c: RTP instance '0xaf5bd438' is setup and ready to go [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Creating connection for aaln/1@0005ca7b7c5.localnet.dsl-1 in cxmode: recvonly callid: 357d80ae4f246694 [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: We're at 192.168.25.3 port 17134 [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Answering with capability ulaw [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Slow sequence is 0 [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Posting Request: CRCX 7 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 C: 357d80ae4f246694 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 17134 RTP/AVP 0 a=rtpmap:0 PCMU/8000 to 10.67.90.13:2427 [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: MGCP Asked to indicate tone: L/rg,L/ci(08/24/07/58,,) on aaln/1@0005ca7b7c5.localnet.dsl-1 in cxmode: recvonly [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Slow sequence is 0 [Aug 24 07:58:05] DEBUG[5318] chan_mgcp.c: Posting Request: RQNT 8 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 X: 2cce90d2 R: L/hd(N) S: L/rg,L/ci(08/24/07/58,,) to 10.67.90.13:2427 [Aug 24 07:58:05] DEBUG[5021] devicestate.c: Changing state for MGCP/aaln/1@0005ca7b7c5.localnet.dsl - state 6 (Ringing) [Aug 24 07:58:05] DEBUG[5021] devicestate.c: device 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl' state '6' [Aug 24 07:58:05] VERBOSE[5318] app_dial.c: -- Called aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 07:58:05] 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 07:58:05] DEBUG[5318] channel.c: Set channel MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1 to read format slin [Aug 24 07:58:05] DEBUG[5318] channel.c: Set channel ALSA/default to write format slin [Aug 24 07:58:05] DEBUG[5318] channel.c: Set channel ALSA/default to read format slin [Aug 24 07:58:05] DEBUG[5318] channel.c: Set channel MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1 to write format slin [Aug 24 07:58:06] DEBUG[5048] chan_mgcp.c: Retransmitting #1 transaction 7 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:06] DEBUG[5048] chan_mgcp.c: Retransmitting #1 transaction 8 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:07] DEBUG[5048] chan_mgcp.c: Retransmitting #2 transaction 7 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:07] DEBUG[5048] chan_mgcp.c: Retransmitting #2 transaction 8 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:08] DEBUG[5048] chan_mgcp.c: Retransmitting #3 transaction 7 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:08] DEBUG[5048] chan_mgcp.c: Retransmitting #3 transaction 8 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:09] DEBUG[5048] chan_mgcp.c: Retransmitting #4 transaction 7 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:09] DEBUG[5048] chan_mgcp.c: Retransmitting #4 transaction 8 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:10] DEBUG[5048] chan_mgcp.c: Retransmitting #5 transaction 7 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:10] DEBUG[5048] chan_mgcp.c: Retransmitting #5 transaction 8 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:10] DEBUG[5030] chan_iax2.c: ip callno count decremented to 2 for 192.168.25.1 [Aug 24 07:58:11] NOTICE[5048] chan_mgcp.c: Transaction 7 timed out [Aug 24 07:58:11] NOTICE[5048] chan_mgcp.c: DLCX for all connections on 0005ca7b7c5.localnet.dsl due to error 406 [Aug 24 07:58:11] DEBUG[5048] chan_mgcp.c: Delete connection aaln/1@0005ca7b7c5.localnet.dsl-1 with new mode: recvonly on callid: 357d80ae4f246694 [Aug 24 07:58:11] DEBUG[5048] chan_mgcp.c: Slow sequence is 0 [Aug 24 07:58:11] DEBUG[5048] chan_mgcp.c: Posting Request: DLCX 9 aaln/1@0005ca7b7c5.localnet.dsl MGCP 1.0 NCS 1.0 C: 357d80ae4f246694 X: 4f246694 to 10.67.90.13:2427 [Aug 24 07:58:11] NOTICE[5048] chan_mgcp.c: Terminating on result 406 from aaln/1@0005ca7b7c5.localnet.dsl-1 [Aug 24 07:58:11] DEBUG[5318] channel.c: Hanging up channel 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1' [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: mgcp_hangup(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: MGCP mgcp_hangup(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) on aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: MGCP Asked to indicate tone: on aaln/1@0005ca7b7c5.localnet.dsl-1 in cxmode: recvonly [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: Slow sequence is 0 [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: Queueing Request: RQNT 10 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 07:58:11] DEBUG[5318] rtp_engine.c: Destroyed RTP instance '0xaf5bd438' [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: MGCP mgcp_hangup(MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1) on aaln/1@0005ca7b7c5.localnet.dsl set vmwi(-) [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: MGCP Asked to indicate tone: L/vmwi(-) on aaln/1@0005ca7b7c5.localnet.dsl-1 in cxmode: inactive [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: Slow sequence is 0 [Aug 24 07:58:11] DEBUG[5318] chan_mgcp.c: Queueing Request: RQNT 11 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 07:58:11] VERBOSE[5318] app_dial.c: == Everyone is busy/congested at this time (1:0/0/1) [Aug 24 07:58:11] DEBUG[5021] devicestate.c: No provider found, checking channel drivers for MGCP - aaln/1@0005ca7b7c5.localnet.dsl [Aug 24 07:58:11] DEBUG[5318] app_dial.c: Exiting with DIALSTATUS=CHANUNAVAIL. [Aug 24 07:58:11] DEBUG[5021] devicestate.c: Changing state for MGCP/aaln/1@0005ca7b7c5.localnet.dsl - state 0 (Unknown) [Aug 24 07:58:11] VERBOSE[5318] pbx.c: -- Auto fallthrough, channel 'ALSA/default' status is 'CHANUNAVAIL' [Aug 24 07:58:11] DEBUG[5021] devicestate.c: device 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl' state '0' [Aug 24 07:58:11] DEBUG[5318] channel.c: Driver for channel 'ALSA/default' does not support indication 8, emulating it [Aug 24 07:58:11] 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 07:58:11] DEBUG[5318] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Aug 24 07:58:11] DEBUG[5318] channel.c: Prodding channel 'ALSA/default' [Aug 24 07:58:11] DEBUG[5021] devicestate.c: No provider found, checking channel drivers for ALSA - default [Aug 24 07:58:11] DEBUG[5021] devicestate.c: Changing state for ALSA/default - state 4 (Invalid) [Aug 24 07:58:11] DEBUG[5021] devicestate.c: device 'ALSA/default' state '4' [Aug 24 07:58:11] DEBUG[5060] app_queue.c: Device 'ALSA/default' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Aug 24 07:58:12] DEBUG[5048] chan_mgcp.c: Posting Queued Request: RQNT 10 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 07:58:12] NOTICE[5048] chan_mgcp.c: Transaction 8 timed out [Aug 24 07:58:13] DEBUG[5048] chan_mgcp.c: Retransmitting #1 transaction 9 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:13] DEBUG[5048] chan_mgcp.c: Retransmitting #1 transaction 10 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:14] DEBUG[5048] chan_mgcp.c: Retransmitting #2 transaction 9 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:14] DEBUG[5048] chan_mgcp.c: Retransmitting #2 transaction 10 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:15] DEBUG[5048] chan_mgcp.c: Retransmitting #3 transaction 9 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:15] DEBUG[5048] chan_mgcp.c: Retransmitting #3 transaction 10 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:15] DEBUG[5318] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Aug 24 07:58:15] DEBUG[5318] channel.c: Soft-Hanging up channel 'ALSA/default' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Launching 'Hangup' [Aug 24 07:58:15] VERBOSE[5318] pbx.c: -- Executing [h@default:1] Hangup("ALSA/default", "") in new stack [Aug 24 07:58:15] DEBUG[5318] pbx.c: Spawn extension (default,h,1) exited non-zero on 'ALSA/default' [Aug 24 07:58:15] VERBOSE[5318] pbx.c: == Spawn extension (default, h, 1) exited non-zero on 'ALSA/default' [Aug 24 07:58:15] DEBUG[5318] channel.c: Hanging up channel 'ALSA/default' [Aug 24 07:58:15] VERBOSE[5318] chan_alsa.c: << Hangup on console >> [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is '2010-08-24 07:58:05' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is '(null)' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is 'default' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is 'ALSA/default' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is 'Dial' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is 'MGCP/aaln/1@0005ca7b7c5.localnet.dsl' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is '10' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is '0' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is 'NO ANSWER' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is 'DOCUMENTATION' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is '(null)' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is '1282629485.0' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is '(null)' [Aug 24 07:58:15] DEBUG[5318] pbx.c: Function result is '(null)' [Aug 24 07:58:15] DEBUG[5318] 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 07:58:05','','default','ALSA/default','MGCP/aaln/1@0005ca7b7c5.localnet.dsl-1','Dial','MGCP/aaln/1@0005ca7b7c5.localnet.dsl','10','0','NO ANSWER','DOCUMENTATION','','1282629485.0','','') [Aug 24 07:58:15] DEBUG[5021] devicestate.c: No provider found, checking channel drivers for ALSA - default [Aug 24 07:58:15] DEBUG[5021] devicestate.c: Changing state for ALSA/default - state 4 (Invalid) [Aug 24 07:58:15] DEBUG[5021] devicestate.c: device 'ALSA/default' state '4' [Aug 24 07:58:15] DEBUG[5060] app_queue.c: Device 'ALSA/default' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Aug 24 07:58:16] DEBUG[5048] chan_mgcp.c: Retransmitting #4 transaction 9 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:16] DEBUG[5048] chan_mgcp.c: Retransmitting #4 transaction 10 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:17] DEBUG[5048] chan_mgcp.c: Retransmitting #5 transaction 9 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:17] DEBUG[5048] chan_mgcp.c: Retransmitting #5 transaction 10 on [0005ca7b7c5.localnet.dsl] [Aug 24 07:58:18] VERBOSE[5048] chan_mgcp.c: -- No command found on [0005ca7b7c5.localnet.dsl] for transaction 9. Ignoring... [Aug 24 07:58:19] VERBOSE[5048] chan_mgcp.c: -- No command found on [0005ca7b7c5.localnet.dsl] for transaction 10. Ignoring... [Aug 24 07:58:30] DEBUG[5030] chan_iax2.c: ip callno count decremented to 1 for 192.168.25.1 [Aug 24 07:58:30] DEBUG[5037] chan_iax2.c: ip callno count incremented to 2 for 192.168.25.1 [Aug 24 07:58:30] DEBUG[5040] chan_iax2.c: schedule decrement of callno used for 192.168.25.1 in 60 seconds [Aug 24 07:58:30] DEBUG[5040] chan_iax2.c: Peer system-server-link: got pong, lastms 8, historicms 8, maxms 2000 [Aug 24 07:58:34] DEBUG[5027] res_pktccops.c: COPS: got from CASA-C3000: Header: versflag=0x10 opcode=9 clienttype=0x0000 msglength=8 [Aug 24 07:58:34] DEBUG[5027] res_pktccops.c: COPS: Keepalive Request got echoing back CASA-C3000 [Aug 24 07:58:34] DEBUG[5027] res_pktccops.c: COPS: sending opcode: 9 len: 8 [Aug 24 07:58:50] DEBUG[5031] chan_iax2.c: Allocate call number [Aug 24 07:58:50] DEBUG[5031] chan_iax2.c: ip callno count incremented to 3 for 192.168.25.1 [Aug 24 07:58:50] DEBUG[5031] chan_iax2.c: Registration created on call 1717 [Aug 24 07:58:50] DEBUG[5033] chan_iax2.c: schedule decrement of callno used for 192.168.25.1 in 60 seconds [Aug 24 07:59:18] VERBOSE[5289] asterisk.c: -- Remote UNIX connection disconnected