--- [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #25 [Apr 5 17:28:48] <--- SIP read from 192.168.4.11:5060 ---> SIP/2.0 405 Method Not Allowed Via: SIP/2.0/UDP 192.168.4.14:5060;rport=5060;received=192.168.4.14;branch=z9hG4bK7cf5743c Content-Length: 0 Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY Call-ID: 46aad36f1592930018cae795774fd5fa@192.168.4.14 CSeq: 102 OPTIONS From: "asterisk";tag=as12bae4c3 Server: SJphone/1.60.289a (SJ Labs) To: "unknown" <-------------> [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 405 Method Not Allowed (30) [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;rport=5060;received=192.168.4.14;branch=z9hG4bK7cf5743c (90) [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY (46) [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 46aad36f1592930018cae795774fd5fa@192.168.4.14 (54) [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: From: "asterisk";tag=as12bae4c3 (58) [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Server: SJphone/1.60.289a (SJ Labs) (35) [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: To: "unknown" (40) [Apr 5 17:28:48] --- (9 headers 0 lines) --- [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #25 [Apr 5 17:28:48] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '46aad36f1592930018cae795774fd5fa@192.168.4.14' of Request 102: Match Not Found [Apr 5 17:28:48] Really destroying SIP dialog '46aad36f1592930018cae795774fd5fa@192.168.4.14' Method: OPTIONS [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:102@192.168.4.104:5060;line=9l1gd4rz SIP/2.0 (56) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK40d8d9ee;rport (63) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as3c0179c1 (59) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Contact: (36) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 2f8bc5a272e1614736eaab4d26e50883@192.168.4.14 (54) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 05 Apr 2007 15:28:49 GMT (35) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Apr 5 17:28:49] Reliably Transmitting (NAT) to 192.168.4.104:5060: OPTIONS sip:102@192.168.4.104:5060;line=9l1gd4rz SIP/2.0 Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK40d8d9ee;rport From: "asterisk" ;tag=as3c0179c1 To: Contact: Call-ID: 2f8bc5a272e1614736eaab4d26e50883@192.168.4.14 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 15:28:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #28 [Apr 5 17:28:49] <--- SIP read from 192.168.4.104:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK40d8d9ee;rport=5060 From: "asterisk" ;tag=as3c0179c1 To: Call-ID: 2f8bc5a272e1614736eaab4d26e50883@192.168.4.14 CSeq: 102 OPTIONS Contact: User-Agent: snom220-3.56z Accept-Language: en Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces Content-Length: 0 <-------------> [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK40d8d9ee;rport=5060 (68) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as3c0179c1 (59) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 2f8bc5a272e1614736eaab4d26e50883@192.168.4.14 (54) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Contact: (51) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: User-Agent: snom220-3.56z (25) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Accept-Language: en (19) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Accept: application/sdp (23) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Allow-Events: talk, hold, refer (31) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: Supported: timer, 100rel, replaces (34) [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 0 (17) [Apr 5 17:28:49] --- (14 headers 0 lines) --- [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #28 [Apr 5 17:28:49] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '2f8bc5a272e1614736eaab4d26e50883@192.168.4.14' of Request 102: Match Not Found [Apr 5 17:28:49] Really destroying SIP dialog '2f8bc5a272e1614736eaab4d26e50883@192.168.4.14' Method: OPTIONS [Apr 5 17:28:54] <--- SIP read from 192.168.4.11:5060 ---> OPTIONS sip:192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515ad0000762700000034 Content-Length: 0 Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 CSeq: 10 OPTIONS From: ;tag=3454962514087 Max-Forwards: 70 To: <-------------> [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:192.168.4.14:5060 SIP/2.0 (37) [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515ad0000762700000034 (90) [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 (58) [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 10 OPTIONS (16) [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: ;tag=3454962514087 (51) [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: (27) [Apr 5 17:28:54] --- (8 headers 0 lines) --- [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 - OPTIONS (No RTP) [Apr 5 17:28:54] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 5 17:28:54] Looking for s in default (domain 192.168.4.14) [Apr 5 17:28:54] <--- Transmitting (no NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000000b461515ad0000762700000034;received=192.168.4.11;rport=5060 From: ;tag=3454962514087 To: ;tag=as7a366f26 Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 CSeq: 10 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Apr 5 17:28:54] Scheduling destruction of SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' in 32000 ms (Method: OPTIONS) [Apr 5 17:29:04] <--- SIP read from 192.168.4.11:5060 ---> INVITE sip:103@192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515b70000279f00000036 Content-Length: 337 Contact: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 Content-Type: application/sdp CSeq: 1 INVITE From: "unknown";tag=3455892130696 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3384775735 3384775735 IN IP4 192.168.4.11 s=SJphone c=IN IP4 192.168.4.11 t=0 0 a=direction:active m=audio 49156 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:103@192.168.4.14:5060 SIP/2.0 (40) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515b70000279f00000036 (90) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 337 (19) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Contact: (36) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: Content-Type: application/sdp (29) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: CSeq: 1 INVITE (14) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: From: "unknown";tag=3455892130696 (60) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: To: (31) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: (0) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: o=- 3384775735 3384775735 IN IP4 192.168.4.11 (45) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: s=SJphone (9) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: c=IN IP4 192.168.4.11 (21) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=direction:active (18) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: m=audio 49156 RTP/AVP 3 97 98 8 0 101 (37) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=fmtp:98 mode=20 (17) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 5 17:29:04] --- (11 headers 15 lines) --- [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to Off [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2580 do_setnat: Setting NAT on VRTP to Off [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2585 do_setnat: Setting NAT on UDPTL to Off [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 - INVITE (With RTP) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 5 17:29:04] Sending to 192.168.4.11 : 5060 (NAT) [Apr 5 17:29:04] Using INVITE request as basis request - 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 [Apr 5 17:29:04] Found peer '101' [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to On [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2580 do_setnat: Setting NAT on VRTP to On [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2585 do_setnat: Setting NAT on UDPTL to On [Apr 5 17:29:04] <--- Reliably Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000028461515b70000279f00000036;received=192.168.4.11;rport=5060 From: "unknown";tag=3455892130696 To: ;tag=as73fdee90 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 1 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Proxy-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="5927eeae" Content-Length: 0 <------------> [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #32 [Apr 5 17:29:04] Scheduling destruction of SIP dialog '9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11' in 256 ms (Method: INVITE) [Apr 5 17:29:04] <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515b70000279f00000036 Content-Length: 0 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 1 ACK From: "unknown";tag=3455892130696 Max-Forwards: 70 To: ;tag=as73fdee90 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: ACK sip:103@192.168.4.14:5060 SIP/2.0 (37) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515b70000279f00000036 (90) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 1 ACK (11) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: "unknown";tag=3455892130696 (60) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: ;tag=as73fdee90 (46) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:04] --- (9 headers 0 lines) --- [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #32 [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11' of Response 1: Match Not Found [Apr 5 17:29:04] <--- SIP read from 192.168.4.11:5060 ---> INVITE sip:103@192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515b70000038500000037 Content-Length: 337 Contact: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 Content-Type: application/sdp CSeq: 2 INVITE From: "unknown";tag=3455892130696 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Proxy-Authorization: Digest username="101",realm="asterisk",nonce="5927eeae",uri="sip:103@192.168.4.14:5060",response="a7792a738bcbfc5b06c1b31ae9dee3ba",algorithm="MD5" v=0 o=- 3384775735 3384775735 IN IP4 192.168.4.11 s=SJphone c=IN IP4 192.168.4.11 t=0 0 a=direction:active m=audio 49156 RTP/AVP 3 97 98 8 0 101 a=rtpmap:3 GSM/8000 a=rtpmap:97 iLBC/8000 a=rtpmap:98 iLBC/8000 a=fmtp:98 mode=20 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:103@192.168.4.14:5060 SIP/2.0 (40) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515b70000038500000037 (90) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 337 (19) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Contact: (36) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: Content-Type: application/sdp (29) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: CSeq: 2 INVITE (14) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: From: "unknown";tag=3455892130696 (60) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: To: (31) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Proxy-Authorization: Digest username="101",realm="asterisk",nonce="5927eeae",uri="sip:103@192.168.4.14:5060",response="a7792a738bcbfc5b06c1b31ae9dee3ba",algorithm="MD5" (168) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: (0) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: o=- 3384775735 3384775735 IN IP4 192.168.4.11 (45) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: s=SJphone (9) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: c=IN IP4 192.168.4.11 (21) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=direction:active (18) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: m=audio 49156 RTP/AVP 3 97 98 8 0 101 (37) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=fmtp:98 mode=20 (17) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 5 17:29:04] --- (12 headers 15 lines) --- [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 5 17:29:04] Sending to 192.168.4.11 : 5060 (NAT) [Apr 5 17:29:04] Using INVITE request as basis request - 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 [Apr 5 17:29:04] Found peer '101' [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to On [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2580 do_setnat: Setting NAT on VRTP to On [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2585 do_setnat: Setting NAT on UDPTL to On [Apr 5 17:29:04] Found RTP audio format 3 [Apr 5 17:29:04] Found RTP audio format 97 [Apr 5 17:29:04] Found RTP audio format 98 [Apr 5 17:29:04] Found RTP audio format 8 [Apr 5 17:29:04] Found RTP audio format 0 [Apr 5 17:29:04] Found RTP audio format 101 [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4899 process_sdp: Peer doesn't provide T.38 UDPTL [Apr 5 17:29:04] Peer audio RTP is at port 192.168.4.11:49156 [Apr 5 17:29:04] Found description format GSM for ID 3 [Apr 5 17:29:04] Found description format iLBC for ID 97 [Apr 5 17:29:04] Found description format iLBC for ID 98 [Apr 5 17:29:04] Got unsupported a:fmtp in SDP offer [Apr 5 17:29:04] Found description format PCMA for ID 8 [Apr 5 17:29:04] Found description format PCMU for ID 0 [Apr 5 17:29:04] Found description format telephone-event for ID 101 [Apr 5 17:29:04] Got unsupported a:fmtp in SDP offer [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel [Apr 5 17:29:04] Capabilities: us - 0x4 (ulaw), peer - audio=0x40e (gsm|ulaw|alaw|ilbc)/video=0x0 (nothing), combined - 0x4 (ulaw) [Apr 5 17:29:04] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 5 17:29:04] Peer audio RTP is at port 192.168.4.11:49156 [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:13401 handle_request_invite: Checking SIP call limits for device 101 [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:3003 update_call_counter: Updating call counter for incoming call [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:3077 update_call_counter: Call from peer '101' is 1 out of 2 [Apr 5 17:29:04] DEBUG[3695]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Apr 5 17:29:04] Looking for 103 in from-sip (domain 192.168.4.14) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:3805 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:7980 build_route: build_route: Contact hop: [Apr 5 17:29:04] list_route: hop: [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:13476 handle_request_invite: SIP/101-081dfaf0: New call is still down.... Trying... [Apr 5 17:29:04] <--- Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000028461515b70000038500000037;received=192.168.4.11;rport=5060 From: "unknown";tag=3455892130696 To: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 17:29:04] DEBUG[3695]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081dfaf0 [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:04] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/101 - state 2 (In use) [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:04] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:04] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/101 - state 2 (In use) [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:04] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:04] ERROR[3706]: pbx.c:1523 ast_func_read: Function DEVSTATE not registered [Apr 5 17:29:04] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '(null)' [Apr 5 17:29:04] DEBUG[3706]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Apr 5 17:29:04] -- Executing [103@from-sip:1] NoOp("SIP/101-081dfaf0", "SIP/103 has state ") in new stack [Apr 5 17:29:04] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '0' [Apr 5 17:29:04] DEBUG[3706]: pbx.c:1795 pbx_extension_helper: Launching 'NoOp' [Apr 5 17:29:04] -- Executing [103@from-sip:2] NoOp("SIP/101-081dfaf0", "SIPPEER(103:curcalls) is 0") in new stack [Apr 5 17:29:04] DEBUG[3706]: pbx.c:1795 pbx_extension_helper: Launching 'Dial' [Apr 5 17:29:04] -- Executing [103@from-sip:3] Dial("SIP/101-081dfaf0", "SIP/103") in new stack [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:15310 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:2621 create_addr_from_peer: Our T38 capability (3856) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:2575 do_setnat: Setting NAT on RTP to On [Apr 5 17:29:04] DEBUG[3707]: app_queue.c:546 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:2585 do_setnat: Setting NAT on UDPTL to On [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:3805 sip_new: *** Our native formats are 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:3806 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:3807 sip_new: *** Our capabilities are 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:3808 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:3810 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:3831 sip_new: This channel will not be able to handle video. [Apr 5 17:29:04] DEBUG[3706]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-3. [Apr 5 17:29:04] DEBUG[3706]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-2. [Apr 5 17:29:04] DEBUG[3706]: channel.c:3301 ast_channel_inherit_variables: Not copying variable STACK-from-sip-103-1. [Apr 5 17:29:04] DEBUG[3708]: app_queue.c:546 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 5 17:29:04] DEBUG[3706]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 5 17:29:04] DEBUG[3706]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 5 17:29:04] DEBUG[3706]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 5 17:29:04] DEBUG[3706]: channel.c:3301 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:2830 sip_call: Outgoing Call for 103 [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:3077 update_call_counter: Call to peer '103' is 1 out of 2 [Apr 5 17:29:04] DEBUG[3706]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:04] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/103 - state 6 (Ringing) [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:04] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:04] DEBUG[3709]: app_queue.c:546 changethread: Device 'SIP/103' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:2845 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:6188 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Apr 5 17:29:04] Audio is at 192.168.4.14 port 14814 [Apr 5 17:29:04] Adding codec 0x4 (ulaw) to SDP [Apr 5 17:29:04] Adding non-codec 0x1 (telephone-event) to SDP [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 (55) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport (63) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 2: From: "unknown" ;tag=as68d694a4 (53) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 4: Contact: (31) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 (54) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 INVITE (16) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 05 Apr 2007 15:29:04 GMT (35) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 238 (19) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4573 parse_request: Header 14: (0) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: o=root 3673 3673 IN IP4 192.168.4.14 (36) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: s=session (9) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: c=IN IP4 192.168.4.14 (21) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: m=audio 14814 RTP/AVP 0 101 (27) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-16 (15) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: a=silenceSupp:off - - - - (25) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:4605 parse_request: Line: a=sendrecv (10) [Apr 5 17:29:04] Reliably Transmitting (NAT) to 192.168.4.109:2051: INVITE sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport From: "unknown" ;tag=as68d694a4 To: Contact: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 15:29:04 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 238 v=0 o=root 3673 3673 IN IP4 192.168.4.14 s=session c=IN IP4 192.168.4.14 t=0 0 m=audio 14814 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 5 17:29:04] DEBUG[3706]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #34 [Apr 5 17:29:04] -- Called 103 [Apr 5 17:29:04] <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 From: "unknown" ;tag=as68d694a4 To: ;tag=vafsgm496j Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 (68) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "unknown" ;tag=as68d694a4 (53) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=vafsgm496j (61) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 (54) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Contact: ;flow-id=1 (61) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Apr 5 17:29:04] --- (10 headers 0 lines) --- [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2122 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #34 - INVITE (got response) [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6f39eca54d9e994f14b286323c57093b@192.168.4.14' Request 102: Found [Apr 5 17:29:04] DEBUG[3695]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite [Apr 5 17:29:04] DEBUG[3695]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081e4478 [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:04] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/103 - state 6 (Ringing) [Apr 5 17:29:04] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:04] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:04] DEBUG[3710]: app_queue.c:546 changethread: Device 'SIP/103' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Apr 5 17:29:04] -- SIP/103-081e4478 is ringing [Apr 5 17:29:04] <--- Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000028461515b70000038500000037;received=192.168.4.11;rport=5060 From: "unknown";tag=3455892130696 To: ;tag=as2b67e197 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 17:29:05] <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 From: "unknown" ;tag=as68d694a4 To: ;tag=vafsgm496j Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 (68) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "unknown" ;tag=as68d694a4 (53) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=vafsgm496j (61) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 (54) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Contact: ;flow-id=1 (61) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Apr 5 17:29:05] --- (10 headers 0 lines) --- [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6f39eca54d9e994f14b286323c57093b@192.168.4.14' Request 102: Found [Apr 5 17:29:05] DEBUG[3695]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite [Apr 5 17:29:05] -- SIP/103-081e4478 is ringing [Apr 5 17:29:06] <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 From: "unknown" ;tag=as68d694a4 To: ;tag=vafsgm496j Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 (68) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "unknown" ;tag=as68d694a4 (53) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=vafsgm496j (61) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 (54) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Contact: ;flow-id=1 (61) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Apr 5 17:29:06] --- (10 headers 0 lines) --- [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6f39eca54d9e994f14b286323c57093b@192.168.4.14' Request 102: Found [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite [Apr 5 17:29:06] -- SIP/103-081e4478 is ringing [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' [Apr 5 17:29:06] DEBUG[3695]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 [Apr 5 17:29:06] Really destroying SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' Method: OPTIONS [Apr 5 17:29:08] <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 From: "unknown" ;tag=as68d694a4 To: ;tag=vafsgm496j Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 (68) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "unknown" ;tag=as68d694a4 (53) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=vafsgm496j (61) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 (54) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Contact: ;flow-id=1 (61) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Content-Length: 0 (17) [Apr 5 17:29:08] --- (10 headers 0 lines) --- [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:2131 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6f39eca54d9e994f14b286323c57093b@192.168.4.14' Request 102: Found [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:11641 handle_response_invite: SIP response 180 to standard invite [Apr 5 17:29:08] -- SIP/103-081e4478 is ringing [Apr 5 17:29:08] DEBUG[3706]: rtp.c:868 ast_rtcp_read: RTCP NAT: Got RTCP from other end. Now sending to address 192.168.4.109:18485 [Apr 5 17:29:08] DEBUG[3706]: rtp.c:873 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 5 17:29:08] <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 From: "unknown" ;tag=as68d694a4 To: ;tag=vafsgm496j Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 102 INVITE Contact: ;flow-id=1 User-Agent: snom360/6.5.8 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Content-Type: application/sdp Content-Length: 327 v=0 o=root 392795164 392795165 IN IP4 192.168.4.109 s=call c=IN IP4 192.168.4.109 t=0 0 m=audio 18484 RTP/AVP 0 101 a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:ZIWHtZlOSd5s8pcWSIUW/ZgobF5Yz4LuVX1IN3o+ a=rtpmap:0 pcmu/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=encryption:optional a=sendrecv <-------------> [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 Ok (14) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK7c395ccf;rport=5060 (68) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "unknown" ;tag=as68d694a4 (53) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: ;tag=vafsgm496j (61) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 (54) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 INVITE (16) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Contact: ;flow-id=1 (61) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: User-Agent: snom360/6.5.8 (25) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Allow-Events: talk, hold, refer (31) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Supported: timer, 100rel, replaces, callerid (44) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Content-Type: application/sdp (29) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 327 (19) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 13: (0) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: o=root 392795164 392795165 IN IP4 192.168.4.109 (47) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: s=call (6) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: c=IN IP4 192.168.4.109 (22) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: m=audio 18484 RTP/AVP 0 101 (27) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=crypto:1 AES_CM_128_HMAC_SHA1_32 inline:ZIWHtZlOSd5s8pcWSIUW/ZgobF5Yz4LuVX1IN3o+ (82) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=fmtp:101 0-16 (15) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=ptime:20 (10) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=encryption:optional (21) [Apr 5 17:29:08] --- (13 headers 13 lines) --- [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:2071 __sip_ack: Acked pending invite 102 [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6f39eca54d9e994f14b286323c57093b@192.168.4.14' of Request 102: Match Not Found [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:11641 handle_response_invite: SIP response 200 to standard invite [Apr 5 17:29:08] Found RTP audio format 0 [Apr 5 17:29:08] Found RTP audio format 101 [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4899 process_sdp: Peer doesn't provide T.38 UDPTL [Apr 5 17:29:08] Peer audio RTP is at port 192.168.4.109:18484 [Apr 5 17:29:08] Got unsupported a:crypto in SDP offer [Apr 5 17:29:08] Found description format pcmu for ID 0 [Apr 5 17:29:08] Found description format telephone-event for ID 101 [Apr 5 17:29:08] Got unsupported a:fmtp in SDP offer [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/103-081e4478 [Apr 5 17:29:08] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Apr 5 17:29:08] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 5 17:29:08] Peer audio RTP is at port 192.168.4.109:18484 [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Apr 5 17:29:08] DEBUG[3695]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:7980 build_route: build_route: Contact hop: ;flow-id=1 [Apr 5 17:29:08] list_route: hop: [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:08] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/103 - state 2 (In use) [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:08] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:5643 reqprep: Strict routing enforced for session 6f39eca54d9e994f14b286323c57093b@192.168.4.14 [Apr 5 17:29:08] set_destination: Parsing for address/port to send to [Apr 5 17:29:08] set_destination: set destination to 192.168.4.109, port 2051 [Apr 5 17:29:08] Transmitting (NAT) to 192.168.4.109:2051: ACK sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK39963306;rport From: "unknown" ;tag=as68d694a4 To: ;tag=vafsgm496j Contact: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 5 17:29:08] -- Call on SIP/103-081e4478 left from hold [Apr 5 17:29:08] DEBUG[3706]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081e4478 [Apr 5 17:29:08] -- SIP/103-081e4478 answered SIP/101-081dfaf0 [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:08] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/103 - state 2 (In use) [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:08] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:08] DEBUG[3711]: app_queue.c:546 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 5 17:29:08] DEBUG[3706]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081dfaf0 [Apr 5 17:29:08] DEBUG[3706]: chan_sip.c:3463 sip_answer: SIP answering channel: SIP/101-081dfaf0 [Apr 5 17:29:08] DEBUG[3706]: chan_sip.c:6420 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 5 17:29:08] DEBUG[3706]: chan_sip.c:6188 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 5 17:29:08] DEBUG[3706]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 5 17:29:08] Audio is at 192.168.4.14 port 12360 [Apr 5 17:29:08] Adding codec 0x4 (ulaw) to SDP [Apr 5 17:29:08] Adding non-codec 0x1 (telephone-event) to SDP [Apr 5 17:29:08] DEBUG[3706]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Apr 5 17:29:08] DEBUG[3706]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 5 17:29:08] <--- Reliably Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000028461515b70000038500000037;received=192.168.4.11;rport=5060 From: "unknown";tag=3455892130696 To: ;tag=as2b67e197 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 2 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 238 v=0 o=root 3673 3673 IN IP4 192.168.4.14 s=session c=IN IP4 192.168.4.14 t=0 0 m=audio 12360 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 5 17:29:08] DEBUG[3706]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #36 [Apr 5 17:29:08] -- Packet2Packet bridging SIP/101-081dfaf0 and SIP/103-081e4478 [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:08] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/101 - state 2 (In use) [Apr 5 17:29:08] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:08] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:08] DEBUG[3712]: app_queue.c:546 changethread: Device 'SIP/103' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 5 17:29:08] DEBUG[3713]: app_queue.c:546 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 5 17:29:08] <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.14 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515bb000073670000003b Content-Length: 0 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 2 ACK From: "unknown";tag=3455892130696 Max-Forwards: 70 To: ;tag=as2b67e197 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: ACK sip:103@192.168.4.14 SIP/2.0 (32) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515bb000073670000003b (90) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 2 ACK (11) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: "unknown";tag=3455892130696 (60) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: ;tag=as2b67e197 (46) [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:08] --- (9 headers 0 lines) --- [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #36 [Apr 5 17:29:08] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11' of Response 2: Match Not Found [Apr 5 17:29:13] DEBUG[3706]: rtp.c:873 ast_rtcp_read: Got RTCP report of 52 bytes sip[Apr 5 17:29:14] <--- SIP read from 192.168.4.11:5060 ---> OPTIONS sip:192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515c1000078d90000003c Content-Length: 0 Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 CSeq: 11 OPTIONS From: ;tag=345696252806 Max-Forwards: 70 To: <-------------> [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:192.168.4.14:5060 SIP/2.0 (37) [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515c1000078d90000003c (90) [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 (58) [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 11 OPTIONS (16) [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: ;tag=345696252806 (50) [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: (27) [Apr 5 17:29:14] --- (8 headers 0 lines) --- [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 - OPTIONS (No RTP) [Apr 5 17:29:14] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 5 17:29:14] Looking for s in default (domain 192.168.4.14) [Apr 5 17:29:14] <--- Transmitting (no NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000000b461515c1000078d90000003c;received=192.168.4.11;rport=5060 From: ;tag=345696252806 To: ;tag=as6c6ad6f8 Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 CSeq: 11 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Apr 5 17:29:14] Scheduling destruction of SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' in 32000 ms (Method: OPTIONS) sho[Apr 5 17:29:15] <--- SIP read from 192.168.4.11:5060 ---> REGISTER sip:192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515c2000055360000003e Content-Length: 0 Contact: Call-ID: D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 CSeq: 5 REGISTER From: ;tag=345701094842 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:192.168.4.14:5060 SIP/2.0 (38) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515c2000055360000003e (90) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Contact: (36) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 (58) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 5 REGISTER (16) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: From: ;tag=345701094842 (50) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Max-Forwards: 70 (16) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: To: (31) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:15] --- (10 headers 0 lines) --- [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 - REGISTER (No RTP) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 5 17:29:15] Using latest REGISTER request as basis request [Apr 5 17:29:15] Sending to 192.168.4.11 : 5060 (NAT) [Apr 5 17:29:15] <--- Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000000b461515c2000055360000003e;received=192.168.4.11;rport=5060 From: ;tag=345701094842 To: Call-ID: D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 CSeq: 5 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 17:29:15] <--- Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000000b461515c2000055360000003e;received=192.168.4.11;rport=5060 From: ;tag=345701094842 To: ;tag=as46c5da45 Call-ID: D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 CSeq: 5 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces WWW-Authenticate: Digest algorithm=MD5, realm="asterisk", nonce="480d774c" Content-Length: 0 <------------> [Apr 5 17:29:15] Scheduling destruction of SIP dialog 'D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11' in 32000 ms (Method: REGISTER) [Apr 5 17:29:15] <--- SIP read from 192.168.4.11:5060 ---> REGISTER sip:192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515c2000032ea00000041 Content-Length: 0 Contact: Call-ID: D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 CSeq: 6 REGISTER From: ;tag=3457010927078 Max-Forwards: 70 To: User-Agent: SJphone/1.60.289a (SJ Labs) Authorization: Digest username="101",realm="asterisk",nonce="480d774c",uri="sip:192.168.4.14:5060",response="fe6d00dda7cdf580049344fbe845ce4b",algorithm="MD5" <-------------> [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: REGISTER sip:192.168.4.14:5060 SIP/2.0 (38) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515c2000032ea00000041 (90) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Contact: (36) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 (58) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 6 REGISTER (16) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: From: ;tag=3457010927078 (51) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Max-Forwards: 70 (16) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: To: (31) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Authorization: Digest username="101",realm="asterisk",nonce="480d774c",uri="sip:192.168.4.14:5060",response="fe6d00dda7cdf580049344fbe845ce4b",algorithm="MD5" (158) [Apr 5 17:29:15] --- (11 headers 0 lines) --- [Apr 5 17:29:15] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Apr 5 17:29:15] Using latest REGISTER request as basis request [Apr 5 17:29:15] Sending to 192.168.4.11 : 5060 (NAT) [Apr 5 17:29:15] <--- Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000000b461515c2000032ea00000041;received=192.168.4.11;rport=5060 From: ;tag=3457010927078 To: Call-ID: D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 CSeq: 6 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> w[Apr 5 17:29:15] -- Saved useragent "SJphone/1.60.289a (SJ Labs)" for peer 101 [Apr 5 17:29:15] <--- Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000000b461515c2000032ea00000041;received=192.168.4.11;rport=5060 From: ;tag=3457010927078 To: ;tag=as46c5da45 Call-ID: D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 CSeq: 6 REGISTER User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 120 Contact: ;expires=120 Date: Thu, 05 Apr 2007 15:29:15 GMT Content-Length: 0 <------------> [Apr 5 17:29:15] DEBUG[3695]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Apr 5 17:29:15] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:15] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:15] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/101 - state 2 (In use) [Apr 5 17:29:15] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:15] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:15] Scheduling destruction of SIP dialog 'D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11' in 32000 ms (Method: REGISTER) [Apr 5 17:29:15] DEBUG[3714]: app_queue.c:546 changethread: Device 'SIP/101' changed to state '2' (In use) but we don't care because they're not a member of any queue. inuse * User name In use Limit * Peer name In use Limit 103 1/0 2 102 0/0 2 101 1/0 2 *CLI> [Apr 5 17:29:18] DEBUG[3706]: rtp.c:873 ast_rtcp_read: Got RTCP report of 52 bytes core show hints -= Registered Asterisk Dial Plan Hints =- 103@from-sip : SIP/103 State:InUse Watchers 0 102@from-sip : SIP/102 State:Idle Watchers 0 101@from-sip : SIP/101 State:InUse Watchers 0 ---------------- - 3 hints registered *CLI> [Apr 5 17:29:23] DEBUG[3706]: rtp.c:873 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 5 17:29:24] <--- SIP read from 192.168.4.11:5060 ---> INVITE sip:103@192.168.4.14 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515cb0000377700000044 Content-Length: 214 Contact: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 Content-Type: application/sdp CSeq: 3 INVITE From: "unknown";tag=3455892130696 Max-Forwards: 70 To: ;tag=as2b67e197 User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3384775735 3384775736 IN IP4 192.168.4.11 s=SJphone c=IN IP4 0.0.0.0 t=0 0 a=direction:active m=audio 49156 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:103@192.168.4.14 SIP/2.0 (35) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515cb0000377700000044 (90) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 214 (19) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Contact: (36) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: Content-Type: application/sdp (29) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: CSeq: 3 INVITE (14) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: From: "unknown";tag=3455892130696 (60) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: To: ;tag=as2b67e197 (46) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: (0) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: o=- 3384775735 3384775736 IN IP4 192.168.4.11 (45) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: s=SJphone (9) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=direction:active (18) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: m=audio 49156 RTP/AVP 0 101 (27) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 5 17:29:24] --- (11 headers 10 lines) --- [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 5 17:29:24] Sending to 192.168.4.11 : 5060 (NAT) [Apr 5 17:29:24] Found RTP audio format 0 [Apr 5 17:29:24] Found RTP audio format 101 [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4899 process_sdp: Peer doesn't provide T.38 UDPTL [Apr 5 17:29:24] Peer audio RTP is at port 0.0.0.0:49156 [Apr 5 17:29:24] Found description format PCMU for ID 0 [Apr 5 17:29:24] Found description format telephone-event for ID 101 [Apr 5 17:29:24] Got unsupported a:fmtp in SDP offer [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/101-081dfaf0 [Apr 5 17:29:24] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Apr 5 17:29:24] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 5 17:29:24] Peer audio RTP is at port 0.0.0.0:49156 [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Apr 5 17:29:24] DEBUG[3695]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:13454 handle_request_invite: Got a SIP re-invite for call 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:13549 handle_request_invite: SIP/101-081dfaf0: This call is UP.... [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:6420 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:6188 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 5 17:29:24] Audio is at 192.168.4.14 port 12360 [Apr 5 17:29:24] Adding codec 0x4 (ulaw) to SDP [Apr 5 17:29:24] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:24] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:24] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/101 - state 8 (On Hold) [Apr 5 17:29:24] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:24] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:24] Adding non-codec 0x1 (telephone-event) to SDP [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 5 17:29:24] <--- Reliably Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000028461515cb0000377700000044;received=192.168.4.11;rport=5060 From: "unknown";tag=3455892130696 To: ;tag=as2b67e197 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 3 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 238 v=0 o=root 3673 3674 IN IP4 192.168.4.14 s=session c=IN IP4 192.168.4.14 t=0 0 m=audio 12360 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #41 [Apr 5 17:29:24] -- Started music on hold, class 'default', on SIP/103-081e4478 [Apr 5 17:29:24] DEBUG[3706]: channel.c:1997 ast_settimeout: Scheduling timer at 160 sample intervals [Apr 5 17:29:24] DEBUG[3706]: channel.c:2332 __ast_read: Generator got voice, switching to phase locked mode [Apr 5 17:29:24] DEBUG[3706]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 5 17:29:24] <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.14 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515cb00006c9500000046 Content-Length: 0 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 3 ACK From: "unknown";tag=3455892130696 Max-Forwards: 70 To: ;tag=as2b67e197 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: ACK sip:103@192.168.4.14 SIP/2.0 (32) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515cb00006c9500000046 (90) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 3 ACK (11) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: "unknown";tag=3455892130696 (60) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: ;tag=as2b67e197 (46) [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:24] --- (9 headers 0 lines) --- [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #41 [Apr 5 17:29:24] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11' of Response 3: Match Not Found [Apr 5 17:29:24] DEBUG[3706]: channel.c:2845 set_format: Set channel SIP/103-081e4478 to write format slin [Apr 5 17:29:24] DEBUG[3715]: app_queue.c:546 changethread: Device 'SIP/101' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Apr 5 17:29:24] DEBUG[3706]: res_musiconhold.c:254 ast_moh_files_next: SIP/103-081e4478 Opened file 1 '/var/lib/asterisk/moh/fpm-sunshine' [Apr 5 17:29:24] DEBUG[3706]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 5 17:29:24] DEBUG[3706]: rtp.c:2706 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 5 17:29:25] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3816, ms is 497 [Apr 5 17:29:25] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3824, ms is 498 [Apr 5 17:29:26] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3824, ms is 498 [Apr 5 17:29:26] DEBUG[3695]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' [Apr 5 17:29:26] DEBUG[3695]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 [Apr 5 17:29:26] Really destroying SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' Method: OPTIONS [Apr 5 17:29:29] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3824, ms is 498 [Apr 5 17:29:28] DEBUG[3706]: rtp.c:873 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 5 17:29:31] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3736, ms is 487 [Apr 5 17:29:32] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3816, ms is 497 [Apr 5 17:29:32] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3824, ms is 498 core show hintssip show inuse[Apr 5 17:29:34] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3792, ms is 494 [Apr 5 17:29:34] DEBUG[3706]: rtp.c:873 ast_rtcp_read: Got RTCP report of 52 bytes * User name In use Limit * Peer name In use Limit 103 1/0 2 102 0/0 2 101 1/0 2 *CLI> sip show inuse[Apr 5 17:29:35] <--- SIP read from 192.168.4.11:5060 ---> OPTIONS sip:192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515d50000155700000047 Content-Length: 0 Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 CSeq: 12 OPTIONS From: ;tag=345896257387 Max-Forwards: 70 To: <-------------> [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:192.168.4.14:5060 SIP/2.0 (37) [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515d50000155700000047 (90) [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 (58) [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 12 OPTIONS (16) [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: ;tag=345896257387 (50) [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: (27) [Apr 5 17:29:35] --- (8 headers 0 lines) --- [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 - OPTIONS (No RTP) [Apr 5 17:29:35] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 5 17:29:35] Looking for s in default (domain 192.168.4.14) [Apr 5 17:29:35] <--- Transmitting (no NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000000b461515d50000155700000047;received=192.168.4.11;rport=5060 From: ;tag=345896257387 To: ;tag=as40231ca4 Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 CSeq: 12 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Apr 5 17:29:35] Scheduling destruction of SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' in 32000 ms (Method: OPTIONS) core show hints[Apr 5 17:29:35] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3840, ms is 500 [Apr 5 17:29:36] DEBUG[3706]: rtp.c:2559 ast_rtp_raw_write: Difference is 3824, ms is 498 -= Registered Asterisk Dial Plan Hints =- 103@from-sip : SIP/103 State:InUse Watchers 0 102@from-sip : SIP/102 State:Idle Watchers 0 101@from-sip : SIP/101 State:Hold Watchers 0 ---------------- - 3 hints registered *CLI> [Apr 5 17:29:38] <--- SIP read from 192.168.4.11:5060 ---> INVITE sip:103@192.168.4.14 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515d90000676600000049 Content-Length: 219 Contact: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 Content-Type: application/sdp CSeq: 4 INVITE From: "unknown";tag=3455892130696 Max-Forwards: 70 To: ;tag=as2b67e197 User-Agent: SJphone/1.60.289a (SJ Labs) v=0 o=- 3384775735 3384775737 IN IP4 192.168.4.11 s=SJphone c=IN IP4 192.168.4.11 t=0 0 a=direction:active m=audio 49156 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-11,16 <-------------> [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: INVITE sip:103@192.168.4.14 SIP/2.0 (35) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515d90000676600000049 (90) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 219 (19) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Contact: (36) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: Content-Type: application/sdp (29) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: CSeq: 4 INVITE (14) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: From: "unknown";tag=3455892130696 (60) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: To: ;tag=as2b67e197 (46) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: (0) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: v=0 (3) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: o=- 3384775735 3384775737 IN IP4 192.168.4.11 (45) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: s=SJphone (9) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: c=IN IP4 192.168.4.11 (21) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: t=0 0 (5) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=direction:active (18) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: m=audio 49156 RTP/AVP 0 101 (27) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4605 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 5 17:29:38] --- (11 headers 10 lines) --- [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 5 17:29:38] Sending to 192.168.4.11 : 5060 (NAT) [Apr 5 17:29:38] Found RTP audio format 0 [Apr 5 17:29:38] Found RTP audio format 101 [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4899 process_sdp: Peer doesn't provide T.38 UDPTL [Apr 5 17:29:38] Peer audio RTP is at port 192.168.4.11:49156 [Apr 5 17:29:38] Found description format PCMU for ID 0 [Apr 5 17:29:38] Found description format telephone-event for ID 101 [Apr 5 17:29:38] Got unsupported a:fmtp in SDP offer [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:5129 process_sdp: T38 state changed to 0 on channel SIP/101-081dfaf0 [Apr 5 17:29:38] Capabilities: us - 0x4 (ulaw), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x4 (ulaw) [Apr 5 17:29:38] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Apr 5 17:29:38] Peer audio RTP is at port 192.168.4.11:49156 [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:5209 process_sdp: We're settling with these formats: 0x4 (ulaw) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:5216 process_sdp: We have an owner, now see if we need to change this call [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:13454 handle_request_invite: Got a SIP re-invite for call 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:13549 handle_request_invite: SIP/101-081dfaf0: This call is UP.... [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:6420 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:6188 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:6189 add_sdp: ** Our prefcodec: 0x0 (nothing) [Apr 5 17:29:38] Audio is at 192.168.4.14 port 12360 [Apr 5 17:29:38] Adding codec 0x4 (ulaw) to SDP [Apr 5 17:29:38] Adding non-codec 0x1 (telephone-event) to SDP [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:6320 add_sdp: -- Done with adding codecs to SDP [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:6365 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Apr 5 17:29:38] <--- Reliably Transmitting (NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b00000028461515d90000676600000049;received=192.168.4.11;rport=5060 From: "unknown";tag=3455892130696 To: ;tag=as2b67e197 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 4 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 238 v=0 o=root 3673 3675 IN IP4 192.168.4.14 s=session c=IN IP4 192.168.4.14 t=0 0 m=audio 12360 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #44 [Apr 5 17:29:38] DEBUG[3706]: rtp.c:2689 ast_rtp_write: Ooh, format changed from unknown to ulaw [Apr 5 17:29:38] DEBUG[3706]: rtp.c:2706 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Apr 5 17:29:38] -- Stopped music on hold on SIP/103-081e4478 [Apr 5 17:29:38] DEBUG[3706]: channel.c:2845 set_format: Set channel SIP/103-081e4478 to write format ulaw [Apr 5 17:29:38] DEBUG[3706]: channel.c:1997 ast_settimeout: Scheduling timer at 0 sample intervals [Apr 5 17:29:38] <--- SIP read from 192.168.4.11:5060 ---> ACK sip:103@192.168.4.14 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515d9000078600000004b Content-Length: 0 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 4 ACK From: "unknown";tag=3455892130696 Max-Forwards: 70 To: ;tag=as2b67e197 User-Agent: SJphone/1.60.289a (SJ Labs) <-------------> [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: ACK sip:103@192.168.4.14 SIP/2.0 (32) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b00000028461515d9000078600000004b (90) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 4 ACK (11) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: "unknown";tag=3455892130696 (60) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: ;tag=as2b67e197 (46) [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: User-Agent: SJphone/1.60.289a (SJ Labs) (39) [Apr 5 17:29:38] --- (9 headers 0 lines) --- [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #44 [Apr 5 17:29:38] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11' of Response 4: Match Not Found [Apr 5 17:29:39] DEBUG[3706]: rtp.c:873 ast_rtcp_read: Got RTCP report of 52 bytes core show hintssip show inuse * User name In use Limit * Peer name In use Limit 103 1/0 2 102 0/0 2 101 1/0 2 *CLI> sip show inusecore show hints -= Registered Asterisk Dial Plan Hints =- 103@from-sip : SIP/103 State:InUse Watchers 0 102@from-sip : SIP/102 State:Idle Watchers 0 101@from-sip : SIP/101 State:Hold Watchers 0 ---------------- - 3 hints registered *CLI> [Apr 5 17:29:44] DEBUG[3706]: rtp.c:873 ast_rtcp_read: Got RTCP report of 52 bytes [Apr 5 17:29:46] DEBUG[3695]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' [Apr 5 17:29:46] DEBUG[3695]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 [Apr 5 17:29:46] Really destroying SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' Method: OPTIONS [Apr 5 17:29:47] DEBUG[3695]: chan_sip.c:2010 __sip_autodestruct: Auto destroying SIP dialog 'D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11' [Apr 5 17:29:47] DEBUG[3695]: chan_sip.c:3109 sip_destroy: Destroying SIP dialog D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11 [Apr 5 17:29:47] Really destroying SIP dialog 'D654C1FB-2666-4325-A76D-32E4B4E13CB7@192.168.4.11' Method: REGISTER [Apr 5 17:29:48] <--- SIP read from 192.168.4.109:2051 ---> BYE sip:101@192.168.4.14 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.109:2051;branch=z9hG4bK-frq0ynryp4od;rport From: ;tag=vafsgm496j To: "unknown" ;tag=as68d694a4 Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 1 BYE Max-Forwards: 70 Contact: ;flow-id=1 User-Agent: snom360/6.5.8 RTP-RxStat: Total_Rx_Pkts=695,Rx_Pkts=695,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 RTP-TxStat: Total_Tx_Pkts=1927,Tx_Pkts=1927,Remote_Tx_Pkts=695 Content-Length: 0 <-------------> [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: BYE sip:101@192.168.4.14 SIP/2.0 (32) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.109:2051;branch=z9hG4bK-frq0ynryp4od;rport (69) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: ;tag=vafsgm496j (63) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: "unknown" ;tag=as68d694a4 (51) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 (54) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 1 BYE (11) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Contact: ;flow-id=1 (61) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: User-Agent: snom360/6.5.8 (25) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: RTP-RxStat: Total_Rx_Pkts=695,Rx_Pkts=695,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 (78) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: RTP-TxStat: Total_Tx_Pkts=1927,Tx_Pkts=1927,Remote_Tx_Pkts=695 (62) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Content-Length: 0 (17) [Apr 5 17:29:48] --- (12 headers 0 lines) --- [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received BYE (8) - Command in SIP BYE [Apr 5 17:29:48] Sending to 192.168.4.109 : 2051 (NAT) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:1633 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 6f39eca54d9e994f14b286323c57093b@192.168.4.14 [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:14190 handle_request_bye: Received bye, issuing owner hangup [Apr 5 17:29:48] <--- Transmitting (NAT) to 192.168.4.109:2051 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.109:2051;branch=z9hG4bK-frq0ynryp4od;received=192.168.4.109;rport=2051 From: ;tag=vafsgm496j To: "unknown" ;tag=as68d694a4 Call-ID: 6f39eca54d9e994f14b286323c57093b@192.168.4.14 CSeq: 1 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 5 17:29:48] DEBUG[3706]: rtp.c:3088 bridge_p2p_loop: Oooh, got a hangup [Apr 5 17:29:48] DEBUG[3706]: channel.c:4048 ast_channel_bridge: Returning from native bridge, channels: SIP/101-081dfaf0, SIP/103-081e4478 [Apr 5 17:29:48] DEBUG[3706]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/103-081e4478' [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:3312 sip_hangup: Hangup call SIP/103-081e4478, SIP callid 6f39eca54d9e994f14b286323c57093b@192.168.4.14) [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:3321 sip_hangup: update_call_counter(103) - decrement call limit counter on hangup [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:3003 update_call_counter: Updating call counter for outgoing call [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:3051 update_call_counter: Call to peer '103' removed from call limit 2 [Apr 5 17:29:48] DEBUG[3706]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103 [Apr 5 17:29:48] DEBUG[3706]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/103-081e4478 [Apr 5 17:29:48] DEBUG[3706]: rtp.c:1476 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Apr 5 17:29:48] DEBUG[3706]: app_dial.c:1670 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 5 17:29:48] DEBUG[3706]: pbx.c:2393 __ast_pbx_run: Spawn extension (from-sip,103,3) exited non-zero on 'SIP/101-081dfaf0' [Apr 5 17:29:48] == Spawn extension (from-sip, 103, 3) exited non-zero on 'SIP/101-081dfaf0' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '"unknown" <101>' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '101' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '103' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'from-sip' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/101-081dfaf0' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/103-081e4478' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'SIP/103' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 17:29:04' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 17:29:08' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '2007-04-05 17:29:48' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '44' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '40' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '1175786944.0' [Apr 5 17:29:48] DEBUG[3706]: pbx.c:1648 pbx_substitute_variables_helper_full: Function result is '' [Apr 5 17:29:48] DEBUG[3706]: channel.c:1693 ast_hangup: Hanging up channel 'SIP/101-081dfaf0' [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:3312 sip_hangup: Hangup call SIP/101-081dfaf0, SIP callid 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11) [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:3321 sip_hangup: update_call_counter(101) - decrement call limit counter on hangup [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:3003 update_call_counter: Updating call counter for incoming call [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:3051 update_call_counter: Call from peer '101' removed from call limit 2 [Apr 5 17:29:48] DEBUG[3706]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101 [Apr 5 17:29:48] Scheduling destruction of SIP dialog '9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11' in 256 ms (Method: ACK) [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:5643 reqprep: Strict routing enforced for session 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 [Apr 5 17:29:48] set_destination: Parsing for address/port to send to [Apr 5 17:29:48] set_destination: set destination to 192.168.4.11, port 5060 [Apr 5 17:29:48] Reliably Transmitting (NAT) to 192.168.4.11:5060: BYE sip:101@192.168.4.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK5b5cf892;rport From: ;tag=as2b67e197 To: "unknown";tag=3455892130696 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 5 17:29:48] DEBUG[3706]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #47 [Apr 5 17:29:48] DEBUG[3706]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/101-081dfaf0 [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:48] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:48] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:48] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/103 - state 1 (Not in use) [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 103 [Apr 5 17:29:48] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 103 [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:48] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/101 - state 8 (On Hold) [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:48] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:48] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:287 do_state_change: Changing state for SIP/101 - state 8 (On Hold) [Apr 5 17:29:48] DEBUG[3678]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 101 [Apr 5 17:29:48] DEBUG[3678]: chan_sip.c:15244 sip_devicestate: Checking device state for peer 101 [Apr 5 17:29:48] <--- SIP read from 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.14:5060;rport=5060;received=192.168.4.14;branch=z9hG4bK5b5cf892 Content-Length: 0 Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 CSeq: 102 BYE From: ;tag=as2b67e197 Server: SJphone/1.60.289a (SJ Labs) To: "unknown";tag=3455892130696 <-------------> [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;rport=5060;received=192.168.4.14;branch=z9hG4bK5b5cf892 (90) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: 9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11 (58) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 102 BYE (13) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: ;tag=as2b67e197 (48) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Server: SJphone/1.60.289a (SJ Labs) (35) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: "unknown";tag=3455892130696 (58) [Apr 5 17:29:48] --- (8 headers 0 lines) --- [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #47 [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11' of Request 102: Match Not Found [Apr 5 17:29:48] SIP Response message for INCOMING dialog BYE arrived [Apr 5 17:29:48] Really destroying SIP dialog '6f39eca54d9e994f14b286323c57093b@192.168.4.14' Method: BYE [Apr 5 17:29:48] Really destroying SIP dialog '9D369AF3-1C25-4C0B-967E-F9CD2E86546C@192.168.4.11' Method: ACK [Apr 5 17:29:48] DEBUG[3716]: app_queue.c:546 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 17:29:48] DEBUG[3717]: app_queue.c:546 changethread: Device 'SIP/103' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 5 17:29:48] DEBUG[3718]: app_queue.c:546 changethread: Device 'SIP/101' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Apr 5 17:29:48] DEBUG[3719]: app_queue.c:546 changethread: Device 'SIP/101' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 (56) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK5826dd30;rport (63) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as0bce850f (59) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Contact: (36) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 4085b1f672c358ab66c1473b51706dc1@192.168.4.14 (54) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 05 Apr 2007 15:29:48 GMT (35) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Apr 5 17:29:48] Reliably Transmitting (NAT) to 192.168.4.109:2051: OPTIONS sip:103@192.168.4.109:2051;line=0cl0sm4g SIP/2.0 Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK5826dd30;rport From: "asterisk" ;tag=as0bce850f To: Contact: Call-ID: 4085b1f672c358ab66c1473b51706dc1@192.168.4.14 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 15:29:48 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #48 [Apr 5 17:29:48] <--- SIP read from 192.168.4.109:2051 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK5826dd30;rport=5060 From: "asterisk" ;tag=as0bce850f To: Call-ID: 4085b1f672c358ab66c1473b51706dc1@192.168.4.14 CSeq: 102 OPTIONS Contact: ;flow-id=1 User-Agent: snom360/6.5.8 Accept-Language: en Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Content-Length: 0 <-------------> [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK5826dd30;rport=5060 (68) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as0bce850f (59) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 4085b1f672c358ab66c1473b51706dc1@192.168.4.14 (54) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Contact: ;flow-id=1 (69) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: User-Agent: snom360/6.5.8 (25) [Apr 5 17:29:48] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Accept-Language: en (19) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Accept: application/sdp (23) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Allow-Events: talk, hold, refer (31) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: Supported: timer, 100rel, replaces, callerid (44) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 0 (17) [Apr 5 17:29:49] --- (14 headers 0 lines) --- [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #48 [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '4085b1f672c358ab66c1473b51706dc1@192.168.4.14' of Request 102: Match Not Found [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:101@192.168.4.11:5060 SIP/2.0 (41) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK2bf7f2cc;rport (63) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as2cd892a0 (59) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: (31) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Contact: (36) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 34a2a7514df778e95cd843a47c68ea9e@192.168.4.14 (54) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 05 Apr 2007 15:29:49 GMT (35) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Apr 5 17:29:49] Reliably Transmitting (NAT) to 192.168.4.11:5060: OPTIONS sip:101@192.168.4.11:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK2bf7f2cc;rport From: "asterisk" ;tag=as2cd892a0 To: Contact: Call-ID: 34a2a7514df778e95cd843a47c68ea9e@192.168.4.14 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 15:29:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #51 [Apr 5 17:29:49] Really destroying SIP dialog '4085b1f672c358ab66c1473b51706dc1@192.168.4.14' Method: OPTIONS [Apr 5 17:29:49] <--- SIP read from 192.168.4.11:5060 ---> SIP/2.0 405 Method Not Allowed Via: SIP/2.0/UDP 192.168.4.14:5060;rport=5060;received=192.168.4.14;branch=z9hG4bK2bf7f2cc Content-Length: 0 Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY Call-ID: 34a2a7514df778e95cd843a47c68ea9e@192.168.4.14 CSeq: 102 OPTIONS From: "asterisk";tag=as2cd892a0 Server: SJphone/1.60.289a (SJ Labs) To: "unknown" <-------------> [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 405 Method Not Allowed (30) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;rport=5060;received=192.168.4.14;branch=z9hG4bK2bf7f2cc (90) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Allow: INVITE, ACK, CANCEL, BYE, REFER, NOTIFY (46) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 34a2a7514df778e95cd843a47c68ea9e@192.168.4.14 (54) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: From: "asterisk";tag=as2cd892a0 (58) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: Server: SJphone/1.60.289a (SJ Labs) (35) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: To: "unknown" (40) [Apr 5 17:29:49] --- (9 headers 0 lines) --- [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #51 [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '34a2a7514df778e95cd843a47c68ea9e@192.168.4.14' of Request 102: Match Not Found [Apr 5 17:29:49] Really destroying SIP dialog '34a2a7514df778e95cd843a47c68ea9e@192.168.4.14' Method: OPTIONS [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:102@192.168.4.104:5060;line=9l1gd4rz SIP/2.0 (56) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK33fd54e5;rport (63) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as5891e465 (59) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Contact: (36) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: Call-ID: 6599cc4e0edd4e0502625b1e1aaaea90@192.168.4.14 (54) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Date: Thu, 05 Apr 2007 15:29:49 GMT (35) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Supported: replaces (19) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: Content-Length: 0 (17) [Apr 5 17:29:49] Reliably Transmitting (NAT) to 192.168.4.104:5060: OPTIONS sip:102@192.168.4.104:5060;line=9l1gd4rz SIP/2.0 Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK33fd54e5;rport From: "asterisk" ;tag=as5891e465 To: Contact: Call-ID: 6599cc4e0edd4e0502625b1e1aaaea90@192.168.4.14 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 05 Apr 2007 15:29:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:1975 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #54 [Apr 5 17:29:49] <--- SIP read from 192.168.4.104:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK33fd54e5;rport=5060 From: "asterisk" ;tag=as5891e465 To: Call-ID: 6599cc4e0edd4e0502625b1e1aaaea90@192.168.4.14 CSeq: 102 OPTIONS Contact: User-Agent: snom220-3.56z Accept-Language: en Accept: application/sdp Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces Content-Length: 0 <-------------> [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.14:5060;branch=z9hG4bK33fd54e5;rport=5060 (68) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: From: "asterisk" ;tag=as5891e465 (59) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: To: (46) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: Call-ID: 6599cc4e0edd4e0502625b1e1aaaea90@192.168.4.14 (54) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Contact: (51) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: User-Agent: snom220-3.56z (25) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 8: Accept-Language: en (19) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 9: Accept: application/sdp (23) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 11: Allow-Events: talk, hold, refer (31) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 12: Supported: timer, 100rel, replaces (34) [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 13: Content-Length: 0 (17) [Apr 5 17:29:49] --- (14 headers 0 lines) --- [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:2079 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #54 [Apr 5 17:29:49] DEBUG[3695]: chan_sip.c:2089 __sip_ack: Stopping retransmission on '6599cc4e0edd4e0502625b1e1aaaea90@192.168.4.14' of Request 102: Match Not Found [Apr 5 17:29:49] Really destroying SIP dialog '6599cc4e0edd4e0502625b1e1aaaea90@192.168.4.14' Method: OPTIONS [Apr 5 17:29:55] <--- SIP read from 192.168.4.11:5060 ---> OPTIONS sip:192.168.4.14:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515e9000072140000004e Content-Length: 0 Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 CSeq: 13 OPTIONS From: ;tag=3460962517130 Max-Forwards: 70 To: <-------------> [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 0: OPTIONS sip:192.168.4.14:5060 SIP/2.0 (37) [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.4.11;rport;branch=z9hG4bKc0a8040b0000000b461515e9000072140000004e (90) [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 2: Content-Length: 0 (17) [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 3: Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 (58) [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 4: CSeq: 13 OPTIONS (16) [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 5: From: ;tag=3460962517130 (51) [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4573 parse_request: Header 7: To: (27) [Apr 5 17:29:55] --- (8 headers 0 lines) --- [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:4310 sip_alloc: Allocating new SIP dialog for CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 - OPTIONS (No RTP) [Apr 5 17:29:55] DEBUG[3695]: chan_sip.c:14633 handle_request: **** Received OPTIONS (3) - Command in SIP OPTIONS [Apr 5 17:29:55] Looking for s in default (domain 192.168.4.14) [Apr 5 17:29:55] <--- Transmitting (no NAT) to 192.168.4.11:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.4.11;branch=z9hG4bKc0a8040b0000000b461515e9000072140000004e;received=192.168.4.11;rport=5060 From: ;tag=3460962517130 To: ;tag=as199c6115 Call-ID: CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11 CSeq: 13 OPTIONS User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Accept: application/sdp Content-Length: 0 <------------> [Apr 5 17:29:55] Scheduling destruction of SIP dialog 'CE64C4D1-4737-4E96-B31D-48FB8E6FBC49@192.168.4.11' in 32000 ms (Method: OPTIONS) stop now [Apr 5 17:29:59] Beginning asterisk shutdown.... [Apr 5 17:29:59] Executing last minute cleanups [Apr 5 17:29:59] == Destroying musiconhold processes [Apr 5 17:29:59] Asterisk cleanly ending (0). [Apr 5 17:29:59] DEBUG[3673]: asterisk.c:1276 quit_handler: Asterisk ending (0).