[root@AstDev ~]# asterisk -r Asterisk SVN-trunk-r38548M, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'show license' for details. ========================================================================= Connected to Asterisk SVN-trunk-r38548M currently running on AstDev (pid = 27236) Verbosity is at least 3 AstDev*CLI> debug No such command 'debug' (type 'help' for help) AstDev*CLI> show debug No such command 'show debug' (type 'help' for help) [Aug 3 09:48:51] DEBUG[27368]: manager.c:1808 process_message: Manager received command 'Ping' AstDev*CLI> set debug 5 Core debug was 0 and is now 5 [Aug 3 09:49:20] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Aug 3 09:49:20] DEBUG[27304]: chan_sip.c:4299 find_call: = Found Their Call ID: 62f735387376e1565a52ba035924cae4@81.171.226.203 Their Tag Our tag: as60d8d0f0 [Aug 3 09:49:20] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '62f735387376e1565a52ba035924cae4@81.171.226.203' of Request 102: Match Not Found Really destroying SIP dialog '62f735387376e1565a52ba035924cae4@81.171.226.203' Method: NOTIFY AstDev*CLI> set debug 4 Core debug was 5 and is now 4 AstDev*CLI> set debug 4 Core debug is at least 4 [Aug 3 09:49:26] DEBUG[27304]: chan_sip.c:1977 __sip_autodestruct: Auto destroying call '3c392bf4900b-we9xndha0f3l@snom360' [Aug 3 09:49:26] DEBUG[27304]: chan_sip.c:3041 sip_destroy: Destroying SIP dialog 3c392bf4900b-we9xndha0f3l@snom360 Really destroying SIP dialog '3c392bf4900b-we9xndha0f3l@snom360' Method: REGISTER AstDev*CLI> set verbose 4 Verbosity was 3 and is now 4 AstDev*CLI> sip debug SIP Debugging enabled AstDev*CLI> <-- SIP read from 81.171.226.200:61537: REGISTER sip:81.171.226.203 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-1jvnot2x71u2;rport From: "AstDev3060" ;tag=qbmpxm385j To: "AstDev3060" Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316684 REGISTER Max-Forwards: 70 Contact: ;q=1.0;+sip.instance="";audio;mobility="fixed";duplex="full";description="snom360";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO" User-Agent: snom360/4.4 Supported: gruu Allow-Events: dialog X-Real-IP: 10.1.1.15 WWW-Contact: WWW-Contact: Expires: 60 Content-Length: 0 [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: REGISTER sip:81.171.226.203 SIP/2.0 (35) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-1jvnot2x71u2;rport (65) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "AstDev3060" ;tag=qbmpxm385j (59) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: "AstDev3060" (42) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 (42) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 316684 REGISTER (21) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Max-Forwards: 70 (16) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: Contact: ;q=1.0;+sip.instance="";audio;mobility="fixed";duplex="full";description="snom360";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO" (293) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: User-Agent: snom360/4.4 (23) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Supported: gruu (15) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Allow-Events: dialog (20) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: X-Real-IP: 10.1.1.15 (20) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: WWW-Contact: (34) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 13: WWW-Contact: (36) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 14: Expires: 60 (11) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 15: Content-Length: 0 (17) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 16: (0) --- (16 headers 0 lines)--- [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for 3c392bf4900b-we9xndha0f3l@snom360 - REGISTER (No RTP) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 81.171.226.200 : 61537 (NAT) Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-1jvnot2x71u2;received=81.171.226.200;rport=61537 From: "AstDev3060" ;tag=qbmpxm385j To: "AstDev3060" Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316684 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-1jvnot2x71u2;received=81.171.226.200;rport=61537 From: "AstDev3060" ;tag=qbmpxm385j To: "AstDev3060" ;tag=as0d0661b1 Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316684 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: WWW-Authenticate: Digest algorithm=MD5, realm="AuPixDev.aupix.com", nonce="476d96b9" Content-Length: 0 AstDev*CLI> --- Scheduling destruction of SIP dialog '3c392bf4900b-we9xndha0f3l@snom360' in 32000 ms (Method: REGISTER) AstDev*CLI> <-- SIP read from 81.171.226.200:61537: REGISTER sip:81.171.226.203 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6b6649rn4yvy;rport From: "AstDev3060" ;tag=qbmpxm385j To: "AstDev3060" Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316685 REGISTER Max-Forwards: 70 Contact: ;q=1.0;+sip.instance="";audio;mobility="fixed";duplex="full";description="snom360";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO" User-Agent: snom360/4.4 Supported: gruu Allow-Events: dialog X-Real-IP: 10.1.1.15 WWW-Contact: WWW-Contact: Authorization: Digest username="3060",realm="AuPixDev.aupix.com",nonce="476d96b9",uri="sip:81.171.226.203",response="32b0764fc01dcbe89dcf284dcbd14e58",algorithm=md5 Expires: 60 Content-Length: 0 [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: REGISTER sip:81.171.226.203 SIP/2.0 (35) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6b6649rn4yvy;rport (65) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "AstDev3060" ;tag=qbmpxm385j (59) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: "AstDev3060" (42) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 (42) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 316685 REGISTER (21) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Max-Forwards: 70 (16) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: Contact: ;q=1.0;+sip.instance="";audio;mobility="fixed";duplex="full";description="snom360";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO" (293) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: User-Agent: snom360/4.4 (23) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Supported: gruu (15) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Allow-Events: dialog (20) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: X-Real-IP: 10.1.1.15 (20) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: WWW-Contact: (34) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 13: WWW-Contact: (36) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 14: Authorization: Digest username="3060",realm="AuPixDev.aupix.com",nonce="476d96b9",uri="sip:81.171.226.203",response="32b0764fc01dcbe89dcf284dcbd14e58",algorithm=md5 (164) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 15: Expires: 60 (11) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 16: Content-Length: 0 (17) [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 17: (0) --- (17 headers 0 lines)--- [Aug 3 09:49:41] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 81.171.226.200 : 61537 (NAT) Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6b6649rn4yvy;received=81.171.226.200;rport=61537 From: "AstDev3060" ;tag=qbmpxm385j To: "AstDev3060" Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316685 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6b6649rn4yvy;received=81.171.226.200;rport=61537 From: "AstDev3060" ;tag=qbmpxm385j To: "AstDev3060" ;tag=as0d0661b1 Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316685 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Thu, 03 Aug 2006 08:49:41 GMT Content-Length: 0 --- [Aug 3 09:49:41] DEBUG[27304]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3060 Scheduling destruction of SIP dialog '3c392bf4900b-we9xndha0f3l@snom360' in 15000 ms (Method: REGISTER) [Aug 3 09:49:41] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 3 09:49:41] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3060 [Aug 3 09:49:41] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3060 - state 1 (Not in use) [Aug 3 09:49:41] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 3 09:49:41] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3060 [Aug 3 09:49:41] DEBUG[28567]: app_queue.c:537 changethread: Device 'SIP/3060' 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: INVITE sip:3061@10.1.1.9 SIP/2.0 To: From: ;tag=Ua3Zy8eBIrchli0u Contact: CSeq: 2 INVITE Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-v3eehCQYKOm;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 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: INVITE sip:3061@10.1.1.9 SIP/2.0 (32) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: (23) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=Ua3Zy8eBIrchli0u (46) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Contact: (43) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: CSeq: 2 INVITE (14) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local (64) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-v3eehCQYKOm;rport (64) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Accept: application/sdp (23) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Accept-Encoding: identity (25) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Content-Length: 227 (19) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 13: (0) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: v=0 (3) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.70 (31) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: s=phone-call (12) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: u=http://www.AuPix.com (22) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: c=IN IP4 10.1.7.70 (18) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: b=CT:384 (8) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: t=0 0 (5) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=sendrecv (10) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: m=audio 5000 RTP/AVP 18 15 8 0 9 101 (36) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=ptime:60 (10) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 12 lines)--- [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local - INVITE (With RTP) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.70 : 5060 (NAT) Using INVITE request as basis request - mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:9189 check_user_full: Setting NAT on RTP to On [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:9194 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-v3eehCQYKOm;received=10.1.7.70;rport=5060 From: ;tag=Ua3Zy8eBIrchli0u To: ;tag=as524f02e8 Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@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="7201525c" Content-Length: 0 --- [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #543 Scheduling destruction of SIP dialog 'mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local' in 32000 ms (Method: INVITE) Found user '3062' [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) Scheduling destruction of SIP dialog '4656962e233bb6d85d9ff5572c924093@81.171.226.203' in 32000 ms (Method: NOTIFY) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: NOTIFY sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 (52) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK3acf827a;rport (65) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "Unknown" ;tag=as25bd7a51 (59) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: (43) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Contact: (37) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 4656962e233bb6d85d9ff5572c924093@81.171.226.203 (56) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Event: message-summary (22) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Content-Length: 94 (18) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: (0) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: Messages-Waiting: no (20) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: Message-Account: sip:asterisk@81.171.226.203 (44) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: Voice-Message: 0/0 (0/0) (24) Reliably Transmitting (NAT) to 81.171.226.200:61537: NOTIFY sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK3acf827a;rport From: "Unknown" ;tag=as25bd7a51 To: Contact: Call-ID: 4656962e233bb6d85d9ff5572c924093@81.171.226.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@81.171.226.203 Voice-Message: 0/0 (0/0) --- [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #546 AstDev*CLI> <-- SIP read from 10.1.7.70:5060: ACK sip:3061@10.1.1.9 SIP/2.0 To: ;tag=as524f02e8 From: ;tag=Ua3Zy8eBIrchli0u Contact: CSeq: 2 ACK Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-v3eehCQYKOm;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: ACK sip:3061@10.1.1.9 SIP/2.0 (29) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: ;tag=as524f02e8 (38) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=Ua3Zy8eBIrchli0u (46) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Contact: (43) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: CSeq: 2 ACK (11) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local (64) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-v3eehCQYKOm;rport (64) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #543 [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on 'mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@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=Ua3Zy8eBIrchli0u Contact: CSeq: 3 INVITE Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local Proxy-Authorization: Digest username="3062", realm="AuPixDev.aupix.com", nonce="7201525c", uri="sip:3061@10.1.1.9", response="3c7f9507534e1bd58766ebb9f0cbeb5d", algorithm=md5 Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-rlQqqnmJd9c;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 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: INVITE sip:3061@10.1.1.9 SIP/2.0 (32) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: Max-Forwards: 70 (16) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Accept: application/sdp (23) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Accept-Encoding: identity (25) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Content-Length: 227 (19) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Content-Type: application/sdp (29) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: To: (23) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: From: ;tag=Ua3Zy8eBIrchli0u (46) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Contact: (43) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: CSeq: 3 INVITE (14) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local (64) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: Proxy-Authorization: Digest username="3062", realm="AuPixDev.aupix.com", nonce="7201525c", uri="sip:3061@10.1.1.9", response="3c7f9507534e1bd58766ebb9f0cbeb5d", algorithm=md5 (174) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 13: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-rlQqqnmJd9c;rport (64) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 14: (0) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: v=0 (3) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.70 (31) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: s=phone-call (12) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: u=http://www.AuPix.com (22) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: c=IN IP4 10.1.7.70 (18) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: b=CT:384 (8) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: t=0 0 (5) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=sendrecv (10) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: m=audio 5000 RTP/AVP 18 15 8 0 9 101 (36) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=ptime:60 (10) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=fmtp:101 0-15 (15) --- (14 headers 12 lines)--- [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.70 : 5060 (NAT) Using INVITE request as basis request - mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:9189 check_user_full: Setting NAT on RTP to On [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:9194 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 101 in SDP offer [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:5303 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 [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:5414 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:13369 handle_request_invite: Checking SIP call limits for device 3062 [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:2935 update_call_counter: Updating call counter for incoming call Looking for 3061 in from-internal (domain 10.1.1.9) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:3751 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:3752 sip_new: *** Joint capabilities are 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:3753 sip_new: *** Our capabilities are 0x280004 (ulaw|h263|h264) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:3754 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:3777 sip_new: This channel will not be able to handle video. [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:8151 build_route: build_route: Contact hop: list_route: hop: [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:13439 handle_request_invite: SIP/3062-087758f8: 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-rlQqqnmJd9c;received=10.1.7.70;rport=5060 From: ;tag=Ua3Zy8eBIrchli0u To: Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@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 3 09:49:42] DEBUG[27304]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-087758f8 <-- SIP read from 81.171.226.200:61537: SIP/2.0 200 Ok Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK3acf827a;rport=5060 From: "Unknown" ;tag=as25bd7a51 To: Call-ID: 4656962e233bb6d85d9ff5572c924093@81.171.226.203 CSeq: 102 NOTIFY Content-Length: 0 [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK3acf827a;rport=5060 (70) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "Unknown" ;tag=as25bd7a51 (59) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: (43) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 4656962e233bb6d85d9ff5572c924093@81.171.226.203 (56) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 102 NOTIFY (16) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Content-Length: 0 (17) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: (0) --- (7 headers 0 lines)--- [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #546 [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '4656962e233bb6d85d9ff5572c924093@81.171.226.203' of Request 102: Match Not Found Really destroying SIP dialog '4656962e233bb6d85d9ff5572c924093@81.171.226.203' Method: NOTIFY [Aug 3 09:49:42] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 3 09:49:42] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3062 [Aug 3 09:49:42] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 3 09:49:42] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 3 09:49:42] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3062 [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Macro' -- Executing [3061@from-internal:1] Macro("SIP/3062-087758f8", "exten-vm|novm|3061") in new stack [Aug 3 09:49:42] NOTICE[28568]: pbx.c:1569 pbx_substitute_variables_helper_full: Error in extension logic (missing ']') [Aug 3 09:49:42] NOTICE[28568]: pbx.c:1495 pbx_substitute_variables_helper_full: Error in extension logic (missing '}') [Aug 3 09:49:42] WARNING[28568]: pbx.c:1394 func_args: Can't find trailing parenthesis? [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '3062' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:1] NoOp("SIP/3062-087758f8", "3062") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:2] GotoIf("SIP/3062-087758f8", "0?5") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:5554 pbx_builtin_gotoif: Not taking any branch [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:3] GotoIf("SIP/3062-087758f8", "1?5") in new stack -- Goto (macro-exten-vm,s,5) [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:5] GotoIf("SIP/3062-087758f8", "1?:7") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:5554 pbx_builtin_gotoif: Not taking any branch [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:6] Set("SIP/3062-087758f8", "__VRSID=1154594982.6") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:7] Set("SIP/3062-087758f8", "CDR(userfield)=1154594982.6") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:8] NoOp("SIP/3062-087758f8", "SESSION ID IS SET TO: 1154594982.6") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:9] Macro("SIP/3062-087758f8", "dial|600|tr|3061") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:1] NoOp("SIP/3062-087758f8", "DIAL with CALLERID(number) = 3062") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'device' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:2] NoOp("SIP/3062-087758f8", "DIAL with CALLERID(name) = device") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:3] NoOp("SIP/3062-087758f8", "DIAL with CALLERIDNAME = ") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:4] Set("SIP/3062-087758f8", "CDR(userfield)=1154594982.6") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '1154594982.6' [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:5] NoOp("SIP/3062-087758f8", "GOING TO DIAL VRSID 1154594982.6 SAME AS 1154594982.6") in new stack [Aug 3 09:49:42] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial:6] Dial("SIP/3062-087758f8", "SIP/3061| 600| tr") in new stack [Aug 3 09:49:42] DEBUG[28569]: app_queue.c:543 changethread: Device 'SIP/3062' changed to state '1' (Not in use) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:15176 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:2554 create_addr_from_peer: Setting NAT on RTP to Off [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:2560 create_addr_from_peer: Setting NAT on VRTP to Off [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:3751 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:3752 sip_new: *** Joint capabilities are 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:3753 sip_new: *** Our capabilities are 0x280004 (ulaw|h263|h264) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:3754 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:3756 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:3777 sip_new: This channel will not be able to handle video. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-6. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-5. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-4. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-3. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable ARG3. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable ARG2. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable ARG1. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-9. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-8. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-7. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3226 ast_channel_inherit_variables: Copying hard-transferable variable VRSID. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-6. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-5. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-3. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-2. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-1. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-from-internal-3061-1. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Aug 3 09:49:42] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable SIPURI. [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:2757 sip_call: Outgoing Call for 3061 [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:2935 update_call_counter: Updating call counter for outgoing call [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:2782 sip_call: Our T38 capability (0), joint T38 capability (0) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:6365 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:6366 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.1.1.9 port 10276 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:6520 add_sdp: -- Done with adding codecs to SDP [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:6562 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 0: INVITE sip:3061@10.1.7.25;line=10.1.1.9 SIP/2.0 (47) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7509fcdc;rport (59) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 2: From: "device" ;tag=as519bc400 (55) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 3: To: (38) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 4: Contact: (28) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 9: Date: Thu, 03 Aug 2006 08:49:42 GMT (35) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 11: Supported: replaces (19) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 13: Content-Length: 193 (19) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 14: (0) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: v=0 (3) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: o=root 27236 27236 IN IP4 10.1.1.9 (34) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: s=session (9) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: c=IN IP4 10.1.1.9 (17) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: t=0 0 (5) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: m=audio 10276 RTP/AVP 0 101 (27) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: a=fmtp:101 0-16 (15) [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:4503 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=z9hG4bK7509fcdc;rport From: "device" ;tag=as519bc400 To: Contact: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 102 INVITE User-Agent: AuPix PBX Max-Forwards: 70 Date: Thu, 03 Aug 2006 08:49:42 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 193 v=0 o=root 27236 27236 IN IP4 10.1.1.9 s=session c=IN IP4 10.1.1.9 t=0 0 m=audio 10276 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv --- [Aug 3 09:49:42] DEBUG[28568]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #547 -- 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-rlQqqnmJd9c;received=10.1.7.70;rport=5060 From: ;tag=Ua3Zy8eBIrchli0u To: ;tag=as2b902122 Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@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=HTD5KbkluTUfmRK3 Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7509fcdc;rport=5060;received=10.1.1.9 From: "device" ;tag=as519bc400 Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 102 INVITE User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: ;tag=HTD5KbkluTUfmRK3 (59) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: Contact: (43) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7509fcdc;rport=5060;received=10.1.1.9 (82) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: From: "device" ;tag=as519bc400 (55) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Content-Length: 0 (17) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:2081 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #547 - INVITE (got response) [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:2090 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203' Request 102: Found [Aug 3 09:49:42] DEBUG[27304]: chan_sip.c:11730 handle_response_invite: SIP response 180 to standard invite [Aug 3 09:49:42] DEBUG[27304]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061-0879c9b0 [Aug 3 09:49:42] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 3 09:49:42] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3061 [Aug 3 09:49:42] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 1 (Not in use) [Aug 3 09:49:42] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 3 09:49:42] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3061 -- SIP/3061-0879c9b0 is ringing [Aug 3 09:49:42] DEBUG[28570]: app_queue.c:537 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.25:5060: SIP/2.0 200 Ok To: ;tag=HTD5KbkluTUfmRK3 Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7509fcdc;rport=5060;received=10.1.1.9 From: "device" ;tag=as519bc400 Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.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 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: ;tag=HTD5KbkluTUfmRK3 (59) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: Contact: (43) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7509fcdc;rport=5060;received=10.1.1.9 (82) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: From: "device" ;tag=as519bc400 (55) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Content-Length: 214 (19) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Type: application/sdp (29) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: v=0 (3) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.25 (31) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: s=phone-call (12) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: u=http://www.AuPix.com (22) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: c=IN IP4 10.1.7.25 (18) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: b=CT:64 (7) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: t=0 0 (5) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=sendrecv (10) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: m=audio 5000 RTP/AVP 0 101 9 8 15 18 (36) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=fmtp:101 0-15 (15) --- (10 headers 11 lines)--- [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:2030 __sip_ack: Acked pending invite 102 [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203' of Request 102: Match Not Found [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:11730 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 101 in SDP offer [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:5303 process_sdp: T38 state changed to 0 on channel SIP/3061-0879c9b0 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 3 09:49:43] DEBUG[27304]: chan_sip.c:5414 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:5421 process_sdp: We have an owner, now see if we need to change this call [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:2935 update_call_counter: Updating call counter for outgoing call [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:8151 build_route: build_route: Contact hop: list_route: hop: [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:5854 reqprep: Strict routing enforced for session 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.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=z9hG4bK6758d849;rport From: "device" ;tag=as519bc400 To: ;tag=HTD5KbkluTUfmRK3 Contact: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 102 ACK User-Agent: AuPix PBX Max-Forwards: 70 Content-Length: 0 --- -- Call on SIP/3061-0879c9b0 is indicating caps [Aug 3 09:49:43] DEBUG[28568]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061-0879c9b0 -- SIP/3061-0879c9b0 answered SIP/3062-087758f8 [Aug 3 09:49:43] DEBUG[28568]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-087758f8 [Aug 3 09:49:43] DEBUG[28568]: chan_sip.c:3375 sip_answer: SIP answering channel: SIP/3062-087758f8 [Aug 3 09:49:43] DEBUG[28568]: chan_sip.c:6365 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Aug 3 09:49:43] DEBUG[28568]: chan_sip.c:6366 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.1.1.9 port 15938 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 3 09:49:43] DEBUG[28568]: chan_sip.c:6520 add_sdp: -- Done with adding codecs to SDP [Aug 3 09:49:43] DEBUG[28568]: chan_sip.c:6562 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-rlQqqnmJd9c;received=10.1.7.70;rport=5060 From: ;tag=Ua3Zy8eBIrchli0u To: ;tag=as2b902122 Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@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: 193 v=0 o=root 27236 27236 IN IP4 10.1.1.9 s=session c=IN IP4 10.1.1.9 t=0 0 m=audio 15938 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv --- [Aug 3 09:49:43] DEBUG[28568]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #549 [Aug 3 09:49:43] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 3 09:49:43] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3061 [Aug 3 09:49:43] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 1 (Not in use) [Aug 3 09:49:43] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 3 09:49:43] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3061 [Aug 3 09:49:43] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 3 09:49:43] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3062 [Aug 3 09:49:43] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 3 09:49:43] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 3 09:49:43] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3062 [Aug 3 09:49:43] DEBUG[28571]: app_queue.c:537 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. [Aug 3 09:49:43] DEBUG[28572]: app_queue.c:543 changethread: Device 'SIP/3062' changed to state '1' (Not in use) AstDev*CLI> <-- SIP read from 10.1.7.70:5060: ACK sip:3061@10.1.1.9 SIP/2.0 To: ;tag=as2b902122 From: ;tag=Ua3Zy8eBIrchli0u Contact: CSeq: 3 ACK Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-rlQqqnmJd9c;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: ACK sip:3061@10.1.1.9 SIP/2.0 (29) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: ;tag=as2b902122 (38) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=Ua3Zy8eBIrchli0u (46) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Contact: (43) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: CSeq: 3 ACK (11) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local (64) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-rlQqqnmJd9c;rport (64) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #549 [Aug 3 09:49:43] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on 'mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local' of Response 3: Match Not Found [Aug 3 09:49:44] DEBUG[28568]: rtp.c:2341 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 3 09:49:44] DEBUG[28568]: rtp.c:2341 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 3 09:49:45] DEBUG[28568]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes [Aug 3 09:49:45] DEBUG[28568]: rtp.c:767 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=as519bc400 From: ;tag=HTD5KbkluTUfmRK3 Contact: CSeq: 2 INVITE Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-1ZVVQCHrDYk;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 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: INVITE sip:3062@10.1.1.9 SIP/2.0 (32) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: device ;tag=as519bc400 (51) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=HTD5KbkluTUfmRK3 (61) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Contact: (43) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: CSeq: 2 INVITE (14) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-1ZVVQCHrDYk;rport (64) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Accept: application/sdp (23) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Accept-Encoding: identity (25) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Content-Length: 224 (19) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 13: (0) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: v=0 (3) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.25 (31) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: s=phone-call (12) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: u=http://www.AuPix.com (22) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: c=IN IP4 0.0.0.0 (16) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: b=CT:64 (7) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: t=0 0 (5) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=sendonly (10) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: m=audio 5000 RTP/AVP 0 101 9 8 15 18 (36) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=sendonly (10) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 12 lines)--- [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:14556 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 101 in SDP offer [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:5303 process_sdp: T38 state changed to 0 on channel SIP/3061-0879c9b0 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 3 09:49:45] DEBUG[27304]: chan_sip.c:5414 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:5421 process_sdp: We have an owner, now see if we need to change this call [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:13417 handle_request_invite: Got a SIP re-invite for call 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:13506 handle_request_invite: SIP/3061-0879c9b0: This call is UP.... [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:6365 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:6366 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 10.1.1.9 port 10276 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:6520 add_sdp: -- Done with adding codecs to SDP [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:6562 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-1ZVVQCHrDYk;received=10.1.7.25;rport=5060 From: ;tag=HTD5KbkluTUfmRK3 To: device ;tag=as519bc400 Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.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: 193 v=0 o=root 27236 27237 IN IP4 10.1.1.9 s=session c=IN IP4 10.1.1.9 t=0 0 m=audio 10276 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=recvonly --- [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #552 -- Started music on hold, class 'default', on SIP/3062-087758f8 [Aug 3 09:49:45] DEBUG[28568]: channel.c:1827 ast_settimeout: Scheduling timer at 160 sample intervals [Aug 3 09:49:45] DEBUG[28568]: channel.c:3724 ast_generic_bridge: Got a FRAME_CONTROL (33554436) frame on channel SIP/3061-0879c9b0 [Aug 3 09:49:45] DEBUG[28568]: channel.c:3989 ast_channel_bridge: Bridge stops bridging channels SIP/3062-087758f8 and SIP/3061-0879c9b0 AstDev*CLI> <-- SIP read from 10.1.7.25:5060: ACK sip:3062@10.1.1.9 SIP/2.0 To: device ;tag=as519bc400 From: ;tag=HTD5KbkluTUfmRK3 Contact: CSeq: 2 ACK Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-1ZVVQCHrDYk;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: ACK sip:3062@10.1.1.9 SIP/2.0 (29) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: device ;tag=as519bc400 (51) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=HTD5KbkluTUfmRK3 (61) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Contact: (43) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: CSeq: 2 ACK (11) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-1ZVVQCHrDYk;rport (64) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #552 [Aug 3 09:49:45] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203' of Response 2: Match Not Found [Aug 3 09:49:45] DEBUG[28568]: channel.c:2755 set_format: Set channel SIP/3062-087758f8 to write format slin [Aug 3 09:49:45] DEBUG[28568]: res_musiconhold.c:248 ast_moh_files_next: SIP/3062-087758f8 Opened file 0 '/var/lib/asterisk/moh-native/fpm-sunshine' [Aug 3 09:49:45] DEBUG[28568]: channel.c:2107 __ast_read: Generator got voice, switching to phase locked mode [Aug 3 09:49:45] DEBUG[28568]: channel.c:1827 ast_settimeout: Scheduling timer at 0 sample intervals [Aug 3 09:49:47] DEBUG[28568]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes AstDev*CLI> <-- SIP read from 10.1.7.25:5060: REFER sip:3062@10.1.1.9 SIP/2.0 To: device ;tag=as519bc400 From: ;tag=HTD5KbkluTUfmRK3 Contact: CSeq: 3 REFER Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 Refer-To: Allow-Events: refer Accept: message/sipfrag Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-QiHpK0lVx83;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 AstDev*CLI> [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: REFER sip:3062@10.1.1.9 SIP/2.0 (31) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: device ;tag=as519bc400 (51) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=HTD5KbkluTUfmRK3 (61) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Contact: (43) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: CSeq: 3 REFER (13) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Refer-To: (29) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: Allow-Events: refer (19) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Accept: message/sipfrag (23) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-QiHpK0lVx83;rport (64) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Max-Forwards: 70 (16) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: Content-Length: 0 (17) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 13: (0) --- (13 headers 0 lines)--- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received REFER (9) - Command in SIP REFER Call 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 got a SIP call transfer from callee: (REFER)! [Aug 3 09:49:48] WARNING[27304]: chan_sip.c:8802 get_refer_info: Huh? Not a sip: header (Referred-by: ). Skipping. SIP transfer to extension 3060@from-internal by (null) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:13907 handle_request_refer: SIP blind transfer: Transferer channel SIP/3061-0879c9b0, transferee channel SIP/3062-087758f8 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:13923 handle_request_refer: Got SIP transfer, applying to bridged peer 'SIP/3062-087758f8' Transmitting (NAT) to 10.1.7.25:5060: SIP/2.0 202 Accepted Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-QiHpK0lVx83;received=10.1.7.25;rport=5060 From: ;tag=HTD5KbkluTUfmRK3 To: device ;tag=as519bc400 Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 3 REFER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:13961 handle_request_refer: chan1->name: SIP/3061-0879c9b0 [Aug 3 09:49:48] ERROR[27304]: ../include/asterisk/lock.h:405 __ast_pthread_mutex_unlock: chan_sip.c line 13996 (handle_request_refer): mutex '¤t.chan2->lock' freed more times than we've locked! [Aug 3 09:49:48] ERROR[27304]: ../include/asterisk/lock.h:418 __ast_pthread_mutex_unlock: chan_sip.c line 13996 (handle_request_refer): Error releasing mutex: Operation not permitted [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:5854 reqprep: Strict routing enforced for session 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 set_destination: Parsing for address/port to send to set_destination: set destination to 10.1.7.25, port 5060 Reliably Transmitting (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=z9hG4bK06c4df73;rport From: "device" ;tag=as519bc400 To: ;tag=HTD5KbkluTUfmRK3 Contact: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 103 NOTIFY User-Agent: AuPix PBX Max-Forwards: 70 Event: refer;id=3 Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 21 SIP/2.0 183 Ringing --- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #553 [Aug 3 09:49:48] DEBUG[27304]: channel.c:1309 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/3062-087758f8' [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:14032 handle_request_refer: Blind transfer succeeded. Telling transferer. [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:5854 reqprep: Strict routing enforced for session 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 set_destination: Parsing for address/port to send to set_destination: set destination to 10.1.7.25, port 5060 Reliably Transmitting (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=z9hG4bK6cb03c3c;rport From: "device" ;tag=as519bc400 To: ;tag=HTD5KbkluTUfmRK3 Contact: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 104 NOTIFY User-Agent: AuPix PBX Max-Forwards: 70 Event: refer;id=3 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 16 SIP/2.0 200 Ok --- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #554 -- Stopped music on hold on SIP/3062-087758f8 [Aug 3 09:49:48] DEBUG[28568]: channel.c:2755 set_format: Set channel SIP/3062-087758f8 to write format ulaw [Aug 3 09:49:48] DEBUG[28568]: channel.c:1827 ast_settimeout: Scheduling timer at 0 sample intervals [Aug 3 09:49:48] DEBUG[28568]: channel.c:3702 ast_generic_bridge: Didn't get a frame from channel: SIP/3062-087758f8 [Aug 3 09:49:48] DEBUG[28568]: channel.c:3989 ast_channel_bridge: Bridge stops bridging channels SIP/3062-087758f8 and SIP/3061-0879c9b0 [Aug 3 09:49:48] DEBUG[28568]: channel.c:1527 ast_hangup: Hanging up channel 'SIP/3061-0879c9b0' [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:3222 sip_hangup: SIP Transfer: Not hanging up right now... Rescheduling hangup for 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203. Scheduling destruction of SIP dialog '60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203' in 32000 ms (Method: REFER) [Aug 3 09:49:48] DEBUG[28568]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061-0879c9b0 [Aug 3 09:49:48] DEBUG[28568]: rtp.c:1307 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Aug 3 09:49:48] DEBUG[28568]: app_dial.c:1636 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Aug 3 09:49:48] DEBUG[28568]: app_macro.c:221 macro_exec: Spawn extension (from-internal,3060,0) exited non-zero on 'SIP/3062-087758f8' in macro 'dial' [Aug 3 09:49:48] DEBUG[28568]: app_macro.c:221 macro_exec: Spawn extension (from-internal,3060,0) exited non-zero on 'SIP/3062-087758f8' in macro 'exten-vm' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:2271 __ast_pbx_run: Spawn extension (from-internal,3060,0) exited non-zero on 'SIP/3062-087758f8' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Macro' -- Executing [3060@from-internal:1] Macro("SIP/3062-087758f8", "exten-vm|novm|3060") in new stack [Aug 3 09:49:48] NOTICE[28568]: pbx.c:1569 pbx_substitute_variables_helper_full: Error in extension logic (missing ']') [Aug 3 09:49:48] NOTICE[28568]: pbx.c:1495 pbx_substitute_variables_helper_full: Error in extension logic (missing '}') [Aug 3 09:49:48] WARNING[28568]: pbx.c:1394 func_args: Can't find trailing parenthesis? [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '3062' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:1] NoOp("SIP/3062-087758f8", "3062") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:2] GotoIf("SIP/3062-087758f8", "0?5") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:5554 pbx_builtin_gotoif: Not taking any branch [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:3] GotoIf("SIP/3062-087758f8", "1?5") in new stack -- Goto (macro-exten-vm,s,5) [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1596 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:5] GotoIf("SIP/3062-087758f8", "0?:7") in new stack -- Goto (macro-exten-vm,s,7) [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:7] Set("SIP/3062-087758f8", "CDR(userfield)=1154594982.6") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:8] NoOp("SIP/3062-087758f8", "SESSION ID IS SET TO: 1154594982.6") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:9] Macro("SIP/3062-087758f8", "dial|600|tr|3060") in new stack [Aug 3 09:49:48] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 3 09:49:48] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3061 [Aug 3 09:49:48] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 1 (Not in use) [Aug 3 09:49:48] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 3 09:49:48] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3061 [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:1] NoOp("SIP/3062-087758f8", "DIAL with CALLERID(number) = 3062") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is 'device' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:2] NoOp("SIP/3062-087758f8", "DIAL with CALLERID(name) = device") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:3] NoOp("SIP/3062-087758f8", "DIAL with CALLERIDNAME = ") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:4] Set("SIP/3062-087758f8", "CDR(userfield)=1154594982.6") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1529 pbx_substitute_variables_helper_full: Function result is '1154594982.6' [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:5] NoOp("SIP/3062-087758f8", "GOING TO DIAL VRSID 1154594982.6 SAME AS 1154594982.6") in new stack [Aug 3 09:49:48] DEBUG[28568]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial:6] Dial("SIP/3062-087758f8", "SIP/3060| 600| tr") in new stack [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:15176 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:2554 create_addr_from_peer: Setting NAT on RTP to On [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:3751 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:3752 sip_new: *** Joint capabilities are 0x4 (ulaw) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:3753 sip_new: *** Our capabilities are 0x280004 (ulaw|h263|h264) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:3754 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:3756 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:3777 sip_new: This channel will not be able to handle video. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-6. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-5. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-4. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-3. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable ARG3. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable ARG2. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable ARG1. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-9. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-8. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-7. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-5. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-3. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-2. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-1. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-from-internal-3060-1. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable DIALSTATUS. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable DIALEDTIME. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable ANSWEREDTIME. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3218 ast_channel_inherit_variables: Copying soft-transferable variable SIPTRANSFER_REFERER. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3218 ast_channel_inherit_variables: Copying soft-transferable variable SIPTRANSFER. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable BLINDTRANSFER. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable BRIDGEPEER. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable DIALEDPEERNAME. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3226 ast_channel_inherit_variables: Copying hard-transferable variable VRSID. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-6. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable STACK-from-internal-3061-1. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Aug 3 09:49:48] DEBUG[28568]: channel.c:3231 ast_channel_inherit_variables: Not copying variable SIPURI. [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:2749 sip_call: Call for 3060 transfered by [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:2757 sip_call: Outgoing Call for 3060 [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:2935 update_call_counter: Updating call counter for outgoing call [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:2782 sip_call: Our T38 capability (0), joint T38 capability (0) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:6365 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: False [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:6366 add_sdp: ** Our prefcodec: 0x4 (ulaw) Audio is at 81.171.226.203 port 16790 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:6520 add_sdp: -- Done with adding codecs to SDP [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:6562 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 0: INVITE sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 (52) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport (65) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 2: From: "device" ;tag=as12885efe (55) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 3: To: (43) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 4: Contact: (34) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 (56) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 9: Date: Thu, 03 Aug 2006 08:49:48 GMT (35) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 11: Supported: replaces (19) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 13: Content-Length: 205 (19) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4471 parse_request: Header 14: (0) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: v=0 (3) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: o=root 27236 27236 IN IP4 81.171.226.203 (40) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: s=session (9) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: c=IN IP4 81.171.226.203 (23) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: t=0 0 (5) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: m=audio 16790 RTP/AVP 0 101 (27) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: a=fmtp:101 0-16 (15) [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:4503 parse_request: Line: a=sendrecv (10) Reliably Transmitting (NAT) to 81.171.226.200:61537: INVITE sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport From: "device" ;tag=as12885efe To: Contact: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 102 INVITE User-Agent: AuPix PBX Max-Forwards: 70 Date: Thu, 03 Aug 2006 08:49:48 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 205 v=0 o=root 27236 27236 IN IP4 81.171.226.203 s=session c=IN IP4 81.171.226.203 t=0 0 m=audio 16790 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv --- [Aug 3 09:49:48] DEBUG[28568]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #556 -- Called 3060 [Aug 3 09:49:48] DEBUG[28568]: channel.c:2206 ast_indicate_data: Driver for channel 'SIP/3062-087758f8' does not support indication 3, emulating it [Aug 3 09:49:48] DEBUG[28568]: channel.c:2755 set_format: Set channel SIP/3062-087758f8 to write format slin [Aug 3 09:49:48] DEBUG[28568]: channel.c:1827 ast_settimeout: Scheduling timer at 160 sample intervals [Aug 3 09:49:48] DEBUG[28568]: channel.c:2107 __ast_read: Generator got voice, switching to phase locked mode [Aug 3 09:49:48] DEBUG[28568]: channel.c:1827 ast_settimeout: Scheduling timer at 0 sample intervals AstDev*CLI> <-- SIP read from 10.1.7.25:5060: SIP/2.0 400 Bad request To: ;tag=HTD5KbkluTUfmRK3 Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK06c4df73;rport=5060;received=10.1.1.9 From: "device" ;tag=as519bc400 Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 103 NOTIFY User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 400 Bad request (23) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: ;tag=HTD5KbkluTUfmRK3 (59) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: Contact: (43) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK06c4df73;rport=5060;received=10.1.1.9 (82) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: From: "device" ;tag=as519bc400 (55) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 103 NOTIFY (16) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Content-Length: 0 (17) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #553 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203' of Request 103: Match Not Found -- Got SIP response 400 "Bad request" back from 10.1.7.25 [Aug 3 09:49:48] DEBUG[28573]: app_queue.c:537 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.25:5060: SIP/2.0 200 Ok To: ;tag=HTD5KbkluTUfmRK3 Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK6cb03c3c;rport=5060;received=10.1.1.9 From: "device" ;tag=as519bc400 Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 104 NOTIFY User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: ;tag=HTD5KbkluTUfmRK3 (59) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: Contact: (43) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK6cb03c3c;rport=5060;received=10.1.1.9 (82) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: From: "device" ;tag=as519bc400 (55) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 104 NOTIFY (16) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Content-Length: 0 (17) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #554 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203' of Request 104: Match Not Found Really destroying SIP dialog '60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203' Method: REFER <-- SIP read from 10.1.7.25:5060: BYE sip:3062@10.1.1.9 SIP/2.0 To: device ;tag=as519bc400 From: ;tag=HTD5KbkluTUfmRK3 Contact: CSeq: 4 BYE Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-nm99kALoPFL;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: BYE sip:3062@10.1.1.9 SIP/2.0 (29) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: device ;tag=as519bc400 (51) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=HTD5KbkluTUfmRK3 (61) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Contact: (43) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: CSeq: 4 BYE (11) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 (56) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-nm99kALoPFL;rport (64) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 - BYE (No RTP) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 10.1.7.25 : 5060 (NAT) 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-nm99kALoPFL;received=10.1.7.25;rport=5060 From: ;tag=HTD5KbkluTUfmRK3 To: device ;tag=as519bc400 Call-ID: 60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203 CSeq: 4 BYE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- Really destroying SIP dialog '60639c797a2e66ee1b55fa2c350b6df0@81.171.226.203' Method: BYE [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:1840 retrans_pkt: SIP TIMER: Rescheduling retransmission #556 (1) INVITE - 5 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:1854 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 200 ms (t1 100 ms (Retrans id #556)) Retransmitting #1 (NAT) to 81.171.226.200:61537: INVITE sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport From: "device" ;tag=as12885efe To: Contact: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 102 INVITE User-Agent: AuPix PBX Max-Forwards: 70 Date: Thu, 03 Aug 2006 08:49:48 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 205 v=0 o=root 27236 27236 IN IP4 81.171.226.203 s=session c=IN IP4 81.171.226.203 t=0 0 m=audio 16790 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv --- AstDev*CLI> <-- SIP read from 81.171.226.200:61537: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport=5060 From: "device" ;tag=as12885efe To: ;tag=tm2uy195es Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 102 INVITE Contact: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport=5060 (70) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "device" ;tag=as12885efe (55) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: ;tag=tm2uy195es (58) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 (56) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 102 INVITE (16) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Contact: (48) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:2081 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #556 - INVITE (got response) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:2090 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '233b783415e319316e0e938c1d73de68@81.171.226.203' Request 102: Found [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:11730 handle_response_invite: SIP response 180 to standard invite [Aug 3 09:49:48] DEBUG[27304]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3060-0878b900 -- SIP/3060-0878b900 is ringing [Aug 3 09:49:48] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 3 09:49:48] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3060 [Aug 3 09:49:48] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3060 - state 1 (Not in use) [Aug 3 09:49:48] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 3 09:49:48] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3060 [Aug 3 09:49:48] DEBUG[28574]: app_queue.c:537 changethread: Device 'SIP/3060' 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 81.171.226.200:61537: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport=5060 From: "device" ;tag=as12885efe To: ;tag=tm2uy195es Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 102 INVITE Contact: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport=5060 (70) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "device" ;tag=as12885efe (55) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: ;tag=tm2uy195es (58) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 (56) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 102 INVITE (16) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Contact: (48) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:2090 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '233b783415e319316e0e938c1d73de68@81.171.226.203' Request 102: Found [Aug 3 09:49:48] DEBUG[27304]: chan_sip.c:11730 handle_response_invite: SIP response 180 to standard invite -- SIP/3060-0878b900 is ringing AstDev*CLI> <-- SIP read from 81.171.226.200:61537: SIP/2.0 180 Ringing Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport=5060 From: "device" ;tag=as12885efe To: ;tag=tm2uy195es Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 102 INVITE Contact: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport=5060 (70) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "device" ;tag=as12885efe (55) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: ;tag=tm2uy195es (58) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 (56) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 102 INVITE (16) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Contact: (48) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:2090 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '233b783415e319316e0e938c1d73de68@81.171.226.203' Request 102: Found [Aug 3 09:49:49] DEBUG[27304]: chan_sip.c:11730 handle_response_invite: SIP response 180 to standard invite -- SIP/3060-0878b900 is ringing [Aug 3 09:49:49] DEBUG[28568]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes AstDev*CLI> <-- SIP read from 81.171.226.200:61537: SIP/2.0 200 Ok Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport=5060 From: "device" ;tag=as12885efe To: ;tag=tm2uy195es Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 102 INVITE Contact: User-Agent: snom360/4.4 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: 280 v=0 o=root 1776684735 1776684736 IN IP4 10.1.1.15 s=call c=IN IP4 10.1.1.15 t=0 0 m=audio 57376 RTP/AVP 0 101 k=base64:l6YjJRuneDEnedXX14oqqubhYWa9oW3XNB2LVjrSWKM= a=rtpmap:0 pcmu/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=encryption:optional a=sendrecv [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK17c21c4a;rport=5060 (70) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "device" ;tag=as12885efe (55) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: ;tag=tm2uy195es (58) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 (56) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 102 INVITE (16) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Contact: (48) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: snom360/4.4 (23) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Allow-Events: talk, hold, refer (31) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Supported: timer, 100rel, replaces, callerid (44) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Content-Type: application/sdp (29) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: Content-Length: 280 (19) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 13: (0) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: v=0 (3) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: o=root 1776684735 1776684736 IN IP4 10.1.1.15 (45) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: s=call (6) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: c=IN IP4 10.1.1.15 (18) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: t=0 0 (5) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: m=audio 57376 RTP/AVP 0 101 (27) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: k=base64:l6YjJRuneDEnedXX14oqqubhYWa9oW3XNB2LVjrSWKM= (53) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=fmtp:101 0-15 (15) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=encryption:optional (21) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:4503 parse_request: Line: a=sendrecv (10) --- (13 headers 12 lines)--- [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:2030 __sip_ack: Acked pending invite 102 [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '233b783415e319316e0e938c1d73de68@81.171.226.203' of Request 102: Match Not Found [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:11730 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Peer audio RTP is at port 10.1.1.15:57376 Found description format pcmu for ID 0 Found description format telephone-event for ID 101 [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:5303 process_sdp: T38 state changed to 0 on channel SIP/3060-0878b900 Haven't got any video bitrates set Capabilities: us - 0x280004 (ulaw|h263|h264), peer - audio=0x4 (ulaw)/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.1.15:57376 [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:5414 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:5421 process_sdp: We have an owner, now see if we need to change this call [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:2935 update_call_counter: Updating call counter for outgoing call [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:8151 build_route: build_route: Contact hop: list_route: hop: [Aug 3 09:49:50] DEBUG[27304]: chan_sip.c:5854 reqprep: Strict routing enforced for session 233b783415e319316e0e938c1d73de68@81.171.226.203 set_destination: Parsing for address/port to send to set_destination: set destination to 10.1.1.15, port 2051 Transmitting (NAT) to 81.171.226.200:61537: ACK sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK309b6595;rport From: "device" ;tag=as12885efe To: ;tag=tm2uy195es Contact: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 102 ACK User-Agent: AuPix PBX Max-Forwards: 70 Content-Length: 0 --- -- Call on SIP/3060-0878b900 is indicating caps [Aug 3 09:49:50] DEBUG[28568]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3060-0878b900 -- SIP/3060-0878b900 answered SIP/3062-087758f8 [Aug 3 09:49:50] DEBUG[28568]: channel.c:2755 set_format: Set channel SIP/3062-087758f8 to write format ulaw [Aug 3 09:49:50] DEBUG[28568]: channel.c:1827 ast_settimeout: Scheduling timer at 0 sample intervals [Aug 3 09:49:50] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 3 09:49:50] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3060 [Aug 3 09:49:50] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3060 - state 1 (Not in use) [Aug 3 09:49:50] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 3 09:49:50] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3060 [Aug 3 09:49:50] DEBUG[28575]: app_queue.c:537 changethread: Device 'SIP/3060' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 3 09:49:50] DEBUG[28568]: rtp.c:2341 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 3 09:49:51] DEBUG[27368]: manager.c:1808 process_message: Manager received command 'Ping' [Aug 3 09:49:51] DEBUG[28568]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes [Aug 3 09:49:51] NOTICE[28568]: rtp.c:678 process_rfc3389: Comfort noise support incomplete in Asterisk (RFC 3389). Please turn off on client if possible. Client IP: 10.1.1.15 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: OPTIONS sip:3063@10.1.3.10;line=10.1.1.9 SIP/2.0 (48) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK1a798cce;rport (59) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "Unknown" ;tag=as387dd0a5 (59) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: (38) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Contact: (31) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 1c6fd17e68ed83514e378e1222d276ab@81.171.226.203 (56) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Date: Thu, 03 Aug 2006 08:49:53 GMT (35) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Supported: replaces (19) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 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=z9hG4bK1a798cce;rport From: "Unknown" ;tag=as387dd0a5 To: Contact: Call-ID: 1c6fd17e68ed83514e378e1222d276ab@81.171.226.203 CSeq: 102 OPTIONS User-Agent: AuPix PBX Max-Forwards: 70 Date: Thu, 03 Aug 2006 08:49:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #559 AstDev*CLI> <-- SIP read from 10.1.3.10:5060: SIP/2.0 200 Ok To: From: "Unknown" ;tag=as387dd0a5 Call-ID: 1c6fd17e68ed83514e378e1222d276ab@81.171.226.203 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK1a798cce;rport=5060;received=10.1.1.9 CSeq: 102 OPTIONS Contact: User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: (38) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "Unknown" ;tag=as387dd0a5 (59) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Call-ID: 1c6fd17e68ed83514e378e1222d276ab@81.171.226.203 (56) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK1a798cce;rport=5060;received=10.1.1.9 (82) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Contact: (24) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Content-Length: 0 (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #559 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '1c6fd17e68ed83514e378e1222d276ab@81.171.226.203' of Request 102: Match Not Found Really destroying SIP dialog '1c6fd17e68ed83514e378e1222d276ab@81.171.226.203' Method: OPTIONS [Aug 3 09:49:53] DEBUG[28568]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes AstDev*CLI> <-- SIP read from 81.171.226.200:61537: BYE sip:3062@81.171.226.203 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6cek67fapj86;rport From: ;tag=tm2uy195es To: "device" ;tag=as12885efe Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 1 BYE Max-Forwards: 70 Contact: User-Agent: snom360/4.4 Content-Length: 0 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: BYE sip:3062@81.171.226.203 SIP/2.0 (35) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6cek67fapj86;rport (65) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=tm2uy195es (60) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: "device" ;tag=as12885efe (53) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 (56) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 1 BYE (11) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Max-Forwards: 70 (16) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: Contact: (48) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: User-Agent: snom360/4.4 (23) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 81.171.226.200 : 61537 (NAT) Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6cek67fapj86;received=81.171.226.200;rport=61537 From: ;tag=tm2uy195es To: "device" ;tag=as12885efe Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 1 BYE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Aug 3 09:49:53] DEBUG[28568]: channel.c:3702 ast_generic_bridge: Didn't get a frame from channel: SIP/3060-0878b900 [Aug 3 09:49:53] DEBUG[28568]: channel.c:3989 ast_channel_bridge: Bridge stops bridging channels SIP/3062-087758f8 and SIP/3060-0878b900 [Aug 3 09:49:53] DEBUG[28568]: channel.c:1527 ast_hangup: Hanging up channel 'SIP/3060-0878b900' [Aug 3 09:49:53] DEBUG[28568]: chan_sip.c:3236 sip_hangup: Hangup call SIP/3060-0878b900, SIP callid 233b783415e319316e0e938c1d73de68@81.171.226.203) [Aug 3 09:49:53] DEBUG[28568]: chan_sip.c:3244 sip_hangup: update_call_counter(3060) - decrement call limit counter on hangup [Aug 3 09:49:53] DEBUG[28568]: chan_sip.c:2935 update_call_counter: Updating call counter for outgoing call [Aug 3 09:49:53] DEBUG[28568]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3060-0878b900 [Aug 3 09:49:53] DEBUG[28568]: rtp.c:1307 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Aug 3 09:49:53] DEBUG[28568]: app_dial.c:1636 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Aug 3 09:49:53] DEBUG[28568]: app_macro.c:221 macro_exec: Spawn extension (macro-dial,s,6) exited non-zero on 'SIP/3062-087758f8' in macro 'dial' [Aug 3 09:49:53] DEBUG[28568]: app_macro.c:221 macro_exec: Spawn extension (macro-dial,s,6) exited non-zero on 'SIP/3062-087758f8' in macro 'exten-vm' [Aug 3 09:49:53] DEBUG[28568]: pbx.c:2271 __ast_pbx_run: Spawn extension (macro-dial,s,6) exited non-zero on 'SIP/3062-087758f8' [Aug 3 09:49:53] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 3 09:49:53] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3060 [Aug 3 09:49:53] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3060 - state 1 (Not in use) [Aug 3 09:49:53] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 3 09:49:53] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3060 [Aug 3 09:49:53] DEBUG[28576]: app_queue.c:537 changethread: Device 'SIP/3060' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Aug 3 09:49:53] DEBUG[28568]: channel.c:1527 ast_hangup: Hanging up channel 'SIP/3062-087758f8' [Aug 3 09:49:53] DEBUG[28568]: chan_sip.c:3236 sip_hangup: Hangup call SIP/3062-087758f8, SIP callid mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local) [Aug 3 09:49:53] DEBUG[28568]: chan_sip.c:3244 sip_hangup: update_call_counter(3062) - decrement call limit counter on hangup [Aug 3 09:49:53] DEBUG[28568]: chan_sip.c:2935 update_call_counter: Updating call counter for incoming call [Aug 3 09:49:53] DEBUG[28568]: chan_sip.c:5854 reqprep: Strict routing enforced for session mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local set_destination: Parsing for address/port to send to set_destination: set destination to 10.1.7.70, port 5060 Reliably Transmitting (NAT) to 10.1.7.70:5060: BYE sip:3062@10.1.7.70;line=10.1.1.9 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK04296439;rport From: ;tag=as2b902122 To: ;tag=Ua3Zy8eBIrchli0u Contact: Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local CSeq: 102 BYE User-Agent: AuPix PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 3 09:49:53] DEBUG[28568]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #562 [Aug 3 09:49:53] DEBUG[28568]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-087758f8 [Aug 3 09:49:53] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 3 09:49:53] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3062 [Aug 3 09:49:53] DEBUG[27295]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 3 09:49:53] DEBUG[27295]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 3 09:49:53] DEBUG[27295]: chan_sip.c:15120 sip_devicestate: Checking device state for peer 3062 [Aug 3 09:49:53] DEBUG[28577]: app_queue.c:543 changethread: Device 'SIP/3062' changed to state '1' (Not in use) AstDev*CLI> <-- SIP read from 10.1.7.70:5060: SIP/2.0 200 Ok To: ;tag=Ua3Zy8eBIrchli0u Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK04296439;rport=5060;received=10.1.1.9 From: ;tag=as2b902122 Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local CSeq: 102 BYE User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: ;tag=Ua3Zy8eBIrchli0u (44) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: Contact: (43) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK04296439;rport=5060;received=10.1.1.9 (82) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: From: ;tag=as2b902122 (40) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local (64) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 BYE (13) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Content-Length: 0 (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #562 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on 'mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '233b783415e319316e0e938c1d73de68@81.171.226.203' Method: BYE Really destroying SIP dialog 'mVRcUcupSA-Cn-PTLdP_ugeCaZwSgA~k@videophone.aupix.local' Method: ACK [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: OPTIONS sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 (53) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK4f6c384c;rport (65) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "Unknown" ;tag=as039d3162 (59) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: (43) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Contact: (37) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 39b581785cf138503a912da767236e3b@81.171.226.203 (56) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Date: Thu, 03 Aug 2006 08:49:53 GMT (35) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Supported: replaces (19) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 81.171.226.200:61537: OPTIONS sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK4f6c384c;rport From: "Unknown" ;tag=as039d3162 To: Contact: Call-ID: 39b581785cf138503a912da767236e3b@81.171.226.203 CSeq: 102 OPTIONS User-Agent: AuPix PBX Max-Forwards: 70 Date: Thu, 03 Aug 2006 08:49:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #563 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: OPTIONS sip:3040@10.1.2.11;line=10.1.1.9 SIP/2.0 (48) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK5148f685;rport (59) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "Unknown" ;tag=as33c6d0c8 (59) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: (38) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Contact: (31) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: Call-ID: 2eba100910e8f5ea2e650e1060cf372b@81.171.226.203 (56) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Date: Thu, 03 Aug 2006 08:49:53 GMT (35) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Supported: replaces (19) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 10.1.2.11:5060: OPTIONS sip:3040@10.1.2.11;line=10.1.1.9 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK5148f685;rport From: "Unknown" ;tag=as33c6d0c8 To: Contact: Call-ID: 2eba100910e8f5ea2e650e1060cf372b@81.171.226.203 CSeq: 102 OPTIONS User-Agent: AuPix PBX Max-Forwards: 70 Date: Thu, 03 Aug 2006 08:49:53 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:1945 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #565 AstDev*CLI> <-- SIP read from 10.1.2.11:5060: SIP/2.0 200 Ok To: From: "Unknown" ;tag=as33c6d0c8 Call-ID: 2eba100910e8f5ea2e650e1060cf372b@81.171.226.203 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK5148f685;rport=5060;received=10.1.1.9 CSeq: 102 OPTIONS Contact: User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: To: (38) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "Unknown" ;tag=as33c6d0c8 (59) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: Call-ID: 2eba100910e8f5ea2e650e1060cf372b@81.171.226.203 (56) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK5148f685;rport=5060;received=10.1.1.9 (82) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Contact: (24) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Content-Length: 0 (17) [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #565 [Aug 3 09:49:53] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '2eba100910e8f5ea2e650e1060cf372b@81.171.226.203' of Request 102: Match Not Found Really destroying SIP dialog '2eba100910e8f5ea2e650e1060cf372b@81.171.226.203' Method: OPTIONS AstDev*CLI> <-- SIP read from 81.171.226.200:61537: BYE sip:3062@81.171.226.203 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6cek67fapj86;rport From: ;tag=tm2uy195es To: "device" ;tag=as12885efe Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 1 BYE Max-Forwards: 70 Contact: User-Agent: snom360/4.4 Content-Length: 0 [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: BYE sip:3062@81.171.226.203 SIP/2.0 (35) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6cek67fapj86;rport (65) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: ;tag=tm2uy195es (60) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: "device" ;tag=as12885efe (53) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 (56) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 1 BYE (11) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Max-Forwards: 70 (16) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: Contact: (48) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: User-Agent: snom360/4.4 (23) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Content-Length: 0 (17) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4251 sip_alloc: Allocating new SIP dialog for 233b783415e319316e0e938c1d73de68@81.171.226.203 - BYE (No RTP) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:14556 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 81.171.226.200 : 61537 (NAT) Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-6cek67fapj86;received=81.171.226.200;rport=61537 From: ;tag=tm2uy195es To: "device" ;tag=as12885efe Call-ID: 233b783415e319316e0e938c1d73de68@81.171.226.203 CSeq: 1 BYE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- Really destroying SIP dialog '233b783415e319316e0e938c1d73de68@81.171.226.203' Method: BYE <-- SIP read from 81.171.226.200:61537: SIP/2.0 200 OK Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK4f6c384c;rport=5060 From: "Unknown" ;tag=as039d3162 To: Call-ID: 39b581785cf138503a912da767236e3b@81.171.226.203 CSeq: 102 OPTIONS Contact: User-Agent: snom360/4.4 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 [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 0: SIP/2.0 200 OK (14) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 1: Via: SIP/2.0/UDP 81.171.226.203:5060;branch=z9hG4bK4f6c384c;rport=5060 (70) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 2: From: "Unknown" ;tag=as039d3162 (59) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 3: To: (43) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 4: Call-ID: 39b581785cf138503a912da767236e3b@81.171.226.203 (56) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 5: CSeq: 102 OPTIONS (17) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 6: Contact: (48) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 7: User-Agent: snom360/4.4 (23) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 8: Accept-Language: en (19) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 9: Accept: application/sdp (23) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE,PRACK, MESSAGE, INFO (88) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 11: Allow-Events: talk, hold, refer (31) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 12: Supported: timer, 100rel, replaces, callerid (44) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 13: Content-Length: 0 (17) [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:4471 parse_request: Header 14: (0) --- (14 headers 0 lines)--- [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:2038 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #563 [Aug 3 09:49:54] DEBUG[27304]: chan_sip.c:2048 __sip_ack: Stopping retransmission on '39b581785cf138503a912da767236e3b@81.171.226.203' of Request 102: Match Not Found Really destroying SIP dialog '39b581785cf138503a912da767236e3b@81.171.226.203' Method: OPTIONS [Aug 3 09:49:56] DEBUG[27304]: chan_sip.c:1977 __sip_autodestruct: Auto destroying call '3c392bf4900b-we9xndha0f3l@snom360' [Aug 3 09:49:56] DEBUG[27304]: chan_sip.c:3041 sip_destroy: Destroying SIP dialog 3c392bf4900b-we9xndha0f3l@snom360 Really destroying SIP dialog '3c392bf4900b-we9xndha0f3l@snom360' Method: REGISTER [Aug 3 09:49:58] DEBUG[27354]: manager.c:1808 process_message: Manager received command 'Command' [Aug 3 09:49:58] DEBUG[27354]: manager.c:1808 process_message: Manager received command 'Command' [Aug 3 09:49:58] DEBUG[27354]: manager.c:1808 process_message: Manager received command 'Command' AstDev*CLI> set debug 0 Core debug is now OFF AstDev*CLI> set verbose 3 Verbosity was 4 and is now 3 AstDev*CLI> <-- SIP read from 81.171.226.200:61537: REGISTER sip:81.171.226.203 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-ciuiyat9s0l7;rport From: "AstDev3060" ;tag=1febamafgi To: "AstDev3060" Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316686 REGISTER Max-Forwards: 70 Contact: ;q=1.0;+sip.instance="";audio;mobility="fixed";duplex="full";description="snom360";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO" User-Agent: snom360/4.4 Supported: gruu Allow-Events: dialog X-Real-IP: 10.1.1.15 WWW-Contact: WWW-Contact: Expires: 60 Content-Length: 0 --- (16 headers 0 lines)--- Using latest REGISTER request as basis request Sending to 81.171.226.200 : 61537 (NAT) Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-ciuiyat9s0l7;received=81.171.226.200;rport=61537 From: "AstDev3060" ;tag=1febamafgi To: "AstDev3060" Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316686 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-ciuiyat9s0l7;received=81.171.226.200;rport=61537 From: "AstDev3060" ;tag=1febamafgi To: "AstDev3060" ;tag=as69212e65 Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316686 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: WWW-Authenticate: Digest algorithm=MD5, realm="AuPixDev.aupix.com", nonce="1e2c9c55" Content-Length: 0 --- Scheduling destruction of SIP dialog '3c392bf4900b-we9xndha0f3l@snom360' in 32000 ms (Method: REGISTER) AstDev*CLI> <-- SIP read from 81.171.226.200:61537: REGISTER sip:81.171.226.203 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-iftlcnhu1jcc;rport From: "AstDev3060" ;tag=1febamafgi To: "AstDev3060" Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316687 REGISTER Max-Forwards: 70 Contact: ;q=1.0;+sip.instance="";audio;mobility="fixed";duplex="full";description="snom360";actor="principal";events="dialog";methods="INVITE,ACK,CANCEL,BYE,REFER,OPTIONS,NOTIFY,SUBSCRIBE,PRACK,MESSAGE,INFO" User-Agent: snom360/4.4 Supported: gruu Allow-Events: dialog X-Real-IP: 10.1.1.15 WWW-Contact: WWW-Contact: Authorization: Digest username="3060",realm="AuPixDev.aupix.com",nonce="1e2c9c55",uri="sip:81.171.226.203",response="025a07f93d3ba2b5cd268677a53f1a09",algorithm=md5 Expires: 60 Content-Length: 0 --- (17 headers 0 lines)--- Using latest REGISTER request as basis request Sending to 81.171.226.200 : 61537 (NAT) Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-iftlcnhu1jcc;received=81.171.226.200;rport=61537 From: "AstDev3060" ;tag=1febamafgi To: "AstDev3060" Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316687 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (NAT) to 81.171.226.200:61537: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-iftlcnhu1jcc;received=81.171.226.200;rport=61537 From: "AstDev3060" ;tag=1febamafgi To: "AstDev3060" ;tag=as69212e65 Call-ID: 3c392bf4900b-we9xndha0f3l@snom360 CSeq: 316687 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Thu, 03 Aug 2006 08:50:11 GMT Content-Length: 0 --- Scheduling destruction of SIP dialog '3c392bf4900b-we9xndha0f3l@snom360' in 15000 ms (Method: REGISTER) AstDev*CLI> sip no debug SIP Debugging Disabled [Aug 3 09:50:51] DEBUG[27368]: manager.c:1808 process_message: Manager received command 'Ping' [Aug 3 09:51:51] DEBUG[27368]: manager.c:1808 process_message: Manager received command 'Ping' [Aug 3 09:51:58] DEBUG[27354]: manager.c:1808 process_message: Manager received command 'Command' [Aug 3 09:51:58] DEBUG[27354]: manager.c:1808 process_message: Manager received command 'Command' [Aug 3 09:51:58] DEBUG[27354]: manager.c:1808 process_message: Manager received command 'Command' AstDev*CLI>