[Jan 30 10:24:58] Asterisk SVN-branch-11-r380043 built by root @ ubuntu on a x86_64 running Linux on 2013-01-26 23:28:17 UTC [Jan 30 10:24:58] VERBOSE[13992] config.c: == Parsing '/etc/asterisk/logger.conf': Found [Jan 30 10:24:58] VERBOSE[13992] logger.c: Asterisk Queue Logger restarted [Jan 30 10:25:01] VERBOSE[13992] asterisk.c: -- Remote UNIX connection disconnected [Jan 30 10:28:20] VERBOSE[12179] asterisk.c: -- Remote UNIX connection [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: = Looking for Call ID: Aw86d0QaNQ2tJAqDtLdoC8fNNDHsBFm7 (Checking From) --From tag gav5O4wcXVLlbm6Wwrz5iUFR2dMTZI98 --To-tag [Jan 30 10:28:52] DEBUG[12194] acl.c: For destination 'X.X.X.X', our source address is 'X.X.X.X'. [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Setting SIP_TRANSPORT_UDP with address X.X.X.X:5060 [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Allocating new SIP dialog for Aw86d0QaNQ2tJAqDtLdoC8fNNDHsBFm7 - REGISTER (No RTP) [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 10:28:52] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:28:52] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:28:52] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:28:52] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: = Looking for Call ID: Aw86d0QaNQ2tJAqDtLdoC8fNNDHsBFm7 (Checking From) --From tag gav5O4wcXVLlbm6Wwrz5iUFR2dMTZI98 --To-tag [Jan 30 10:28:52] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:28:52] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:28:52] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:28:52] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 10:28:52] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:28:52] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:28:52] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:28:52] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 30 10:28:52] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:28:52] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Allocating new SIP dialog for 7adcb74f48cf2b246e9eeb995722ffac@X.X.X.X:5060 - NOTIFY (No RTP) [Jan 30 10:28:52] DEBUG[12194] acl.c: For destination 'X.X.X.X', our source address is 'X.X.X.X'. [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Setting SIP_TRANSPORT_UDP with address X.X.X.X:5060 [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: SIP call-id changed from '7adcb74f48cf2b246e9eeb995722ffac@X.X.X.X:5060' to '127830181cfa95c505290b3e7218d9e0@X.X.X.X:5060' [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Initializing initreq for method NOTIFY - callid 127830181cfa95c505290b3e7218d9e0@X.X.X.X:5060 [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:28:52] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Jan 30 10:28:52] DEBUG[12183] chan_sip.c: Checking device state for peer 6001 [Jan 30 10:28:52] DEBUG[12183] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Jan 30 10:28:52] DEBUG[12183] devicestate.c: device 'SIP/6001' state '1' [Jan 30 10:28:52] DEBUG[12217] app_queue.c: Device 'SIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: = Looking for Call ID: 127830181cfa95c505290b3e7218d9e0@X.X.X.X:5060 (Checking To) --From tag as2928c944 --To-tag z9hG4bK20d0934b [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Stopping retransmission on '127830181cfa95c505290b3e7218d9e0@X.X.X.X:5060' of Request 102: Match Found [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Got 200 accepted on NOTIFY 127830181cfa95c505290b3e7218d9e0@X.X.X.X:5060 [Jan 30 10:28:52] DEBUG[12194] chan_sip.c: Destroying SIP dialog 127830181cfa95c505290b3e7218d9e0@X.X.X.X:5060 [Jan 30 10:29:14] DEBUG[12194] chan_sip.c: = Looking for Call ID: 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t (Checking From) --From tag Q.PzHAy6MjQOD92Qjlr9idZzCOYAuqLC --To-tag [Jan 30 10:29:14] DEBUG[12194] logger.c: CALL_ID [C-00000005] created by thread. [Jan 30 10:29:14] DEBUG[12194] acl.c: For destination 'X.X.X.X', our source address is 'X.X.X.X'. [Jan 30 10:29:14] DEBUG[12194] chan_sip.c: Setting SIP_TRANSPORT_UDP with address X.X.X.X:5060 [Jan 30 10:29:14] DEBUG[12194] chan_sip.c: Allocating new SIP dialog for 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t - INVITE (No RTP) [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Begin: parsing SIP "Supported: replaces, 100rel, timer, norefersub" [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Found SIP option: -replaces- [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Matched SIP option: replaces [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Found SIP option: -100rel- [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Matched SIP option: 100rel [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Found SIP option: -timer- [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Matched SIP option: timer [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Found SIP option: -norefersub- [Jan 30 10:29:14] DEBUG[12194][C-00000005] sip/reqresp_parser.c: Matched SIP option: norefersub [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:14] DEBUG[12194] chan_sip.c: = Looking for Call ID: 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t (Checking From) --From tag Q.PzHAy6MjQOD92Qjlr9idZzCOYAuqLC --To-tag as72052d14 [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Stopping retransmission on '8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t' of Response 21697: Match Found [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:14] DEBUG[12194] chan_sip.c: = Looking for Call ID: 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t (Checking From) --From tag Q.PzHAy6MjQOD92Qjlr9idZzCOYAuqLC --To-tag [Jan 30 10:29:14] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f4fac01f288' [Jan 30 10:29:14] DEBUG[12194][C-00000005] res_rtp_asterisk.c: Allocated port 19278 for RTP instance '0x7f4fac01f288' [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: RTP instance '0x7f4fac01f288' is setup and ready to go [Jan 30 10:29:14] DEBUG[12194][C-00000005] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f4fac01f288' [Jan 30 10:29:14] VERBOSE[12194][C-00000005] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Setting NAT on RTP to Off [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP o=- 54934644 54934644 IN IP4 X.X.X.X... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP s=digphn... UNSUPPORTED OR FAILED. [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP c=IN IP4 X.X.X.X... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 0 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 8 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 9 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 111 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 18 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 58 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 118 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 58 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 96 based on m type on 0x7f4fc2aef600 [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4001 IN IP4 X.X.X.X... UNSUPPORTED OR FAILED. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:8 PCMA/8000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:9 G722/8000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:111 G726-32/8000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:18 G729/8000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16/16000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:118 L16/8000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:58 L16-256/16000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [Jan 30 10:29:14] DEBUG[12194][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4fac01f288' [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 0 from 0x7f4fc2aef600 to 0x7f4fac01f450 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 8 from 0x7f4fc2aef600 to 0x7f4fac01f450 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 9 from 0x7f4fc2aef600 to 0x7f4fac01f450 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 18 from 0x7f4fc2aef600 to 0x7f4fac01f450 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 58 from 0x7f4fc2aef600 to 0x7f4fac01f450 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 96 from 0x7f4fc2aef600 to 0x7f4fac01f450 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 111 from 0x7f4fc2aef600 to 0x7f4fac01f450 [Jan 30 10:29:14] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 118 from 0x7f4fc2aef600 to 0x7f4fac01f450 [Jan 30 10:29:14] DEBUG[12194][C-00000005] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f4fac01f288' [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: We're settling with these formats: (ulaw) [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Checking SIP call limits for device 6001 [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Updating call counter for incoming call [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: *** Our native formats are (ulaw) [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: *** Joint capabilities are (ulaw) [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: *** Our capabilities are (ulaw) [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: This channel will not be able to handle video. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: build_route: Contact hop: "RustyONE" [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Incoming INVITE with 'timer' option supported and "Session-Expires" header. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Session-Expires: 1800 [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Received Min-SE: 90 [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Session timer started: 14126 - 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: SIP/6001-0000000a: New call is still down.... Trying... [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:14] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Jan 30 10:29:14] DEBUG[12183] chan_sip.c: Checking device state for peer 6001 [Jan 30 10:29:14] DEBUG[12183] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Jan 30 10:29:14] DEBUG[12183] devicestate.c: device 'SIP/6001' state '1' [Jan 30 10:29:14] DEBUG[14230][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:14] DEBUG[14230][C-00000005] pbx.c: Launching 'NoOp' [Jan 30 10:29:14] VERBOSE[14230][C-00000005] pbx.c: -- Executing [6002@internal:1] NoOp("SIP/6001-0000000a", "ENTERING INTERNAL PHONE DIALING") in new stack [Jan 30 10:29:14] DEBUG[12217] app_queue.c: Device 'SIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:29:14] DEBUG[14230][C-00000005] pbx.c: Result of 'EXTEN' is '6002' [Jan 30 10:29:14] DEBUG[14230][C-00000005] pbx.c: Launching 'Goto' [Jan 30 10:29:14] VERBOSE[14230][C-00000005] pbx.c: -- Executing [6002@internal:2] Goto("SIP/6001-0000000a", "phones,6002,1") in new stack [Jan 30 10:29:14] VERBOSE[14230][C-00000005] pbx.c: -- Goto (phones,6002,1) [Jan 30 10:29:14] DEBUG[14230][C-00000005] pbx.c: Result of 'EXTEN' is '6002' [Jan 30 10:29:14] DEBUG[14230][C-00000005] pbx.c: Launching 'Dial' [Jan 30 10:29:14] VERBOSE[14230][C-00000005] pbx.c: -- Executing [6002@phones:1] Dial("SIP/6001-0000000a", "SIP/6002,5,Tt") in new stack [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Allocating new SIP dialog for 227722bc58f4eb3f3f2b02a40cd1226c@X.X.X.X:5060 - INVITE (No RTP) [Jan 30 10:29:14] DEBUG[14230][C-00000005] rtp_engine.c: Using engine 'asterisk' for RTP instance '0x7f4f980125c8' [Jan 30 10:29:14] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Allocated port 16646 for RTP instance '0x7f4f980125c8' [Jan 30 10:29:14] DEBUG[14230][C-00000005] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:14] DEBUG[14230][C-00000005] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:14] DEBUG[14230][C-00000005] rtp_engine.c: RTP instance '0x7f4f980125c8' is setup and ready to go [Jan 30 10:29:14] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setup RTCP on RTP instance '0x7f4f980125c8' [Jan 30 10:29:14] VERBOSE[14230][C-00000005] netsock2.c: == Using SIP RTP CoS mark 5 [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Setting NAT on RTP to Off [Jan 30 10:29:14] DEBUG[14230][C-00000005] acl.c: For destination 'X.X.X.X', our source address is 'X.X.X.X'. [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Setting SIP_TRANSPORT_UDP with address X.X.X.X:5060 [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: SIP call-id changed from '227722bc58f4eb3f3f2b02a40cd1226c@X.X.X.X:5060' to '6b923615219e9f195ba08c844c22efec@X.X.X.X:5060' [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: *** Our native formats are (ulaw) [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: *** Joint capabilities are (ulaw) [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: *** Our capabilities are (ulaw) [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: This channel will not be able to handle video. [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel_internal_api.c: Channel Call ID changing from [C-00000005] to [C-00000005] [Jan 30 10:29:14] DEBUG[14230][C-00000005] rtp_engine.c: Seeded SDP of 'SIP/6002-0000000b' with that of 'SIP/6001-0000000a' [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel.c: Not copying variable DIALEDTIME. [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel.c: Not copying variable ANSWEREDTIME. [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel.c: Not copying variable DIALEDPEERNAME. [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel.c: Not copying variable DIALEDPEERNUMBER. [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel.c: Not copying variable DIALSTATUS. [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel.c: Not copying variable SIPCALLID. [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel.c: Not copying variable SIPDOMAIN. [Jan 30 10:29:14] DEBUG[14230][C-00000005] channel.c: Not copying variable SIPURI. [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Outgoing Call for 6002 [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Updating call counter for outgoing call [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: ** Our capability: (ulaw) Video flag: False Text flag: False [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: ** Our prefcodec: (ulaw) [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: -- Done with adding codecs to SDP [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Initializing initreq for method INVITE - callid 6b923615219e9f195ba08c844c22efec@X.X.X.X:5060 [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Trying to put 'INVITE sip:' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:14] VERBOSE[14230][C-00000005] app_dial.c: -- Called SIP/6002 [Jan 30 10:29:14] DEBUG[12194] chan_sip.c: = Looking for Call ID: 6b923615219e9f195ba08c844c22efec@X.X.X.X:5060 (Checking To) --From tag as33b03616 --To-tag [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6b923615219e9f195ba08c844c22efec@X.X.X.X:5060' Request 102: Found [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: SIP response 100 to standard invite [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:14] DEBUG[12194] chan_sip.c: = Looking for Call ID: 6b923615219e9f195ba08c844c22efec@X.X.X.X:5060 (Checking To) --From tag as33b03616 --To-tag M.HBJbNghpg6CEG6nwwzu-2sb6DZJHwm [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '6b923615219e9f195ba08c844c22efec@X.X.X.X:5060' Request 102: Found [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: SIP response 180 to standard invite [Jan 30 10:29:14] DEBUG[12194][C-00000005] chan_sip.c: build_route: Contact hop: "RustyTWO" [Jan 30 10:29:14] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:14] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6002 [Jan 30 10:29:14] DEBUG[12183] chan_sip.c: Checking device state for peer 6002 [Jan 30 10:29:14] DEBUG[12183] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use) [Jan 30 10:29:14] DEBUG[12183] devicestate.c: device 'SIP/6002' state '1' [Jan 30 10:29:14] VERBOSE[14230][C-00000005] app_dial.c: -- SIP/6002-0000000b is ringing [Jan 30 10:29:14] DEBUG[12217] app_queue.c: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:29:14] DEBUG[14230][C-00000005] rtp_engine.c: Setting early bridge SDP of 'SIP/6001-0000000a' with that of 'SIP/6002-0000000b' [Jan 30 10:29:14] DEBUG[14230][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: = Looking for Call ID: 2a22d0e3-bcf809f2-f9afa62d@X.X.X.X (Checking From) --From tag 63D6315C-EAC995DF --To-tag [Jan 30 10:29:15] DEBUG[12194] acl.c: For destination 'X.X.X.X', our source address is 'X.X.X.X'. [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Setting SIP_TRANSPORT_UDP with address X.X.X.X:5060 [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Allocating new SIP dialog for 2a22d0e3-bcf809f2-f9afa62d@X.X.X.X - REGISTER (No RTP) [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 10:29:15] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:15] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:15] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:15] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: = Looking for Call ID: 2a22d0e3-bcf809f2-f9afa62d@X.X.X.X (Checking From) --From tag 63D6315C-EAC995DF --To-tag [Jan 30 10:29:15] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:15] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:15] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:15] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 10:29:15] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:15] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:15] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:15] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 30 10:29:15] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:15] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Allocating new SIP dialog for 13d8e0e835e0846170c25f0b2715ff7c@X.X.X.X:5060 - NOTIFY (No RTP) [Jan 30 10:29:15] DEBUG[12194] acl.c: For destination 'X.X.X.X', our source address is 'X.X.X.X'. [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Setting SIP_TRANSPORT_UDP with address X.X.X.X:5060 [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: SIP call-id changed from '13d8e0e835e0846170c25f0b2715ff7c@X.X.X.X:5060' to '3b8b86c875305d3869714fc74dd70587@X.X.X.X:5060' [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Initializing initreq for method NOTIFY - callid 3b8b86c875305d3869714fc74dd70587@X.X.X.X:5060 [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:15] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6003 [Jan 30 10:29:15] DEBUG[12183] chan_sip.c: Checking device state for peer 6003 [Jan 30 10:29:15] DEBUG[12183] devicestate.c: Changing state for SIP/6003 - state 1 (Not in use) [Jan 30 10:29:15] DEBUG[12183] devicestate.c: device 'SIP/6003' state '1' [Jan 30 10:29:15] DEBUG[12217] app_queue.c: Device 'SIP/6003' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: = Looking for Call ID: 3b8b86c875305d3869714fc74dd70587@X.X.X.X:5060 (Checking To) --From tag as24e892ae --To-tag CE664BA1-B5843788 [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Stopping retransmission on '3b8b86c875305d3869714fc74dd70587@X.X.X.X:5060' of Request 102: Match Found [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Got 200 accepted on NOTIFY 3b8b86c875305d3869714fc74dd70587@X.X.X.X:5060 [Jan 30 10:29:15] DEBUG[12194] chan_sip.c: Destroying SIP dialog 3b8b86c875305d3869714fc74dd70587@X.X.X.X:5060 [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: = Looking for Call ID: YEK8w.DvqhIH8fufXGDzda7KmMndWr8l (Checking From) --From tag ed7y8GcBHFcJZrb40TOSEu7ey6tG1NtL --To-tag [Jan 30 10:29:16] DEBUG[12194] acl.c: For destination 'X.X.X.X', our source address is 'X.X.X.X'. [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: Setting SIP_TRANSPORT_UDP with address X.X.X.X:5060 [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: Allocating new SIP dialog for YEK8w.DvqhIH8fufXGDzda7KmMndWr8l - REGISTER (No RTP) [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 10:29:16] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:16] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:16] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:16] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: Trying to put 'SIP/2.0 401' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: = Looking for Call ID: YEK8w.DvqhIH8fufXGDzda7KmMndWr8l (Checking From) --From tag ed7y8GcBHFcJZrb40TOSEu7ey6tG1NtL --To-tag [Jan 30 10:29:16] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:16] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:16] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:16] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: **** Received REGISTER (2) - Command in SIP REGISTER [Jan 30 10:29:16] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:16] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:16] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:16] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: Store REGISTER's Contact header for call routing. [Jan 30 10:29:16] DEBUG[12194] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:16] DEBUG[12194] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: Trying to put 'NOTIFY sip:' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:16] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6002 [Jan 30 10:29:16] DEBUG[12183] chan_sip.c: Checking device state for peer 6002 [Jan 30 10:29:16] DEBUG[12183] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use) [Jan 30 10:29:16] DEBUG[12183] devicestate.c: device 'SIP/6002' state '1' [Jan 30 10:29:16] DEBUG[12217] app_queue.c: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: = Looking for Call ID: mgxmEF9mczA-ZBbIJeOhGhomTt9LK.16 (Checking To) --From tag as178289e5 --To-tag jgQRFWZzjQOsUfo9xE9iUQ6OEqCGHKAm [Jan 30 10:29:16] DEBUG[12194] chan_sip.c: Stopping retransmission on 'mgxmEF9mczA-ZBbIJeOhGhomTt9LK.16' of Request 119: Match Found [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- start learning mode pass with addr = X.X.X.X:4048 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- probation = 4, seq = 53543 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- start learning mode pass with addr = X.X.X.X:4048 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- probation = 3, seq = 53544 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- start learning mode pass with addr = X.X.X.X:4048 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- probation = 2, seq = 53545 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:18] DEBUG[12194] chan_sip.c: = Looking for Call ID: 6b923615219e9f195ba08c844c22efec@X.X.X.X:5060 (Checking To) --From tag as33b03616 --To-tag M.HBJbNghpg6CEG6nwwzu-2sb6DZJHwm [Jan 30 10:29:18] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Acked pending invite 102 [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Stopping retransmission on '6b923615219e9f195ba08c844c22efec@X.X.X.X:5060' of Request 102: Match Found [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: SIP response 200 to standard invite [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP o=- 54934644 54934645 IN IP4 X.X.X.X... OK. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP s=digphn... UNSUPPORTED OR FAILED. [Jan 30 10:29:18] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X' into... [Jan 30 10:29:18] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port ''. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP c=IN IP4 X.X.X.X... OK. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing session-level SDP a=X-nat:0... UNSUPPORTED OR FAILED. [Jan 30 10:29:18] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 0 based on m type on 0x7f4fc2aeeaa0 [Jan 30 10:29:18] DEBUG[12194][C-00000005] rtp_engine.c: Setting payload 96 based on m type on 0x7f4fc2aeeaa0 [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtcp:4049 IN IP4 X.X.X.X... UNSUPPORTED OR FAILED. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:96 telephone-event/8000... OK. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Processing media-level (audio) SDP a=fmtp:96 0-15... UNSUPPORTED OR FAILED. [Jan 30 10:29:18] DEBUG[12194][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4f980125c8' [Jan 30 10:29:18] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 0 from 0x7f4fc2aeeaa0 to 0x7f4f98012790 [Jan 30 10:29:18] DEBUG[12194][C-00000005] rtp_engine.c: Copying payload 96 from 0x7f4fc2aeeaa0 to 0x7f4f98012790 [Jan 30 10:29:18] DEBUG[12194][C-00000005] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0x7f4f980125c8' [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: We're settling with these formats: (ulaw) [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: We have an owner, now see if we need to change this call [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Updating call counter for outgoing call [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: build_route: Contact hop: "RustyTWO" [Jan 30 10:29:18] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:18] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:18] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:18] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:18] DEBUG[12194][C-00000005] chan_sip.c: Trying to put 'ACK sip:600' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:18] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:18] VERBOSE[14230][C-00000005] app_dial.c: -- SIP/6002-0000000b answered SIP/6001-0000000a [Jan 30 10:29:18] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6002 [Jan 30 10:29:18] DEBUG[12183] chan_sip.c: Checking device state for peer 6002 [Jan 30 10:29:18] DEBUG[14230][C-00000005] chan_sip.c: SIP answering channel: SIP/6001-0000000a [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:18] DEBUG[12183] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use) [Jan 30 10:29:18] DEBUG[12183] devicestate.c: device 'SIP/6002' state '1' [Jan 30 10:29:18] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Jan 30 10:29:18] DEBUG[12183] chan_sip.c: Checking device state for peer 6001 [Jan 30 10:29:18] DEBUG[12183] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Jan 30 10:29:18] DEBUG[14230][C-00000005] chan_sip.c: Setting framing from config on incoming call [Jan 30 10:29:18] DEBUG[12183] devicestate.c: device 'SIP/6001' state '1' [Jan 30 10:29:18] DEBUG[12217] app_queue.c: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:29:18] DEBUG[12217] app_queue.c: Device 'SIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:29:18] DEBUG[14230][C-00000005] chan_sip.c: ** Our capability: (ulaw) Video flag: True Text flag: True [Jan 30 10:29:18] DEBUG[14230][C-00000005] chan_sip.c: ** Our prefcodec: (nothing) [Jan 30 10:29:18] DEBUG[14230][C-00000005] chan_sip.c: -- Done with adding codecs to SDP [Jan 30 10:29:18] DEBUG[14230][C-00000005] chan_sip.c: Done building SDP. Settling with this capability: (ulaw) [Jan 30 10:29:18] DEBUG[14230][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:18] DEBUG[14230][C-00000005] features.c: bridge answer set, chan answer set [Jan 30 10:29:18] DEBUG[14230][C-00000005] features.c: Removing dialed interfaces datastore on SIP/6002-0000000b since we're bridging [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- start learning mode pass with addr = X.X.X.X:4048 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- probation = 4, seq = 53546 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- start learning mode pass with addr = X.X.X.X:4048 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- probation = 3, seq = 53547 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- start learning mode pass with addr = X.X.X.X:4048 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- probation = 2, seq = 53548 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- start learning mode pass with addr = X.X.X.X:4048 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- probation = 1, seq = 53549 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4f98017bb0 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address X.X.X.X:4048 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Jan 30 10:29:18] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Starting RTCP transmission on RTP instance '0x7f4fac01f288' [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- start learning mode pass with addr = X.X.X.X:4000 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- probation = 4, seq = 28284 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- start learning mode pass with addr = X.X.X.X:4000 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- probation = 3, seq = 28285 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:19] DEBUG[12194] chan_sip.c: = Looking for Call ID: 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t (Checking From) --From tag Q.PzHAy6MjQOD92Qjlr9idZzCOYAuqLC --To-tag as663d975d [Jan 30 10:29:19] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:19] DEBUG[12194][C-00000005] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Jan 30 10:29:19] DEBUG[12194][C-00000005] chan_sip.c: Stopping retransmission on '8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t' of Response 21698: Match Found [Jan 30 10:29:19] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- start learning mode pass with addr = X.X.X.X:4000 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- probation = 2, seq = 28286 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- Condition for learning hasn't exited, so reject the frame. [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- start learning mode pass with addr = X.X.X.X:4000 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- probation = 1, seq = 28287 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: 0x7f4fac0237d0 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address X.X.X.X:4000 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Ooh, format changed from unknown to ulaw [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Created smoother: format: ulaw ms: 20 len: 160 [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 42 (*), at X.X.X.X:4048 [Jan 30 10:29:19] DTMF[14230][C-00000005] channel.c: DTMF begin '*' received on SIP/6002-0000000b [Jan 30 10:29:19] DTMF[14230][C-00000005] channel.c: DTMF begin passthrough '*' on SIP/6002-0000000b [Jan 30 10:29:19] DEBUG[14230][C-00000005] channel.c: Got DTMF begin on channel (SIP/6002-0000000b) [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:19] DEBUG[14230][C-00000005] channel.c: Bridge stops bridging channels SIP/6001-0000000a and SIP/6002-0000000b [Jan 30 10:29:19] DEBUG[14230][C-00000005] features.c: Not passing DTMF through, since it may be a feature code [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Creating END DTMF Frame: 42 (*), at X.X.X.X:4048 [Jan 30 10:29:19] DTMF[14230][C-00000005] channel.c: DTMF end '*' received on SIP/6002-0000000b, duration 110 ms [Jan 30 10:29:19] DTMF[14230][C-00000005] channel.c: DTMF end accepted with begin '*' on SIP/6002-0000000b [Jan 30 10:29:19] DTMF[14230][C-00000005] channel.c: DTMF end passthrough '*' on SIP/6002-0000000b [Jan 30 10:29:19] DEBUG[14230][C-00000005] channel.c: Got DTMF end on channel (SIP/6002-0000000b) [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:19] DEBUG[14230][C-00000005] channel.c: Bridge stops bridging channels SIP/6001-0000000a and SIP/6002-0000000b [Jan 30 10:29:19] DEBUG[14230][C-00000005] features.c: Feature interpret: chan=SIP/6001-0000000a, peer=SIP/6002-0000000b, code=*, sense=2, features=2, dynamic=# [Jan 30 10:29:19] DEBUG[14230][C-00000005] features.c: Set feature timer to 1000 ms [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:19] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Creating BEGIN DTMF Frame: 50 (2), at X.X.X.X:4048 [Jan 30 10:29:20] DTMF[14230][C-00000005] channel.c: DTMF begin '2' received on SIP/6002-0000000b [Jan 30 10:29:20] DTMF[14230][C-00000005] channel.c: DTMF begin passthrough '2' on SIP/6002-0000000b [Jan 30 10:29:20] DEBUG[14230][C-00000005] channel.c: Got DTMF begin on channel (SIP/6002-0000000b) [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:20] DEBUG[14230][C-00000005] channel.c: Bridge stops bridging channels SIP/6001-0000000a and SIP/6002-0000000b [Jan 30 10:29:20] DEBUG[14230][C-00000005] features.c: Not passing DTMF through, since it may be a feature code [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Creating END DTMF Frame: 50 (2), at X.X.X.X:4048 [Jan 30 10:29:20] DTMF[14230][C-00000005] channel.c: DTMF end '2' received on SIP/6002-0000000b, duration 80 ms [Jan 30 10:29:20] DTMF[14230][C-00000005] channel.c: DTMF end accepted with begin '2' on SIP/6002-0000000b [Jan 30 10:29:20] DTMF[14230][C-00000005] channel.c: DTMF end passthrough '2' on SIP/6002-0000000b [Jan 30 10:29:20] DEBUG[14230][C-00000005] channel.c: Got DTMF end on channel (SIP/6002-0000000b) [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:20] DEBUG[14230][C-00000005] channel.c: Bridge stops bridging channels SIP/6001-0000000a and SIP/6002-0000000b [Jan 30 10:29:20] DEBUG[14230][C-00000005] features.c: Feature interpret: chan=SIP/6001-0000000a, peer=SIP/6002-0000000b, code=*2, sense=2, features=2, dynamic=# [Jan 30 10:29:20] DEBUG[14230][C-00000005] features.c: Feature detected: fname=Attended Transfer sname=atxfer exten=*2 [Jan 30 10:29:20] DEBUG[14230][C-00000005] features.c: Executing Attended Transfer SIP/6001-0000000a, SIP/6002-0000000b (sense=2) [Jan 30 10:29:20] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:20] VERBOSE[14230][C-00000005] res_musiconhold.c: -- Started music on hold, class 'default', on SIP/6001-0000000a [Jan 30 10:29:20] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 30 10:29:20] DEBUG[14230][C-00000005] channel.c: Set channel SIP/6002-0000000b to write format gsm [Jan 30 10:29:20] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 30 10:29:20] VERBOSE[14230][C-00000005] file.c: -- Playing 'pbx-transfer.gsm' (language 'en') [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] channel.c: Generator got voice, switching to phase locked mode [Jan 30 10:29:20] DEBUG[12222][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 30 10:29:20] DEBUG[12222][C-00000005] channel.c: Set channel SIP/6001-0000000a to write format slin [Jan 30 10:29:20] DEBUG[12222][C-00000005] res_musiconhold.c: SIP/6001-0000000a Opened file 0 '/var/lib/asterisk/moh/macroform-cold_day' [Jan 30 10:29:20] DEBUG[12222][C-00000005] res_rtp_asterisk.c: Difference is 696, ms is 107 [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:20] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Got RTCP report of 64 bytes [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 30 10:29:21] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 30 10:29:21] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 30 10:29:21] DEBUG[14230][C-00000005] channel.c: Set channel SIP/6002-0000000b to write format ulaw [Jan 30 10:29:21] DEBUG[14230][C-00000005] channel.c: Set channel SIP/6002-0000000b to write format slin [Jan 30 10:29:21] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (50 requested / 50 actual) timer ticks per second [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[14230][C-00000005] channel.c: Generator got voice, switching to phase locked mode [Jan 30 10:29:21] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:21] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:22] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Got RTCP report of 72 bytes [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:23] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:24] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:24] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:24] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:24] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:24] DEBUG[12222][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:24] DEBUG[12222][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:24] DEBUG[12194] chan_sip.c: = Looking for Call ID: 6b923615219e9f195ba08c844c22efec@X.X.X.X:5060 (Checking From) --From tag M.HBJbNghpg6CEG6nwwzu-2sb6DZJHwm --To-tag as33b03616 [Jan 30 10:29:24] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:24] DEBUG[12194][C-00000005] chan_sip.c: **** Received BYE (8) - Command in SIP BYE [Jan 30 10:29:24] DEBUG[12194][C-00000005] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:24] DEBUG[12194][C-00000005] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:24] DEBUG[12194][C-00000005] chan_sip.c: Setting SIP_ALREADYGONE on dialog 6b923615219e9f195ba08c844c22efec@X.X.X.X:5060 [Jan 30 10:29:24] DEBUG[12194][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4f980125c8' [Jan 30 10:29:24] DEBUG[12194][C-00000005] chan_sip.c: Received bye, issuing owner hangup [Jan 30 10:29:24] DEBUG[12194][C-00000005] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:24] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:24] DEBUG[14230][C-00000005] channel.c: Set channel SIP/6002-0000000b to write format ulaw [Jan 30 10:29:24] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 30 10:29:24] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting the marker bit due to a source update [Jan 30 10:29:24] VERBOSE[14230][C-00000005] res_musiconhold.c: -- Stopped music on hold on SIP/6001-0000000a [Jan 30 10:29:24] DEBUG[14230][C-00000005] channel.c: Set channel SIP/6001-0000000a to write format ulaw [Jan 30 10:29:24] DEBUG[14230][C-00000005] channel.c: Scheduling timer at (0 requested / 0 actual) timer ticks per second [Jan 30 10:29:24] DEBUG[14230][C-00000005] channel.c: Hanging up channel 'SIP/6002-0000000b' [Jan 30 10:29:24] DEBUG[14230][C-00000005] chan_sip.c: Hangup call SIP/6002-0000000b, SIP callid 6b923615219e9f195ba08c844c22efec@X.X.X.X:5060 [Jan 30 10:29:24] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4f980125c8' [Jan 30 10:29:24] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6002 [Jan 30 10:29:24] DEBUG[12183] chan_sip.c: Checking device state for peer 6002 [Jan 30 10:29:24] DEBUG[12183] devicestate.c: Changing state for SIP/6002 - state 1 (Not in use) [Jan 30 10:29:24] DEBUG[12183] devicestate.c: device 'SIP/6002' state '1' [Jan 30 10:29:24] DEBUG[12217] app_queue.c: Device 'SIP/6002' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:29:24] DEBUG[14230][C-00000005] app_dial.c: Exiting with DIALSTATUS=ANSWER. [Jan 30 10:29:24] DEBUG[14230][C-00000005] pbx.c: Spawn extension (phones,6002,1) exited non-zero on 'SIP/6001-0000000a' [Jan 30 10:29:24] VERBOSE[14230][C-00000005] pbx.c: == Spawn extension (phones, 6002, 1) exited non-zero on 'SIP/6001-0000000a' [Jan 30 10:29:24] DEBUG[14230][C-00000005] channel.c: Soft-Hanging up channel 'SIP/6001-0000000a' [Jan 30 10:29:24] DEBUG[14230][C-00000005] channel.c: Hanging up channel 'SIP/6001-0000000a' [Jan 30 10:29:24] DEBUG[14230][C-00000005] chan_sip.c: Hangup call SIP/6001-0000000a, SIP callid 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t [Jan 30 10:29:24] DEBUG[14230][C-00000005] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0x7f4fac01f288' [Jan 30 10:29:24] DEBUG[14230][C-00000005] chan_sip.c: Session timer stopped: 14126 - 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t [Jan 30 10:29:24] DEBUG[14230][C-00000005] netsock2.c: Splitting 'X.X.X.X:5060' into... [Jan 30 10:29:24] DEBUG[14230][C-00000005] netsock2.c: ...host 'X.X.X.X' and port '5060'. [Jan 30 10:29:24] DEBUG[14230][C-00000005] chan_sip.c: Trying to put 'BYE sip:600' onto UDP socket destined for X.X.X.X:5060 [Jan 30 10:29:24] DEBUG[12183] devicestate.c: No provider found, checking channel drivers for SIP - 6001 [Jan 30 10:29:24] DEBUG[12183] chan_sip.c: Checking device state for peer 6001 [Jan 30 10:29:24] DEBUG[12183] devicestate.c: Changing state for SIP/6001 - state 1 (Not in use) [Jan 30 10:29:24] DEBUG[12183] devicestate.c: device 'SIP/6001' state '1' [Jan 30 10:29:24] DEBUG[12217] app_queue.c: Device 'SIP/6001' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jan 30 10:29:24] DEBUG[12194] chan_sip.c: = Looking for Call ID: 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t (Checking To) --From tag as663d975d --To-tag Q.PzHAy6MjQOD92Qjlr9idZzCOYAuqLC [Jan 30 10:29:24] DEBUG[12194][C-00000005] logger.c: CALL_ID [C-00000005] bound to thread. [Jan 30 10:29:24] DEBUG[12194][C-00000005] chan_sip.c: Stopping retransmission on '8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t' of Request 102: Match Found [Jan 30 10:29:24] DEBUG[12194][C-00000005] logger.c: Call_ID [C-00000005] being removed from thread. [Jan 30 10:29:24] DEBUG[12194] chan_sip.c: Destroying SIP dialog 8Jjr-Bp7W0tdmdui1JAxvjyhcAB6fu9t [Jan 30 10:29:24] DEBUG[12194] rtp_engine.c: Destroyed RTP instance '0x7f4fac01f288' [Jan 30 10:29:24] DEBUG[12194] chan_sip.c: Auto destroying SIP dialog 'Aw86d0QaNQ2tJAqDtLdoC8fNNDHsBFm7' [Jan 30 10:29:24] DEBUG[12194] chan_sip.c: Destroying SIP dialog Aw86d0QaNQ2tJAqDtLdoC8fNNDHsBFm7 [Jan 30 10:29:47] DEBUG[12194] chan_sip.c: Auto destroying SIP dialog '2a22d0e3-bcf809f2-f9afa62d@X.X.X.X' [Jan 30 10:29:47] DEBUG[12194] chan_sip.c: Destroying SIP dialog 2a22d0e3-bcf809f2-f9afa62d@X.X.X.X [Jan 30 10:29:48] DEBUG[12194] chan_sip.c: Auto destroying SIP dialog 'YEK8w.DvqhIH8fufXGDzda7KmMndWr8l' [Jan 30 10:29:48] DEBUG[12194] chan_sip.c: Destroying SIP dialog YEK8w.DvqhIH8fufXGDzda7KmMndWr8l [Jan 30 10:29:56] DEBUG[12194] chan_sip.c: Auto destroying SIP dialog '6b923615219e9f195ba08c844c22efec@X.X.X.X:5060' [Jan 30 10:29:56] DEBUG[12194] chan_sip.c: Destroying SIP dialog 6b923615219e9f195ba08c844c22efec@X.X.X.X:5060 [Jan 30 10:29:56] DEBUG[12194] rtp_engine.c: Destroyed RTP instance '0x7f4f980125c8'