[Apr 13 13:14:56] Asterisk 1.6.0-beta7.1, Copyright (C) 1999 - 2008 Digium, Inc. and others. SIP Debugging enabled *CLI> [Apr 13 13:17:18] <--- SIP read from UDP://10.50.10.2:5060 ---> OPTIONS sip:metaswitch@10.50.10.171:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-24d0a8bec9eb4666d5732ae4217c4710-metaswitch-1 Allow-Events: message-summary Allow-Events: refer Allow-Events: dialog Allow-Events: line-seize Max-Forwards: 70 Call-ID: 6FD7E337@metaswitch From: ;tag=metaswitch+1+0+d1d885cc CSeq: 1044437156 OPTIONS Organization: Supported: 100rel Content-Length: 0 Contact: To: <-------------> [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 62]: OPTIONS sip:metaswitch@10.50.10.171:5060;transport=udp SIP/2.0 [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 99]: Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-24d0a8bec9eb4666d5732ae4217c4710-metaswitch-1 [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 29]: Allow-Events: message-summary [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 19]: Allow-Events: refer [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 20]: Allow-Events: dialog [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 24]: Allow-Events: line-seize [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 28]: Call-ID: 6FD7E337@metaswitch [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 66]: From: ;tag=metaswitch+1+0+d1d885cc [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 9 [ 24]: CSeq: 1044437156 OPTIONS [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 10 [ 14]: Organization: [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 11 [ 17]: Supported: 100rel [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 12 [ 17]: Content-Length: 0 [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 13 [ 41]: Contact: [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 14 [ 33]: To: [Apr 13 13:17:18] --- (15 headers 0 lines) --- [Apr 13 13:17:18] DEBUG[3171]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:5810 sip_alloc: Allocating new SIP dialog for 6FD7E337@metaswitch - OPTIONS (No RTP) [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:17847 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 13 13:17:18] Looking for metaswitch in default (domain 10.50.10.171) [Apr 13 13:17:18] <--- Transmitting (no NAT) to 10.50.10.2:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-24d0a8bec9eb4666d5732ae4217c4710-metaswitch-1;received=10.50.10.2 From: ;tag=metaswitch+1+0+d1d885cc To: ;tag=as06663848 Call-ID: 6FD7E337@metaswitch CSeq: 1044437156 OPTIONS User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket... [Apr 13 13:17:18] Scheduling destruction of SIP dialog '6FD7E337@metaswitch' in 32000 ms (Method: OPTIONS) [Apr 13 13:17:18] DEBUG[3171]: chan_sip.c:18085 handle_request_do: SIP message could not be handled, bad request: 6FD7E337@metaswitch [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2893 __sip_autodestruct: Auto destroying SIP dialog '86E4947E@metaswitch' [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:4482 sip_destroy: Destroying SIP dialog 86E4947E@metaswitch [Apr 13 13:17:20] Really destroying SIP dialog '86E4947E@metaswitch' Method: OPTIONS [Apr 13 13:17:20] <--- SIP read from UDP://10.50.10.183:5060 ---> INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKe94f4613acd6249e7 Max-Forwards: 70 From: "Trunk01" ;tag=73cd605058 To: "station3_line1" Call-ID: 31f73dfddaf76719 CSeq: 16337 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference Contact: Trunk01 Supported: timer, 100rel, replaces User-Agent: Aastra 55i/2.2.0.166 Content-Type: application/sdp Content-Length: 282 v=0 o=MxSIP 0 0 IN IP4 10.50.10.183 s=SIP Call c=IN IP4 10.50.10.183 t=0 0 m=audio 3000 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=silenceSupp:on - - - - a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 51]: INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKe94f4613acd6249e7 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 63]: From: "Trunk01" ;tag=73cd605058 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 59]: To: "station3_line1" [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: 31f73dfddaf76719 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 18]: CSeq: 16337 INVITE [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 87]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 36]: Allow-Events: talk, hold, conference [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 9 [ 63]: Contact: Trunk01 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 10 [ 34]: Supported: timer, 100rel, replaces [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 11 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 13 [ 19]: Content-Length: 282 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 14 [ 0]: [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 0 [ 3]: v=0 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 1 [ 31]: o=MxSIP 0 0 IN IP4 10.50.10.183 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 2 [ 10]: s=SIP Call [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 3 [ 21]: c=IN IP4 10.50.10.183 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 4 [ 5]: t=0 0 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 5 [ 31]: m=audio 3000 RTP/AVP 0 8 18 101 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 10 [ 24]: a=silenceSupp:on - - - - [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 11 [ 15]: a=fmtp:101 0-15 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 12 [ 10]: a=ptime:30 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6141 parse_request: Body 13 [ 10]: a=sendrecv [Apr 13 13:17:20] --- (14 headers 14 lines) --- [Apr 13 13:17:20] DEBUG[3171]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 13 13:17:20] == Using SIP RTP CoS mark 5 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:3837 do_setnat: Setting NAT on RTP to Off [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:5810 sip_alloc: Allocating new SIP dialog for 31f73dfddaf76719 - INVITE (With RTP) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:17847 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2420 parse_sip_options: Begin: parsing SIP "Supported: timer, 100rel, replaces" [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2428 parse_sip_options: Found SIP option: -timer- [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2434 parse_sip_options: Matched SIP option: timer [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2428 parse_sip_options: Found SIP option: -100rel- [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2434 parse_sip_options: Matched SIP option: 100rel [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2428 parse_sip_options: Found SIP option: -replaces- [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2434 parse_sip_options: Matched SIP option: replaces [Apr 13 13:17:20] Sending to 10.50.10.183 : 5060 (no NAT) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:16265 handle_request_invite: Initializing initreq for method INVITE - callid 31f73dfddaf76719 [Apr 13 13:17:20] Using INVITE request as basis request - 31f73dfddaf76719 [Apr 13 13:17:20] Found user 'station3' for 'station3' [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:3837 do_setnat: Setting NAT on RTP to Off [Apr 13 13:17:20] <--- Reliably Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKe94f4613acd6249e7;received=10.50.10.183 From: "Trunk01" ;tag=73cd605058 To: "station3_line1" ;tag=as74a27d6a Call-ID: 31f73dfddaf76719 CSeq: 16337 INVITE User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5325342f" Content-Length: 0 <------------> [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2837 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #61 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket... [Apr 13 13:17:20] Scheduling destruction of SIP dialog '31f73dfddaf76719' in 32000 ms (Method: INVITE) [Apr 13 13:17:20] <--- SIP read from UDP://10.50.10.183:5060 ---> ACK sip:station3_line1@10.50.10.171:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKe94f4613acd6249e7 Max-Forwards: 70 From: "Trunk01" ;tag=73cd605058 To: "station3_line1" ;tag=as74a27d6a Call-ID: 31f73dfddaf76719 CSeq: 16337 ACK User-Agent: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 48]: ACK sip:station3_line1@10.50.10.171:5060 SIP/2.0 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bKe94f4613acd6249e7 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 63]: From: "Trunk01" ;tag=73cd605058 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 74]: To: "station3_line1" ;tag=as74a27d6a [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: 31f73dfddaf76719 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 15]: CSeq: 16337 ACK [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 17]: Content-Length: 0 [Apr 13 13:17:20] --- (9 headers 0 lines) --- [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:17847 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2966 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #61 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2996 __sip_ack: Stopping retransmission on '31f73dfddaf76719' of Response 16337: Match Found [Apr 13 13:17:20] <--- SIP read from UDP://10.50.10.183:5060 ---> INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK41c3044840f2ef9ce Max-Forwards: 70 From: "Trunk01" ;tag=73cd605058 To: "station3_line1" Call-ID: 31f73dfddaf76719 CSeq: 16338 INVITE Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO Allow-Events: talk, hold, conference Authorization: Digest username="station3",realm="asterisk",nonce="5325342f",uri="sip:station3_line1@10.50.10.171:5060",response="04393e1cfb8bc15b81174670cf0b0d7c",algorithm=MD5 Contact: Trunk01 Supported: timer, 100rel, replaces User-Agent: Aastra 55i/2.2.0.166 Content-Type: application/sdp Content-Length: 282 v=0 o=MxSIP 0 0 IN IP4 10.50.10.183 s=SIP Call c=IN IP4 10.50.10.183 t=0 0 m=audio 3000 RTP/AVP 0 8 18 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=rtpmap:101 telephone-event/8000 a=silenceSupp:on - - - - a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 51]: INVITE sip:station3_line1@10.50.10.171:5060 SIP/2.0 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK41c3044840f2ef9ce [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 63]: From: "Trunk01" ;tag=73cd605058 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 59]: To: "station3_line1" [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: 31f73dfddaf76719 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 18]: CSeq: 16338 INVITE [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 87]: Allow: INVITE, ACK, CANCEL, BYE, NOTIFY, REFER, OPTIONS, UPDATE, PRACK, SUBSCRIBE, INFO [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 36]: Allow-Events: talk, hold, conference [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 9 [176]: Authorization: Digest username="station3",realm="asterisk",nonce="5325342f",uri="sip:station3_line1@10.50.10.171:5060",response="04393e1cfb8bc15b81174670cf0b0d7c",algorithm=MD5 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 10 [ 63]: Contact: Trunk01 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 11 [ 34]: Supported: timer, 100rel, replaces [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 12 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 13 [ 29]: Content-Type: application/sdp [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 14 [ 19]: Content-Length: 282 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 15 [ 0]: [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 0 [ 3]: v=0 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 1 [ 31]: o=MxSIP 0 0 IN IP4 10.50.10.183 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 2 [ 10]: s=SIP Call [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 3 [ 21]: c=IN IP4 10.50.10.183 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 4 [ 5]: t=0 0 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 5 [ 31]: m=audio 3000 RTP/AVP 0 8 18 101 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 7 [ 20]: a=rtpmap:8 PCMA/8000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 8 [ 21]: a=rtpmap:18 G729/8000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 10 [ 24]: a=silenceSupp:on - - - - [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 11 [ 15]: a=fmtp:101 0-15 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Body 12 [ 10]: a=ptime:30 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6141 parse_request: Body 13 [ 10]: a=sendrecv [Apr 13 13:17:20] --- (15 headers 14 lines) --- [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:17847 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Apr 13 13:17:20] Sending to 10.50.10.183 : 5060 (no NAT) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:16265 handle_request_invite: Initializing initreq for method INVITE - callid 31f73dfddaf76719 [Apr 13 13:17:20] Using INVITE request as basis request - 31f73dfddaf76719 [Apr 13 13:17:20] Found user 'station3' for 'station3' [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:3837 do_setnat: Setting NAT on RTP to Off [Apr 13 13:17:20] Found RTP audio format 0 [Apr 13 13:17:20] Found RTP audio format 8 [Apr 13 13:17:20] Found RTP audio format 18 [Apr 13 13:17:20] Found RTP audio format 101 [Apr 13 13:17:20] Peer audio RTP is at port 10.50.10.183:3000 [Apr 13 13:17:20] Found audio description format PCMU for ID 0 [Apr 13 13:17:20] Found audio description format PCMA for ID 8 [Apr 13 13:17:20] Found audio description format G729 for ID 18 [Apr 13 13:17:20] Found audio description format telephone-event for ID 101 [Apr 13 13:17:20] Got unsupported a:fmtp in SDP offer [Apr 13 13:17:20] Capabilities: us - 0xe (gsm|ulaw|alaw), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xc (ulaw|alaw) [Apr 13 13:17:20] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 13 13:17:20] Peer audio RTP is at port 10.50.10.183:3000 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6894 process_sdp: We're settling with these formats: 0xc (ulaw|alaw) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:16342 handle_request_invite: Checking SIP call limits for device station3 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:4381 update_call_counter: Updating call counter for incoming call [Apr 13 13:17:20] Looking for station3_line1 in sla_stations (domain 10.50.10.171) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:5241 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:5242 sip_new: *** Joint capabilities are 0xc (ulaw|alaw) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:5243 sip_new: *** Our capabilities are 0xe (gsm|ulaw|alaw) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:5244 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:5272 sip_new: This channel will not be able to handle video. [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:9937 build_route: build_route: Contact hop: Trunk01 [Apr 13 13:17:20] list_route: hop: [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:16552 handle_request_invite: SIP/station3-085045c8: New call is still down.... Trying... [Apr 13 13:17:20] <--- Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK41c3044840f2ef9ce;received=10.50.10.183 From: "Trunk01" ;tag=73cd605058 To: "station3_line1" Call-ID: 31f73dfddaf76719 CSeq: 16338 INVITE User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket... [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3-085045c8 [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3 [Apr 13 13:17:20] DEBUG[3171]: pbx.c:2693 pbx_extension_helper: Launching 'SLAStation' [Apr 13 13:17:20] -- Executing [station3_line1@sla_stations:1] SLAStation("SIP/station3-085045c8", "station3_line1") in new stack [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1 [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1 [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1 [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3-085045c8 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3-085045c8 [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:430 do_state_change: Changing state for SIP/station3-085045c8 - state 1 (Not in use) [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3 [Apr 13 13:17:20] DEBUG[3171]: devicestate.c:430 do_state_change: Changing state for SIP/station3 - state 1 (Not in use) [Apr 13 13:17:20] DEBUG[3171]: channel.c:3690 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 13 13:17:20] DEBUG[3171]: channel.c:3690 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 13 13:17:20] DEBUG[3171]: channel.c:3690 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 13 13:17:20] -- Called disa@line1_outbound [Apr 13 13:17:20] Reliably Transmitting (no NAT) to 10.50.10.183:5060: NOTIFY sip:station3@10.50.10.183:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK3c2e3073;rport Max-Forwards: 70 From: ;tag=as22b73eb9 To: Trunk01 ;tag=b73ddcd0cd Contact: Call-ID: df6f22fa49bf414d CSeq: 103 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta7.1 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 229 confirmed --- [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2837 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #63 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2520 __sip_xmit: Trying to put 'NOTIFY sip' onto UDP socket... [Apr 13 13:17:20] == Extension Changed station3_line1[sla_stations] new state InUse for Notify User station3 [Apr 13 13:17:20] DEBUG[3171]: app_queue.c:761 handle_statechange: Device 'SIP/station3-085045c8' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 13:17:20] DEBUG[3171]: app_queue.c:761 handle_statechange: Device 'SIP/station3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 13:17:20] DEBUG[3171]: pbx.c:2693 pbx_extension_helper: Launching 'DISA' [Apr 13 13:17:20] -- Executing [disa@line1_outbound:2] DISA("Local/disa@line1_outbound-d5fc;2", "no-password") in new stack [Apr 13 13:17:20] DEBUG[3171]: app_disa.c:142 disa_exec: Digittimeout: 5000 [Apr 13 13:17:20] DEBUG[3171]: app_disa.c:143 disa_exec: Responsetimeout: 10000 [Apr 13 13:17:20] DEBUG[3171]: app_disa.c:156 disa_exec: Mailbox: [Apr 13 13:17:20] DEBUG[3171]: app_disa.c:166 disa_exec: Context: disa [Apr 13 13:17:20] DEBUG[3171]: app_disa.c:170 disa_exec: DISA no-password login success [Apr 13 13:17:20] DEBUG[3171]: channel.c:2908 ast_prod: Prodding channel 'Local/disa@line1_outbound-d5fc;2' [Apr 13 13:17:20] DEBUG[3171]: channel.c:3174 set_format: Set channel Local/disa@line1_outbound-d5fc;2 to write format slin [Apr 13 13:17:20] DEBUG[3171]: channel.c:2156 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 13 13:17:20] <--- SIP read from UDP://10.50.10.183:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK3c2e3073;rport=5060;received=10.50.10.171 From: ;tag=as22b73eb9 To: Trunk01 ;tag=b73ddcd0cd Call-ID: df6f22fa49bf414d CSeq: 103 NOTIFY Contact: Trunk01 Server: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK3c2e3073;rport=5060;received=10.50.10.171 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 59]: From: ;tag=as22b73eb9 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 59]: To: Trunk01 ;tag=b73ddcd0cd [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 25]: Call-ID: df6f22fa49bf414d [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 16]: CSeq: 103 NOTIFY [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 63]: Contact: Trunk01 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 28]: Server: Aastra 55i/2.2.0.166 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 17]: Content-Length: 0 [Apr 13 13:17:20] --- (9 headers 0 lines) --- [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2961 __sip_ack: Acked pending invite 103 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2966 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #63 [Apr 13 13:17:20] DEBUG[3171]: chan_sip.c:2996 __sip_ack: Stopping retransmission on 'df6f22fa49bf414d' of Request 103: Match Found [Apr 13 13:17:20] SIP Response message for INCOMING dialog NOTIFY arrived [Apr 13 13:17:30] DEBUG[3171]: app_disa.c:183 disa_exec: DISA extension entry timeout on chan Local/disa@line1_outbound-d5fc;2 [Apr 13 13:17:30] -- Local/disa@line1_outbound-d5fc;1 is circuit-busy [Apr 13 13:17:30] DEBUG[3171]: channel.c:1617 ast_hangup: Hanging up channel 'Local/disa@line1_outbound-d5fc;1' [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-d5fc;1 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 13:17:30] DEBUG[3171]: channel.c:3174 set_format: Set channel Local/disa@line1_outbound-d5fc;2 to write format ulaw [Apr 13 13:17:30] DEBUG[3171]: channel.c:2156 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 13 13:17:30] DEBUG[3171]: pbx.c:3336 __ast_pbx_run: Spawn extension (line1_outbound,disa,2) exited non-zero on 'Local/disa@line1_outbound-d5fc;2' [Apr 13 13:17:30] == Spawn extension (line1_outbound, disa, 2) exited non-zero on 'Local/disa@line1_outbound-d5fc;2' [Apr 13 13:17:30] DEBUG[3171]: channel.c:1518 ast_softhangup_nolock: Soft-Hanging up channel 'Local/disa@line1_outbound-d5fc;2' [Apr 13 13:17:30] DEBUG[3171]: channel.c:1617 ast_hangup: Hanging up channel 'Local/disa@line1_outbound-d5fc;2' [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound-d5fc;2 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel Local/disa@line1_outbound [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-d5fc;1 [Apr 13 13:17:30] DEBUG[3171]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound-d5fc;1 exists (devicestate) [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound-d5fc;1 - state 4 (Invalid) [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 13:17:30] DEBUG[3171]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound - state 1 (Not in use) [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound-d5fc;2 [Apr 13 13:17:30] DEBUG[3171]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound-d5fc;2 exists (devicestate) [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound-d5fc;2 - state 4 (Invalid) [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for Local - disa@line1_outbound [Apr 13 13:17:30] DEBUG[3171]: chan_local.c:141 local_devicestate: Checking if extension disa@line1_outbound exists (devicestate) [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:430 do_state_change: Changing state for Local/disa@line1_outbound - state 1 (Not in use) [Apr 13 13:17:30] DEBUG[3171]: app_queue.c:761 handle_statechange: Device 'Local/disa@line1_outbound-d5fc;1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 13:17:30] DEBUG[3171]: app_queue.c:761 handle_statechange: Device 'Local/disa@line1_outbound' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 13:17:30] DEBUG[3171]: app_queue.c:761 handle_statechange: Device 'Local/disa@line1_outbound-d5fc;2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 13 13:17:30] DEBUG[3171]: app_queue.c:761 handle_statechange: Device 'Local/disa@line1_outbound' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 13:17:30] DEBUG[3171]: app_meetme.c:4905 sla_station_exec: Trunk didn't get created. chan: 0 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station1_line1 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station2_line1 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SLA:station3_line1 [Apr 13 13:17:30] -- Auto fallthrough, channel 'SIP/station3-085045c8' status is 'UNKNOWN' [Apr 13 13:17:30] DEBUG[3171]: channel.c:1518 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/station3-085045c8' [Apr 13 13:17:30] DEBUG[3171]: channel.c:1617 ast_hangup: Hanging up channel 'SIP/station3-085045c8' [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:4689 sip_hangup: Hangup call SIP/station3-085045c8, SIP callid 31f73dfddaf76719 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:4708 sip_hangup: Hanging up channel in state Ring (not UP) [Apr 13 13:17:30] Scheduling destruction of SIP dialog '31f73dfddaf76719' in 32000 ms (Method: INVITE) [Apr 13 13:17:30] <--- Reliably Transmitting (no NAT) to 10.50.10.183:5060 ---> SIP/2.0 603 Declined Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK41c3044840f2ef9ce;received=10.50.10.183 From: "Trunk01" ;tag=73cd605058 To: "station3_line1" ;tag=as10985b60 Call-ID: 31f73dfddaf76719 CSeq: 16338 INVITE User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Contact: Content-Length: 0 <------------> [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2837 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #65 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 60' onto UDP socket... [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3-085045c8 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:441 __ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/station3 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3-085045c8 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3-085045c8 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:430 do_state_change: Changing state for SIP/station3-085045c8 - state 1 (Not in use) [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:320 ast_device_state: No provider found, checking channel drivers for SIP - station3 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:18907 sip_devicestate: Checking device state for peer station3 [Apr 13 13:17:30] DEBUG[3171]: devicestate.c:430 do_state_change: Changing state for SIP/station3 - state 1 (Not in use) [Apr 13 13:17:30] Reliably Transmitting (no NAT) to 10.50.10.183:5060: NOTIFY sip:station3@10.50.10.183:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK0d4f75c5;rport Max-Forwards: 70 From: ;tag=as22b73eb9 To: Trunk01 ;tag=b73ddcd0cd Contact: Call-ID: df6f22fa49bf414d CSeq: 104 NOTIFY User-Agent: Asterisk PBX 1.6.0-beta7.1 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 230 terminated --- [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2837 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #66 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2520 __sip_xmit: Trying to put 'NOTIFY sip' onto UDP socket... [Apr 13 13:17:30] == Extension Changed station3_line1[sla_stations] new state Idle for Notify User station3 [Apr 13 13:17:30] DEBUG[3171]: app_queue.c:761 handle_statechange: Device 'SIP/station3-085045c8' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 13:17:30] DEBUG[3171]: app_queue.c:761 handle_statechange: Device 'SIP/station3' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 13 13:17:30] <--- SIP read from UDP://10.50.10.183:5060 ---> ACK sip:station3_line1@10.50.10.171:5060 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK41c3044840f2ef9ce Max-Forwards: 70 From: "Trunk01" ;tag=73cd605058 To: "station3_line1" ;tag=as10985b60 Call-ID: 31f73dfddaf76719 CSeq: 16338 ACK User-Agent: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 48]: ACK sip:station3_line1@10.50.10.171:5060 SIP/2.0 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 66]: Via: SIP/2.0/UDP 10.50.10.183:5060;branch=z9hG4bK41c3044840f2ef9ce [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 63]: From: "Trunk01" ;tag=73cd605058 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 74]: To: "station3_line1" ;tag=as10985b60 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 25]: Call-ID: 31f73dfddaf76719 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 15]: CSeq: 16338 ACK [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 32]: User-Agent: Aastra 55i/2.2.0.166 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 17]: Content-Length: 0 [Apr 13 13:17:30] --- (9 headers 0 lines) --- [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:17847 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2966 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #65 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2996 __sip_ack: Stopping retransmission on '31f73dfddaf76719' of Response 16338: Match Found [Apr 13 13:17:30] <--- SIP read from UDP://10.50.10.183:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK0d4f75c5;rport=5060;received=10.50.10.171 From: ;tag=as22b73eb9 To: Trunk01 ;tag=b73ddcd0cd Call-ID: df6f22fa49bf414d CSeq: 104 NOTIFY Contact: Trunk01 Server: Aastra 55i/2.2.0.166 Content-Length: 0 <-------------> [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 14]: SIP/2.0 200 OK [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 90]: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK0d4f75c5;rport=5060;received=10.50.10.171 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 59]: From: ;tag=as22b73eb9 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 59]: To: Trunk01 ;tag=b73ddcd0cd [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 25]: Call-ID: df6f22fa49bf414d [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 16]: CSeq: 104 NOTIFY [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 63]: Contact: Trunk01 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 28]: Server: Aastra 55i/2.2.0.166 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 17]: Content-Length: 0 [Apr 13 13:17:30] --- (9 headers 0 lines) --- [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2961 __sip_ack: Acked pending invite 104 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2966 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #66 [Apr 13 13:17:30] DEBUG[3171]: chan_sip.c:2996 __sip_ack: Stopping retransmission on 'df6f22fa49bf414d' of Request 104: Match Found [Apr 13 13:17:30] SIP Response message for INCOMING dialog NOTIFY arrived [Apr 13 13:17:48] <--- SIP read from UDP://10.50.10.2:5060 ---> OPTIONS sip:metaswitch@10.50.10.171:5060;transport=udp SIP/2.0 Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-4c4373eb63015e5c66d3ffc4d9e7b753-metaswitch-1 Allow-Events: message-summary Allow-Events: refer Allow-Events: dialog Allow-Events: line-seize Max-Forwards: 70 Call-ID: DEDB1136@metaswitch From: ;tag=metaswitch+1+0+6741c44d CSeq: 518999346 OPTIONS Organization: Supported: 100rel Content-Length: 0 Contact: To: <-------------> [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 62]: OPTIONS sip:metaswitch@10.50.10.171:5060;transport=udp SIP/2.0 [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 99]: Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-4c4373eb63015e5c66d3ffc4d9e7b753-metaswitch-1 [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 29]: Allow-Events: message-summary [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 19]: Allow-Events: refer [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 20]: Allow-Events: dialog [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 24]: Allow-Events: line-seize [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 16]: Max-Forwards: 70 [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 28]: Call-ID: DEDB1136@metaswitch [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 66]: From: ;tag=metaswitch+1+0+6741c44d [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 9 [ 23]: CSeq: 518999346 OPTIONS [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 10 [ 14]: Organization: [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 11 [ 17]: Supported: 100rel [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 12 [ 17]: Content-Length: 0 [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 13 [ 41]: Contact: [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 14 [ 33]: To: [Apr 13 13:17:48] --- (15 headers 0 lines) --- [Apr 13 13:17:48] DEBUG[3171]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:5810 sip_alloc: Allocating new SIP dialog for DEDB1136@metaswitch - OPTIONS (No RTP) [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:17847 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 13 13:17:48] Looking for metaswitch in default (domain 10.50.10.171) [Apr 13 13:17:48] <--- Transmitting (no NAT) to 10.50.10.2:5060 ---> SIP/2.0 404 Not Found Via: SIP/2.0/UDP 10.50.10.2:5060;rport;branch=z9hG4bK-4c4373eb63015e5c66d3ffc4d9e7b753-metaswitch-1;received=10.50.10.2 From: ;tag=metaswitch+1+0+6741c44d To: ;tag=as56b99b97 Call-ID: DEDB1136@metaswitch CSeq: 518999346 OPTIONS User-Agent: Asterisk PBX 1.6.0-beta7.1 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Accept: application/sdp Content-Length: 0 <------------> [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:2520 __sip_xmit: Trying to put 'SIP/2.0 40' onto UDP socket... [Apr 13 13:17:48] Scheduling destruction of SIP dialog 'DEDB1136@metaswitch' in 32000 ms (Method: OPTIONS) [Apr 13 13:17:48] DEBUG[3171]: chan_sip.c:18085 handle_request_do: SIP message could not be handled, bad request: DEDB1136@metaswitch [Apr 13 13:17:50] DEBUG[3171]: chan_sip.c:2893 __sip_autodestruct: Auto destroying SIP dialog '6FD7E337@metaswitch' [Apr 13 13:17:50] DEBUG[3171]: chan_sip.c:4482 sip_destroy: Destroying SIP dialog 6FD7E337@metaswitch [Apr 13 13:17:50] Really destroying SIP dialog '6FD7E337@metaswitch' Method: OPTIONS [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:5810 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 13 13:17:59] DEBUG[3171]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:2312 initialize_initreq: Initializing initreq for method OPTIONS - callid 56f95fcd030f7a626858f42d2f4d0ffb@10.50.10.171 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 30]: OPTIONS sip:10.50.10.2 SIP/2.0 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 63]: Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK1b368b89;rport [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 59]: From: "asterisk" ;tag=as6f1ff750 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 20]: To: [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 36]: Contact: [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 54]: Call-ID: 56f95fcd030f7a626858f42d2f4d0ffb@10.50.10.171 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 17]: CSeq: 102 OPTIONS [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 38]: User-Agent: Asterisk PBX 1.6.0-beta7.1 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 9 [ 35]: Date: Sun, 13 Apr 2008 20:17:59 GMT [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 11 [ 26]: Supported: replaces, timer [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 12 [ 17]: Content-Length: 0 [Apr 13 13:17:59] Reliably Transmitting (no NAT) to 10.50.10.2:5060: OPTIONS sip:10.50.10.2 SIP/2.0 Via: SIP/2.0/UDP 10.50.10.171:5060;branch=z9hG4bK1b368b89;rport Max-Forwards: 70 From: "asterisk" ;tag=as6f1ff750 To: Contact: Call-ID: 56f95fcd030f7a626858f42d2f4d0ffb@10.50.10.171 CSeq: 102 OPTIONS User-Agent: Asterisk PBX 1.6.0-beta7.1 Date: Sun, 13 Apr 2008 20:17:59 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces, timer Content-Length: 0 --- [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:2837 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #68 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:2520 __sip_xmit: Trying to put 'OPTIONS si' onto UDP socket... [Apr 13 13:17:59] <--- SIP read from UDP://10.50.10.2:5060 ---> SIP/2.0 403 From: URI not recognized From: "asterisk" ;tag=as6f1ff750 To: ;tag=metaswitch+1+0+66292390 Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK1b368b89 Server: DC-SIP/2.0 Organization: Content-Length: 0 Call-ID: 56f95fcd030f7a626858f42d2f4d0ffb@10.50.10.171 CSeq: 102 OPTIONS <-------------> [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 0 [ 36]: SIP/2.0 403 From: URI not recognized [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 1 [ 59]: From: "asterisk" ;tag=as6f1ff750 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 2 [ 48]: To: ;tag=metaswitch+1+0+66292390 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 3 [ 68]: Via: SIP/2.0/UDP 10.50.10.171:5060;rport=5060;branch=z9hG4bK1b368b89 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 4 [ 18]: Server: DC-SIP/2.0 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 5 [ 14]: Organization: [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 6 [ 17]: Content-Length: 0 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 7 [ 54]: Call-ID: 56f95fcd030f7a626858f42d2f4d0ffb@10.50.10.171 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:6121 parse_request: Header 8 [ 17]: CSeq: 102 OPTIONS [Apr 13 13:17:59] --- (9 headers 0 lines) --- [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:2966 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #68 [Apr 13 13:17:59] DEBUG[3171]: chan_sip.c:2996 __sip_ack: Stopping retransmission on '56f95fcd030f7a626858f42d2f4d0ffb@10.50.10.171' of Request 102: Match Found [Apr 13 13:17:59] Really destroying SIP dialog '56f95fcd030f7a626858f42d2f4d0ffb@10.50.10.171' Method: OPTIONS