<--- SIP read from 212.147.65.170:8157 ---> REGISTER sip:194.148.41.50 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK3e7000007af9ffff From: "0625037902" ;tag=2191000024500000 To: Contact: Authorization: Digest username="0625037902", realm="vtxvoip", algorithm=MD5, uri="sip:194.148.41.50", nonce="2983c2b8", response="92d5c45781ba27fad7e3184b4f107a04" Call-ID: 1dbfffff9f900000@10.0.0.102 CSeq: 3926 REGISTER Expires: 60 User-Agent: Grandstream HT488 1.0.3.44 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 <-------------> [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: REGISTER sip:194.148.41.50 SIP/2.0 (34) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK3e7000007af9ffff (58) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "0625037902" ;tag=2191000024500000 (81) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (45) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (47) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Authorization: Digest username="0625037902", realm="vtxvoip", algorithm=MD5, uri="sip:194.148.41.50", nonce="2983c2b8", response="92d5c45781ba27fad7e3184b4f107a04" (163) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 1dbfffff9f900000@10.0.0.102 (36) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: CSeq: 3926 REGISTER (19) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Expires: 60 (11) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Max-Forwards: 70 (16) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 13: (0) [Mar 28 16:26:10] --- (13 headers 0 lines) --- [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 1dbfffff9f900000@10.0.0.102 - REGISTER (No RTP) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 28 16:26:10] Using latest REGISTER request as basis request [Mar 28 16:26:10] Sending to 10.0.0.102 : 5060 (no NAT) [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '0625037902' [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:7639 reg_source_db: SIP Seeding peer from astdb: '0625037902' at 0625037902@212.147.65.170:8157 for 60 [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:0625037902@10.0.0.102;user=phone SIP/2.0 (52) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5676bf38;rport (64) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as6a4e3144 (60) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (42) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 6536d9c12ac4698644842788081cfb74@194.148.41.50 (55) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Date: Wed, 28 Mar 2007 14:26:10 GMT (35) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Supported: replaces (19) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:26:10] Reliably Transmitting (NAT) to 212.147.65.170:8157: OPTIONS sip:0625037902@10.0.0.102;user=phone SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5676bf38;rport From: "asterisk" ;tag=as6a4e3144 To: Contact: Call-ID: 6536d9c12ac4698644842788081cfb74@194.148.41.50 CSeq: 102 OPTIONS User-Agent: VTX SIP Max-Forwards: 70 Date: Wed, 28 Mar 2007 14:26:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #13 [Mar 28 16:26:10] DEBUG[18180]: pbx.c:4826 ast_add_extension2: Added extension '0625037902' priority 1 to voip-test-01 [Mar 28 16:26:10] -- Added extension '0625037902' priority 1 to voip-test-01 [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:355 update_mysql: MySQL RealTime: Update SQL: UPDATE sip_users SET RegisteredTo = 'voip-test-01' WHERE name = '0625037902' [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 0 rows on table: sip_users [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:355 update_mysql: MySQL RealTime: Update SQL: UPDATE sip_users SET RegisterStart = '\'+NOW()+\'' WHERE name = '0625037902' [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 0 rows on table: sip_users [Mar 28 16:26:10] <--- Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK3e7000007af9ffff;received=212.147.65.170 From: "0625037902" ;tag=2191000024500000 To: Call-ID: 1dbfffff9f900000@10.0.0.102 CSeq: 3926 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:26:10] <--- Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK3e7000007af9ffff;received=212.147.65.170 From: "0625037902" ;tag=2191000024500000 To: ;tag=as52ad201d Call-ID: 1dbfffff9f900000@10.0.0.102 CSeq: 3926 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="vtxvoip", nonce="6f8b3a2f" Content-Length: 0 <------------> [Mar 28 16:26:10] Scheduling destruction of SIP dialog '1dbfffff9f900000@10.0.0.102' in 32000 ms (Method: REGISTER) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 28 16:26:10] Scheduling destruction of SIP dialog '093b3da77f5d759634a9dcff0b893a79@194.148.41.50' in 32000 ms (Method: NOTIFY) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: NOTIFY sip:0625037902@10.0.0.102;user=phone SIP/2.0 (51) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK45839a11;rport (64) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as261f83f0 (60) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (42) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 093b3da77f5d759634a9dcff0b893a79@194.148.41.50 (55) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Event: message-summary (22) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 93 (18) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Messages-Waiting: no (20) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Message-Account: sip:asterisk@194.148.41.50 (43) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 28 16:26:10] Reliably Transmitting (NAT) to 212.147.65.170:8157: NOTIFY sip:0625037902@10.0.0.102;user=phone SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK45839a11;rport From: "asterisk" ;tag=as261f83f0 To: Contact: Call-ID: 093b3da77f5d759634a9dcff0b893a79@194.148.41.50 CSeq: 102 NOTIFY User-Agent: VTX SIP Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 93 Messages-Waiting: no Message-Account: sip:asterisk@194.148.41.50 Voice-Message: 0/0 (0/0) --- [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #18 [Mar 28 16:26:10] <--- SIP read from 212.147.65.170:8157 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5676bf38;rport From: "asterisk" ;tag=as6a4e3144 To: ;tag=23e60000c3a60000 Call-ID: 6536d9c12ac4698644842788081cfb74@194.148.41.50 CSeq: 102 OPTIONS User-Agent: Grandstream HT488 1.0.3.44 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 <-------------> [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5676bf38;rport (64) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as6a4e3144 (60) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=23e60000c3a60000 (63) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 6536d9c12ac4698644842788081cfb74@194.148.41.50 (55) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Contact: (47) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Supported: replaces (19) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Length: 0 (17) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:26:10] --- (11 headers 0 lines) --- [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #13 [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6536d9c12ac4698644842788081cfb74@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:26:10] NOTICE[18180]: chan_sip.c:12147 handle_response_peerpoke: Peer '0625037902' is now Reachable. (14ms / 2000ms) [Mar 28 16:26:10] DEBUG[18180]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902 [Mar 28 16:26:10] Really destroying SIP dialog '6536d9c12ac4698644842788081cfb74@194.148.41.50' Method: OPTIONS [Mar 28 16:26:10] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:26:10] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:26:10] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 1 (Not in use) [Mar 28 16:26:10] DEBUG[18182]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:10] <--- SIP read from 212.147.65.170:8157 ---> REGISTER sip:194.148.41.50 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bKf5660000f7660000 From: "0625037902" ;tag=2191000024500000 To: Contact: Authorization: Digest username="0625037902", realm="vtxvoip", algorithm=MD5, uri="sip:194.148.41.50", nonce="6f8b3a2f", response="67eba5cf5b59bf8aac689d46974706de" Call-ID: 1dbfffff9f900000@10.0.0.102 CSeq: 3927 REGISTER Expires: 60 User-Agent: Grandstream HT488 1.0.3.44 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 <-------------> [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: REGISTER sip:194.148.41.50 SIP/2.0 (34) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bKf5660000f7660000 (58) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "0625037902" ;tag=2191000024500000 (81) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (45) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (47) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Authorization: Digest username="0625037902", realm="vtxvoip", algorithm=MD5, uri="sip:194.148.41.50", nonce="6f8b3a2f", response="67eba5cf5b59bf8aac689d46974706de" (163) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 1dbfffff9f900000@10.0.0.102 (36) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: CSeq: 3927 REGISTER (19) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Expires: 60 (11) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Max-Forwards: 70 (16) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 13: (0) [Mar 28 16:26:10] --- (13 headers 0 lines) --- [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 28 16:26:10] Using latest REGISTER request as basis request [Mar 28 16:26:10] Sending to 212.147.65.170 : 8157 (NAT) [Mar 28 16:26:10] <--- Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bKf5660000f7660000;received=212.147.65.170 From: "0625037902" ;tag=2191000024500000 To: Call-ID: 1dbfffff9f900000@10.0.0.102 CSeq: 3927 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:26:10] -- Saved useragent "Grandstream HT488 1.0.3.44" for peer 0625037902 [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:355 update_mysql: MySQL RealTime: Update SQL: UPDATE sip_users SET ipaddr = '212.147.65.170', port = '8157', regseconds = '1175092030', username = '0625037902', fullcontact = 'sip:0625037902@10.0.0.102;user=phone' WHERE name = '0625037902' [Mar 28 16:26:10] DEBUG[18180]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 1 rows on table: sip_users [Mar 28 16:26:10] <--- Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bKf5660000f7660000;received=212.147.65.170 From: "0625037902" ;tag=2191000024500000 To: ;tag=as52ad201d Call-ID: 1dbfffff9f900000@10.0.0.102 CSeq: 3927 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Wed, 28 Mar 2007 14:26:10 GMT Content-Length: 0 <------------> [Mar 28 16:26:10] DEBUG[18180]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902 [Mar 28 16:26:10] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:26:10] Scheduling destruction of SIP dialog '1dbfffff9f900000@10.0.0.102' in 32000 ms (Method: REGISTER) [Mar 28 16:26:10] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:26:10] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 1 (Not in use) [Mar 28 16:26:10] DEBUG[18183]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:10] <--- SIP read from 212.147.65.170:8157 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK45839a11;rport From: "asterisk" ;tag=as261f83f0 To: ;tag=a32600006339ffff Call-ID: 093b3da77f5d759634a9dcff0b893a79@194.148.41.50 CSeq: 102 NOTIFY User-Agent: Grandstream HT488 1.0.3.44 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 <-------------> [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK45839a11;rport (64) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as261f83f0 (60) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=a32600006339ffff (63) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 093b3da77f5d759634a9dcff0b893a79@194.148.41.50 (55) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: CSeq: 102 NOTIFY (16) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Contact: (47) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Supported: replaces (19) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Length: 0 (17) [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:26:10] --- (11 headers 0 lines) --- [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #18 [Mar 28 16:26:10] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '093b3da77f5d759634a9dcff0b893a79@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:26:10] Really destroying SIP dialog '093b3da77f5d759634a9dcff0b893a79@194.148.41.50' Method: NOTIFY [Mar 28 16:26:11] <--- SIP read from 212.40.9.10:5060 ---> OPTIONS sip:212.40.9.9:5060 SIP/2.0 Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK3f15e613 Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=2619f102 Call-ID: 00002132460a7769@bigip.vtx.ch CSeq: 1175091049 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK3f15e613 (57) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=2619f102 (45) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 00002132460a7769@bigip.vtx.ch (38) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091049 OPTIONS (24) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:26:11] --- (9 headers 0 lines) --- [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 00002132460a7769@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:26:11] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:26:11] Looking for s in default (domain 212.40.9.9) [Mar 28 16:26:11] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:11] DEBUG[18180]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 's' AND context = 'default' AND priority = '1' [Mar 28 16:26:11] <--- Transmitting (no NAT) to 212.40.9.10:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK3f15e613;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=2619f102 To: sip:212.40.9.9;tag=as0433df6d Call-ID: 00002132460a7769@bigip.vtx.ch CSeq: 1175091049 OPTIONS User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Mar 28 16:26:11] Scheduling destruction of SIP dialog '00002132460a7769@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) [Mar 28 16:26:16] <--- SIP read from 212.40.9.10:5060 ---> OPTIONS sip:212.40.9.9:5060 SIP/2.0 Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK3636fecc Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=792b1620 Call-ID: 00002136460a776e@bigip.vtx.ch CSeq: 1175091054 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK3636fecc (57) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=792b1620 (45) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 00002136460a776e@bigip.vtx.ch (38) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091054 OPTIONS (24) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:26:16] --- (9 headers 0 lines) --- [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 00002136460a776e@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:26:16] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:26:16] Looking for s in default (domain 212.40.9.9) [Mar 28 16:26:16] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:16] DEBUG[18180]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 's' AND context = 'default' AND priority = '1' [Mar 28 16:26:16] <--- Transmitting (no NAT) to 212.40.9.10:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK3636fecc;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=792b1620 To: sip:212.40.9.9;tag=as12c6de36 Call-ID: 00002136460a776e@bigip.vtx.ch CSeq: 1175091054 OPTIONS User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Mar 28 16:26:16] Scheduling destruction of SIP dialog '00002136460a776e@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) [Mar 28 16:26:21] <--- SIP read from 212.40.9.10:5060 ---> OPTIONS sip:212.40.9.9:5060 SIP/2.0 Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK2e756002 Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=0d775cd6 Call-ID: 0000213a460a7773@bigip.vtx.ch CSeq: 1175091059 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK2e756002 (57) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=0d775cd6 (45) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 0000213a460a7773@bigip.vtx.ch (38) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091059 OPTIONS (24) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:26:21] --- (9 headers 0 lines) --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 0000213a460a7773@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:26:21] Looking for s in default (domain 212.40.9.9) [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 's' AND context = 'default' AND priority = '1' [Mar 28 16:26:21] <--- Transmitting (no NAT) to 212.40.9.10:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK2e756002;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=0d775cd6 To: sip:212.40.9.9;tag=as0be49176 Call-ID: 0000213a460a7773@bigip.vtx.ch CSeq: 1175091059 OPTIONS User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Mar 28 16:26:21] Scheduling destruction of SIP dialog '0000213a460a7773@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 28 16:26:21] Scheduling destruction of SIP dialog '18c523233b1c5ec62db2b21b1bba2824@194.148.41.50' in 6400 ms (Method: NOTIFY) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: NOTIFY sip:0625037902@10.0.0.102;user=phone SIP/2.0 (51) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK0f3033ea;rport (64) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as4eacf9cc (60) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (42) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 18c523233b1c5ec62db2b21b1bba2824@194.148.41.50 (55) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Event: message-summary (22) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 93 (18) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Messages-Waiting: no (20) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Message-Account: sip:asterisk@194.148.41.50 (43) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 28 16:26:21] Reliably Transmitting (NAT) to 212.147.65.170:8157: NOTIFY sip:0625037902@10.0.0.102;user=phone SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK0f3033ea;rport From: "asterisk" ;tag=as4eacf9cc To: Contact: Call-ID: 18c523233b1c5ec62db2b21b1bba2824@194.148.41.50 CSeq: 102 NOTIFY User-Agent: VTX SIP Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 93 Messages-Waiting: no Message-Account: sip:asterisk@194.148.41.50 Voice-Message: 0/0 (0/0) --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #26 [Mar 28 16:26:21] <--- SIP read from 212.147.65.170:8157 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK0f3033ea;rport From: "asterisk" ;tag=as4eacf9cc To: ;tag=4e520000cdbaffff Call-ID: 18c523233b1c5ec62db2b21b1bba2824@194.148.41.50 CSeq: 102 NOTIFY User-Agent: Grandstream HT488 1.0.3.44 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 <-------------> [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK0f3033ea;rport (64) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as4eacf9cc (60) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=4e520000cdbaffff (63) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 18c523233b1c5ec62db2b21b1bba2824@194.148.41.50 (55) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: CSeq: 102 NOTIFY (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Contact: (47) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Supported: replaces (19) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Length: 0 (17) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:26:21] --- (11 headers 0 lines) --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #26 [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '18c523233b1c5ec62db2b21b1bba2824@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:26:21] Really destroying SIP dialog '18c523233b1c5ec62db2b21b1bba2824@194.148.41.50' Method: NOTIFY [Mar 28 16:26:21] <--- SIP read from 212.147.0.191:11840 ---> REGISTER sip:194.148.41.50 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-457670586b706e7d-1--d87543-;rport Max-Forwards: 70 Contact: To: "0625037901" From: "0625037901";tag=2477442c Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 5 REGISTER Expires: 60 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO User-Agent: eyeBeam release 1003l stamp 30936 Authorization: Digest username="0625037901",realm="vtxvoip",nonce="7fab113c",uri="sip:194.148.41.50",response="0afaaa8b2b98988d3a52d76652a865e7",algorithm=MD5 Content-Length: 0 <-------------> [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: REGISTER sip:194.148.41.50 SIP/2.0 (34) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-457670586b706e7d-1--d87543-;rport (91) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 70 (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: Contact: (72) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: To: "0625037901" (46) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: From: "0625037901";tag=2477442c (61) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. (69) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: CSeq: 5 REGISTER (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Expires: 60 (11) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Authorization: Digest username="0625037901",realm="vtxvoip",nonce="7fab113c",uri="sip:194.148.41.50",response="0afaaa8b2b98988d3a52d76652a865e7",algorithm=MD5 (158) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 13: (0) [Mar 28 16:26:21] --- (13 headers 0 lines) --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. - REGISTER (No RTP) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 28 16:26:21] Using latest REGISTER request as basis request [Mar 28 16:26:21] Sending to 212.147.0.191 : 11840 (NAT) [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '0625037901' [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:7639 reg_source_db: SIP Seeding peer from astdb: '0625037901' at 0625037901@212.147.0.191:11840 for 60 [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:0625037901@212.147.0.191:11840;rinstance=62d70f12da108d78 SIP/2.0 (77) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK7b456201;rport (64) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as06565fab (60) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (67) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 4885b60e5b7110be71180c826f5453b8@194.148.41.50 (55) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Date: Wed, 28 Mar 2007 14:26:21 GMT (35) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Supported: replaces (19) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:26:21] Reliably Transmitting (NAT) to 212.147.0.191:11840: OPTIONS sip:0625037901@212.147.0.191:11840;rinstance=62d70f12da108d78 SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK7b456201;rport From: "asterisk" ;tag=as06565fab To: Contact: Call-ID: 4885b60e5b7110be71180c826f5453b8@194.148.41.50 CSeq: 102 OPTIONS User-Agent: VTX SIP Max-Forwards: 70 Date: Wed, 28 Mar 2007 14:26:21 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #27 [Mar 28 16:26:21] DEBUG[18180]: pbx.c:4826 ast_add_extension2: Added extension '0625037901' priority 1 to voip-test-01 [Mar 28 16:26:21] -- Added extension '0625037901' priority 1 to voip-test-01 [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:355 update_mysql: MySQL RealTime: Update SQL: UPDATE sip_users SET RegisteredTo = 'voip-test-01' WHERE name = '0625037901' [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 0 rows on table: sip_users [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:355 update_mysql: MySQL RealTime: Update SQL: UPDATE sip_users SET RegisterStart = '\'+NOW()+\'' WHERE name = '0625037901' [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 0 rows on table: sip_users [Mar 28 16:26:21] <--- Transmitting (NAT) to 212.147.0.191:11840 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-457670586b706e7d-1--d87543-;received=212.147.0.191;rport=11840 From: "0625037901";tag=2477442c To: "0625037901" Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 5 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:26:21] <--- Transmitting (NAT) to 212.147.0.191:11840 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-457670586b706e7d-1--d87543-;received=212.147.0.191;rport=11840 From: "0625037901";tag=2477442c To: "0625037901";tag=as1c4d4bab Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 5 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="vtxvoip", nonce="0c5ca2b1" Content-Length: 0 <------------> [Mar 28 16:26:21] Scheduling destruction of SIP dialog '24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg.' in 32000 ms (Method: REGISTER) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 28 16:26:21] Scheduling destruction of SIP dialog '62e5743c71c8ad565ed3eed531d4e77b@194.148.41.50' in 32000 ms (Method: NOTIFY) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: NOTIFY sip:0625037901@212.147.0.191:11840;rinstance=62d70f12da108d78 SIP/2.0 (76) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK061eabe1;rport (64) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as4b52e384 (60) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (67) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 62e5743c71c8ad565ed3eed531d4e77b@194.148.41.50 (55) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Event: message-summary (22) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 93 (18) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Messages-Waiting: no (20) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Message-Account: sip:asterisk@194.148.41.50 (43) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 28 16:26:21] Reliably Transmitting (NAT) to 212.147.0.191:11840: NOTIFY sip:0625037901@212.147.0.191:11840;rinstance=62d70f12da108d78 SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK061eabe1;rport From: "asterisk" ;tag=as4b52e384 To: Contact: Call-ID: 62e5743c71c8ad565ed3eed531d4e77b@194.148.41.50 CSeq: 102 NOTIFY User-Agent: VTX SIP Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 93 Messages-Waiting: no Message-Account: sip:asterisk@194.148.41.50 Voice-Message: 0/0 (0/0) --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32 [Mar 28 16:26:21] <--- SIP read from 212.147.0.191:11840 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK7b456201;rport=5060 Contact: To: ;tag=b7597a7c From: "asterisk";tag=as06565fab Call-ID: 4885b60e5b7110be71180c826f5453b8@194.148.41.50 CSeq: 102 OPTIONS Accept: application/sdp Accept-Language: en Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO User-Agent: eyeBeam release 1003l stamp 30936 Content-Length: 0 <-------------> [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK7b456201;rport=5060 (69) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Contact: (33) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=b7597a7c (80) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: From: "asterisk";tag=as06565fab (59) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 4885b60e5b7110be71180c826f5453b8@194.148.41.50 (55) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Accept-Language: en (19) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 0 (17) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:26:21] --- (12 headers 0 lines) --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #27 [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4885b60e5b7110be71180c826f5453b8@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:26:21] NOTICE[18180]: chan_sip.c:12147 handle_response_peerpoke: Peer '0625037901' is now Reachable. (11ms / 2000ms) [Mar 28 16:26:21] DEBUG[18180]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037901 [Mar 28 16:26:21] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037901 [Mar 28 16:26:21] Really destroying SIP dialog '4885b60e5b7110be71180c826f5453b8@194.148.41.50' Method: OPTIONS [Mar 28 16:26:21] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037901 [Mar 28 16:26:21] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/0625037901 - state 1 (Not in use) [Mar 28 16:26:21] DEBUG[18184]: app_queue.c:546 changethread: Device 'SIP/0625037901' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:21] <--- SIP read from 212.147.0.191:11840 ---> REGISTER sip:194.148.41.50 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-6471f0681334d344-1--d87543-;rport Max-Forwards: 70 Contact: To: "0625037901" From: "0625037901";tag=2477442c Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 6 REGISTER Expires: 60 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO User-Agent: eyeBeam release 1003l stamp 30936 Authorization: Digest username="0625037901",realm="vtxvoip",nonce="0c5ca2b1",uri="sip:194.148.41.50",response="5629826a13ccc4740c7023f376ff3455",algorithm=MD5 Content-Length: 0 <-------------> [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: REGISTER sip:194.148.41.50 SIP/2.0 (34) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-6471f0681334d344-1--d87543-;rport (91) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 70 (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: Contact: (72) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: To: "0625037901" (46) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: From: "0625037901";tag=2477442c (61) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. (69) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: CSeq: 6 REGISTER (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Expires: 60 (11) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Authorization: Digest username="0625037901",realm="vtxvoip",nonce="0c5ca2b1",uri="sip:194.148.41.50",response="5629826a13ccc4740c7023f376ff3455",algorithm=MD5 (158) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 13: (0) [Mar 28 16:26:21] --- (13 headers 0 lines) --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 28 16:26:21] Using latest REGISTER request as basis request [Mar 28 16:26:21] Sending to 212.147.0.191 : 11840 (NAT) [Mar 28 16:26:21] <--- Transmitting (NAT) to 212.147.0.191:11840 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-6471f0681334d344-1--d87543-;received=212.147.0.191;rport=11840 From: "0625037901";tag=2477442c To: "0625037901" Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 6 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:26:21] -- Saved useragent "eyeBeam release 1003l stamp 30936" for peer 0625037901 [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:355 update_mysql: MySQL RealTime: Update SQL: UPDATE sip_users SET ipaddr = '212.147.0.191', port = '11840', regseconds = '1175092041', username = '0625037901', fullcontact = 'sip:0625037901@212.147.0.191:11840;rinstance=62d70f12da108d78' WHERE name = '0625037901' [Mar 28 16:26:21] DEBUG[18180]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 1 rows on table: sip_users [Mar 28 16:26:21] <--- Transmitting (NAT) to 212.147.0.191:11840 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-6471f0681334d344-1--d87543-;received=212.147.0.191;rport=11840 From: "0625037901";tag=2477442c To: "0625037901";tag=as1c4d4bab Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 6 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Wed, 28 Mar 2007 14:26:21 GMT Content-Length: 0 <------------> [Mar 28 16:26:21] DEBUG[18180]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037901 [Mar 28 16:26:21] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037901 [Mar 28 16:26:21] Scheduling destruction of SIP dialog '24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg.' in 32000 ms (Method: REGISTER) [Mar 28 16:26:21] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037901 [Mar 28 16:26:21] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/0625037901 - state 1 (Not in use) [Mar 28 16:26:21] <--- SIP read from 212.147.0.191:11840 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK061eabe1;rport=5060 Contact: To: ;tag=31778d4b From: "asterisk";tag=as4b52e384 Call-ID: 62e5743c71c8ad565ed3eed531d4e77b@194.148.41.50 CSeq: 102 NOTIFY User-Agent: eyeBeam release 1003l stamp 30936 Content-Length: 0 <-------------> [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK061eabe1;rport=5060 (69) [Mar 28 16:26:21] DEBUG[18185]: app_queue.c:546 changethread: Device 'SIP/0625037901' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Contact: (33) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=31778d4b (80) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: From: "asterisk";tag=as4b52e384 (59) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 62e5743c71c8ad565ed3eed531d4e77b@194.148.41.50 (55) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:26:21] --- (9 headers 0 lines) --- [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #32 [Mar 28 16:26:21] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '62e5743c71c8ad565ed3eed531d4e77b@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:26:21] Really destroying SIP dialog '62e5743c71c8ad565ed3eed531d4e77b@194.148.41.50' Method: NOTIFY [Mar 28 16:26:22] <--- SIP read from 212.147.65.170:8157 ---> INVITE sip:0217211252@194.148.41.50;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK465200006e520000 From: "0625037902" ;tag=9cb30000f559ffff To: Contact: Supported: replaces Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65506 INVITE User-Agent: Grandstream HT488 1.0.3.44 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 303 v=0 o=0625037902 8000 8000 IN IP4 10.0.0.102 s=SIP Call c=IN IP4 10.0.0.102 t=0 0 m=audio 5004 RTP/AVP 0 8 4 18 2 97 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=ptime:20 <-------------> [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: INVITE sip:0217211252@194.148.41.50;user=phone SIP/2.0 (54) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK465200006e520000 (58) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "0625037902" ;tag=9cb30000f559ffff (81) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (45) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (47) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Supported: replaces (19) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 0f25000081b20000@10.0.0.102 (36) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: CSeq: 65506 INVITE (18) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Max-Forwards: 70 (16) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Content-Type: application/sdp (29) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 303 (19) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 13: (0) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: v=0 (3) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: o=0625037902 8000 8000 IN IP4 10.0.0.102 (40) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: s=SIP Call (10) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: c=IN IP4 10.0.0.102 (19) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: t=0 0 (5) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: m=audio 5004 RTP/AVP 0 8 4 18 2 97 (34) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=fmtp:97 mode=20 (17) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=ptime:20 (10) [Mar 28 16:26:22] --- (13 headers 15 lines) --- [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2582 do_setnat: Setting NAT on RTP to Off [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2592 do_setnat: Setting NAT on UDPTL to Off [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 0f25000081b20000@10.0.0.102 - INVITE (With RTP) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:1680 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:1688 parse_sip_options: Found SIP option: -replaces- [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:1694 parse_sip_options: Matched SIP option: replaces [Mar 28 16:26:22] Sending to 10.0.0.102 : 5060 (no NAT) [Mar 28 16:26:22] Using INVITE request as basis request - 0f25000081b20000@10.0.0.102 [Mar 28 16:26:22] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18180]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '0625037902' [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2582 do_setnat: Setting NAT on RTP to On [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2592 do_setnat: Setting NAT on UDPTL to On [Mar 28 16:26:22] <--- Reliably Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK465200006e520000;received=212.147.65.170 From: "0625037902" ;tag=9cb30000f559ffff To: ;tag=as410fec7e Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65506 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="vtxvoip", nonce="53e996b3" Content-Length: 0 <------------> [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #36 [Mar 28 16:26:22] Scheduling destruction of SIP dialog '0f25000081b20000@10.0.0.102' in 32000 ms (Method: INVITE) [Mar 28 16:26:22] Found user '0625037902' [Mar 28 16:26:22] <--- SIP read from 212.147.65.170:8157 ---> ACK sip:0217211252@194.148.41.50;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK465200006e520000 From: "0625037902" ;tag=9cb30000f559ffff To: ;tag=as410fec7e Contact: Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65506 ACK User-Agent: Grandstream HT488 1.0.3.44 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 <-------------> [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: ACK sip:0217211252@194.148.41.50;user=phone SIP/2.0 (51) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK465200006e520000 (58) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "0625037902" ;tag=9cb30000f559ffff (81) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=as410fec7e (60) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (47) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 0f25000081b20000@10.0.0.102 (36) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 65506 ACK (15) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Length: 0 (17) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:26:22] --- (11 headers 0 lines) --- [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #36 [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '0f25000081b20000@10.0.0.102' of Response 65506: Match Not Found [Mar 28 16:26:22] <--- SIP read from 212.147.65.170:8157 ---> INVITE sip:0217211252@194.148.41.50;user=phone SIP/2.0 Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK37740000c0840000 From: "0625037902" ;tag=9cb30000f559ffff To: Contact: Supported: replaces Proxy-Authorization: Digest username="0625037902", realm="vtxvoip", algorithm=MD5, uri="sip:0217211252@194.148.41.50;user=phone", nonce="53e996b3", response="671a98efb214773c12233ba24ab9a7e4" Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65507 INVITE User-Agent: Grandstream HT488 1.0.3.44 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Content-Length: 303 v=0 o=0625037902 8000 8001 IN IP4 10.0.0.102 s=SIP Call c=IN IP4 10.0.0.102 t=0 0 m=audio 5004 RTP/AVP 0 8 4 18 2 97 a=sendrecv a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:18 G729/8000 a=rtpmap:2 G726-32/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=ptime:20 <-------------> [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: INVITE sip:0217211252@194.148.41.50;user=phone SIP/2.0 (54) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK37740000c0840000 (58) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "0625037902" ;tag=9cb30000f559ffff (81) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (45) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (47) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Supported: replaces (19) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Proxy-Authorization: Digest username="0625037902", realm="vtxvoip", algorithm=MD5, uri="sip:0217211252@194.148.41.50;user=phone", nonce="53e996b3", response="671a98efb214773c12233ba24ab9a7e4" (191) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Call-ID: 0f25000081b20000@10.0.0.102 (36) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: CSeq: 65507 INVITE (18) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Max-Forwards: 70 (16) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 13: Content-Length: 303 (19) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 14: (0) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: v=0 (3) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: o=0625037902 8000 8001 IN IP4 10.0.0.102 (40) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: s=SIP Call (10) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: c=IN IP4 10.0.0.102 (19) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: t=0 0 (5) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: m=audio 5004 RTP/AVP 0 8 4 18 2 97 (34) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=fmtp:97 mode=20 (17) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=ptime:20 (10) [Mar 28 16:26:22] --- (14 headers 15 lines) --- [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 28 16:26:22] Sending to 212.147.65.170 : 8157 (NAT) [Mar 28 16:26:22] Using INVITE request as basis request - 0f25000081b20000@10.0.0.102 [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2582 do_setnat: Setting NAT on RTP to On [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2592 do_setnat: Setting NAT on UDPTL to On [Mar 28 16:26:22] Found user '0625037902' [Mar 28 16:26:22] Found RTP audio format 0 [Mar 28 16:26:22] Found RTP audio format 8 [Mar 28 16:26:22] Found RTP audio format 4 [Mar 28 16:26:22] Found RTP audio format 18 [Mar 28 16:26:22] Found RTP audio format 2 [Mar 28 16:26:22] Found RTP audio format 97 [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4906 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 28 16:26:22] Peer audio RTP is at port 10.0.0.102:5004 [Mar 28 16:26:22] Found description format PCMU for ID 0 [Mar 28 16:26:22] Found description format PCMA for ID 8 [Mar 28 16:26:22] Found description format G723 for ID 4 [Mar 28 16:26:22] Found description format G729 for ID 18 [Mar 28 16:26:22] Found description format G726-32 for ID 2 [Mar 28 16:26:22] Found description format iLBC for ID 97 [Mar 28 16:26:22] Got unsupported a:fmtp in SDP offer [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel [Mar 28 16:26:22] Capabilities: us - 0x10e (gsm|ulaw|alaw|g729), peer - audio=0xd0d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0x10c (ulaw|alaw|g729) [Mar 28 16:26:22] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 28 16:26:22] Peer audio RTP is at port 10.0.0.102:5004 [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x10c (ulaw|alaw|g729) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:13408 handle_request_invite: Checking SIP call limits for device 0625037902 [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:3010 update_call_counter: Updating call counter for incoming call [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:3084 update_call_counter: Call from user '0625037902' is 1 out of 6 [Mar 28 16:26:22] Looking for 0217211252 in sipresidential (domain 194.148.41.50) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:3812 sip_new: *** Our native formats are 0x100 (g729) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:3813 sip_new: *** Joint capabilities are 0x10c (ulaw|alaw|g729) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:3814 sip_new: *** Our capabilities are 0x10e (gsm|ulaw|alaw|g729) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:3815 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:3838 sip_new: This channel will not be able to handle video. [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:7987 build_route: build_route: Contact hop: [Mar 28 16:26:22] list_route: hop: [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:13483 handle_request_invite: SIP/0625037902-00703dc0: New call is still down.... Trying... [Mar 28 16:26:22] <--- Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK37740000c0840000;received=212.147.65.170 From: "0625037902" ;tag=9cb30000f559ffff To: Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65507 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:26:22] DEBUG[18180]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902-00703dc0 [Mar 28 16:26:22] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:26:22] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:26:22] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 1 (Not in use) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Macro' [Mar 28 16:26:22] DEBUG[18187]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:1] Macro("SIP/0625037902-00703dc0", "screening|0217211252") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [s@macro-screening:1] NoOp("SIP/0625037902-00703dc0", "macro-screening: Start of screening macro") in new stack [Mar 28 16:26:22] DEBUG[18186]: func_strings.c:134 regex: FUNCTION REGEX (%23)(0217211252) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-screening:2] GotoIf("SIP/0625037902-00703dc0", "0?:get-header-info|1") in new stack [Mar 28 16:26:22] -- Goto (macro-screening,get-header-info,1) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '(null)' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:1] Set("SIP/0625037902-00703dc0", "HEADER_RPID=|_CNPN_PSTN_SCREENED=|_EMERGENCY_CALL=0") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:2] Set("SIP/0625037902-00703dc0", "HEADER_RPID=") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:3] Set("SIP/0625037902-00703dc0", "_RPID_CNPN=") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:4] Set("SIP/0625037902-00703dc0", "_RPID_CNPN_DOMAIN=") in new stack [Mar 28 16:26:22] DEBUG[18186]: func_strings.c:134 regex: FUNCTION REGEX (^.*privacy=full.*)() [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:5] Set("SIP/0625037902-00703dc0", "_RPID_CNPN_PI=0") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:6] GotoIf("SIP/0625037902-00703dc0", "0?:called") in new stack [Mar 28 16:26:22] -- Goto (macro-screening,get-header-info,9) [Mar 28 16:26:22] DEBUG[18186]: func_strings.c:134 regex: FUNCTION REGEX (^.*screen=pass.*)() [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:9] Set("SIP/0625037902-00703dc0", "_RPID_CNPN_SI=0") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0625037902' [Mar 28 16:26:22] DEBUG[18186]: func_strings.c:134 regex: FUNCTION REGEX (^.*anonymous.*)(0625037902) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:10] Set("SIP/0625037902-00703dc0", "_RPID_CNPN_PI=0") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:26:22] -- Executing [get-header-info@macro-screening:11] Goto("SIP/0625037902-00703dc0", "callfrom|1") in new stack [Mar 28 16:26:22] -- Goto (macro-screening,callfrom,1) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0625037902' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [callfrom@macro-screening:1] GotoIf("SIP/0625037902-00703dc0", "0?callfrom-pstn|1:callfrom-voip|1") in new stack [Mar 28 16:26:22] -- Goto (macro-screening,callfrom-voip,1) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [callfrom-voip@macro-screening:1] NoOp("SIP/0625037902-00703dc0", "macro-screening: Call from VOIP detected. Get all needed values from DB") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [callfrom-voip@macro-screening:2] Set("SIP/0625037902-00703dc0", "_PSTN_CALL=0") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [callfrom-voip@macro-screening:3] MYSQL("SIP/0625037902-00703dc0", "Connect connid 194.148.41.10 asterisk ast-business asterisk_db") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [callfrom-voip@macro-screening:4] GotoIf("SIP/0625037902-00703dc0", "1?no-rpid-detected|1:rpid-detected|1") in new stack [Mar 28 16:26:22] -- Goto (macro-screening,no-rpid-detected,1) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [no-rpid-detected@macro-screening:1] NoOp("SIP/0625037902-00703dc0", "macro-screening: No RPID detected or Transfered PSTN call. Using CALLERID(num) to verify and screen it") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [no-rpid-detected@macro-screening:2] GotoIf("SIP/0625037902-00703dc0", "1?get-info|1") in new stack [Mar 28 16:26:22] -- Goto (macro-screening,get-info,1) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0625037902' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:1] MYSQL("SIP/0625037902-00703dc0", "Query resultid 1 SELECT number,name,clid_flag,clid_number,language from number_options where number='0625037902'") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:2] MYSQL("SIP/0625037902-00703dc0", "Fetch fetchid 2 db_number db_name db_clid_flag db_clid_number db_language") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:3] MYSQL("SIP/0625037902-00703dc0", "Clear 2") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:4] NoOp("SIP/0625037902-00703dc0", "macro-screening: read values from DB: 0625037902 0 0625037902 fr") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:5] GotoIf("SIP/0625037902-00703dc0", "0?stopCall|1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:6] GotoIf("SIP/0625037902-00703dc0", "0?:noclid") in new stack [Mar 28 16:26:22] -- Goto (macro-screening,get-info,12) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:12] NoOp("SIP/0625037902-00703dc0", "macro-screening: clid_flag not set| will use mainnumber as screened number") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:13] Set("SIP/0625037902-00703dc0", "CALLERID(all)="" <0625037902>") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:14] Set("SIP/0625037902-00703dc0", "_CNPN_DDI=0625037902") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:26:22] -- Executing [get-info@macro-screening:15] Goto("SIP/0625037902-00703dc0", "endMacro|1") in new stack [Mar 28 16:26:22] -- Goto (macro-screening,endMacro,1) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [endMacro@macro-screening:1] MYSQL("SIP/0625037902-00703dc0", "Disconnect 1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [endMacro@macro-screening:2] Set("SIP/0625037902-00703dc0", "CHANNEL(language)=fr") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MacroExit' [Mar 28 16:26:22] -- Executing [endMacro@macro-screening:3] MacroExit("SIP/0625037902-00703dc0", "") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Macro' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:2] Macro("SIP/0625037902-00703dc0", "privacy|0217211252") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [s@macro-privacy:1] NoOp("SIP/0625037902-00703dc0", "macro-privacy: Start of privacy macro *31#/#31# or db") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0625037902' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [s@macro-privacy:2] Set("SIP/0625037902-00703dc0", "_CNPN_ANI=0625037902") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [s@macro-privacy:3] Set("SIP/0625037902-00703dc0", "db_clir=0") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-privacy:4] GotoIf("SIP/0625037902-00703dc0", "0?pi-allowed|1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-privacy:5] GotoIf("SIP/0625037902-00703dc0", "0?pi-prohib|1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-privacy:6] GotoIf("SIP/0625037902-00703dc0", "0?pi-allowed|1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-privacy:7] GotoIf("SIP/0625037902-00703dc0", "0?pi-prohib|1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-privacy:8] GotoIf("SIP/0625037902-00703dc0", "0?pi-allowed|1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-privacy:9] GotoIf("SIP/0625037902-00703dc0", "0?pi-prohib|1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-privacy:10] MYSQL("SIP/0625037902-00703dc0", "Connect connid 194.148.41.10 asterisk ast-business asterisk_db") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-privacy:11] MYSQL("SIP/0625037902-00703dc0", "Query resultid 1 SELECT clir,clid_flag,clid_number,name from number_options where number='0625037902'") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-privacy:12] MYSQL("SIP/0625037902-00703dc0", "Fetch fetchid 2 db_clir db_clid_flag db_clid_number db_name") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-privacy:13] MYSQL("SIP/0625037902-00703dc0", "Clear 2") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-privacy:14] MYSQL("SIP/0625037902-00703dc0", "Disconnect 1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:26:22] -- Executing [s@macro-privacy:15] Goto("SIP/0625037902-00703dc0", "end|1") in new stack [Mar 28 16:26:22] -- Goto (macro-privacy,end,1) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [end@macro-privacy:1] NoOp("SIP/0625037902-00703dc0", "macro-privacy: PI and CNPN_ANI saved| return to upper function") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MacroExit' [Mar 28 16:26:22] -- Executing [end@macro-privacy:2] MacroExit("SIP/0625037902-00703dc0", "") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Macro' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:3] Macro("SIP/0625037902-00703dc0", "check-registration|0217211252") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:1] NoOp("SIP/0625037902-00703dc0", "macro-check-registration: Start of macro check-registration| SERVER = voip-test-01") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:2] Set("SIP/0625037902-00703dc0", "_OUT_TRUNK=") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:3] MYSQL("SIP/0625037902-00703dc0", "Connect connid 194.148.41.10 asterisk ast-business asterisk_db") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:4] MYSQL("SIP/0625037902-00703dc0", "Query resultid 1 SELECT a.RegisteredTo from sip_users a,number_options b where b.number='0217211252' and a.name=b.sip_users_name limit 1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:5] MYSQL("SIP/0625037902-00703dc0", "Fetch fetchid 2 db_registered_server") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:6] MYSQL("SIP/0625037902-00703dc0", "Clear 2") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:7] MYSQL("SIP/0625037902-00703dc0", "Disconnect 1") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:8] NoOp("SIP/0625037902-00703dc0", "macro-check-registration: 0217211252 is registered on server "") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:9] GotoIf("SIP/0625037902-00703dc0", "1?test1") in new stack [Mar 28 16:26:22] -- Goto (macro-check-registration,s,13) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:13] GotoIf("SIP/0625037902-00703dc0", "1?end") in new stack [Mar 28 16:26:22] -- Goto (macro-check-registration,s,15) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MacroExit' [Mar 28 16:26:22] -- Executing [s@macro-check-registration:15] MacroExit("SIP/0625037902-00703dc0", "") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '5' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '6' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:4] GotoIf("SIP/0625037902-00703dc0", "1?5:6") in new stack [Mar 28 16:26:22] -- Goto (sipresidential,0217211252,5) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Gosub' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:5] Gosub("SIP/0625037902-00703dc0", "default|0217211252|1") in new stack [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '0217211252' AND context = 'default' AND priority = '1' [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '1' ORDER BY exten [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '0217211252' AND context = 'default' AND priority = '1' [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '1' ORDER BY exten [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'i' AND context = 'default' AND priority = '1' [Mar 28 16:26:22] -- Sent into invalid extension '0217211252' in context 'default' on SIP/0625037902-00703dc0 [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'i' AND context = 'default' AND priority = '1' [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'i' AND context = 'default' AND priority = '1' [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'i' AND context = 'default' AND priority = '1' [Mar 28 16:26:22] -- Executing Macro("SIP/0625037902-00703dc0", "nullroute|0217211252") [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:1] NoOp("SIP/0625037902-00703dc0", ""Invalid number dialed (0217211252)"") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:2] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:3] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:4] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:5] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:6] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:7] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:8] NoOp("SIP/0625037902-00703dc0", ""Checking blocked shortnumbers"") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:9] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:10] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:11] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:12] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:13] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:14] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:15] GotoIf("SIP/0625037902-00703dc0", "0?invalid") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'MacroExit' [Mar 28 16:26:22] -- Executing [s@macro-nullroute:16] MacroExit("SIP/0625037902-00703dc0", "") in new stack [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'i' AND context = 'default' AND priority = '2' [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'i' AND context = 'default' AND priority = '2' [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:22] DEBUG[18186]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'i' AND context = 'default' AND priority = '2' [Mar 28 16:26:22] -- Executing Return("SIP/0625037902-00703dc0", "") [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:6] NoOp("SIP/0625037902-00703dc0", "Reverse CLI to original value for PSTN calls if its a PSTN call RealNumber=, OUT_TRUNK=, EMERGENCY_CALL=0") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0625037902' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:7] Set("SIP/0625037902-00703dc0", "CALLERID(all)= <>") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '9' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:8] GotoIf("SIP/0625037902-00703dc0", "0?15:9") in new stack [Mar 28 16:26:22] -- Goto (sipresidential,0217211252,9) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '10' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:9] GotoIf("SIP/0625037902-00703dc0", "0?12:10") in new stack [Mar 28 16:26:22] -- Goto (sipresidential,0217211252,10) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:10] Set("SIP/0625037902-00703dc0", "CALLERID(all)="0625037902" <00090041625037902>") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:11] Goto("SIP/0625037902-00703dc0", "30") in new stack [Mar 28 16:26:22] -- Goto (sipresidential,0217211252,30) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:30] NoOp("SIP/0625037902-00703dc0", "") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '34' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '32' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:31] GotoIf("SIP/0625037902-00703dc0", "0?34:32") in new stack [Mar 28 16:26:22] -- Goto (sipresidential,0217211252,32) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:32] Set("SIP/0625037902-00703dc0", "EXTEN_NEW=00090041217211252") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '35' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:33] Goto("SIP/0625037902-00703dc0", "35") in new stack [Mar 28 16:26:22] -- Goto (sipresidential,0217211252,35) [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'SetCallerPres' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:35] SetCallerPres("SIP/0625037902-00703dc0", "allowed_passed_screen") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '37' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:36] GotoIf("SIP/0625037902-00703dc0", "1?37:50") in new stack [Mar 28 16:26:22] -- Goto (sipresidential,0217211252,37) [Mar 28 16:26:22] DEBUG[18186]: func_rand.c:71 acf_rand_exec: 48 was the lucky number in range [0,99] [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '48' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:37] GotoIf("SIP/0625037902-00703dc0", "0?40") in new stack [Mar 28 16:26:22] DEBUG[18186]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:26:22] DEBUG[18186]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Mar 28 16:26:22] -- Executing [0217211252@sipresidential:38] Dial("SIP/0625037902-00703dc0", "sip/00090041217211252@sip_trunk_gva-mg-01") in new stack [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:15317 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:2628 create_addr_from_peer: Our T38 capability (3856) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:2582 do_setnat: Setting NAT on RTP to Off [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:2592 do_setnat: Setting NAT on UDPTL to Off [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:3812 sip_new: *** Our native formats are 0x100 (g729) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:3813 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:3814 sip_new: *** Our capabilities are 0x108 (alaw|g729) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:3815 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:3817 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:3838 sip_new: This channel will not be able to handle video. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-38. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-37. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-36. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-35. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-33. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable EXTEN_NEW. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-32. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-31. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-30. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-11. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-10. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-9. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-8. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-7. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-6. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-16. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-15. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-14. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-13. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-12. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-11. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-10. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-9. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-8. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-7. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-6. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-5. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-4. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-3. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-nullroute-s-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable INVALID_EXTEN. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-5. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-4. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-15. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-13. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-9. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-8. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MYSQL_STATUS. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-7. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-6. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable fetchid. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_registered_server. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-5. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable resultid. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-4. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable connid. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-3. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable OUT_TRUNK. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-3. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-end-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-end-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-15. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-14. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-13. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_name. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_clid_number. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_clid_flag. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_clir. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-12. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-11. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-10. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-9. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-8. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-7. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-6. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-5. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-4. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-3. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable CNPN_ANI. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-endMacro-3. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-endMacro-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-endMacro-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-15. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable CNPN_DDI. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-14. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-13. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-12. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-6. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-5. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-4. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-3. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_language. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_number. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-info-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-no-rpid-detected-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-no-rpid-detected-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-voip-4. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-voip-3. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable PSTN_CALL. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-voip-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-voip-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-11. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable RPID_CNPN_PI. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-10. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable RPID_CNPN_SI. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-9. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-6. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-5. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable RPID_CNPN_DOMAIN. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-4. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable RPID_CNPN. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-3. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable HEADER_RPID. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable EMERGENCY_CALL. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable CNPN_PSTN_SCREENED. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-s-2. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-s-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-sipresidential-0217211252-1. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 28 16:26:22] DEBUG[18186]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:2837 sip_call: Outgoing Call for 00090041217211252 [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:3010 update_call_counter: Updating call counter for outgoing call [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:2852 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:6195 add_sdp: ** Our capability: 0x108 (alaw|g729) Video flag: False [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:6196 add_sdp: ** Our prefcodec: 0x100 (g729) [Mar 28 16:26:22] Audio is at 194.148.41.50 port 12834 [Mar 28 16:26:22] Adding codec 0x100 (g729) to SDP [Mar 28 16:26:22] Adding codec 0x8 (alaw) to SDP [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:6327 add_sdp: -- Done with adding codecs to SDP [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:6372 add_sdp: Done building SDP. Settling with this capability: 0x108 (alaw|g729) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 0: INVITE sip:00090041217211252@212.147.20.222 SIP/2.0 (51) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea (58) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 2: From: "0625037902" ;tag=as698ff048 (71) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 3: To: (42) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 4: Contact: (46) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 (55) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 9: Date: Wed, 28 Mar 2007 14:26:22 GMT (35) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 11: Supported: replaces (19) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 13: Content-Length: 233 (19) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4580 parse_request: Header 14: (0) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: v=0 (3) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: o=root 18152 18152 IN IP4 194.148.41.50 (39) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: s=session (9) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: c=IN IP4 194.148.41.50 (22) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: t=0 0 (5) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: m=audio 12834 RTP/AVP 18 8 (26) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: a=fmtp:18 annexb=no (19) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: a=ptime:20 (10) [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:26:22] Reliably Transmitting (no NAT) to 212.147.20.222:5060: INVITE sip:00090041217211252@212.147.20.222 SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea From: "0625037902" ;tag=as698ff048 To: Contact: Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 CSeq: 102 INVITE User-Agent: VTX SIP Max-Forwards: 70 Date: Wed, 28 Mar 2007 14:26:22 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 233 v=0 o=root 18152 18152 IN IP4 194.148.41.50 s=session c=IN IP4 194.148.41.50 t=0 0 m=audio 12834 RTP/AVP 18 8 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 28 16:26:22] DEBUG[18186]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #38 [Mar 28 16:26:22] -- Called 00090041217211252@sip_trunk_gva-mg-01 [Mar 28 16:26:22] <--- SIP read from 212.147.20.222:5060 ---> SIP/2.0 100 Trying Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 CSeq: 102 INVITE From: "0625037902" ;tag=as698ff048 To: ;tag=23445c923bdde5b Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea Content-Length: 0 User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 <-------------> [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 (55) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: From: "0625037902" ;tag=as698ff048 (71) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: To: ;tag=23445c923bdde5b (62) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea (58) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Content-Length: 0 (17) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 (53) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: (0) [Mar 28 16:26:22] --- (8 headers 0 lines) --- [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #38 - INVITE (got response) [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50' Request 102: Found [Mar 28 16:26:22] DEBUG[18180]: chan_sip.c:11648 handle_response_invite: SIP response 100 to standard invite [Mar 28 16:26:23] <--- SIP read from 212.147.20.222:5060 ---> SIP/2.0 183 Session Progress Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 CSeq: 102 INVITE From: "0625037902" ;tag=as698ff048 To: ;tag=23445c923bdde5b Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea Content-Length: 0 Contact: sip:00090041217211252@212.147.20.222:5060 User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 <-------------> [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 183 Session Progress (28) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 (55) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: From: "0625037902" ;tag=as698ff048 (71) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: To: ;tag=23445c923bdde5b (62) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea (58) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Content-Length: 0 (17) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Contact: sip:00090041217211252@212.147.20.222:5060 (50) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 (53) [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:26:23] --- (9 headers 0 lines) --- [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50' Request 102: Found [Mar 28 16:26:23] DEBUG[18180]: chan_sip.c:11648 handle_response_invite: SIP response 183 to standard invite [Mar 28 16:26:26] <--- SIP read from 212.40.9.10:5060 ---> OPTIONS sip:212.40.9.9:5060 SIP/2.0 Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK25990d6e Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=20cdaf94 Call-ID: 0000213e460a7778@bigip.vtx.ch CSeq: 1175091064 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK25990d6e (57) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=20cdaf94 (45) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 0000213e460a7778@bigip.vtx.ch (38) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091064 OPTIONS (24) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:26:26] --- (9 headers 0 lines) --- [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 0000213e460a7778@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:26:26] Looking for s in default (domain 212.40.9.9) [Mar 28 16:26:26] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:26] DEBUG[18180]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 's' AND context = 'default' AND priority = '1' [Mar 28 16:26:26] <--- Transmitting (no NAT) to 212.40.9.10:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK25990d6e;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=20cdaf94 To: sip:212.40.9.9;tag=as37e1541e Call-ID: 0000213e460a7778@bigip.vtx.ch CSeq: 1175091064 OPTIONS User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Mar 28 16:26:26] Scheduling destruction of SIP dialog '0000213e460a7778@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) [Mar 28 16:26:26] <--- SIP read from 212.147.20.222:5060 ---> SIP/2.0 180 Ringing Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 CSeq: 102 INVITE From: "0625037902" ;tag=as698ff048 To: ;tag=23445c923bdde5b Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea Content-Length: 193 Content-Type: application/sdp Contact: sip:00090041217211252@212.147.20.222:5060 User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 v=0 o=MxSIP 0 26383 IN IP4 212.147.20.222 s=SIP Call c=IN IP4 212.147.20.222 t=0 0 m=audio 5278 RTP/AVP 18 8 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=fmtp:18 annexb=no a=sendrecv <-------------> [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 (55) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: From: "0625037902" ;tag=as698ff048 (71) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: To: ;tag=23445c923bdde5b (62) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea (58) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Content-Length: 193 (19) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Content-Type: application/sdp (29) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Contact: sip:00090041217211252@212.147.20.222:5060 (50) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 (53) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: (0) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: v=0 (3) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: o=MxSIP 0 26383 IN IP4 212.147.20.222 (37) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: s=SIP Call (10) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: c=IN IP4 212.147.20.222 (23) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: t=0 0 (5) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: m=audio 5278 RTP/AVP 18 8 (25) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=fmtp:18 annexb=no (19) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:26:26] --- (10 headers 10 lines) --- [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50' Request 102: Found [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:11648 handle_response_invite: SIP response 180 to standard invite [Mar 28 16:26:26] DEBUG[18180]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sip_trunk_gva-mg-01-0071b7a0 [Mar 28 16:26:26] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sip_trunk_gva-mg-01 [Mar 28 16:26:26] Found RTP audio format 18 [Mar 28 16:26:26] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer sip_trunk_gva-mg-01 [Mar 28 16:26:26] Found RTP audio format 8 [Mar 28 16:26:26] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/sip_trunk_gva-mg-01 - state 1 (Not in use) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:4906 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 28 16:26:26] Peer audio RTP is at port 212.147.20.222:5278 [Mar 28 16:26:26] Found description format G729 for ID 18 [Mar 28 16:26:26] DEBUG[18188]: app_queue.c:546 changethread: Device 'SIP/sip_trunk_gva-mg-01' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:26] Found description format PCMA for ID 8 [Mar 28 16:26:26] Got unsupported a:fmtp in SDP offer [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/sip_trunk_gva-mg-01-0071b7a0 [Mar 28 16:26:26] Capabilities: us - 0x108 (alaw|g729), peer - audio=0x108 (alaw|g729)/video=0x0 (nothing), combined - 0x108 (alaw|g729) [Mar 28 16:26:26] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 28 16:26:26] Peer audio RTP is at port 212.147.20.222:5278 [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x108 (alaw|g729) [Mar 28 16:26:26] DEBUG[18180]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Mar 28 16:26:26] -- SIP/sip_trunk_gva-mg-01-0071b7a0 is ringing [Mar 28 16:26:26] <--- Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK37740000c0840000;received=212.147.65.170 From: "0625037902" ;tag=9cb30000f559ffff To: ;tag=as25d5b943 Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65507 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:26:26] -- Call on SIP/sip_trunk_gva-mg-01-0071b7a0 left from hold [Mar 28 16:26:26] -- SIP/sip_trunk_gva-mg-01-0071b7a0 is making progress passing it to SIP/0625037902-00703dc0 [Mar 28 16:26:26] DEBUG[18186]: chan_sip.c:6427 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 28 16:26:26] DEBUG[18186]: chan_sip.c:6195 add_sdp: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: True [Mar 28 16:26:26] DEBUG[18186]: chan_sip.c:6196 add_sdp: ** Our prefcodec: 0x0 (nothing) [Mar 28 16:26:26] Audio is at 194.148.41.50 port 12180 [Mar 28 16:26:26] Adding codec 0x100 (g729) to SDP [Mar 28 16:26:26] Adding codec 0x8 (alaw) to SDP [Mar 28 16:26:26] Adding codec 0x4 (ulaw) to SDP [Mar 28 16:26:26] DEBUG[18186]: chan_sip.c:6327 add_sdp: -- Done with adding codecs to SDP [Mar 28 16:26:26] DEBUG[18186]: chan_sip.c:6372 add_sdp: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729) [Mar 28 16:26:26] <--- Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 183 Session Progress Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK37740000c0840000;received=212.147.65.170 From: "0625037902" ;tag=9cb30000f559ffff To: ;tag=as25d5b943 Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65507 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 257 v=0 o=root 18152 18152 IN IP4 194.148.41.50 s=session c=IN IP4 194.148.41.50 t=0 0 m=audio 12180 RTP/AVP 18 8 0 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Mar 28 16:26:26] DEBUG[18186]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to g729 [Mar 28 16:26:26] DEBUG[18186]: rtp.c:2706 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Mar 28 16:26:26] DEBUG[18186]: rtp.c:1151 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 212.147.65.170:12691 [Mar 28 16:26:26] DEBUG[18186]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to g729 [Mar 28 16:26:26] DEBUG[18186]: rtp.c:2706 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Mar 28 16:26:27] <--- SIP read from 212.147.0.191:11840 ---> <-------------> [Mar 28 16:26:27] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: (0) [Mar 28 16:26:27] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: (0) [Mar 28 16:26:27] --- (0 headers 1 lines) --- [Mar 28 16:26:27] DEBUG[18186]: rtp.c:873 ast_rtcp_read: Got RTCP report of 80 bytes [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog '00002126460a775a@bigip.vtx.ch' [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:3116 sip_destroy: Destroying SIP dialog 00002126460a775a@bigip.vtx.ch [Mar 28 16:26:28] Really destroying SIP dialog '00002126460a775a@bigip.vtx.ch' Method: OPTIONS [Mar 28 16:26:28] <--- SIP read from 212.147.20.222:5060 ---> SIP/2.0 200 OK Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 CSeq: 102 INVITE From: "0625037902" ;tag=as698ff048 To: ;tag=23445c923bdde5b Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea Content-Length: 193 Content-Type: application/sdp Supported: replaces Contact: sip:00090041217211252@212.147.20.222:5060 User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 v=0 o=MxSIP 0 26383 IN IP4 212.147.20.222 s=SIP Call c=IN IP4 212.147.20.222 t=0 0 m=audio 5278 RTP/AVP 18 8 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=fmtp:18 annexb=no a=sendrecv <-------------> [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 (55) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: CSeq: 102 INVITE (16) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: From: "0625037902" ;tag=as698ff048 (71) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: To: ;tag=23445c923bdde5b (62) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK05f8f8ea (58) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Content-Length: 193 (19) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Content-Type: application/sdp (29) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Supported: replaces (19) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Contact: sip:00090041217211252@212.147.20.222:5060 (50) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 (53) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: v=0 (3) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: o=MxSIP 0 26383 IN IP4 212.147.20.222 (37) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: s=SIP Call (10) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: c=IN IP4 212.147.20.222 (23) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: t=0 0 (5) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: m=audio 5278 RTP/AVP 18 8 (25) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=fmtp:18 annexb=no (19) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:26:28] --- (11 headers 10 lines) --- [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:11648 handle_response_invite: SIP response 200 to standard invite [Mar 28 16:26:28] Found RTP audio format 18 [Mar 28 16:26:28] Found RTP audio format 8 [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4906 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 28 16:26:28] Peer audio RTP is at port 212.147.20.222:5278 [Mar 28 16:26:28] Found description format G729 for ID 18 [Mar 28 16:26:28] Found description format PCMA for ID 8 [Mar 28 16:26:28] Got unsupported a:fmtp in SDP offer [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/sip_trunk_gva-mg-01-0071b7a0 [Mar 28 16:26:28] Capabilities: us - 0x108 (alaw|g729), peer - audio=0x108 (alaw|g729)/video=0x0 (nothing), combined - 0x108 (alaw|g729) [Mar 28 16:26:28] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 28 16:26:28] Peer audio RTP is at port 212.147.20.222:5278 [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x108 (alaw|g729) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:3010 update_call_counter: Updating call counter for outgoing call [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:7987 build_route: build_route: Contact hop: sip:00090041217211252@212.147.20.222:5060 [Mar 28 16:26:28] list_route: hop: [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:5650 reqprep: Strict routing enforced for session 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 [Mar 28 16:26:28] set_destination: Parsing for address/port to send to [Mar 28 16:26:28] set_destination: set destination to 212.147.20.222, port 5060 [Mar 28 16:26:28] Transmitting (no NAT) to 212.147.20.222:5060: ACK sip:00090041217211252@212.147.20.222:5060 SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK0ded6288 From: "0625037902" ;tag=as698ff048 To: ;tag=23445c923bdde5b Contact: Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 CSeq: 102 ACK User-Agent: VTX SIP Max-Forwards: 70 Content-Length: 0 --- [Mar 28 16:26:28] -- Call on SIP/sip_trunk_gva-mg-01-0071b7a0 left from hold [Mar 28 16:26:28] DEBUG[18186]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sip_trunk_gva-mg-01-0071b7a0 [Mar 28 16:26:28] -- SIP/sip_trunk_gva-mg-01-0071b7a0 answered SIP/0625037902-00703dc0 [Mar 28 16:26:28] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sip_trunk_gva-mg-01 [Mar 28 16:26:28] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer sip_trunk_gva-mg-01 [Mar 28 16:26:28] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/sip_trunk_gva-mg-01 - state 1 (Not in use) [Mar 28 16:26:28] DEBUG[18189]: app_queue.c:546 changethread: Device 'SIP/sip_trunk_gva-mg-01' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:28] DEBUG[18186]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902-00703dc0 [Mar 28 16:26:28] DEBUG[18186]: chan_sip.c:3470 sip_answer: SIP answering channel: SIP/0625037902-00703dc0 [Mar 28 16:26:28] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:26:28] DEBUG[18186]: chan_sip.c:6427 transmit_response_with_sdp: Setting framing from config on incoming call [Mar 28 16:26:28] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:26:28] DEBUG[18186]: chan_sip.c:6195 add_sdp: ** Our capability: 0x10c (ulaw|alaw|g729) Video flag: True [Mar 28 16:26:28] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 1 (Not in use) [Mar 28 16:26:28] DEBUG[18186]: chan_sip.c:6196 add_sdp: ** Our prefcodec: 0x0 (nothing) [Mar 28 16:26:28] Audio is at 194.148.41.50 port 12180 [Mar 28 16:26:28] DEBUG[18190]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:28] Adding codec 0x100 (g729) to SDP [Mar 28 16:26:28] Adding codec 0x8 (alaw) to SDP [Mar 28 16:26:28] Adding codec 0x4 (ulaw) to SDP [Mar 28 16:26:28] DEBUG[18186]: chan_sip.c:6327 add_sdp: -- Done with adding codecs to SDP [Mar 28 16:26:28] DEBUG[18186]: chan_sip.c:6372 add_sdp: Done building SDP. Settling with this capability: 0x10c (ulaw|alaw|g729) [Mar 28 16:26:28] <--- Reliably Transmitting (NAT) to 212.147.65.170:8157 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bK37740000c0840000;received=212.147.65.170 From: "0625037902" ;tag=9cb30000f559ffff To: ;tag=as25d5b943 Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65507 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 257 v=0 o=root 18152 18153 IN IP4 194.148.41.50 s=session c=IN IP4 194.148.41.50 t=0 0 m=audio 12180 RTP/AVP 18 8 0 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Mar 28 16:26:28] DEBUG[18186]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #43 [Mar 28 16:26:28] DEBUG[18186]: rtp.c:2706 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Mar 28 16:26:28] <--- SIP read from 212.147.65.170:8157 ---> ACK sip:0217211252@194.148.41.50 SIP/2.0 Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bKc2b300000a4cffff From: "0625037902" ;tag=9cb30000f559ffff To: ;tag=as25d5b943 Contact: Proxy-Authorization: Digest username="0625037902", realm="vtxvoip", algorithm=MD5, uri="sip:0217211252@194.148.41.50", nonce="53e996b3", response="52c599c47c020008c0374b608b8ca9d2" Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 65507 ACK User-Agent: Grandstream HT488 1.0.3.44 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Length: 0 <-------------> [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: ACK sip:0217211252@194.148.41.50 SIP/2.0 (40) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 10.0.0.102;branch=z9hG4bKc2b300000a4cffff (58) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "0625037902" ;tag=9cb30000f559ffff (81) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=as25d5b943 (60) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (47) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Proxy-Authorization: Digest username="0625037902", realm="vtxvoip", algorithm=MD5, uri="sip:0217211252@194.148.41.50", nonce="53e996b3", response="52c599c47c020008c0374b608b8ca9d2" (180) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 0f25000081b20000@10.0.0.102 (36) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: CSeq: 65507 ACK (15) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Max-Forwards: 70 (16) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 0 (17) [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:26:28] --- (12 headers 0 lines) --- [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #43 [Mar 28 16:26:28] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '0f25000081b20000@10.0.0.102' of Response 65507: Match Not Found [Mar 28 16:26:30] <--- SIP read from 212.147.65.170:8157 ---> <-------------> [Mar 28 16:26:30] --- (0 headers 0 lines) Nat keepalive --- [Mar 28 16:26:31] <--- SIP read from 212.40.9.10:5060 ---> OPTIONS sip:212.40.9.9:5060 SIP/2.0 Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK5c9fcf09 Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=738ac641 Call-ID: 00002142460a777d@bigip.vtx.ch CSeq: 1175091069 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK5c9fcf09 (57) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=738ac641 (45) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 00002142460a777d@bigip.vtx.ch (38) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091069 OPTIONS (24) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:26:31] --- (9 headers 0 lines) --- [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 00002142460a777d@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:26:31] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:26:31] Looking for s in default (domain 212.40.9.9) [Mar 28 16:26:31] DEBUG[18180]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:26:31] DEBUG[18180]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 's' AND context = 'default' AND priority = '1' [Mar 28 16:26:31] <--- Transmitting (no NAT) to 212.40.9.10:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK5c9fcf09;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=738ac641 To: sip:212.40.9.9;tag=as6e4c7661 Call-ID: 00002142460a777d@bigip.vtx.ch CSeq: 1175091069 OPTIONS User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Mar 28 16:26:31] Scheduling destruction of SIP dialog '00002142460a777d@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) [Mar 28 16:26:32] <--- SIP read from 212.147.20.222:5060 ---> BYE sip:00090041625037902@194.148.41.50 SIP/2.0 Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bKf25dc553b Max-Forwards: 70 Content-Length: 0 To: "0625037902" ;tag=as698ff048 From: ;tag=23445c923bdde5b Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 CSeq: 98724418 BYE Supported: timer Supported: replaces User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 <-------------> [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: BYE sip:00090041625037902@194.148.41.50 SIP/2.0 (47) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bKf25dc553b (60) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 70 (16) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: Content-Length: 0 (17) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: To: "0625037902" ;tag=as698ff048 (69) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: From: ;tag=23445c923bdde5b (64) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 (55) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: CSeq: 98724418 BYE (18) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Supported: timer (16) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Supported: replaces (19) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 (53) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:26:32] --- (11 headers 0 lines) --- [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:14640 handle_request: **** Received BYE (8) - Command in SIP BYE [Mar 28 16:26:32] Sending to 212.147.20.222 : 5060 (no NAT) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:14197 handle_request_bye: Received bye, issuing owner hangup [Mar 28 16:26:32] <--- Transmitting (no NAT) to 212.147.20.222:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bKf25dc553b;received=212.147.20.222 From: ;tag=23445c923bdde5b To: "0625037902" ;tag=as698ff048 Call-ID: 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50 CSeq: 98724418 BYE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:26:32] DEBUG[18186]: channel.c:3800 ast_generic_bridge: Didn't get a frame from channel: SIP/sip_trunk_gva-mg-01-0071b7a0 [Mar 28 16:26:32] DEBUG[18186]: channel.c:4118 ast_channel_bridge: Bridge stops bridging channels SIP/0625037902-00703dc0 and SIP/sip_trunk_gva-mg-01-0071b7a0 [Mar 28 16:26:32] DEBUG[18186]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/sip_trunk_gva-mg-01-0071b7a0' [Mar 28 16:26:32] DEBUG[18186]: chan_sip.c:3319 sip_hangup: Hangup call SIP/sip_trunk_gva-mg-01-0071b7a0, SIP callid 3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50) [Mar 28 16:26:32] DEBUG[18186]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/sip_trunk_gva-mg-01-0071b7a0 [Mar 28 16:26:32] DEBUG[18186]: rtp.c:1476 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Mar 28 16:26:32] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - sip_trunk_gva-mg-01 [Mar 28 16:26:32] DEBUG[18186]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Mar 28 16:26:32] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer sip_trunk_gva-mg-01 [Mar 28 16:26:32] DEBUG[18186]: pbx.c:2393 __ast_pbx_run: Spawn extension (sipresidential,0217211252,38) exited non-zero on 'SIP/0625037902-00703dc0' [Mar 28 16:26:32] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/sip_trunk_gva-mg-01 - state 1 (Not in use) [Mar 28 16:26:32] == Spawn extension (sipresidential, 0217211252, 38) exited non-zero on 'SIP/0625037902-00703dc0' [Mar 28 16:26:32] DEBUG[18191]: app_queue.c:546 changethread: Device 'SIP/sip_trunk_gva-mg-01' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"0625037902" <00090041625037902>' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '00090041625037902' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0217211252' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'sipresidential' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/0625037902-00703dc0' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/sip_trunk_gva-mg-01-0071b7a0' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'sip/00090041217211252@sip_trunk_gva-mg-01' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-28 16:26:22' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-28 16:26:28' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-28 16:26:32' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '10' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '4' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175091982.0' [Mar 28 16:26:32] DEBUG[18186]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 28 16:26:32] Scheduling destruction of SIP dialog '7c8268706bd6bc28107bda7d1cd87d2f@194.148.41.50' in 6400 ms (Method: NOTIFY) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: NOTIFY sip:0625037901@212.147.0.191:11840;rinstance=62d70f12da108d78 SIP/2.0 (76) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK3935afff;rport (64) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as53273d0c (60) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: (67) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:26:32] DEBUG[18186]: cdr_addon_mysql.c:210 mysql_log: cdr_mysql: inserting a CDR record. [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 7c8268706bd6bc28107bda7d1cd87d2f@194.148.41.50 (55) [Mar 28 16:26:32] DEBUG[18186]: 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,userfield) VALUES ('2007-03-28 16:26:22','\"0625037902\" <00090041625037902>','00090041625037902','0217211252','sipresidential', 'SIP/0625037902-00703dc0','SIP/sip_trunk_gva-mg-01-0071b7a0','Dial','sip/00090041217211252@sip_trunk_gva-mg-01',10,4,'ANSWERED',3,'','') [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Event: message-summary (22) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 93 (18) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Messages-Waiting: no (20) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Message-Account: sip:asterisk@194.148.41.50 (43) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4612 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 28 16:26:32] Reliably Transmitting (NAT) to 212.147.0.191:11840: NOTIFY sip:0625037901@212.147.0.191:11840;rinstance=62d70f12da108d78 SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK3935afff;rport From: "asterisk" ;tag=as53273d0c To: Contact: Call-ID: 7c8268706bd6bc28107bda7d1cd87d2f@194.148.41.50 CSeq: 102 NOTIFY User-Agent: VTX SIP Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 93 Messages-Waiting: no Message-Account: sip:asterisk@194.148.41.50 Voice-Message: 0/0 (0/0) --- [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #46 [Mar 28 16:26:32] DEBUG[18186]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/0625037902-00703dc0' [Mar 28 16:26:32] DEBUG[18186]: chan_sip.c:3319 sip_hangup: Hangup call SIP/0625037902-00703dc0, SIP callid 0f25000081b20000@10.0.0.102) [Mar 28 16:26:32] DEBUG[18186]: chan_sip.c:3328 sip_hangup: update_call_counter(0625037902) - decrement call limit counter on hangup [Mar 28 16:26:32] DEBUG[18186]: chan_sip.c:3010 update_call_counter: Updating call counter for incoming call [Mar 28 16:26:32] DEBUG[18186]: chan_sip.c:3058 update_call_counter: Call from user '0625037902' removed from call limit 6 [Mar 28 16:26:32] Scheduling destruction of SIP dialog '0f25000081b20000@10.0.0.102' in 32000 ms (Method: ACK) [Mar 28 16:26:32] DEBUG[18186]: chan_sip.c:5650 reqprep: Strict routing enforced for session 0f25000081b20000@10.0.0.102 [Mar 28 16:26:32] set_destination: Parsing for address/port to send to [Mar 28 16:26:32] set_destination: set destination to 10.0.0.102, port 5060 [Mar 28 16:26:32] Reliably Transmitting (NAT) to 212.147.65.170:8157: BYE sip:0625037902@10.0.0.102;user=phone SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK26752e88;rport From: ;tag=as25d5b943 To: "0625037902" ;tag=9cb30000f559ffff Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 102 BYE User-Agent: VTX SIP Max-Forwards: 70 Content-Length: 0 --- [Mar 28 16:26:32] DEBUG[18186]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #48 [Mar 28 16:26:32] DEBUG[18186]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902-00703dc0 [Mar 28 16:26:32] DEBUG[18157]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:26:32] DEBUG[18157]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:26:32] DEBUG[18157]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 1 (Not in use) [Mar 28 16:26:32] DEBUG[18192]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 28 16:26:32] Really destroying SIP dialog '3fc2500f52892e45796b6a4e054ffbc4@194.148.41.50' Method: BYE [Mar 28 16:26:32] <--- SIP read from 212.147.65.170:8157 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK26752e88;rport From: ;tag=as25d5b943 To: "0625037902" ;tag=9cb30000f559ffff Call-ID: 0f25000081b20000@10.0.0.102 CSeq: 102 BYE User-Agent: Grandstream HT488 1.0.3.44 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Supported: replaces Content-Length: 0 <-------------> [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK26752e88;rport (64) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: From: ;tag=as25d5b943 (62) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: "0625037902" ;tag=9cb30000f559ffff (79) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 0f25000081b20000@10.0.0.102 (36) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: CSeq: 102 BYE (13) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: Contact: (47) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: Supported: replaces (19) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 10: Content-Length: 0 (17) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:26:32] --- (11 headers 0 lines) --- [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #48 [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '0f25000081b20000@10.0.0.102' of Request 102: Match Not Found [Mar 28 16:26:32] SIP Response message for INCOMING dialog BYE arrived [Mar 28 16:26:32] Really destroying SIP dialog '0f25000081b20000@10.0.0.102' Method: ACK [Mar 28 16:26:32] <--- SIP read from 212.147.0.191:11840 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK3935afff;rport=5060 Contact: To: ;tag=084fe91d From: "asterisk";tag=as53273d0c Call-ID: 7c8268706bd6bc28107bda7d1cd87d2f@194.148.41.50 CSeq: 102 NOTIFY User-Agent: eyeBeam release 1003l stamp 30936 Content-Length: 0 <-------------> [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK3935afff;rport=5060 (69) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 2: Contact: (33) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=084fe91d (80) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 4: From: "asterisk";tag=as53273d0c (59) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 7c8268706bd6bc28107bda7d1cd87d2f@194.148.41.50 (55) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 7: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:26:32] --- (9 headers 0 lines) --- [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #46 [Mar 28 16:26:32] DEBUG[18180]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '7c8268706bd6bc28107bda7d1cd87d2f@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:26:32] Really destroying SIP dialog '7c8268706bd6bc28107bda7d1cd87d2f@194.148.41.50' Method: NOTIFY s[Mar 28 16:26:33] DEBUG[18180]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog '0000212a460a775f@bigip.vtx.ch' [Mar 28 16:26:33] DEBUG[18180]: chan_sip.c:3116 sip_destroy: Destroying SIP dialog 0000212a460a775f@bigip.vtx.ch [Mar 28 16:26:33] Really destroying SIP dialog '0000212a460a775f@bigip.vtx.ch' Method: OPTIONS top now [Mar 28 16:26:35] Beginning asterisk shutdown.... [Mar 28 16:26:35] Executing last minute cleanups [Mar 28 16:26:35] == Destroying musiconhold processes [Mar 28 16:26:35] DEBUG[18152]: res_musiconhold.c:1125 ast_moh_destroy: killing 18159! [Mar 28 16:26:35] DEBUG[18152]: res_musiconhold.c:1139 ast_moh_destroy: mpg123 pid 18159 and child died after 65536 bytes read [Mar 28 16:26:35] Asterisk cleanly ending (0). [Mar 28 16:26:35] DEBUG[18152]: asterisk.c:1276 quit_handler: Asterisk ending (0).