XXXXXXXXXX => calling phone number YYYYYYYYYY => receiving phone number The Asterisk->target part has been omitted from this log, as it doesn't use SIP and thus is irrelevant and would reveal unrelated details about the dialplan. With my patches applied. [...Asterisk called through registered peer at 212.25.52.5:5061...] <--- SIP read from 212.27.52.5:5061 ---> INVITE sip:s@88.191.14.223:5060;transport=udp SIP/2.0 Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net Contact: Content-Type: application/sdp CSeq: 1122841 INVITE From: ;tag=29846-SL-00112919-76b42f7b6 Max-Forwards: 26 Record-Route: To: Via: SIP/2.0/UDP 212.27.52.5:5061;branch=z9hG4bK-R0-000003df-1ad87e5a,SIP/2.0/UDP 172.17.20.241:5063;emission,SIP/2.0/UDP 212.27.52.5:5060;branch=z9hG4bK-2A77-CDB4 Allow: UPDATE,REFER User-Agent: Cirpack/v4.40 (gw_sip) Content-Length: 172 v=0 o=cp10 116542254048 116542254049 IN IP4 172.25.20.58 s=SIP Call c=IN IP4 212.27.52.129 t=0 0 m=audio 37964 RTP/AVP 8 b=AS:64 a=rtpmap:8 PCMA/8000/1 a=ptime:30 <-------------> [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 0 [ 53]: INVITE sip:s@88.191.14.223:5060;transport=udp SIP/2.0 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 1 [ 51]: Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 2 [ 31]: Contact: [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 3 [ 29]: Content-Type: application/sdp [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 4 [ 20]: CSeq: 1122841 INVITE [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 5 [ 80]: From: ;tag=29846-SL-00112919-76b42f7b6 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 6 [ 16]: Max-Forwards: 26 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 7 [ 48]: Record-Route: [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 8 [ 43]: To: [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 9 [163]: Via: SIP/2.0/UDP 212.27.52.5:5061;branch=z9hG4bK-R0-000003df-1ad87e5a,SIP/2.0/UDP 172.17.20.241:5063;emission,SIP/2.0/UDP 212.27.52.5:5060;branch=z9hG4bK-2A77-CDB4 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 10 [ 19]: Allow: UPDATE,REFER [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 11 [ 34]: User-Agent: Cirpack/v4.40 (gw_sip) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 12 [ 19]: Content-Length: 172 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 13 [ 0]: [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 0 [ 3]: v=0 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 1 [ 52]: o=cp10 116542254048 116542254049 IN IP4 172.25.20.58 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 2 [ 10]: s=SIP Call [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 3 [ 22]: c=IN IP4 212.27.52.129 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 4 [ 5]: t=0 0 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 5 [ 23]: m=audio 37964 RTP/AVP 8 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 6 [ 7]: b=AS:64 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 7 [ 22]: a=rtpmap:8 PCMA/8000/1 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4651 parse_request: Body 8 [ 10]: a=ptime:30 --- (13 headers 9 lines) --- [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:2677 do_setnat: Setting NAT on RTP to Off [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:4373 sip_alloc: Allocating new SIP dialog for 29846-DX-00112918-0b0c97f95@freephonie.net - INVITE (With RTP) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:14655 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 212.27.52.5 : 5061 (no NAT) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:13366 handle_request_invite: Initializing initreq for method INVITE - callid 29846-DX-00112918-0b0c97f95@freephonie.net Using INVITE request as basis request - 29846-DX-00112918-0b0c97f95@freephonie.net No user 'XXXXXXXXXX' in SIP users list Found peer 'freephonie.net' for 'XXXXXXXXXX' from 212.27.52.5:5061 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:2677 do_setnat: Setting NAT on RTP to Off Found RTP audio format 8 Peer audio RTP is at port 212.27.52.129:37964 Found description format PCMA for ID 8 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:5168 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x50f (g723|gsm|ulaw|alaw|g729|ilbc), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) Peer audio RTP is at port 212.27.52.129:37964 [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:5245 process_sdp: We're settling with these formats: 0x8 (alaw) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:13443 handle_request_invite: Checking SIP call limits for device YYYYYYYYYY [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:3100 update_call_counter: Updating call counter for incoming call Looking for s in fromfree (domain 88.191.14.223) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:3879 sip_new: *** Our native formats are 0x8 (alaw) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:3880 sip_new: *** Joint capabilities are 0x8 (alaw) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:3881 sip_new: *** Our capabilities are 0x50f (g723|gsm|ulaw|alaw|g729|ilbc) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:3882 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:3905 sip_new: This channel will not be able to handle video. [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:7944 build_route: build_route: Record-Route hop: list_route: hop: [Dec 6 17:29:00] DEBUG[13347]: chan_sip.c:13516 handle_request_invite: SIP/YYYYYYYYYY-081dd370: New call is still down.... Trying... <--- Transmitting (no NAT) to 212.27.52.5:5061 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 212.27.52.5:5061;branch=z9hG4bK-R0-000003df-1ad87e5a;received=212.27.52.5,SIP/2.0/UDP 172.17.20.241:5063;emission,SIP/2.0/UDP 212.27.52.5:5060;branch=z9hG4bK-2A77-CDB4 From: ;tag=29846-SL-00112919-76b42f7b6 To: Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net CSeq: 1122841 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 [...target phone contacted and ringing] <--- Transmitting (no NAT) to 212.27.52.5:5061 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 212.27.52.5:5061;branch=z9hG4bK-R0-000003df-1ad87e5a;received=212.27.52.5,SIP/2.0/UDP 172.17.20.241:5063;emission,SIP/2.0/UDP 212.27.52.5:5060;branch=z9hG4bK-2A77-CDB4 From: ;tag=29846-SL-00112919-76b42f7b6 To: ;tag=as23180f02 Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net CSeq: 1122841 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Dec 6 17:29:00] DEBUG[18659]: app_queue.c:568 changethread: Device 'SIP/YYYYYYYYYY' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [...target phone ringing...] <--- Transmitting (no NAT) to 212.27.52.5:5061 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 212.27.52.5:5061;branch=z9hG4bK-R0-000003df-1ad87e5a;received=212.27.52.5,SIP/2.0/UDP 172.17.20.241:5063;emission,SIP/2.0/UDP 212.27.52.5:5060;branch=z9hG4bK-2A77-CDB4 From: ;tag=29846-SL-00112919-76b42f7b6 To: ;tag=as23180f02 Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net CSeq: 1122841 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 [...hangup from caller...] <--- SIP read from 212.27.52.5:5061 ---> CANCEL sip:s@88.191.14.223:5060;transport=udp SIP/2.0 Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net CSeq: 1122841 CANCEL From: ;tag=29846-SL-00112919-76b42f7b6 Max-Forwards: 26 To: Via: SIP/2.0/UDP 212.27.52.5:5061;received=212.27.52.5;branch=z9hG4bK-R0-000003df-1ad87e5a Content-Length: 0 <-------------> [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 0 [ 53]: CANCEL sip:s@88.191.14.223:5060;transport=udp SIP/2.0 [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 1 [ 51]: Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 2 [ 20]: CSeq: 1122841 CANCEL [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 3 [ 80]: From: ;tag=29846-SL-00112919-76b42f7b6 [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 4 [ 16]: Max-Forwards: 26 [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 5 [ 43]: To: [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 6 [ 90]: Via: SIP/2.0/UDP 212.27.52.5:5061;received=212.27.52.5;branch=z9hG4bK-R0-000003df-1ad87e5a [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 7 [ 17]: Content-Length: 0 [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:4651 parse_request: Header 8 [ 0]: --- (8 headers 0 lines) --- [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:14655 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL Sending to 212.27.52.5 : 5061 (no NAT) [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:1666 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 29846-DX-00112918-0b0c97f95@freephonie.net <--- Reliably Transmitting (no NAT) to 212.27.52.5:5061 ---> SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 212.27.52.5:5061;branch=z9hG4bK-R0-000003df-1ad87e5a;received=212.27.52.5,SIP/2.0/UDP 172.17.20.241:5063;emission,SIP/2.0/UDP 212.27.52.5:5060;branch=z9hG4bK-2A77-CDB4 From: ;tag=29846-SL-00112919-76b42f7b6 To: ;tag=as23180f02 Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net CSeq: 1122841 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> [Dec 6 17:29:07] DEBUG[13347]: chan_sip.c:2003 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #23 <--- Transmitting (no NAT) to 212.27.52.5:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 212.27.52.5:5061;received=212.27.52.5;branch=z9hG4bK-R0-000003df-1ad87e5a;received=212.27.52.5 From: ;tag=29846-SL-00112919-76b42f7b6 To: ;tag=as23180f02 Call-ID: 29846-DX-00112918-0b0c97f95@freephonie.net CSeq: 1122841 CANCEL User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0