[Apr 3 03:30:40] VERBOSE[19667] logger.c: <--- SIP read from 111.111.111.111:5060 ---> INVITE sip:10123456789@asterisk SIP/2.0 Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;rport From: "0000000000" ;tag=as1b00c647 To: Contact: Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Tue, 03 Apr 2007 07:30:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 287 v=0 o=root 2808 2808 IN IP4 111.111.111.111 s=session c=IN IP4 111.111.111.111 t=0 0 m=audio 19622 RTP/AVP 8 0 3 97 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - <-------------> [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 0: INVITE sip:10123456789@asterisk SIP/2.0 (51) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;rport (63) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1b00c647 (63) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 3: To: (42) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 4: Contact: (38) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 5: Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 (54) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 9: Date: Tue, 03 Apr 2007 07:30:40 GMT (35) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 11: Content-Type: application/sdp (29) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 12: Content-Length: 287 (19) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 13: (0) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: v=0 (3) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: o=root 2808 2808 IN IP4 111.111.111.111 (36) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: s=session (9) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: c=IN IP4 111.111.111.111 (21) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: t=0 0 (5) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: m=audio 19622 RTP/AVP 8 0 3 97 101 (34) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: a=rtpmap:3 GSM/8000 (19) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: a=rtpmap:97 iLBC/8000 (21) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Apr 3 03:30:40] VERBOSE[19667] logger.c: --- (13 headers 13 lines) --- [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Setting NAT on RTP to Off [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Setting NAT on VRTP to Off [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Setting NAT on UDPTL to Off [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Allocating new SIP dialog for 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 - INVITE (With RTP) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: **** Received INVITE (5) - Command in SIP INVITE [Apr 3 03:30:40] VERBOSE[19667] logger.c: Sending to 111.111.111.111 : 5060 (NAT) [Apr 3 03:30:40] VERBOSE[19667] logger.c: Using INVITE request as basis request - 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found peer 'home' [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Setting NAT on RTP to Off [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Setting NAT on VRTP to Off [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Setting NAT on UDPTL to Off [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found RTP audio format 8 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found RTP audio format 0 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found RTP audio format 3 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found RTP audio format 97 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found RTP audio format 101 [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Peer doesn't provide T.38 UDPTL [Apr 3 03:30:40] VERBOSE[19667] logger.c: Peer audio RTP is at port 111.111.111.111:19622 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found description format PCMA for ID 8 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found description format PCMU for ID 0 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found description format GSM for ID 3 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found description format iLBC for ID 97 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Found description format telephone-event for ID 101 [Apr 3 03:30:40] VERBOSE[19667] logger.c: Got unsupported a:fmtp in SDP offer [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: T38 state changed to 0 on channel [Apr 3 03:30:40] VERBOSE[19667] logger.c: Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x40e (gsm|ulaw|alaw|ilbc)/video=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw) [Apr 3 03:30:40] VERBOSE[19667] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 3 03:30:40] VERBOSE[19667] logger.c: Peer audio RTP is at port 111.111.111.111:19622 [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Checking SIP call limits for device [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Updating call counter for incoming call [Apr 3 03:30:40] VERBOSE[19667] logger.c: Looking for 10123456789 in home (domain asterisk) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: *** Our native formats are 0x2 (gsm) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: This channel will not be able to handle video. [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: build_route: Contact hop: [Apr 3 03:30:40] VERBOSE[19667] logger.c: list_route: hop: [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: SIP/111.111.111.111-099dbbd8: New call is still down.... Trying... [Apr 3 03:30:40] VERBOSE[19667] logger.c: <--- Transmitting (no NAT) to 111.111.111.111:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;received=111.111.111.111;rport=5060 From: "0000000000" ;tag=as1b00c647 To: Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 CSeq: 102 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 3 03:30:40] DEBUG[19667] devicestate.c: Notification of state change to be queued on device/channel SIP/111.111.111.111-099dbbd8 [Apr 3 03:30:40] DEBUG[19660] devicestate.c: No provider found, checking channel drivers for SIP - 111.111.111.111 [Apr 3 03:30:40] DEBUG[19660] chan_sip.c: Checking device state for peer 111.111.111.111 [Apr 3 03:30:40] DEBUG[19660] devicestate.c: Changing state for SIP/111.111.111.111 - state 2 (In use) [Apr 3 03:30:40] DEBUG[19777] pbx.c: Launching 'Dial' [Apr 3 03:30:40] VERBOSE[19777] logger.c: -- Executing [10123456789@home:1] Dial("SIP/111.111.111.111-099dbbd8", "SIP/provider/10123456789") in new stack [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Asked to create a SIP channel with formats: 0x2 (gsm) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Our T38 capability (3856) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Setting NAT on RTP to Off [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Setting NAT on UDPTL to Off [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** Our native formats are 0x100 (g729) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** Our capabilities are 0x100 (g729) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** Our preferred formats from the incoming channel are 0x2 (gsm) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: This channel will not be able to handle video. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable STACK-home-10123456789-1. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable SIPCALLID. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable SIPUSERAGENT. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable SIPDOMAIN. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable SIPURI. [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Outgoing Call for 10123456789 [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Updating call counter for outgoing call [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: ** Our capability: 0x100 (g729) Video flag: False [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: ** Our prefcodec: 0x2 (gsm) [Apr 3 03:30:40] VERBOSE[19777] logger.c: Audio is at 333.333.333.333 port 16108 [Apr 3 03:30:40] VERBOSE[19777] logger.c: Adding codec 0x100 (g729) to SDP [Apr 3 03:30:40] VERBOSE[19777] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: -- Done with adding codecs to SDP [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 0: INVITE sip:10123456789@222.222.222.222 SIP/2.0 (45) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK67d7ba37;rport (64) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 2: From: "0000000000" ;tag=as45d232c1 (64) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 3: To: (36) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 4: Contact: (39) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 5: Call-ID: 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333 (55) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 7: User-Agent: Asterisk (18) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 9: Remote-Party-ID: "0000000000" ;privacy=off;screen=no (82) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 10: Date: Tue, 03 Apr 2007 07:30:40 GMT (35) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 12: Supported: replaces (19) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 14: Content-Length: 265 (19) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 15: (0) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: v=0 (3) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: o=root 19653 19653 IN IP4 333.333.333.333 (39) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: s=session (9) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: c=IN IP4 333.333.333.333 (22) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: t=0 0 (5) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: m=audio 16108 RTP/AVP 18 101 (28) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=fmtp:18 annexb=no (19) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=ptime:20 (10) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=sendrecv (10) [Apr 3 03:30:40] VERBOSE[19777] logger.c: Reliably Transmitting (no NAT) to 222.222.222.222:5060: INVITE sip:10123456789@222.222.222.222 SIP/2.0 Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK67d7ba37;rport From: "0000000000" ;tag=as45d232c1 To: Contact: Call-ID: 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333 CSeq: 102 INVITE User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "0000000000" ;privacy=off;screen=no Date: Tue, 03 Apr 2007 07:30:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 19653 19653 IN IP4 333.333.333.333 s=session c=IN IP4 333.333.333.333 t=0 0 m=audio 16108 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1458 [Apr 3 03:30:40] VERBOSE[19777] logger.c: -- Called provider/10123456789 [Apr 3 03:30:40] DEBUG[19777] channel.c: Set channel SIP/provider-099dd158 to read format slin [Apr 3 03:30:40] DEBUG[19777] channel.c: Set channel SIP/111.111.111.111-099dbbd8 to write format slin [Apr 3 03:30:40] DEBUG[19777] channel.c: Set channel SIP/111.111.111.111-099dbbd8 to read format slin [Apr 3 03:30:40] DEBUG[19777] channel.c: Set channel SIP/provider-099dd158 to write format slin [Apr 3 03:30:40] VERBOSE[19667] logger.c: <--- SIP read from 222.222.222.222:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK67d7ba37;rport=5060;received=333.333.333.333 From: "0000000000" ;tag=as45d232c1 To: Call-ID: 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333 CSeq: 102 INVITE Server: MERA MSIP v.3.0 Content-Length: 0 <-------------> [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK67d7ba37;rport=5060;received=333.333.333.333 (92) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as45d232c1 (64) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 3: To: (36) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333 (55) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 6: Server: MERA MSIP v.3.0 (23) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 7: Content-Length: 0 (17) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 8: (0) [Apr 3 03:30:40] VERBOSE[19667] logger.c: --- (8 headers 0 lines) --- [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: *** SIP TIMER: Cancelling retransmission #1458 - INVITE (got response) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '19278ed9748b9a8d39b874182b4f9aec@333.333.333.333' Request 102: Found [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: SIP response 100 to standard invite [Apr 3 03:30:40] VERBOSE[19667] logger.c: <--- SIP read from 222.222.222.222:5060 ---> SIP/2.0 302 Moved Temporarily Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK67d7ba37;rport=5060;received=333.333.333.333 From: "0000000000" ;tag=as45d232c1 To: ;tag=1047070-269615776-352321664-658962373 Call-ID: 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333 CSeq: 102 INVITE Contact: Server: MERA MSIP v.3.0 Content-Length: 0 <-------------> [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 0: SIP/2.0 302 Moved Temporarily (29) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK67d7ba37;rport=5060;received=333.333.333.333 (92) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as45d232c1 (64) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 3: To: ;tag=1047070-269615776-352321664-658962373 (78) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333 (55) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 6: Contact: (46) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 7: Server: MERA MSIP v.3.0 (23) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 8: Content-Length: 0 (17) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 9: (0) [Apr 3 03:30:40] VERBOSE[19667] logger.c: --- (9 headers 0 lines) --- [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Acked pending invite 102 [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Stopping retransmission on '19278ed9748b9a8d39b874182b4f9aec@333.333.333.333' of Request 102: Match Not Found [Apr 3 03:30:40] VERBOSE[19667] logger.c: -- Got SIP response 302 "Moved Temporarily" back from 222.222.222.222 [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Found promiscuous redirection to 'SIP/10123456789@222.222.222.222:5061' [Apr 3 03:30:40] VERBOSE[19667] logger.c: Transmitting (no NAT) to 222.222.222.222:5060: ACK sip:10123456789@222.222.222.222 SIP/2.0 Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK67d7ba37;rport From: "0000000000" ;tag=as45d232c1 To: ;tag=1047070-269615776-352321664-658962373 Contact: Call-ID: 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333 CSeq: 102 ACK User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "0000000000" ;privacy=off;screen=no Content-Length: 0 --- [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Setting SIP_ALREADYGONE on dialog 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333 [Apr 3 03:30:40] VERBOSE[19777] logger.c: -- Now forwarding SIP/111.111.111.111-099dbbd8 to 'SIP/10123456789@222.222.222.222:5061' (thanks to SIP/provider-099dd158) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Asked to create a SIP channel with formats: 0x2 (gsm) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** Our native formats are 0x100 (g729) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** Joint capabilities are 0x0 (nothing) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** Our capabilities are 0x100 (g729) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** Our preferred formats from the incoming channel are 0x2 (gsm) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: This channel will not be able to handle video. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable STACK-home-10123456789-1. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable SIPCALLID. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable SIPUSERAGENT. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable SIPDOMAIN. [Apr 3 03:30:40] DEBUG[19777] channel.c: Not copying variable SIPURI. [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Outgoing Call for 10123456789 [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Updating call counter for outgoing call [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Our T38 capability (3856), joint T38 capability (3856) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: ** Our capability: 0x100 (g729) Video flag: False [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: ** Our prefcodec: 0x2 (gsm) [Apr 3 03:30:40] VERBOSE[19777] logger.c: Audio is at 333.333.333.333 port 15934 [Apr 3 03:30:40] VERBOSE[19777] logger.c: Adding codec 0x100 (g729) to SDP [Apr 3 03:30:40] VERBOSE[19777] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: -- Done with adding codecs to SDP [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Done building SDP. Settling with this capability: 0x100 (g729) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 0: INVITE sip:10123456789@222.222.222.222:5061 SIP/2.0 (50) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport (64) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 2: From: "0000000000" ;tag=as1539d35f (64) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 3: To: (41) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 4: Contact: (39) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 5: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 (55) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 6: CSeq: 102 INVITE (16) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 7: User-Agent: Asterisk (18) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 9: Remote-Party-ID: "0000000000" ;privacy=off;screen=no (82) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 10: Date: Tue, 03 Apr 2007 07:30:40 GMT (35) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 12: Supported: replaces (19) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 13: Content-Type: application/sdp (29) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 14: Content-Length: 265 (19) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Header 15: (0) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: v=0 (3) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: o=root 19653 19653 IN IP4 333.333.333.333 (39) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: s=session (9) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: c=IN IP4 333.333.333.333 (22) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: t=0 0 (5) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: m=audio 15934 RTP/AVP 18 101 (28) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=fmtp:18 annexb=no (19) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=fmtp:101 0-16 (15) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=silenceSupp:off - - - - (25) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=ptime:20 (10) [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Line: a=sendrecv (10) [Apr 3 03:30:40] VERBOSE[19777] logger.c: Reliably Transmitting (no NAT) to 222.222.222.222:5061: INVITE sip:10123456789@222.222.222.222:5061 SIP/2.0 Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport From: "0000000000" ;tag=as1539d35f To: Contact: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 INVITE User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "0000000000" ;privacy=off;screen=no Date: Tue, 03 Apr 2007 07:30:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 265 v=0 o=root 19653 19653 IN IP4 333.333.333.333 s=session c=IN IP4 333.333.333.333 t=0 0 m=audio 15934 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1462 [Apr 3 03:30:40] DEBUG[19777] channel.c: Hanging up channel 'SIP/provider-099dd158' [Apr 3 03:30:40] DEBUG[19777] chan_sip.c: Hangup call SIP/provider-099dd158, SIP callid 19278ed9748b9a8d39b874182b4f9aec@333.333.333.333) [Apr 3 03:30:40] DEBUG[19777] devicestate.c: Notification of state change to be queued on device/channel SIP/provider-099dd158 [Apr 3 03:30:40] DEBUG[19660] devicestate.c: No provider found, checking channel drivers for SIP - provider [Apr 3 03:30:40] DEBUG[19660] chan_sip.c: Checking device state for peer provider [Apr 3 03:30:40] DEBUG[19660] devicestate.c: Changing state for SIP/provider - state 1 (Not in use) [Apr 3 03:30:40] VERBOSE[19667] logger.c: <--- SIP read from 222.222.222.222:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 From: "0000000000" ;tag=as1539d35f To: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 INVITE Server: MERA MSIP v.3.0 Content-Length: 0 <-------------> [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 0: SIP/2.0 100 Trying (18) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 (92) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1539d35f (64) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 3: To: (41) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 (55) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 6: Server: MERA MSIP v.3.0 (23) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 7: Content-Length: 0 (17) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: Header 8: (0) [Apr 3 03:30:40] VERBOSE[19667] logger.c: --- (8 headers 0 lines) --- [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: *** SIP TIMER: Cancelling retransmission #1462 - INVITE (got response) [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' Request 102: Found [Apr 3 03:30:40] DEBUG[19667] chan_sip.c: SIP response 100 to standard invite [Apr 3 03:30:40] VERBOSE[19667] logger.c: Really destroying SIP dialog '19278ed9748b9a8d39b874182b4f9aec@333.333.333.333' Method: INVITE [Apr 3 03:30:41] VERBOSE[19667] logger.c: <--- SIP read from 222.222.222.222:5061 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 From: "0000000000" ;tag=as1539d35f To: ;tag=1764220-269615776-352321664-658962373 Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 INVITE Contact: Server: MERA MSIP v.3.0 Content-Length: 0 <-------------> [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 0: SIP/2.0 180 Ringing (19) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 (92) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1539d35f (64) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 3: To: ;tag=1764220-269615776-352321664-658962373 (83) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 (55) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 6: Contact: (46) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 7: Server: MERA MSIP v.3.0 (23) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 8: Content-Length: 0 (17) [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: Header 9: (0) [Apr 3 03:30:41] VERBOSE[19667] logger.c: --- (9 headers 0 lines) --- [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' Request 102: Found [Apr 3 03:30:41] DEBUG[19667] chan_sip.c: SIP response 180 to standard invite [Apr 3 03:30:41] DEBUG[19667] devicestate.c: Notification of state change to be queued on device/channel SIP/222.222.222.222:5061-09a1f5b8 [Apr 3 03:30:42] DEBUG[19660] devicestate.c: No provider found, checking channel drivers for SIP - 222.222.222.222:5061 [Apr 3 03:30:42] DEBUG[19660] chan_sip.c: Checking device state for peer 222.222.222.222:5061 [Apr 3 03:30:42] DEBUG[19660] devicestate.c: Changing state for SIP/222.222.222.222:5061 - state 4 (Invalid) [Apr 3 03:30:42] VERBOSE[19777] logger.c: -- SIP/222.222.222.222:5061-09a1f5b8 is ringing [Apr 3 03:30:42] VERBOSE[19777] logger.c: <--- Transmitting (no NAT) to 111.111.111.111:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;received=111.111.111.111;rport=5060 From: "0000000000" ;tag=as1b00c647 To: ;tag=as7d8358e8 Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 CSeq: 102 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 3 03:30:42] DEBUG[19777] channel.c: Driver for channel 'SIP/111.111.111.111-099dbbd8' does not support indication 3, emulating it [Apr 3 03:30:42] DEBUG[19777] channel.c: Prodding channel 'SIP/111.111.111.111-099dbbd8' [Apr 3 03:30:42] DEBUG[19777] chan_sip.c: Setting framing from config on incoming call [Apr 3 03:30:42] DEBUG[19777] chan_sip.c: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True [Apr 3 03:30:42] DEBUG[19777] chan_sip.c: ** Our prefcodec: 0x0 (nothing) [Apr 3 03:30:42] VERBOSE[19777] logger.c: Audio is at 333.333.333.333 port 12948 [Apr 3 03:30:42] VERBOSE[19777] logger.c: Adding codec 0x2 (gsm) to SDP [Apr 3 03:30:42] VERBOSE[19777] logger.c: Adding codec 0x4 (ulaw) to SDP [Apr 3 03:30:42] VERBOSE[19777] logger.c: Adding codec 0x8 (alaw) to SDP [Apr 3 03:30:42] VERBOSE[19777] logger.c: Adding non-codec 0x1 (telephone-event) to SDP [Apr 3 03:30:42] DEBUG[19777] chan_sip.c: -- Done with adding codecs to SDP [Apr 3 03:30:42] DEBUG[19777] chan_sip.c: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Apr 3 03:30:42] VERBOSE[19777] logger.c: <--- Transmitting (no NAT) to 111.111.111.111:5060 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;received=111.111.111.111;rport=5060 From: "0000000000" ;tag=as1b00c647 To: ;tag=as7d8358e8 Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 CSeq: 102 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 289 v=0 o=root 19653 19653 IN IP4 333.333.333.333 s=session c=IN IP4 333.333.333.333 t=0 0 m=audio 12948 RTP/AVP 3 0 8 101 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 3 03:30:42] DEBUG[19777] channel.c: Scheduling timer at 160 sample intervals [Apr 3 03:30:42] DEBUG[19777] rtp.c: Ooh, format changed from unknown to gsm [Apr 3 03:30:42] DEBUG[19777] rtp.c: Created smoother: format: 2 ms: 20 len: 33 [Apr 3 03:30:42] VERBOSE[19667] logger.c: <--- SIP read from 222.222.222.222:5061 ---> SIP/2.0 183 Progress Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 From: "0000000000" ;tag=as1539d35f To: ;tag=1764220-269615776-352321664-658962373 Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 INVITE Contact: Server: MERA MSIP v.3.0 Content-Type: application/sdp Content-Length: 217 v=0 o=- 1175585442 1175585442 IN IP4 222.222.222.222 s=- c=IN IP4 222.222.222.222 t=0 0 m=audio 38464 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 0: SIP/2.0 183 Progress (20) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 (92) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1539d35f (64) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 3: To: ;tag=1764220-269615776-352321664-658962373 (83) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 (55) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 6: Contact: (46) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 7: Server: MERA MSIP v.3.0 (23) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 8: Content-Type: application/sdp (29) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 9: Content-Length: 217 (21) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 10: (0) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: v=0 (3) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: o=- 1175585442 1175585442 IN IP4 222.222.222.222 (47) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: s=- (3) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: c=IN IP4 222.222.222.222 (23) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: t=0 0 (5) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: m=audio 38464 RTP/AVP 18 101 (28) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: a=fmtp:18 annexb=no (19) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: a=fmtp:101 0-15 (15) [Apr 3 03:30:42] VERBOSE[19667] logger.c: --- (10 headers 10 lines) --- [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' Request 102: Found [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: SIP response 183 to standard invite [Apr 3 03:30:42] VERBOSE[19667] logger.c: Found RTP audio format 18 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Found RTP audio format 101 [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Peer doesn't provide T.38 UDPTL [Apr 3 03:30:42] VERBOSE[19667] logger.c: Peer audio RTP is at port 222.222.222.222:38464 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Found description format G729 for ID 18 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Got unsupported a:fmtp in SDP offer [Apr 3 03:30:42] VERBOSE[19667] logger.c: Found description format telephone-event for ID 101 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Got unsupported a:fmtp in SDP offer [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: T38 state changed to 0 on channel SIP/222.222.222.222:5061-09a1f5b8 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Capabilities: us - 0x100 (g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Apr 3 03:30:42] VERBOSE[19667] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 3 03:30:42] VERBOSE[19667] logger.c: Peer audio RTP is at port 222.222.222.222:38464 [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: We're settling with these formats: 0x100 (g729) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: We have an owner, now see if we need to change this call [Apr 3 03:30:42] VERBOSE[19777] logger.c: -- Call on SIP/222.222.222.222:5061-09a1f5b8 left from hold [Apr 3 03:30:42] DEBUG[19777] channel.c: Scheduling timer at 0 sample intervals [Apr 3 03:30:42] VERBOSE[19777] logger.c: -- SIP/222.222.222.222:5061-09a1f5b8 is making progress passing it to SIP/111.111.111.111-099dbbd8 [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] DEBUG[19777] rtp.c: Got RTCP report of 48 bytes [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] VERBOSE[19667] logger.c: <--- SIP read from 222.222.222.222:5061 ---> SIP/2.0 183 Progress Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 From: "0000000000" ;tag=as1539d35f To: ;tag=1764220-269615776-352321664-658962373 Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 INVITE Contact: Server: MERA MSIP v.3.0 Content-Type: application/sdp Content-Length: 217 v=0 o=- 1175585442 1175585442 IN IP4 222.222.222.222 s=- c=IN IP4 222.222.222.222 t=0 0 m=audio 38464 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 0: SIP/2.0 183 Progress (20) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 (92) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1539d35f (64) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 3: To: ;tag=1764220-269615776-352321664-658962373 (83) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 (55) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 6: Contact: (46) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 7: Server: MERA MSIP v.3.0 (23) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 8: Content-Type: application/sdp (29) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 9: Content-Length: 217 (21) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Header 10: (0) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: v=0 (3) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: o=- 1175585442 1175585442 IN IP4 222.222.222.222 (47) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: s=- (3) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: c=IN IP4 222.222.222.222 (23) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: t=0 0 (5) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: m=audio 38464 RTP/AVP 18 101 (28) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: a=rtpmap:18 G729/8000 (21) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: a=fmtp:18 annexb=no (19) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Line: a=fmtp:101 0-15 (15) [Apr 3 03:30:42] VERBOSE[19667] logger.c: --- (10 headers 10 lines) --- [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: (Provisional) Stopping retransmission (but retaining packet) on '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' Request 102: Found [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: SIP response 183 to standard invite [Apr 3 03:30:42] VERBOSE[19667] logger.c: Found RTP audio format 18 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Found RTP audio format 101 [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: Peer doesn't provide T.38 UDPTL [Apr 3 03:30:42] VERBOSE[19667] logger.c: Peer audio RTP is at port 222.222.222.222:38464 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Found description format G729 for ID 18 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Got unsupported a:fmtp in SDP offer [Apr 3 03:30:42] VERBOSE[19667] logger.c: Found description format telephone-event for ID 101 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Got unsupported a:fmtp in SDP offer [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: T38 state changed to 0 on channel SIP/222.222.222.222:5061-09a1f5b8 [Apr 3 03:30:42] VERBOSE[19667] logger.c: Capabilities: us - 0x100 (g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Apr 3 03:30:42] VERBOSE[19667] logger.c: Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 3 03:30:42] VERBOSE[19667] logger.c: Peer audio RTP is at port 222.222.222.222:38464 [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: We're settling with these formats: 0x100 (g729) [Apr 3 03:30:42] DEBUG[19667] chan_sip.c: We have an owner, now see if we need to change this call [Apr 3 03:30:42] VERBOSE[19777] logger.c: -- Call on SIP/222.222.222.222:5061-09a1f5b8 left from hold [Apr 3 03:30:42] VERBOSE[19777] logger.c: -- SIP/222.222.222.222:5061-09a1f5b8 is making progress passing it to SIP/111.111.111.111-099dbbd8 [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:42] WARNING[19777] chan_sip.c: Asked to transmit frame type 64, while native formats is 0x100 (g729)(256) read/write = 0x100 (g729)(256)/0x100 (g729)(256) [Apr 3 03:30:43] VERBOSE[19667] logger.c: <--- SIP read from 111.111.111.111:5060 ---> CANCEL sip:10123456789@asterisk SIP/2.0 Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;rport From: "0000000000" ;tag=as1b00c647 To: Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 0: CANCEL sip:10123456789@asterisk SIP/2.0 (51) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;rport (63) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1b00c647 (63) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 3: To: (42) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 (54) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 CANCEL (16) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 6: User-Agent: Asterisk PBX (24) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 7: Max-Forwards: 70 (16) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 8: Content-Length: 0 (17) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 9: (0) [Apr 3 03:30:43] VERBOSE[19667] logger.c: --- (9 headers 0 lines) --- [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: **** Received CANCEL (14) - Command in SIP CANCEL [Apr 3 03:30:43] VERBOSE[19667] logger.c: Sending to 111.111.111.111 : 5060 (NAT) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Setting SIP_ALREADYGONE on dialog 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 [Apr 3 03:30:43] VERBOSE[19667] logger.c: <--- Reliably Transmitting (NAT) to 111.111.111.111:5060 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;received=111.111.111.111;rport=5060 From: "0000000000" ;tag=as1b00c647 To: ;tag=as7d8358e8 Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 CSeq: 102 INVITE User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1470 [Apr 3 03:30:43] VERBOSE[19667] logger.c: <--- Transmitting (NAT) to 111.111.111.111:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;received=111.111.111.111;rport=5060 From: "0000000000" ;tag=as1b00c647 To: ;tag=as7d8358e8 Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 CSeq: 102 CANCEL User-Agent: Asterisk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 3 03:30:43] DEBUG[19777] rtp.c: Channel '' has no RTP, not doing anything [Apr 3 03:30:43] DEBUG[19777] channel.c: Hanging up channel 'SIP/222.222.222.222:5061-09a1f5b8' [Apr 3 03:30:43] DEBUG[19777] chan_sip.c: Hangup call SIP/222.222.222.222:5061-09a1f5b8, SIP callid 4af49d6a55e403de24214fd02a0b3927@333.333.333.333) [Apr 3 03:30:43] DEBUG[19777] chan_sip.c: Hanging up channel in state Ringing (not UP) [Apr 3 03:30:43] VERBOSE[19777] logger.c: Scheduling destruction of SIP dialog '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' in 32000 ms (Method: INVITE) [Apr 3 03:30:43] DEBUG[19777] chan_sip.c: Acked pending invite 102 [Apr 3 03:30:43] DEBUG[19777] chan_sip.c: Stopping retransmission on '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' of Request 102: Match Not Found [Apr 3 03:30:43] VERBOSE[19777] logger.c: Reliably Transmitting (no NAT) to 222.222.222.222:5061: CANCEL sip:10123456789@222.222.222.222:5061 SIP/2.0 Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport From: "0000000000" ;tag=as1539d35f To: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 CANCEL User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "0000000000" ;privacy=off;screen=no Content-Length: 0 --- [Apr 3 03:30:43] DEBUG[19777] chan_sip.c: *** SIP TIMER: Initalizing retransmit timer on packet: Id #1472 [Apr 3 03:30:43] VERBOSE[19777] logger.c: Scheduling destruction of SIP dialog '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' in 32000 ms (Method: INVITE) [Apr 3 03:30:43] DEBUG[19777] devicestate.c: Notification of state change to be queued on device/channel SIP/222.222.222.222:5061-09a1f5b8 [Apr 3 03:30:43] DEBUG[19777] app_dial.c: Exiting with DIALSTATUS=CANCEL. [Apr 3 03:30:43] DEBUG[19777] pbx.c: Spawn extension (home,10123456789,1) exited non-zero on 'SIP/111.111.111.111-099dbbd8' [Apr 3 03:30:43] VERBOSE[19777] logger.c: == Spawn extension (home, 10123456789, 1) exited non-zero on 'SIP/111.111.111.111-099dbbd8' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '"0000000000" <0000000000>' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '0000000000' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '10123456789' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is 'home' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is 'SIP/111.111.111.111-099dbbd8' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is 'SIP/provider-099dd158' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is 'Dial' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is 'SIP/provider/10123456789' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '2007-04-03 03:30:40' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '2007-04-03 03:30:43' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '3' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '0' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is 'NO ANSWER' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is 'DOCUMENTATION' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is 'home' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '1175585440.3' [Apr 3 03:30:43] DEBUG[19777] pbx.c: Function result is '' [Apr 3 03:30:43] DEBUG[19660] devicestate.c: No provider found, checking channel drivers for SIP - 222.222.222.222:5061 [Apr 3 03:30:43] DEBUG[19660] chan_sip.c: Checking device state for peer 222.222.222.222:5061 [Apr 3 03:30:43] DEBUG[19777] channel.c: Hanging up channel 'SIP/111.111.111.111-099dbbd8' [Apr 3 03:30:43] DEBUG[19777] chan_sip.c: Hangup call SIP/111.111.111.111-099dbbd8, SIP callid 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111) [Apr 3 03:30:43] DEBUG[19777] chan_sip.c: Hanging up channel in state Ring (not UP) [Apr 3 03:30:43] DEBUG[19777] devicestate.c: Notification of state change to be queued on device/channel SIP/111.111.111.111-099dbbd8 [Apr 3 03:30:43] DEBUG[19660] devicestate.c: Changing state for SIP/222.222.222.222:5061 - state 4 (Invalid) [Apr 3 03:30:43] DEBUG[19660] devicestate.c: No provider found, checking channel drivers for SIP - 111.111.111.111 [Apr 3 03:30:43] DEBUG[19660] chan_sip.c: Checking device state for peer 111.111.111.111 [Apr 3 03:30:43] DEBUG[19660] devicestate.c: Changing state for SIP/111.111.111.111 - state 1 (Not in use) [Apr 3 03:30:43] VERBOSE[19667] logger.c: <--- SIP read from 111.111.111.111:5060 ---> ACK sip:10123456789@asterisk SIP/2.0 Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;rport From: "0000000000" ;tag=as1b00c647 To: ;tag=as7d8358e8 Contact: Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 <-------------> [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 0: ACK sip:10123456789@asterisk SIP/2.0 (48) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 111.111.111.111:5060;branch=z9hG4bK0c3dab05;rport (63) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1b00c647 (63) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 3: To: ;tag=as7d8358e8 (57) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 4: Contact: (38) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 5: Call-ID: 3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111 (54) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 6: CSeq: 102 ACK (13) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 7: User-Agent: Asterisk PBX (24) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 8: Max-Forwards: 70 (16) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 9: Content-Length: 0 (17) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 10: (0) [Apr 3 03:30:43] VERBOSE[19667] logger.c: --- (10 headers 0 lines) --- [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: **** Received ACK (6) - Command in SIP ACK [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1470 [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Stopping retransmission on '3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111' of Response 102: Match Not Found [Apr 3 03:30:43] VERBOSE[19667] logger.c: Really destroying SIP dialog '3c841e4b6c9c5bb0310dca210fbdccb7@111.111.111.111' Method: ACK [Apr 3 03:30:43] VERBOSE[19667] logger.c: <--- SIP read from 222.222.222.222:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 From: "0000000000" ;tag=as1539d35f To: ;tag=6532660-269615779-352321664-658962373 Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 CANCEL Contact: Server: MERA MSIP v.3.0 Content-Length: 0 <-------------> [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 0: SIP/2.0 200 OK (14) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 (92) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1539d35f (64) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 3: To: ;tag=6532660-269615779-352321664-658962373 (83) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 (55) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 CANCEL (16) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 6: Contact: (46) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 7: Server: MERA MSIP v.3.0 (23) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 8: Content-Length: 0 (17) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 9: (0) [Apr 3 03:30:43] VERBOSE[19667] logger.c: --- (9 headers 0 lines) --- [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #1472 [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Stopping retransmission on '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' of Request 102: Match Not Found [Apr 3 03:30:43] VERBOSE[19667] logger.c: <--- SIP read from 222.222.222.222:5061 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 From: "0000000000" ;tag=as1539d35f To: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 INVITE Server: MERA MSIP v.3.0 Content-Length: 0 <-------------> [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 0: SIP/2.0 487 Request Terminated (30) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 1: Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport=5060;received=333.333.333.333 (92) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 2: From: "0000000000" ;tag=as1539d35f (64) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 3: To: (41) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 4: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 (55) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 5: CSeq: 102 INVITE (16) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 6: Server: MERA MSIP v.3.0 (23) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 7: Content-Length: 0 (17) [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Header 8: (0) [Apr 3 03:30:43] VERBOSE[19667] logger.c: --- (8 headers 0 lines) --- [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Stopping retransmission on '4af49d6a55e403de24214fd02a0b3927@333.333.333.333' of Request 102: Match Found [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: SIP response 487 to standard invite [Apr 3 03:30:43] VERBOSE[19667] logger.c: Transmitting (no NAT) to 222.222.222.222:5061: ACK sip:10123456789@222.222.222.222:5061 SIP/2.0 Via: SIP/2.0/UDP 333.333.333.333:5060;branch=z9hG4bK6880bdfb;rport From: "0000000000" ;tag=as1539d35f To: Contact: Call-ID: 4af49d6a55e403de24214fd02a0b3927@333.333.333.333 CSeq: 102 ACK User-Agent: Asterisk Max-Forwards: 70 Remote-Party-ID: "0000000000" ;privacy=off;screen=no Content-Length: 0 --- [Apr 3 03:30:43] DEBUG[19667] chan_sip.c: Updating call counter for outgoing call