*CLI> set debug 4 Core debug was 5 and is now 4 *CLI> set verbose 4 Verbosity was 5 and is now 4 *CLI> se[Feb 27 20:17:24] DEBUG[7949]: chan_sip.c:1341 __sip_autodestruct: Auto destroying call '2206229189-1947513985@192.168.1.73'  No such command 's' (type 'help' for help) *CLI> sip debug SIP Debugging enabled *CLI> [Feb 27 20:17:39] <-- SIP read from 192.168.1.73:5060: INVITE sip:552@192.168.1.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2934912910267903566;rport From: 573 ;tag=2722030966 To: "552" Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 1 INVITE Contact: max-forwards: 70 supported: 100rel user-agent: Voip Phone 1.0 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, SUBSCRIBE, PRACK, UPDATE Content-Type: application/sdp Content-Length: 286 v=0 o=sdp_admin 68122087 11055854 IN IP4 192.168.1.73 s=A conversation c=IN IP4 192.168.1.73 t=0 0 m=audio 10000 RTP/AVP 8 4 4 18 0 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:4 G723high/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:0 PCMU/8000 a=sendrecv [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: INVITE sip:552@192.168.1.100 SIP/2.0 (36) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2934912910267903566;rport (74) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: 573 ;tag=2722030966 (48) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: "552" (33) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 1712013045-28234116@192.168.1.73 (41) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 1 INVITE (14) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Contact: (36) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: max-forwards: 70 (16) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: supported: 100rel (17) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 9: user-agent: Voip Phone 1.0 (26) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 10: Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, SUBSCRIBE, PRACK, UPDATE (81) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 11: Content-Type: application/sdp (29) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 12: Content-Length: 286 (21) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 13: (0) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: v=0 (3) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: o=sdp_admin 68122087 11055854 IN IP4 192.168.1.73 (49) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: s=A conversation (16) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: c=IN IP4 192.168.1.73 (21) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: t=0 0 (5) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: m=audio 10000 RTP/AVP 8 4 4 18 0 (32) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:4 G723high/8000 (24) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=fmtp:18 annexb=no (19) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=sendrecv (10) [Feb 27 20:17:39] --- (13 headers 13 lines) --- [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3164 sip_alloc: Allocating new SIP dialog for 1712013045-28234116@192.168.1.73 - INVITE (With RTP) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:11534 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1020 parse_sip_options: Begin: parsing SIP "Supported: 100rel" [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1032 parse_sip_options: Found SIP option: -100rel- [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1038 parse_sip_options: Matched SIP option: 100rel [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1049 parse_sip_options: * SIP extension value: 2 for call 1712013045-28234116@192.168.1.73 [Feb 27 20:17:39] Using INVITE request as basis request - 1712013045-28234116@192.168.1.73 [Feb 27 20:17:39] Sending to 192.168.1.73 : 5060 (NAT) [Feb 27 20:17:39] DEBUG[7949]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7949]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM sip WHERE name = '573' [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:7396 check_user_full: Setting NAT on RTP to 0 [Feb 27 20:17:39] Reliably Transmitting (no NAT) to 192.168.1.73:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2934912910267903566;received=192.168.1.73;rport=5060 From: 573 ;tag=2722030966 To: "552" ;tag=as1e90062f Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="7d956bb7" Content-Length: 0 --- [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #49 [Feb 27 20:17:39] Scheduling destruction of call '1712013045-28234116@192.168.1.73' in 15000 ms [Feb 27 20:17:39] Found user '573' [Feb 27 20:17:39] <-- SIP read from 192.168.1.73:5060: ACK sip:552@192.168.1.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2934912910267903566;rport From: 573 ;tag=2722030966 To: "552" ;tag=as1e90062f Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 1 ACK max-forwards: 70 Content-Length: 0 [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: ACK sip:552@192.168.1.100 SIP/2.0 (33) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2934912910267903566;rport (74) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: 573 ;tag=2722030966 (48) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: "552" ;tag=as1e90062f (48) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 1712013045-28234116@192.168.1.73 (41) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 1 ACK (11) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: max-forwards: 70 (16) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: (0) [Feb 27 20:17:39] --- (8 headers 0 lines) --- [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:11534 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #49 [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '1712013045-28234116@192.168.1.73' of Response 1: Match Found [Feb 27 20:17:39] <-- SIP read from 192.168.1.73:5060: INVITE sip:552@192.168.1.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;rport From: 573 ;tag=2722030966 To: "552" Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 2 INVITE Contact: Proxy-Authorization: Digest username="573", realm="asterisk", nonce="7d956bb7", uri="sip:552@192.168.1.100", response="0d2573deda35e653ed27081e8c88e97c", algorithm=MD5 max-forwards: 70 supported: 100rel user-agent: Voip Phone 1.0 Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, SUBSCRIBE, PRACK, UPDATE Content-Type: application/sdp Content-Length: 286 v=0 o=sdp_admin 68122087 11055854 IN IP4 192.168.1.73 s=A conversation c=IN IP4 192.168.1.73 t=0 0 m=audio 10000 RTP/AVP 8 4 4 18 0 a=rtpmap:8 PCMA/8000 a=rtpmap:4 G723/8000 a=rtpmap:4 G723high/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:0 PCMU/8000 a=sendrecv [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: INVITE sip:552@192.168.1.100 SIP/2.0 (36) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;rport (74) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: 573 ;tag=2722030966 (48) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: "552" (33) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 1712013045-28234116@192.168.1.73 (41) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 2 INVITE (14) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Contact: (36) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: Proxy-Authorization: Digest username="573", realm="asterisk", nonce="7d956bb7", uri="sip:552@192.168.1.100", response="0d2573deda35e653ed27081e8c88e97c", algorithm=MD5 (167) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: max-forwards: 70 (16) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 9: supported: 100rel (17) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 10: user-agent: Voip Phone 1.0 (26) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 11: Allow: INVITE, ACK, OPTIONS, BYE, CANCEL, REFER, NOTIFY, SUBSCRIBE, PRACK, UPDATE (81) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 13: Content-Length: 286 (21) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 14: (0) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: v=0 (3) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: o=sdp_admin 68122087 11055854 IN IP4 192.168.1.73 (49) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: s=A conversation (16) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: c=IN IP4 192.168.1.73 (21) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: t=0 0 (5) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: m=audio 10000 RTP/AVP 8 4 4 18 0 (32) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:4 G723/8000 (20) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:4 G723high/8000 (24) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=fmtp:18 annexb=no (19) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3461 parse_request: Line: a=sendrecv (10) [Feb 27 20:17:39] --- (14 headers 13 lines) --- [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:11534 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 27 20:17:39] Using INVITE request as basis request - 1712013045-28234116@192.168.1.73 [Feb 27 20:17:39] Sending to 192.168.1.73 : 5060 (NAT) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:7396 check_user_full: Setting NAT on RTP to 0 [Feb 27 20:17:39] Found user '573' [Feb 27 20:17:39] Found RTP audio format 8 [Feb 27 20:17:39] Found RTP audio format 4 [Feb 27 20:17:39] Found RTP audio format 4 [Feb 27 20:17:39] Found RTP audio format 18 [Feb 27 20:17:39] Found RTP audio format 0 [Feb 27 20:17:39] Peer audio RTP is at port 192.168.1.73:10000 [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3670 process_sdp: Peer audio RTP is at port 192.168.1.73:10000 [Feb 27 20:17:39] Found description format PCMA [Feb 27 20:17:39] Found description format G723 [Feb 27 20:17:39] Found description format G723high [Feb 27 20:17:39] Found description format G729 [Feb 27 20:17:39] Found description format PCMU [Feb 27 20:17:39] Capabilities: us - 0x8 (alaw), peer - audio=0x10d (g723|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x8 (alaw) [Feb 27 20:17:39] Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:10833 handle_request_invite: Checking SIP call limits for device 573 [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:2208 update_call_counter: Updating call counter for incoming call [Feb 27 20:17:39] Looking for 552 in sip (domain 192.168.1.100) [Feb 27 20:17:39] DEBUG[7949]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7949]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '552' AND context = 'sip' AND priority = '1' [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:6301 build_route: build_route: Contact hop: [Feb 27 20:17:39] list_route: hop: [Feb 27 20:17:39] Transmitting (no NAT) to 192.168.1.73:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;received=192.168.1.73;rport=5060 From: 573 ;tag=2722030966 To: "552" Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Feb 27 20:17:39] DEBUG[7941]: chan_sip.c:12124 sip_devicestate: Checking device state for peer 573 [Feb 27 20:17:39] DEBUG[7941]: devicestate.c:189 do_state_change: Changing state for SIP/573 - state 2 (In use) [Feb 27 20:17:39] DEBUG[7972]: app_queue.c:500 changethread: Device 'SIP/573' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '552' AND context = 'sip' AND priority = '1' [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '552' AND context = 'sip' AND priority = '1' [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '552' AND context = 'sip' AND priority = '1' [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '552' AND context = 'sip' AND priority = '1' [Feb 27 20:17:39] -- Executing System("SIP/573-081c5df8", "/opt/fv/callstart asterisk-7937-1172600259.0 573 552 sip START 1>/dev/null 2>/dev/null") [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '552' AND context = 'sip' AND priority = '2' [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '552' AND context = 'sip' AND priority = '2' [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:39] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = '552' AND context = 'sip' AND priority = '2' [Feb 27 20:17:39] -- Executing Dial("SIP/573-081c5df8", "SIP/552|40|rtwWo") [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3164 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:1876 create_addr_from_peer: Setting NAT on RTP to 0 [Feb 27 20:17:39] DEBUG[7971]: channel.c:2956 ast_channel_inherit_variables: Not copying variable SYSTEMSTATUS. [Feb 27 20:17:39] DEBUG[7971]: channel.c:2956 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 27 20:17:39] DEBUG[7971]: channel.c:2956 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 27 20:17:39] DEBUG[7971]: channel.c:2956 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 27 20:17:39] DEBUG[7971]: channel.c:2956 ast_channel_inherit_variables: Not copying variable SIPURI. [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:2070 sip_call: Outgoing Call for 552 [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:2208 update_call_counter: Updating call counter for outgoing call [Feb 27 20:17:39] We're at 192.168.1.100 port 10506 [Feb 27 20:17:39] Adding codec 0x8 (alaw) to SDP [Feb 27 20:17:39] Adding non-codec 0x1 (telephone-event) to SDP [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 0: INVITE sip:552@192.168.1.52:5060 SIP/2.0 (40) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport (64) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 2: From: "Martyns" ;tag=as06fcf625 (54) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 3: To: (31) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 4: Contact: (32) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 5: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 (55) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 9: Date: Tue, 27 Feb 2007 18:17:39 GMT (35) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 11: Content-Type: application/sdp (29) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 12: Content-Length: 216 (19) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3429 parse_request: Header 13: (0) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: v=0 (3) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: o=root 7937 7937 IN IP4 192.168.1.100 (37) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: s=session (9) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: c=IN IP4 192.168.1.100 (22) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: t=0 0 (5) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: m=audio 10506 RTP/AVP 8 101 (27) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:3461 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 27 20:17:39] 13 headers, 10 lines [Feb 27 20:17:39] Reliably Transmitting (no NAT) to 192.168.1.52:5060: INVITE sip:552@192.168.1.52:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: Contact: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Tue, 27 Feb 2007 18:17:39 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 216 v=0 o=root 7937 7937 IN IP4 192.168.1.100 s=session c=IN IP4 192.168.1.100 t=0 0 m=audio 10506 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - --- [Feb 27 20:17:39] DEBUG[7971]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #51 [Feb 27 20:17:39] -- Called 552 [Feb 27 20:17:39] Transmitting (no NAT) to 192.168.1.73:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;received=192.168.1.73;rport=5060 From: 573 ;tag=2722030966 To: "552" ;tag=as731fc553 Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Feb 27 20:17:39] <-- SIP read from 192.168.1.52:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 INVITE Content-Length: 0 [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport (64) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: "Martyns" ;tag=as06fcf625 (54) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: (31) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 (55) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Content-Length: 0 (17) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: (0) [Feb 27 20:17:39] --- (7 headers 0 lines) --- [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1464 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #51 - INVITE (got response) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1473 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' Request 102: Found [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:9878 handle_response_invite: SIP response 100 to standard invite [Feb 27 20:17:39] <-- SIP read from 192.168.1.52:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: ;tag=919014754 Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 INVITE Contact: Content-Length: 0 [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport (64) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: "Martyns" ;tag=as06fcf625 (54) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: ;tag=919014754 (45) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 (55) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Contact: (36) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: (0) [Feb 27 20:17:39] --- (8 headers 0 lines) --- [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:1473 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' Request 102: Found [Feb 27 20:17:39] DEBUG[7949]: chan_sip.c:9878 handle_response_invite: SIP response 180 to standard invite [Feb 27 20:17:39] -- SIP/552-081bf3b8 is ringing [Feb 27 20:17:39] DEBUG[7941]: chan_sip.c:12124 sip_devicestate: Checking device state for peer 552 [Feb 27 20:17:39] DEBUG[7941]: devicestate.c:189 do_state_change: Changing state for SIP/552 - state 6 (Ringing) [Feb 27 20:17:39] DEBUG[7977]: app_queue.c:500 changethread: Device 'SIP/552' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 27 20:17:45] <-- SIP read from 192.168.1.73:5060: CANCEL sip:552@192.168.1.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;rport From: 573 ;tag=2722030966 To: "552" Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 2 CANCEL Proxy-Authorization: Digest username="573", realm="asterisk", nonce="7d956bb7", uri="sip:552@192.168.1.100", response="0d2573deda35e653ed27081e8c88e97c", algorithm=MD5 max-forwards: 70 user-agent: Voip Phone 1.0 Content-Length: 0 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: CANCEL sip:552@192.168.1.100 SIP/2.0 (36) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;rport (74) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: 573 ;tag=2722030966 (48) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: "552" (33) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 1712013045-28234116@192.168.1.73 (41) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 2 CANCEL (14) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Proxy-Authorization: Digest username="573", realm="asterisk", nonce="7d956bb7", uri="sip:552@192.168.1.100", response="0d2573deda35e653ed27081e8c88e97c", algorithm=MD5 (167) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: max-forwards: 70 (16) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: user-agent: Voip Phone 1.0 (26) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 9: Content-Length: 0 (17) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 10: (0) [Feb 27 20:17:45] --- (10 headers 0 lines) --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:11534 handle_request: **** Received CANCEL (14) - Command in SIP CANCEL [Feb 27 20:17:45] Sending to 192.168.1.73 : 5060 (NAT) [Feb 27 20:17:45] Reliably Transmitting (NAT) to 192.168.1.73:5060: SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;received=192.168.1.73;rport=5060 From: 573 ;tag=2722030966 To: "552" ;tag=as731fc553 Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #53 [Feb 27 20:17:45] Transmitting (NAT) to 192.168.1.73:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;received=192.168.1.73;rport=5060 From: 573 ;tag=2722030966 To: "552" ;tag=as731fc553 Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 2 CANCEL User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- [Feb 27 20:17:45] DEBUG[7971]: channel.c:1395 ast_hangup: Hanging up channel 'SIP/552-081bf3b8' [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:2418 sip_hangup: Hangup call SIP/552-081bf3b8, SIP callid 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100) [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:2426 sip_hangup: update_call_counter(552) - decrement call limit counter [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:2208 update_call_counter: Updating call counter for outgoing call [Feb 27 20:17:45] Scheduling destruction of call '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' in 32000 ms [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:1397 __sip_ack: Acked pending invite 102 [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' of Request 102: Match Found [Feb 27 20:17:45] Reliably Transmitting (no NAT) to 192.168.1.52:5060: CANCEL sip:552@192.168.1.52:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:1312 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #55 [Feb 27 20:17:45] DEBUG[7971]: app_dial.c:1671 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Feb 27 20:17:45] DEBUG[7971]: pbx.c:2317 __ast_pbx_run: Spawn extension (sip,552,2) exited non-zero on 'SIP/573-081c5df8' [Feb 27 20:17:45] == Spawn extension (sip, 552, 2) exited non-zero on 'SIP/573-081c5df8' [Feb 27 20:17:45] DEBUG[7941]: chan_sip.c:12124 sip_devicestate: Checking device state for peer 552 [Feb 27 20:17:45] DEBUG[7941]: devicestate.c:189 do_state_change: Changing state for SIP/552 - state 1 (Not in use) [Feb 27 20:17:45] DEBUG[7978]: app_queue.c:500 changethread: Device 'SIP/552' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'h' AND context = 'sip' AND priority = '1' [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'h' AND context = 'sip' AND priority = '1' [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'h' AND context = 'sip' AND priority = '1' [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'h' AND context = 'sip' AND priority = '1' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is 'SIP/552-081bf3b8' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '(null)' [Feb 27 20:17:45] -- Executing System("SIP/573-081c5df8", "/opt/fv/callstop asterisk-7937-1172600259.0 552 CANCEL SIP/552-081bf3b8 "" 1>/dev/null 2>/dev/null") [Feb 27 20:17:45] <-- SIP read from 192.168.1.73:5060: ACK sip:552@192.168.1.100 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;rport From: 573 ;tag=2722030966 To: "552" ;tag=as731fc553 Call-ID: 1712013045-28234116@192.168.1.73 CSeq: 2 ACK Proxy-Authorization: Digest username="573", realm="asterisk", nonce="7d956bb7", uri="sip:552@192.168.1.100", response="0d2573deda35e653ed27081e8c88e97c", algorithm=MD5 max-forwards: 70 Content-Length: 0 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: ACK sip:552@192.168.1.100 SIP/2.0 (33) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.73:5060;branch=z9hG4bK2450415364731510535;rport (74) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: 573 ;tag=2722030966 (48) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: "552" ;tag=as731fc553 (48) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 1712013045-28234116@192.168.1.73 (41) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 2 ACK (11) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Proxy-Authorization: Digest username="573", realm="asterisk", nonce="7d956bb7", uri="sip:552@192.168.1.100", response="0d2573deda35e653ed27081e8c88e97c", algorithm=MD5 (167) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: max-forwards: 70 (16) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: Content-Length: 0 (17) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 9: (0) [Feb 27 20:17:45] --- (9 headers 0 lines) --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:11534 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #53 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '1712013045-28234116@192.168.1.73' of Response 2: Match Found [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1200 retrans_pkt: SIP TIMER: Rescheduling retransmission #55 (1) CANCEL - 14 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1214 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 18 ms (t1 9 ms (Retrans id #55)) [Feb 27 20:17:45] Retransmitting #1 (no NAT) to 192.168.1.52:5060: CANCEL sip:552@192.168.1.52:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 27 20:17:45] DEBUG[7949]: sched.c:218 sched_settime: Request to schedule in the past?!?! [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1200 retrans_pkt: SIP TIMER: Rescheduling retransmission #55 (2) CANCEL - 14 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1214 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 36 ms (t1 9 ms (Retrans id #55)) [Feb 27 20:17:45] Retransmitting #2 (no NAT) to 192.168.1.52:5060: CANCEL sip:552@192.168.1.52:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:141 realtime_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten = 'h' AND context = 'sip' AND priority = '2' [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1200 retrans_pkt: SIP TIMER: Rescheduling retransmission #55 (3) CANCEL - 14 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1214 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 72 ms (t1 9 ms (Retrans id #55)) [Feb 27 20:17:45] Retransmitting #3 (no NAT) to 192.168.1.52:5060: CANCEL sip:552@192.168.1.52:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:674 mysql_reconnect: MySQL RealTime: Everything is fine. [Feb 27 20:17:45] DEBUG[7971]: res_config_mysql.c:261 realtime_multi_mysql: MySQL RealTime: Retrieve SQL: SELECT * FROM extensions_table WHERE exten LIKE '\\_%' AND context = 'sip' AND priority = '2' ORDER BY exten [Feb 27 20:17:45] DEBUG[7971]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. [Feb 27 20:17:45] DEBUG[7971]: cdr_addon_mysql.c:222 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO pbx_cdr1 (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,uniqueid) VALUES ('2007-02-27 20:17:39','\"Martyns\" <573>','573','552','sip', 'SIP/573-081c5df8','SIP/552-081bf3b8','System','/opt/fv/callstop asterisk-7937-1172600259.0 552 CANCEL SIP/552-081bf3b8 \"\" 1>/d',6,0,'NO ANSWER',3,'','asterisk-7937-1172600259.0') [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '"Martyns" <573>' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '573' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '552' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is 'sip' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is 'SIP/573-081c5df8' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is 'SIP/552-081bf3b8' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is 'System' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '/opt/fv/callstop asterisk-7937-1172600259.0 552 CANCEL SIP/552-081bf3b8 "" 1>/d' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '2007-02-27 20:17:39' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '(null)' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '2007-02-27 20:17:45' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '6' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '0' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is 'NO ANSWER' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '(null)' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is 'asterisk-7937-1172600259.0' [Feb 27 20:17:45] DEBUG[7971]: pbx.c:1523 pbx_substitute_variables_helper_full: Function result is '(null)' [Feb 27 20:17:45] DEBUG[7971]: channel.c:1395 ast_hangup: Hanging up channel 'SIP/573-081c5df8' [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:2418 sip_hangup: Hangup call SIP/573-081c5df8, SIP callid 1712013045-28234116@192.168.1.73) [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:2426 sip_hangup: update_call_counter(573) - decrement call limit counter [Feb 27 20:17:45] DEBUG[7971]: chan_sip.c:2208 update_call_counter: Updating call counter for incoming call [Feb 27 20:17:45] DEBUG[7941]: chan_sip.c:12124 sip_devicestate: Checking device state for peer 573 [Feb 27 20:17:45] DEBUG[7941]: devicestate.c:189 do_state_change: Changing state for SIP/573 - state 1 (Not in use) [Feb 27 20:17:45] DEBUG[7982]: app_queue.c:500 changethread: Device 'SIP/573' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 27 20:17:45] <-- SIP read from 192.168.1.52:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: ;tag=919014754 Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 CANCEL Contact: Content-Length: 0 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport (64) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: "Martyns" ;tag=as06fcf625 (54) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: ;tag=919014754 (45) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 (55) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 102 CANCEL (16) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Contact: (36) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: (0) [Feb 27 20:17:45] --- (8 headers 0 lines) --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1408 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #55 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' of Request 102: Match Found [Feb 27 20:17:45] Destroying call '1712013045-28234116@192.168.1.73' [Feb 27 20:17:45] <-- SIP read from 192.168.1.52:5060: SIP/2.0 487 Request Terminated Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: ;tag=919014754 Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 INVITE Content-Length: 0 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: SIP/2.0 487 Request Terminated (30) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport (64) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: "Martyns" ;tag=as06fcf625 (54) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: ;tag=919014754 (45) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 (55) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Content-Length: 0 (17) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: (0) [Feb 27 20:17:45] --- (7 headers 0 lines) --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' of Request 102: Match Not Found [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:9878 handle_response_invite: SIP response 487 to standard invite [Feb 27 20:17:45] Transmitting (no NAT) to 192.168.1.52:5060: ACK sip:552@192.168.1.52:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: ;tag=919014754 Contact: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:2208 update_call_counter: Updating call counter for outgoing call [Feb 27 20:17:45] <-- SIP read from 192.168.1.52:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: ;tag=919014754 Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 CANCEL Contact: Content-Length: 0 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport (64) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: "Martyns" ;tag=as06fcf625 (54) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: ;tag=919014754 (45) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 (55) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 102 CANCEL (16) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Contact: (36) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: (0) [Feb 27 20:17:45] --- (8 headers 0 lines) --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' of Request 102: Match Not Found [Feb 27 20:17:45] <-- SIP read from 192.168.1.52:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: ;tag=919014754 Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 CANCEL Contact: Content-Length: 0 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport (64) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: "Martyns" ;tag=as06fcf625 (54) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: ;tag=919014754 (45) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 (55) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 102 CANCEL (16) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Contact: (36) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: (0) [Feb 27 20:17:45] --- (8 headers 0 lines) --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' of Request 102: Match Not Found [Feb 27 20:17:45] <-- SIP read from 192.168.1.52:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport From: "Martyns" ;tag=as06fcf625 To: ;tag=919014754 Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 CSeq: 102 CANCEL Contact: Content-Length: 0 [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.100:5060;branch=z9hG4bK4c2e5bc6;rport (64) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 2: From: "Martyns" ;tag=as06fcf625 (54) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 3: To: ;tag=919014754 (45) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 4: Call-ID: 304d6f2d067e273a223fbf9073f8cffc@192.168.1.100 (55) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 5: CSeq: 102 CANCEL (16) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 6: Contact: (36) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 7: Content-Length: 0 (17) [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:3429 parse_request: Header 8: (0) [Feb 27 20:17:45] --- (8 headers 0 lines) --- [Feb 27 20:17:45] DEBUG[7949]: chan_sip.c:1420 __sip_ack: Stopping retransmission on '304d6f2d067e273a223fbf9073f8cffc@192.168.1.100' of Request 102: Match Not Found *CLI> stop now [Feb 27 20:17:53] Beginning asterisk shutdown.... [Feb 27 20:17:53] Executing last minute cleanups [Feb 27 20:17:53] == Destroying musiconhold processes [Feb 27 20:17:53] Asterisk cleanly ending (0). [Feb 27 20:17:53] DEBUG[7937]: asterisk.c:901 quit_handler: Asterisk ending (0).