Asterisk 1.2.10, 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.10 currently running on ops3 (pid = 24425) ops3*CLI> -- Remote UNIX connection Verbosity is at least 4 ops3*CLI> sip debug 2006-08-24 17:19:07 DEBUG[24495]: chan_sip.c:1323 __sip_autodestruct: Auto destroying call '9964BC2D-1C14-4D67-A9BB-87A7063E8192@192.168.1.65' 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=z9hG4bKc0a8014100000ff744ee17d200002d0d00004b3b Content-Length: 159 Contact: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 Content-Type: application/sdp CSeq: 1 INVITE From: "unknown";tag=11471409330329 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3365443154 3365443154 IN IP4 192.168.1.65 s=SJphone c=IN IP4 192.168.1.65 t=0 0 a=direction:active m=audio 49284 RTP/AVP 3 a=rtpmap:3 GSM/8000 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: INVITE sip:18@ops3.opschile.cl SIP/2.0 (38) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000ff744ee17d200002d0d00004b3b (90) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 159 (19) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: Contact: (40) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 (58) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: Content-Type: application/sdp (29) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: CSeq: 1 INVITE (14) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: From: "unknown";tag=11471409330329 (64) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: Max-Forwards: 70 (16) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: To: (29) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: (0) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: v=0 (3) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: o=- 3365443154 3365443154 IN IP4 192.168.1.65 (45) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: s=SJphone (9) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: c=IN IP4 192.168.1.65 (21) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: t=0 0 (5) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=direction:active (18) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: m=audio 49284 RTP/AVP 3 (23) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:3 GSM/8000 (19) --- (11 headers 8 lines)--- ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.65 with 192.168.1.0 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3141 sip_alloc: Allocating new SIP dialog for 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 - INVITE (With RTP) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 Sending to 192.168.1.65 : 5060 (NAT) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:7149 check_user_full: Setting NAT on RTP to 0 ops3*CLI> 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=z9hG4bKc0a8014100000ff744ee17d200002d0d00004b3b;received=192.168.1.65 From: "unknown";tag=11471409330329 To: ;tag=as23063739 Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@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="44f2f6f9" Content-Length: 0 --- ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #33 ops3*CLI> Scheduling destruction of call '46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65' in 15000 ms ops3*CLI> 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=z9hG4bKc0a8014100000ff744ee17d200002d0d00004b3b Content-Length: 0 Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 CSeq: 1 ACK From: "unknown";tag=11471409330329 Max-Forwards: 70 To: ;tag=as23063739 User-Agent: SJphone/1.60.289a (SJ Labs) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: ACK sip:18@ops3.opschile.cl SIP/2.0 (35) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000ff744ee17d200002d0d00004b3b (90) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 (58) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: CSeq: 1 ACK (11) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: From: "unknown";tag=11471409330329 (64) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: Max-Forwards: 70 (16) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: To: ;tag=as23063739 (44) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: (0) --- (9 headers 0 lines)--- 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received ACK (6) - Command in SIP ACK 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #33 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65' of Response 1: Match Found <-- 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=z9hG4bKc0a8014100000ff744ee17d20000585900004b3c Content-Length: 159 Contact: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 Content-Type: application/sdp CSeq: 2 INVITE From: "unknown";tag=11471409330329 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Proxy-Authorization: Digest username="6528516",realm="opschile.cl",nonce="44f2f6f9",uri="sip:18@ops3.opschile.cl",response="73ea3685f9538a2c3f066e43d6a22748",algorithm="MD5" v=0 o=- 3365443154 3365443154 IN IP4 192.168.1.65 s=SJphone c=IN IP4 192.168.1.65 t=0 0 a=direction:active m=audio 49284 RTP/AVP 3 a=rtpmap:3 GSM/8000 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: INVITE sip:18@ops3.opschile.cl SIP/2.0 (38) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000ff744ee17d20000585900004b3c (90) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 159 (19) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: Contact: (40) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 (58) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: Content-Type: application/sdp (29) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: CSeq: 2 INVITE (14) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: From: "unknown";tag=11471409330329 (64) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: Max-Forwards: 70 (16) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: To: (29) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: Proxy-Authorization: Digest username="6528516",realm="opschile.cl",nonce="44f2f6f9",uri="sip:18@ops3.opschile.cl",response="73ea3685f9538a2c3f066e43d6a22748",algorithm="MD5" (173) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 12: (0) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: v=0 (3) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: o=- 3365443154 3365443154 IN IP4 192.168.1.65 (45) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: s=SJphone (9) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: c=IN IP4 192.168.1.65 (21) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: t=0 0 (5) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=direction:active (18) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: m=audio 49284 RTP/AVP 3 (23) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:3 GSM/8000 (19) --- (12 headers 8 lines)--- 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 ops3*CLI> Sending to 192.168.1.65 : 5060 (NAT) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:7149 check_user_full: Setting NAT on RTP to 0 ops3*CLI> Found user '6528516' ops3*CLI> Found RTP audio format 3 ops3*CLI> Peer audio RTP is at port 192.168.1.65:49284 ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3598 process_sdp: Peer audio RTP is at port 192.168.1.65:49284 ops3*CLI> Found description format GSM ops3*CLI> 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) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:10496 handle_request_invite: Checking SIP call limits for device 6528516 ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:2206 update_call_counter: Updating call counter for incoming call ops3*CLI> Looking for 18 in outgoing_full (domain ops3.opschile.cl) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:6131 build_route: build_route: Contact hop: list_route: hop: ops3*CLI> 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=z9hG4bKc0a8014100000ff744ee17d20000585900004b3c;received=192.168.1.65 From: "unknown";tag=11471409330329 To: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@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:19:10 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528516 2006-08-24 17:19:10 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528516 - state 2 (In use) 2006-08-24 17:19:10 DEBUG[24511]: pbx.c:1677 pbx_extension_helper: Launching 'Dial' ops3*CLI> -- Executing Dial("SIP/6528516-b7d030c8", "SIP/6528518|30") in new stack ops3*CLI> 2006-08-24 17:19:10 DEBUG[24512]: 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> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3141 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:1874 create_addr_from_peer: Setting NAT on RTP to 0 ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.198 with 192.168.1.0 ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2856 ast_channel_inherit_variables: Not copying variable STACK-outgoing_full-18-1. ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2856 ast_channel_inherit_variables: Not copying variable SIPCALLID. ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2856 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2856 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2856 ast_channel_inherit_variables: Not copying variable SIPURI. ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:2068 sip_call: Outgoing Call for 6528518 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:2206 update_call_counter: Updating call counter for outgoing call ops3*CLI> We're at 192.168.1.3 port 18470 ops3*CLI> Adding codec 0x10 (g726) to SDP ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 0: INVITE sip:6528518@192.168.1.198:45057 SIP/2.0 (46) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK092d460f;rport (62) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 2: From: "6528516" ;tag=as242cc6cc (56) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 3: To: (37) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 4: Contact: (34) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 5: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 (53) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 6: CSeq: 102 INVITE (16) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 7: User-Agent: Asterisk PBX (24) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 8: Max-Forwards: 70 (16) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 9: Date: Thu, 24 Aug 2006 21:19:10 GMT (35) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 11: Content-Type: application/sdp (29) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 12: Content-Length: 165 (19) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3357 parse_request: Header 13: (0) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3389 parse_request: Line: v=0 (3) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3389 parse_request: Line: o=root 24425 24425 IN IP4 192.168.1.3 (37) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3389 parse_request: Line: s=session (9) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3389 parse_request: Line: c=IN IP4 192.168.1.3 (20) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3389 parse_request: Line: t=0 0 (5) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3389 parse_request: Line: m=audio 18470 RTP/AVP 111 (25) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3389 parse_request: Line: a=rtpmap:111 G726-32/8000 (25) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:3389 parse_request: Line: a=silenceSupp:off - - - - (25) ops3*CLI> 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=z9hG4bK092d460f;rport From: "6528516" ;tag=as242cc6cc To: Contact: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:19:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Type: application/sdp Content-Length: 165 v=0 o=root 24425 24425 IN IP4 192.168.1.3 s=session c=IN IP4 192.168.1.3 t=0 0 m=audio 18470 RTP/AVP 111 a=rtpmap:111 G726-32/8000 a=silenceSupp:off - - - - --- ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #35 ops3*CLI> -- Called 6528518 ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528518-08c8c6b0 to read format slin ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528516-b7d030c8 to write format slin ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528516-b7d030c8 to read format slin ops3*CLI> 2006-08-24 17:19:10 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528518-08c8c6b0 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=z9hG4bK092d460f;rport From: "6528516" ;tag=as242cc6cc To: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 CSeq: 102 INVITE User-Agent: Grandstream HT287 1.0.8.23 Content-Length: 0 ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: SIP/2.0 100 Trying (18) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK092d460f;rport (62) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528516" ;tag=as242cc6cc (56) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: (37) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 (53) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: CSeq: 102 INVITE (16) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: Content-Length: 0 (17) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: (0) --- (8 headers 0 lines)--- 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:1445 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #35 - INVITE (got response) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4730ab6778ff27074e1a362148c5c434@192.168.1.3' Request 102: Found 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:9578 handle_response_invite: SIP response 100 to standard invite <-- SIP read from 192.168.1.198:45057: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK092d460f;rport From: "6528516" ;tag=as242cc6cc To: ;tag=57b06d45ac9165a0 Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 CSeq: 102 INVITE User-Agent: Grandstream HT287 1.0.8.23 Content-Length: 0 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: SIP/2.0 180 Ringing (19) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK092d460f;rport (62) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528516" ;tag=as242cc6cc (56) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: ;tag=57b06d45ac9165a0 (58) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 (53) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: CSeq: 102 INVITE (16) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: (0) ops3*CLI> --- (8 headers 0 lines)--- ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:1454 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '4730ab6778ff27074e1a362148c5c434@192.168.1.3' Request 102: Found ops3*CLI> 2006-08-24 17:19:10 DEBUG[24495]: chan_sip.c:9578 handle_response_invite: SIP response 180 to standard invite ops3*CLI> 2006-08-24 17:19:10 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528518 2006-08-24 17:19:10 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528518 - state 6 (Ringing) ops3*CLI> -- SIP/6528518-08c8c6b0 is ringing 2006-08-24 17:19:10 DEBUG[24513]: 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> 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=z9hG4bKc0a8014100000ff744ee17d20000585900004b3c;received=192.168.1.65 From: "unknown";tag=11471409330329 To: ;tag=as3c94be3c Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@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> --- ops3*CLI> 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3141 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) ops3*CLI> 2006-08-24 17:19:11 DEBUG[24495]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.191 with 192.168.1.0 ops3*CLI> 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: OPTIONS sip:6528517@192.168.1.191:30954 SIP/2.0 (47) ops3*CLI> 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK451b4dc0;rport (62) ops3*CLI> 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "asterisk" ;tag=as686aaff3 (58) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: (37) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Contact: (35) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: Call-ID: 69233ed433277e4f3d092d5639548635@192.168.1.3 (53) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: CSeq: 102 OPTIONS (17) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: User-Agent: Asterisk PBX (24) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: Max-Forwards: 70 (16) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: Date: Thu, 24 Aug 2006 21:19:11 GMT (35) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) ops3*CLI> 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: Content-Length: 0 (17) 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 12: (0) 12 headers, 0 lines 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=z9hG4bK451b4dc0;rport From: "asterisk" ;tag=as686aaff3 To: Contact: C ops3*CLI> all-ID: 69233ed433277e4f3d092d5639548635@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:19:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- 2006-08-24 17:19:11 DEBUG[24495]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #37 ops3*CLI> 2006-08-24 17:19:12 DEBUG[24495]: chan_sip.c:1179 retrans_pkt: SIP TIMER: Not rescheduling id #37: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=z9hG4bK451b4dc0;rport From: "asterisk" ;tag=as686aaff3 To: Contact: Call-ID: 69233ed433277e4f3d092d5639548635@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:19:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- ops3*CLI> 2006-08-24 17:19:13 DEBUG[24495]: chan_sip.c:1179 retrans_pkt: SIP TIMER: Not rescheduling id #37: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=z9hG4bK451b4dc0;rport From: "asterisk" ;tag=as686aaff3 To: Contact: Call-ID: 69233ed433277e4f3d092d5639548635@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:19:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- ops3*CLI> 2006-08-24 17:19:14 DEBUG[24495]: chan_sip.c:1179 retrans_pkt: SIP TIMER: Not rescheduling id #37: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=z9hG4bK451b4dc0;rport From: "asterisk" ;tag=as686aaff3 To: Contact: Call-ID: 69233ed433277e4f3d092d5639548635@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:19:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- 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=z9hG4bKf0d11100b425770e From: "6528519" ;tag=8138ff2da2bc5431 To: Contact: Supported: replaces, timer Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64114 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:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: INVITE sip:*8@ops3.opschile.cl SIP/2.0 (38) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKf0d11100b425770e (67) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528519" ;tag=8138ff2da2bc5431 (67) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: (29) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Contact: (42) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: Supported: replaces, timer (26) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: Call-ID: dde48f42667496a3@192.168.1.192 (39) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: CSeq: 64114 INVITE (18) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: Max-Forwards: 70 (16) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: Content-Type: application/sdp (29) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 12: Content-Length: 307 (19) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 13: (0) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: v=0 (3) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: o=6528519 8000 8000 IN IP4 192.168.1.192 (40) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: s=SIP Call (10) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: c=IN IP4 192.168.1.192 (22) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: t=0 0 (5) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: m=audio 16462 RTP/AVP 2 8 0 97 18 4 (35) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=sendrecv (10) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=fmtp:97 mode=20 (17) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:18 G729/8000 (21) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:4 G723/8000 (20) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=ptime:20 (10) --- (13 headers 15 lines)--- ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: acl.c:211 ast_apply_ha: ##### Testing 192.168.1.192 with 192.168.1.0 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3141 sip_alloc: Allocating new SIP dialog for dde48f42667496a3@192.168.1.192 - INVITE (With RTP) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received INVITE (5) - Command in SIP INVITE ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1004 parse_sip_options: Begin: parsing SIP "Supported: replaces, timer" 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1016 parse_sip_options: Found SIP option: -replaces- 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1022 parse_sip_options: Matched SIP option: replaces 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1016 parse_sip_options: Found SIP option: -timer- 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1022 parse_sip_options: Matched SIP option: timer 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1033 parse_sip_options: * SIP extension value: 5 for call dde48f42667496a3@192.168.1.192 Using INVITE request as basis request - dde48f42667496a3@192.168.1.192 Sending to 192.168.1.192 : 53035 (non-NAT) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:7149 check_user_full: Setting NAT on RTP to 0 ops3*CLI> 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=z9hG4bKf0d11100b425770e;received=192.168.1.192 From: "6528519" ;tag=8138ff2da2bc5431 To: ;tag=as61104967 Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64114 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Proxy-Authenticate: Digest algorithm=MD5, realm="opschile.cl", nonce="431d471a" Content-Length: 0 --- ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #39 ops3*CLI> Scheduling destruction of call 'dde48f42667496a3@192.168.1.192' in 15000 ms ops3*CLI> 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=z9hG4bKf0d11100b425770e From: "6528519" ;tag=8138ff2da2bc5431 To: ;tag=as61104967 Contact: Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64114 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:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: ACK sip:*8@ops3.opschile.cl SIP/2.0 (35) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKf0d11100b425770e (67) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528519" ;tag=8138ff2da2bc5431 (67) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: ;tag=as61104967 (44) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Contact: (42) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: Call-ID: dde48f42667496a3@192.168.1.192 (39) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: CSeq: 64114 ACK (15) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: Max-Forwards: 70 (16) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: Content-Length: 0 (17) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: (0) ops3*CLI> --- (11 headers 0 lines)--- 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received ACK (6) - Command in SIP ACK 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #39 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'dde48f42667496a3@192.168.1.192' of Response 64114: 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=z9hG4bK34fb4b382c65cce8 From: "6528519" ;tag=8138ff2da2bc5431 To: Contact: Supported: replaces, timer Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@ops3.opschile.cl", nonce="431d471a", response="8f54807e1509ff4cb75d851a5c634e4a" Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64115 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 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: INVITE sip:*8@ops3.opschile.cl SIP/2.0 (38) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bK34fb4b382c65cce8 (67) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528519" ;tag=8138ff2da2bc5431 (67) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: (29) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Contact: (42) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: Supported: replaces, timer (26) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@ops3.opschile.cl", nonce="431d471a", response="8f54807e1509ff4cb75d851a5c634e4a" (176) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: Call-ID: dde48f42667496a3@192.168.1.192 (39) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: CSeq: 64115 INVITE (18) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: Max-Forwards: 70 (16) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 12: Content-Type: application/sdp (29) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 13: Content-Length: 307 (19) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 14: (0) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: v=0 (3) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: o=6528519 8000 8001 IN IP4 192.168.1.192 (40) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: s=SIP Call (10) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: c=IN IP4 192.168.1.192 (22) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: t=0 0 (5) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: m=audio 16462 RTP/AVP 2 8 0 97 18 4 (35) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=sendrecv (10) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:2 G726-32/8000 (23) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=fmtp:97 mode=20 (17) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:18 G729/8000 (21) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=rtpmap:4 G723/8000 (20) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3389 parse_request: Line: a=ptime:20 (10) --- (14 headers 15 lines)--- 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received INVITE (5) - Command in SIP INVITE Using INVITE request as basis request - dde48f42667496a3@192.168.1.192 Sending to 192.168.1.192 : 53035 (non-NAT) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:7149 check_user_full: Setting NAT on RTP to 0 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:19:15 DEBUG[24495]: chan_sip.c:3598 process_sdp: Peer audio RTP is at port 192.168.1.192:16462 Found description format G726-32 ops3*CLI> Found description format PCMA ops3*CLI> Found description format PCMU ops3*CLI> Found description format iLBC ops3*CLI> Found description format G729 ops3*CLI> Found description format G723 ops3*CLI> 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:19:15 DEBUG[24495]: chan_sip.c:10496 handle_request_invite: Checking SIP call limits for device 6528519 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:2206 update_call_counter: Updating call counter for incoming call Looking for *8 in outgoing_full (domain ops3.opschile.cl) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:6131 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=z9hG4bK34fb4b382c65cce8;received=192.168.1.192 From: "6528519" ;tag=8138ff2da2bc5431 To: Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64115 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 --- ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528519 2006-08-24 17:19:15 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 2 (In use) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: res_features.c:1943 ast_pickup_call: Call pickup on chan 'SIP/6528518-08c8c6b0' by 'SIP/6528519-b7d0ad88' 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:2537 sip_answer: sip_answer(SIP/6528519-b7d0ad88) We're at 192.168.1.3 port 14000 Adding codec 0x10 (g726) to SDP 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=z9hG4bK34fb4b382c65cce8;received=192.168.1.192 From: "6528519" ;tag=8138ff2da2bc5431 To: ;tag=as4daec669 ops3*CLI> Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64115 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 24425 24425 IN IP4 192.168.1.3 s=session c=IN IP4 192.168.1.3 t=0 0 m=audio 14000 RTP/AVP 2 a=rtpmap:2 G726-32/8000 a=silenceSupp:off - - - - --- 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #41 2006-08-24 17:19:15 DEBUG[24495]: channel.c:2788 ast_channel_masquerade: Planning to masquerade channel SIP/6528519-b7d0ad88 into the structure of SIP/6528518-08c8c6b0 2006-08-24 17:19:15 DEBUG[24495]: channel.c:2801 ast_channel_masquerade: Done planning to masquerade channel SIP/6528519-b7d0ad88 into the structure of SIP/6528518-08c8c6b0 2006-08-24 17:19:15 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528519 2006-08-24 17:19:15 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 2 (In use) 2006-08-24 17:19:15 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528519 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 2 (In use) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: channel.c:2913 ast_do_masquerade: Actually Masquerading SIP/6528519-b7d0ad88(0) into the structure of SIP/6528518-08c8c6b0(5) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: channel.c:2924 ast_do_masquerade: Got clone lock for masquerade on 'SIP/6528519-b7d0ad88' at 0xb7d11134 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: chan_sip.c:2415 sip_hangup: Hangup call SIP/6528519-b7d0ad88, SIP callid 4730ab6778ff27074e1a362148c5c434@192.168.1.3) 2006-08-24 17:19:15 DEBUG[24511]: chan_sip.c:2423 sip_hangup: update_call_counter(6528518) - decrement call limit counter 2006-08-24 17:19:15 DEBUG[24511]: chan_sip.c:2206 update_call_counter: Updating call counter for outgoing call 2006-08-24 17:19:15 DEBUG[24511]: chan_sip.c:1379 __sip_ack: Acked pending invite 102 2006-08-24 17:19:15 DEBUG[24511]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '4730ab6778ff27074e1a362148c5c434@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=z9hG4bK092d460f;rport From: "6528516" ;tag=as242cc6cc To: Contact: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 CSeq: 102 CANCEL User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #42 ops3*CLI> Scheduling destruction of call '4730ab6778ff27074e1a362148c5c434@192.168.1.3' in 32000 ms ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528519-b7d0ad88 to write format slin 2006-08-24 17:19:15 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528519-b7d0ad88 to read format slin 2006-08-24 17:19:15 DEBUG[24511]: channel.c:3085 ast_do_masquerade: Putting channel SIP/6528519-b7d0ad88 in 64/64 formats 2006-08-24 17:19:15 DEBUG[24511]: channel.c:3105 ast_do_masquerade: Destroying channel clone 'SIP/6528518-08c8c6b0' 2006-08-24 17:19:15 DEBUG[24511]: channel.c:3129 ast_do_masquerade: Done Masquerading SIP/6528519-b7d0ad88 (0) ops3*CLI> -- SIP/6528519-b7d0ad88 answered SIP/6528516-b7d030c8 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528516-b7d030c8 to read format slin ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528519-b7d0ad88 to write format slin ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528519-b7d0ad88 to read format slin 2006-08-24 17:19:15 DEBUG[24511]: channel.c:2363 set_format: Set channel SIP/6528516-b7d030c8 to write format slin 2006-08-24 17:19:15 DEBUG[24511]: chan_sip.c:2537 sip_answer: sip_answer(SIP/6528516-b7d030c8) We're at 192.168.1.3 port 11206 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=z9hG4bKc0a8014100000ff744ee17d20000585900004b3c;received=192.168.1.65 From: "unknown";tag=11471409330329 To: ;tag=as3c94be3c Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@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 24425 24425 IN IP4 192.168.1.3 s=session c=IN IP4 192.168.1.3 t=0 0 m=audio 11206 RTP/AVP 3 a=rtpmap:3 GSM/8000 a=silenceSupp:off - - - - --- 2006-08-24 17:19:15 DEBUG[24515]: 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:19:15 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528518 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528518 - state 1 (Not in use) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528519 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 2 (In use) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528516 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: channel.c:777 channel_find_locked: Avoiding initial deadlock for 'SIP/6528516-b7d030c8' ops3*CLI> 2006-08-24 17:19:15 DEBUG[24516]: 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:19:15 DEBUG[24511]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #44 ops3*CLI> -- Attempting native bridge of SIP/6528516-b7d030c8 and SIP/6528519-b7d0ad88 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: rtp.c:1603 ast_rtp_bridge: Channel codec0 = 2 is not codec1 = 1309, cannot native bridge in RTP. ops3*CLI> 2006-08-24 17:19:15 DEBUG[24514]: 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:19:15 DEBUG[24517]: 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:19:15 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528516 - state 2 (In use) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24518]: 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:19:15 DEBUG[24519]: 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=z9hG4bK092d460f;rport From: "6528516" ;tag=as242cc6cc To: ;tag=57b06d45ac9165a0 Call-ID: 4730ab6778ff27074e1a362148c5c434@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:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: SIP/2.0 200 OK (14) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK092d460f;rport (62) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528516" ;tag=as242cc6cc (56) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: ;tag=57b06d45ac9165a0 (58) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 (53) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: CSeq: 102 CANCEL (16) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: User-Agent: Grandstream HT287 1.0.8.23 (38) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: Contact: (42) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: Supported: replaces, timer (26) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: (0) --- (11 headers 0 lines)--- 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #42 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '4730ab6778ff27074e1a362148c5c434@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=z9hG4bKc0a8014100000ff744ee17d600000c0b00004b40 Content-Length: 0 Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 CSeq: 2 ACK From: "unknown";tag=11471409330329 Max-Forwards: 70 To: ;tag=as3c94be3c User-Agent: SJphone/1.60.289a (SJ Labs) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: ACK sip:18@192.168.1.3 SIP/2.0 (30) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.65;rport;branch=z9hG4bKc0a8014100000ff744ee17d600000c0b00004b40 (90) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 (58) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: CSeq: 2 ACK (11) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: From: "unknown";tag=11471409330329 (64) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: Max-Forwards: 70 (16) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: To: ;tag=as3c94be3c (44) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: (0) --- (9 headers 0 lines)--- 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received ACK (6) - Command in SIP ACK 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #44 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65' of Response 2: Match Found 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=z9hG4bKa9d88a9e10c922d4 From: "6528519" ;tag=8138ff2da2bc5431 To: ;tag=as4daec669 Contact: Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@192.168.1.3", nonce="431d471a", response="81a958a24d287768dcb3c6ffad6a8e74" Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64115 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:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: ACK sip:*8@192.168.1.3 SIP/2.0 (30) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKa9d88a9e10c922d4 (67) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528519" ;tag=8138ff2da2bc5431 (67) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: ;tag=as4daec669 (44) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Contact: (42) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@192.168.1.3", nonce="431d471a", response="81a958a24d287768dcb3c6ffad6a8e74" (171) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: Call-ID: dde48f42667496a3@192.168.1.192 (39) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: CSeq: 64115 ACK (15) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: Max-Forwards: 70 (16) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: Content-Length: 0 (17) 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 12: (0) ops3*CLI> --- (12 headers 0 lines)--- 2006-08-24 17:19:15 DEBUG[24511]: rtp.c:1353 ast_rtp_write: Ooh, format changed from unknown to g726 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received ACK (6) - Command in SIP ACK ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #41 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1401 __sip_ack: Stopping retransmission on 'dde48f42667496a3@192.168.1.192' of Response 64115: Match Found ops3*CLI> 2006-08-24 17:19:15 DEBUG[24511]: rtp.c:1353 ast_rtp_write: Ooh, format changed from unknown to gsm 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=z9hG4bK092d460f;rport From: "6528516" ;tag=as242cc6cc To: ;tag=57b06d45ac9165a0 Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 CSeq: 102 INVITE User-Agent: Grandstream HT287 1.0.8.23 Content-Length: 0 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: SIP/2.0 487 Request Cancelled (29) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;branch=z9hG4bK092d460f;rport (62) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528516" ;tag=as242cc6cc (56) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: ;tag=57b06d45ac9165a0 (58) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 (53) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: CSeq: 102 INVITE (16) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: User-Agent: Grandstream HT287 1.0.8.23 (38) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: (0) ops3*CLI> --- (8 headers 0 lines)--- 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '4730ab6778ff27074e1a362148c5c434@192.168.1.3' of Request 102: Match Not Found 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:2206 update_call_counter: Updating call counter for outgoing call 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=z9hG4bK092d460f;rport From: "6528516" ;tag=as242cc6cc To: ;tag=57b06d45ac9165a0 Contact: Call-ID: 4730ab6778ff27074e1a362148c5c434@192.168.1.3 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- Destroying call '4730ab6778ff27074e1a362148c5c434@192.168.1.3' ops3*CLI> 2006-08-24 17:19:15 DEBUG[24495]: chan_sip.c:1179 retrans_pkt: SIP TIMER: Not rescheduling id #37: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=z9hG4bK451b4dc0;rport From: "asterisk" ;tag=as686aaff3 To: Contact: Call-ID: 69233ed433277e4f3d092d5639548635@192.168.1.3 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 24 Aug 2006 21:19:11 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Content-Length: 0 --- ops3*CLI> Destroying call '69233ed433277e4f3d092d5639548635@192.168.1.3' ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528517 ops3*CLI> 2006-08-24 17:19:15 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528517 - state 1 (Not in use) ops3*CLI> 2006-08-24 17:19:15 DEBUG[24520]: 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 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=z9hG4bKc75fe1acd3b259f7 From: "6528519" ;tag=8138ff2da2bc5431 To: ;tag=as4daec669 Supported: replaces, timer Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@192.168.1.3", nonce="431d471a", response="a235e7c7894cc040be7eaf6c56aef3b6" Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64116 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:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: BYE sip:*8@192.168.1.3 SIP/2.0 (30) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.192:53035;branch=z9hG4bKc75fe1acd3b259f7 (67) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: From: "6528519" ;tag=8138ff2da2bc5431 (67) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: To: ;tag=as4daec669 (44) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: Supported: replaces, timer (26) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: Proxy-Authorization: Digest username="6528519", realm="opschile.cl", algorithm=MD5, uri="sip:*8@192.168.1.3", nonce="431d471a", response="a235e7c7894cc040be7eaf6c56aef3b6" (171) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: Call-ID: dde48f42667496a3@192.168.1.192 (39) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: CSeq: 64116 BYE (15) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: User-Agent: Grandstream HT287 1.0.8.23 (38) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 9: Max-Forwards: 70 (16) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 10: Allow: INVITE,ACK,CANCEL,BYE,NOTIFY,REFER,OPTIONS,INFO,SUBSCRIBE,UPDATE (71) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 11: Content-Length: 0 (17) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 12: (0) --- (12 headers 0 lines)--- 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:11139 handle_request: **** Received BYE (8) - Command in SIP BYE ops3*CLI> Sending to 192.168.1.192 : 53035 (non-NAT) 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=z9hG4bKc75fe1acd3b259f7;received=192.168.1.192 From: "6528519" ;tag=8138ff2da2bc5431 To: ;tag=as4daec669 Call-ID: dde48f42667496a3@192.168.1.192 CSeq: 64116 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Contact: Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing --- ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: channel.c:3308 ast_generic_bridge: Didn't get a frame from channel: SIP/6528519-b7d0ad88 ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: channel.c:3584 ast_channel_bridge: Bridge stops bridging channels SIP/6528516-b7d030c8 and SIP/6528519-b7d0ad88 ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: channel.c:1336 ast_hangup: Hanging up channel 'SIP/6528519-b7d0ad88' ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: chan_sip.c:2415 sip_hangup: Hangup call SIP/6528519-b7d0ad88, SIP callid dde48f42667496a3@192.168.1.192) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: chan_sip.c:2423 sip_hangup: update_call_counter(6528519) - decrement call limit counter ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: chan_sip.c:2206 update_call_counter: Updating call counter for incoming call ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: app_dial.c:1628 dial_exec_full: Exiting with DIALSTATUS=ANSWER. ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:2316 __ast_pbx_run: Spawn extension (outgoing_full,18,1) exited non-zero on 'SIP/6528516-b7d030c8' 2006-08-24 17:19:18 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528519 2006-08-24 17:19:18 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528519 - state 1 (Not in use) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: cdr_addon_mysql.c:206 mysql_log: cdr_mysql: inserting a CDR record. ops3*CLI> 2006-08-24 17:19:18 DEBUG[24521]: app_queue.c:490 changethread: 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:19:18 DEBUG[24511]: 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:19:10','\"6528516\" <6528516>','6528516','18','outgoing_full', 'SIP/6528516-b7d030c8','SIP/6528519-b7d0ad88','Dial','SIP/6528518|30',8,3,'ANSWERED',3,'') ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '"6528516" <6528516>' ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '6528516' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '18' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'outgoing_full' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6528516-b7d030c8' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6528519-b7d0ad88' ops3*CLI> 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'Dial' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'SIP/6528518|30' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-24 17:19:10' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-24 17:19:15' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '2006-08-24 17:19:18' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '8' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '3' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '1156454350.0' 2006-08-24 17:19:18 DEBUG[24511]: pbx.c:1522 pbx_substitute_variables_helper_full: Function result is '(null)' 2006-08-24 17:19:18 DEBUG[24511]: channel.c:1336 ast_hangup: Hanging up channel 'SIP/6528516-b7d030c8' 2006-08-24 17:19:18 DEBUG[24511]: chan_sip.c:2415 sip_hangup: Hangup call SIP/6528516-b7d030c8, SIP callid 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65) 2006-08-24 17:19:18 DEBUG[24511]: chan_sip.c:2423 sip_hangup: update_call_counter(6528516) - decrement call limit counter 2006-08-24 17:19:18 DEBUG[24511]: chan_sip.c:2206 update_call_counter: Updating call counter for incoming call set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.1.65, port 5060 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=z9hG4bK00c6e473;rport From: ;tag=as3c94be3c To: "unknown";tag=11471409330329 Contact: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- 2006-08-24 17:19:18 DEBUG[24511]: chan_sip.c:1293 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #46 2006-08-24 17:19:18 DEBUG[24473]: chan_sip.c:11670 sip_devicestate: Checking device state for peer 6528516 2006-08-24 17:19:18 DEBUG[24473]: devicestate.c:187 do_state_change: Changing state for SIP/6528516 - state 1 (Not in use) 2006-08-24 17:19:18 DEBUG[24522]: 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=z9hG4bK00c6e473 Content-Length: 0 Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 CSeq: 102 BYE From: ;tag=as3c94be3c Server: SJphone/1.60.289a (SJ Labs) To: "unknown";tag=11471409330329 ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 0: SIP/2.0 200 OK (14) 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.1.3:5060;rport=5060;received=192.168.1.3;branch=z9hG4bK00c6e473 (88) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 2: Content-Length: 0 (17) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 3: Call-ID: 46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65 (58) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 4: CSeq: 102 BYE (13) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 5: From: ;tag=as3c94be3c (46) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 6: Server: SJphone/1.60.289a (SJ Labs) (35) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 7: To: "unknown";tag=11471409330329 (62) ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:3357 parse_request: Header 8: (0) ops3*CLI> --- (8 headers 0 lines)--- ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:1390 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #46 ops3*CLI> 2006-08-24 17:19:18 DEBUG[24495]: chan_sip.c:1401 __sip_ack: Stopping retransmission on '46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65' of Request 102: Match Found ops3*CLI> Destroying call 'dde48f42667496a3@192.168.1.192' ops3*CLI> Destroying call '46E8D292-3749-4B50-82E3-25970B77A391@192.168.1.65' ops3*CLI> sip no debug ops3*CLI> SIP Debugging Disabled ops3*CLI> exit