<--- SIP read from UDP:81.201.xxx.xxx:5060 ---> INVITE sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 INVITE From: "15141234567" ;tag=59098 To: Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 Max-Forwards: 69 Content-Type: application/sdp Contact: User-Agent: Vox Callcontrol Content-Length: 238 v=0 o=root 6410 6410 IN IP4 81.201.85.81 s=session c=IN IP4 81.201.85.81 t=0 0 m=audio 10728 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <-------------> [2013-04-23 13:44:30] VERBOSE[25939] chan_sip.c: <--- SIP read from UDP:81.201.xxx.xxx:5060 ---> INVITE sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 INVITE From: "15141234567" ;tag=59098 To: Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 Max-Forwards: 69 Content-Type: application/sdp Contact: User-Agent: Vox Callcontrol Content-Length: 238 v=0 o=root 6410 6410 IN IP4 81.201.85.81 s=session c=IN IP4 81.201.85.81 t=0 0 m=audio 10728 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <-------------> [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 0 [ 46]: INVITE sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 0 [ 46]: INVITE sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 1 [ 48]: Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 1 [ 48]: Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 2 [ 16]: CSeq: 102 INVITE [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 2 [ 16]: CSeq: 102 INVITE [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 3 [ 59]: From: "15141234567" ;tag=59098 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 3 [ 59]: From: "15141234567" ;tag=59098 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 4 [ 37]: To: [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 4 [ 37]: To: [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 5 [ 89]: Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 5 [ 89]: Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 6 [ 16]: Max-Forwards: 69 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 6 [ 16]: Max-Forwards: 69 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 7 [ 29]: Content-Type: application/sdp [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 8 [ 58]: Contact: [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 8 [ 58]: Contact: [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 9 [ 27]: User-Agent: Vox Callcontrol [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 9 [ 27]: User-Agent: Vox Callcontrol [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 10 [ 19]: Content-Length: 238 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 10 [ 19]: Content-Length: 238 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 11 [ 0]: [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Header 11 [ 0]: [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 0 [ 3]: v=0 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 0 [ 3]: v=0 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 1 [ 36]: o=root 6410 6410 IN IP4 81.201.85.81 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 1 [ 36]: o=root 6410 6410 IN IP4 81.201.85.81 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 2 [ 9]: s=session [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 2 [ 9]: s=session [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 3 [ 21]: c=IN IP4 81.201.85.81 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 3 [ 21]: c=IN IP4 81.201.85.81 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 4 [ 5]: t=0 0 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 4 [ 5]: t=0 0 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 5 [ 27]: m=audio 10728 RTP/AVP 0 101 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 5 [ 27]: m=audio 10728 RTP/AVP 0 101 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 8 [ 15]: a=fmtp:101 0-16 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 9 [ 25]: a=silenceSupp:off - - - - [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 10 [ 10]: a=ptime:20 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 10 [ 10]: a=ptime:20 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 11 [ 10]: a=sendrecv [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Body 11 [ 10]: a=sendrecv [2013-04-23 13:44:30] VERBOSE[25939] chan_sip.c: --- (11 headers 12 lines) --- [2013-04-23 13:44:30] VERBOSE[25939] chan_sip.c: --- (11 headers 12 lines) --- [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: = Looking for Call ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx (Checking From) --From tag 59098 --To-tag [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: = Looking for Call ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx (Checking From) --From tag 59098 --To-tag [2013-04-23 13:44:30] DEBUG[25939] logger.c: CALL_ID [C-00000001] created by thread. [2013-04-23 13:44:30] DEBUG[25939] logger.c: CALL_ID [C-00000001] created by thread. [2013-04-23 13:44:30] DEBUG[25939] acl.c: For destination '81.201.xxx.xxx', our source address is '103.xxx.xxx.xxx'. [2013-04-23 13:44:30] DEBUG[25939] acl.c: For destination '81.201.xxx.xxx', our source address is '103.xxx.xxx.xxx'. [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Target address 81.201.xxx.xxx:5060 is not local, substituting externaddr [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Target address 81.201.xxx.xxx:5060 is not local, substituting externaddr [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Setting SIP_TRANSPORT_UDP with address 103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Allocating new SIP dialog for BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx - INVITE (No RTP) [2013-04-23 13:44:30] DEBUG[25939] chan_sip.c: Allocating new SIP dialog for BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx - INVITE (No RTP) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting '81.201.xxx.xxx:5060' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting '81.201.xxx.xxx:5060' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host '81.201.xxx.xxx' and port '5060'. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host '81.201.xxx.xxx' and port '5060'. [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Sending to 81.201.xxx.xxx:5060 (NAT) [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Sending to 81.201.xxx.xxx:5060 (NAT) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Using INVITE request as basis request - BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Using INVITE request as basis request - BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting 'voxbone.com' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting 'voxbone.com' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host 'voxbone.com' and port ''. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host 'voxbone.com' and port ''. [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found peer 'VoxboneNY' for '15141234567' from 81.201.xxx.xxx:5060 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found peer 'VoxboneNY' for '15141234567' from 81.201.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb6f2569c' [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb6f2569c' [2013-04-23 13:44:30] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Allocated port 18372 for RTP instance '0xb6f2569c' [2013-04-23 13:44:30] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Allocated port 18372 for RTP instance '0xb6f2569c' [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting '103.xxx.xxx.xxx' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting '103.xxx.xxx.xxx' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host '103.xxx.xxx.xxx' and port ''. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host '103.xxx.xxx.xxx' and port ''. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: RTP instance '0xb6f2569c' is setup and ready to go [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: RTP instance '0xb6f2569c' is setup and ready to go [2013-04-23 13:44:30] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb6f2569c' [2013-04-23 13:44:30] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb6f2569c' [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Setting NAT on RTP to On [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Setting NAT on RTP to On [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP v=0... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP o=root 6410 6410 IN IP4 81.201.85.81... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP o=root 6410 6410 IN IP4 81.201.85.81... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP s=session... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting '81.201.85.81' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting '81.201.85.81' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host '81.201.85.81' and port ''. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host '81.201.85.81' and port ''. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 81.201.85.81... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP c=IN IP4 81.201.85.81... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing session-level SDP t=0 0... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found RTP audio format 0 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found RTP audio format 0 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0xb628f2d8 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Setting payload 0 based on m type on 0xb628f2d8 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found RTP audio format 101 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found RTP audio format 101 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Setting payload 101 based on m type on 0xb628f2d8 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Setting payload 101 based on m type on 0xb628f2d8 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found audio description format PCMU for ID 0 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found audio description format PCMU for ID 0 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:0 PCMU/8000... OK. [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found audio description format telephone-event for ID 101 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Found audio description format telephone-event for ID 101 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=rtpmap:101 telephone-event/8000... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=fmtp:101 0-16... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=silenceSupp:off - - - -... UNSUPPORTED OR FAILED. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=ptime:20... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Processing media-level (audio) SDP a=sendrecv... OK. [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Capabilities: us - (ulaw|alaw|g729), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw) [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Capabilities: us - (ulaw|alaw|g729), peer - audio=(ulaw)/video=(nothing)/text=(nothing), combined - (ulaw) [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event|), peer - 0x1 (telephone-event|), combined - 0x1 (telephone-event|) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6f2569c' [2013-04-23 13:44:30] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6f2569c' [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Peer audio RTP is at port 81.201.85.81:10728 [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Peer audio RTP is at port 81.201.85.81:10728 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Copying payload 0 from 0xb628f2d8 to 0xb6f25848 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Copying payload 0 from 0xb628f2d8 to 0xb6f25848 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Copying payload 101 from 0xb628f2d8 to 0xb6f25848 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] rtp_engine.c: Copying payload 101 from 0xb628f2d8 to 0xb6f25848 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb6f2569c' [2013-04-23 13:44:30] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Ignoring duplicate RTCP property on RTP instance '0xb6f2569c' [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: We're settling with these formats: (ulaw) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Checking SIP call limits for device [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Checking SIP call limits for device [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Updating call counter for incoming call [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Updating call counter for incoming call [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting '103.xxx.xxx.xxx' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting '103.xxx.xxx.xxx' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host '103.xxx.xxx.xxx' and port ''. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host '103.xxx.xxx.xxx' and port ''. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting 'voxbone.com' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: Splitting 'voxbone.com' into... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host 'voxbone.com' and port ''. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] netsock2.c: ...host 'voxbone.com' and port ''. [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Looking for #0216479999999 in from-trunk-sip-VoxboneNY (domain 103.xxx.xxx.xxx) [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: Looking for #0216479999999 in from-trunk-sip-VoxboneNY (domain 103.xxx.xxx.xxx) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: *** Our capabilities are (ulaw|alaw|g729) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: *** Our capabilities are (ulaw|alaw|g729) [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: This channel will not be able to handle video. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: This channel will not be able to handle video. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: build_route: Contact hop: [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: build_route: Contact hop: [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: list_route: hop: [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: list_route: hop: [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: SIP/VoxboneNY-00000002: New call is still down.... Trying... [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: SIP/VoxboneNY-00000002: New call is still down.... Trying... [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: <--- Transmitting (NAT) to 81.201.xxx.xxx:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143;received=81.201.xxx.xxx;rport=5060 From: "15141234567" ;tag=59098 To: Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 INVITE Server: FPBX2.11.0rc1(11.3.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [2013-04-23 13:44:30] VERBOSE[25939][C-00000001] chan_sip.c: <--- Transmitting (NAT) to 81.201.xxx.xxx:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143;received=81.201.xxx.xxx;rport=5060 From: "15141234567" ;tag=59098 To: Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 INVITE Server: FPBX2.11.0rc1(11.3.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 81.201.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 100' onto UDP socket destined for 81.201.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[25939][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:30] DEBUG[25939][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk-sip-VoxboneNY:1] Set("SIP/VoxboneNY-00000002", "GROUP()=OUT_9") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk-sip-VoxboneNY:1] Set("SIP/VoxboneNY-00000002", "GROUP()=OUT_9") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'EXTEN' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'EXTEN' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Goto' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Goto' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk-sip-VoxboneNY:2] Goto("SIP/VoxboneNY-00000002", "from-trunk,#0216479999999,1") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk-sip-VoxboneNY:2] Goto("SIP/VoxboneNY-00000002", "from-trunk,#0216479999999,1") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (from-trunk,#0216479999999,1) [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (from-trunk,#0216479999999,1) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'EXTEN' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'EXTEN' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:1] Set("SIP/VoxboneNY-00000002", "__FROM_DID=#0216479999999") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:1] Set("SIP/VoxboneNY-00000002", "__FROM_DID=#0216479999999") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Gosub' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Gosub' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:2] Gosub("SIP/VoxboneNY-00000002", "app-blacklist-check,s,1()") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:2] Gosub("SIP/VoxboneNY-00000002", "app-blacklist-check,s,1()") in new stack [2013-04-23 13:44:30] DEBUG[25928] devicestate.c: No provider found, checking channel drivers for SIP - VoxboneNY [2013-04-23 13:44:30] DEBUG[25928] devicestate.c: No provider found, checking channel drivers for SIP - VoxboneNY [2013-04-23 13:44:30] DEBUG[26192][C-00000001] app_stack.c: Channel SIP/VoxboneNY-00000002 has no datastore, so we're allocating one. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] app_stack.c: Channel SIP/VoxboneNY-00000002 has no datastore, so we're allocating one. [2013-04-23 13:44:30] DEBUG[25928] chan_sip.c: Checking device state for peer VoxboneNY [2013-04-23 13:44:30] DEBUG[25928] chan_sip.c: Checking device state for peer VoxboneNY [2013-04-23 13:44:30] DEBUG[25928] devicestate.c: Changing state for SIP/VoxboneNY - state 1 (Not in use) [2013-04-23 13:44:30] DEBUG[25928] devicestate.c: Changing state for SIP/VoxboneNY - state 1 (Not in use) [2013-04-23 13:44:30] DEBUG[25928] devicestate.c: device 'SIP/VoxboneNY' state '1' [2013-04-23 13:44:30] DEBUG[25928] devicestate.c: device 'SIP/VoxboneNY' state '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] db.c: Unable to find key '15141234567' in family 'blacklist' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] db.c: Unable to find key '15141234567' in family 'blacklist' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] db.c: Unable to find key '15141234567' in family 'blacklist' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] db.c: Unable to find key '15141234567' in family 'blacklist' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '0' [2013-04-23 13:44:30] DEBUG[25959] app_queue.c: Device 'SIP/VoxboneNY' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2013-04-23 13:44:30] DEBUG[25959] app_queue.c: Device 'SIP/VoxboneNY' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'GotoIf' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'GotoIf' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/VoxboneNY-00000002", "0?blacklisted") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:1] GotoIf("SIP/VoxboneNY-00000002", "0?blacklisted") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Not taking any branch [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Not taking any branch [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/VoxboneNY-00000002", "CALLED_BLACKLIST=1") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:2] Set("SIP/VoxboneNY-00000002", "CALLED_BLACKLIST=1") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Return' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Return' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/VoxboneNY-00000002", "") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@app-blacklist-check:3] Return("SIP/VoxboneNY-00000002", "") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Gosub' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Gosub' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:3] Gosub("SIP/VoxboneNY-00000002", "sub-record-cancel,s,1()") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:3] Gosub("SIP/VoxboneNY-00000002", "sub-record-cancel,s,1()") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'REC_POLICY_MODE_SAVE' is NULL [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'REC_POLICY_MODE_SAVE' is NULL [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-record-cancel:1] Set("SIP/VoxboneNY-00000002", "__REC_POLICY_MODE=") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-record-cancel:1] Set("SIP/VoxboneNY-00000002", "__REC_POLICY_MODE=") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'REC_STATUS' is NULL [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'REC_STATUS' is NULL [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'ExecIf' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'ExecIf' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-record-cancel:2] ExecIf("SIP/VoxboneNY-00000002", "1?Return()") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-record-cancel:2] ExecIf("SIP/VoxboneNY-00000002", "1?Return()") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:4] Set("SIP/VoxboneNY-00000002", "__REC_POLICY_MODE=never") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:4] Set("SIP/VoxboneNY-00000002", "__REC_POLICY_MODE=never") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'FROM_DID' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'FROM_DID' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:5] Set("SIP/VoxboneNY-00000002", "CDR(did)=#0216479999999") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:5] Set("SIP/VoxboneNY-00000002", "CDR(did)=#0216479999999") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '15141234567' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '15141234567' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '15141234567' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '15141234567' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'ExecIf' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'ExecIf' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:6] ExecIf("SIP/VoxboneNY-00000002", "0 ?Set(CALLERID(name)=15141234567)") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:6] ExecIf("SIP/VoxboneNY-00000002", "0 ?Set(CALLERID(name)=15141234567)") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:7] Set("SIP/VoxboneNY-00000002", "CHANNEL(musicclass)=none") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:7] Set("SIP/VoxboneNY-00000002", "CHANNEL(musicclass)=none") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:8] Set("SIP/VoxboneNY-00000002", "__MOHCLASS=none") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:8] Set("SIP/VoxboneNY-00000002", "__MOHCLASS=none") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is 'allowed_not_screened' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is 'allowed_not_screened' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:9] Set("SIP/VoxboneNY-00000002", "__CALLINGPRES_SV=allowed_not_screened") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:9] Set("SIP/VoxboneNY-00000002", "__CALLINGPRES_SV=allowed_not_screened") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:10] Set("SIP/VoxboneNY-00000002", "CALLERPRES()=allowed_not_screened") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:10] Set("SIP/VoxboneNY-00000002", "CALLERPRES()=allowed_not_screened") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Goto' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Goto' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:11] Goto("SIP/VoxboneNY-00000002", "ext-trunk,5,1") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [#0216479999999@from-trunk:11] Goto("SIP/VoxboneNY-00000002", "ext-trunk,5,1") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (ext-trunk,5,1) [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (ext-trunk,5,1) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [5@ext-trunk:1] Set("SIP/VoxboneNY-00000002", "TDIAL_STRING=SIP/ABCAsia") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [5@ext-trunk:1] Set("SIP/VoxboneNY-00000002", "TDIAL_STRING=SIP/ABCAsia") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [5@ext-trunk:2] Set("SIP/VoxboneNY-00000002", "DIAL_TRUNK=5") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [5@ext-trunk:2] Set("SIP/VoxboneNY-00000002", "DIAL_TRUNK=5") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Goto' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Goto' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [5@ext-trunk:3] Goto("SIP/VoxboneNY-00000002", "ext-trunk,tdial,1") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [5@ext-trunk:3] Goto("SIP/VoxboneNY-00000002", "ext-trunk,tdial,1") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (ext-trunk,tdial,1) [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (ext-trunk,tdial,1) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:1] Set("SIP/VoxboneNY-00000002", "OUTBOUND_GROUP=OUT_5") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:1] Set("SIP/VoxboneNY-00000002", "OUTBOUND_GROUP=OUT_5") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'OUTMAXCHANS_5' is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'OUTMAXCHANS_5' is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'GotoIf' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'GotoIf' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:2] GotoIf("SIP/VoxboneNY-00000002", "1?nomax") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:2] GotoIf("SIP/VoxboneNY-00000002", "1?nomax") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (ext-trunk,tdial,4) [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (ext-trunk,tdial,4) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'CALLINGPRES_SV' is 'allowed_not_screened' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'CALLINGPRES_SV' is 'allowed_not_screened' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'CALLINGPRES_SV' is 'allowed_not_screened' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'CALLINGPRES_SV' is 'allowed_not_screened' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'ExecIf' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'ExecIf' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:4] ExecIf("SIP/VoxboneNY-00000002", "1?Set(CALLERPRES()=allowed_not_screened)") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:4] ExecIf("SIP/VoxboneNY-00000002", "1?Set(CALLERPRES()=allowed_not_screened)") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'FROM_DID' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'FROM_DID' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:5] Set("SIP/VoxboneNY-00000002", "DIAL_NUMBER=#0216479999999") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:5] Set("SIP/VoxboneNY-00000002", "DIAL_NUMBER=#0216479999999") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'PREFIX_TRUNK_5' is '2' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'PREFIX_TRUNK_5' is '2' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'GosubIf' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'GosubIf' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:6] GosubIf("SIP/VoxboneNY-00000002", "1?sub-flp-5,s,1()") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:6] GosubIf("SIP/VoxboneNY-00000002", "1?sub-flp-5,s,1()") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_NUMBER' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_NUMBER' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] func_strings.c: FUNCTION REGEX (^#66[0-9#\*\+]+$)(#0216479999999) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] func_strings.c: FUNCTION REGEX (^#66[0-9#\*\+]+$)(#0216479999999) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_NUMBER' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_NUMBER' is '#0216479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'ExecIf' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'ExecIf' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-flp-5:1] ExecIf("SIP/VoxboneNY-00000002", "1?Set(TARGET_FLP_5=+16479999999)") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-flp-5:1] ExecIf("SIP/VoxboneNY-00000002", "1?Set(TARGET_FLP_5=+16479999999)") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TARGET_FLP_5' is '+16479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TARGET_FLP_5' is '+16479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '12' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '12' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '1' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'GotoIf' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'GotoIf' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-flp-5:2] GotoIf("SIP/VoxboneNY-00000002", "1?match") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-flp-5:2] GotoIf("SIP/VoxboneNY-00000002", "1?match") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (sub-flp-5,s,6) [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Goto (sub-flp-5,s,6) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TARGET_FLP_5' is '+16479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TARGET_FLP_5' is '+16479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-flp-5:6] Set("SIP/VoxboneNY-00000002", "DIAL_NUMBER=+16479999999") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-flp-5:6] Set("SIP/VoxboneNY-00000002", "DIAL_NUMBER=+16479999999") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Return' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Return' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-flp-5:7] Return("SIP/VoxboneNY-00000002", "") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [s@sub-flp-5:7] Return("SIP/VoxboneNY-00000002", "") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'OUTPREFIX_5' is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'OUTPREFIX_5' is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_NUMBER' is '+16479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_NUMBER' is '+16479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:7] Set("SIP/VoxboneNY-00000002", "OUTNUM=+16479999999") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:7] Set("SIP/VoxboneNY-00000002", "OUTNUM=+16479999999") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK' is '5' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] db.c: Unable to find key '5/dialopts' in family 'TRUNK' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] db.c: Unable to find key '5/dialopts' in family 'TRUNK' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Expression result is '0' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DB_RESULT' is NULL [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DB_RESULT' is NULL [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TRUNK_OPTIONS' is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TRUNK_OPTIONS' is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Function result is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Set' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:8] Set("SIP/VoxboneNY-00000002", "DIAL_TRUNK_OPTIONS=") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:8] Set("SIP/VoxboneNY-00000002", "DIAL_TRUNK_OPTIONS=") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TDIAL_STRING' is 'SIP/ABCAsia' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TDIAL_STRING' is 'SIP/ABCAsia' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'OUTNUM' is '+16479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'OUTNUM' is '+16479999999' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TRUNK_RING_TIMER' is '300' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'TRUNK_RING_TIMER' is '300' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK_OPTIONS' is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Result of 'DIAL_TRUNK_OPTIONS' is '' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Dial' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] pbx.c: Launching 'Dial' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:9] Dial("SIP/VoxboneNY-00000002", "SIP/ABCAsia/+16479999999,300,") in new stack [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] pbx.c: -- Executing [tdial@ext-trunk:9] Dial("SIP/VoxboneNY-00000002", "SIP/ABCAsia/+16479999999,300,") in new stack [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Asked to create a SIP channel with formats: (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Allocating new SIP dialog for 37766afd63f63ee95575b8aa6d706277@103.xxx.xxx.xxx:5060 - INVITE (No RTP) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Allocating new SIP dialog for 37766afd63f63ee95575b8aa6d706277@103.xxx.xxx.xxx:5060 - INVITE (No RTP) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb6e2a994' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] rtp_engine.c: Using engine 'asterisk' for RTP instance '0xb6e2a994' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Allocated port 11194 for RTP instance '0xb6e2a994' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Allocated port 11194 for RTP instance '0xb6e2a994' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] netsock2.c: Splitting '103.xxx.xxx.xxx' into... [2013-04-23 13:44:30] DEBUG[26192][C-00000001] netsock2.c: Splitting '103.xxx.xxx.xxx' into... [2013-04-23 13:44:30] DEBUG[26192][C-00000001] netsock2.c: ...host '103.xxx.xxx.xxx' and port ''. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] netsock2.c: ...host '103.xxx.xxx.xxx' and port ''. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] rtp_engine.c: RTP instance '0xb6e2a994' is setup and ready to go [2013-04-23 13:44:30] DEBUG[26192][C-00000001] rtp_engine.c: RTP instance '0xb6e2a994' is setup and ready to go [2013-04-23 13:44:30] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb6e2a994' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Setup RTCP on RTP instance '0xb6e2a994' [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184 [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] netsock2.c: == Using SIP RTP TOS bits 184 [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] netsock2.c: == Using SIP RTP CoS mark 5 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Setting NAT on RTP to On [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Setting NAT on RTP to On [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: OBPROXY: Not applying OBproxy to this call [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: OBPROXY: Not applying OBproxy to this call [2013-04-23 13:44:30] DEBUG[26192][C-00000001] acl.c: For destination '202.xxx.xxx.xxx', our source address is '103.xxx.xxx.xxx'. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] acl.c: For destination '202.xxx.xxx.xxx', our source address is '103.xxx.xxx.xxx'. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Target address 202.xxx.xxx.xxx:5060 is not local, substituting externaddr [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Target address 202.xxx.xxx.xxx:5060 is not local, substituting externaddr [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Setting SIP_TRANSPORT_TCP with address 103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: SIP call-id changed from '37766afd63f63ee95575b8aa6d706277@103.xxx.xxx.xxx:5060' to '6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: SIP call-id changed from '37766afd63f63ee95575b8aa6d706277@103.xxx.xxx.xxx:5060' to '6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060' [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** Our native formats are (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** Joint capabilities are (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** Our capabilities are (ulaw|alaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** Our capabilities are (ulaw|alaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** AST_CODEC_CHOOSE formats are ulaw [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: *** Our preferred formats from the incoming channel are (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: This channel will not be able to handle video. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: This channel will not be able to handle video. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] dsp.c: Setup tone 1100 Hz, 500 ms, block_size=160, hits_required=21 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] dsp.c: Setup tone 2100 Hz, 2600 ms, block_size=160, hits_required=116 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel_internal_api.c: Channel Call ID changing from [C-00000001] to [C-00000001] [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIALEDTIME. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIALEDTIME. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable ANSWEREDTIME. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable ANSWEREDTIME. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIALEDPEERNAME. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIALEDPEERNAME. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIALEDPEERNUMBER. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIALEDPEERNUMBER. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIALSTATUS. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIALSTATUS. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIAL_TRUNK_OPTIONS. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIAL_TRUNK_OPTIONS. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable OUTNUM. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable OUTNUM. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable GOSUB_RETVAL. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable GOSUB_RETVAL. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIAL_NUMBER. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIAL_NUMBER. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable TARGET_FLP_5. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable TARGET_FLP_5. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable OUTBOUND_GROUP. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable OUTBOUND_GROUP. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIAL_TRUNK. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable DIAL_TRUNK. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable TDIAL_STRING. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable TDIAL_STRING. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Copying hard-transferable variable CALLINGPRES_SV. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Copying hard-transferable variable CALLINGPRES_SV. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Copying hard-transferable variable MOHCLASS. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Copying hard-transferable variable MOHCLASS. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Copying hard-transferable variable REC_POLICY_MODE. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Copying hard-transferable variable REC_POLICY_MODE. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable CALLED_BLACKLIST. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable CALLED_BLACKLIST. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Copying hard-transferable variable FROM_DID. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Copying hard-transferable variable FROM_DID. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable SIPCALLID. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable SIPCALLID. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable SIPDOMAIN. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable SIPDOMAIN. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable SIPURI. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] channel.c: Not copying variable SIPURI. [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Outgoing Call for +16479999999 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Outgoing Call for +16479999999 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Updating call counter for outgoing call [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Updating call counter for outgoing call [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: False Text flag: False [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: ** Our capability: (ulaw|alaw) Video flag: False Text flag: False [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: ** Our prefcodec: (ulaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: ** Our prefcodec: (ulaw) [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Audio is at 11194 [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Audio is at 11194 [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Adding codec 100003 (ulaw) to SDP [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Adding codec 100003 (ulaw) to SDP [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Adding codec 100004 (alaw) to SDP [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Adding codec 100004 (alaw) to SDP [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Adding non-codec 0x1 (telephone-event) to SDP [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: -- Done with adding codecs to SDP [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Done building SDP. Settling with this capability: (ulaw|alaw) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Initializing initreq for method INVITE - callid 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 0 [ 47]: INVITE sip:+16479999999@202.xxx.xxx.xxx SIP/2.0 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 0 [ 47]: INVITE sip:+16479999999@202.xxx.xxx.xxx SIP/2.0 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 1 [ 63]: Via: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 2 [ 16]: Max-Forwards: 70 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 3 [ 65]: From: "15141234567" ;tag=as6760216f [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 3 [ 65]: From: "15141234567" ;tag=as6760216f [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 4 [ 38]: To: [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 4 [ 38]: To: [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 5 [ 58]: Contact: [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 5 [ 58]: Contact: [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 6 [ 59]: Call-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 6 [ 59]: Call-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 7 [ 16]: CSeq: 102 INVITE [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 8 [ 33]: User-Agent: FPBX2.11.0rc1(11.3.0) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 8 [ 33]: User-Agent: FPBX2.11.0rc1(11.3.0) [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 9 [ 35]: Date: Tue, 23 Apr 2013 17:44:30 GMT [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 9 [ 35]: Date: Tue, 23 Apr 2013 17:44:30 GMT [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 10 [ 81]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 11 [ 26]: Supported: replaces, timer [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Header 12 [ 29]: Content-Type: application/sdp [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Reliably Transmitting (NAT) to 202.xxx.xxx.xxx:5060: INVITE sip:+16479999999@202.xxx.xxx.xxx SIP/2.0 Via: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport Max-Forwards: 70 From: "15141234567" ;tag=as6760216f To: Contact: Call-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 CSeq: 102 INVITE User-Agent: FPBX2.11.0rc1(11.3.0) Date: Tue, 23 Apr 2013 17:44:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 259 v=0 o=root 1772789492 1772789492 IN IP4 103.xxx.xxx.xxx s=Asterisk PBX 11.3.0 c=IN IP4 103.xxx.xxx.xxx t=0 0 m=audio 11194 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] chan_sip.c: Reliably Transmitting (NAT) to 202.xxx.xxx.xxx:5060: INVITE sip:+16479999999@202.xxx.xxx.xxx SIP/2.0 Via: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport Max-Forwards: 70 From: "15141234567" ;tag=as6760216f To: Contact: Call-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 CSeq: 102 INVITE User-Agent: FPBX2.11.0rc1(11.3.0) Date: Tue, 23 Apr 2013 17:44:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Type: application/sdp Content-Length: 259 v=0 o=root 1772789492 1772789492 IN IP4 103.xxx.xxx.xxx s=Asterisk PBX 11.3.0 c=IN IP4 103.xxx.xxx.xxx t=0 0 m=audio 11194 RTP/AVP 0 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv --- [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Trying to put 'INVITE sip:' onto TCP socket destined for 202.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26192][C-00000001] chan_sip.c: Trying to put 'INVITE sip:' onto TCP socket destined for 202.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] app_dial.c: -- Called SIP/ABCAsia/+16479999999 [2013-04-23 13:44:30] VERBOSE[26192][C-00000001] app_dial.c: -- Called SIP/ABCAsia/+16479999999 [2013-04-23 13:44:30] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 100 Trying FROM: "15141234567";tag=as6760216f TO: CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTENT-LENGTH: 0 <-------------> [2013-04-23 13:44:30] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 100 Trying FROM: "15141234567";tag=as6760216f TO: CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTENT-LENGTH: 0 <-------------> [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 0 [ 18]: SIP/2.0 100 Trying [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 2 [ 38]: TO: [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 2 [ 38]: TO: [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:30] VERBOSE[26119] chan_sip.c: --- (7 headers 0 lines) --- [2013-04-23 13:44:30] VERBOSE[26119] chan_sip.c: --- (7 headers 0 lines) --- [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag [2013-04-23 13:44:30] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag [2013-04-23 13:44:30] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:30] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:30] DEBUG[26119][C-00000001] chan_sip.c: SIP response 100 to standard invite [2013-04-23 13:44:30] DEBUG[26119][C-00000001] chan_sip.c: SIP response 100 to standard invite [2013-04-23 13:44:30] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:30] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:31] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6e2a994' [2013-04-23 13:44:31] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6e2a994' [2013-04-23 13:44:31] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:31] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:31] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 84 bytes [2013-04-23 13:44:31] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 84 bytes [2013-04-23 13:44:33] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:33] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:33] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:33] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:33] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 183 Session Progress FROM: "15141234567";tag=as6760216f TO: ;tag=b76b2c1233;epid=B28FC44EFA CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTACT: CONTENT-LENGTH: 0 ALLOW: CANCEL ALLOW: BYE ALLOW: UPDATE ALLOW: PRACK SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:33] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 183 Session Progress FROM: "15141234567";tag=as6760216f TO: ;tag=b76b2c1233;epid=B28FC44EFA CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTACT: CONTENT-LENGTH: 0 ALLOW: CANCEL ALLOW: BYE ALLOW: UPDATE ALLOW: PRACK SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 2 [ 69]: TO: ;tag=b76b2c1233;epid=B28FC44EFA [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 2 [ 69]: TO: ;tag=b76b2c1233;epid=B28FC44EFA [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 6 [ 87]: CONTACT: [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 6 [ 87]: CONTACT: [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 8 [ 13]: ALLOW: CANCEL [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 8 [ 13]: ALLOW: CANCEL [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 9 [ 10]: ALLOW: BYE [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 9 [ 10]: ALLOW: BYE [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 10 [ 13]: ALLOW: UPDATE [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 10 [ 13]: ALLOW: UPDATE [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 11 [ 12]: ALLOW: PRACK [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 11 [ 12]: ALLOW: PRACK [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 12 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: Header 12 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:33] VERBOSE[26119] chan_sip.c: --- (13 headers 0 lines) --- [2013-04-23 13:44:33] VERBOSE[26119] chan_sip.c: --- (13 headers 0 lines) --- [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag b76b2c1233 [2013-04-23 13:44:33] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag b76b2c1233 [2013-04-23 13:44:33] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:33] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:33] DEBUG[26119][C-00000001] chan_sip.c: SIP response 183 to standard invite [2013-04-23 13:44:33] DEBUG[26119][C-00000001] chan_sip.c: SIP response 183 to standard invite [2013-04-23 13:44:33] DEBUG[26119][C-00000001] chan_sip.c: build_route: Contact hop: [2013-04-23 13:44:33] DEBUG[26119][C-00000001] chan_sip.c: build_route: Contact hop: [2013-04-23 13:44:33] VERBOSE[26119][C-00000001] chan_sip.c: list_route: hop: [2013-04-23 13:44:33] VERBOSE[26119][C-00000001] chan_sip.c: list_route: hop: [2013-04-23 13:44:33] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:33] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:33] VERBOSE[26192][C-00000001] app_dial.c: -- SIP/ABCAsia-00000003 is ringing [2013-04-23 13:44:33] VERBOSE[26192][C-00000001] app_dial.c: -- SIP/ABCAsia-00000003 is ringing [2013-04-23 13:44:33] DEBUG[26192][C-00000001] rtp_engine.c: Setting early bridge SDP of 'SIP/VoxboneNY-00000002' with that of 'SIP/ABCAsia-00000003' [2013-04-23 13:44:33] DEBUG[26192][C-00000001] rtp_engine.c: Setting early bridge SDP of 'SIP/VoxboneNY-00000002' with that of 'SIP/ABCAsia-00000003' [2013-04-23 13:44:33] VERBOSE[26192][C-00000001] chan_sip.c: <--- Transmitting (NAT) to 81.201.xxx.xxx:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143;received=81.201.xxx.xxx;rport=5060 From: "15141234567" ;tag=59098 To: ;tag=as2e90450e Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 INVITE Server: FPBX2.11.0rc1(11.3.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [2013-04-23 13:44:33] VERBOSE[26192][C-00000001] chan_sip.c: <--- Transmitting (NAT) to 81.201.xxx.xxx:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143;received=81.201.xxx.xxx;rport=5060 From: "15141234567" ;tag=59098 To: ;tag=as2e90450e Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 INVITE Server: FPBX2.11.0rc1(11.3.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Contact: Content-Length: 0 <------------> [2013-04-23 13:44:33] DEBUG[26192][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 81.201.xxx.xxx:5060 [2013-04-23 13:44:33] DEBUG[26192][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 180' onto UDP socket destined for 81.201.xxx.xxx:5060 [2013-04-23 13:44:34] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 183 Session Progress FROM: "15141234567";tag=as6760216f TO: ;tag=b76b2c1233;epid=B28FC44EFA CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTACT: CONTENT-LENGTH: 0 ALLOW: CANCEL ALLOW: BYE ALLOW: UPDATE ALLOW: PRACK SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:34] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 183 Session Progress FROM: "15141234567";tag=as6760216f TO: ;tag=b76b2c1233;epid=B28FC44EFA CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTACT: CONTENT-LENGTH: 0 ALLOW: CANCEL ALLOW: BYE ALLOW: UPDATE ALLOW: PRACK SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 2 [ 69]: TO: ;tag=b76b2c1233;epid=B28FC44EFA [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 2 [ 69]: TO: ;tag=b76b2c1233;epid=B28FC44EFA [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 6 [ 87]: CONTACT: [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 6 [ 87]: CONTACT: [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 8 [ 13]: ALLOW: CANCEL [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 8 [ 13]: ALLOW: CANCEL [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 9 [ 10]: ALLOW: BYE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 9 [ 10]: ALLOW: BYE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 10 [ 13]: ALLOW: UPDATE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 10 [ 13]: ALLOW: UPDATE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 11 [ 12]: ALLOW: PRACK [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 11 [ 12]: ALLOW: PRACK [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 12 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 12 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:34] VERBOSE[26119] chan_sip.c: --- (13 headers 0 lines) --- [2013-04-23 13:44:34] VERBOSE[26119] chan_sip.c: --- (13 headers 0 lines) --- [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag b76b2c1233 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag b76b2c1233 [2013-04-23 13:44:34] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:34] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:34] DEBUG[26119][C-00000001] chan_sip.c: SIP response 183 to standard invite [2013-04-23 13:44:34] DEBUG[26119][C-00000001] chan_sip.c: SIP response 183 to standard invite [2013-04-23 13:44:34] DEBUG[26119][C-00000001] chan_sip.c: build_route: Contact hop: [2013-04-23 13:44:34] DEBUG[26119][C-00000001] chan_sip.c: build_route: Contact hop: [2013-04-23 13:44:34] VERBOSE[26119][C-00000001] chan_sip.c: list_route: hop: [2013-04-23 13:44:34] VERBOSE[26119][C-00000001] chan_sip.c: list_route: hop: [2013-04-23 13:44:34] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:34] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:34] VERBOSE[26192][C-00000001] app_dial.c: -- SIP/ABCAsia-00000003 is ringing [2013-04-23 13:44:34] VERBOSE[26192][C-00000001] app_dial.c: -- SIP/ABCAsia-00000003 is ringing [2013-04-23 13:44:34] DEBUG[26192][C-00000001] rtp_engine.c: Setting early bridge SDP of 'SIP/VoxboneNY-00000002' with that of 'SIP/ABCAsia-00000003' [2013-04-23 13:44:34] DEBUG[26192][C-00000001] rtp_engine.c: Setting early bridge SDP of 'SIP/VoxboneNY-00000002' with that of 'SIP/ABCAsia-00000003' [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- start learning mode pass with addr = 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- start learning mode pass with addr = 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- probation = 4, seq = 31542 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- probation = 4, seq = 31542 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- Condition for learning hasn't exited, so reject the frame. [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- Condition for learning hasn't exited, so reject the frame. [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- start learning mode pass with addr = 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- start learning mode pass with addr = 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- probation = 3, seq = 31543 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- probation = 3, seq = 31543 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- Condition for learning hasn't exited, so reject the frame. [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- Condition for learning hasn't exited, so reject the frame. [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- start learning mode pass with addr = 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- start learning mode pass with addr = 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- probation = 2, seq = 31544 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- probation = 2, seq = 31544 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- Condition for learning hasn't exited, so reject the frame. [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- Condition for learning hasn't exited, so reject the frame. [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- start learning mode pass with addr = 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- start learning mode pass with addr = 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- probation = 1, seq = 31545 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- probation = 1, seq = 31545 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] DEBUG[26192][C-00000001] res_rtp_asterisk.c: 0xb6e2f8e8 -- Probation Ended. Set strict_rtp_state to STRICT_RTP_CLOSED with address 202.xxx.xxx.xxx:55514 [2013-04-23 13:44:34] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 183 Session Progress FROM: "15141234567";tag=as6760216f TO: ;tag=b76b2c1233;epid=B28FC44EFA CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTACT: CONTENT-LENGTH: 0 ALLOW: CANCEL ALLOW: BYE ALLOW: UPDATE ALLOW: PRACK SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:34] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 183 Session Progress FROM: "15141234567";tag=as6760216f TO: ;tag=b76b2c1233;epid=B28FC44EFA CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTACT: CONTENT-LENGTH: 0 ALLOW: CANCEL ALLOW: BYE ALLOW: UPDATE ALLOW: PRACK SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 0 [ 28]: SIP/2.0 183 Session Progress [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 2 [ 69]: TO: ;tag=b76b2c1233;epid=B28FC44EFA [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 2 [ 69]: TO: ;tag=b76b2c1233;epid=B28FC44EFA [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 6 [ 87]: CONTACT: [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 6 [ 87]: CONTACT: [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 7 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 8 [ 13]: ALLOW: CANCEL [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 8 [ 13]: ALLOW: CANCEL [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 9 [ 10]: ALLOW: BYE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 9 [ 10]: ALLOW: BYE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 10 [ 13]: ALLOW: UPDATE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 10 [ 13]: ALLOW: UPDATE [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 11 [ 12]: ALLOW: PRACK [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 11 [ 12]: ALLOW: PRACK [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 12 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: Header 12 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:34] VERBOSE[26119] chan_sip.c: --- (13 headers 0 lines) --- [2013-04-23 13:44:34] VERBOSE[26119] chan_sip.c: --- (13 headers 0 lines) --- [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag b76b2c1233 [2013-04-23 13:44:34] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag b76b2c1233 [2013-04-23 13:44:34] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:34] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:34] DEBUG[26119][C-00000001] chan_sip.c: SIP response 183 to standard invite [2013-04-23 13:44:34] DEBUG[26119][C-00000001] chan_sip.c: SIP response 183 to standard invite [2013-04-23 13:44:34] DEBUG[26119][C-00000001] chan_sip.c: build_route: Contact hop: [2013-04-23 13:44:34] DEBUG[26119][C-00000001] chan_sip.c: build_route: Contact hop: [2013-04-23 13:44:34] VERBOSE[26119][C-00000001] chan_sip.c: list_route: hop: [2013-04-23 13:44:34] VERBOSE[26119][C-00000001] chan_sip.c: list_route: hop: [2013-04-23 13:44:34] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:34] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:34] VERBOSE[26192][C-00000001] app_dial.c: -- SIP/ABCAsia-00000003 is ringing [2013-04-23 13:44:34] VERBOSE[26192][C-00000001] app_dial.c: -- SIP/ABCAsia-00000003 is ringing [2013-04-23 13:44:34] DEBUG[26192][C-00000001] rtp_engine.c: Setting early bridge SDP of 'SIP/VoxboneNY-00000002' with that of 'SIP/ABCAsia-00000003' [2013-04-23 13:44:34] DEBUG[26192][C-00000001] rtp_engine.c: Setting early bridge SDP of 'SIP/VoxboneNY-00000002' with that of 'SIP/ABCAsia-00000003' [2013-04-23 13:44:35] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 236 bytes [2013-04-23 13:44:35] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 236 bytes [2013-04-23 13:44:35] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:35] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:35] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:35] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:40] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:41] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:42] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:43] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:44] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:45] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:46] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 28 bytes [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Got RTCP report of 104 bytes [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: <--- SIP read from UDP:81.201.xxx.xxx:5060 ---> CANCEL sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx To: CSeq: 102 CANCEL From: "15141234567" ;tag=59098 Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 Max-Forwards: 69 Content-Length: 0 <-------------> [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: <--- SIP read from UDP:81.201.xxx.xxx:5060 ---> CANCEL sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx To: CSeq: 102 CANCEL From: "15141234567" ;tag=59098 Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 Max-Forwards: 69 Content-Length: 0 <-------------> [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 0 [ 46]: CANCEL sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 0 [ 46]: CANCEL sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 1 [ 48]: Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 1 [ 48]: Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 2 [ 37]: To: [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 2 [ 37]: To: [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 3 [ 16]: CSeq: 102 CANCEL [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 3 [ 16]: CSeq: 102 CANCEL [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 4 [ 59]: From: "15141234567" ;tag=59098 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 4 [ 59]: From: "15141234567" ;tag=59098 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 5 [ 89]: Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 5 [ 89]: Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 6 [ 16]: Max-Forwards: 69 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 6 [ 16]: Max-Forwards: 69 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: --- (8 headers 0 lines) --- [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: --- (8 headers 0 lines) --- [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: = Looking for Call ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx (Checking From) --From tag 59098 --To-tag [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: = Looking for Call ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx (Checking From) --From tag 59098 --To-tag [2013-04-23 13:44:47] DEBUG[25939][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:47] DEBUG[25939][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [2013-04-23 13:44:47] DEBUG[25939][C-00000001] netsock2.c: Splitting '81.201.xxx.xxx:5060' into... [2013-04-23 13:44:47] DEBUG[25939][C-00000001] netsock2.c: Splitting '81.201.xxx.xxx:5060' into... [2013-04-23 13:44:47] DEBUG[25939][C-00000001] netsock2.c: ...host '81.201.xxx.xxx' and port '5060'. [2013-04-23 13:44:47] DEBUG[25939][C-00000001] netsock2.c: ...host '81.201.xxx.xxx' and port '5060'. [2013-04-23 13:44:47] VERBOSE[25939][C-00000001] chan_sip.c: Sending to 81.201.xxx.xxx:5060 (NAT) [2013-04-23 13:44:47] VERBOSE[25939][C-00000001] chan_sip.c: Sending to 81.201.xxx.xxx:5060 (NAT) [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: Setting SIP_ALREADYGONE on dialog BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: Setting SIP_ALREADYGONE on dialog BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6f2569c' [2013-04-23 13:44:47] DEBUG[25939][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6f2569c' [2013-04-23 13:44:47] VERBOSE[25939][C-00000001] chan_sip.c: <--- Reliably Transmitting (NAT) to 81.201.xxx.xxx:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143;received=81.201.xxx.xxx;rport=5060 From: "15141234567" ;tag=59098 To: ;tag=as2e90450e Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 INVITE Server: FPBX2.11.0rc1(11.3.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [2013-04-23 13:44:47] VERBOSE[25939][C-00000001] chan_sip.c: <--- Reliably Transmitting (NAT) to 81.201.xxx.xxx:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143;received=81.201.xxx.xxx;rport=5060 From: "15141234567" ;tag=59098 To: ;tag=as2e90450e Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 INVITE Server: FPBX2.11.0rc1(11.3.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #160 [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: *** SIP TIMER: Initializing retransmit timer on packet: Id #160 [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for 81.201.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 487' onto UDP socket destined for 81.201.xxx.xxx:5060 [2013-04-23 13:44:47] VERBOSE[25939][C-00000001] chan_sip.c: <--- Transmitting (NAT) to 81.201.xxx.xxx:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143;received=81.201.xxx.xxx;rport=5060 From: "15141234567" ;tag=59098 To: ;tag=as2e90450e Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 CANCEL Server: FPBX2.11.0rc1(11.3.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [2013-04-23 13:44:47] VERBOSE[25939][C-00000001] chan_sip.c: <--- Transmitting (NAT) to 81.201.xxx.xxx:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143;received=81.201.xxx.xxx;rport=5060 From: "15141234567" ;tag=59098 To: ;tag=as2e90450e Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx CSeq: 102 CANCEL Server: FPBX2.11.0rc1(11.3.0) Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO, PUBLISH Supported: replaces, timer Content-Length: 0 <------------> [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 81.201.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: Trying to put 'SIP/2.0 200' onto UDP socket destined for 81.201.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[25939][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:47] DEBUG[25939][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:47] DEBUG[26192][C-00000001] channel.c: Hanging up channel 'SIP/ABCAsia-00000003' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] channel.c: Hanging up channel 'SIP/ABCAsia-00000003' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Hangup call SIP/ABCAsia-00000003, SIP callid 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Hangup call SIP/ABCAsia-00000003, SIP callid 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Hanging up channel in state Down (not UP) [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Hanging up channel in state Down (not UP) [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6e2a994' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6e2a994' [2013-04-23 13:44:47] VERBOSE[26192][C-00000001] chan_sip.c: Scheduling destruction of SIP dialog '6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060' in 32000 ms (Method: INVITE) [2013-04-23 13:44:47] VERBOSE[26192][C-00000001] chan_sip.c: Scheduling destruction of SIP dialog '6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060' in 32000 ms (Method: INVITE) [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Strict routing enforced for session 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Strict routing enforced for session 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] VERBOSE[26192][C-00000001] chan_sip.c: Reliably Transmitting (NAT) to 202.xxx.xxx.xxx:5060: CANCEL sip:+16479999999@202.xxx.xxx.xxx SIP/2.0 Via: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport Max-Forwards: 70 From: "15141234567" ;tag=as6760216f To: Call-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 CSeq: 102 CANCEL User-Agent: FPBX2.11.0rc1(11.3.0) Content-Length: 0 --- [2013-04-23 13:44:47] VERBOSE[26192][C-00000001] chan_sip.c: Reliably Transmitting (NAT) to 202.xxx.xxx.xxx:5060: CANCEL sip:+16479999999@202.xxx.xxx.xxx SIP/2.0 Via: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport Max-Forwards: 70 From: "15141234567" ;tag=as6760216f To: Call-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 CSeq: 102 CANCEL User-Agent: FPBX2.11.0rc1(11.3.0) Content-Length: 0 --- [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Trying to put 'CANCEL sip:' onto TCP socket destined for 202.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Trying to put 'CANCEL sip:' onto TCP socket destined for 202.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] VERBOSE[26192][C-00000001] chan_sip.c: Scheduling destruction of SIP dialog '6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060' in 32000 ms (Method: INVITE) [2013-04-23 13:44:47] VERBOSE[26192][C-00000001] chan_sip.c: Scheduling destruction of SIP dialog '6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060' in 32000 ms (Method: INVITE) [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: No provider found, checking channel drivers for SIP - ABCAsia [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: No provider found, checking channel drivers for SIP - ABCAsia [2013-04-23 13:44:47] DEBUG[25928] chan_sip.c: Checking device state for peer ABCAsia [2013-04-23 13:44:47] DEBUG[25928] chan_sip.c: Checking device state for peer ABCAsia [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: Changing state for SIP/ABCAsia - state 1 (Not in use) [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: Changing state for SIP/ABCAsia - state 1 (Not in use) [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: device 'SIP/ABCAsia' state '1' [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: device 'SIP/ABCAsia' state '1' [2013-04-23 13:44:47] DEBUG[25959] app_queue.c: Device 'SIP/ABCAsia' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2013-04-23 13:44:47] DEBUG[25959] app_queue.c: Device 'SIP/ABCAsia' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2013-04-23 13:44:47] DEBUG[26192][C-00000001] app_dial.c: Exiting with DIALSTATUS=CANCEL. [2013-04-23 13:44:47] DEBUG[26192][C-00000001] app_dial.c: Exiting with DIALSTATUS=CANCEL. [2013-04-23 13:44:47] DEBUG[26192][C-00000001] pbx.c: Spawn extension (ext-trunk,tdial,9) exited non-zero on 'SIP/VoxboneNY-00000002' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] pbx.c: Spawn extension (ext-trunk,tdial,9) exited non-zero on 'SIP/VoxboneNY-00000002' [2013-04-23 13:44:47] VERBOSE[26192][C-00000001] pbx.c: == Spawn extension (ext-trunk, tdial, 9) exited non-zero on 'SIP/VoxboneNY-00000002' [2013-04-23 13:44:47] VERBOSE[26192][C-00000001] pbx.c: == Spawn extension (ext-trunk, tdial, 9) exited non-zero on 'SIP/VoxboneNY-00000002' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] channel.c: Soft-Hanging up channel 'SIP/VoxboneNY-00000002' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] channel.c: Soft-Hanging up channel 'SIP/VoxboneNY-00000002' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] channel.c: Hanging up channel 'SIP/VoxboneNY-00000002' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] channel.c: Hanging up channel 'SIP/VoxboneNY-00000002' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Hangup call SIP/VoxboneNY-00000002, SIP callid BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[26192][C-00000001] chan_sip.c: Hangup call SIP/VoxboneNY-00000002, SIP callid BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6f2569c' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] res_rtp_asterisk.c: Setting RTCP address on RTP instance '0xb6f2569c' [2013-04-23 13:44:47] DEBUG[26192][C-00000001] cdr_mysql.c: Inserting a CDR record. [2013-04-23 13:44:47] DEBUG[26192][C-00000001] cdr_mysql.c: Inserting a CDR record. [2013-04-23 13:44:47] DEBUG[26192][C-00000001] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`did`) VALUES ('2013-04-23 13:44:30','\"15141234567\" <15141234567>','15141234567','tdial','ext-trunk','SIP/VoxboneNY-00000002','SIP/ABCAsia-00000003','Dial','SIP/ABCAsia/+16479999999,300,','17','0','NO ANSWER','3','1366739070.2','#0216479999999') [2013-04-23 13:44:47] DEBUG[26192][C-00000001] cdr_mysql.c: SQL command as follows: INSERT INTO cdr (`calldate`,`clid`,`src`,`dst`,`dcontext`,`channel`,`dstchannel`,`lastapp`,`lastdata`,`duration`,`billsec`,`disposition`,`amaflags`,`uniqueid`,`did`) VALUES ('2013-04-23 13:44:30','\"15141234567\" <15141234567>','15141234567','tdial','ext-trunk','SIP/VoxboneNY-00000002','SIP/ABCAsia-00000003','Dial','SIP/ABCAsia/+16479999999,300,','17','0','NO ANSWER','3','1366739070.2','#0216479999999') [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: No provider found, checking channel drivers for SIP - VoxboneNY [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: No provider found, checking channel drivers for SIP - VoxboneNY [2013-04-23 13:44:47] DEBUG[25928] chan_sip.c: Checking device state for peer VoxboneNY [2013-04-23 13:44:47] DEBUG[25928] chan_sip.c: Checking device state for peer VoxboneNY [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: Changing state for SIP/VoxboneNY - state 1 (Not in use) [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: Changing state for SIP/VoxboneNY - state 1 (Not in use) [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: device 'SIP/VoxboneNY' state '1' [2013-04-23 13:44:47] DEBUG[25928] devicestate.c: device 'SIP/VoxboneNY' state '1' [2013-04-23 13:44:47] DEBUG[25959] app_queue.c: Device 'SIP/VoxboneNY' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2013-04-23 13:44:47] DEBUG[25959] app_queue.c: Device 'SIP/VoxboneNY' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [2013-04-23 13:44:47] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 487 Request Terminated FROM: "15141234567";tag=as6760216f TO: ;epid=B28FC44EFA;tag=b76b2c1233 CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTENT-LENGTH: 0 SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:47] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 487 Request Terminated FROM: "15141234567";tag=as6760216f TO: ;epid=B28FC44EFA;tag=b76b2c1233 CSEQ: 102 INVITE CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTENT-LENGTH: 0 SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 0 [ 30]: SIP/2.0 487 Request Terminated [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 0 [ 30]: SIP/2.0 487 Request Terminated [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 2 [ 69]: TO: ;epid=B28FC44EFA;tag=b76b2c1233 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 2 [ 69]: TO: ;epid=B28FC44EFA;tag=b76b2c1233 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 INVITE [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 7 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 7 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:47] VERBOSE[26119] chan_sip.c: --- (8 headers 0 lines) --- [2013-04-23 13:44:47] VERBOSE[26119] chan_sip.c: --- (8 headers 0 lines) --- [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag b76b2c1233 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag b76b2c1233 [2013-04-23 13:44:47] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:47] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:47] DEBUG[26119][C-00000001] chan_sip.c: SIP response 487 to standard invite [2013-04-23 13:44:47] DEBUG[26119][C-00000001] chan_sip.c: SIP response 487 to standard invite [2013-04-23 13:44:47] DEBUG[26119][C-00000001] chan_sip.c: Strict routing enforced for session 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26119][C-00000001] chan_sip.c: Strict routing enforced for session 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] VERBOSE[26119][C-00000001] chan_sip.c: Transmitting (NAT) to 202.xxx.xxx.xxx:5060: ACK sip:LYNC10xxxHK.NY.ABC.com:5060;transport=Tcp;maddr=202.xxx.xxx.xxx SIP/2.0 Via: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport Max-Forwards: 70 From: "15141234567" ;tag=as6760216f To: ;tag=b76b2c1233 Contact: Call-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 CSeq: 102 ACK User-Agent: FPBX2.11.0rc1(11.3.0) Content-Length: 0 --- [2013-04-23 13:44:47] VERBOSE[26119][C-00000001] chan_sip.c: Transmitting (NAT) to 202.xxx.xxx.xxx:5060: ACK sip:LYNC10xxxHK.NY.ABC.com:5060;transport=Tcp;maddr=202.xxx.xxx.xxx SIP/2.0 Via: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport Max-Forwards: 70 From: "15141234567" ;tag=as6760216f To: ;tag=b76b2c1233 Contact: Call-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 CSeq: 102 ACK User-Agent: FPBX2.11.0rc1(11.3.0) Content-Length: 0 --- [2013-04-23 13:44:47] DEBUG[26119][C-00000001] chan_sip.c: Trying to put 'ACK sip:LYN' onto TCP socket destined for 202.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26119][C-00000001] chan_sip.c: Trying to put 'ACK sip:LYN' onto TCP socket destined for 202.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26119][C-00000001] chan_sip.c: Updating call counter for outgoing call [2013-04-23 13:44:47] DEBUG[26119][C-00000001] chan_sip.c: Updating call counter for outgoing call [2013-04-23 13:44:47] VERBOSE[26119][C-00000001] chan_sip.c: Scheduling destruction of SIP dialog '6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060' in 32000 ms (Method: INVITE) [2013-04-23 13:44:47] VERBOSE[26119][C-00000001] chan_sip.c: Scheduling destruction of SIP dialog '6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060' in 32000 ms (Method: INVITE) [2013-04-23 13:44:47] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:47] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:47] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 200 OK FROM: "15141234567";tag=as6760216f TO: ;epid=B28FC44EFA CSEQ: 102 CANCEL CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTENT-LENGTH: 0 SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:47] VERBOSE[26119] chan_sip.c: <--- SIP read from TCP:202.xxx.xxx.xxx:5060 ---> SIP/2.0 200 OK FROM: "15141234567";tag=as6760216f TO: ;epid=B28FC44EFA CSEQ: 102 CANCEL CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport CONTENT-LENGTH: 0 SERVER: RTCC/4.0.0.0 MediationServer <-------------> [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 0 [ 14]: SIP/2.0 200 OK [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 1 [ 64]: FROM: "15141234567";tag=as6760216f [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 2 [ 54]: TO: ;epid=B28FC44EFA [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 2 [ 54]: TO: ;epid=B28FC44EFA [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 CANCEL [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 3 [ 16]: CSEQ: 102 CANCEL [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 4 [ 59]: CALL-ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 5 [ 63]: VIA: SIP/2.0/TCP 103.xxx.xxx.xxx:5060;branch=z9hG4bK6bcd145f;rport [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 6 [ 17]: CONTENT-LENGTH: 0 [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 7 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: Header 7 [ 36]: SERVER: RTCC/4.0.0.0 MediationServer [2013-04-23 13:44:47] VERBOSE[26119] chan_sip.c: --- (8 headers 0 lines) --- [2013-04-23 13:44:47] VERBOSE[26119] chan_sip.c: --- (8 headers 0 lines) --- [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag [2013-04-23 13:44:47] DEBUG[26119] chan_sip.c: = Looking for Call ID: 6017da2456c38fed1a9d492c4b9d8f43@103.xxx.xxx.xxx:5060 (Checking To) --From tag as6760216f --To-tag [2013-04-23 13:44:47] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:47] DEBUG[26119][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:47] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:47] DEBUG[26119][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: <--- SIP read from UDP:81.201.xxx.xxx:5060 ---> ACK sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx Max-Forwards: 69 From: "15141234567" ;tag=59098 To: ;tag=as2e90450e Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 CSeq: 102 ACK Content-Length: 0 <-------------> [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: <--- SIP read from UDP:81.201.xxx.xxx:5060 ---> ACK sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx Max-Forwards: 69 From: "15141234567" ;tag=59098 To: ;tag=as2e90450e Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 CSeq: 102 ACK Content-Length: 0 <-------------> [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 0 [ 43]: ACK sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 0 [ 43]: ACK sip:#0216479999999@103.xxx.xxx.xxx SIP/2.0 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 1 [ 48]: Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 1 [ 48]: Call-ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 2 [ 16]: Max-Forwards: 69 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 2 [ 16]: Max-Forwards: 69 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 3 [ 59]: From: "15141234567" ;tag=59098 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 3 [ 59]: From: "15141234567" ;tag=59098 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 4 [ 52]: To: ;tag=as2e90450e [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 4 [ 52]: To: ;tag=as2e90450e [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 5 [ 89]: Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 5 [ 89]: Via: SIP/2.0/UDP 81.201.xxx.xxx:5060;branch=z9hG4bK-343935-4e777b42e1a81e9427cf334ce46bc143 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 6 [ 13]: CSeq: 102 ACK [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 6 [ 13]: CSeq: 102 ACK [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Header 7 [ 17]: Content-Length: 0 [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: --- (8 headers 0 lines) --- [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: --- (8 headers 0 lines) --- [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: = Looking for Call ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx (Checking From) --From tag 59098 --To-tag as2e90450e [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: = Looking for Call ID: BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx (Checking From) --From tag 59098 --To-tag as2e90450e [2013-04-23 13:44:47] DEBUG[25939][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:47] DEBUG[25939][C-00000001] logger.c: CALL_ID [C-00000001] bound to thread. [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #160 [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #160 [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: Stopping retransmission on 'BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx' of Response 102: Match Found [2013-04-23 13:44:47] DEBUG[25939][C-00000001] chan_sip.c: Stopping retransmission on 'BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx' of Response 102: Match Found [2013-04-23 13:44:47] DEBUG[25939][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:47] DEBUG[25939][C-00000001] logger.c: Call_ID [C-00000001] being removed from thread. [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Destroying SIP dialog BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] DEBUG[25939] chan_sip.c: Destroying SIP dialog BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: Really destroying SIP dialog 'BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx' Method: ACK [2013-04-23 13:44:47] VERBOSE[25939] chan_sip.c: Really destroying SIP dialog 'BBBDSM2BHZGYRI4PKK5JLSPWOM@81.201.xxx.xxx' Method: ACK [2013-04-23 13:44:47] DEBUG[25939] rtp_engine.c: Destroyed RTP instance '0xb6f2569c' [2013-04-23 13:44:47] DEBUG[25939] rtp_engine.c: Destroyed RTP instance '0xb6f2569c' FreePBX®FreePBX is a registered trademark of Schmooze Com., Inc. FreePBX 2.11.0.0rc1.2 is licensed under the GPL Copyright© 2013www.schmoozecom.com