AstDev*CLI> [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4106 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) Scheduling destruction of SIP dialog '7ca252a06c06d7667d00beeb481c79bc@xxx.xxx.xxx.203' in 32000 ms (Method: NOTIFY) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: NOTIFY sip:3061@10.1.7.25;line=10.1.1.9 SIP/2.0 (47) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK605035a8;rport (59) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: "Unknown" ;tag=as4a998dfa (59) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: To: (38) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: Contact: (31) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 7ca252a06c06d7667d00beeb481c79bc@xxx.xxx.xxx.203 (56) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Event: message-summary (22) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 11: Content-Length: 94 (18) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 12: (0) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: Messages-Waiting: no (20) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: Message-Account: sip:asterisk@xxx.xxx.xxx.203 (44) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: Voice-Message: 0/0 (0/0) (24) Reliably Transmitting (no NAT) to 10.1.7.25:5060: NOTIFY sip:3061@10.1.7.25;line=10.1.1.9 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK605035a8;rport From: "Unknown" ;tag=as4a998dfa To: Contact: Call-ID: 7ca252a06c06d7667d00beeb481c79bc@xxx.xxx.xxx.203 CSeq: 102 NOTIFY User-Agent: AuPix PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:asterisk@xxx.xxx.xxx.203 Voice-Message: 0/0 (0/0) --- [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #70 [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4106 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) Scheduling destruction of SIP dialog '448ef8f714d4b67f6ed8414336f904a5@xxx.xxx.xxx.203' in 32000 ms (Method: NOTIFY) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: NOTIFY sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 (52) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: Via: SIP/2.0/UDP xxx.xxx.xxx.203:5060;branch=z9hG4bK69b4e7b2;rport (65) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: "Unknown" ;tag=as354ee5a6 (59) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: To: (43) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: Contact: (37) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 448ef8f714d4b67f6ed8414336f904a5@xxx.xxx.xxx.203 (56) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Event: message-summary (22) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 11: Content-Length: 94 (18) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 12: (0) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: Messages-Waiting: no (20) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: Message-Account: sip:asterisk@xxx.xxx.xxx.203 (44) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: Voice-Message: 0/0 (0/0) (24) Reliably Transmitting (NAT) to xxx.xxx.xxx.200:61537: NOTIFY sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 Via: SIP/2.0/UDP xxx.xxx.xxx.203:5060;branch=z9hG4bK69b4e7b2;rport From: "Unknown" ;tag=as354ee5a6 To: Contact: Call-ID: 448ef8f714d4b67f6ed8414336f904a5@xxx.xxx.xxx.203 CSeq: 102 NOTIFY User-Agent: AuPix PBX Max-Forwards: 70 Event: message-summary Content-Type: application/simple-message-summary Content-Length: 94 Messages-Waiting: no Message-Account: sip:asterisk@xxx.xxx.xxx.203 Voice-Message: 0/0 (0/0) --- [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #72 AstDev*CLI> <-- SIP read from 10.1.7.25:5060: SIP/2.0 200 Ok To: From: "Unknown" ;tag=as4a998dfa Call-ID: 7ca252a06c06d7667d00beeb481c79bc@xxx.xxx.xxx.203 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK605035a8;rport=5060;received=10.1.1.9 CSeq: 102 NOTIFY Contact: User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: (38) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: "Unknown" ;tag=as4a998dfa (59) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Call-ID: 7ca252a06c06d7667d00beeb481c79bc@xxx.xxx.xxx.203 (56) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK605035a8;rport=5060;received=10.1.1.9 (82) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: CSeq: 102 NOTIFY (16) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Contact: (24) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Content-Length: 0 (17) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #70 [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '7ca252a06c06d7667d00beeb481c79bc@xxx.xxx.xxx.203' of Request 102: Match Not Found Really destroying SIP dialog '7ca252a06c06d7667d00beeb481c79bc@xxx.xxx.xxx.203' Method: NOTIFY AstDev*CLI> <-- SIP read from xxx.xxx.xxx.200:61537: SIP/2.0 200 Ok Via: SIP/2.0/UDP xxx.xxx.xxx.203:5060;branch=z9hG4bK69b4e7b2;rport=5060 From: "Unknown" ;tag=as354ee5a6 To: Call-ID: 448ef8f714d4b67f6ed8414336f904a5@xxx.xxx.xxx.203 CSeq: 102 NOTIFY Content-Length: 0 [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: Via: SIP/2.0/UDP xxx.xxx.xxx.203:5060;branch=z9hG4bK69b4e7b2;rport=5060 (70) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: "Unknown" ;tag=as354ee5a6 (59) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: To: (43) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: Call-ID: 448ef8f714d4b67f6ed8414336f904a5@xxx.xxx.xxx.203 (56) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: CSeq: 102 NOTIFY (16) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Content-Length: 0 (17) [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: (0) --- (7 headers 0 lines)--- [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #72 [Aug 4 10:43:19] DEBUG[22813]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '448ef8f714d4b67f6ed8414336f904a5@xxx.xxx.xxx.203' of Request 102: Match Not Found Really destroying SIP dialog '448ef8f714d4b67f6ed8414336f904a5@xxx.xxx.xxx.203' Method: NOTIFY [Aug 4 10:43:25] DEBUG[22813]: chan_sip.c:1943 __sip_autodestruct: Auto destroying call 'fiBzVBmVZSMAhqPHCb-kTTWchxGMXdeP@jdm.aupix.local' [Aug 4 10:43:25] DEBUG[22813]: chan_sip.c:2985 sip_destroy: Destroying SIP dialog fiBzVBmVZSMAhqPHCb-kTTWchxGMXdeP@jdm.aupix.local Really destroying SIP dialog 'fiBzVBmVZSMAhqPHCb-kTTWchxGMXdeP@jdm.aupix.local' Method: REGISTER [Aug 4 10:43:30] DEBUG[22813]: chan_sip.c:1943 __sip_autodestruct: Auto destroying call '3c392bf4900b-we9xndha0f3l@snom360' [Aug 4 10:43:30] DEBUG[22813]: chan_sip.c:2985 sip_destroy: Destroying SIP dialog 3c392bf4900b-we9xndha0f3l@snom360 Really destroying SIP dialog '3c392bf4900b-we9xndha0f3l@snom360' Method: REGISTER AstDev*CLI> <-- SIP read from 10.1.7.70:5060: INVITE sip:3061@10.1.1.9 SIP/2.0 To: From: ;tag=-4LPzfkHeF2blWUc Contact: CSeq: 2 INVITE Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-wfarVCV9I6J;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Accept: application/sdp Accept-Encoding: identity Content-Length: 227 Content-Type: application/sdp v=0 o=AuPix 1001 0 IN IP4 10.1.7.70 s=phone-call u=http://www.AuPix.com c=IN IP4 10.1.7.70 b=CT:384 t=0 0 a=sendrecv m=audio 5000 RTP/AVP 18 15 8 0 9 101 a=ptime:60 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: INVITE sip:3061@10.1.1.9 SIP/2.0 (32) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: (23) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: ;tag=-4LPzfkHeF2blWUc (46) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Contact: (43) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: CSeq: 2 INVITE (14) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local (64) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-wfarVCV9I6J;rport (64) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Accept: application/sdp (23) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: Accept-Encoding: identity (25) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 11: Content-Length: 227 (19) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 13: (0) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: v=0 (3) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.70 (31) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: s=phone-call (12) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: u=http://www.AuPix.com (22) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: c=IN IP4 10.1.7.70 (18) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: b=CT:384 (8) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: t=0 0 (5) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=sendrecv (10) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: m=audio 5000 RTP/AVP 18 15 8 0 9 101 (36) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=ptime:60 (10) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 12 lines)--- [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4106 sip_alloc: Allocating new SIP dialog for _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local - INVITE (With RTP) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:13981 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.70 : 5060 (NAT) Using INVITE request as basis request - _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:8624 check_user_full: Setting NAT on RTP to On [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:8629 check_user_full: Setting NAT on VRTP to On Reliably Transmitting (NAT) to 10.1.7.70:5060: SIP/2.0 407 Proxy Authentication Required Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-wfarVCV9I6J;received=10.1.7.70;rport=5060 From: ;tag=-4LPzfkHeF2blWUc To: ;tag=as38979ec2 Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local CSeq: 2 INVITE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Proxy-Authenticate: Digest algorithm=MD5, realm="AuPixDev.aupix.com", nonce="331a901e" Content-Length: 0 --- [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #73 Scheduling destruction of SIP dialog '_UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local' in 32000 ms (Method: INVITE) Found user '3062' AstDev*CLI> <-- SIP read from 10.1.7.70:5060: ACK sip:3061@10.1.1.9 SIP/2.0 To: ;tag=as38979ec2 From: ;tag=-4LPzfkHeF2blWUc Contact: CSeq: 2 ACK Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-wfarVCV9I6J;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: ACK sip:3061@10.1.1.9 SIP/2.0 (29) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: ;tag=as38979ec2 (38) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: ;tag=-4LPzfkHeF2blWUc (46) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Contact: (43) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: CSeq: 2 ACK (11) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local (64) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-wfarVCV9I6J;rport (64) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Content-Length: 0 (17) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:13981 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #73 [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '_UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local' of Response 2: Match Not Found AstDev*CLI> <-- SIP read from 10.1.7.70:5060: INVITE sip:3061@10.1.1.9 SIP/2.0 User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Accept: application/sdp Accept-Encoding: identity Content-Length: 227 Content-Type: application/sdp To: From: ;tag=-4LPzfkHeF2blWUc Contact: CSeq: 3 INVITE Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local Proxy-Authorization: Digest username="3062", realm="AuPixDev.aupix.com", nonce="331a901e", uri="sip:3061@10.1.1.9", response="2ab4ab059cb9de4552e9eff137012827", algorithm=md5 Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-f6DW50Frp8m;rport v=0 o=AuPix 1001 0 IN IP4 10.1.7.70 s=phone-call u=http://www.AuPix.com c=IN IP4 10.1.7.70 b=CT:384 t=0 0 a=sendrecv m=audio 5000 RTP/AVP 18 15 8 0 9 101 a=ptime:60 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: INVITE sip:3061@10.1.1.9 SIP/2.0 (32) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: Max-Forwards: 70 (16) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Accept: application/sdp (23) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: Accept-Encoding: identity (25) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Content-Length: 227 (19) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Content-Type: application/sdp (29) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: To: (23) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: From: ;tag=-4LPzfkHeF2blWUc (46) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Contact: (43) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: CSeq: 3 INVITE (14) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 11: Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local (64) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 12: Proxy-Authorization: Digest username="3062", realm="AuPixDev.aupix.com", nonce="331a901e", uri="sip:3061@10.1.1.9", response="2ab4ab059cb9de4552e9eff137012827", algorithm=md5 (174) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 13: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-f6DW50Frp8m;rport (64) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 14: (0) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: v=0 (3) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.70 (31) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: s=phone-call (12) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: u=http://www.AuPix.com (22) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: c=IN IP4 10.1.7.70 (18) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: b=CT:384 (8) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: t=0 0 (5) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=sendrecv (10) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: m=audio 5000 RTP/AVP 18 15 8 0 9 101 (36) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=ptime:60 (10) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=fmtp:101 0-15 (15) --- (14 headers 12 lines)--- [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:13981 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.70 : 5060 (NAT) Using INVITE request as basis request - _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:8624 check_user_full: Setting NAT on RTP to On [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:8629 check_user_full: Setting NAT on VRTP to On Found user '3062' Found RTP audio format 18 Found RTP audio format 15 Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 9 Found RTP audio format 101 Peer audio RTP is at port 10.1.7.70:5000 Got unsupported a:ptime in SDP offer Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4831 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x280004 (ulaw|h263|h264), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 10.1.7.70:5000 Peer video RTP is at port 10.1.7.70:40192 [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4901 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:12794 handle_request_invite: Checking SIP call limits for device 3062 [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:2879 update_call_counter: Updating call counter for incoming call Looking for 3061 in from-internal (domain 10.1.1.9) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:3608 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:3609 sip_new: *** Joint capabilities are 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:3610 sip_new: *** Our capabilities are 0x280004 (ulaw|h263|h264) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:3611 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:3634 sip_new: This channel will not be able to handle video. [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:7589 build_route: build_route: Contact hop: list_route: hop: [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:12864 handle_request_invite: SIP/3062-098c7ef8: New call is still down.... Trying... Transmitting (NAT) to 10.1.7.70:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-f6DW50Frp8m;received=10.1.7.70;rport=5060 From: ;tag=-4LPzfkHeF2blWUc To: Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local CSeq: 3 INVITE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Aug 4 10:43:32] DEBUG[22813]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-098c7ef8 [Aug 4 10:43:32] DEBUG[22807]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 4 10:43:32] DEBUG[22807]: chan_sip.c:14565 sip_devicestate: Checking device state for peer 3062 [Aug 4 10:43:32] DEBUG[22807]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 4 10:43:32] DEBUG[22807]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 4 10:43:32] DEBUG[22807]: chan_sip.c:14565 sip_devicestate: Checking device state for peer 3062 [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'Macro' -- Executing [3061@from-internal:1] Macro("SIP/3062-098c7ef8", "exten-vm|novm|3061") in new stack [Aug 4 10:43:32] DEBUG[22849]: app_queue.c:542 changethread: Device 'SIP/3062' changed to state '1' (Not in use) [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:1] NoOp("SIP/3062-098c7ef8", "3062") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:2] GotoIf("SIP/3062-098c7ef8", "0?5") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:5554 pbx_builtin_gotoif: Not taking any branch [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:3] GotoIf("SIP/3062-098c7ef8", "1?5") in new stack -- Goto (macro-exten-vm,s,5) [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:5] GotoIf("SIP/3062-098c7ef8", "1?:7") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:5554 pbx_builtin_gotoif: Not taking any branch [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:6] Set("SIP/3062-098c7ef8", "__VRSID=1154684612.0") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:7] Set("SIP/3062-098c7ef8", "CDR(userfield)=1154684612.0") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:8] NoOp("SIP/3062-098c7ef8", "SESSION ID IS SET TO: 1154684612.0") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:9] Macro("SIP/3062-098c7ef8", "dial|600|tr|3061") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:1] NoOp("SIP/3062-098c7ef8", "DIAL with CALLERID(number) = 3062") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'device' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:2] NoOp("SIP/3062-098c7ef8", "DIAL with CALLERID(name) = device") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:3] NoOp("SIP/3062-098c7ef8", "DIAL with CALLERIDNAME = ") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:4] Set("SIP/3062-098c7ef8", "CDR(userfield)=1154684612.0") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '1154684612.0' [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:5] NoOp("SIP/3062-098c7ef8", "GOING TO DIAL VRSID 1154684612.0 SAME AS 1154684612.0") in new stack [Aug 4 10:43:32] DEBUG[22848]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial:6] Dial("SIP/3062-098c7ef8", "SIP/3061| 600| tr") in new stack [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:14621 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4106 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:2520 create_addr_from_peer: Setting NAT on RTP to Off [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:2526 create_addr_from_peer: Setting NAT on VRTP to Off [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:3608 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:3609 sip_new: *** Joint capabilities are 0x0 (nothing) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:3610 sip_new: *** Our capabilities are 0x280004 (ulaw|h263|h264) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:3611 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:3613 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:3634 sip_new: This channel will not be able to handle video. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-6. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-5. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-4. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-3. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable ARG3. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable ARG2. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable ARG1. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-9. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-8. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-7. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3014 ast_channel_inherit_variables: Copying hard-transferable variable VRSID. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-6. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-5. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-3. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-2. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-1. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable STACK-from-internal-3061-1. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Aug 4 10:43:32] DEBUG[22848]: channel.c:3019 ast_channel_inherit_variables: Not copying variable SIPURI. [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:2718 sip_call: Outgoing Call for 3061 [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:2726 sip_call: Our T38 capability (0), joint T38 capability (0) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:5806 add_sdp: ** Our capability: 0x280004 (ulaw|h263|h264) Video flag: False [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:5807 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:5820 add_sdp: This call needs video offers! Video is at 10.1.1.9 port 17260 [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:5856 add_sdp: ** No compatible video codecs... Disabling video. Audio is at 10.1.1.9 port 17694 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:5959 add_sdp: -- Done with adding codecs to SDP [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:5998 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 0: INVITE sip:3061@10.1.7.25;line=10.1.1.9 SIP/2.0 (47) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK77678c06;rport (59) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 2: From: "device" ;tag=as054b6f0a (55) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 3: To: (38) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 4: Contact: (28) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 (56) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 9: Date: Fri, 04 Aug 2006 09:43:32 GMT (35) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 11: Supported: replaces (19) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 13: Content-Length: 220 (19) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4326 parse_request: Header 14: (0) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: v=0 (3) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: o=root 22803 22803 IN IP4 10.1.1.9 (34) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: s=session (9) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: c=IN IP4 10.1.1.9 (17) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: t=0 0 (5) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: m=audio 17694 RTP/AVP 0 101 (27) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: a=fmtp:101 0-16 (15) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: a=silenceSupp:off - - - - (25) [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:4358 parse_request: Line: a=sendrecv (10) Reliably Transmitting (no NAT) to 10.1.7.25:5060: INVITE sip:3061@10.1.7.25;line=10.1.1.9 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK77678c06;rport From: "device" ;tag=as054b6f0a To: Contact: Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 CSeq: 102 INVITE User-Agent: AuPix PBX Max-Forwards: 70 Date: Fri, 04 Aug 2006 09:43:32 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 220 v=0 o=root 22803 22803 IN IP4 10.1.1.9 s=session c=IN IP4 10.1.1.9 t=0 0 m=audio 17694 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 4 10:43:32] DEBUG[22848]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #75 -- Called 3061 Transmitting (NAT) to 10.1.7.70:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-f6DW50Frp8m;received=10.1.7.70;rport=5060 From: ;tag=-4LPzfkHeF2blWUc To: ;tag=as70752b4d Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local CSeq: 3 INVITE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- AstDev*CLI> <-- SIP read from 10.1.7.25:5060: SIP/2.0 180 Ringing To: ;tag=rgIDXb1NF0ibutke Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK77678c06;rport=5060;received=10.1.1.9 From: "device" ;tag=as054b6f0a Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 CSeq: 102 INVITE User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: ;tag=rgIDXb1NF0ibutke (59) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: Contact: (43) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK77678c06;rport=5060;received=10.1.1.9 (82) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: From: "device" ;tag=as054b6f0a (55) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 (56) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Content-Length: 0 (17) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:2047 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #75 - INVITE (got response) [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:2056 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203' Request 102: Found [Aug 4 10:43:32] DEBUG[22813]: chan_sip.c:11152 handle_response_invite: SIP response 180 to standard invite [Aug 4 10:43:32] DEBUG[22813]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061-098d07a8 [Aug 4 10:43:32] DEBUG[22807]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 4 10:43:32] DEBUG[22807]: chan_sip.c:14565 sip_devicestate: Checking device state for peer 3061 [Aug 4 10:43:32] DEBUG[22807]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 1 (Not in use) [Aug 4 10:43:32] DEBUG[22807]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 4 10:43:32] DEBUG[22807]: chan_sip.c:14565 sip_devicestate: Checking device state for peer 3061 [Aug 4 10:43:32] DEBUG[22850]: app_queue.c:536 changethread: Device 'SIP/3061' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. -- SIP/3061-098d07a8 is ringing AstDev*CLI> <-- SIP read from 10.1.7.25:5060: SIP/2.0 200 Ok To: ;tag=rgIDXb1NF0ibutke Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK77678c06;rport=5060;received=10.1.1.9 From: "device" ;tag=as054b6f0a Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 CSeq: 102 INVITE User-Agent: AuPix/v1.01.11 Content-Length: 214 Content-Type: application/sdp v=0 o=AuPix 1001 0 IN IP4 10.1.7.25 s=phone-call u=http://www.AuPix.com c=IN IP4 10.1.7.25 b=CT:64 t=0 0 a=sendrecv m=audio 5000 RTP/AVP 0 101 9 8 15 18 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: ;tag=rgIDXb1NF0ibutke (59) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: Contact: (43) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK77678c06;rport=5060;received=10.1.1.9 (82) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: From: "device" ;tag=as054b6f0a (55) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 (56) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Content-Length: 214 (19) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Content-Type: application/sdp (29) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: (0) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: v=0 (3) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.25 (31) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: s=phone-call (12) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: u=http://www.AuPix.com (22) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: c=IN IP4 10.1.7.25 (18) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: b=CT:64 (7) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: t=0 0 (5) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=sendrecv (10) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: m=audio 5000 RTP/AVP 0 101 9 8 15 18 (36) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=fmtp:101 0-15 (15) --- (10 headers 11 lines)--- [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:1996 __sip_ack: Acked pending invite 102 [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203' of Request 102: Match Not Found [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:11152 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Found RTP audio format 9 Found RTP audio format 8 Found RTP audio format 15 Found RTP audio format 18 Peer audio RTP is at port 10.1.7.25:5000 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4831 process_sdp: T38 state changed to 0 on channel SIP/3061-098d07a8 Capabilities: us - 0x280004 (ulaw|h263|h264), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 10.1.7.25:5000 [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4901 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4908 process_sdp: We have an owner, now see if we need to change this call [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:2879 update_call_counter: Updating call counter for outgoing call [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:7589 build_route: build_route: Contact hop: list_route: hop: [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:5337 reqprep: Strict routing enforced for session 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 set_destination: Parsing for address/port to send to set_destination: set destination to 10.1.7.25, port 5060 Transmitting (no NAT) to 10.1.7.25:5060: ACK sip:3061@10.1.7.25;line=10.1.1.9 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK08f74c7a;rport From: "device" ;tag=as054b6f0a To: ;tag=rgIDXb1NF0ibutke Contact: Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 CSeq: 102 ACK User-Agent: AuPix PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 4 10:43:34] DEBUG[22848]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061-098d07a8 -- SIP/3061-098d07a8 answered SIP/3062-098c7ef8 [Aug 4 10:43:34] DEBUG[22848]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-098c7ef8 [Aug 4 10:43:34] DEBUG[22848]: chan_sip.c:3319 sip_answer: SIP answering channel: SIP/3062-098c7ef8 [Aug 4 10:43:34] DEBUG[22848]: chan_sip.c:5806 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Aug 4 10:43:34] DEBUG[22848]: chan_sip.c:5807 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.1.1.9 port 17900 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 4 10:43:34] DEBUG[22848]: chan_sip.c:5959 add_sdp: -- Done with adding codecs to SDP [Aug 4 10:43:34] DEBUG[22848]: chan_sip.c:5998 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) Reliably Transmitting (NAT) to 10.1.7.70:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-f6DW50Frp8m;received=10.1.7.70;rport=5060 From: ;tag=-4LPzfkHeF2blWUc To: ;tag=as70752b4d Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local CSeq: 3 INVITE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 220 v=0 o=root 22803 22803 IN IP4 10.1.1.9 s=session c=IN IP4 10.1.1.9 t=0 0 m=audio 17900 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 4 10:43:34] DEBUG[22848]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #77 [Aug 4 10:43:34] DEBUG[22807]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 4 10:43:34] DEBUG[22807]: chan_sip.c:14565 sip_devicestate: Checking device state for peer 3061 [Aug 4 10:43:34] DEBUG[22807]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 1 (Not in use) [Aug 4 10:43:34] DEBUG[22807]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 4 10:43:34] DEBUG[22807]: chan_sip.c:14565 sip_devicestate: Checking device state for peer 3061 [Aug 4 10:43:34] DEBUG[22807]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 4 10:43:34] DEBUG[22807]: chan_sip.c:14565 sip_devicestate: Checking device state for peer 3062 [Aug 4 10:43:34] DEBUG[22807]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 4 10:43:34] DEBUG[22807]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 4 10:43:34] DEBUG[22807]: chan_sip.c:14565 sip_devicestate: Checking device state for peer 3062 [Aug 4 10:43:34] DEBUG[22852]: app_queue.c:542 changethread: Device 'SIP/3062' changed to state '1' (Not in use) [Aug 4 10:43:34] DEBUG[22851]: app_queue.c:536 changethread: Device 'SIP/3061' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. AstDev*CLI> <-- SIP read from 10.1.7.70:5060: ACK sip:3061@10.1.1.9 SIP/2.0 To: ;tag=as70752b4d From: ;tag=-4LPzfkHeF2blWUc Contact: CSeq: 3 ACK Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-f6DW50Frp8m;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: ACK sip:3061@10.1.1.9 SIP/2.0 (29) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: ;tag=as70752b4d (38) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: ;tag=-4LPzfkHeF2blWUc (46) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Contact: (43) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: CSeq: 3 ACK (11) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: _UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local (64) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-f6DW50Frp8m;rport (64) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Content-Length: 0 (17) [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:13981 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #77 [Aug 4 10:43:34] DEBUG[22813]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '_UMF~cZlCVTA_T-wqAgu+iNdaeUhmCMD@videophone.aupix.local' of Response 3: Match Not Found [Aug 4 10:43:35] DEBUG[22848]: rtp.c:2343 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 4 10:43:35] DEBUG[22848]: rtp.c:2343 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 4 10:43:36] DEBUG[22848]: rtp.c:778 ast_rtcp_read: Got RTCP report of 84 bytes [Aug 4 10:43:36] DEBUG[22848]: rtp.c:778 ast_rtcp_read: Got RTCP report of 84 bytes AstDev*CLI> <-- SIP read from 10.1.7.25:5060: INVITE sip:3062@10.1.1.9 SIP/2.0 To: device ;tag=as054b6f0a From: ;tag=rgIDXb1NF0ibutke Contact: CSeq: 2 INVITE Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-kZyzEZcBcTB;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Accept: application/sdp Accept-Encoding: identity Content-Length: 224 Content-Type: application/sdp v=0 o=AuPix 1001 0 IN IP4 10.1.7.25 s=phone-call u=http://www.AuPix.com c=IN IP4 0.0.0.0 b=CT:64 t=0 0 a=sendonly m=audio 5000 RTP/AVP 0 101 9 8 15 18 a=sendonly a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: INVITE sip:3062@10.1.1.9 SIP/2.0 (32) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: device ;tag=as054b6f0a (51) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: ;tag=rgIDXb1NF0ibutke (61) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Contact: (43) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: CSeq: 2 INVITE (14) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 (56) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-kZyzEZcBcTB;rport (64) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Accept: application/sdp (23) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: Accept-Encoding: identity (25) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 11: Content-Length: 224 (19) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 13: (0) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: v=0 (3) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.25 (31) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: s=phone-call (12) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: u=http://www.AuPix.com (22) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: b=CT:64 (7) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: t=0 0 (5) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=sendonly (10) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: m=audio 5000 RTP/AVP 0 101 9 8 15 18 (36) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=sendonly (10) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4358 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 12 lines)--- [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:13981 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.25 : 5060 (NAT) Found RTP audio format 0 Found RTP audio format 101 Found RTP audio format 9 Found RTP audio format 8 Found RTP audio format 15 Found RTP audio format 18 Peer audio RTP is at port 0.0.0.0:5000 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4831 process_sdp: T38 state changed to 0 on channel SIP/3061-098d07a8 Capabilities: us - 0x280004 (ulaw|h263|h264), peer - audio=0x10c (ulaw|alaw|g729)/video=0x0 (nothing), combined - 0x4 (ulaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 0.0.0.0:5000 [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4901 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4908 process_sdp: We have an owner, now see if we need to change this call [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:12842 handle_request_invite: Got a SIP re-invite for call 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:12931 handle_request_invite: SIP/3061-098d07a8: This call is UP.... [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:5806 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:5807 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.1.1.9 port 17694 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:5959 add_sdp: -- Done with adding codecs to SDP [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:5998 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) Reliably Transmitting (NAT) to 10.1.7.25:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-kZyzEZcBcTB;received=10.1.7.25;rport=5060 From: ;tag=rgIDXb1NF0ibutke To: device ;tag=as054b6f0a Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 CSeq: 2 INVITE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 220 v=0 o=root 22803 22804 IN IP4 10.1.1.9 s=session c=IN IP4 10.1.1.9 t=0 0 m=audio 17694 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=recvonly --- [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #80 -- Started music on hold, class 'default', on SIP/3062-098c7ef8 [Aug 4 10:43:37] DEBUG[22848]: channel.c:1827 ast_settimeout: Scheduling timer at 160 sample intervals [Aug 4 10:43:37] DEBUG[22848]: channel.c:2107 __ast_read: Generator got voice, switching to phase locked mode [Aug 4 10:43:37] DEBUG[22848]: channel.c:1827 ast_settimeout: Scheduling timer at 0 sample intervals [Aug 4 10:43:37] DEBUG[22848]: channel.c:2554 set_format: Set channel SIP/3062-098c7ef8 to write format slin [Aug 4 10:43:37] DEBUG[22848]: res_musiconhold.c:252 ast_moh_files_next: SIP/3062-098c7ef8 Opened file 0 '/var/lib/asterisk/moh-native/fpm-sunshine' AstDev*CLI> <-- SIP read from 10.1.7.25:5060: ACK sip:3062@10.1.1.9 SIP/2.0 To: device ;tag=as054b6f0a From: ;tag=rgIDXb1NF0ibutke Contact: CSeq: 2 ACK Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-kZyzEZcBcTB;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: ACK sip:3062@10.1.1.9 SIP/2.0 (29) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: device ;tag=as054b6f0a (51) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: ;tag=rgIDXb1NF0ibutke (61) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Contact: (43) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: CSeq: 2 ACK (11) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 (56) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-kZyzEZcBcTB;rport (64) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Content-Length: 0 (17) [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:13981 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #80 [Aug 4 10:43:37] DEBUG[22813]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203' of Response 2: Match Not Found [Aug 4 10:43:38] DEBUG[22848]: rtp.c:778 ast_rtcp_read: Got RTCP report of 84 bytes [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4106 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: OPTIONS sip:3063@10.1.3.10;line=10.1.1.9 SIP/2.0 (48) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK19c2f254;rport (59) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: "Unknown" ;tag=as07799b4b (59) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: To: (38) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: Contact: (31) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 1973081c70d480d01c97f7b2611f9ee6@xxx.xxx.xxx.203 (56) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Date: Fri, 04 Aug 2006 09:43:40 GMT (35) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 11: Supported: replaces (19) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 10.1.3.10:5060: OPTIONS sip:3063@10.1.3.10;line=10.1.1.9 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK19c2f254;rport From: "Unknown" ;tag=as07799b4b To: Contact: Call-ID: 1973081c70d480d01c97f7b2611f9ee6@xxx.xxx.xxx.203 CSeq: 102 OPTIONS User-Agent: AuPix PBX Max-Forwards: 70 Date: Fri, 04 Aug 2006 09:43:40 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:1911 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #81 AstDev*CLI> <-- SIP read from 10.1.3.10:5060: SIP/2.0 200 Ok To: From: "Unknown" ;tag=as07799b4b Call-ID: 1973081c70d480d01c97f7b2611f9ee6@xxx.xxx.xxx.203 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK19c2f254;rport=5060;received=10.1.1.9 CSeq: 102 OPTIONS Contact: User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: (38) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: "Unknown" ;tag=as07799b4b (59) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Call-ID: 1973081c70d480d01c97f7b2611f9ee6@xxx.xxx.xxx.203 (56) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK19c2f254;rport=5060;received=10.1.1.9 (82) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Contact: (24) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Content-Length: 0 (17) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:2004 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #81 [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:2014 __sip_ack: Stopping retransmission on '1973081c70d480d01c97f7b2611f9ee6@xxx.xxx.xxx.203' of Request 102: Match Not Found Really destroying SIP dialog '1973081c70d480d01c97f7b2611f9ee6@xxx.xxx.xxx.203' Method: OPTIONS AstDev*CLI> <-- SIP read from 10.1.7.25:5060: REFER sip:3062@10.1.1.9 SIP/2.0 To: device ;tag=as054b6f0a From: ;tag=rgIDXb1NF0ibutke Contact: CSeq: 3 REFER Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 Refer-To: Allow-Events: refer Accept: message/sipfrag Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-17caPAyeapG;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 AstDev*CLI> [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 0: REFER sip:3062@10.1.1.9 SIP/2.0 (31) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 1: To: device ;tag=as054b6f0a (51) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 2: From: ;tag=rgIDXb1NF0ibutke (61) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 3: Contact: (43) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 4: CSeq: 3 REFER (13) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 5: Call-ID: 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 (56) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 6: Refer-To: (29) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 7: Allow-Events: refer (19) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 8: Accept: message/sipfrag (23) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 9: Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-17caPAyeapG;rport (64) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 10: User-Agent: AuPix/v1.01.11 (26) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 11: Max-Forwards: 70 (16) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 12: Content-Length: 0 (17) [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:4326 parse_request: Header 13: (0) --- (13 headers 0 lines)--- [Aug 4 10:43:40] DEBUG[22813]: chan_sip.c:13981 handle_request: **** Received REFER (9) - Command in SIP REFER Call 45967def023fe6864fe47769063f91b9@xxx.xxx.xxx.203 got a SIP call transfer from callee: (REFER)! [Aug 4 10:43:40] WARNING[22813]: chan_sip.c:8240 get_refer_info: Huh? Not a sip: header (Referred-by: ). Skipping. AstDev*CLI> Disconnected from Asterisk server /usr/sbin/safe_asterisk: line 42: 22803 Segmentation fault (core dumped) ${ASTSBINDIR}/asterisk ${CLIARGS} ${ASTARGS} >&/dev/${TTY}