pbx*CLI> <--- SIP read from 192.168.255.2:5060 ---> INVITE sip:210@192.168.255.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK4ac88b71;rport From: "0720440931013" ;tag=as4ba36eb0 To: Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave VoIP Gateway by Christoph Stadlmann Max-Forwards: 70 Date: Mon, 23 Jul 2007 13:18:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 242 v=0 o=root 15772 15772 IN IP4 192.168.255.2 s=session c=IN IP4 192.168.255.2 t=0 0 m=audio 16964 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <-------------> [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: INVITE sip:210@192.168.255.1 SIP/2.0 (36) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK4ac88b71;rport (64) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "0720440931013" ;tag=as4ba36eb0 (70) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: (27) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Contact: (42) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (55) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: CSeq: 102 INVITE (16) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: User-Agent: mywave VoIP Gateway by Christoph Stadlmann (54) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Date: Mon, 23 Jul 2007 13:18:30 GMT (35) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Supported: replaces (19) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Content-Type: application/sdp (29) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Content-Length: 242 (19) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: (0) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: v=0 (3) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: o=root 15772 15772 IN IP4 192.168.255.2 (39) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: s=session (9) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: c=IN IP4 192.168.255.2 (22) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: t=0 0 (5) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: m=audio 16964 RTP/AVP 8 101 (27) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=fmtp:101 0-16 (15) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=silenceSupp:off - - - - (25) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=ptime:20 (10) --- (14 headers 12 lines) --- [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (Checking From) --From tag as4ba36eb0 --To-tag [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009d1f6-xtugam4fa2s1@snom360-000413239674 Their Tag 9srndsbna6 Our tag: as71bebf89 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 5af609d26990fcfd19c6e10e02aab654@192.168.255.2 Their Tag as7daadba7 Our tag: as2cf1ad60 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 7bd83a710e44908e1320fc5945144274@192.168.255.6 Their Tag as0899dcea Our tag: as602c6440 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c26700c2e63-1vdz1isctxgd@snom360-000413239675 Their Tag 30essrokdm Our tag: as3e4adb4e [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c2670076167-0hy88wqhd8nc@192-168-4-104 Their Tag spqh326hwe Our tag: as4b2d092c [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 43c8b5474cf3a6e94fb3f52646bc9c76@192.168.255.1 Their Tag as542d34f9 Our tag: as31b84b54 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 625303904-49107-7@10.98.0.4 Their Tag 1869514991 Our tag: as6289fe4a [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 13c2dd0745a3e1fe2300b7c72c6d4f65@192.168.255.1 Their Tag as49034766 Our tag: as38553910 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 961972835-49107-6@10.98.0.4 Their Tag 1738525494 Our tag: as40938d1d [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009cf85-f70b43qbhben@snom360-000413239673 Their Tag tb0ivqhewt Our tag: as4c19cba5 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009dbba-t14c5hof6dow@snom360-000413239674 Their Tag 0m2e7zoed6 Our tag: as4d87dc91 [Jul 23 15:18:30] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 192.168.255.2 with 192.168.0.0 [Jul 23 15:18:30] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 192.168.255.2 with 10.0.0.0 [Jul 23 15:18:30] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 192.168.255.2 with 172.16.0.0 [Jul 23 15:18:30] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 192.168.255.2 with 169.254.0.0 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for 048b051b6828e8f57f3db2f74744839e@192.168.255.2 - INVITE (With RTP) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:1688 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:1696 parse_sip_options: Found SIP option: -replaces- [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:1702 parse_sip_options: Matched SIP option: replaces Sending to 192.168.255.2 : 5060 (NAT) Using INVITE request as basis request - 048b051b6828e8f57f3db2f74744839e@192.168.255.2 [Jul 23 15:18:30] DEBUG[28619]: res_config_mysql.c:650 mysql_reconnect: MySQL RealTime: Everything is fine. [Jul 23 15:18:30] DEBUG[28619]: res_config_mysql.c:138 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '0720440931013' Found peer 'v203500aa' [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On pbx*CLI> <--- Reliably Transmitting (NAT) to 192.168.255.2:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK4ac88b71;received=192.168.255.2;rport=5060 From: "0720440931013" ;tag=as4ba36eb0 To: ;tag=as08a8ae49 Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="69cc2dec" Content-Length: 0 <------------> [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2017 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32563 Scheduling destruction of SIP dialog '048b051b6828e8f57f3db2f74744839e@192.168.255.2' in 192 ms (Method: INVITE) pbx*CLI> <--- SIP read from 192.168.255.2:5060 ---> ACK sip:210@192.168.255.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK4ac88b71;rport From: "0720440931013" ;tag=as4ba36eb0 To: ;tag=as08a8ae49 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 ACK User-Agent: mywave VoIP Gateway by Christoph Stadlmann Max-Forwards: 70 Content-Length: 0 <-------------> [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: ACK sip:210@192.168.255.1 SIP/2.0 (33) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK4ac88b71;rport (64) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "0720440931013" ;tag=as4ba36eb0 (70) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: ;tag=as08a8ae49 (42) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Contact: (42) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (55) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: CSeq: 102 ACK (13) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: User-Agent: mywave VoIP Gateway by Christoph Stadlmann (54) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Content-Length: 0 (17) --- (10 headers 0 lines) --- [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (Checking From) --From tag as4ba36eb0 --To-tag as08a8ae49 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 Their Tag as4ba36eb0 Our tag: as08a8ae49 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received ACK (6) - Command in SIP ACK [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2128 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #32563 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '048b051b6828e8f57f3db2f74744839e@192.168.255.2' of Response 102: Match Not Found <--- SIP read from 192.168.255.2:5060 ---> INVITE sip:210@192.168.255.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK37e94b8b;rport From: "0720440931013" ;tag=as4ba36eb0 To: Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 103 INVITE User-Agent: mywave VoIP Gateway by Christoph Stadlmann Max-Forwards: 70 Proxy-Authorization: Digest username="v203500aa", realm="asterisk", algorithm=MD5, uri="sip:210@192.168.255.1", nonce="69cc2dec", response="9220fd8f9d1fdb6f18c99f8a87b6dcb5", opaque="" Date: Mon, 23 Jul 2007 13:18:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 242 v=0 o=root 15772 15773 IN IP4 192.168.255.2 s=session c=IN IP4 192.168.255.2 t=0 0 m=audio 16964 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <-------------> [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: INVITE sip:210@192.168.255.1 SIP/2.0 (36) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK37e94b8b;rport (64) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "0720440931013" ;tag=as4ba36eb0 (70) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: (27) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Contact: (42) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (55) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: CSeq: 103 INVITE (16) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: User-Agent: mywave VoIP Gateway by Christoph Stadlmann (54) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Proxy-Authorization: Digest username="v203500aa", realm="asterisk", algorithm=MD5, uri="sip:210@192.168.255.1", nonce="69cc2dec", response="9220fd8f9d1fdb6f18c99f8a87b6dcb5", opaque="" (184) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Date: Mon, 23 Jul 2007 13:18:30 GMT (35) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Supported: replaces (19) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Content-Type: application/sdp (29) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: Content-Length: 242 (19) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 15: (0) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: v=0 (3) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: o=root 15772 15773 IN IP4 192.168.255.2 (39) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: s=session (9) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: c=IN IP4 192.168.255.2 (22) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: t=0 0 (5) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: m=audio 16964 RTP/AVP 8 101 (27) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=fmtp:101 0-16 (15) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=silenceSupp:off - - - - (25) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=ptime:20 (10) --- (15 headers 12 lines) --- [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (Checking From) --From tag as4ba36eb0 --To-tag [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 Their Tag as4ba36eb0 Our tag: as08a8ae49 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.255.2 : 5060 (NAT) Using INVITE request as basis request - 048b051b6828e8f57f3db2f74744839e@192.168.255.2 [Jul 23 15:18:30] DEBUG[28619]: res_config_mysql.c:650 mysql_reconnect: MySQL RealTime: Everything is fine. [Jul 23 15:18:30] DEBUG[28619]: res_config_mysql.c:138 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '0720440931013' Found peer 'v203500aa' [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On Found RTP audio format 8 Found RTP audio format 101 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4993 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.255.2:16964 Found description format PCMA for ID 8 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:5226 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.255.2:16964 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:5306 process_sdp: We're settling with these formats: 0x8 (alaw) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:13540 handle_request_invite: Checking SIP call limits for device v203500aa [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:3058 update_call_counter: Updating call counter for incoming call Looking for 210 in trunk-203500 (domain 192.168.255.1) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:3867 sip_new: *** Our native formats are 0x8 (alaw) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x8 (alaw) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x8 (alaw) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:3893 sip_new: This channel will not be able to handle video. [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:8065 build_route: build_route: Contact hop: list_route: hop: [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:13615 handle_request_invite: SIP/v203500aa-0826bec8: New call is still down.... Trying... <--- Transmitting (NAT) to 192.168.255.2:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK37e94b8b;received=192.168.255.2;rport=5060 From: "0720440931013" ;tag=as4ba36eb0 To: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 103 INVITE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jul 23 15:18:30] DEBUG[28619]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/v203500aa-0826bec8 [Jul 23 15:18:30] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - v203500aa [Jul 23 15:18:30] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer v203500aa [Jul 23 15:18:30] DEBUG[28603]: devicestate.c:287 do_state_change: Changing state for SIP/v203500aa - state 1 (Not in use) [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0720440931013' [Jul 23 15:18:30] DEBUG[31400]: app_queue.c:547 changethread: Device 'SIP/v203500aa' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [210@trunk-203500:1] GotoIf("SIP/v203500aa-0826bec8", "0?ANONYMOUS:NONANONYMOUS") in new stack -- Goto (trunk-203500,210,4) [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '0720440931013' [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [210@trunk-203500:4] Set("SIP/v203500aa-0826bec8", "CALLERID(all)=00720440931013") in new stack [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [210@trunk-203500:5] Set("SIP/v203500aa-0826bec8", "CDR(userfield)=203500") in new stack [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' -- Executing [210@trunk-203500:6] Goto("SIP/v203500aa-0826bec8", "extensions-did-203500|210|1") in new stack -- Goto (extensions-did-203500,210,1) [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Goto' -- Executing [210@extensions-did-203500:1] Goto("SIP/v203500aa-0826bec8", "extensions-local-203500|210|1") in new stack -- Goto (extensions-local-203500,210,1) [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Macro' -- Executing [210@extensions-local-203500:1] Macro("SIP/v203500aa-0826bec8", "dial-exten-vm|203500_210|15|210") in new stack [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '203500' [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial-exten-vm:1] GotoIf("SIP/v203500aa-0826bec8", "0?NOUSERFIELDSET:USERFIELDSET") in new stack -- Goto (macro-dial-exten-vm,s,3) [Jul 23 15:18:30] DEBUG[31399]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1730 pbx_substitute_variables_helper_full: Expression result is '0' [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial-exten-vm:3] GotoIf("SIP/v203500aa-0826bec8", "0?QUEUE:NONQUEUE") in new stack -- Goto (macro-dial-exten-vm,s,7) [Jul 23 15:18:30] DEBUG[31399]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial-exten-vm:7] Set("SIP/v203500aa-0826bec8", "RT=15") in new stack [Jul 23 15:18:30] DEBUG[31399]: app_macro.c:337 _macro_exec: Executed application: Set [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-dial-exten-vm:8] AGI("SIP/v203500aa-0826bec8", "dialinternal.php|203500_210|15") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/dialinternal.php dialinternal.php|203500_210|15: AGI Request: dialinternal.php|203500_210|15: Array dialinternal.php|203500_210|15: ( dialinternal.php|203500_210|15: [agi_request] => dialinternal.php dialinternal.php|203500_210|15: [agi_channel] => SIP/v203500aa-0826bec8 dialinternal.php|203500_210|15: [agi_language] => de dialinternal.php|203500_210|15: [agi_type] => SIP dialinternal.php|203500_210|15: [agi_uniqueid] => 1185196710.67 dialinternal.php|203500_210|15: [agi_callerid] => 00720440931013 dialinternal.php|203500_210|15: [agi_calleridname] => unknown dialinternal.php|203500_210|15: [agi_callingpres] => 0 dialinternal.php|203500_210|15: [agi_callingani2] => 0 dialinternal.php|203500_210|15: [agi_callington] => 0 dialinternal.php|203500_210|15: [agi_callingtns] => 0 dialinternal.php|203500_210|15: [agi_dnid] => 210 dialinternal.php|203500_210|15: [agi_rdnis] => unknown dialinternal.php|203500_210|15: [agi_context] => macro-dial-exten-vm dialinternal.php|203500_210|15: [agi_extension] => s dialinternal.php|203500_210|15: [agi_priority] => 8 dialinternal.php|203500_210|15: [agi_enhanced] => 0.0 dialinternal.php|203500_210|15: [agi_accountcode] => dialinternal.php|203500_210|15: ) dialinternal.php|203500_210|15: dialinternal.php|203500_210|15: Peer: 203500_210 dialinternal.php|203500_210|15: Status: 0 dialinternal.php|203500_210|15: Context: dialinternal.php|203500_210|15: Limit: 203500 dialinternal.php|203500_210|15: Curcalls: 2 dialinternal.php|203500_210|15: State: 1 - InUse dialinternal.php|203500_210|15: ------------------------------ dialinternal.php|203500_210|15: RT is set to 30 dialinternal.php|203500_210|15: CF is disabled dialinternal.php|203500_210|15: CFU is disabled dialinternal.php|203500_210|15: DND is disabled dialinternal.php|203500_210|15: CW is enabled and extension is ready to take call dialinternal.php|203500_210|15: DID is disabled dialinternal.php|203500_210|15: Setting dialstring to SIP/203500_210|30 -- AGI Script dialinternal.php completed, returning 0 [Jul 23 15:18:30] DEBUG[31399]: app_macro.c:337 _macro_exec: Executed application: AGI [Jul 23 15:18:30] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial-exten-vm:20] Dial("SIP/v203500aa-0826bec8", "SIP/203500_210|30") in new stack [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:15547 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:2670 create_addr_from_peer: Our T38 capability (3872) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:2624 do_setnat: Setting NAT on RTP to On [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:2634 do_setnat: Setting NAT on UDPTL to On [Jul 23 15:18:30] DEBUG[31399]: acl.c:215 ast_apply_ha: ##### Testing 85.124.45.93 with 192.168.0.0 [Jul 23 15:18:30] DEBUG[31399]: acl.c:215 ast_apply_ha: ##### Testing 85.124.45.93 with 10.0.0.0 [Jul 23 15:18:30] DEBUG[31399]: acl.c:215 ast_apply_ha: ##### Testing 85.124.45.93 with 172.16.0.0 [Jul 23 15:18:30] DEBUG[31399]: acl.c:215 ast_apply_ha: ##### Testing 85.124.45.93 with 169.254.0.0 [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:1816 ast_sip_ouraddrfor: Target address 85.124.45.93 is not local, substituting externip [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:3867 sip_new: *** Our native formats are 0x8 (alaw) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:3868 sip_new: *** Joint capabilities are 0x0 (nothing) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:3869 sip_new: *** Our capabilities are 0x8 (alaw) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:3870 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:3872 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:3893 sip_new: This channel will not be able to handle video. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-exten-vm-s-20. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable AGISTATUS. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ds. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3457 ast_channel_inherit_variables: Copying soft-transferable variable ORIGDST. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-exten-vm-s-8. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable RT. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-exten-vm-s-7. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-exten-vm-s-3. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-exten-vm-s-1. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG3. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG2. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable ARG1. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-extensions-local-203500-210-1. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-extensions-did-203500-210-1. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-trunk-203500-210-6. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-trunk-203500-210-5. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-trunk-203500-210-4. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable STACK-trunk-203500-210-1. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jul 23 15:18:30] DEBUG[31399]: channel.c:3470 ast_channel_inherit_variables: Not copying variable SIPURI. [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:2882 sip_call: Outgoing Call for 203500_210 [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:3133 update_call_counter: Call to peer '203500_210' is 1 out of 2 [Jul 23 15:18:30] DEBUG[31399]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203500_210 [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:2897 sip_call: Our T38 capability (3872), joint T38 capability (3872) [Jul 23 15:18:30] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:6263 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False [Jul 23 15:18:30] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x8 (alaw) Audio is at 85.193.128.16 port 19636 Adding codec 0x8 (alaw) to SDP [Jul 23 15:18:30] DEBUG[28603]: devicestate.c:287 do_state_change: Adding non-codec 0x1 (telephone-event) to SDP Changing state for SIP/203500_210 - state 6 (Ringing) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP [Jul 23 15:18:30] DEBUG[31399]: channel.c:2522 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=43) [Jul 23 15:18:30] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:30] DEBUG[31402]: app_queue.c:547 changethread: Device 'SIP/203500_210' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Jul 23 15:18:30] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 0: INVITE sip:203500_210@10.98.0.4:49107 SIP/2.0 (45) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK774605d5;rport (64) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 2: From: "00720440931013" ;tag=as5e6e22b7 (72) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 3: To: (36) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 4: Contact: (43) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 5: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 (55) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 6: CSeq: 102 INVITE (16) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 7: User-Agent: mywave Hosted PBX (29) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 9: Date: Mon, 23 Jul 2007 13:18:30 GMT (35) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 11: Supported: replaces (19) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 12: Content-Type: application/sdp (29) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 13: Content-Length: 242 (19) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4640 parse_request: Header 14: (0) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: v=0 (3) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: o=root 22333 22333 IN IP4 85.193.128.16 (39) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: s=session (9) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: c=IN IP4 85.193.128.16 (22) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: t=0 0 (5) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: m=audio 19636 RTP/AVP 8 101 (27) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: a=fmtp:101 0-16 (15) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: a=silenceSupp:off - - - - (25) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: a=ptime:20 (10) [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:4672 parse_request: Line: a=sendrecv (10) Reliably Transmitting (NAT) to 85.124.45.93:23100: INVITE sip:203500_210@10.98.0.4:49107 SIP/2.0 Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK774605d5;rport From: "00720440931013" ;tag=as5e6e22b7 To: Contact: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Max-Forwards: 70 Date: Mon, 23 Jul 2007 13:18:30 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 242 v=0 o=root 22333 22333 IN IP4 85.193.128.16 s=session c=IN IP4 85.193.128.16 t=0 0 m=audio 19636 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jul 23 15:18:30] DEBUG[31399]: chan_sip.c:2017 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32565 -- Called 203500_210 <--- SIP read from 85.124.45.93:23100 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK774605d5;rport=5060 From: "00720440931013" ;tag=as5e6e22b7 To: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 102 INVITE Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Length: 0 <-------------> [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: SIP/2.0 100 Trying (18) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK774605d5;rport=5060 (69) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "00720440931013" ;tag=as5e6e22b7 (72) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: (36) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 (55) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 102 INVITE (16) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Supported: replaces, path (25) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Content-Length: 0 (17) --- (10 headers 0 lines) --- [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 317c30576ada254342a966106074d666@85.193.128.16 (Checking To) --From tag as5e6e22b7 --To-tag [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag Our tag: as5e6e22b7 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2171 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #32565 - INVITE (got response) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '317c30576ada254342a966106074d666@85.193.128.16' Request 102: Found [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:11730 handle_response_invite: SIP response 100 to standard invite <--- SIP read from 85.124.45.93:23100 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK774605d5;rport=5060 From: "00720440931013" ;tag=as5e6e22b7 To: ;tag=1602322080 Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 102 INVITE Contact: Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Allow-Events: talk, hold Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Length: 0 <-------------> [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK774605d5;rport=5060 (69) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "00720440931013" ;tag=as5e6e22b7 (72) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: ;tag=1602322080 (51) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 (55) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 102 INVITE (16) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: (41) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Supported: replaces, path (25) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Allow-Events: talk, hold (24) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Content-Length: 0 (17) --- (12 headers 0 lines) --- [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 317c30576ada254342a966106074d666@85.193.128.16 (Checking To) --From tag as5e6e22b7 --To-tag 1602322080 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag Our tag: as5e6e22b7 [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:2180 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '317c30576ada254342a966106074d666@85.193.128.16' Request 102: Found [Jul 23 15:18:30] DEBUG[28619]: chan_sip.c:11730 handle_response_invite: SIP response 180 to standard invite [Jul 23 15:18:30] DEBUG[28619]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203500_210-0827a4a8 -- SIP/203500_210-0827a4a8 is ringing [Jul 23 15:18:30] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:30] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 pbx*CLI> <--- Transmitting (NAT) to 192.168.255.2:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK37e94b8b;received=192.168.255.2;rport=5060 From: "0720440931013" ;tag=as4ba36eb0 To: ;tag=as29486f20 Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 103 INVITE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Jul 23 15:18:30] DEBUG[28603]: devicestate.c:287 do_state_change: Changing state for SIP/203500_210 - state 6 (Ringing) [Jul 23 15:18:30] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:30] DEBUG[31403]: app_queue.c:547 changethread: Device 'SIP/203500_210' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Jul 23 15:18:30] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 <--- SIP read from 86.32.17.48:45780 ---> <-------------> --- (0 headers 0 lines) Nat keepalive --- pbx*CLI> <--- SIP read from 85.124.45.93:23100 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK774605d5;rport=5060 From: "00720440931013" ;tag=as5e6e22b7 To: ;tag=1602322080 Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 102 INVITE Contact: Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Type: application/sdp Content-Length: 248 v=0 o=203500_210 8000 8000 IN IP4 10.98.0.4 s=SIP Call c=IN IP4 10.98.0.4 t=0 0 m=audio 39157 RTP/AVP 8 101 a=sendrecv a=rtpmap:8 PCMA/8000 a=ptime:20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16,32-36,54 a=silenceSupp:off - - - - <-------------> [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: SIP/2.0 200 OK (14) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK774605d5;rport=5060 (69) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "00720440931013" ;tag=as5e6e22b7 (72) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: ;tag=1602322080 (51) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 (55) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 102 INVITE (16) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: (41) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Supported: replaces, path (25) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Content-Type: application/sdp (29) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Content-Length: 248 (19) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: (0) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: v=0 (3) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: o=203500_210 8000 8000 IN IP4 10.98.0.4 (39) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: s=SIP Call (10) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: c=IN IP4 10.98.0.4 (18) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: t=0 0 (5) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: m=audio 39157 RTP/AVP 8 101 (27) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=sendrecv (10) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=ptime:20 (10) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=fmtp:101 0-16,32-36,54 (24) --- (12 headers 12 lines) --- [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 317c30576ada254342a966106074d666@85.193.128.16 (Checking To) --From tag as5e6e22b7 --To-tag 1602322080 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag 1602322080 Our tag: as5e6e22b7 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:2120 __sip_ack: Acked pending invite 102 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '317c30576ada254342a966106074d666@85.193.128.16' of Request 102: Match Not Found [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:11730 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 8 Found RTP audio format 101 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4993 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 10.98.0.4:39157 Found description format PCMA for ID 8 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:5226 process_sdp: T38 state changed to 0 on channel SIP/203500_210-0827a4a8 Capabilities: us - 0x8 (alaw), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 10.98.0.4:39157 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:5306 process_sdp: We're settling with these formats: 0x8 (alaw) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:5313 process_sdp: We have an owner, now see if we need to change this call [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call [Jul 23 15:18:34] DEBUG[28619]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203500_210 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:8065 build_route: build_route: Contact hop: list_route: hop: [Jul 23 15:18:34] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:5713 reqprep: Strict routing enforced for session 317c30576ada254342a966106074d666@85.193.128.16 [Jul 23 15:18:34] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:34] DEBUG[28603]: devicestate.c:287 do_state_change: set_destination: Parsing for address/port to send to Changing state for SIP/203500_210 - state 2 (In use) set_destination: set destination to 10.98.0.4, port 49107 [Jul 23 15:18:34] DEBUG[31404]: app_queue.c:547 changethread: Transmitting (NAT) to 85.124.45.93:23100: ACK sip:203500_210@10.98.0.4:49107 SIP/2.0 Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK3ebd371c;rport From: "00720440931013" ;tag=as5e6e22b7 To: ;tag=1602322080 Contact: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 102 ACK User-Agent: mywave Hosted PBX Max-Forwards: 70 Content-Length: 0 --- Device 'SIP/203500_210' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 23 15:18:34] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:34] DEBUG[31399]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203500_210-0827a4a8 -- SIP/203500_210-0827a4a8 answered SIP/v203500aa-0826bec8 [Jul 23 15:18:34] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:34] DEBUG[31399]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/v203500aa-0826bec8 [Jul 23 15:18:34] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:34] DEBUG[31399]: chan_sip.c:3525 sip_answer: SIP answering channel: SIP/v203500aa-0826bec8 [Jul 23 15:18:34] DEBUG[31399]: chan_sip.c:6499 transmit_response_with_sdp: Setting framing from config on incoming call [Jul 23 15:18:34] DEBUG[31399]: chan_sip.c:6263 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Jul 23 15:18:34] DEBUG[31399]: chan_sip.c:6264 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.255.1 port 12438 Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jul 23 15:18:34] DEBUG[31399]: chan_sip.c:6395 add_sdp: -- Done with adding codecs to SDP [Jul 23 15:18:34] DEBUG[31399]: channel.c:2522 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=39) [Jul 23 15:18:34] DEBUG[31399]: chan_sip.c:6440 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) pbx*CLI> <--- Reliably Transmitting (NAT) to 192.168.255.2:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK37e94b8b;received=192.168.255.2;rport=5060 From: "0720440931013" ;tag=as4ba36eb0 To: ;tag=as29486f20 Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 103 INVITE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 242 v=0 o=root 22333 22333 IN IP4 192.168.255.1 s=session c=IN IP4 192.168.255.1 t=0 0 m=audio 12438 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Jul 23 15:18:34] DEBUG[31399]: chan_sip.c:2017 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32567 -- Packet2Packet bridging SIP/v203500aa-0826bec8 and SIP/203500_210-0827a4a8 [Jul 23 15:18:34] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:34] DEBUG[28603]: devicestate.c:287 do_state_change: Changing state for SIP/203500_210 - state 2 (In use) [Jul 23 15:18:34] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:34] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:34] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - v203500aa [Jul 23 15:18:34] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer v203500aa [Jul 23 15:18:34] DEBUG[28603]: devicestate.c:287 do_state_change: Changing state for SIP/v203500aa - state 1 (Not in use) [Jul 23 15:18:34] DEBUG[31405]: app_queue.c:547 changethread: Device 'SIP/203500_210' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Jul 23 15:18:34] DEBUG[31406]: app_queue.c:547 changethread: Device 'SIP/v203500aa' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. pbx*CLI> <--- SIP read from 192.168.255.2:5060 ---> ACK sip:210@192.168.255.1 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK0baa00bd;rport From: "0720440931013" ;tag=as4ba36eb0 To: ;tag=as29486f20 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 103 ACK User-Agent: mywave VoIP Gateway by Christoph Stadlmann Max-Forwards: 70 Content-Length: 0 <-------------> [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: ACK sip:210@192.168.255.1 SIP/2.0 (33) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.255.2:5060;branch=z9hG4bK0baa00bd;rport (64) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "0720440931013" ;tag=as4ba36eb0 (70) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: ;tag=as29486f20 (42) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Contact: (42) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (55) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: CSeq: 103 ACK (13) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: User-Agent: mywave VoIP Gateway by Christoph Stadlmann (54) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Content-Length: 0 (17) --- (10 headers 0 lines) --- [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (Checking From) --From tag as4ba36eb0 --To-tag as29486f20 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag 1602322080 Our tag: as5e6e22b7 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 Their Tag as4ba36eb0 Our tag: as29486f20 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received ACK (6) - Command in SIP ACK [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:2128 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #32567 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '048b051b6828e8f57f3db2f74744839e@192.168.255.2' of Response 103: Match Not Found [Jul 23 15:18:34] DEBUG[31399]: rtp.c:1173 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 85.124.45.93:14766 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Jul 23 15:18:34] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 85.193.129.82 with 192.168.0.0 [Jul 23 15:18:34] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 85.193.129.82 with 10.0.0.0 [Jul 23 15:18:34] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 85.193.129.82 with 172.16.0.0 [Jul 23 15:18:34] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 85.193.129.82 with 169.254.0.0 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:1816 ast_sip_ouraddrfor: Target address 85.193.129.82 is not local, substituting externip [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: OPTIONS sip:203500_150@172.24.0.160:5044 SIP/2.0 (48) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK7ab5dfb5;rport (64) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "asterisk" ;tag=as3501fada (60) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: (38) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Contact: (37) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: Call-ID: 4761ba953445b6f4105d6b1330dccc49@85.193.128.16 (55) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: User-Agent: mywave Hosted PBX (29) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Date: Mon, 23 Jul 2007 13:18:34 GMT (35) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Supported: replaces (19) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 85.193.129.82:5044: OPTIONS sip:203500_150@172.24.0.160:5044 SIP/2.0 Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK7ab5dfb5;rport From: "asterisk" ;tag=as3501fada To: Contact: Call-ID: 4761ba953445b6f4105d6b1330dccc49@85.193.128.16 CSeq: 102 OPTIONS User-Agent: mywave Hosted PBX Max-Forwards: 70 Date: Mon, 23 Jul 2007 13:18:34 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:2017 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32568 pbx*CLI> <--- SIP read from 85.193.129.82:5044 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK7ab5dfb5;rport=5060 From: "asterisk" ;tag=as3501fada To: ;tag=2914800619 Call-ID: 4761ba953445b6f4105d6b1330dccc49@85.193.128.16 CSeq: 102 OPTIONS Contact: "Schnurlos Ansfelden" Supported: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO Accept: application/sdp,application/dtmf-relay Accept-Encoding: identity Accept-Language: en Content-Length: 0 <-------------> [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: SIP/2.0 200 OK (14) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK7ab5dfb5;rport=5060 (69) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: "asterisk" ;tag=as3501fada (60) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: ;tag=2914800619 (53) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 4761ba953445b6f4105d6b1330dccc49@85.193.128.16 (55) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: "Schnurlos Ansfelden" (65) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Supported: (11) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, OPTIONS, INFO (46) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Accept: application/sdp,application/dtmf-relay (46) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Accept-Encoding: identity (25) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Accept-Language: en (19) [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Content-Length: 0 (17) --- (13 headers 0 lines) --- [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 4761ba953445b6f4105d6b1330dccc49@85.193.128.16 (Checking To) --From tag as3501fada --To-tag 2914800619 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 4761ba953445b6f4105d6b1330dccc49@85.193.128.16 Their Tag Our tag: as3501fada [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:2128 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #32568 [Jul 23 15:18:34] DEBUG[28619]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '4761ba953445b6f4105d6b1330dccc49@85.193.128.16' of Request 102: Match Not Found Really destroying SIP dialog '4761ba953445b6f4105d6b1330dccc49@85.193.128.16' Method: OPTIONS pbx*CLI> <--- SIP read from 86.32.17.48:45780 ---> SUBSCRIBE sip:203500_310@85.193.128.16 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK541311185;rport From: ;tag=1083364188 To: Call-ID: 1547473219-45780-2@192.168.1.2 CSeq: 193580 SUBSCRIBE Contact: Expires: 3600 Max-Forwards: 70 Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Event: message-summary Accept: application/simple-message-summary Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Length: 0 <-------------> [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: SUBSCRIBE sip:203500_310@85.193.128.16 SIP/2.0 (46) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK541311185;rport (64) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: ;tag=1083364188 (51) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: (34) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 1547473219-45780-2@192.168.1.2 (39) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 193580 SUBSCRIBE (22) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: (43) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Expires: 3600 (13) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Supported: replaces, path (25) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Event: message-summary (22) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Accept: application/simple-message-summary (42) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: Content-Length: 0 (17) --- (15 headers 0 lines) --- [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 1547473219-45780-2@192.168.1.2 (Checking From) --From tag 1083364188 --To-tag [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag 1602322080 Our tag: as5e6e22b7 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 Their Tag as4ba36eb0 Our tag: as29486f20 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009d1f6-xtugam4fa2s1@snom360-000413239674 Their Tag 9srndsbna6 Our tag: as71bebf89 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 5af609d26990fcfd19c6e10e02aab654@192.168.255.2 Their Tag as7daadba7 Our tag: as2cf1ad60 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 7bd83a710e44908e1320fc5945144274@192.168.255.6 Their Tag as0899dcea Our tag: as602c6440 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c26700c2e63-1vdz1isctxgd@snom360-000413239675 Their Tag 30essrokdm Our tag: as3e4adb4e [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c2670076167-0hy88wqhd8nc@192-168-4-104 Their Tag spqh326hwe Our tag: as4b2d092c [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 43c8b5474cf3a6e94fb3f52646bc9c76@192.168.255.1 Their Tag as542d34f9 Our tag: as31b84b54 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 625303904-49107-7@10.98.0.4 Their Tag 1869514991 Our tag: as6289fe4a [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 13c2dd0745a3e1fe2300b7c72c6d4f65@192.168.255.1 Their Tag as49034766 Our tag: as38553910 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 961972835-49107-6@10.98.0.4 Their Tag 1738525494 Our tag: as40938d1d [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009cf85-f70b43qbhben@snom360-000413239673 Their Tag tb0ivqhewt Our tag: as4c19cba5 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009dbba-t14c5hof6dow@snom360-000413239674 Their Tag 0m2e7zoed6 Our tag: as4d87dc91 [Jul 23 15:18:35] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 86.32.17.48 with 192.168.0.0 [Jul 23 15:18:35] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 86.32.17.48 with 10.0.0.0 [Jul 23 15:18:35] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 86.32.17.48 with 172.16.0.0 [Jul 23 15:18:35] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 86.32.17.48 with 169.254.0.0 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:1816 ast_sip_ouraddrfor: Target address 86.32.17.48 is not local, substituting externip [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for 1547473219-45780-2@192.168.1.2 - SUBSCRIBE (No RTP) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Creating new subscription Sending to 86.32.17.48 : 45780 (NAT) Found peer '203500_310' pbx*CLI> <--- Transmitting (NAT) to 86.32.17.48:45780 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK541311185;received=86.32.17.48;rport=45780 From: ;tag=1083364188 To: ;tag=as55fe0003 Call-ID: 1547473219-45780-2@192.168.1.2 CSeq: 193580 SUBSCRIBE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7c65392b" Content-Length: 0 <------------> Scheduling destruction of SIP dialog '1547473219-45780-2@192.168.1.2' in 2880 ms (Method: SUBSCRIBE) pbx*CLI> <--- SIP read from 86.32.17.48:45780 ---> SUBSCRIBE sip:203500_310@85.193.128.16 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK1550891878;rport From: ;tag=1083364188 To: Call-ID: 1547473219-45780-2@192.168.1.2 CSeq: 193581 SUBSCRIBE Contact: Authorization: Digest username="203500_310", realm="asterisk", nonce="7c65392b", uri="sip:203500_310@85.193.128.16", response="a46f2dab1745e357793e6a599e640148", algorithm=MD5 Expires: 3600 Max-Forwards: 70 Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Event: message-summary Accept: application/simple-message-summary Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Length: 0 <-------------> [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: SUBSCRIBE sip:203500_310@85.193.128.16 SIP/2.0 (46) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK1550891878;rport (65) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: ;tag=1083364188 (51) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: (34) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 1547473219-45780-2@192.168.1.2 (39) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 193581 SUBSCRIBE (22) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: (43) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Authorization: Digest username="203500_310", realm="asterisk", nonce="7c65392b", uri="sip:203500_310@85.193.128.16", response="a46f2dab1745e357793e6a599e640148", algorithm=MD5 (175) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Expires: 3600 (13) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Max-Forwards: 70 (16) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Supported: replaces, path (25) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Event: message-summary (22) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Accept: application/simple-message-summary (42) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 15: Content-Length: 0 (17) --- (16 headers 0 lines) --- [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 1547473219-45780-2@192.168.1.2 (Checking From) --From tag 1083364188 --To-tag [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 1547473219-45780-2@192.168.1.2 Their Tag 1083364188 Our tag: as55fe0003 [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jul 23 15:18:35] DEBUG[28619]: chan_sip.c:14448 handle_request_subscribe: Got a new subscription 1547473219-45780-2@192.168.1.2 (possibly with auth) Creating new subscription Sending to 86.32.17.48 : 45780 (NAT) Found peer '203500_310' Looking for 203500_310 in 203500 (domain 85.193.128.16) pbx*CLI> <--- Transmitting (NAT) to 86.32.17.48:45780 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK1550891878;received=86.32.17.48;rport=45780 From: ;tag=1083364188 To: ;tag=as55fe0003 Call-ID: 1547473219-45780-2@192.168.1.2 CSeq: 193581 SUBSCRIBE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> Really destroying SIP dialog '1547473219-45780-2@192.168.1.2' Method: SUBSCRIBE pbx*CLI> <--- SIP read from 86.32.17.48:45780 ---> SUBSCRIBE sip:203500_310@85.193.128.16 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK304053615;rport From: ;tag=288809471 To: Call-ID: 1547473219-45780-2@192.168.1.2 CSeq: 193590 SUBSCRIBE Contact: Expires: 3600 Max-Forwards: 70 Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Event: message-summary Accept: application/simple-message-summary Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Length: 0 <-------------> [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: SUBSCRIBE sip:203500_310@85.193.128.16 SIP/2.0 (46) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK304053615;rport (64) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: ;tag=288809471 (50) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: (34) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 1547473219-45780-2@192.168.1.2 (39) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 193590 SUBSCRIBE (22) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: (43) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Expires: 3600 (13) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Supported: replaces, path (25) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Event: message-summary (22) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Accept: application/simple-message-summary (42) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: Content-Length: 0 (17) --- (15 headers 0 lines) --- [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 1547473219-45780-2@192.168.1.2 (Checking From) --From tag 288809471 --To-tag [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag 1602322080 Our tag: as5e6e22b7 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 Their Tag as4ba36eb0 Our tag: as29486f20 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009d1f6-xtugam4fa2s1@snom360-000413239674 Their Tag 9srndsbna6 Our tag: as71bebf89 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 5af609d26990fcfd19c6e10e02aab654@192.168.255.2 Their Tag as7daadba7 Our tag: as2cf1ad60 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 7bd83a710e44908e1320fc5945144274@192.168.255.6 Their Tag as0899dcea Our tag: as602c6440 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c26700c2e63-1vdz1isctxgd@snom360-000413239675 Their Tag 30essrokdm Our tag: as3e4adb4e [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c2670076167-0hy88wqhd8nc@192-168-4-104 Their Tag spqh326hwe Our tag: as4b2d092c [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 43c8b5474cf3a6e94fb3f52646bc9c76@192.168.255.1 Their Tag as542d34f9 Our tag: as31b84b54 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 625303904-49107-7@10.98.0.4 Their Tag 1869514991 Our tag: as6289fe4a [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 13c2dd0745a3e1fe2300b7c72c6d4f65@192.168.255.1 Their Tag as49034766 Our tag: as38553910 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 961972835-49107-6@10.98.0.4 Their Tag 1738525494 Our tag: as40938d1d [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009cf85-f70b43qbhben@snom360-000413239673 Their Tag tb0ivqhewt Our tag: as4c19cba5 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = No match Their Call ID: 3c267009dbba-t14c5hof6dow@snom360-000413239674 Their Tag 0m2e7zoed6 Our tag: as4d87dc91 [Jul 23 15:18:36] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 86.32.17.48 with 192.168.0.0 [Jul 23 15:18:36] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 86.32.17.48 with 10.0.0.0 [Jul 23 15:18:36] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 86.32.17.48 with 172.16.0.0 [Jul 23 15:18:36] DEBUG[28619]: acl.c:215 ast_apply_ha: ##### Testing 86.32.17.48 with 169.254.0.0 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:1816 ast_sip_ouraddrfor: Target address 86.32.17.48 is not local, substituting externip [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4375 sip_alloc: Allocating new SIP dialog for 1547473219-45780-2@192.168.1.2 - SUBSCRIBE (No RTP) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Creating new subscription Sending to 86.32.17.48 : 45780 (NAT) Found peer '203500_310' pbx*CLI> <--- Transmitting (NAT) to 86.32.17.48:45780 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK304053615;received=86.32.17.48;rport=45780 From: ;tag=288809471 To: ;tag=as040f0c95 Call-ID: 1547473219-45780-2@192.168.1.2 CSeq: 193590 SUBSCRIBE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="40ebbf34" Content-Length: 0 <------------> Scheduling destruction of SIP dialog '1547473219-45780-2@192.168.1.2' in 2880 ms (Method: SUBSCRIBE) pbx*CLI> <--- SIP read from 86.32.17.48:45780 ---> SUBSCRIBE sip:203500_310@85.193.128.16 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK628215809;rport From: ;tag=288809471 To: Call-ID: 1547473219-45780-2@192.168.1.2 CSeq: 193591 SUBSCRIBE Contact: Authorization: Digest username="203500_310", realm="asterisk", nonce="40ebbf34", uri="sip:203500_310@85.193.128.16", response="6df5c51bc4676d747e9e365a8f792834", algorithm=MD5 Expires: 3600 Max-Forwards: 70 Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Event: message-summary Accept: application/simple-message-summary Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Length: 0 <-------------> [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: SUBSCRIBE sip:203500_310@85.193.128.16 SIP/2.0 (46) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK628215809;rport (64) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: ;tag=288809471 (50) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: (34) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 1547473219-45780-2@192.168.1.2 (39) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 193591 SUBSCRIBE (22) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: (43) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Authorization: Digest username="203500_310", realm="asterisk", nonce="40ebbf34", uri="sip:203500_310@85.193.128.16", response="6df5c51bc4676d747e9e365a8f792834", algorithm=MD5 (175) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Expires: 3600 (13) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Max-Forwards: 70 (16) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Supported: replaces, path (25) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Event: message-summary (22) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Accept: application/simple-message-summary (42) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 15: Content-Length: 0 (17) --- (16 headers 0 lines) --- [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 1547473219-45780-2@192.168.1.2 (Checking From) --From tag 288809471 --To-tag [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 1547473219-45780-2@192.168.1.2 Their Tag 288809471 Our tag: as040f0c95 [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jul 23 15:18:36] DEBUG[28619]: chan_sip.c:14448 handle_request_subscribe: Got a new subscription 1547473219-45780-2@192.168.1.2 (possibly with auth) Creating new subscription Sending to 86.32.17.48 : 45780 (NAT) Found peer '203500_310' Looking for 203500_310 in 203500 (domain 85.193.128.16) pbx*CLI> <--- Transmitting (NAT) to 86.32.17.48:45780 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 192.168.1.2:45780;branch=z9hG4bK628215809;received=86.32.17.48;rport=45780 From: ;tag=288809471 To: ;tag=as040f0c95 Call-ID: 1547473219-45780-2@192.168.1.2 CSeq: 193591 SUBSCRIBE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <------------> Really destroying SIP dialog '1547473219-45780-2@192.168.1.2' Method: SUBSCRIBE pbx*CLI> <--- SIP read from 10.2.14.48:34484 ---> <-------------> --- (0 headers 0 lines) Nat keepalive --- pbx*CLI> <--- SIP read from 85.124.45.93:23100 ---> INVITE sip:00720440931013@85.193.128.16 SIP/2.0 Via: SIP/2.0/UDP 10.98.0.4:49107;branch=z9hG4bK159136260;rport From: ;tag=1602322080 To: "00720440931013" ;tag=as5e6e22b7 Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 103 INVITE Contact: Max-Forwards: 70 Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Type: application/sdp Accept: application/sdp, application/dtmf-relay Content-Length: 350 v=0 o=203500_210 8000 8001 IN IP4 10.98.0.4 s=SIP Call c=IN IP4 10.98.0.4 t=0 0 m=image 39157 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy <-------------> [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: INVITE sip:00720440931013@85.193.128.16 SIP/2.0 (47) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 10.98.0.4:49107;branch=z9hG4bK159136260;rport (62) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: ;tag=1602322080 (53) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: "00720440931013" ;tag=as5e6e22b7 (70) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 (55) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 103 INVITE (16) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: (41) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Max-Forwards: 70 (16) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Supported: replaces, path (25) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Content-Type: application/sdp (29) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Accept: application/sdp, application/dtmf-relay (47) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Content-Length: 350 (19) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: (0) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: v=0 (3) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: o=203500_210 8000 8001 IN IP4 10.98.0.4 (39) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: s=SIP Call (10) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: c=IN IP4 10.98.0.4 (18) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: t=0 0 (5) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: m=image 39157 udptl t38 (23) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxVersion:0 (17) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38MaxBitRate:14400 (21) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxFillBitRemoval:0 (24) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxTranscodingMMR:0 (24) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxTranscodingJBIG:0 (25) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxRateManagement:transferredTCF (37) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxMaxBuffer:400 (21) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxMaxDatagram:280 (23) --- (14 headers 15 lines) --- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 317c30576ada254342a966106074d666@85.193.128.16 (Checking From) --From tag 1602322080 --To-tag as5e6e22b7 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag 1602322080 Our tag: as5e6e22b7 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1688 parse_sip_options: Begin: parsing SIP "Supported: replaces, path" [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1696 parse_sip_options: Found SIP option: -replaces- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1702 parse_sip_options: Matched SIP option: replaces [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1696 parse_sip_options: Found SIP option: -path- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1702 parse_sip_options: Matched SIP option: path Sending to 85.124.45.93 : 23100 (NAT) Got T.38 offer in SDP in dialog 317c30576ada254342a966106074d666@85.193.128.16 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4935 process_sdp: T38 state changed to 4 on channel SIP/203500_210-0827a4a8 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4989 process_sdp: Peer T.38 UDPTL is at port 10.98.0.4:39157 Got T.38 Re-invite without audio. Keeping RTP active during T.38 session. Callid 317c30576ada254342a966106074d666@85.193.128.16 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5158 process_sdp: FaxVersion: 0 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5134 process_sdp: T38MaxBitRate: 14400 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5172 process_sdp: FillBitRemoval: 0 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5178 process_sdp: Transcoding MMR: 0 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5185 process_sdp: Transcoding JBIG: 0 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5191 process_sdp: RateManagement: transferredTCF [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5130 process_sdp: MaxBufferSize:400 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5166 process_sdp: FaxMaxDatagram: 280 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5199 process_sdp: UDP EC: t38UDPRedundancy [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5219 process_sdp: Our T38 capability = (3872), peer T38 capability (16160), joint T38 capability (3872) Capabilities: us - 0x8 (alaw), peer - audio=0x0 (nothing)/video=0x0 (nothing), combined - 0x0 (nothing) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5261 process_sdp: Have T.38 but no audio codecs, accepting offer anyway [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:13592 handle_request_invite: Got a SIP re-invite for call 317c30576ada254342a966106074d666@85.193.128.16 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:13689 handle_request_invite: SIP/203500_210-0827a4a8: This call is UP.... [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:16986 sip_handle_t38_reinvite: Sending reinvite on SIP '048b051b6828e8f57f3db2f74744839e@192.168.255.2' - It's UDPTL soon redirected to us (IP 192.168.255.1) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:5713 reqprep: Strict routing enforced for session 048b051b6828e8f57f3db2f74744839e@192.168.255.2 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.255.2, port 5060 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:6117 add_t38_sdp: T.38 UDPTL is at 192.168.255.1 port 4087 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:6123 add_t38_sdp: Our T38 capability (3872), peer T38 capability (3872), joint capability (3872) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:6050 t38_get_rate: T38MaxFaxRate 9600 found [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1629 initialize_initreq: Initializing already initialized SIP dialog 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (presumably reinvite) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: INVITE sip:0720440931013@192.168.255.2 SIP/2.0 (46) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.255.1:5060;branch=z9hG4bK1fea8063;rport (64) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: ;tag=as29486f20 (44) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: "0720440931013" ;tag=as4ba36eb0 (68) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Contact: (32) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 (55) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: CSeq: 102 INVITE (16) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: User-Agent: mywave Hosted PBX (29) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Max-Forwards: 70 (16) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Supported: replaces (19) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: X-asterisk-info: SIP re-invite (T38 switchover) (47) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Content-Type: application/sdp (29) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Content-Length: 351 (19) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: (0) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: v=0 (3) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: o=root 22333 22334 IN IP4 192.168.255.1 (39) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: s=session (9) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: c=IN IP4 192.168.255.1 (22) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: t=0 0 (5) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: m=image 4087 udptl t38 (22) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxVersion:0 (17) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38MaxBitRate:9600 (20) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxFillBitRemoval:0 (24) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxTranscodingMMR:0 (24) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxTranscodingJBIG:0 (25) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxRateManagement:transferredTCF (37) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxMaxBuffer:280 (21) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxMaxDatagram:280 (23) [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxUdpEC:t38UDPRedundancy (30) Reliably Transmitting (NAT) to 192.168.255.2:5060: INVITE sip:0720440931013@192.168.255.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.1:5060;branch=z9hG4bK1fea8063;rport From: ;tag=as29486f20 To: "0720440931013" ;tag=as4ba36eb0 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 351 v=0 o=root 22333 22334 IN IP4 192.168.255.1 s=session c=IN IP4 192.168.255.1 t=0 0 m=image 4087 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:280 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy --- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:2017 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32573 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1884 retrans_pkt: SIP TIMER: Rescheduling retransmission #32573 (1) INVITE - 5 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1898 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 6 ms (t1 3 ms (Retrans id #32573)) Retransmitting #1 (NAT) to 192.168.255.2:5060: INVITE sip:0720440931013@192.168.255.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.1:5060;branch=z9hG4bK1fea8063;rport From: ;tag=as29486f20 To: "0720440931013" ;tag=as4ba36eb0 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 351 v=0 o=root 22333 22334 IN IP4 192.168.255.1 s=session c=IN IP4 192.168.255.1 t=0 0 m=image 4087 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:280 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy --- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1884 retrans_pkt: SIP TIMER: Rescheduling retransmission #32573 (2) INVITE - 5 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1898 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 12 ms (t1 3 ms (Retrans id #32573)) Retransmitting #2 (NAT) to 192.168.255.2:5060: INVITE sip:0720440931013@192.168.255.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.1:5060;branch=z9hG4bK1fea8063;rport From: ;tag=as29486f20 To: "0720440931013" ;tag=as4ba36eb0 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 351 v=0 o=root 22333 22334 IN IP4 192.168.255.1 s=session c=IN IP4 192.168.255.1 t=0 0 m=image 4087 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:280 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy --- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1884 retrans_pkt: SIP TIMER: Rescheduling retransmission #32573 (3) INVITE - 5 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1898 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 24 ms (t1 3 ms (Retrans id #32573)) Retransmitting #3 (NAT) to 192.168.255.2:5060: INVITE sip:0720440931013@192.168.255.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.1:5060;branch=z9hG4bK1fea8063;rport From: ;tag=as29486f20 To: "0720440931013" ;tag=as4ba36eb0 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 351 v=0 o=root 22333 22334 IN IP4 192.168.255.1 s=session c=IN IP4 192.168.255.1 t=0 0 m=image 4087 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:280 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy --- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1884 retrans_pkt: SIP TIMER: Rescheduling retransmission #32573 (4) INVITE - 5 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1898 retrans_pkt: ** SIP timers: Rescheduling retransmission 5 to 48 ms (t1 3 ms (Retrans id #32573)) Retransmitting #4 (NAT) to 192.168.255.2:5060: INVITE sip:0720440931013@192.168.255.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.1:5060;branch=z9hG4bK1fea8063;rport From: ;tag=as29486f20 To: "0720440931013" ;tag=as4ba36eb0 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 351 v=0 o=root 22333 22334 IN IP4 192.168.255.1 s=session c=IN IP4 192.168.255.1 t=0 0 m=image 4087 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:280 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy --- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1884 retrans_pkt: SIP TIMER: Rescheduling retransmission #32573 (5) INVITE - 5 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1898 retrans_pkt: ** SIP timers: Rescheduling retransmission 6 to 96 ms (t1 3 ms (Retrans id #32573)) Retransmitting #5 (NAT) to 192.168.255.2:5060: INVITE sip:0720440931013@192.168.255.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.1:5060;branch=z9hG4bK1fea8063;rport From: ;tag=as29486f20 To: "0720440931013" ;tag=as4ba36eb0 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 351 v=0 o=root 22333 22334 IN IP4 192.168.255.1 s=session c=IN IP4 192.168.255.1 t=0 0 m=image 4087 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:280 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy --- [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1884 retrans_pkt: SIP TIMER: Rescheduling retransmission #32573 (6) INVITE - 5 [Jul 23 15:18:40] DEBUG[28619]: chan_sip.c:1898 retrans_pkt: ** SIP timers: Rescheduling retransmission 7 to 192 ms (t1 3 ms (Retrans id #32573)) Retransmitting #6 (NAT) to 192.168.255.2:5060: INVITE sip:0720440931013@192.168.255.2 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.1:5060;branch=z9hG4bK1fea8063;rport From: ;tag=as29486f20 To: "0720440931013" ;tag=as4ba36eb0 Contact: Call-ID: 048b051b6828e8f57f3db2f74744839e@192.168.255.2 CSeq: 102 INVITE User-Agent: mywave Hosted PBX Max-Forwards: 70 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces X-asterisk-info: SIP re-invite (T38 switchover) Content-Type: application/sdp Content-Length: 351 v=0 o=root 22333 22334 IN IP4 192.168.255.1 s=session c=IN IP4 192.168.255.1 t=0 0 m=image 4087 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:9600 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:280 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy --- [Jul 23 15:18:41] WARNING[28619]: chan_sip.c:1920 retrans_pkt: Maximum retries exceeded on transmission 048b051b6828e8f57f3db2f74744839e@192.168.255.2 for seqno 102 (Critical Request) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:1641 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 048b051b6828e8f57f3db2f74744839e@192.168.255.2 [Jul 23 15:18:41] WARNING[28619]: chan_sip.c:1944 retrans_pkt: Hanging up call 048b051b6828e8f57f3db2f74744839e@192.168.255.2 - no reply to our critical packet. [Jul 23 15:18:41] DEBUG[31399]: rtp.c:3137 bridge_p2p_loop: Oooh, got a hangup [Jul 23 15:18:41] DEBUG[31399]: channel.c:4224 ast_channel_bridge: Returning from native bridge, channels: SIP/v203500aa-0826bec8, SIP/203500_210-0827a4a8 [Jul 23 15:18:41] DEBUG[31399]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/203500_210-0827a4a8' [Jul 23 15:18:41] DEBUG[31399]: chan_sip.c:3368 sip_hangup: Hangup call SIP/203500_210-0827a4a8, SIP callid 317c30576ada254342a966106074d666@85.193.128.16) [Jul 23 15:18:41] DEBUG[31399]: chan_sip.c:3377 sip_hangup: update_call_counter(203500_210) - decrement call limit counter on hangup [Jul 23 15:18:41] DEBUG[31399]: chan_sip.c:3058 update_call_counter: Updating call counter for outgoing call [Jul 23 15:18:41] DEBUG[31399]: chan_sip.c:3107 update_call_counter: Call to peer '203500_210' removed from call limit 2 [Jul 23 15:18:41] DEBUG[31399]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203500_210 Scheduling destruction of SIP dialog '317c30576ada254342a966106074d666@85.193.128.16' in 6400 ms (Method: INVITE) [Jul 23 15:18:41] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:41] DEBUG[31399]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/203500_210-0827a4a8 [Jul 23 15:18:41] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:41] DEBUG[28603]: devicestate.c:287 do_state_change: Changing state for SIP/203500_210 - state 1 (Not in use) [Jul 23 15:18:41] DEBUG[31399]: rtp.c:1499 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jul 23 15:18:41] DEBUG[31407]: app_queue.c:547 changethread: Device 'SIP/203500_210' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 23 15:18:41] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:41] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:41] DEBUG[31399]: app_dial.c:1686 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Jul 23 15:18:41] DEBUG[31399]: app_macro.c:329 _macro_exec: Spawn extension (macro-dial-exten-vm,s,20) exited non-zero on 'SIP/v203500aa-0826bec8' in macro 'dial-exten-vm' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:2407 __ast_pbx_run: Spawn extension (macro-dial-exten-vm,s,20) exited non-zero on 'SIP/v203500aa-0826bec8' == Spawn extension (macro-dial-exten-vm, s, 20) exited non-zero on 'SIP/v203500aa-0826bec8' [Jul 23 15:18:41] DEBUG[31399]: channel.c:1539 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/v203500aa-0826bec8' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Macro' -- Executing [h@macro-dial-exten-vm:1] Macro("SIP/v203500aa-0826bec8", "hangupcall") in new stack [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'ResetCDR' -- Executing [s@macro-hangupcall:1] ResetCDR("SIP/v203500aa-0826bec8", "w") in new stack [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '00720440931013' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '00720440931013' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '210' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'extensions-local-203500' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'SIP/v203500aa-0826bec8' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'SIP/203500_210-0827a4a8' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'Dial' [Jul 23 15:18:41] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'SIP/203500_210|30' [Jul 23 15:18:41] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-07-23 15:18:30' [Jul 23 15:18:41] DEBUG[28603]: devicestate.c:287 do_state_change: Changing state for SIP/203500_210 - state 1 (Not in use) [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-07-23 15:18:34' [Jul 23 15:18:41] DEBUG[31408]: app_queue.c:547 changethread: Device 'SIP/203500_210' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Jul 23 15:18:41] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 203500_210 [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '2007-07-23 15:18:41' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '11' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '7' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '1185196710.67' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1662 pbx_substitute_variables_helper_full: Function result is '203500' [Jul 23 15:18:41] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer 203500_210 [Jul 23 15:18:41] DEBUG[31399]: cdr_addon_mysql.c:210 mysql_log: cdr_mysql: inserting a CDR record. [Jul 23 15:18:41] DEBUG[31399]: cdr_addon_mysql.c:226 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid,userfield) VALUES ('2007-07-23 15:18:30','00720440931013','00720440931013','210','extensions-local-203500', 'SIP/v203500aa-0826bec8','SIP/203500_210-0827a4a8','Dial','SIP/203500_210|30',11,7,'ANSWERED',3,'','1185196710.67','203500') [Jul 23 15:18:41] DEBUG[31399]: app_macro.c:337 _macro_exec: Executed application: ResetCDR [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'NoCDR' -- Executing [s@macro-hangupcall:2] NoCDR("SIP/v203500aa-0826bec8", "") in new stack [Jul 23 15:18:41] DEBUG[31399]: app_macro.c:337 _macro_exec: Executed application: NoCDR [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'DeadAGI' -- Executing [s@macro-hangupcall:3] DeadAGI("SIP/v203500aa-0826bec8", "normalize_cdr.php|0") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/normalize_cdr.php normalize_cdr.php|0: AGI Request: normalize_cdr.php|0: Array normalize_cdr.php|0: ( normalize_cdr.php|0: [agi_request] => normalize_cdr.php normalize_cdr.php|0: [agi_channel] => SIP/v203500aa-0826bec8 normalize_cdr.php|0: [agi_language] => de normalize_cdr.php|0: [agi_type] => SIP normalize_cdr.php|0: [agi_uniqueid] => 1185196710.67 normalize_cdr.php|0: [agi_callerid] => 00720440931013 normalize_cdr.php|0: [agi_calleridname] => unknown normalize_cdr.php|0: [agi_callingpres] => 0 normalize_cdr.php|0: [agi_callingani2] => 0 normalize_cdr.php|0: [agi_callington] => 0 normalize_cdr.php|0: [agi_callingtns] => 0 normalize_cdr.php|0: [agi_dnid] => 210 normalize_cdr.php|0: [agi_rdnis] => unknown normalize_cdr.php|0: [agi_context] => macro-hangupcall normalize_cdr.php|0: [agi_extension] => s normalize_cdr.php|0: [agi_priority] => 3 normalize_cdr.php|0: [agi_enhanced] => 0.0 normalize_cdr.php|0: [agi_accountcode] => normalize_cdr.php|0: ) normalize_cdr.php|0: normalize_cdr.php|0: Array normalize_cdr.php|0: ( normalize_cdr.php|0: [calldate] => 2007-07-23 15:18:30 normalize_cdr.php|0: [clid] => 00720440931013 normalize_cdr.php|0: [src] => 00720440931013 normalize_cdr.php|0: [dst] => 210 normalize_cdr.php|0: [dcontext] => extensions-local-203500 normalize_cdr.php|0: [channel] => SIP/v203500aa-0826bec8 normalize_cdr.php|0: [dstchannel] => SIP/203500_210-0827a4a8 normalize_cdr.php|0: [lastapp] => Dial normalize_cdr.php|0: [lastdata] => SIP/203500_210|30 normalize_cdr.php|0: [duration] => 11 normalize_cdr.php|0: [billsec] => 7 normalize_cdr.php|0: [disposition] => ANSWERED normalize_cdr.php|0: [amaflags] => 3 normalize_cdr.php|0: [accountcode] => normalize_cdr.php|0: [uniqueid] => 1185196710.67 normalize_cdr.php|0: [userfield] => 203500 normalize_cdr.php|0: ) normalize_cdr.php|0: normalize_cdr.php|0: SRC: external -> 00720440931013 normalize_cdr.php|0: DST: internal -> 210 -- AGI Script normalize_cdr.php completed, returning 0 [Jul 23 15:18:41] DEBUG[31399]: app_macro.c:337 _macro_exec: Executed application: DeadAGI [Jul 23 15:18:41] DEBUG[31399]: pbx.c:1809 pbx_extension_helper: Launching 'Hangup' -- Executing [s@macro-hangupcall:4] Hangup("SIP/v203500aa-0826bec8", "") in new stack [Jul 23 15:18:41] DEBUG[31399]: app_macro.c:329 _macro_exec: Spawn extension (macro-hangupcall,s,4) exited non-zero on 'SIP/v203500aa-0826bec8' in macro 'hangupcall' [Jul 23 15:18:41] DEBUG[31399]: pbx.c:2530 __ast_pbx_run: Spawn extension (macro-hangupcall,s,4) exited non-zero on 'SIP/v203500aa-0826bec8' == Spawn extension (macro-hangupcall, s, 4) exited non-zero on 'SIP/v203500aa-0826bec8' [Jul 23 15:18:41] DEBUG[31399]: channel.c:1756 ast_hangup: Hanging up channel 'SIP/v203500aa-0826bec8' [Jul 23 15:18:41] DEBUG[31399]: chan_sip.c:3368 sip_hangup: Hangup call SIP/v203500aa-0826bec8, SIP callid 048b051b6828e8f57f3db2f74744839e@192.168.255.2) [Jul 23 15:18:41] DEBUG[31399]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/v203500aa-0826bec8 [Jul 23 15:18:41] DEBUG[28603]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - v203500aa [Jul 23 15:18:41] DEBUG[28603]: chan_sip.c:15481 sip_devicestate: Checking device state for peer v203500aa [Jul 23 15:18:41] DEBUG[28603]: devicestate.c:287 do_state_change: Changing state for SIP/v203500aa - state 1 (Not in use) [Jul 23 15:18:41] DEBUG[31410]: app_queue.c:547 changethread: Device 'SIP/v203500aa' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 85.124.45.93:23100 ---> INVITE sip:00720440931013@85.193.128.16 SIP/2.0 Via: SIP/2.0/UDP 10.98.0.4:49107;branch=z9hG4bK159136260;rport From: ;tag=1602322080 To: "00720440931013" ;tag=as5e6e22b7 Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 103 INVITE Contact: Max-Forwards: 70 Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Type: application/sdp Accept: application/sdp, application/dtmf-relay Content-Length: 350 v=0 o=203500_210 8000 8001 IN IP4 10.98.0.4 s=SIP Call c=IN IP4 10.98.0.4 t=0 0 m=image 39157 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:280 a=T38FaxUdpEC:t38UDPRedundancy <-------------> [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: INVITE sip:00720440931013@85.193.128.16 SIP/2.0 (47) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 10.98.0.4:49107;branch=z9hG4bK159136260;rport (62) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: ;tag=1602322080 (53) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: "00720440931013" ;tag=as5e6e22b7 (70) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 (55) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 103 INVITE (16) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Contact: (41) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 7: Max-Forwards: 70 (16) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 8: Supported: replaces, path (25) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 9: User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 (45) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 10: Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE (80) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 11: Content-Type: application/sdp (29) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 12: Accept: application/sdp, application/dtmf-relay (47) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 13: Content-Length: 350 (19) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 14: (0) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: v=0 (3) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: o=203500_210 8000 8001 IN IP4 10.98.0.4 (39) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: s=SIP Call (10) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: c=IN IP4 10.98.0.4 (18) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: t=0 0 (5) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: m=image 39157 udptl t38 (23) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxVersion:0 (17) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38MaxBitRate:14400 (21) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxFillBitRemoval:0 (24) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxTranscodingMMR:0 (24) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxTranscodingJBIG:0 (25) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxRateManagement:transferredTCF (37) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxMaxBuffer:400 (21) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4672 parse_request: Line: a=T38FaxMaxDatagram:280 (23) --- (14 headers 15 lines) --- [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 317c30576ada254342a966106074d666@85.193.128.16 (Checking From) --From tag 1602322080 --To-tag as5e6e22b7 [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag 1602322080 Our tag: as5e6e22b7 [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:14875 handle_request: Ignoring SIP message because of retransmit (INVITE Seqno 103, ours 103) Ignoring this INVITE request [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:13594 handle_request_invite: Got a SIP re-transmit of INVITE for call 317c30576ada254342a966106074d666@85.193.128.16 [Jul 23 15:18:41] NOTICE[28619]: chan_sip.c:13786 handle_request_invite: Unable to create/find SIP channel for this INVITE pbx*CLI> <--- Transmitting (NAT) to 85.124.45.93:23100 ---> SIP/2.0 503 Unavailable Via: SIP/2.0/UDP 10.98.0.4:49107;branch=z9hG4bK159136260;received=85.124.45.93;rport=23100 From: ;tag=1602322080 To: "00720440931013" ;tag=as5e6e22b7 Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 103 INVITE User-Agent: mywave Hosted PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> Scheduling destruction of SIP dialog '317c30576ada254342a966106074d666@85.193.128.16' in 6400 ms (Method: INVITE) Really destroying SIP dialog '048b051b6828e8f57f3db2f74744839e@192.168.255.2' Method: ACK pbx*CLI> <--- SIP read from 85.124.45.93:23100 ---> ACK sip:00720440931013@85.193.128.16 SIP/2.0 Via: SIP/2.0/UDP 10.98.0.4:49107;branch=z9hG4bK159136260;rport From: ;tag=1602322080 To: "00720440931013" ;tag=as5e6e22b7 Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 103 ACK Content-Length: 0 <-------------> [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 0: ACK sip:00720440931013@85.193.128.16 SIP/2.0 (44) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 1: Via: SIP/2.0/UDP 10.98.0.4:49107;branch=z9hG4bK159136260;rport (62) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 2: From: ;tag=1602322080 (53) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 3: To: "00720440931013" ;tag=as5e6e22b7 (70) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 4: Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 (55) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 5: CSeq: 103 ACK (13) [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4640 parse_request: Header 6: Content-Length: 0 (17) --- (7 headers 0 lines) --- [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4412 find_call: = Looking for Call ID: 317c30576ada254342a966106074d666@85.193.128.16 (Checking From) --From tag 1602322080 --To-tag as5e6e22b7 [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:4428 find_call: = Found Their Call ID: 317c30576ada254342a966106074d666@85.193.128.16 Their Tag 1602322080 Our tag: as5e6e22b7 [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:14856 handle_request: **** Received ACK (6) - Command in SIP ACK [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:2138 __sip_ack: Stopping retransmission on '317c30576ada254342a966106074d666@85.193.128.16' of Response 103: Match Found [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:5713 reqprep: Strict routing enforced for session 317c30576ada254342a966106074d666@85.193.128.16 set_destination: Parsing for address/port to send to set_destination: set destination to 10.98.0.4, port 49107 Reliably Transmitting (NAT) to 85.124.45.93:23100: BYE sip:203500_210@10.98.0.4:49107 SIP/2.0 Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK32907973;rport From: "00720440931013" ;tag=as5e6e22b7 To: ;tag=1602322080 Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 103 BYE User-Agent: mywave Hosted PBX Max-Forwards: 70 Content-Length: 0 --- [Jul 23 15:18:41] DEBUG[28619]: chan_sip.c:2017 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32576 Scheduling destruction of SIP dialog '317c30576ada254342a966106074d666@85.193.128.16' in 6400 ms (Method: ACK) <--- SIP read from 85.124.45.93:23100 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 85.193.128.16:5060;branch=z9hG4bK32907973;rport=5060 From: "00720440931013" ;tag=as5e6e22b7 To: ;tag=1602322080 Call-ID: 317c30576ada254342a966106074d666@85.193.128.16 CSeq: 103 BYE Contact: Supported: replaces, path User-Agent: Grandstream HT-502 V0.2A 1.0.0.44 Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE Content-Length: 0 <------------->