Asterisk 1.2.11, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'show license' for details. ========================================================================= Connected to Asterisk 1.2.11 currently running on ops3 (pid = 23943) ops3*CLI> -- Remote UNIX connection Verbosity is at least 4 ops3*CLI> 2006-08-24 17:13:04 DEBUG[24032]: chan_sip.c:1332 __sip_autodestruct: Auto destroying call '9964BC2D-1C14-4D67-A9BB-87A7063E8192@192.168.1.65' ops3*CLI> s 2006-08-24 17:13:04 DEBUG[24032]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.65 with 192.168.1.0 ops3*CLI> s 2006-08-24 17:13:04 DEBUG[24032]: chan_sip.c:3159 sip_alloc: Allocating new SIP dialog for 6212AB07-B06A-4B55-A233-EB58566715C9@192.168.1.65 - OPTIONS (No RTP) ops3*CLI> s 2006-08-24 17:13:04 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS ops3*CLI> sip debug ops3*CLI> SIP Debugging enabled ops3*CLI> <-- SIP read from 192.168.1.65:5060: INVITE sip:18@ops3.opschile.cl SIP/2.0 Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000076e900004af0 Content-Length: 159 Contact: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 Content-Type: application/sdp CSeq: 1 INVITE From: "unknown";tag=11435264015802 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3365442793 3365442793 IN IP4 192.168.1.65 s=SJphone c=IN IP4 192.168.1.65 t=0 0 a=direction:active m=audio 49280 RTP/AVP 3 a=rtpmap:3 GSM/8000 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: INVITE sip:18@ops3.opschile.cl SIP/2.0 (38) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000076e900004af0 (90) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: Content-Length: 159 (19) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: Contact: (40) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 (58) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: Content-Type: application/sdp (29) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: CSeq: 1 INVITE (14) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: From: "unknown";tag=11435264015802 (64) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: Max-Forwards: 70 (16) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: To: (29) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: (0) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: v=0 (3) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: o=- 3365442793 3365442793 IN IP4 192.168.1.65 (45) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: s=SJphone (9) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: c=IN IP4 192.168.1.65 (21) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: t=0 0 (5) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=direction:active (18) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: m=audio 49280 RTP/AVP 3 (23) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:3 GSM/8000 (19) --- (11 headers 8 lines)--- 2006-08-24 17:13:09 DEBUG[24032]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.65 with 192.168.1.0 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3159 sip_alloc: Allocating new SIP dialog for CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 - INVITE (With RTP) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 Sending to 192.168.1.65 : 5060 (NAT) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:7167 check_user_full: Setting NAT on RTP to 0 Reliably Transmitting (no NAT) to 192.168.1.65:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000076e900004af0;received=192.168.1.65 From: "unknown";tag=11435264015802 To: ;tag=as5f79e8f2 Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest algorithm=MD5, realm="opschile.cl", nonce="2101ff79" Content-Length: 0 --- 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #33 Scheduling destruction of call 'CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65' in 15000 ms Found user '6528516' ops3*CLI> <-- SIP read from 192.168.1.65:5060: ACK sip:18@ops3.opschile.cl SIP/2.0 Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000076e900004af0 Content-Length: 0 Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 CSeq: 1 ACK From: "unknown";tag=11435264015802 Max-Forwards: 70 To: ;tag=as5f79e8f2 User-Agent: SJphone/1.60.289a (SJ Labs) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: ACK sip:18@ops3.opschile.cl SIP/2.0 (35) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000076e900004af0 (90) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: Content-Length: 0 (17) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 (58) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: CSeq: 1 ACK (11) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: From: "unknown";tag=11435264015802 (64) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: Max-Forwards: 70 (16) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: To: ;tag=as5f79e8f2 (44) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: (0) --- (9 headers 0 lines)--- 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received ACK (6) - Command in SIP ACK 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #33 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:1410 __sip_ack: Stopping retransmission on 'CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65' of Response 1: Match Found ops3*CLI> <-- SIP read from 192.168.1.65:5060: INVITE sip:18@ops3.opschile.cl SIP/2.0 Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000001ab00004af1 Content-Length: 159 Contact: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 Content-Type: application/sdp CSeq: 2 INVITE From: "unknown";tag=11435264015802 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Proxy-Authorization: Digest username="6528516",realm="opschile.cl",nonce="2101ff79",uri="sip:18@ops3.opschile.cl",response="d32c695933b831bdf2becf9296829a60",algorithm="MD5" v=0 o=- 3365442793 3365442793 IN IP4 192.168.1.65 s=SJphone c=IN IP4 192.168.1.65 t=0 0 a=direction:active m=audio 49280 RTP/AVP 3 a=rtpmap:3 GSM/8000 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: INVITE sip:18@ops3.opschile.cl SIP/2.0 (38) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000001ab00004af1 (90) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: Content-Length: 159 (19) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: Contact: (40) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 (58) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: Content-Type: application/sdp (29) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: CSeq: 2 INVITE (14) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: From: "unknown";tag=11435264015802 (64) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: Max-Forwards: 70 (16) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: To: (29) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: Proxy-Authorization: Digest username="6528516",realm="opschile.cl",nonce="2101ff79",uri="sip:18@ops3.opschile.cl",response="d32c695933b831bdf2becf9296829a60",algorithm="MD5" (173) ops3*CLI> 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 12: (0) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: v=0 (3) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: o=- 3365442793 3365442793 IN IP4 192.168.1.65 (45) ops3*CLI> 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: s=SJphone (9) ops3*CLI> 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: c=IN IP4 192.168.1.65 (21) ops3*CLI> 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: t=0 0 (5) ops3*CLI> 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=direction:active (18) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: m=audio 49280 RTP/AVP 3 (23) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:3 GSM/8000 (19) --- (12 headers 8 lines)--- ops3*CLI> 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 Sending to 192.168.1.65 : 5060 (NAT) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:7167 check_user_full: Setting NAT on RTP to 0 Found user '6528516' Found RTP audio format 3 Peer audio RTP is at port 192.168.1.65:49280 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3614 process_sdp: Peer audio RTP is at port 192.168.1.65:49280 Found description format GSM Capabilities: us - 0x2 (gsm), peer - audio=0x2 (gsm)/video=0x0 (nothing), combined - 0x2 (gsm) ops3*CLI> Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:10517 handle_request_invite: Checking SIP call limits for device 6528516 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:2215 update_call_counter: Updating call counter for incoming call Looking for 18 in outgoing_full (domain ops3.opschile.cl) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:6145 build_route: build_route: Contact hop: list_route: hop: Transmitting (no NAT) to 192.168.1.65:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000001ab00004af1;received=192.168.1.65 From: "unknown";tag=11435264015802 To: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- 2006-08-24 17:13:09 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528516 2006-08-24 17:13:09 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528516 - state 2 (In use) ops3*CLI> 2006-08-24 17:13:09 DEBUG[24045]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' -- Executing Dial("SIP/6528516-08a90fc0", "SIP/6528518|30") in new stack 2006-08-24 17:13:09 DEBUG[24046]: app_queue.c:490 changethread: Device 'SIP/6528516' changed to state '2' (In use) but we don't care because they're not a member of any queue. 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3159 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:1883 create_addr_from_peer: Setting NAT on RTP to 0 2006-08-24 17:13:09 DEBUG[24045]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.198 with 192.168.1.0 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2869 ast_channel_inherit_variables: Not copying variable STACK-outgoing_full-18-1. 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2869 ast_channel_inherit_variables: Not copying variable SIPCALLID. 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2869 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2869 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2869 ast_channel_inherit_variables: Not copying variable SIPURI. 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:2077 sip_call: Outgoing Call for 6528518 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:2215 update_call_counter: Updating call counter for outgoing call We're at 192.168.1.3 port 14824 Adding codec 0x10 (g726) to SDP 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 0: INVITE sip:6528518@192.168.1.198:45057 SIP/2.0 (46) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport (62) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 2: From: "6528516" ;tag=as34e1b61d (56) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 3: To: (37) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 4: Contact: (34) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 5: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 (53) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 6: CSeq: 102 INVITE (16) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 7: User-Agent: Asterisk PBX (24) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 8: Max-Forwards: 70 (16) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 9: Date: Thu, 24 Aug 2006 21:13:09 GMT (35) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 11: Content-Type: application/sdp (29) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 12: Content-Length: 165 (19) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3375 parse_request: Header 13: (0) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3407 parse_request: Line: v=0 (3) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3407 parse_request: Line: o=root 23943 23943 IN IP4 192.168.1.3 (37) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3407 parse_request: Line: s=session (9) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3407 parse_request: Line: c=IN IP4 192.168.1.3 (20) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3407 parse_request: Line: t=0 0 (5) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3407 parse_request: Line: m=audio 14824 RTP/AVP 111 (25) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3407 parse_request: Line: a=rtpmap:111 G726-32/8000 (25) 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:3407 parse_request: Line: a=silenceSupp:off - - - - (25) 13 headers, 8 lines ops3*CLI> Reliably Transmitting (no NAT) to 192.168.1.198:45057: INVITE sip:6528518@192.168.1.198:45057 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport From: "6528516" ;tag=as34e1b61d To: Contact: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:13:09 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 165 v=0 o=root 23943 23943 IN IP4 192.168.1.3 s=session c=IN IP4 192.168.1.3 t=0 0 m=audio 14824 RTP/AVP 111 a=rtpmap:111 G726-32/8000 a=silenceSupp:off - - - - --- 2006-08-24 17:13:09 DEBUG[24045]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #35 -- Called 6528518 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2376 set_format: Set channel SIP/6528518-08a883f0 to read format slin ops3*CLI> 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2376 set_format: Set channel SIP/6528516-08a90fc0 to write format slin 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2376 set_format: Set channel SIP/6528516-08a90fc0 to read format slin ops3*CLI> 2006-08-24 17:13:09 DEBUG[24045]: channel.c:2376 set_format: Set channel SIP/6528518-08a883f0 to write format slin ops3*CLI> <-- SIP read from 192.168.1.198:45057: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport From: "6528516" ;tag=as34e1b61d To: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 CSeq: 102 INVITE User-Agent: Grandstream HT287 1.0.8.23 Content-Length: 0 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: SIP/2.0 100 Trying (18) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport (62) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528516" ;tag=as34e1b61d (56) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: (37) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 (53) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: CSeq: 102 INVITE (16) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: Content-Length: 0 (17) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: (0) --- (8 headers 0 lines)--- 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:1454 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #35 - INVITE (got response) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:1463 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3' Request 102: Found 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:9596 handle_response_invite: SIP response 100 to standard invite ops3*CLI> <-- SIP read from 192.168.1.198:45057: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport From: "6528516" ;tag=as34e1b61d To: ;tag=d4f77e96bcd0f76f Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 CSeq: 102 INVITE User-Agent: Grandstream HT287 1.0.8.23 Content-Length: 0 ops3*CLI> 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: SIP/2.0 180 Ringing (19) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport (62) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528516" ;tag=as34e1b61d (56) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: ;tag=d4f77e96bcd0f76f (58) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 (53) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: CSeq: 102 INVITE (16) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: Content-Length: 0 (17) 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: (0) --- (8 headers 0 lines)--- 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:1463 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3' Request 102: Found 2006-08-24 17:13:09 DEBUG[24032]: chan_sip.c:9596 handle_response_invite: SIP response 180 to standard invite -- SIP/6528518-08a883f0 is ringing ops3*CLI> Transmitting (no NAT) to 192.168.1.65:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000001ab00004af1;received=192.168.1.65 From: "unknown";tag=11435264015802 To: ;tag=as370b6861 Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 ops3*CLI> --- 2006-08-24 17:13:09 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528518 ops3*CLI> 2006-08-24 17:13:09 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528518 - state 6 (Ringing) ops3*CLI> 2006-08-24 17:13:09 DEBUG[24047]: app_queue.c:490 changethread: Device 'SIP/6528518' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. ops3*CLI> <-- SIP read from 192.168.1.192:53035: INVITE sip:*8@ops3.opschile.cl SIP/2.0 Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK06cc0cbeb789edfe From: "6528519" ;tag=0c8aa043aec1a5f3 To: Contact: Supported: replaces, timer Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51884 INVITE User-Agent: Grandstream HT287 1.0.8.23 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Type: application/sdp Content-Length: 307 v=0 o=6528519 8000 8000 IN IP4 192.168.1.192 s=SIP Call c=IN IP4 192.168.1.192 t=0 0 m=audio 16462 RTP/AVP 2 8 0 97 18 4 a=sendrecv a=rtpmap:2 G726-32/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=ptime:20 ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: INVITE sip:*8@ops3.opschile.cl SIP/2.0 (38) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK06cc0cbeb789edfe (67) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528519" ;tag=0c8aa043aec1a5f3 (67) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: (29) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Contact: (42) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: Supported: replaces, timer (26) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: Call-ID: e9e33a9139008c14@192.168.1.192 (39) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: CSeq: 51884 INVITE (18) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: Max-Forwards: 70 (16) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: Content-Type: application/sdp (29) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 12: Content-Length: 307 (19) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 13: (0) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: v=0 (3) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: o=6528519 8000 8000 IN IP4 192.168.1.192 (40) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: s=SIP Call (10) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: c=IN IP4 192.168.1.192 (22) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: t=0 0 (5) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: m=audio 16462 RTP/AVP 2 8 0 97 18 4 (35) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=sendrecv (10) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=fmtp:97 mode=20 (17) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:18 G729/8000 (21) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:4 G723/8000 (20) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=ptime:20 (10) ops3*CLI> --- (13 headers 15 lines)--- ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.192 with 192.168.1.0 ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3159 sip_alloc: Allocating new SIP dialog for e9e33a9139008c14@192.168.1.192 - INVITE (With RTP) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received INVITE (5) - Command in SIP INVITE ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1013 parse_sip_options: Begin: parsing SIP "Supported: replaces, timer" ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1025 parse_sip_options: Found SIP option: -replaces- 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1031 parse_sip_options: Matched SIP option: replaces 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1025 parse_sip_options: Found SIP option: -timer- 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1031 parse_sip_options: Matched SIP option: timer 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1042 parse_sip_options: * SIP extension value: 5 for call e9e33a9139008c14@192.168.1.192 Using INVITE request as basis request - e9e33a9139008c14@192.168.1.192 Sending to 192.168.1.192 : 53035 (non-NAT) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:7167 check_user_full: Setting NAT on RTP to 0 Reliably Transmitting (no NAT) to 192.168.1.192:53035: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK06cc0cbeb789edfe;received=192.168.1.192 From: "6528519" ;tag=0c8aa043aec1a5f3 To: ;tag=as337422ae Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51884 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest algorithm=MD5, realm="opschile.cl", nonce="5b94054e" Content-Length: 0 --- 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #37 Scheduling destruction of call 'e9e33a9139008c14@192.168.1.192' in 15000 ms Found user '6528519' ops3*CLI> <-- SIP read from 192.168.1.192:53035: ACK sip:*8@ops3.opschile.cl SIP/2.0 Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK06cc0cbeb789edfe From: "6528519" ;tag=0c8aa043aec1a5f3 To: ;tag=as337422ae Contact: Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51884 ACK User-Agent: Grandstream HT287 1.0.8.23 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Length: 0 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: ACK sip:*8@ops3.opschile.cl SIP/2.0 (35) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK06cc0cbeb789edfe (67) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528519" ;tag=0c8aa043aec1a5f3 (67) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: ;tag=as337422ae (44) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Contact: (42) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: Call-ID: e9e33a9139008c14@192.168.1.192 (39) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: CSeq: 51884 ACK (15) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: Max-Forwards: 70 (16) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: Content-Length: 0 (17) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: (0) --- (11 headers 0 lines)--- 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received ACK (6) - Command in SIP ACK 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #37 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1410 __sip_ack: Stopping retransmission on 'e9e33a9139008c14@192.168.1.192' of Response 51884: Match Found ops3*CLI> <-- SIP read from 192.168.1.192:53035: INVITE sip:*8@ops3.opschile.cl SIP/2.0 Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKa591fa84055f60ac From: "6528519" ;tag=0c8aa043aec1a5f3 To: Contact: Supported: replaces, timer Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@ops3.opschile.cl", nonce="5b94054e", response="62540689077d26704cdf8cbdc319fdd0" Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51885 INVITE User-Agent: Grandstream HT287 1.0.8.23 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Type: application/sdp Content-Length: 307 v=0 o=6528519 8000 8001 IN IP4 192.168.1.192 s=SIP Call c=IN IP4 192.168.1.192 t=0 0 m=audio 16462 RTP/AVP 2 8 0 97 18 4 a=sendrecv a=rtpmap:2 G726-32/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=ptime:20 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: INVITE sip:*8@ops3.opschile.cl SIP/2.0 (38) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKa591fa84055f60ac (67) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528519" ;tag=0c8aa043aec1a5f3 (67) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: (29) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Contact: (42) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: Supported: replaces, timer (26) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@ops3.opschile.cl", nonce="5b94054e", response="62540689077d26704cdf8cbdc319fdd0" (176) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: Call-ID: e9e33a9139008c14@192.168.1.192 (39) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: CSeq: 51885 INVITE (18) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: Max-Forwards: 70 (16) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 12: Content-Type: application/sdp (29) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 13: Content-Length: 307 (19) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 14: (0) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: v=0 (3) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: o=6528519 8000 8001 IN IP4 192.168.1.192 (40) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: s=SIP Call (10) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: c=IN IP4 192.168.1.192 (22) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: t=0 0 (5) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: m=audio 16462 RTP/AVP 2 8 0 97 18 4 (35) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=sendrecv (10) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=fmtp:97 mode=20 (17) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:18 G729/8000 (21) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=rtpmap:4 G723/8000 (20) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3407 parse_request: Line: a=ptime:20 (10) --- (14 headers 15 lines)--- 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - e9e33a9139008c14@192.168.1.192 Sending to 192.168.1.192 : 53035 (non-NAT) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:7167 check_user_full: Setting NAT on RTP to 0 ops3*CLI> Found user '6528519' Found RTP audio format 2 Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 97 Found RTP audio format 18 Found RTP audio format 4 Peer audio RTP is at port 192.168.1.192:16462 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3614 process_sdp: Peer audio RTP is at port 192.168.1.192:16462 Found description format G726-32 Found description format PCMA Found description format PCMU Found description format iLBC Found description format G729 Found description format G723 Capabilities: us - 0x10 (g726), peer - audio=0x51d (g723|ulaw|alaw|g726|g729|ilbc)/video=0x0 (nothing), combined - 0x10 (g726) Non-codec capabilities: us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:10517 handle_request_invite: Checking SIP call limits for device 6528519 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:2215 update_call_counter: Updating call counter for incoming call Looking for *8 in outgoing_full (domain ops3.opschile.cl) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:6145 build_route: build_route: Contact hop: list_route: hop: Transmitting (no NAT) to 192.168.1.192:53035: SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKa591fa84055f60ac;received=192.168.1.192 From: "6528519" ;tag=0c8aa043aec1a5f3 To: Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51885 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: res_features.c:1947 ast_pickup_call: Call pickup on chan 'SIP/6528518-08a883f0' by 'SIP/6528519-08ad1820' ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:2546 sip_answer: sip_answer(SIP/6528519-08ad1820) We're at 192.168.1.3 port 12566 Adding codec 0x10 (g726) to SDP ops3*CLI> Reliably Transmitting (no NAT) to 192.168.1.192:53035: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKa591fa84055f60ac;received=192.168.1.192 From: "6528519" ;tag=0c8aa043aec1a5f3 To: ;tag=as194375c2 Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51885 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 161 v=0 o=root 23943 23943 IN IP4 192.168.1.3 s=session c=IN IP4 192.168.1.3 t=0 0 m=audio 12566 RTP/AVP 2 a=rtpmap:2 G726-32/8000 a=silenceSupp:off - - - - --- 2006-08-24 17:13:12 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528519 ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #39 2006-08-24 17:13:12 DEBUG[24032]: channel.c:2801 ast_channel_masquerade: Planning to masquerade channel SIP/6528519-08ad1820 into the structure of SIP/6528518-08a883f0 2006-08-24 17:13:12 DEBUG[24032]: channel.c:2814 ast_channel_masquerade: Done planning to masquerade channel SIP/6528519-08ad1820 into the structure of SIP/6528518-08a883f0 2006-08-24 17:13:12 DEBUG[23996]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6528519-08ad1820' ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: channel.c:2926 ast_do_masquerade: Actually Masquerading SIP/6528519-08ad1820(0) into the structure of SIP/6528518-08a883f0(5) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: channel.c:2937 ast_do_masquerade: Got clone lock for masquerade on 'SIP/6528519-08ad1820' at 0x8ad790c ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: chan_sip.c:2424 sip_hangup: Hangup call SIP/6528519-08ad1820, SIP callid 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: chan_sip.c:2432 sip_hangup: update_call_counter(6528518) - decrement call limit counter ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: chan_sip.c:2215 update_call_counter: Updating call counter for outgoing call ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: chan_sip.c:1388 __sip_ack: Acked pending invite 102 ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: chan_sip.c:1410 __sip_ack: Stopping retransmission on '574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3' of Request 102: Match Found ops3*CLI> Reliably Transmitting (no NAT) to 192.168.1.198:45057: CANCEL sip:6528518@192.168.1.198:45057 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport From: "6528516" ;tag=as34e1b61d To: Contact: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- 2006-08-24 17:13:12 DEBUG[24045]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #40 Scheduling destruction of call '574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3' in 32000 ms 2006-08-24 17:13:12 DEBUG[23996]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6528519-08ad1820' ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: channel.c:3098 ast_do_masquerade: Putting channel SIP/6528519-08ad1820 in 64/64 formats 2006-08-24 17:13:12 DEBUG[24045]: channel.c:3118 ast_do_masquerade: Destroying channel clone 'SIP/6528518-08a883f0' 2006-08-24 17:13:12 DEBUG[24045]: channel.c:3142 ast_do_masquerade: Done Masquerading SIP/6528519-08ad1820 (0) ops3*CLI> -- SIP/6528519-08ad1820 answered SIP/6528516-08a90fc0 ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: chan_sip.c:2546 sip_answer: sip_answer(SIP/6528516-08a90fc0) ops3*CLI> We're at 192.168.1.3 port 15764 ops3*CLI> Adding codec 0x2 (gsm) to SDP ops3*CLI> Reliably Transmitting (no NAT) to 192.168.1.65:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee1669000001ab00004af1;received=192.168.1.65 From: "unknown";tag=11435264015802 To: ;tag=as370b6861 Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Type: application/sdp Content-Length: 157 v=0 o=root 23943 23943 IN IP4 192.168.1.3 s=session c=IN IP4 192.168.1.3 t=0 0 m=audio 15764 RTP/AVP 3 a=rtpmap:3 GSM/8000 a=silenceSupp:off - - - - --- 2006-08-24 17:13:12 DEBUG[24045]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #42 ops3*CLI> -- Attempting native bridge of SIP/6528516-08a90fc0 and SIP/6528519-08ad1820 ops3*CLI> 2006-08-24 17:13:12 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 2 (In use) 2006-08-24 17:13:12 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528519 2006-08-24 17:13:12 DEBUG[23996]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6528519-08ad1820' ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: rtp.c:1603 ast_rtp_bridge: Channel codec0 = 2 is not codec1 = 1309, cannot native bridge in RTP. ops3*CLI> 2006-08-24 17:13:12 DEBUG[24048]: app_queue.c:490 changethread: Device 'SIP/6528519' changed to state '2' (In use) but we don't care because they're not a member of any queue. ops3*CLI> 2006-08-24 17:13:12 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 2 (In use) 2006-08-24 17:13:12 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528519 2006-08-24 17:13:12 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 2 (In use) 2006-08-24 17:13:12 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528518 2006-08-24 17:13:12 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528518 - state 1 (Not in use) 2006-08-24 17:13:12 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528519 ops3*CLI> 2006-08-24 17:13:12 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 2 (In use) ops3*CLI> 2006-08-24 17:13:12 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528516 ops3*CLI> 2006-08-24 17:13:12 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528516 - state 2 (In use) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24052]: app_queue.c:490 changethread: Device 'SIP/6528519' changed to state '2' (In use) but we don't care because they're not a member of any queue. ops3*CLI> 2006-08-24 17:13:12 DEBUG[24051]: app_queue.c:490 changethread: Device 'SIP/6528518' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. ops3*CLI> 2006-08-24 17:13:12 DEBUG[24050]: app_queue.c:490 changethread: Device 'SIP/6528519' changed to state '2' (In use) but we don't care because they're not a member of any queue. ops3*CLI> 2006-08-24 17:13:12 DEBUG[24049]: app_queue.c:490 changethread: Device 'SIP/6528519' changed to state '2' (In use) but we don't care because they're not a member of any queue. ops3*CLI> 2006-08-24 17:13:12 DEBUG[24053]: app_queue.c:490 changethread: Device 'SIP/6528516' changed to state '2' (In use) but we don't care because they're not a member of any queue. ops3*CLI> <-- SIP read from 192.168.1.198:45057: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport From: "6528516" ;tag=as34e1b61d To: ;tag=d4f77e96bcd0f76f Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 CSeq: 102 CANCEL User-Agent: Grandstream HT287 1.0.8.23 Contact: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE Supported: replaces, timer Content-Length: 0 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: SIP/2.0 200 OK (14) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport (62) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528516" ;tag=as34e1b61d (56) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: ;tag=d4f77e96bcd0f76f (58) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 (53) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: CSeq: 102 CANCEL (16) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: Contact: (42) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: Supported: replaces, timer (26) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: Content-Length: 0 (17) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: (0) --- (11 headers 0 lines)--- ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #40 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1410 __sip_ack: Stopping retransmission on '574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3' of Request 102: Match Found <-- SIP read from 192.168.1.65:5060: ACK sip:18@192.168.1.3 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee166c00004a2700004af5 Content-Length: 0 Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 CSeq: 2 ACK From: "unknown";tag=11435264015802 Max-Forwards: 70 To: ;tag=as370b6861 User-Agent: SJphone/1.60.289a (SJ Labs) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: ACK sip:18@192.168.1.3 SIP/2.0 (30) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000fe244ee166c00004a2700004af5 (90) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 (58) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: CSeq: 2 ACK (11) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: From: "unknown";tag=11435264015802 (64) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: Max-Forwards: 70 (16) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: To: ;tag=as370b6861 (44) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: (0) --- (9 headers 0 lines)--- 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received ACK (6) - Command in SIP ACK 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #42 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1410 __sip_ack: Stopping retransmission on 'CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65' of Response 2: Match Found ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> <-- SIP read from 192.168.1.192:53035: ACK sip:*8@192.168.1.3 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKcb582fceab589ece From: "6528519" ;tag=0c8aa043aec1a5f3 To: ;tag=as194375c2 Contact: Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@192.168.1.3", nonce="5b94054e", response="75da4dd054e6855be02b0cf7ba3ba62c" Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51885 ACK User-Agent: Grandstream HT287 1.0.8.23 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Length: 0 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: ACK sip:*8@192.168.1.3 SIP/2.0 (30) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKcb582fceab589ece (67) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528519" ;tag=0c8aa043aec1a5f3 (67) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: ;tag=as194375c2 (44) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Contact: (42) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@192.168.1.3", nonce="5b94054e", response="75da4dd054e6855be02b0cf7ba3ba62c" (171) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: Call-ID: e9e33a9139008c14@192.168.1.192 (39) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: CSeq: 51885 ACK (15) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: Max-Forwards: 70 (16) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: Content-Length: 0 (17) 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 12: (0) --- (12 headers 0 lines)--- 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received ACK (6) - Command in SIP ACK 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #39 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1410 __sip_ack: Stopping retransmission on 'e9e33a9139008c14@192.168.1.192' of Response 51885: Match Found ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> <-- SIP read from 192.168.1.198:45057: SIP/2.0 487 Request Cancelled Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport From: "6528516" ;tag=as34e1b61d To: ;tag=d4f77e96bcd0f76f Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 CSeq: 102 INVITE User-Agent: Grandstream HT287 1.0.8.23 Content-Length: 0 ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: SIP/2.0 487 Request Cancelled (29) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport (62) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528516" ;tag=as34e1b61d (56) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: ;tag=d4f77e96bcd0f76f (58) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 (53) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: CSeq: 102 INVITE (16) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: User-Agent: Grandstream HT287 1.0.8.23 (38) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: (0) --- (8 headers 0 lines)--- 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:1410 __sip_ack: Stopping retransmission on '574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3' of Request 102: Match Not Found 2006-08-24 17:13:12 DEBUG[24032]: chan_sip.c:2215 update_call_counter: Updating call counter for outgoing call 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) Transmitting (no NAT) to 192.168.1.198:45057: ACK sip:6528518@192.168.1.198:45057 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0cf65fd3;rport From: "6528516" ;tag=as34e1b61d To: ;tag=d4f77e96bcd0f76f Contact: Call-ID: 574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Destroying call '574006ca377f5e3c0f4dedbf4702ddff@192.168.1.3' ops3*CLI> 2006-08-24 17:13:12 DEBUG[24045]: rtp.c:1353 ast_rtp_write: Ooh, format changed from unknown to gsm ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:12 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3159 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.191 with 192.168.1.0 ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: OPTIONS sip:6528517@192.168.1.191:30954 SIP/2.0 (47) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0fec3bb5;rport (62) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "asterisk" ;tag=as34686977 (58) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: (37) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Contact: (35) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: Call-ID: 42ee5c8d1cf3b69228983a6d31a711bc@192.168.1.3 (53) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: CSeq: 102 OPTIONS (17) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: User-Agent: Asterisk PBX (24) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: Max-Forwards: 70 (16) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: Date: Thu, 24 Aug 2006 21:13:13 GMT (35) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 12: (0) ops3*CLI> 12 headers, 0 lines ops3*CLI> Reliably Transmitting (no NAT) to 192.168.1.191:30954: OPTIONS sip:6528517@192.168.1.191:30954 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0fec3bb5;rport From: "asterisk" ;tag=as34686977 To: Contact: Call-ID: 42ee5c8d1cf3b69228983a6d31a711bc@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:13:13 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- ops3*CLI> 2006-08-24 17:13:13 DEBUG[24032]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #43 ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:13 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:1188 retrans_pkt: SIP TIMER: Not rescheduling id #43:OPTIONS (Method 3) (No timer T1) ops3*CLI> Retransmitting #1 (no NAT) to 192.168.1.191:30954: OPTIONS sip:6528517@192.168.1.191:30954 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0fec3bb5;rport From: "asterisk" ;tag=as34686977 To: Contact: Call-ID: 42ee5c8d1cf3b69228983a6d31a711bc@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:13:13 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> 2006-08-24 17:13:14 WARNING[24045]: chan_sip.c:2561 sip_write: Asked to transmit frame type 64, while native formats is 16 (read/write = 64/64) ops3*CLI> <-- SIP read from 192.168.1.192:53035: BYE sip:*8@192.168.1.3 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK0e1c10589895f109 From: "6528519" ;tag=0c8aa043aec1a5f3 To: ;tag=as194375c2 Supported: replaces, timer Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@192.168.1.3", nonce="5b94054e", response="a097d0f3a4bc9ceb33097edfbc35dafe" Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51886 BYE User-Agent: Grandstream HT287 1.0.8.23 Max-Forwards: 70 Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE Content-Length: 0 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: BYE sip:*8@192.168.1.3 SIP/2.0 (30) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK0e1c10589895f109 (67) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: From: "6528519" ;tag=0c8aa043aec1a5f3 (67) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: To: ;tag=as194375c2 (44) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: Supported: replaces, timer (26) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@192.168.1.3", nonce="5b94054e", response="a097d0f3a4bc9ceb33097edfbc35dafe" (171) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: Call-ID: e9e33a9139008c14@192.168.1.192 (39) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: CSeq: 51886 BYE (15) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 9: Max-Forwards: 70 (16) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 11: Content-Length: 0 (17) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 12: (0) --- (12 headers 0 lines)--- 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:11160 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.1.192 : 53035 (non-NAT) ops3*CLI> Transmitting (no NAT) to 192.168.1.192:53035: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK0e1c10589895f109;received=192.168.1.192 From: "6528519" ;tag=0c8aa043aec1a5f3 To: ;tag=as194375c2 Call-ID: e9e33a9139008c14@192.168.1.192 CSeq: 51886 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing --- 2006-08-24 17:13:14 DEBUG[24045]: channel.c:3321 ast_generic_bridge: Didn't get a frame from channel: SIP/6528519-08ad1820 2006-08-24 17:13:14 DEBUG[24045]: channel.c:3604 ast_channel_bridge: Bridge stops bridging channels SIP/6528516-08a90fc0 and SIP/6528519-08ad1820 2006-08-24 17:13:14 DEBUG[24045]: channel.c:1342 ast_hangup: Hanging up channel 'SIP/6528519-08ad1820' 2006-08-24 17:13:14 DEBUG[24045]: chan_sip.c:2424 sip_hangup: Hangup call SIP/6528519-08ad1820, SIP callid e9e33a9139008c14@192.168.1.192) 2006-08-24 17:13:14 DEBUG[24045]: chan_sip.c:2432 sip_hangup: update_call_counter(6528519) - decrement call limit counter 2006-08-24 17:13:14 DEBUG[24045]: chan_sip.c:2215 update_call_counter: Updating call counter for incoming call 2006-08-24 17:13:14 DEBUG[24045]: app_dial.c:1635 dial_exec_full: Exiting with DIALSTATUS=ANSWER. 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:2316 __ast_pbx_run: Spawn extension (outgoing_full,18,1) exited non-zero on 'SIP/6528516-08a90fc0' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: cdr_addon_mysql.c:222 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) VALUES ('2006-08-24 17:13:09','\"6528516\" <6528516>','6528516','18','outgoing_full', 'SIP/6528516-08a90fc0','SIP/6528519-08ad1820','Dial','SIP/6528518|30',5,2,'ANSWERED',3,'') ops3*CLI> 2006-08-24 17:13:14 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528519 ops3*CLI> 2006-08-24 17:13:14 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 1 (Not in use) ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"6528516" <6528516>' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6528516' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '18' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'outgoing_full' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6528516-08a90fc0' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6528519-08ad1820' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6528518|30' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-24 17:13:09' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-24 17:13:12' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-24 17:13:14' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '5' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1156453989.0' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: channel.c:1342 ast_hangup: Hanging up channel 'SIP/6528516-08a90fc0' ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: chan_sip.c:2424 sip_hangup: Hangup call SIP/6528516-08a90fc0, SIP callid CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65) ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: chan_sip.c:2432 sip_hangup: update_call_counter(6528516) - decrement call limit counter ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: chan_sip.c:2215 update_call_counter: Updating call counter for incoming call set_destination: Parsing for address/port to send to ops3*CLI> set_destination: set destination to 192.168.1.65, port 5060 ops3*CLI> 2006-08-24 17:13:14 DEBUG[24054]: app_queue.c:490 changethread: Reliably Transmitting (no NAT) to 192.168.1.65:5060: BYE sip:6528516@192.168.1.65:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK1866e4f9;rport From: ;tag=as370b6861 To: "unknown";tag=11435264015802 Contact: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- ops3*CLI> Device 'SIP/6528519' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. ops3*CLI> 2006-08-24 17:13:14 DEBUG[24045]: chan_sip.c:1302 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #45 ops3*CLI> 2006-08-24 17:13:14 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528516 ops3*CLI> 2006-08-24 17:13:14 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528516 - state 1 (Not in use) ops3*CLI> 2006-08-24 17:13:14 DEBUG[24055]: app_queue.c:490 changethread: Device 'SIP/6528516' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. ops3*CLI> <-- SIP read from 192.168.1.65:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.1.3:5060;rport=5060;received=192.168.1.3;branch=z9hG4bK1866e4f9 Content-Length: 0 Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 CSeq: 102 BYE From: ;tag=as370b6861 Server: SJphone/1.60.289a (SJ Labs) To: "unknown";tag=11435264015802 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 0: SIP/2.0 200 OK (14) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;rport=5060;received=192.168.1.3;branch=z9hG4bK1866e4f9 (88) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 2: Content-Length: 0 (17) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 3: Call-ID: CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65 (58) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 4: CSeq: 102 BYE (13) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 5: From: ;tag=as370b6861 (46) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 6: Server: SJphone/1.60.289a (SJ Labs) (35) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 7: To: "unknown";tag=11435264015802 (62) 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:3375 parse_request: Header 8: (0) --- (8 headers 0 lines)--- 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:1399 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #45 2006-08-24 17:13:14 DEBUG[24032]: chan_sip.c:1410 __sip_ack: Stopping retransmission on 'CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65' of Request 102: Match Found Destroying call 'e9e33a9139008c14@192.168.1.192' Destroying call 'CB7296D4-7596-4C40-A601-B11993884C53@192.168.1.65' ops3*CLI> 2006-08-24 17:13:15 DEBUG[24032]: chan_sip.c:1188 retrans_pkt: SIP TIMER: Not rescheduling id #43:OPTIONS (Method 3) (No timer T1) ops3*CLI> Retransmitting #2 (no NAT) to 192.168.1.191:30954: OPTIONS sip:6528517@192.168.1.191:30954 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0fec3bb5;rport From: "asterisk" ;tag=as34686977 To: Contact: Call-ID: 42ee5c8d1cf3b69228983a6d31a711bc@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:13:13 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- ops3*CLI> 2006-08-24 17:13:16 DEBUG[24032]: chan_sip.c:1188 retrans_pkt: SIP TIMER: Not rescheduling id #43:OPTIONS (Method 3) (No timer T1) ops3*CLI> Retransmitting #3 (no NAT) to 192.168.1.191:30954: OPTIONS sip:6528517@192.168.1.191:30954 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0fec3bb5;rport From: "asterisk" ;tag=as34686977 To: Contact: Call-ID: 42ee5c8d1cf3b69228983a6d31a711bc@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:13:13 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- ops3*CLI> 2006-08-24 17:13:17 DEBUG[24032]: chan_sip.c:1188 retrans_pkt: SIP TIMER: Not rescheduling id #43:OPTIONS (Method 3) (No timer T1) ops3*CLI> Retransmitting #4 (no NAT) to 192.168.1.191:30954: OPTIONS sip:6528517@192.168.1.191:30954 SIP/2.0 Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK0fec3bb5;rport From: "asterisk" ;tag=as34686977 To: Contact: Call-ID: 42ee5c8d1cf3b69228983a6d31a711bc@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:13:13 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- ops3*CLI> Destroying call '42ee5c8d1cf3b69228983a6d31a711bc@192.168.1.3' ops3*CLI> 2006-08-24 17:13:17 DEBUG[23996]: chan_sip.c:11701 sip_devicestate: Checking device state for peer 6528517 2006-08-24 17:13:17 DEBUG[23996]: devicestate.c:187 do_state_change: Changing state for SIP/6528517 - state 1 (Not in use) 2006-08-24 17:13:17 DEBUG[24056]: app_queue.c:490 changethread: Device 'SIP/6528517' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. ops3*CLI> sip no debug ops3*CLI> SIP Debugging Disabled ops3*CLI> exit