Asterisk SVN-trunk-r126903, Copyright (C) 1999 - 2008 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core 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 'core show license' for details. ========================================================================= Connected to Asterisk SVN-trunk-r126903 currently running on sip-outboundproxy-test-trunk (pid = 1163) sip-outboundproxy-test-trunk*CLI> sipsip set debug sip-outboundproxy-test-trunk*CLI> No such command 'sip set debug' (type 'help sip set debug' for other possible commands) sip-outboundproxy-test-trunk*CLI> sip set debug on sip-outboundproxy-test-trunk*CLI> SIP Debugging enabled sip-outboundproxy-test-trunk*CLI> cores set verbose 47 sip-outboundproxy-test-trunk*CLI> No such command 'cores set verbose 7' (type 'help cores set' for other possible commands) sip-outboundproxy-test-trunk*CLI> core set debug 7 sip-outboundproxy-test-trunk*CLI> Core debug was 0 and is now 7 sip-outboundproxy-test-trunk*CLI> core set verbose 7 sip-outboundproxy-test-trunk*CLI> Verbosity was 0 and is now 7 sip-outboundproxy-test-trunk*CLI> <--- SIP read from UDP://10.19.18.226:5061 ---> REGISTER sip:10.19.21.227 SIP/2.0 CSeq: 1 REGISTER Via: SIP/2.0/UDP 10.19.18.226:5061;branch=z9hG4bKc237c0b8-9847-dd11-942c-001d09892b15;rport User-Agent: Ekiga/2.0.11 From: ;tag=6233c0b8-9847-dd11-942c-001d09892b15 Call-ID: ac18beb8-9847-dd11-942c-001d09892b15@solo To: Contact: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Expires: 3600 Content-Length: 0 Max-Forwards: 70 <-------------> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 33]: REGISTER sip:10.19.21.227 SIP/2.0 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 16]: CSeq: 1 REGISTER [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 91]: Via: SIP/2.0/UDP 10.19.18.226:5061;branch=z9hG4bKc237c0b8-9847-dd11-942c-001d09892b15;rport [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 24]: User-Agent: Ekiga/2.0.11 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 71]: From: ;tag=6233c0b8-9847-dd11-942c-001d09892b15 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 50]: Call-ID: ac18beb8-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 28]: To: [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 52]: Contact: [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 57]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 13]: Expires: 3600 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 17]: Content-Length: 0 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 11 [ 16]: Max-Forwards: 70 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 12 [ 0]: --- (12 headers 0 lines) --- [Jul 3 18:08:35] DEBUG[1167]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6171 sip_alloc: Allocating new SIP dialog for ac18beb8-9847-dd11-942c-001d09892b15@solo - REGISTER (No RTP) [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:19323 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:19186 handle_request_register: Initializing initreq for method REGISTER - callid ac18beb8-9847-dd11-942c-001d09892b15@solo Sending to 10.19.18.226 : 5061 (NAT) <--- Transmitting (no NAT) to 10.19.18.226:5061 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.19.18.226:5061;branch=z9hG4bKc237c0b8-9847-dd11-942c-001d09892b15;received=10.19.18.226;rport=5061 From: ;tag=6233c0b8-9847-dd11-942c-001d09892b15 To: ;tag=as384a65e3 Call-ID: ac18beb8-9847-dd11-942c-001d09892b15@solo CSeq: 1 REGISTER Server: Asterisk PBX SVN-trunk-r126903 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="2e008db8" Content-Length: 0 <------------> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket destined for 10.19.18.226:5061 Scheduling destruction of SIP dialog 'ac18beb8-9847-dd11-942c-001d09892b15@solo' in 32000 ms (Method: REGISTER) sip-outboundproxy-test-trunk*CLI> <--- SIP read from UDP://10.19.18.226:5061 ---> REGISTER sip:10.19.21.227 SIP/2.0 CSeq: 2 REGISTER Via: SIP/2.0/UDP 10.19.18.226:5061;branch=z9hG4bKa8a1c0b8-9847-dd11-942c-001d09892b15;rport User-Agent: Ekiga/2.0.11 Authorization: Digest username="ekiga", realm="asterisk", nonce="2e008db8", uri="sip:10.19.21.227", algorithm=md5, response="6ffcd491ae9dc4de2f2dfda463202cae" From: ;tag=6233c0b8-9847-dd11-942c-001d09892b15 Call-ID: ac18beb8-9847-dd11-942c-001d09892b15@solo To: Contact: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Expires: 3600 Content-Length: 0 Max-Forwards: 70 <-------------> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 33]: REGISTER sip:10.19.21.227 SIP/2.0 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 16]: CSeq: 2 REGISTER [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 91]: Via: SIP/2.0/UDP 10.19.18.226:5061;branch=z9hG4bKa8a1c0b8-9847-dd11-942c-001d09892b15;rport [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 24]: User-Agent: Ekiga/2.0.11 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [158]: Authorization: Digest username="ekiga", realm="asterisk", nonce="2e008db8", uri="sip:10.19.21.227", algorithm=md5, response="6ffcd491ae9dc4de2f2dfda463202cae" [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 71]: From: ;tag=6233c0b8-9847-dd11-942c-001d09892b15 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 50]: Call-ID: ac18beb8-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 28]: To: [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 52]: Contact: [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 57]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 13]: Expires: 3600 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 11 [ 17]: Content-Length: 0 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 12 [ 16]: Max-Forwards: 70 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 13 [ 0]: --- (13 headers 0 lines) --- [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:19323 handle_incoming: **** Received REGISTER (2) - Command in SIP REGISTER [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:19186 handle_request_register: Initializing initreq for method REGISTER - callid ac18beb8-9847-dd11-942c-001d09892b15@solo Sending to 10.19.18.226 : 5061 (NAT) sip-outboundproxy-test-trunk*CLI> > Saved useragent "Ekiga/2.0.11" for peer ekiga <--- Transmitting (no NAT) to 10.19.18.226:5061 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.19.18.226:5061;branch=z9hG4bKa8a1c0b8-9847-dd11-942c-001d09892b15;received=10.19.18.226;rport=5061 From: ;tag=6233c0b8-9847-dd11-942c-001d09892b15 To: ;tag=as384a65e3 Call-ID: ac18beb8-9847-dd11-942c-001d09892b15@solo CSeq: 2 REGISTER Server: Asterisk PBX SVN-trunk-r126903 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Expires: 3600 Contact: ;expires=3600 Date: Thu, 03 Jul 2008 18:08:35 GMT Content-Length: 0 <------------> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 10.19.18.226:5061 [Jul 3 18:08:35] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ekiga Scheduling destruction of SIP dialog 'ac18beb8-9847-dd11-942c-001d09892b15@solo' in 32000 ms (Method: REGISTER) sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:35] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - ekiga sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer ekiga sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:35] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/ekiga - state 1 (Not in use) sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:35] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/ekiga' state '1' sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:35] DEBUG[1167]: devicestate.c:665 handle_devstate_change: Processing device state change for 'SIP/ekiga' sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:35] DEBUG[1167]: devicestate.c:621 process_collection: Aggregate devstate result is 1 sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:35] DEBUG[1167]: devicestate.c:643 process_collection: Aggregate state for device 'SIP/ekiga' has changed to 'Not in use' sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:35] DEBUG[1167]: app_queue.c:779 handle_statechange: Device 'SIP/ekiga' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. sip-outboundproxy-test-trunk*CLI> <--- SIP read from UDP://10.19.18.226:5062 ---> SUBSCRIBE sip:ekiga@sip-outboundproxy-test-trunk SIP/2.0 CSeq: 3 SUBSCRIBE Via: SIP/2.0/UDP 10.19.18.226:5062;branch=z9hG4bK6a07c6b8-9847-dd11-942c-001d09892b15;rport User-Agent: Ekiga/2.0.11 From: ;tag=6e03c6b8-9847-dd11-942c-001d09892b15 Call-ID: 4e6bc4b8-9847-dd11-942c-001d09892b15@solo To: Contact: Accept: application/simple-message-summary Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Expires: 3600 Event: message-summary Content-Length: 0 Max-Forwards: 70 <-------------> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 56]: SUBSCRIBE sip:ekiga@sip-outboundproxy-test-trunk SIP/2.0 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 17]: CSeq: 3 SUBSCRIBE [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 91]: Via: SIP/2.0/UDP 10.19.18.226:5062;branch=z9hG4bK6a07c6b8-9847-dd11-942c-001d09892b15;rport [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 24]: User-Agent: Ekiga/2.0.11 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 87]: From: ;tag=6e03c6b8-9847-dd11-942c-001d09892b15 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 50]: Call-ID: 4e6bc4b8-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 44]: To: [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 52]: Contact: [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 42]: Accept: application/simple-message-summary [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 57]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 13]: Expires: 3600 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 11 [ 22]: Event: message-summary [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 12 [ 17]: Content-Length: 0 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 13 [ 16]: Max-Forwards: 70 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 14 [ 0]: --- (14 headers 0 lines) --- [Jul 3 18:08:35] DEBUG[1167]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6171 sip_alloc: Allocating new SIP dialog for 4e6bc4b8-9847-dd11-942c-001d09892b15@solo - SUBSCRIBE (No RTP) [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:19323 handle_incoming: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Creating new subscription [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:18920 handle_request_subscribe: Initializing initreq for method SUBSCRIBE - callid 4e6bc4b8-9847-dd11-942c-001d09892b15@solo Sending to 10.19.18.226 : 5062 (NAT) Found peer 'ekiga' for 'ekiga' from 10.19.18.226:5062 <--- Transmitting (no NAT) to 10.19.18.226:5062 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.19.18.226:5062;branch=z9hG4bK6a07c6b8-9847-dd11-942c-001d09892b15;received=10.19.18.226;rport=5062 From: ;tag=6e03c6b8-9847-dd11-942c-001d09892b15 To: ;tag=as6d60013f Call-ID: 4e6bc4b8-9847-dd11-942c-001d09892b15@solo CSeq: 3 SUBSCRIBE Server: Asterisk PBX SVN-trunk-r126903 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="398c4660" Content-Length: 0 <------------> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket destined for 10.19.18.226:5062 Scheduling destruction of SIP dialog '4e6bc4b8-9847-dd11-942c-001d09892b15@solo' in 32000 ms (Method: SUBSCRIBE) sip-outboundproxy-test-trunk*CLI> <--- SIP read from UDP://10.19.18.226:5062 ---> SUBSCRIBE sip:ekiga@sip-outboundproxy-test-trunk SIP/2.0 CSeq: 4 SUBSCRIBE Via: SIP/2.0/UDP 10.19.18.226:5062;branch=z9hG4bKa666c6b8-9847-dd11-942c-001d09892b15;rport User-Agent: Ekiga/2.0.11 Authorization: Digest username="ekiga", realm="asterisk", nonce="398c4660", uri="sip:ekiga@sip-outboundproxy-test-trunk", algorithm=md5, response="4477ed8d91f4ff19fccd1f260a5fdcb2" From: ;tag=6e03c6b8-9847-dd11-942c-001d09892b15 Call-ID: 4e6bc4b8-9847-dd11-942c-001d09892b15@solo To: Contact: Accept: application/simple-message-summary Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Expires: 3600 Event: message-summary Content-Length: 0 Max-Forwards: 70 <-------------> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 56]: SUBSCRIBE sip:ekiga@sip-outboundproxy-test-trunk SIP/2.0 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 17]: CSeq: 4 SUBSCRIBE [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 91]: Via: SIP/2.0/UDP 10.19.18.226:5062;branch=z9hG4bKa666c6b8-9847-dd11-942c-001d09892b15;rport [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 24]: User-Agent: Ekiga/2.0.11 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [180]: Authorization: Digest username="ekiga", realm="asterisk", nonce="398c4660", uri="sip:ekiga@sip-outboundproxy-test-trunk", algorithm=md5, response="4477ed8d91f4ff19fccd1f260a5fdcb2" [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 87]: From: ;tag=6e03c6b8-9847-dd11-942c-001d09892b15 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 50]: Call-ID: 4e6bc4b8-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 44]: To: [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 52]: Contact: [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 42]: Accept: application/simple-message-summary [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 57]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 11 [ 13]: Expires: 3600 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 12 [ 22]: Event: message-summary [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 13 [ 17]: Content-Length: 0 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 14 [ 16]: Max-Forwards: 70 [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 15 [ 0]: --- (15 headers 0 lines) --- [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:19323 handle_incoming: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:18888 handle_request_subscribe: Got a new subscription 4e6bc4b8-9847-dd11-942c-001d09892b15@solo (possibly with auth) Creating new subscription [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:18920 handle_request_subscribe: Initializing initreq for method SUBSCRIBE - callid 4e6bc4b8-9847-dd11-942c-001d09892b15@solo Sending to 10.19.18.226 : 5062 (NAT) Found peer 'ekiga' for 'ekiga' from 10.19.18.226:5062 Looking for ekiga in default (domain sip-outboundproxy-test-trunk) <--- Transmitting (no NAT) to 10.19.18.226:5062 ---> SIP/2.0 404 Not found (no mailbox) Via: SIP/2.0/UDP 10.19.18.226:5062;branch=z9hG4bKa666c6b8-9847-dd11-942c-001d09892b15;received=10.19.18.226;rport=5062 From: ;tag=6e03c6b8-9847-dd11-942c-001d09892b15 To: ;tag=as6d60013f Call-ID: 4e6bc4b8-9847-dd11-942c-001d09892b15@solo CSeq: 4 SUBSCRIBE Server: Asterisk PBX SVN-trunk-r126903 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 <------------> [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket destined for 10.19.18.226:5062 [Jul 3 18:08:35] NOTICE[1167]: chan_sip.c:19050 handle_request_subscribe: Received SIP subscribe for peer without mailbox: ekiga [Jul 3 18:08:35] DEBUG[1167]: chan_sip.c:4814 sip_destroy: Destroying SIP dialog 4e6bc4b8-9847-dd11-942c-001d09892b15@solo Really destroying SIP dialog '4e6bc4b8-9847-dd11-942c-001d09892b15@solo' Method: SUBSCRIBE sip-outboundproxy-test-trunk*CLI> <--- SIP read from UDP://10.19.18.226:5063 ---> INVITE sip:s@10.19.21.227 SIP/2.0 Date: Thu, 03 Jul 2008 18:08:51 GMT CSeq: 1 INVITE Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK9613c0c2-9847-dd11-942c-001d09892b15;rport User-Agent: Ekiga/2.0.11 From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo To: Contact: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Content-Type: application/sdp Content-Length: 257 Max-Forwards: 70 v=0 o=- 1215108531 1215108531 IN IP4 10.19.18.226 s=Opal SIP Session c=IN IP4 10.19.18.226 t=0 0 m=audio 5000 RTP/AVP 0 3 107 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:107 MS-GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 33]: INVITE sip:s@10.19.21.227 SIP/2.0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 35]: Date: Thu, 03 Jul 2008 18:08:51 GMT [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 14]: CSeq: 1 INVITE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 91]: Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK9613c0c2-9847-dd11-942c-001d09892b15;rport [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 24]: User-Agent: Ekiga/2.0.11 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 91]: From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 50]: Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 24]: To: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 52]: Contact: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 57]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 29]: Content-Type: application/sdp [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 11 [ 19]: Content-Length: 257 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 12 [ 16]: Max-Forwards: 70 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 13 [ 0]: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 0 [ 3]: v=0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 1 [ 45]: o=- 1215108531 1215108531 IN IP4 10.19.18.226 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 2 [ 18]: s=Opal SIP Session [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 3 [ 21]: c=IN IP4 10.19.18.226 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 4 [ 5]: t=0 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 5 [ 32]: m=audio 5000 RTP/AVP 0 3 107 101 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 8 [ 24]: a=rtpmap:107 MS-GSM/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 10 [ 15]: a=fmtp:101 0-15 --- (13 headers 11 lines) --- [Jul 3 18:08:51] DEBUG[1167]: acl.c:490 ast_ouraddrfor: Found IP address for this socket == Using SIP RTP CoS mark 5 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4150 do_setnat: Setting NAT on RTP to Off [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6171 sip_alloc: Allocating new SIP dialog for 6e3cbfc2-9847-dd11-942c-001d09892b15@solo - INVITE (With RTP) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:19323 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.19.18.226 : 5063 (NAT) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:17672 handle_request_invite: Initializing initreq for method INVITE - callid 6e3cbfc2-9847-dd11-942c-001d09892b15@solo Using INVITE request as basis request - 6e3cbfc2-9847-dd11-942c-001d09892b15@solo Found user 'ekiga' for 'ekiga' [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4150 do_setnat: Setting NAT on RTP to Off <--- Reliably Transmitting (no NAT) to 10.19.18.226:5063 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK9613c0c2-9847-dd11-942c-001d09892b15;received=10.19.18.226;rport=5063 From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 To: ;tag=as3c508b5f Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo CSeq: 1 INVITE Server: Asterisk PBX SVN-trunk-r126903 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="31b47158" Content-Length: 0 <------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3089 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #8 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket destined for 10.19.18.226:5063 Scheduling destruction of SIP dialog '6e3cbfc2-9847-dd11-942c-001d09892b15@solo' in 32000 ms (Method: INVITE) sip-outboundproxy-test-trunk*CLI> <--- SIP read from UDP://10.19.18.226:5063 ---> ACK sip:s@10.19.21.227 SIP/2.0 CSeq: 1 ACK Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK9613c0c2-9847-dd11-942c-001d09892b15;rport From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo To: ;tag=as3c508b5f Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Content-Length: 0 Max-Forwards: 70 <-------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 30]: ACK sip:s@10.19.21.227 SIP/2.0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 11]: CSeq: 1 ACK [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 91]: Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK9613c0c2-9847-dd11-942c-001d09892b15;rport [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 91]: From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 50]: Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 39]: To: ;tag=as3c508b5f [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 57]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 17]: Content-Length: 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:19323 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3224 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #8 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3256 __sip_ack: Stopping retransmission on '6e3cbfc2-9847-dd11-942c-001d09892b15@solo' of Response 1: Match Found sip-outboundproxy-test-trunk*CLI> <--- SIP read from UDP://10.19.18.226:5063 ---> INVITE sip:s@10.19.21.227 SIP/2.0 Date: Thu, 03 Jul 2008 18:08:51 GMT CSeq: 2 INVITE Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK0c10c1c2-9847-dd11-942c-001d09892b15;rport User-Agent: Ekiga/2.0.11 Authorization: Digest username="ekiga", realm="asterisk", nonce="31b47158", uri="sip:s@10.19.21.227", algorithm=md5, response="ff3760132a56919f04e83d844bf9787a" From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 sip-outboundproxy-test-trunk*CLI> Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo To: Contact: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Content-Type: application/sdp Content-Length: 257 Max-Forwards: 70 v=0 o=- 1215108531 1215108531 IN IP4 10.19.18.226 s=Opal SIP Session c=IN IP4 10.19.18.226 t=0 0 m=audio 5000 RTP/AVP 0 3 107 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:107 MS-GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 <-------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 33]: INVITE sip:s@10.19.21.227 SIP/2.0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 35]: Date: Thu, 03 Jul 2008 18:08:51 GMT [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 14]: CSeq: 2 INVITE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 91]: Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK0c10c1c2-9847-dd11-942c-001d09892b15;rport [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 24]: User-Agent: Ekiga/2.0.11 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [160]: Authorization: Digest username="ekiga", realm="asterisk", nonce="31b47158", uri="sip:s@10.19.21.227", algorithm=md5, response="ff3760132a56919f04e83d844bf9787a" [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 91]: From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 50]: Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 24]: To: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 52]: Contact: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 57]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 12 [ 19]: Content-Length: 257 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 13 [ 16]: Max-Forwards: 70 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 14 [ 0]: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 0 [ 3]: v=0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 1 [ 45]: o=- 1215108531 1215108531 IN IP4 10.19.18.226 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 2 [ 18]: s=Opal SIP Session [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 3 [ 21]: c=IN IP4 10.19.18.226 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 4 [ 5]: t=0 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 5 [ 32]: m=audio 5000 RTP/AVP 0 3 107 101 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 8 [ 24]: a=rtpmap:107 MS-GSM/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 10 [ 15]: a=fmtp:101 0-15 --- (14 headers 11 lines) --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:19323 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.19.18.226 : 5063 (NAT) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:17672 handle_request_invite: Initializing initreq for method INVITE - callid 6e3cbfc2-9847-dd11-942c-001d09892b15@solo Using INVITE request as basis request - 6e3cbfc2-9847-dd11-942c-001d09892b15@solo Found user 'ekiga' for 'ekiga' [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4150 do_setnat: Setting NAT on RTP to Off Found RTP audio format 0 Found RTP audio format 3 Found RTP audio format 107 Found RTP audio format 101 Peer audio RTP is at port 10.19.18.226:5000 Found audio description format PCMU for ID 0 Found audio description format GSM for ID 3 Found unknown media description format MS-GSM for ID 107 Found audio description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer Capabilities: us - 0x4 (ulaw), peer - audio=0x6 (gsm|ulaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 10.19.18.226:5000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:7354 process_sdp: We're settling with these formats: 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:17749 handle_request_invite: Checking SIP call limits for device ekiga [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4707 update_call_counter: Updating call counter for incoming call Looking for s in default (domain 10.19.21.227) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5596 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5597 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5598 sip_new: *** Our capabilities are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5599 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5627 sip_new: This channel will not be able to handle video. [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:10557 build_route: build_route: Contact hop: list_route: hop: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:17962 handle_request_invite: SIP/ekiga-0824d3d8: New call is still down.... Trying... <--- Transmitting (no NAT) to 10.19.18.226:5063 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK0c10c1c2-9847-dd11-942c-001d09892b15;received=10.19.18.226;rport=5063 From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 To: Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo CSeq: 2 INVITE Server: Asterisk PBX SVN-trunk-r126903 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket destined for 10.19.18.226:5063 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ekiga [Jul 3 18:08:51] DEBUG[1167]: pbx.c:2967 pbx_extension_helper: Launching 'NoOp' -- Executing [s@default:1] NoOp("SIP/ekiga-0824d3d8", "") in new stack [Jul 3 18:08:51] DEBUG[1167]: pbx.c:2967 pbx_extension_helper: Launching 'Dial' -- Executing [s@default:2] Dial("SIP/ekiga-0824d3d8", "sip/6286@pbxproxy") in new stack [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20506 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) == Using SIP RTP CoS mark 5 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6171 sip_alloc: Allocating new SIP dialog for 760f09ea2d986d37096eebfa0b2d50b7@10.19.21.227 - INVITE (With RTP) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2592 obproxy_get: OBPROXY: Applying global OBproxy to this call [Jul 3 18:08:51] DEBUG[1167]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Jul 3 18:08:51] DEBUG[1167]: frame.c:1198 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5596 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5597 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5598 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Jul 3 18:08:51] DEBUG[1167]: frame.c:1198 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5599 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5601 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5627 sip_new: This channel will not be able to handle video. [Jul 3 18:08:51] DEBUG[1167]: rtp.c:2161 ast_rtp_make_compatible: Seeded SDP of 'SIP/pbxproxy-08254fd8' with that of 'SIP/ekiga-0824d3d8' [Jul 3 18:08:51] DEBUG[1167]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jul 3 18:08:51] DEBUG[1167]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jul 3 18:08:51] DEBUG[1167]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPURI. [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4518 sip_call: Outgoing Call for 6286 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4707 update_call_counter: Updating call counter for outgoing call [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4537 sip_call: Our T38 capability (0), joint T38 capability (0) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8488 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8489 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8508 add_sdp: This call needs video offers, but there's no video support enabled! Audio is at 127.0.0.1 port 19782 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8642 add_sdp: -- Done with adding codecs to SDP [Jul 3 18:08:51] DEBUG[1167]: channel.c:2763 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=29) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8707 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2535 initialize_initreq: Initializing initreq for method INVITE - callid 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 34]: INVITE sip:6286@pbxproxy:0 SIP/2.0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK78575329;rport [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 62]: From: "Matthew Nicholson" ;tag=as739af1ff [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 25]: To: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 30]: Contact: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 51]: Call-ID: 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 42]: User-Agent: Asterisk PBX SVN-trunk-r126903 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 35]: Date: Thu, 03 Jul 2008 18:08:51 GMT [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 11 [ 26]: Supported: replaces, timer [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 13 [ 19]: Content-Length: 312 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 14 [ 0]: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 0 [ 3]: v=0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 1 [ 43]: o=root 224341039 224341039 IN IP4 127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 2 [ 32]: s=Asterisk PBX SVN-trunk-r126903 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 3 [ 18]: c=IN IP4 127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 4 [ 5]: t=0 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 5 [ 31]: m=audio 19782 RTP/AVP 0 3 8 101 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 10 [ 15]: a=fmtp:101 0-16 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 11 [ 25]: a=silenceSupp:off - - - - [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 12 [ 10]: a=ptime:20 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 13 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to 10.19.20.229:5060: INVITE sip:6286@pbxproxy:0 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK78575329;rport Max-Forwards: 70 From: "Matthew Nicholson" ;tag=as739af1ff To: Contact: Call-ID: 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r126903 Date: Thu, 03 Jul 2008 18:08:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Type: application/sdp Content-Length: 312 v=0 o=root 224341039 224341039 IN IP4 127.0.0.1 s=Asterisk PBX SVN-trunk-r126903 c=IN IP4 127.0.0.1 t=0 0 m=audio 19782 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3089 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #10 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 10.19.20.229:5060 -- Called 6286@pbxproxy <--- SIP read from UDP://10.19.20.229:5060 ---> SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK78575329;rport=5060;received=10.19.21.227 From: "Matthew Nicholson" ;tag=as739af1ff To: Call-ID: 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 CSeq: 102 INVITE Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 10.19.20.229:5060 "Noisy feedback tells: pid=1112 req_src_ip=10.19.21.227 req_src_port=5060 in_uri=sip:6286@pbxproxy:0 out_uri=sip:6286@pbxproxy:0 via_cnt==1" <-------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 50]: SIP/2.0 100 trying -- your call is important to us [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 87]: Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK78575329;rport=5060;received=10.19.21.227 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 62]: From: "Matthew Nicholson" ;tag=as739af1ff [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 25]: To: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 51]: Call-ID: 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 42]: Server: OpenSer (1.1.0-notls (i386/linux)) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 17]: Content-Length: 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [172]: Warning: 392 10.19.20.229:5060 "Noisy feedback tells: pid=1112 req_src_ip=10.19.21.227 req_src_port=5060 in_uri=sip:6286@pbxproxy:0 out_uri=sip:6286@pbxproxy:0 via_cnt==1" [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3289 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #10 - INVITE (got response) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3296 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '60df610f7292f3fc444140ca0030e2b3@127.0.0.1' Request 102: Found [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:15819 handle_response_invite: SIP response 100 to standard invite <--- SIP read from UDP://10.19.20.229:5060 ---> SIP/2.0 403 Forbidden Via: SIP/2.0/UDP 127.0.0.1:5060;received=10.19.21.227;branch=z9hG4bK78575329;rport=5060 From: "Matthew Nicholson" ;tag=as739af1ff To: ;tag=as62d6af36 Call-ID: 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <-------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 21]: SIP/2.0 403 Forbidden [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 87]: Via: SIP/2.0/UDP 127.0.0.1:5060;received=10.19.21.227;branch=z9hG4bK78575329;rport=5060 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 62]: From: "Matthew Nicholson" ;tag=as739af1ff [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 40]: To: ;tag=as62d6af36 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 51]: Call-ID: 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 24]: User-Agent: Asterisk PBX [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 19]: Supported: replaces [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 17]: Content-Length: 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3219 __sip_ack: Acked pending invite 102 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3256 __sip_ack: Stopping retransmission on '60df610f7292f3fc444140ca0030e2b3@127.0.0.1' of Request 102: Match Found [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:15819 handle_response_invite: SIP response 403 to standard invite Transmitting (no NAT) to 10.19.20.229:5060: ACK sip:6286@pbxproxy:0 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK78575329;rport Max-Forwards: 70 From: "Matthew Nicholson" ;tag=as739af1ff To: ;tag=as62d6af36 Contact: Call-ID: 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r126903 Content-Length: 0 --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'ACK sip:62' onto UDP socket destined for 10.19.20.229:5060 [Jul 3 18:08:51] WARNING[1167]: chan_sip.c:16042 handle_response_invite: Received response: "Forbidden" from '"Matthew Nicholson" ;tag=as739af1ff' [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2546 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 -- SIP/pbxproxy-08254fd8 is circuit-busy [Jul 3 18:08:51] DEBUG[1167]: channel.c:1648 ast_hangup: Hanging up channel 'SIP/pbxproxy-08254fd8' [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5023 sip_hangup: Hangup call SIP/pbxproxy-08254fd8, SIP callid 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/pbxproxy-08254fd8 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/pbxproxy == Everyone is busy/congested at this time (1:0/1/0) [Jul 3 18:08:51] DEBUG[1167]: rtp.c:2037 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jul 3 18:08:51] DEBUG[1167]: app_dial.c:1993 dial_exec_full: Exiting with DIALSTATUS=CONGESTION. [Jul 3 18:08:51] DEBUG[1167]: pbx.c:2967 pbx_extension_helper: Launching 'Dial' -- Executing [s@default:3] Dial("SIP/ekiga-0824d3d8", "sip/2564286286@pbxproxy") in new stack [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20506 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) == Using SIP RTP CoS mark 5 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6171 sip_alloc: Allocating new SIP dialog for 74e5f41b7b6aef3e77571fdd70ee8309@10.19.21.227 - INVITE (With RTP) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2592 obproxy_get: OBPROXY: Applying global OBproxy to this call [Jul 3 18:08:51] DEBUG[1167]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Jul 3 18:08:51] DEBUG[1167]: frame.c:1198 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5596 sip_new: *** Our native formats are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5597 sip_new: *** Joint capabilities are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5598 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Jul 3 18:08:51] DEBUG[1167]: frame.c:1198 ast_codec_choose: Could not find preferred codec - Going for the best codec [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5599 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5601 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5627 sip_new: This channel will not be able to handle video. [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4814 sip_destroy: Destroying SIP dialog 60df610f7292f3fc444140ca0030e2b3@127.0.0.1 Really destroying SIP dialog '60df610f7292f3fc444140ca0030e2b3@127.0.0.1' Method: INVITE [Jul 3 18:08:51] DEBUG[1167]: rtp.c:2161 ast_rtp_make_compatible: Seeded SDP of 'SIP/pbxproxy-08267118' with that of 'SIP/ekiga-0824d3d8' [Jul 3 18:08:51] DEBUG[1167]: channel.c:3759 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Jul 3 18:08:51] DEBUG[1167]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Jul 3 18:08:51] DEBUG[1167]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Jul 3 18:08:51] DEBUG[1167]: channel.c:3759 ast_channel_inherit_variables: Not copying variable SIPURI. sip-outboundproxy-test-trunk*CLI> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4518 sip_call: Outgoing Call for 2564286286 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4707 update_call_counter: Updating call counter for outgoing call [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4537 sip_call: Our T38 capability (0), joint T38 capability (0) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8488 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8489 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8508 add_sdp: This call needs video offers, but there's no video support enabled! Audio is at 127.0.0.1 port 13494 Adding codec 0x4 (ulaw) to SDP Adding codec 0x2 (gsm) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8642 add_sdp: -- Done with adding codecs to SDP [Jul 3 18:08:51] DEBUG[1167]: channel.c:2763 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=31) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:8707 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2535 initialize_initreq: Initializing initreq for method INVITE - callid 6c731b3a470698452e330aab38e4bc73@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 40]: INVITE sip:2564286286@pbxproxy:0 SIP/2.0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 60]: Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK709c3960;rport [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 62]: From: "Matthew Nicholson" ;tag=as72fca25f [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 31]: To: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 30]: Contact: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 51]: Call-ID: 6c731b3a470698452e330aab38e4bc73@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 42]: User-Agent: Asterisk PBX SVN-trunk-r126903 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 35]: Date: Thu, 03 Jul 2008 18:08:51 GMT [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 11 [ 26]: Supported: replaces, timer [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 13 [ 19]: Content-Length: 314 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 14 [ 0]: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 0 [ 3]: v=0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 1 [ 45]: o=root 2042560492 2042560492 IN IP4 127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 2 [ 32]: s=Asterisk PBX SVN-trunk-r126903 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 3 [ 18]: c=IN IP4 127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 4 [ 5]: t=0 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 5 [ 31]: m=audio 13494 RTP/AVP 0 3 8 101 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 10 [ 15]: a=fmtp:101 0-16 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 11 [ 25]: a=silenceSupp:off - - - - [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 12 [ 10]: a=ptime:20 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Body 13 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to 10.19.20.229:5060: INVITE sip:2564286286@pbxproxy:0 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK709c3960;rport Max-Forwards: 70 From: "Matthew Nicholson" ;tag=as72fca25f To: Contact: Call-ID: 6c731b3a470698452e330aab38e4bc73@127.0.0.1 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r126903 Date: Thu, 03 Jul 2008 18:08:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Type: application/sdp Content-Length: 314 v=0 o=root 2042560492 2042560492 IN IP4 127.0.0.1 s=Asterisk PBX SVN-trunk-r126903 c=IN IP4 127.0.0.1 t=0 0 m=audio 13494 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3089 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #12 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'INVITE sip' onto UDP socket destined for 10.19.20.229:5060 -- Called 2564286286@pbxproxy <--- SIP read from UDP://10.19.20.229:5060 ---> SIP/2.0 100 trying -- your call is important to us Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK709c3960;rport=5060;received=10.19.21.227 From: "Matthew Nicholson" ;tag=as72fca25f To: Call-ID: 6c731b3a470698452e330aab38e4bc73@127.0.0.1 CSeq: 102 INVITE Server: OpenSer (1.1.0-notls (i386/linux)) Content-Length: 0 Warning: 392 10.19.20.229:5060 "Noisy feedback tells: pid=1115 req_src_ip=10.19.21.227 req_src_port=5060 in_uri=sip:2564286286@pbxproxy:0 out_uri=sip:2564286286@pbxproxy:0 via_cnt==1" <-------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 50]: SIP/2.0 100 trying -- your call is important to us [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 87]: Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK709c3960;rport=5060;received=10.19.21.227 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 62]: From: "Matthew Nicholson" ;tag=as72fca25f [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 31]: To: [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 51]: Call-ID: 6c731b3a470698452e330aab38e4bc73@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 42]: Server: OpenSer (1.1.0-notls (i386/linux)) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 17]: Content-Length: 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [184]: Warning: 392 10.19.20.229:5060 "Noisy feedback tells: pid=1115 req_src_ip=10.19.21.227 req_src_port=5060 in_uri=sip:2564286286@pbxproxy:0 out_uri=sip:2564286286@pbxproxy:0 via_cnt==1" [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 0]: --- (9 headers 0 lines) --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3289 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #12 - INVITE (got response) [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3296 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6c731b3a470698452e330aab38e4bc73@127.0.0.1' Request 102: Found [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:15819 handle_response_invite: SIP response 100 to standard invite <--- SIP read from UDP://10.19.20.229:5060 ---> SIP/2.0 403 Forbidden Via: SIP/2.0/UDP 127.0.0.1:5060;received=10.19.21.227;branch=z9hG4bK709c3960;rport=5060 From: "Matthew Nicholson" ;tag=as72fca25f To: ;tag=as177d546a Call-ID: 6c731b3a470698452e330aab38e4bc73@127.0.0.1 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 <-------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 21]: SIP/2.0 403 Forbidden [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 87]: Via: SIP/2.0/UDP 127.0.0.1:5060;received=10.19.21.227;branch=z9hG4bK709c3960;rport=5060 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 62]: From: "Matthew Nicholson" ;tag=as72fca25f [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [ 46]: To: ;tag=as177d546a [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 51]: Call-ID: 6c731b3a470698452e330aab38e4bc73@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 24]: User-Agent: Asterisk PBX [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 19]: Supported: replaces [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 17]: Content-Length: 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3219 __sip_ack: Acked pending invite 102 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3256 __sip_ack: Stopping retransmission on '6c731b3a470698452e330aab38e4bc73@127.0.0.1' of Request 102: Match Found [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:15819 handle_response_invite: SIP response 403 to standard invite Transmitting (no NAT) to 10.19.20.229:5060: ACK sip:2564286286@pbxproxy:0 SIP/2.0 Via: SIP/2.0/UDP 127.0.0.1:5060;branch=z9hG4bK709c3960;rport Max-Forwards: 70 From: "Matthew Nicholson" ;tag=as72fca25f To: ;tag=as177d546a Contact: Call-ID: 6c731b3a470698452e330aab38e4bc73@127.0.0.1 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r126903 Content-Length: 0 --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'ACK sip:25' onto UDP socket destined for 10.19.20.229:5060 [Jul 3 18:08:51] WARNING[1167]: chan_sip.c:16042 handle_response_invite: Received response: "Forbidden" from '"Matthew Nicholson" ;tag=as72fca25f' [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2546 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 6c731b3a470698452e330aab38e4bc73@127.0.0.1 -- SIP/pbxproxy-08267118 is circuit-busy [Jul 3 18:08:51] DEBUG[1167]: channel.c:1648 ast_hangup: Hanging up channel 'SIP/pbxproxy-08267118' [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5023 sip_hangup: Hangup call SIP/pbxproxy-08267118, SIP callid 6c731b3a470698452e330aab38e4bc73@127.0.0.1 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/pbxproxy-08267118 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/pbxproxy == Everyone is busy/congested at this time (1:0/1/0) [Jul 3 18:08:51] DEBUG[1167]: rtp.c:2037 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Jul 3 18:08:51] DEBUG[1167]: app_dial.c:1993 dial_exec_full: Exiting with DIALSTATUS=CONGESTION. -- Auto fallthrough, channel 'SIP/ekiga-0824d3d8' status is 'CONGESTION' <--- Reliably Transmitting (no NAT) to 10.19.18.226:5063 ---> SIP/2.0 503 Service Unavailable Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK0c10c1c2-9847-dd11-942c-001d09892b15;received=10.19.18.226;rport=5063 From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 To: ;tag=as5e729e82 Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo CSeq: 2 INVITE Server: Asterisk PBX SVN-trunk-r126903 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 X-Asterisk-HangupCause: Call Rejected X-Asterisk-HangupCauseCode: 21 <------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3089 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #14 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2763 __sip_xmit: Trying to put 'SIP/2.0 50' onto UDP socket destined for 10.19.18.226:5063 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:2546 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 6e3cbfc2-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:51] DEBUG[1167]: channel.c:1547 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/ekiga-0824d3d8' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ekiga [Jul 3 18:08:51] DEBUG[1167]: channel.c:1547 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/ekiga-0824d3d8' [Jul 3 18:08:51] DEBUG[1167]: channel.c:1648 ast_hangup: Hanging up channel 'SIP/ekiga-0824d3d8' [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:5023 sip_hangup: Hangup call SIP/ekiga-0824d3d8, SIP callid 6e3cbfc2-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:466 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/ekiga [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/ekiga-0824d3d8 - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/ekiga-0824d3d8' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - ekiga [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer ekiga [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/ekiga - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/ekiga' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - pbxproxy-08254fd8 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer pbxproxy-08254fd8 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/pbxproxy-08254fd8 - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/pbxproxy-08254fd8' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - pbxproxy [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer pbxproxy [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/pbxproxy - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/pbxproxy' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - pbxproxy-08267118 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer pbxproxy-08267118 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/pbxproxy-08267118 - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/pbxproxy-08267118' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - pbxproxy [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer pbxproxy [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/pbxproxy - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/pbxproxy' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/ekiga-0824d3d8 - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/ekiga-0824d3d8' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - ekiga [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer ekiga [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/ekiga - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/ekiga' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer ekiga-0824d3d8 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/ekiga-0824d3d8 - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/ekiga-0824d3d8' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:342 ast_device_state: No provider found, checking channel drivers for SIP - ekiga [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:20421 sip_devicestate: Checking device state for peer ekiga [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:455 do_state_change: Changing state for SIP/ekiga - state 1 (Not in use) [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:426 devstate_event: device 'SIP/ekiga' state '1' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:665 handle_devstate_change: Processing device state change for 'SIP/ekiga-0824d3d8' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:621 process_collection: Aggregate devstate result is 1 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:643 process_collection: Aggregate state for device 'SIP/ekiga-0824d3d8' has changed to 'Not in use' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:665 handle_devstate_change: Processing device state change for 'SIP/ekiga' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:621 process_collection: Aggregate devstate result is 1 [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:637 process_collection: Aggregate state for device 'SIP/ekiga' has not changed from 'Not in use' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:665 handle_devstate_change: Processing device state change for 'SIP/pbxproxy-08254fd8' [Jul 3 18:08:51] DEBUG[1167]: devicestate.c:621 process_collection: Aggregate devstate result is 1 sip-outboundproxy-test-trunk*CLI> <--- SIP read from UDP://10.19.18.226:5063 ---> ACK sip:s@10.19.21.227 SIP/2.0 CSeq: 2 ACK Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK0c10c1c2-9847-dd11-942c-001d09892b15;rport Authorization: Digest username="ekiga", realm="asterisk", nonce="31b47158", uri="sip:s@10.19.21.227", algorithm=md5, response="39334a083a6d071a923c129b9ac97776" From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo To: ;tag=as5e729e82 Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE Content-Length: 0 Max-Forwards: 70 <-------------> [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 0 [ 30]: ACK sip:s@10.19.21.227 SIP/2.0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 1 [ 11]: CSeq: 2 ACK [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 2 [ 91]: Via: SIP/2.0/UDP 10.19.18.226:5063;branch=z9hG4bK0c10c1c2-9847-dd11-942c-001d09892b15;rport [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 3 [160]: Authorization: Digest username="ekiga", realm="asterisk", nonce="31b47158", uri="sip:s@10.19.21.227", algorithm=md5, response="39334a083a6d071a923c129b9ac97776" [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 4 [ 91]: From: "Matthew Nicholson" ;tag=ca3fbfc2-9847-dd11-942c-001d09892b15 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 5 [ 50]: Call-ID: 6e3cbfc2-9847-dd11-942c-001d09892b15@solo [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 6 [ 39]: To: ;tag=as5e729e82 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 7 [ 57]: Allow: INVITE,ACK,OPTIONS,BYE,CANCEL,NOTIFY,REFER,MESSAGE [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 8 [ 17]: Content-Length: 0 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 9 [ 16]: Max-Forwards: 70 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:6525 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:19323 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3224 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #14 [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:3256 __sip_ack: Stopping retransmission on '6e3cbfc2-9847-dd11-942c-001d09892b15@solo' of Response 2: Match Found [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4814 sip_destroy: Destroying SIP dialog 6e3cbfc2-9847-dd11-942c-001d09892b15@solo Really destroying SIP dialog '6e3cbfc2-9847-dd11-942c-001d09892b15@solo' Method: ACK [Jul 3 18:08:51] DEBUG[1167]: chan_sip.c:4814 sip_destroy: Destroying SIP dialog 6c731b3a470698452e330aab38e4bc73@127.0.0.1 Really destroying SIP dialog '6c731b3a470698452e330aab38e4bc73@127.0.0.1' Method: INVITE [Jul 3 18:09:07] DEBUG[1167]: chan_sip.c:3146 __sip_autodestruct: Auto destroying SIP dialog 'ac18beb8-9847-dd11-942c-001d09892b15@solo' [Jul 3 18:09:07] DEBUG[1167]: chan_sip.c:4814 sip_destroy: Destroying SIP dialog ac18beb8-9847-dd11-942c-001d09892b15@solo Really destroying SIP dialog 'ac18beb8-9847-dd11-942c-001d09892b15@solo' Method: REGISTER sip-outboundproxy-test-trunk*CLI> exit