*CLI> [Mar 28 16:27:15] <--- 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-fe29ea722c38686e-1--d87543-;rport Max-Forwards: 70 Contact: To: "0625037901" From: "0625037901";tag=2477442c Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 7 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:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: REGISTER sip:194.148.41.50 SIP/2.0 (34) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-fe29ea722c38686e-1--d87543-;rport (91) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 70 (16) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: Contact: (72) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: To: "0625037901" (46) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: From: "0625037901";tag=2477442c (61) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. (69) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: CSeq: 7 REGISTER (16) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Expires: 60 (11) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:27:15] DEBUG[18254]: 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:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 13: (0) [Mar 28 16:27:15] --- (13 headers 0 lines) --- [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. - REGISTER (No RTP) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 28 16:27:15] Using latest REGISTER request as basis request [Mar 28 16:27:15] Sending to 212.147.0.191 : 11840 (NAT) [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '0625037901' [Mar 28 16:27:15] DEBUG[18254]: 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:27:15] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Mar 28 16:27:15] DEBUG[18254]: 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:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK58259c8e;rport (64) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as0e80e73d (60) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: (67) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 5d356e3544c12b02754778604f9f3f29@194.148.41.50 (55) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Date: Wed, 28 Mar 2007 14:27:15 GMT (35) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: Supported: replaces (19) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:27:15] 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=z9hG4bK58259c8e;rport From: "asterisk" ;tag=as0e80e73d To: Contact: Call-ID: 5d356e3544c12b02754778604f9f3f29@194.148.41.50 CSeq: 102 OPTIONS User-Agent: VTX SIP Max-Forwards: 70 Date: Wed, 28 Mar 2007 14:27:15 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #21 [Mar 28 16:27:15] DEBUG[18254]: pbx.c:4826 ast_add_extension2: Added extension '0625037901' priority 1 to voip-test-01 [Mar 28 16:27:15] -- Added extension '0625037901' priority 1 to voip-test-01 [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:15] DEBUG[18254]: 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:27:15] DEBUG[18254]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 0 rows on table: sip_users [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:355 update_mysql: MySQL RealTime: Update SQL: UPDATE sip_users SET RegisterStart = '\'+NOW()+\'' WHERE name = '0625037901' [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 0 rows on table: sip_users [Mar 28 16:27:15] <--- 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-fe29ea722c38686e-1--d87543-;received=212.147.0.191;rport=11840 From: "0625037901";tag=2477442c To: "0625037901" Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 7 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:27:15] <--- 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-fe29ea722c38686e-1--d87543-;received=212.147.0.191;rport=11840 From: "0625037901";tag=2477442c To: "0625037901";tag=as4f2259ff Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 7 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="vtxvoip", nonce="7dd210c0" Content-Length: 0 <------------> [Mar 28 16:27:15] Scheduling destruction of SIP dialog '24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg.' in 32000 ms (Method: REGISTER) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 28 16:27:15] Scheduling destruction of SIP dialog '76273c1e65b06fa27a95ecf02bfc5235@194.148.41.50' in 32000 ms (Method: NOTIFY) [Mar 28 16:27:15] DEBUG[18254]: 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:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK111c4a3d;rport (64) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as1d349dfe (60) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: (67) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 76273c1e65b06fa27a95ecf02bfc5235@194.148.41.50 (55) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Event: message-summary (22) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 93 (18) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Messages-Waiting: no (20) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Message-Account: sip:asterisk@194.148.41.50 (43) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 28 16:27:15] 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=z9hG4bK111c4a3d;rport From: "asterisk" ;tag=as1d349dfe To: Contact: Call-ID: 76273c1e65b06fa27a95ecf02bfc5235@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:27:15] DEBUG[18254]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #26 [Mar 28 16:27:15] <--- SIP read from 212.147.0.191:11840 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK58259c8e;rport=5060 Contact: To: ;tag=5a61577d From: "asterisk";tag=as0e80e73d Call-ID: 5d356e3544c12b02754778604f9f3f29@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:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK58259c8e;rport=5060 (69) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Contact: (33) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=5a61577d (80) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: From: "asterisk";tag=as0e80e73d (59) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 5d356e3544c12b02754778604f9f3f29@194.148.41.50 (55) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Accept-Language: en (19) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 0 (17) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:27:15] --- (12 headers 0 lines) --- [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #21 [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '5d356e3544c12b02754778604f9f3f29@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:27:15] NOTICE[18254]: chan_sip.c:12147 handle_response_peerpoke: Peer '0625037901' is now Reachable. (11ms / 2000ms) [Mar 28 16:27:15] DEBUG[18254]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037901 [Mar 28 16:27:15] Really destroying SIP dialog '5d356e3544c12b02754778604f9f3f29@194.148.41.50' Method: OPTIONS [Mar 28 16:27:15] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037901 [Mar 28 16:27:15] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037901 [Mar 28 16:27:15] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/0625037901 - state 1 (Not in use) [Mar 28 16:27:15] DEBUG[18258]: 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:27:15] <--- 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-d446fb75c273685d-1--d87543-;rport Max-Forwards: 70 Contact: To: "0625037901" From: "0625037901";tag=2477442c Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 8 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="7dd210c0",uri="sip:194.148.41.50",response="c00192042da9d456d15ec23f85820f2d",algorithm=MD5 Content-Length: 0 <-------------> [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: REGISTER sip:194.148.41.50 SIP/2.0 (34) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.41:11840;branch=z9hG4bK-d87543-d446fb75c273685d-1--d87543-;rport (91) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 70 (16) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: Contact: (72) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: To: "0625037901" (46) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: From: "0625037901";tag=2477442c (61) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. (69) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: CSeq: 8 REGISTER (16) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Expires: 60 (11) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, NOTIFY, MESSAGE, SUBSCRIBE, INFO (81) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: Authorization: Digest username="0625037901",realm="vtxvoip",nonce="7dd210c0",uri="sip:194.148.41.50",response="c00192042da9d456d15ec23f85820f2d",algorithm=MD5 (158) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: Content-Length: 0 (17) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 13: (0) [Mar 28 16:27:15] --- (13 headers 0 lines) --- [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Mar 28 16:27:15] Using latest REGISTER request as basis request [Mar 28 16:27:15] Sending to 212.147.0.191 : 11840 (NAT) [Mar 28 16:27:15] <--- 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-d446fb75c273685d-1--d87543-;received=212.147.0.191;rport=11840 From: "0625037901";tag=2477442c To: "0625037901" Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 8 REGISTER User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:27:15] -- Saved useragent "eyeBeam release 1003l stamp 30936" for peer 0625037901 [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:355 update_mysql: MySQL RealTime: Update SQL: UPDATE sip_users SET ipaddr = '212.147.0.191', port = '11840', regseconds = '1175092095', username = '0625037901', fullcontact = 'sip:0625037901@212.147.0.191:11840;rinstance=62d70f12da108d78' WHERE name = '0625037901' [Mar 28 16:27:15] DEBUG[18254]: res_config_mysql.c:369 update_mysql: MySQL RealTime: Updated 1 rows on table: sip_users [Mar 28 16:27:15] <--- 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-d446fb75c273685d-1--d87543-;received=212.147.0.191;rport=11840 From: "0625037901";tag=2477442c To: "0625037901";tag=as4f2259ff Call-ID: 24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg. CSeq: 8 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:27:15 GMT Content-Length: 0 <------------> [Mar 28 16:27:15] DEBUG[18254]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037901 [Mar 28 16:27:15] Scheduling destruction of SIP dialog '24565b49c634af11NjIzMmVjOGIxMTJhOTQxNDE2YTU3YTJkZGNiODhmZDg.' in 32000 ms (Method: REGISTER) [Mar 28 16:27:15] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037901 [Mar 28 16:27:15] <--- SIP read from 212.147.0.191:11840 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK111c4a3d;rport=5060 Contact: To: ;tag=77194325 From: "asterisk";tag=as1d349dfe Call-ID: 76273c1e65b06fa27a95ecf02bfc5235@194.148.41.50 CSeq: 102 NOTIFY User-Agent: eyeBeam release 1003l stamp 30936 Content-Length: 0 <-------------> [Mar 28 16:27:15] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037901 [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:27:15] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/0625037901 - state 1 (Not in use) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK111c4a3d;rport=5060 (69) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Contact: (33) [Mar 28 16:27:15] DEBUG[18259]: 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:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=77194325 (80) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: From: "asterisk";tag=as1d349dfe (59) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 76273c1e65b06fa27a95ecf02bfc5235@194.148.41.50 (55) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:27:15] --- (9 headers 0 lines) --- [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #26 [Mar 28 16:27:15] DEBUG[18254]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '76273c1e65b06fa27a95ecf02bfc5235@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:27:15] Really destroying SIP dialog '76273c1e65b06fa27a95ecf02bfc5235@194.148.41.50' Method: NOTIFY [Mar 28 16:27: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=z9hG4bK7de71df7 Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=17d94c58 Call-ID: 00002167460a77aa@bigip.vtx.ch CSeq: 1175091114 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK7de71df7 (57) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=17d94c58 (45) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 00002167460a77aa@bigip.vtx.ch (38) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091114 OPTIONS (24) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:27:16] --- (9 headers 0 lines) --- [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 00002167460a77aa@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:27:16] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:27:16] Looking for s in default (domain 212.40.9.9) [Mar 28 16:27:16] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:16] DEBUG[18254]: 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:27: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=z9hG4bK7de71df7;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=17d94c58 To: sip:212.40.9.9;tag=as73ab257d Call-ID: 00002167460a77aa@bigip.vtx.ch CSeq: 1175091114 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:27:16] Scheduling destruction of SIP dialog '00002167460a77aa@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) [Mar 28 16:27:19] <--- SIP read from 212.147.20.222:5060 ---> INVITE sip:00090041625037902@194.148.41.50 SIP/2.0 Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bK1c77a5a54 Max-Forwards: 70 Content-Length: 334 To: sip:00090041625037902@194.148.41.50 From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 CSeq: 423024424 INVITE Route: Supported: timer Remote-Party-ID: ;party=calling;screen=yes;privacy=off Content-Type: application/sdp Contact: sip:00090041217211111@212.147.20.222:5060 Supported: replaces User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 v=0 o=MxSIP 0 26389 IN IP4 212.147.20.222 s=SIP Call c=IN IP4 212.147.20.222 t=0 0 m=audio 5302 RTP/AVP 18 8 0 100 a=rtpmap:18 G729/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:100 X-NSE/8000 a=fmtp:18 annexb=no a=fmtp:100 192-194 a=sendrecv m=image 5304 udptl t38 a=T38FaxUdpEC:t38UDPRedundancy a=sendrecv <-------------> [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: INVITE sip:00090041625037902@194.148.41.50 SIP/2.0 (50) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bK1c77a5a54 (60) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 70 (16) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: Content-Length: 334 (19) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: To: sip:00090041625037902@194.148.41.50 (39) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b (67) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 (56) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: CSeq: 423024424 INVITE (22) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Route: (29) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Supported: timer (16) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: Remote-Party-ID: ;party=calling;screen=yes;privacy=off (97) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: Content-Type: application/sdp (29) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: Contact: sip:00090041217211111@212.147.20.222:5060 (50) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 13: Supported: replaces (19) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 14: User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 (53) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 15: (0) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: v=0 (3) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: o=MxSIP 0 26389 IN IP4 212.147.20.222 (37) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: s=SIP Call (10) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: c=IN IP4 212.147.20.222 (23) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: t=0 0 (5) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: m=audio 5302 RTP/AVP 18 8 0 100 (31) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=rtpmap:100 X-NSE/8000 (23) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=fmtp:18 annexb=no (19) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=fmtp:100 192-194 (18) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: m=image 5304 udptl t38 (22) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=T38FaxUdpEC:t38UDPRedundancy (30) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:27:19] --- (15 headers 16 lines) --- [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:2582 do_setnat: Setting NAT on RTP to Off [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:2592 do_setnat: Setting NAT on UDPTL to Off [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 - INVITE (With RTP) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:1680 parse_sip_options: Begin: parsing SIP "Supported: timer" [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:1688 parse_sip_options: Found SIP option: -timer- [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:1694 parse_sip_options: Matched SIP option: timer [Mar 28 16:27:19] Sending to 212.147.20.222 : 5060 (no NAT) [Mar 28 16:27:19] Using INVITE request as basis request - 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 [Mar 28 16:27:19] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18254]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '00090041217211111' [Mar 28 16:27:19] Found peer 'sip_trunk_gva-mg-01' [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:2582 do_setnat: Setting NAT on RTP to Off [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:2592 do_setnat: Setting NAT on UDPTL to Off [Mar 28 16:27:19] Found RTP audio format 18 [Mar 28 16:27:19] Found RTP audio format 8 [Mar 28 16:27:19] Found RTP audio format 0 [Mar 28 16:27:19] Found RTP audio format 100 [Mar 28 16:27:19] Got T.38 offer in SDP in dialog 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4852 process_sdp: T38 state changed to 3 on channel [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4902 process_sdp: Peer T.38 UDPTL is at port 212.147.20.222:5304 [Mar 28 16:27:19] Peer audio RTP is at port 212.147.20.222:5302 [Mar 28 16:27:19] Found description format G729 for ID 18 [Mar 28 16:27:19] Found description format PCMA for ID 8 [Mar 28 16:27:19] Found description format PCMU for ID 0 [Mar 28 16:27:19] Found description format X-NSE for ID 100 [Mar 28 16:27:19] Got unsupported a:fmtp in SDP offer [Mar 28 16:27:19] Got unsupported a:fmtp in SDP offer [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:5109 process_sdp: UDP EC: t38UDPRedundancy [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:5129 process_sdp: Our T38 capability = (3856), peer T38 capability (32), joint T38 capability (32) [Mar 28 16:27:19] Capabilities: us - 0x108 (alaw|g729), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x108 (alaw|g729) [Mar 28 16:27:19] Non-codec capabilities (dtmf): us - 0x0 (nothing), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 28 16:27:19] Peer audio RTP is at port 212.147.20.222:5302 [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x108 (alaw|g729) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:13408 handle_request_invite: Checking SIP call limits for device [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:3010 update_call_counter: Updating call counter for incoming call [Mar 28 16:27:19] Looking for 00090041625037902 in default (domain 194.148.41.50) [Mar 28 16:27:19] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18254]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '1' [Mar 28 16:27:19] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18254]: 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:27:19] DEBUG[18254]: chan_sip.c:3812 sip_new: *** Our native formats are 0x100 (g729) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:3813 sip_new: *** Joint capabilities are 0x108 (alaw|g729) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:3814 sip_new: *** Our capabilities are 0x108 (alaw|g729) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:3815 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:3838 sip_new: This channel will not be able to handle video. [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:7987 build_route: build_route: Contact hop: sip:00090041217211111@212.147.20.222:5060 [Mar 28 16:27:19] list_route: hop: [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:13483 handle_request_invite: SIP/5060-006ff080: New call is still down.... Trying... [Mar 28 16:27:19] <--- Transmitting (no NAT) to 212.147.20.222:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bK1c77a5a54;received=212.147.20.222 From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b To: sip:00090041625037902@194.148.41.50 Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 CSeq: 423024424 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:27:19] DEBUG[18254]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-006ff080 [Mar 28 16:27:19] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060 [Mar 28 16:27:19] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 5060 [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '1' [Mar 28 16:27:19] DEBUG[18231]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18231]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '5060' [Mar 28 16:27:19] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid) [Mar 28 16:27:19] DEBUG[18261]: app_queue.c:546 changethread: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: 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:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '1' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: 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:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '1' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: 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:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '1' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: 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:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '00090041217211111' [Mar 28 16:27:19] -- Executing NoOp("SIP/5060-006ff080", "default: Call from <00090041217211111> to 00090041625037902") [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '2' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '2' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '2' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '2' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '2' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '2' ORDER BY exten [Mar 28 16:27:19] -- Executing Macro("SIP/5060-006ff080", "screening|00090041625037902") [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [s@macro-screening:1] NoOp("SIP/5060-006ff080", "macro-screening: Start of screening macro") in new stack [Mar 28 16:27:19] DEBUG[18260]: func_strings.c:134 regex: FUNCTION REGEX (%23)(00090041625037902) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [s@macro-screening:2] GotoIf("SIP/5060-006ff080", "0?:get-header-info|1") in new stack [Mar 28 16:27:19] -- Goto (macro-screening,get-header-info,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is ';party=calling;screen=yes;privacy=off' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [get-header-info@macro-screening:1] Set("SIP/5060-006ff080", "HEADER_RPID=;party=calling;screen=yes;privacy=off|_CNPN_PSTN_SCREENED=|_EMERGENCY_CALL=0") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'sip:00090041217211111@212.147.20.222:5060>;party=calling;screen=yes;privacy=off' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [get-header-info@macro-screening:2] Set("SIP/5060-006ff080", "HEADER_RPID=sip:00090041217211111@212.147.20.222:5060>;party=calling;screen=yes;privacy=off") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '00090041217211111' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [get-header-info@macro-screening:3] Set("SIP/5060-006ff080", "_RPID_CNPN=00090041217211111") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '212.147.20.222:5060' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [get-header-info@macro-screening:4] Set("SIP/5060-006ff080", "_RPID_CNPN_DOMAIN=212.147.20.222:5060") in new stack [Mar 28 16:27:19] DEBUG[18260]: func_strings.c:134 regex: FUNCTION REGEX (^.*privacy=full.*)(sip:00090041217211111@212.147.20.222:5060>;party=calling;screen=yes;privacy=off) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [get-header-info@macro-screening:5] Set("SIP/5060-006ff080", "_RPID_CNPN_PI=0") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '79' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '79' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [get-header-info@macro-screening:6] GotoIf("SIP/5060-006ff080", "79?:called") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] DEBUG[18260]: func_strings.c:134 regex: FUNCTION REGEX (^.*party=calling.*screen=yes.*)(sip:00090041217211111@212.147.20.222:5060>;party=calling;screen=yes;privacy=off) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [get-header-info@macro-screening:7] Set("SIP/5060-006ff080", "_RPID_CNPN_SI=1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:27:19] -- Executing [get-header-info@macro-screening:8] Goto("SIP/5060-006ff080", "callfrom|1") in new stack [Mar 28 16:27:19] -- Goto (macro-screening,callfrom,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '17' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '00090041217211111' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '17' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '17' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [callfrom@macro-screening:1] GotoIf("SIP/5060-006ff080", "17?callfrom-pstn|1:callfrom-voip|1") in new stack [Mar 28 16:27:19] -- Goto (macro-screening,callfrom-pstn,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [callfrom-pstn@macro-screening:1] NoOp("SIP/5060-006ff080", "macro-screening: Call from PSTN detected. Number always screened (SI=yes)| so just convert it to internat/nat format.") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [callfrom-pstn@macro-screening:2] Set("SIP/5060-006ff080", "_PSTN_CALL=1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '17' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [callfrom-pstn@macro-screening:3] GotoIf("SIP/5060-006ff080", "17?:test1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '00090041217211111' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [callfrom-pstn@macro-screening:4] Set("SIP/5060-006ff080", "CALLERID(all)=<0217211111>") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0217211111' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Macro' [Mar 28 16:27:19] -- Executing [callfrom-pstn@macro-screening:5] Macro("SIP/5060-006ff080", "setlanguage|0217211111") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [s@macro-setlanguage:1] NoOp("SIP/5060-006ff080", ""Set language based on A number (0217211111)"") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '3' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [s@macro-setlanguage:2] GotoIf("SIP/5060-006ff080", "3?french") in new stack [Mar 28 16:27:19] -- Goto (macro-setlanguage,s,23) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [s@macro-setlanguage:23] NoOp("SIP/5060-006ff080", ""french area found"") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [s@macro-setlanguage:24] Set("SIP/5060-006ff080", "CHANNEL(language)=fr") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MacroExit' [Mar 28 16:27:19] -- Executing [s@macro-setlanguage:25] MacroExit("SIP/5060-006ff080", "") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MacroExit' [Mar 28 16:27:19] -- Executing [callfrom-pstn@macro-screening:6] MacroExit("SIP/5060-006ff080", "") in new stack [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '3' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '3' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '3' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '3' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '3' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '3' ORDER BY exten [Mar 28 16:27:19] -- Executing Macro("SIP/5060-006ff080", "privacy|00090041625037902") [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [s@macro-privacy:1] NoOp("SIP/5060-006ff080", "macro-privacy: Start of privacy macro *31#/#31# or db") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0217211111' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [s@macro-privacy:2] Set("SIP/5060-006ff080", "_CNPN_ANI=0217211111") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [s@macro-privacy:3] Set("SIP/5060-006ff080", "db_clir=0") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [s@macro-privacy:4] GotoIf("SIP/5060-006ff080", "0?pi-allowed|1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [s@macro-privacy:5] GotoIf("SIP/5060-006ff080", "0?pi-prohib|1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [s@macro-privacy:6] GotoIf("SIP/5060-006ff080", "1?pi-allowed|1") in new stack [Mar 28 16:27:19] -- Goto (macro-privacy,pi-allowed,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [pi-allowed@macro-privacy:1] NoOp("SIP/5060-006ff080", "macro-privacy: Disable CLIR call by call (PI=allowed)") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [pi-allowed@macro-privacy:2] Set("SIP/5060-006ff080", "_CNPN_PI=allowed") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:27:19] -- Executing [pi-allowed@macro-privacy:3] Goto("SIP/5060-006ff080", "end|1") in new stack [Mar 28 16:27:19] -- Goto (macro-privacy,end,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [end@macro-privacy:1] NoOp("SIP/5060-006ff080", "macro-privacy: PI and CNPN_ANI saved| return to upper function") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MacroExit' [Mar 28 16:27:19] -- Executing [end@macro-privacy:2] MacroExit("SIP/5060-006ff080", "") in new stack [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '4' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '4' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '4' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '4' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '4' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '4' ORDER BY exten [Mar 28 16:27:19] -- Executing Macro("SIP/5060-006ff080", "check-registration|0625037902") [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:1] NoOp("SIP/5060-006ff080", "macro-check-registration: Start of macro check-registration| SERVER = voip-test-01") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:2] Set("SIP/5060-006ff080", "_OUT_TRUNK=") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:3] MYSQL("SIP/5060-006ff080", "Connect connid 194.148.41.10 asterisk ast-business asterisk_db") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:4] MYSQL("SIP/5060-006ff080", "Query resultid 1 SELECT a.RegisteredTo from sip_users a,number_options b where b.number='0625037902' and a.name=b.sip_users_name limit 1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:5] MYSQL("SIP/5060-006ff080", "Fetch fetchid 2 db_registered_server") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:6] MYSQL("SIP/5060-006ff080", "Clear 2") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:7] MYSQL("SIP/5060-006ff080", "Disconnect 1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:8] NoOp("SIP/5060-006ff080", "macro-check-registration: 0625037902 is registered on server voip-test-01"") in new stack [Mar 28 16:27:19] WARNING[18260]: ast_expr2.y:742 op_minus: non-numeric argument [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:9] GotoIf("SIP/5060-006ff080", "0?test1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] WARNING[18260]: ast_expr2.y:742 op_minus: non-numeric argument [Mar 28 16:27:19] WARNING[18260]: ast_expr2.y:742 op_minus: non-numeric argument [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:10] GotoIf("SIP/5060-006ff080", "1?end") in new stack [Mar 28 16:27:19] -- Goto (macro-check-registration,s,15) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MacroExit' [Mar 28 16:27:19] -- Executing [s@macro-check-registration:15] MacroExit("SIP/5060-006ff080", "") in new stack [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '5' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '5' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '5' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '5' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '5' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '5' ORDER BY exten [Mar 28 16:27:19] -- Executing NoOp("SIP/5060-006ff080", "default: Saved CNPN_ANI = 0217211111, PI = allowed") [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '6' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '6' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '6' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '6' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '6' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '6' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '7' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '8' [Mar 28 16:27:19] -- Executing gotoif("SIP/5060-006ff080", "0?7:8") [Mar 28 16:27:19] -- Goto (default,00090041625037902,8) [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '8' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '8' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '8' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '8' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '8' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '8' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:27:19] -- Executing gotoif("SIP/5060-006ff080", "1?20:26") [Mar 28 16:27:19] -- Goto (default,00090041625037902,20) [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '20' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '20' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '20' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '20' ORDER BY exten [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '00090041625037902' AND context = 'default' AND priority = '20' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:259 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'default' AND priority = '20' ORDER BY exten [Mar 28 16:27:19] -- Executing gosub("SIP/5060-006ff080", "default|0625037902|1") [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '0625037902' AND context = 'default' AND priority = '1' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '0625037902' AND context = 'default' AND priority = '1' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '0625037902' AND context = 'default' AND priority = '1' [Mar 28 16:27:19] -- Executing Macro("SIP/5060-006ff080", "dial|0625037902") [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [s@macro-dial:1] NoOp("SIP/5060-006ff080", "macro-dial: Start of macro dial| PI = allowed| CNPN_ANI = 0217211111") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:27:19] -- Executing [s@macro-dial:2] Goto("SIP/5060-006ff080", "get-client-info|1") in new stack [Mar 28 16:27:19] -- Goto (macro-dial,get-client-info,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [get-client-info@macro-dial:1] MYSQL("SIP/5060-006ff080", "Connect connid 194.148.41.10 asterisk ast-business asterisk_db") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [get-client-info@macro-dial:2] MYSQL("SIP/5060-006ff080", "Query resultid 1 SELECT fwd_unconditional,fwd_unconditional_flag,fwd_unavailable,fwd_unavailable_timeout,fwd_unavailable_flag,fwd_busy,fwd_busy_flag,dnd_start,dnd_end,language,sip_users_name,backup_number,clip from number_options where number='0625037902'") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [get-client-info@macro-dial:3] MYSQL("SIP/5060-006ff080", "Fetch fetchid 2 db_fwd_unconditional db_fwd_unconditional_flag db_fwd_unavailable db_fwd_unavailable_timeout db_fwd_unavailable_flag db_fwd_busy db_fwd_busy_flag db_dnd_start db_dnd_end db_language db_sip_users_name db_fwd_backup db_clip") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [get-client-info@macro-dial:4] MYSQL("SIP/5060-006ff080", "Clear 2") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'MYSQL' [Mar 28 16:27:19] -- Executing [get-client-info@macro-dial:5] MYSQL("SIP/5060-006ff080", "Disconnect 1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:27:19] -- Executing [get-client-info@macro-dial:6] Goto("SIP/5060-006ff080", "test-clip|1") in new stack [Mar 28 16:27:19] -- Goto (macro-dial,test-clip,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [test-clip@macro-dial:1] GotoIf("SIP/5060-006ff080", "0?test1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [test-clip@macro-dial:2] GotoIf("SIP/5060-006ff080", "0?test2") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'SetCallerPres' [Mar 28 16:27:19] -- Executing [test-clip@macro-dial:3] SetCallerPres("SIP/5060-006ff080", "allowed") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Goto' [Mar 28 16:27:19] -- Executing [test-clip@macro-dial:4] Goto("SIP/5060-006ff080", "dnd|1") in new stack [Mar 28 16:27:19] -- Goto (macro-dial,dnd,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:1] NoOp("SIP/5060-006ff080", "macro-dial: dnd_start="2006-12-13 09:35:00" dnd_stop="2006-12-13 09:35:00" current_time=""") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2006-12-13' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:2] Set("SIP/5060-006ff080", "VAR_dnd_start_date=2006-12-13") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '09:35:00' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:3] Set("SIP/5060-006ff080", "VAR_dnd_start_time=09:35:00") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2006' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '12' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '13' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:4] Set("SIP/5060-006ff080", "VAR_dnd_start_date=20061213") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '09' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '35' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '00' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:5] Set("SIP/5060-006ff080", "VAR_dnd_start_time=093500") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:6] Set("SIP/5060-006ff080", "db_dnd_start=20061213093500") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2006-12-13' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:7] Set("SIP/5060-006ff080", "VAR_dnd_end_date=2006-12-13") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '09:35:00' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:8] Set("SIP/5060-006ff080", "VAR_dnd_end_time=09:35:00") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2006' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '12' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '13' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:9] Set("SIP/5060-006ff080", "VAR_dnd_end_date=20061213") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '09' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '35' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '00' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:10] Set("SIP/5060-006ff080", "VAR_dnd_end_time=093500") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:11] Set("SIP/5060-006ff080", "db_dnd_end=20061213093500") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:12] Set("SIP/5060-006ff080", "VAR_current_ts=") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:13] Set("SIP/5060-006ff080", "current_ts=") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:14] NoOp("SIP/5060-006ff080", "macro-dial: dnd_start="20061213093500" dnd_stop="20061213093500" current_time=""") in new stack [Mar 28 16:27:19] WARNING[18260]: ast_expr2.fl:398 ast_yyerror: ast_yyerror(): syntax error: syntax error, unexpected $end, expecting '-' or '!' or '(' or ''; Input: 20061213093500< ^ [Mar 28 16:27:19] WARNING[18260]: ast_expr2.fl:402 ast_yyerror: If you have questions, please refer to doc/channelvariables.txt in the asterisk source. [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '0' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [dnd@macro-dial:15] GotoIf("SIP/5060-006ff080", "0?:nodnd|1") in new stack [Mar 28 16:27:19] -- Goto (macro-dial,nodnd,1) [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [nodnd@macro-dial:1] NoOp("SIP/5060-006ff080", "macro-dial: Check unconditional") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [nodnd@macro-dial:2] GotoIf("SIP/5060-006ff080", "1?:fwd|1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Mar 28 16:27:19] -- Executing [nodnd@macro-dial:3] NoOp("SIP/5060-006ff080", "macro-dial: dial customer Number=0625037902 via User=0625037902") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0625037902' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Set' [Mar 28 16:27:19] -- Executing [nodnd@macro-dial:4] Set("SIP/5060-006ff080", "CDPN=0625037902|XFER_CNPN=0625037902") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1716 pbx_substitute_variables_helper_full: Expression result is '1' [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'GotoIf' [Mar 28 16:27:19] -- Executing [nodnd@macro-dial:5] GotoIf("SIP/5060-006ff080", "1?:test1") in new stack [Mar 28 16:27:19] DEBUG[18260]: pbx.c:5973 pbx_builtin_gotoif: Not taking any branch [Mar 28 16:27:19] DEBUG[18260]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Mar 28 16:27:19] -- Executing [nodnd@macro-dial:6] Dial("SIP/5060-006ff080", "SIP/0625037902|100|t") in new stack [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:15317 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:2628 create_addr_from_peer: Our T38 capability (3856) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:2582 do_setnat: Setting NAT on RTP to On [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:2592 do_setnat: Setting NAT on UDPTL to On [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:3812 sip_new: *** Our native formats are 0x100 (g729) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:3813 sip_new: *** Joint capabilities are 0x0 (nothing) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:3814 sip_new: *** Our capabilities are 0x10e (gsm|ulaw|alaw|g729) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:3815 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:3817 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:3838 sip_new: This channel will not be able to handle video. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-nodnd-6. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-nodnd-5. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable XFER_CNPN. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable CDPN. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-nodnd-4. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-nodnd-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-nodnd-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-nodnd-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-15. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-14. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable current_ts. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-13. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable VAR_current_ts. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-12. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_dnd_end. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-11. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable VAR_dnd_end_time. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-10. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable VAR_dnd_end_date. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-9. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-8. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-7. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_dnd_start. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-6. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable VAR_dnd_start_time. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-5. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable VAR_dnd_start_date. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-4. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-dnd-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-test-clip-4. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-test-clip-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-test-clip-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-test-clip-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-get-client-info-6. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MYSQL_STATUS. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-get-client-info-5. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-get-client-info-4. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable fetchid. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_clip. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_fwd_backup. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_sip_users_name. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_language. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_fwd_busy_flag. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_fwd_busy. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_fwd_unavailable_flag. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_fwd_unavailable_timeout. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_fwd_unavailable. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_fwd_unconditional_flag. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_fwd_unconditional. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-get-client-info-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable resultid. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-get-client-info-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable connid. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-get-client-info-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable ARG1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable ~GOSUB~STACK~. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-15. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-10. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-9. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-8. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-7. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-6. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_registered_server. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-5. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-4. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable OUT_TRUNK. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-check-registration-s-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-end-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-end-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-pi-allowed-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable CNPN_PI. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-pi-allowed-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-pi-allowed-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-6. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-5. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-4. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable db_clir. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable CNPN_ANI. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-privacy-s-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-pstn-6. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-setlanguage-s-25. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-setlanguage-s-24. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-setlanguage-s-23. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-setlanguage-s-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-setlanguage-s-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-pstn-5. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-pstn-4. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-pstn-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable PSTN_CALL. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-pstn-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-pstn-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-callfrom-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-8. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable RPID_CNPN_SI. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-7. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-6. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable RPID_CNPN_PI. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-5. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable RPID_CNPN_DOMAIN. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-4. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable RPID_CNPN. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-3. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable HEADER_RPID. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable EMERGENCY_CALL. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3288 ast_channel_inherit_variables: Copying soft-transferable variable CNPN_PSTN_SCREENED. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-get-header-info-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-s-2. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-macro-screening-s-1. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Mar 28 16:27:19] DEBUG[18260]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPURI. [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:2837 sip_call: Outgoing Call for 0625037902 [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:3010 update_call_counter: Updating call counter for outgoing call [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:3084 update_call_counter: Call to peer '0625037902' is 1 out of 6 [Mar 28 16:27:19] DEBUG[18260]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902 [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:2852 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Mar 28 16:27:19] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:27:19] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:27:19] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 6 (Ringing) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:6195 add_sdp: ** Our capability: 0x10e (gsm|ulaw|alaw|g729) Video flag: False [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:6196 add_sdp: ** Our prefcodec: 0x100 (g729) [Mar 28 16:27:19] DEBUG[18262]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 28 16:27:19] Audio is at 194.148.41.50 port 18714 [Mar 28 16:27:19] Adding codec 0x100 (g729) to SDP [Mar 28 16:27:19] Adding codec 0x2 (gsm) to SDP [Mar 28 16:27:19] Adding codec 0x8 (alaw) to SDP [Mar 28 16:27:19] Adding codec 0x4 (ulaw) to SDP [Mar 28 16:27:19] Adding non-codec 0x1 (telephone-event) to SDP [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:6327 add_sdp: -- Done with adding codecs to SDP [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:6372 add_sdp: Done building SDP. Settling with this capability: 0x10e (gsm|ulaw|alaw|g729) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 0: INVITE sip:0625037902@10.0.0.102;user=phone SIP/2.0 (51) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK02e1701d;rport (64) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 2: From: "0217211111" ;tag=as06ee4aee (64) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 3: To: (42) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 4: Contact: (39) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 (55) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 INVITE (16) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 9: Date: Wed, 28 Mar 2007 14:27:19 GMT (35) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 11: Supported: replaces (19) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 12: Content-Type: application/sdp (29) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 13: Content-Length: 336 (19) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4580 parse_request: Header 14: (0) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: v=0 (3) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: o=root 18226 18226 IN IP4 194.148.41.50 (39) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: s=session (9) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: c=IN IP4 194.148.41.50 (22) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: t=0 0 (5) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: m=audio 18714 RTP/AVP 18 3 8 0 101 (34) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=fmtp:18 annexb=no (19) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=fmtp:101 0-16 (15) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=silenceSupp:off - - - - (25) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=ptime:20 (10) [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:27:19] Reliably Transmitting (NAT) to 212.147.65.170:8157: INVITE sip:0625037902@10.0.0.102;user=phone SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK02e1701d;rport From: "0217211111" ;tag=as06ee4aee To: Contact: Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 CSeq: 102 INVITE User-Agent: VTX SIP Max-Forwards: 70 Date: Wed, 28 Mar 2007 14:27:19 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 336 v=0 o=root 18226 18226 IN IP4 194.148.41.50 s=session c=IN IP4 194.148.41.50 t=0 0 m=audio 18714 RTP/AVP 18 3 8 0 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Mar 28 16:27:19] DEBUG[18260]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #31 [Mar 28 16:27:19] -- Called 0625037902 [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '0625037902' AND context = 'default' AND priority = '-1' [Mar 28 16:27:19] DEBUG[18260]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:19] DEBUG[18260]: 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:27:19] <--- SIP read from 212.147.65.170:8157 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK02e1701d;rport From: "0217211111" ;tag=as06ee4aee To: Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 CSeq: 102 INVITE User-Agent: Grandstream HT488 1.0.3.44 Content-Length: 0 <-------------> [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 100 Trying (18) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK02e1701d;rport (64) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "0217211111" ;tag=as06ee4aee (64) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: (42) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 (55) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Content-Length: 0 (17) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: (0) [Mar 28 16:27:19] --- (8 headers 0 lines) --- [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #31 - INVITE (got response) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '27cc07382a1339b57fb1d47c367e4114@194.148.41.50' Request 102: Found [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:11648 handle_response_invite: SIP response 100 to standard invite [Mar 28 16:27:19] <--- SIP read from 212.147.65.170:8157 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK02e1701d;rport From: "0217211111" ;tag=as06ee4aee To: ;tag=bc2dffff76240000 Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 CSeq: 102 INVITE User-Agent: Grandstream HT488 1.0.3.44 Content-Length: 0 <-------------> [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK02e1701d;rport (64) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "0217211111" ;tag=as06ee4aee (64) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=bc2dffff76240000 (63) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 (55) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Content-Length: 0 (17) [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: (0) [Mar 28 16:27:19] --- (8 headers 0 lines) --- [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '27cc07382a1339b57fb1d47c367e4114@194.148.41.50' Request 102: Found [Mar 28 16:27:19] DEBUG[18254]: chan_sip.c:11648 handle_response_invite: SIP response 180 to standard invite [Mar 28 16:27:19] DEBUG[18254]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902-00716940 [Mar 28 16:27:19] -- SIP/0625037902-00716940 is ringing [Mar 28 16:27:19] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:27:19] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:27:19] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 6 (Ringing) [Mar 28 16:27:19] <--- Transmitting (no NAT) to 212.147.20.222:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bK1c77a5a54;received=212.147.20.222 From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b To: sip:00090041625037902@194.148.41.50;tag=as1fe29760 Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 CSeq: 423024424 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:27:19] DEBUG[18263]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 28 16:27:20] Scheduling destruction of SIP dialog '780c83b921b409764088c2c419723f24@194.148.41.50' in 6400 ms (Method: NOTIFY) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: NOTIFY sip:0625037902@10.0.0.102;user=phone SIP/2.0 (51) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5e9e5995;rport (64) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as1fa5e55d (60) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: (42) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 780c83b921b409764088c2c419723f24@194.148.41.50 (55) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Event: message-summary (22) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 93 (18) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Messages-Waiting: no (20) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Message-Account: sip:asterisk@194.148.41.50 (43) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 28 16:27:20] 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=z9hG4bK5e9e5995;rport From: "asterisk" ;tag=as1fa5e55d To: Contact: Call-ID: 780c83b921b409764088c2c419723f24@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:27:20] DEBUG[18254]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #34 [Mar 28 16:27:20] <--- SIP read from 212.147.65.170:8157 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5e9e5995;rport From: "asterisk" ;tag=as1fa5e55d To: ;tag=bc2dffff76240000 Call-ID: 780c83b921b409764088c2c419723f24@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:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5e9e5995;rport (64) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as1fa5e55d (60) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=bc2dffff76240000 (63) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 780c83b921b409764088c2c419723f24@194.148.41.50 (55) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: CSeq: 102 NOTIFY (16) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Contact: (47) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Supported: replaces (19) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: Content-Length: 0 (17) [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:27:20] --- (11 headers 0 lines) --- [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #34 [Mar 28 16:27:20] DEBUG[18254]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '780c83b921b409764088c2c419723f24@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:27:20] Really destroying SIP dialog '780c83b921b409764088c2c419723f24@194.148.41.50' Method: NOTIFY [Mar 28 16:27: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=z9hG4bK02e1701d;rport From: "0217211111" ;tag=as06ee4aee To: ;tag=bc2dffff76240000 Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 CSeq: 102 INVITE User-Agent: Grandstream HT488 1.0.3.44 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE Content-Type: application/sdp Supported: replaces Content-Length: 159 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 18 a=sendrecv a=rtpmap:18 G729/8000 a=ptime:20 <-------------> [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK02e1701d;rport (64) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "0217211111" ;tag=as06ee4aee (64) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=bc2dffff76240000 (63) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 (55) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: CSeq: 102 INVITE (16) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Contact: (47) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Content-Type: application/sdp (29) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: Supported: replaces (19) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 159 (19) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: v=0 (3) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: o=0625037902 8000 8000 IN IP4 10.0.0.102 (40) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: s=SIP Call (10) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: c=IN IP4 10.0.0.102 (19) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: t=0 0 (5) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: m=audio 5004 RTP/AVP 18 (23) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=sendrecv (10) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: a=ptime:20 (10) [Mar 28 16:27:21] --- (12 headers 9 lines) --- [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '27cc07382a1339b57fb1d47c367e4114@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:11648 handle_response_invite: SIP response 200 to standard invite [Mar 28 16:27:21] Found RTP audio format 18 [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4906 process_sdp: Peer doesn't provide T.38 UDPTL [Mar 28 16:27:21] Peer audio RTP is at port 10.0.0.102:5004 [Mar 28 16:27:21] Found description format G729 for ID 18 [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:5136 process_sdp: T38 state changed to 0 on channel SIP/0625037902-00716940 [Mar 28 16:27:21] Capabilities: us - 0x10e (gsm|ulaw|alaw|g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) [Mar 28 16:27:21] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Mar 28 16:27:21] Peer audio RTP is at port 10.0.0.102:5004 [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:5216 process_sdp: We're settling with these formats: 0x100 (g729) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:5223 process_sdp: We have an owner, now see if we need to change this call [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:3010 update_call_counter: Updating call counter for outgoing call [Mar 28 16:27:21] DEBUG[18254]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902 [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:7987 build_route: build_route: Contact hop: [Mar 28 16:27:21] list_route: hop: [Mar 28 16:27:21] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:27:21] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:5650 reqprep: Strict routing enforced for session 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 [Mar 28 16:27:21] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 2 (In use) [Mar 28 16:27:21] set_destination: Parsing for address/port to send to [Mar 28 16:27:21] set_destination: set destination to 10.0.0.102, port 5060 [Mar 28 16:27:21] DEBUG[18264]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 28 16:27:21] Transmitting (NAT) to 212.147.65.170:8157: ACK sip:0625037902@10.0.0.102;user=phone SIP/2.0 Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK1e3a618c;rport From: "0217211111" ;tag=as06ee4aee To: ;tag=bc2dffff76240000 Contact: Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 CSeq: 102 ACK User-Agent: VTX SIP Max-Forwards: 70 Content-Length: 0 --- [Mar 28 16:27:21] -- Call on SIP/0625037902-00716940 left from hold [Mar 28 16:27:21] DEBUG[18260]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902-00716940 [Mar 28 16:27:21] -- SIP/0625037902-00716940 answered SIP/5060-006ff080 [Mar 28 16:27:21] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:27:21] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:27:21] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 2 (In use) [Mar 28 16:27:21] DEBUG[18260]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-006ff080 [Mar 28 16:27:21] DEBUG[18265]: app_queue.c:546 changethread: Device 'SIP/0625037902' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 28 16:27:21] DEBUG[18260]: chan_sip.c:3470 sip_answer: SIP answering channel: SIP/5060-006ff080 [Mar 28 16:27:21] DEBUG[18260]: chan_sip.c:3474 sip_answer: T38State change to 5 on channel SIP/5060-006ff080 [Mar 28 16:27:21] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060 [Mar 28 16:27:21] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 5060 [Mar 28 16:27:21] DEBUG[18260]: chan_sip.c:6049 add_t38_sdp: T.38 UDPTL is at 194.148.41.50 port 15640 [Mar 28 16:27:21] DEBUG[18260]: chan_sip.c:6055 add_t38_sdp: Our T38 capability (3856), peer T38 capability (32), joint capability (32) [Mar 28 16:27:21] DEBUG[18260]: chan_sip.c:5998 t38_get_rate: Strange, T38MaxFaxRate NOT found in peers T38 SDP. [Mar 28 16:27:21] <--- Reliably 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=z9hG4bK1c77a5a54;received=212.147.20.222 From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b To: sip:00090041625037902@194.148.41.50;tag=as1fe29760 Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 CSeq: 423024424 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 330 v=0 o=root 18226 18226 IN IP4 194.148.41.50 s=session c=IN IP4 194.148.41.50 t=0 0 m=image 15640 udptl t38 a=T38FaxVersion:0 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy <------------> [Mar 28 16:27:21] DEBUG[18260]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #35 [Mar 28 16:27:21] DEBUG[18231]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:21] DEBUG[18231]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '5060' [Mar 28 16:27:21] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid) [Mar 28 16:27:21] DEBUG[18266]: app_queue.c:546 changethread: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Mar 28 16:27:21] DEBUG[18260]: rtp.c:1151 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 212.147.65.170:12697 [Mar 28 16:27:21] DEBUG[18260]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to g729 [Mar 28 16:27:21] DEBUG[18260]: rtp.c:2706 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Mar 28 16:27: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=z9hG4bK35763c11 Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=6b598fdb Call-ID: 0000216b460a77af@bigip.vtx.ch CSeq: 1175091119 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK35763c11 (57) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=6b598fdb (45) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 0000216b460a77af@bigip.vtx.ch (38) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091119 OPTIONS (24) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:27:21] --- (9 headers 0 lines) --- [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 0000216b460a77af@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:27:21] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:27:21] Looking for s in default (domain 212.40.9.9) [Mar 28 16:27:21] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:21] DEBUG[18254]: 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:27: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=z9hG4bK35763c11;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=6b598fdb To: sip:212.40.9.9;tag=as7e638088 Call-ID: 0000216b460a77af@bigip.vtx.ch CSeq: 1175091119 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:27:21] Scheduling destruction of SIP dialog '0000216b460a77af@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:1866 retrans_pkt: SIP TIMER: Rescheduling retransmission #35 (1) SIP/2.0 - 1 [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:1880 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #35)) [Mar 28 16:27:22] Retransmitting #1 (no NAT) to 212.147.20.222:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bK1c77a5a54;received=212.147.20.222 From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b To: sip:00090041625037902@194.148.41.50;tag=as1fe29760 Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 CSeq: 423024424 INVITE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 330 v=0 o=root 18226 18226 IN IP4 194.148.41.50 s=session c=IN IP4 194.148.41.50 t=0 0 m=image 15640 udptl t38 a=T38FaxVersion:0 a=T38FaxFillBitRemoval:0 a=T38FaxTranscodingMMR:0 a=T38FaxTranscodingJBIG:0 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:400 a=T38FaxMaxDatagram:400 a=T38FaxUdpEC:t38UDPRedundancy --- [Mar 28 16:27:22] <--- SIP read from 212.147.20.222:5060 ---> ACK sip:00090041625037902@194.148.41.50 SIP/2.0 Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bKfb0aea80b Max-Forwards: 70 Content-Length: 0 To: sip:00090041625037902@194.148.41.50;tag=as1fe29760 From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 CSeq: 423024424 ACK Contact: sip:00090041217211111@212.147.20.222:5060 User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 <-------------> [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: ACK sip:00090041625037902@194.148.41.50 SIP/2.0 (47) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bKfb0aea80b (60) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 70 (16) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: Content-Length: 0 (17) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: To: sip:00090041625037902@194.148.41.50;tag=as1fe29760 (54) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b (67) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 (56) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: CSeq: 423024424 ACK (19) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Contact: sip:00090041217211111@212.147.20.222:5060 (50) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 (53) [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: (0) [Mar 28 16:27:22] --- (10 headers 0 lines) --- [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received ACK (6) - Command in SIP ACK [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #35 [Mar 28 16:27:22] DEBUG[18254]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222' of Response 423024424: Match Not Found [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Mar 28 16:27:26] Scheduling destruction of SIP dialog '25b82a3542ecc83359e479dc24971162@194.148.41.50' in 6400 ms (Method: NOTIFY) [Mar 28 16:27:26] DEBUG[18254]: 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:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5b98eebe;rport (64) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "asterisk" ;tag=as205a19c0 (60) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: (67) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Contact: (37) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 25b82a3542ecc83359e479dc24971162@194.148.41.50 (55) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: User-Agent: VTX SIP (19) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Max-Forwards: 70 (16) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Event: message-summary (22) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: Content-Length: 93 (18) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 12: (0) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Messages-Waiting: no (20) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Message-Account: sip:asterisk@194.148.41.50 (43) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: Voice-Message: 0/0 (0/0) (24) [Mar 28 16:27:26] 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=z9hG4bK5b98eebe;rport From: "asterisk" ;tag=as205a19c0 To: Contact: Call-ID: 25b82a3542ecc83359e479dc24971162@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:27:26] DEBUG[18254]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #40 [Mar 28 16:27: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=z9hG4bK48b49ee0 Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=69012983 Call-ID: 00002171460a77b4@bigip.vtx.ch CSeq: 1175091124 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK48b49ee0 (57) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=69012983 (45) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 00002171460a77b4@bigip.vtx.ch (38) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091124 OPTIONS (24) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:27:26] --- (9 headers 0 lines) --- [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 00002171460a77b4@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:27:26] Looking for s in default (domain 212.40.9.9) [Mar 28 16:27:26] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:26] DEBUG[18254]: 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:27: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=z9hG4bK48b49ee0;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=69012983 To: sip:212.40.9.9;tag=as3ce490ed Call-ID: 00002171460a77b4@bigip.vtx.ch CSeq: 1175091124 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:27:26] Scheduling destruction of SIP dialog '00002171460a77b4@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) [Mar 28 16:27:26] <--- SIP read from 212.147.0.191:11840 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5b98eebe;rport=5060 Contact: To: ;tag=8d62207d From: "asterisk";tag=as205a19c0 Call-ID: 25b82a3542ecc83359e479dc24971162@194.148.41.50 CSeq: 102 NOTIFY User-Agent: eyeBeam release 1003l stamp 30936 Content-Length: 0 <-------------> [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK5b98eebe;rport=5060 (69) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Contact: (33) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=8d62207d (80) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: From: "asterisk";tag=as205a19c0 (59) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 25b82a3542ecc83359e479dc24971162@194.148.41.50 (55) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: User-Agent: eyeBeam release 1003l stamp 30936 (45) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:27:26] --- (9 headers 0 lines) --- [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #40 [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '25b82a3542ecc83359e479dc24971162@194.148.41.50' of Request 102: Match Not Found [Mar 28 16:27:26] Really destroying SIP dialog '25b82a3542ecc83359e479dc24971162@194.148.41.50' Method: NOTIFY [Mar 28 16:27:26] <--- 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=z9hG4bKcc00a1613 Max-Forwards: 70 Content-Length: 0 To: sip:00090041625037902@194.148.41.50;tag=as1fe29760 From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 CSeq: 423024425 BYE Supported: timer Supported: replaces User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 <-------------> [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: BYE sip:00090041625037902@194.148.41.50 SIP/2.0 (47) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 212.147.20.222:5060;branch=z9hG4bKcc00a1613 (60) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 70 (16) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: Content-Length: 0 (17) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: To: sip:00090041625037902@194.148.41.50;tag=as1fe29760 (54) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b (67) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 (56) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: CSeq: 423024425 BYE (19) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Supported: timer (16) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Supported: replaces (19) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: User-Agent: Patton SN2400 MxSF v3.2.8.45 00A0BA01C558 (53) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:27:26] --- (11 headers 0 lines) --- [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received BYE (8) - Command in SIP BYE [Mar 28 16:27:26] Sending to 212.147.20.222 : 5060 (no NAT) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:14197 handle_request_bye: Received bye, issuing owner hangup [Mar 28 16:27:26] <--- 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=z9hG4bKcc00a1613;received=212.147.20.222 From: sip:00090041217211111@212.147.20.222:5060;tag=c2a0dce8c1c760b To: sip:00090041625037902@194.148.41.50;tag=as1fe29760 Call-ID: 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222 CSeq: 423024425 BYE User-Agent: VTX SIP Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Mar 28 16:27:26] DEBUG[18260]: channel.c:3800 ast_generic_bridge: Didn't get a frame from channel: SIP/5060-006ff080 [Mar 28 16:27:26] DEBUG[18260]: channel.c:4118 ast_channel_bridge: Bridge stops bridging channels SIP/5060-006ff080 and SIP/0625037902-00716940 [Mar 28 16:27:26] DEBUG[18260]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/0625037902-00716940' [Mar 28 16:27:26] DEBUG[18260]: chan_sip.c:3319 sip_hangup: Hangup call SIP/0625037902-00716940, SIP callid 27cc07382a1339b57fb1d47c367e4114@194.148.41.50) [Mar 28 16:27:26] DEBUG[18260]: chan_sip.c:3328 sip_hangup: update_call_counter(0625037902) - decrement call limit counter on hangup [Mar 28 16:27:26] DEBUG[18260]: chan_sip.c:3010 update_call_counter: Updating call counter for outgoing call [Mar 28 16:27:26] DEBUG[18260]: chan_sip.c:3058 update_call_counter: Call to peer '0625037902' removed from call limit 6 [Mar 28 16:27:26] DEBUG[18260]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902 [Mar 28 16:27:26] Scheduling destruction of SIP dialog '27cc07382a1339b57fb1d47c367e4114@194.148.41.50' in 6400 ms (Method: INVITE) [Mar 28 16:27:26] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:27:26] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:27:26] DEBUG[18260]: chan_sip.c:5650 reqprep: Strict routing enforced for session 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 [Mar 28 16:27:26] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 1 (Not in use) [Mar 28 16:27:26] set_destination: Parsing for address/port to send to [Mar 28 16:27:26] set_destination: set destination to 10.0.0.102, port 5060 [Mar 28 16:27:26] DEBUG[18267]: 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:27:26] 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=z9hG4bK2d31ac87;rport From: "0217211111" ;tag=as06ee4aee To: ;tag=bc2dffff76240000 Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 CSeq: 103 BYE User-Agent: VTX SIP Max-Forwards: 70 Content-Length: 0 --- [Mar 28 16:27:26] DEBUG[18260]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #43 [Mar 28 16:27:26] DEBUG[18260]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/0625037902-00716940 [Mar 28 16:27:26] DEBUG[18260]: rtp.c:1476 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Mar 28 16:27:26] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 0625037902 [Mar 28 16:27:26] DEBUG[18260]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Mar 28 16:27:26] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 0625037902 [Mar 28 16:27:26] DEBUG[18260]: app_macro.c:261 _macro_exec: Spawn extension (macro-dial,nodnd,6) exited non-zero on 'SIP/5060-006ff080' in macro 'dial' [Mar 28 16:27:26] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/0625037902 - state 1 (Not in use) [Mar 28 16:27:26] DEBUG[18260]: pbx.c:2393 __ast_pbx_run: Spawn extension (macro-dial,nodnd,6) exited non-zero on 'SIP/5060-006ff080' [Mar 28 16:27:26] == Spawn extension (macro-dial, nodnd, 6) exited non-zero on 'SIP/5060-006ff080' [Mar 28 16:27:26] DEBUG[18268]: 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:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0217211111' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0217211111' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0625037902' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'default' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/5060-006ff080' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/0625037902-00716940' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/0625037902|100|t' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-28 16:27:19' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-28 16:27:21' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-03-28 16:27:26' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '7' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '5' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175092039.0' [Mar 28 16:27:26] DEBUG[18260]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Mar 28 16:27:26] DEBUG[18260]: cdr_addon_mysql.c:210 mysql_log: cdr_mysql: inserting a CDR record. [Mar 28 16:27:26] DEBUG[18260]: 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:27:19','0217211111','0217211111','0625037902','default', 'SIP/5060-006ff080','SIP/0625037902-00716940','Dial','SIP/0625037902|100|t',7,5,'ANSWERED',3,'','') [Mar 28 16:27:26] DEBUG[18260]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/5060-006ff080' [Mar 28 16:27:26] DEBUG[18260]: chan_sip.c:3319 sip_hangup: Hangup call SIP/5060-006ff080, SIP callid 2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222) [Mar 28 16:27:26] DEBUG[18260]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5060-006ff080 [Mar 28 16:27:26] DEBUG[18231]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5060 [Mar 28 16:27:26] DEBUG[18231]: chan_sip.c:15251 sip_devicestate: Checking device state for peer 5060 [Mar 28 16:27:26] DEBUG[18231]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:26] DEBUG[18231]: res_config_mysql.c:139 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip_users WHERE name = '5060' [Mar 28 16:27:26] DEBUG[18231]: devicestate.c:287 do_state_change: Changing state for SIP/5060 - state 4 (Invalid) [Mar 28 16:27:26] DEBUG[18269]: app_queue.c:546 changethread: Device 'SIP/5060' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Mar 28 16:27:26] <--- SIP read from 212.147.65.170:8157 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK2d31ac87;rport From: "0217211111" ;tag=as06ee4aee To: ;tag=bc2dffff76240000 Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 CSeq: 103 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:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: SIP/2.0 200 OK (14) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP 194.148.41.50:5060;branch=z9hG4bK2d31ac87;rport (64) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: From: "0217211111" ;tag=as06ee4aee (64) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: ;tag=bc2dffff76240000 (63) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: Call-ID: 27cc07382a1339b57fb1d47c367e4114@194.148.41.50 (55) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: CSeq: 103 BYE (13) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: User-Agent: Grandstream HT488 1.0.3.44 (38) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Contact: (47) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE (64) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: Supported: replaces (19) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 10: Content-Length: 0 (17) [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 11: (0) [Mar 28 16:27:26] --- (11 headers 0 lines) --- [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #43 [Mar 28 16:27:26] DEBUG[18254]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '27cc07382a1339b57fb1d47c367e4114@194.148.41.50' of Request 103: Match Not Found [Mar 28 16:27:26] Really destroying SIP dialog '27cc07382a1339b57fb1d47c367e4114@194.148.41.50' Method: INVITE [Mar 28 16:27:26] Really destroying SIP dialog '2326fdfcf172a00f9152e3d75036f6b0@212.147.20.222' Method: BYE [Mar 28 16:27:27] <--- SIP read from 212.147.0.191:11840 ---> <-------------> [Mar 28 16:27:27] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: (0) [Mar 28 16:27:27] DEBUG[18254]: chan_sip.c:4612 parse_request: Line: (0) [Mar 28 16:27:27] --- (0 headers 1 lines) --- [Mar 28 16:27:29] <--- SIP read from 212.147.65.170:8157 ---> <-------------> [Mar 28 16:27:29] --- (0 headers 0 lines) Nat keepalive --- stop[Mar 28 16:27: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=z9hG4bK001e0e8e Max-Forwards: 1 To: sip:212.40.9.9 From: sip:anonymous@bigip.vtx.ch;tag=3c6f1601 Call-ID: 00002175460a77b9@bigip.vtx.ch CSeq: 1175091129 OPTIONS Accept: application/sdp Content-Length: 0 <-------------> [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 0: OPTIONS sip:212.40.9.9:5060 SIP/2.0 (35) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 1: Via: SIP/2.0/UDP bigip.vtx.ch:5060;branch=z9hG4bK001e0e8e (57) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 2: Max-Forwards: 1 (15) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 3: To: sip:212.40.9.9 (18) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 4: From: sip:anonymous@bigip.vtx.ch;tag=3c6f1601 (45) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 5: Call-ID: 00002175460a77b9@bigip.vtx.ch (38) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 6: CSeq: 1175091129 OPTIONS (24) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 7: Accept: application/sdp (23) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 8: Content-Length: 0 (17) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4580 parse_request: Header 9: (0) [Mar 28 16:27:31] --- (9 headers 0 lines) --- [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:4317 sip_alloc: Allocating new SIP dialog for 00002175460a77b9@bigip.vtx.ch - OPTIONS (No RTP) [Mar 28 16:27:31] DEBUG[18254]: chan_sip.c:14640 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Mar 28 16:27:31] Looking for s in default (domain 212.40.9.9) [Mar 28 16:27:31] DEBUG[18254]: res_config_mysql.c:651 mysql_reconnect: MySQL RealTime: Everything is fine. [Mar 28 16:27:31] DEBUG[18254]: 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:27: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=z9hG4bK001e0e8e;received=212.40.9.10 From: sip:anonymous@bigip.vtx.ch;tag=3c6f1601 To: sip:212.40.9.9;tag=as1352299e Call-ID: 00002175460a77b9@bigip.vtx.ch CSeq: 1175091129 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:27:31] Scheduling destruction of SIP dialog '00002175460a77b9@bigip.vtx.ch' in 32000 ms (Method: OPTIONS) now [Mar 28 16:27:34] Beginning asterisk shutdown.... [Mar 28 16:27:34] Executing last minute cleanups [Mar 28 16:27:34] == Destroying musiconhold processes [Mar 28 16:27:34] DEBUG[18226]: res_musiconhold.c:1125 ast_moh_destroy: killing 18233! [Mar 28 16:27:35] DEBUG[18226]: res_musiconhold.c:1139 ast_moh_destroy: mpg123 pid 18233 and child died after 65536 bytes read [Mar 28 16:27:35] Asterisk cleanly ending (0). [Mar 28 16:27:35] DEBUG[18226]: asterisk.c:1276 quit_handler: Asterisk ending (0).