AstDev*CLI> set debug 4 Core debug was 0 and is now 4 [Aug 16 10:39:59] DEBUG[2029]: chan_sip.c:1935 __sip_autodestruct: Auto destroying call 'bMRsoddjKOgBWNvaEbhzqI_AqKsuBrzR@videophone.aupix.local' [Aug 16 10:39:59] DEBUG[2029]: chan_sip.c:2977 sip_destroy: Destroying SIP dialog bMRsoddjKOgBWNvaEbhzqI_AqKsuBrzR@videophone.aupix.local Really destroying SIP dialog 'bMRsoddjKOgBWNvaEbhzqI_AqKsuBrzR@videophone.aupix.local' Method: REGISTER AstDev*CLI> set verbose 4 Verbosity was 3 and is now 4 [Aug 16 10:40:04] DEBUG[2029]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) [Aug 16 10:40:04] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on '39ed9c3d48666d196486db1b719bc0d3@xx.yy.zz.203' of Request 102: Match Not Found Really destroying SIP dialog '39ed9c3d48666d196486db1b719bc0d3@xx.yy.zz.203' Method: NOTIFY AstDev*CLI> sip debug SIP Debugging enabled AstDev*CLI> <-- SIP read from 10.1.7.70:5060: INVITE sip:3061@10.1.1.9 SIP/2.0 To: From: ;tag=-vpAi1sHeGCfCxHH Contact: CSeq: 2 INVITE Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-OwsT2bc8Eb0;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 9 8 0 15 18 101 a=ptime:60 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: INVITE sip:3061@10.1.1.9 SIP/2.0 (32) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: (23) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: ;tag=-vpAi1sHeGCfCxHH (46) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Contact: (43) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: CSeq: 2 INVITE (14) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local (64) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-OwsT2bc8Eb0;rport (64) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Accept: application/sdp (23) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: Accept-Encoding: identity (25) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 11: Content-Length: 227 (19) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 13: (0) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: v=0 (3) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.70 (31) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: s=phone-call (12) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: u=http://www.AuPix.com (22) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: c=IN IP4 10.1.7.70 (18) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: b=CT:384 (8) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=sendrecv (10) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: m=audio 5000 RTP/AVP 9 8 0 15 18 101 (36) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=ptime:60 (10) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 12 lines)--- [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local - INVITE (With RTP) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.70 : 5060 (NAT) Using INVITE request as basis request - LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:8650 check_user_full: Setting NAT on RTP to On [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:8655 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-OwsT2bc8Eb0;received=10.1.7.70;rport=5060 From: ;tag=-vpAi1sHeGCfCxHH To: ;tag=as66eff9ad Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@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="78e98004" Content-Length: 0 --- [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:1903 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #56 Scheduling destruction of SIP dialog 'LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local' in 32000 ms (Method: INVITE) Found user '3062' AstDev*CLI> <-- SIP read from 10.1.7.70:5060: ACK sip:3061@10.1.1.9 SIP/2.0 To: ;tag=as66eff9ad From: ;tag=-vpAi1sHeGCfCxHH Contact: CSeq: 2 ACK Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-OwsT2bc8Eb0;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: ACK sip:3061@10.1.1.9 SIP/2.0 (29) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=as66eff9ad (38) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: ;tag=-vpAi1sHeGCfCxHH (46) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Contact: (43) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: CSeq: 2 ACK (11) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local (64) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-OwsT2bc8Eb0;rport (64) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:1996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #56 [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on 'LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@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=-vpAi1sHeGCfCxHH Contact: CSeq: 3 INVITE Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local Proxy-Authorization: Digest username="3062", realm="AuPixDev.aupix.com", nonce="78e98004", uri="sip:3061@10.1.1.9", response="56aa69908b9c1f1e7e273bcebc7f49b9", algorithm=md5 Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-pf1byBB00d2;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 9 8 0 15 18 101 a=ptime:60 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: INVITE sip:3061@10.1.1.9 SIP/2.0 (32) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: Max-Forwards: 70 (16) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Accept: application/sdp (23) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: Accept-Encoding: identity (25) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Content-Length: 227 (19) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Content-Type: application/sdp (29) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: To: (23) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: From: ;tag=-vpAi1sHeGCfCxHH (46) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Contact: (43) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: CSeq: 3 INVITE (14) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 11: Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local (64) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 12: Proxy-Authorization: Digest username="3062", realm="AuPixDev.aupix.com", nonce="78e98004", uri="sip:3061@10.1.1.9", response="56aa69908b9c1f1e7e273bcebc7f49b9", algorithm=md5 (174) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 13: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-pf1byBB00d2;rport (64) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 14: (0) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: v=0 (3) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.70 (31) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: s=phone-call (12) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: u=http://www.AuPix.com (22) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: c=IN IP4 10.1.7.70 (18) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: b=CT:384 (8) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=sendrecv (10) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: m=audio 5000 RTP/AVP 9 8 0 15 18 101 (36) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=ptime:60 (10) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-15 (15) --- (14 headers 12 lines)--- [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.70 : 5060 (NAT) Using INVITE request as basis request - LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:8650 check_user_full: Setting NAT on RTP to On [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:8655 check_user_full: Setting NAT on VRTP to On Found user '3062' Found RTP audio format 9 Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 15 Found RTP audio format 18 Found RTP audio format 101 Peer audio RTP is at port 10.1.7.70:5000 Got unsupported a:ptime in SDP offer Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4830 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 16 10:40:10] DEBUG[2029]: chan_sip.c:4900 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:12820 handle_request_invite: Checking SIP call limits for device 3062 [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:2871 update_call_counter: Updating call counter for incoming call Looking for 3061 in from-internal (domain 10.1.1.9) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:3600 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:3601 sip_new: *** Joint capabilities are 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:3602 sip_new: *** Our capabilities are 0x280004 (ulaw|h263|h264) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:3603 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:3626 sip_new: This channel will not be able to handle video. [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:7591 build_route: build_route: Contact hop: list_route: hop: [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:12890 handle_request_invite: SIP/3062-0a09b4c0: 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-pf1byBB00d2;received=10.1.7.70;rport=5060 From: ;tag=-vpAi1sHeGCfCxHH To: Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@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 16 10:40:10] DEBUG[2029]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-0a09b4c0 [Aug 16 10:40:10] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:10] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:10] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 16 10:40:10] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:10] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:10] DEBUG[2203]: app_queue.c:543 changethread: Device 'SIP/3062' changed to state '1' (Not in use) [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Macro' -- Executing [3061@from-internal:1] Macro("SIP/3062-0a09b4c0", "exten-vm|novm|3061") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:1] NoOp("SIP/3062-0a09b4c0", "CallerID(number) set to 3062") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:2] GotoIf("SIP/3062-0a09b4c0", "0?5") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:5616 pbx_builtin_gotoif: Not taking any branch [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:3] GotoIf("SIP/3062-0a09b4c0", "1?5") in new stack -- Goto (macro-exten-vm,s,5) [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:5] GotoIf("SIP/3062-0a09b4c0", "1?:7") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:5616 pbx_builtin_gotoif: Not taking any branch [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:6] Set("SIP/3062-0a09b4c0", "__VRSID=1155721210.0") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:7] Set("SIP/3062-0a09b4c0", "CDR(userfield)=1155721210.0") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:8] NoOp("SIP/3062-0a09b4c0", "SESSION ID IS SET TO: 1155721210.0") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:9] Macro("SIP/3062-0a09b4c0", "user-callerid") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:1] Set("SIP/3062-0a09b4c0", "AMPUSER=3062") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is 'Desk2' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:2] Set("SIP/3062-0a09b4c0", "AMPUSERCIDNAME=Desk2") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:3] GotoIf("SIP/3062-0a09b4c0", "0?5") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:5616 pbx_builtin_gotoif: Not taking any branch [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:4] Set("SIP/3062-0a09b4c0", "CALLERID(number)=3062") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:5] Set("SIP/3062-0a09b4c0", "CALLERID(name)=Desk2") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is 'Desk2' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-user-callerid:6] NoOp("SIP/3062-0a09b4c0", "Using CallerID(number) 3062 and CallerID(name) Desk2") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:10] Set("SIP/3062-0a09b4c0", "FROMCONTEXT=exten-vm") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:11] Macro("SIP/3062-0a09b4c0", "record-enable|3061|IN") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '0' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-record-enable:1] GotoIf("SIP/3062-0a09b4c0", "0 > 0?2:4") in new stack -- Goto (macro-record-enable,s,4) [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-record-enable:4] AGI("SIP/3062-0a09b4c0", "recordingcheck||1155721210.0") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck recordingcheck||1155721210.0: Inbound recording not enabled -- AGI Script recordingcheck completed, returning 0 [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-record-enable:5] NoOp("SIP/3062-0a09b4c0", "No recording needed") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:12] Macro("SIP/3062-0a09b4c0", "dial|600|tr|3061") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:1] Set("SIP/3062-0a09b4c0", "CDR(userfield)=1155721210.0") in new stack [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:2] GotoIf("SIP/3062-0a09b4c0", "0?5:3") in new stack -- Goto (macro-dial,s,3) [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '0' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is 'Desk2' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:3] GotoIf("SIP/3062-0a09b4c0", "0?6:5") in new stack -- Goto (macro-dial,s,5) [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-dial:5] AGI("SIP/3062-0a09b4c0", "dialparties.agi") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi -- dialparties.agi: priority = 5 -- dialparties.agi: callingani2 = 0 -- dialparties.agi: accountcode = -- dialparties.agi: channel = SIP/3062-0a09b4c0 -- dialparties.agi: callerid = 3062 -- dialparties.agi: context = macro-dial -- dialparties.agi: callington = 0 -- dialparties.agi: dnid = 3061 -- dialparties.agi: request = dialparties.agi -- dialparties.agi: calleridname = Desk2 -- dialparties.agi: extension = s -- dialparties.agi: language = en -- dialparties.agi: uniqueid = 1155721210.0 -- dialparties.agi: callingpres = 0 -- dialparties.agi: type = SIP -- dialparties.agi: rdnis = unknown -- dialparties.agi: callingtns = 0 -- dialparties.agi: enhanced = 0.0 dialparties.agi: Caller ID name and number are '3062' dialparties.agi: Methodology of ring is 'none' -- dialparties.agi: Added extension 3061 to extension map [Aug 16 10:40:10] DEBUG[2202]: db.c:197 ast_db_get: Unable to find key '3061' in family 'CF' -- dialparties.agi: Extension 3061 cf is disabled [Aug 16 10:40:10] DEBUG[2202]: db.c:197 ast_db_get: Unable to find key '3061' in family 'DND' -- dialparties.agi: Extension 3061 do not disturb is disabled [Aug 16 10:40:10] DEBUG[2202]: db.c:197 ast_db_get: Unable to find key '3061' in family 'CW' [Aug 16 10:40:10] DEBUG[2202]: db.c:197 ast_db_get: Unable to find key '3061' in family 'CFB' > dialparties.agi: extnum: 3061 > dialparties.agi: exthascw: 0 > dialparties.agi: exthascfb: 0 > dialparties.agi: extcfb: -- dialparties.agi: Checking CW and CFB status for extension 3061 [Aug 16 10:40:10] DEBUG[2206]: manager.c:1812 process_message: Manager received command 'Login' [Aug 16 10:40:10] DEBUG[2206]: config.c:723 config_text_file_load: Parsing /etc/asterisk/manager.conf [Aug 16 10:40:10] DEBUG[2206]: config.c:723 config_text_file_load: Parsing /etc/asterisk/manager_custom.conf [Aug 16 10:40:10] DEBUG[2206]: acl.c:199 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer [Aug 16 10:40:10] DEBUG[2206]: acl.c:199 ast_append_ha: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer [Aug 16 10:40:10] DEBUG[2206]: acl.c:199 ast_append_ha: 10.0.0.0/255.0.0.0/255.0.0.0 appended to acl for peer [Aug 16 10:40:10] DEBUG[2206]: acl.c:199 ast_append_ha: 82.32.33.81/255.255.255.255/255.255.255.255 appended to acl for peer [Aug 16 10:40:10] DEBUG[2206]: acl.c:213 ast_apply_ha: ##### Testing 127.0.0.1 with 0.0.0.0 [Aug 16 10:40:10] DEBUG[2206]: acl.c:213 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.0 [Aug 16 10:40:10] DEBUG[2206]: acl.c:213 ast_apply_ha: ##### Testing 127.0.0.1 with 10.0.0.0 [Aug 16 10:40:10] DEBUG[2206]: acl.c:213 ast_apply_ha: ##### Testing 127.0.0.1 with 82.32.33.81 == Manager 'admin' logged on from 127.0.0.1 -- dialparties.agi: Correct AMPMGRUSER and AMPMGRPASS [Aug 16 10:40:10] DEBUG[2206]: manager.c:1812 process_message: Manager received command 'ExtensionState' [Aug 16 10:40:10] DEBUG[2206]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:10] DEBUG[2206]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 [Aug 16 10:40:10] DEBUG[2206]: manager.c:1812 process_message: > dialparties.agi: extstate: 0 Manager received command 'Logoff' == Manager 'admin' logged off from 127.0.0.1 dialparties.agi: Extension 3061 is available...skipping checks -- dialparties.agi: DbSet CALLTRACE/3061 to 3062 -- AGI Script dialparties.agi completed, returning 0 [Aug 16 10:40:10] DEBUG[2202]: pbx.c:1680 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial:10] Dial("SIP/3062-0a09b4c0", "SIP/3061|600|tr") in new stack [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:14649 sip_request_call: Asked to create a SIP channel with formats: 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:2512 create_addr_from_peer: Setting NAT on RTP to Off [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:2518 create_addr_from_peer: Setting NAT on VRTP to Off [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:3600 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:3601 sip_new: *** Joint capabilities are 0x0 (nothing) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:3602 sip_new: *** Our capabilities are 0x280004 (ulaw|h263|h264) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:3603 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:3605 sip_new: *** Our preferred formats from the incoming channel are 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:3626 sip_new: This channel will not be able to handle video. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-10. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable AGISTATUS. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable ds. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-5. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-3. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-2. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-dial-s-1. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable ARG3. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable ARG2. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable ARG1. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-12. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-5. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-4. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-record-enable-s-1. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-11. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable FROMCONTEXT. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-10. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-6. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-5. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-4. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-3. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable AMPUSERCIDNAME. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-2. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable DB_RESULT. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable AMPUSER. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-user-callerid-s-1. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-9. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-8. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-7. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3008 ast_channel_inherit_variables: Copying hard-transferable variable VRSID. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-6. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-5. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-3. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-2. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-macro-exten-vm-s-1. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable STACK-from-internal-3061-1. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Aug 16 10:40:10] DEBUG[2202]: channel.c:3013 ast_channel_inherit_variables: Not copying variable SIPURI. [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:2710 sip_call: Outgoing Call for 3061 [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:2871 update_call_counter: Updating call counter for outgoing call [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:2718 sip_call: Our T38 capability (0), joint T38 capability (0) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:5809 add_sdp: ** Our capability: 0x280004 (ulaw|h263|h264) Video flag: False [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:5810 add_sdp: ** Our prefcodec: 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:5823 add_sdp: This call needs video offers! Video is at 10.1.1.9 port 14356 [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:5859 add_sdp: ** No compatible video codecs... Disabling video. Audio is at 10.1.1.9 port 12834 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:5962 add_sdp: -- Done with adding codecs to SDP [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:6001 add_sdp: Done building SDP. Settling with this capability: 0x4 (ulaw) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 0: INVITE sip:3061@10.1.7.25;line=10.1.1.9 SIP/2.0 (47) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7ceead7b;rport (59) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 2: From: "Desk2" ;tag=as5bc489e4 (54) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 3: To: (38) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 4: Contact: (28) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 5: Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 (56) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 9: Date: Wed, 16 Aug 2006 09:40:10 GMT (35) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 11: Supported: replaces (19) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 13: Content-Length: 218 (19) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4325 parse_request: Header 14: (0) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: v=0 (3) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: o=root 1978 1978 IN IP4 10.1.1.9 (32) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: s=session (9) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: c=IN IP4 10.1.1.9 (17) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: m=audio 12834 RTP/AVP 0 101 (27) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-16 (15) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 parse_request: Line: a=silenceSupp:off - - - - (25) [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:4357 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=z9hG4bK7ceead7b;rport From: "Desk2" ;tag=as5bc489e4 To: Contact: Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 CSeq: 102 INVITE User-Agent: AuPix PBX Max-Forwards: 70 Date: Wed, 16 Aug 2006 09:40:10 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 218 v=0 o=root 1978 1978 IN IP4 10.1.1.9 s=session c=IN IP4 10.1.1.9 t=0 0 m=audio 12834 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 16 10:40:10] DEBUG[2202]: chan_sip.c:1903 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #58 -- 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-pf1byBB00d2;received=10.1.7.70;rport=5060 From: ;tag=-vpAi1sHeGCfCxHH To: ;tag=as6a82ca5e Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@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=cDMzQfndpPV1f6dI Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7ceead7b;rport=5060;received=10.1.1.9 From: "Desk2" ;tag=as5bc489e4 Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 CSeq: 102 INVITE User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=cDMzQfndpPV1f6dI (59) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: Contact: (43) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7ceead7b;rport=5060;received=10.1.1.9 (82) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: From: "Desk2" ;tag=as5bc489e4 (54) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 (56) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Content-Length: 0 (17) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:2039 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #58 - INVITE (got response) [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:2048 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203' Request 102: Found [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:11178 handle_response_invite: SIP response 180 to standard invite [Aug 16 10:40:10] DEBUG[2029]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061-0a0aa6c0 [Aug 16 10:40:10] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:10] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 [Aug 16 10:40:10] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 1 (Not in use) [Aug 16 10:40:10] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:10] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 -- SIP/3061-0a0aa6c0 is ringing [Aug 16 10:40:10] DEBUG[2207]: 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 16 10:40:10] DEBUG[2029]: chan_sip.c:1935 __sip_autodestruct: Auto destroying call '3c8554b588b8-phg18hxi61bi@snom360' [Aug 16 10:40:10] DEBUG[2029]: chan_sip.c:2977 sip_destroy: Destroying SIP dialog 3c8554b588b8-phg18hxi61bi@snom360 Really destroying SIP dialog '3c8554b588b8-phg18hxi61bi@snom360' Method: REGISTER AstDev*CLI> <-- SIP read from 10.1.7.25:5060: SIP/2.0 200 Ok To: ;tag=cDMzQfndpPV1f6dI Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7ceead7b;rport=5060;received=10.1.1.9 From: "Desk2" ;tag=as5bc489e4 Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.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 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=cDMzQfndpPV1f6dI (59) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: Contact: (43) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK7ceead7b;rport=5060;received=10.1.1.9 (82) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: From: "Desk2" ;tag=as5bc489e4 (54) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 (56) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: CSeq: 102 INVITE (16) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Content-Length: 214 (19) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Content-Type: application/sdp (29) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: (0) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: v=0 (3) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.25 (31) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: s=phone-call (12) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: u=http://www.AuPix.com (22) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: c=IN IP4 10.1.7.25 (18) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: b=CT:64 (7) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=sendrecv (10) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: m=audio 5000 RTP/AVP 0 101 9 8 15 18 (36) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-15 (15) --- (10 headers 11 lines)--- [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:1988 __sip_ack: Acked pending invite 102 [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on '49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203' of Request 102: Match Not Found [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:11178 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 0 Found RTP audio format 101 Found RTP audio format 9 Found RTP audio format 8 Found RTP audio format 15 Found RTP audio format 18 Peer audio RTP is at port 10.1.7.25:5000 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4830 process_sdp: T38 state changed to 0 on channel SIP/3061-0a0aa6c0 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 Peer video RTP is at port 10.1.7.25:2314 [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4900 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4907 process_sdp: We have an owner, now see if we need to change this call [Aug 16 10:40:12] DEBUG[2029]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061 [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:2871 update_call_counter: Updating call counter for outgoing call [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:7591 build_route: build_route: Contact hop: list_route: hop: [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:5340 reqprep: Strict routing enforced for session 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.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=z9hG4bK0794b054;rport From: "Desk2" ;tag=as5bc489e4 To: ;tag=cDMzQfndpPV1f6dI Contact: Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 CSeq: 102 ACK User-Agent: AuPix PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:12] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 8 (On Hold) [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:12] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 [Aug 16 10:40:12] DEBUG[2202]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061-0a0aa6c0 -- SIP/3061-0a0aa6c0 answered SIP/3062-0a09b4c0 [Aug 16 10:40:12] DEBUG[2202]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-0a09b4c0 [Aug 16 10:40:12] DEBUG[2202]: chan_sip.c:3311 sip_answer: SIP answering channel: SIP/3062-0a09b4c0 [Aug 16 10:40:12] DEBUG[2202]: chan_sip.c:5809 add_sdp: ** Our capability: 0x4 (ulaw) Video flag: True [Aug 16 10:40:12] DEBUG[2202]: chan_sip.c:5810 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 10.1.1.9 port 14660 Adding codec 0x4 (ulaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Aug 16 10:40:12] DEBUG[2202]: chan_sip.c:5962 add_sdp: -- Done with adding codecs to SDP [Aug 16 10:40:12] DEBUG[2202]: chan_sip.c:6001 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-pf1byBB00d2;received=10.1.7.70;rport=5060 From: ;tag=-vpAi1sHeGCfCxHH To: ;tag=as6a82ca5e Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@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: 218 v=0 o=root 1978 1978 IN IP4 10.1.1.9 s=session c=IN IP4 10.1.1.9 t=0 0 m=audio 14660 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=sendrecv --- [Aug 16 10:40:12] DEBUG[2202]: chan_sip.c:1903 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #60 [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:12] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 8 (On Hold) [Aug 16 10:40:12] DEBUG[2216]: app_queue.c:537 changethread: Device 'SIP/3061' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:12] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:12] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 16 10:40:12] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:12] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:12] DEBUG[2217]: app_queue.c:537 changethread: Device 'SIP/3061' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Aug 16 10:40:12] DEBUG[2218]: 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=as6a82ca5e From: ;tag=-vpAi1sHeGCfCxHH Contact: CSeq: 3 ACK Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-pf1byBB00d2;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: ACK sip:3061@10.1.1.9 SIP/2.0 (29) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=as6a82ca5e (38) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: ;tag=-vpAi1sHeGCfCxHH (46) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Contact: (43) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: CSeq: 3 ACK (11) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local (64) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-pf1byBB00d2;rport (64) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:1996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #60 [Aug 16 10:40:12] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on 'LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local' of Response 3: Match Not Found [Aug 16 10:40:13] DEBUG[2202]: rtp.c:2341 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 16 10:40:13] DEBUG[2202]: rtp.c:2341 ast_rtp_write: Ooh, format changed from unknown to ulaw [Aug 16 10:40:14] DEBUG[2202]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes [Aug 16 10:40:14] DEBUG[2202]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes [Aug 16 10:40:16] DEBUG[2202]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes [Aug 16 10:40:16] DEBUG[2202]: rtp.c:767 ast_rtcp_read: Got RTCP report of 84 bytes AstDev*CLI> <-- SIP read from 10.1.7.25:5060: BYE sip:3062@10.1.1.9 SIP/2.0 To: Desk2 ;tag=as5bc489e4 From: ;tag=cDMzQfndpPV1f6dI Contact: CSeq: 2 BYE Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-x2njbbmw0vp;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: BYE sip:3062@10.1.1.9 SIP/2.0 (29) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: Desk2 ;tag=as5bc489e4 (50) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: ;tag=cDMzQfndpPV1f6dI (61) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Contact: (43) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: CSeq: 2 BYE (11) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 (56) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.25:5060;branch=z9hG4bK-x2njbbmw0vp;rport (64) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:14007 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-x2njbbmw0vp;received=10.1.7.25;rport=5060 From: ;tag=cDMzQfndpPV1f6dI To: Desk2 ;tag=as5bc489e4 Call-ID: 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203 CSeq: 2 BYE User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [Aug 16 10:40:16] DEBUG[2202]: channel.c:3483 ast_generic_bridge: Didn't get a frame from channel: SIP/3061-0a0aa6c0 [Aug 16 10:40:16] DEBUG[2202]: channel.c:3777 ast_channel_bridge: Bridge stops bridging channels SIP/3062-0a09b4c0 and SIP/3061-0a0aa6c0 [Aug 16 10:40:16] DEBUG[2202]: channel.c:1519 ast_hangup: Hanging up channel 'SIP/3061-0a0aa6c0' [Aug 16 10:40:16] DEBUG[2202]: chan_sip.c:3172 sip_hangup: Hangup call SIP/3061-0a0aa6c0, SIP callid 49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203) [Aug 16 10:40:16] DEBUG[2202]: chan_sip.c:3180 sip_hangup: update_call_counter(3061) - decrement call limit counter on hangup [Aug 16 10:40:16] DEBUG[2202]: chan_sip.c:2871 update_call_counter: Updating call counter for outgoing call [Aug 16 10:40:16] DEBUG[2202]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3061-0a0aa6c0 [Aug 16 10:40:16] DEBUG[2202]: rtp.c:1307 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Aug 16 10:40:16] DEBUG[2202]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Aug 16 10:40:16] DEBUG[2202]: app_macro.c:244 _macro_exec: Spawn extension (macro-dial,s,10) exited non-zero on 'SIP/3062-0a09b4c0' in macro'dial' [Aug 16 10:40:16] DEBUG[2202]: app_macro.c:244 _macro_exec: Spawn extension (macro-dial,s,10) exited non-zero on 'SIP/3062-0a09b4c0' in macro'exten-vm' [Aug 16 10:40:16] DEBUG[2202]: pbx.c:2276 __ast_pbx_run: Spawn extension (macro-dial,s,10) exited non-zero on 'SIP/3062-0a09b4c0' [Aug 16 10:40:16] DEBUG[2202]: cdr_addon_mysql.c:208 mysql_log: cdr_mysql: inserting a CDR record. [Aug 16 10:40:16] DEBUG[2202]: cdr_addon_mysql.c:224 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2006-08-16 10:40:10','\"Desk2\" <3062>','3062','3061','from-internal', 'SIP/3062-0a09b4c0','SIP/3061-0a0aa6c0','Dial','SIP/3061|600|tr',6,4,'ANSWERED',3,'','1155721210.0') [Aug 16 10:40:16] DEBUG[2202]: channel.c:1519 ast_hangup: Hanging up channel 'SIP/3062-0a09b4c0' [Aug 16 10:40:16] DEBUG[2202]: chan_sip.c:3172 sip_hangup: Hangup call SIP/3062-0a09b4c0, SIP callid LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local) [Aug 16 10:40:16] DEBUG[2202]: chan_sip.c:3180 sip_hangup: update_call_counter(3062) - decrement call limit counter on hangup [Aug 16 10:40:16] DEBUG[2202]: chan_sip.c:2871 update_call_counter: Updating call counter for incoming call [Aug 16 10:40:16] DEBUG[2202]: chan_sip.c:5340 reqprep: Strict routing enforced for session LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@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=z9hG4bK5a52d714;rport From: ;tag=as6a82ca5e To: ;tag=-vpAi1sHeGCfCxHH Contact: Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local CSeq: 102 BYE User-Agent: AuPix PBX Max-Forwards: 70 Content-Length: 0 --- [Aug 16 10:40:16] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:16] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 [Aug 16 10:40:16] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3061 - state 8 (On Hold) [Aug 16 10:40:16] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:16] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 [Aug 16 10:40:16] DEBUG[2219]: app_queue.c:537 changethread: Device 'SIP/3061' changed to state '8' (On Hold) but we don't care because they're not a member of any queue. [Aug 16 10:40:16] DEBUG[2202]: chan_sip.c:1903 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #63 [Aug 16 10:40:16] DEBUG[2202]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-0a09b4c0 [Aug 16 10:40:16] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:16] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:16] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 16 10:40:16] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:16] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:16] DEBUG[2220]: 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=-vpAi1sHeGCfCxHH Contact: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK5a52d714;rport=5060;received=10.1.1.9 From: ;tag=as6a82ca5e Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local CSeq: 102 BYE User-Agent: AuPix/v1.01.11 Content-Length: 0 [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=-vpAi1sHeGCfCxHH (44) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: Contact: (43) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK5a52d714;rport=5060;received=10.1.1.9 (82) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: From: ;tag=as6a82ca5e (40) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local (64) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: CSeq: 102 BYE (13) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Content-Length: 0 (17) [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:1996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #63 [Aug 16 10:40:16] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on 'LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local' of Request 102: Match Not Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '49b5bdec496703cc66ed001239bae7b8@xx.yy.zz.203' Method: BYE Really destroying SIP dialog 'LnEElBwTzCDAMXeCZCZVX~HCNce+BdFD@videophone.aupix.local' Method: ACK AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> AstDev*CLI> <-- SIP read from 10.1.7.70:5060: INVITE sip:3061@10.1.1.9 SIP/2.0 To: From: ;tag=YAAN3b5CbAHb1B6K Contact: CSeq: 2 INVITE Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-Gt2EMCUDXdy;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 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: INVITE sip:3061@10.1.1.9 SIP/2.0 (32) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: (23) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: ;tag=YAAN3b5CbAHb1B6K (46) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Contact: (43) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: CSeq: 2 INVITE (14) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local (64) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-Gt2EMCUDXdy;rport (64) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Accept: application/sdp (23) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: Accept-Encoding: identity (25) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 11: Content-Length: 227 (19) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 12: Content-Type: application/sdp (29) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 13: (0) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: v=0 (3) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.70 (31) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: s=phone-call (12) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: u=http://www.AuPix.com (22) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: c=IN IP4 10.1.7.70 (18) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: b=CT:384 (8) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=sendrecv (10) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: m=audio 5000 RTP/AVP 18 15 8 0 9 101 (36) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=ptime:60 (10) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-15 (15) --- (13 headers 12 lines)--- [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local - INVITE (With RTP) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.70 : 5060 (NAT) Using INVITE request as basis request - smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:8650 check_user_full: Setting NAT on RTP to On [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:8655 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-Gt2EMCUDXdy;received=10.1.7.70;rport=5060 From: ;tag=YAAN3b5CbAHb1B6K To: ;tag=as16a06076 Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@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="7dbee13c" Content-Length: 0 --- [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:1903 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #64 Scheduling destruction of SIP dialog 'smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local' in 32000 ms (Method: INVITE) Found user '3062' AstDev*CLI> <-- SIP read from 10.1.7.70:5060: ACK sip:3061@10.1.1.9 SIP/2.0 To: ;tag=as16a06076 From: ;tag=YAAN3b5CbAHb1B6K Contact: CSeq: 2 ACK Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-Gt2EMCUDXdy;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: ACK sip:3061@10.1.1.9 SIP/2.0 (29) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=as16a06076 (38) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: ;tag=YAAN3b5CbAHb1B6K (46) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Contact: (43) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: CSeq: 2 ACK (11) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local (64) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-Gt2EMCUDXdy;rport (64) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:1996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #64 [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on 'smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local' of Response 2: Match Not Found <-- 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=YAAN3b5CbAHb1B6K Contact: CSeq: 3 INVITE Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local Proxy-Authorization: Digest username="3062", realm="AuPixDev.aupix.com", nonce="7dbee13c", uri="sip:3061@10.1.1.9", response="8550268fa751a9ab27ff672b7ed06fde", algorithm=md5 Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-kyPH3NwmEdY;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 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: INVITE sip:3061@10.1.1.9 SIP/2.0 (32) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: Max-Forwards: 70 (16) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Accept: application/sdp (23) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: Accept-Encoding: identity (25) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Content-Length: 227 (19) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Content-Type: application/sdp (29) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: To: (23) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: From: ;tag=YAAN3b5CbAHb1B6K (46) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Contact: (43) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: CSeq: 3 INVITE (14) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 11: Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local (64) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 12: Proxy-Authorization: Digest username="3062", realm="AuPixDev.aupix.com", nonce="7dbee13c", uri="sip:3061@10.1.1.9", response="8550268fa751a9ab27ff672b7ed06fde", algorithm=md5 (174) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 13: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-kyPH3NwmEdY;rport (64) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 14: (0) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: v=0 (3) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: o=AuPix 1001 0 IN IP4 10.1.7.70 (31) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: s=phone-call (12) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: u=http://www.AuPix.com (22) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: c=IN IP4 10.1.7.70 (18) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: b=CT:384 (8) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=sendrecv (10) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: m=audio 5000 RTP/AVP 18 15 8 0 9 101 (36) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=ptime:60 (10) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-15 (15) --- (14 headers 12 lines)--- [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 10.1.7.70 : 5060 (NAT) Using INVITE request as basis request - smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:8650 check_user_full: Setting NAT on RTP to On [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:8655 check_user_full: Setting NAT on VRTP to On Found user '3062' Found RTP audio format 18 Found RTP audio format 15 Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 9 Found RTP audio format 101 Peer audio RTP is at port 10.1.7.70:5000 Got unsupported a:ptime in SDP offer Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:4830 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 16 10:40:23] DEBUG[2029]: chan_sip.c:4900 process_sdp: We're settling with these formats: 0x4 (ulaw) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:12820 handle_request_invite: Checking SIP call limits for device 3062 [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:2871 update_call_counter: Updating call counter for incoming call Looking for 3061 in from-internal (domain 10.1.1.9) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:3600 sip_new: *** Our native formats are 0x4 (ulaw) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:3601 sip_new: *** Joint capabilities are 0x4 (ulaw) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:3602 sip_new: *** Our capabilities are 0x280004 (ulaw|h263|h264) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:3603 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:3626 sip_new: This channel will not be able to handle video. [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:7591 build_route: build_route: Contact hop: list_route: hop: [Aug 16 10:40:23] DEBUG[2029]: chan_sip.c:12890 handle_request_invite: SIP/3062-0a09b4c0: 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-kyPH3NwmEdY;received=10.1.7.70;rport=5060 From: ;tag=YAAN3b5CbAHb1B6K To: Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@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 16 10:40:23] DEBUG[2029]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-0a09b4c0 [Aug 16 10:40:23] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:23] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:23] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 16 10:40:23] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:23] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Macro' -- Executing [3061@from-internal:1] Macro("SIP/3062-0a09b4c0", "exten-vm|novm|3061") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:1] NoOp("SIP/3062-0a09b4c0", "CallerID(number) set to 3062") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:2] GotoIf("SIP/3062-0a09b4c0", "0?5") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:5616 pbx_builtin_gotoif: Not taking any branch [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:3] GotoIf("SIP/3062-0a09b4c0", "1?5") in new stack -- Goto (macro-exten-vm,s,5) [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:5] GotoIf("SIP/3062-0a09b4c0", "1?:7") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:5616 pbx_builtin_gotoif: Not taking any branch [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:6] Set("SIP/3062-0a09b4c0", "__VRSID=1155721223.2") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:7] Set("SIP/3062-0a09b4c0", "CDR(userfield)=1155721223.2") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-exten-vm:8] NoOp("SIP/3062-0a09b4c0", "SESSION ID IS SET TO: 1155721223.2") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:9] Macro("SIP/3062-0a09b4c0", "user-callerid") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:1] Set("SIP/3062-0a09b4c0", "AMPUSER=3062") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is 'Desk2' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:2] Set("SIP/3062-0a09b4c0", "AMPUSERCIDNAME=Desk2") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-user-callerid:3] GotoIf("SIP/3062-0a09b4c0", "0?5") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:5616 pbx_builtin_gotoif: Not taking any branch [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:4] Set("SIP/3062-0a09b4c0", "CALLERID(number)=3062") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-user-callerid:5] Set("SIP/3062-0a09b4c0", "CALLERID(name)=Desk2") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '3062' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is 'Desk2' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-user-callerid:6] NoOp("SIP/3062-0a09b4c0", "Using CallerID(number) 3062 and CallerID(name) Desk2") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-exten-vm:10] Set("SIP/3062-0a09b4c0", "FROMCONTEXT=exten-vm") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:11] Macro("SIP/3062-0a09b4c0", "record-enable|3061|IN") in new stack [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '0' [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-record-enable:1] GotoIf("SIP/3062-0a09b4c0", "0 > 0?2:4") in new stack -- Goto (macro-record-enable,s,4) [Aug 16 10:40:23] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-record-enable:4] AGI("SIP/3062-0a09b4c0", "recordingcheck||1155721223.2") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/recordingcheck [Aug 16 10:40:24] DEBUG[2222]: app_queue.c:543 changethread: Device 'SIP/3062' changed to state '1' (Not in use) recordingcheck||1155721223.2: Inbound recording not enabled -- AGI Script recordingcheck completed, returning 0 [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-record-enable:5] NoOp("SIP/3062-0a09b4c0", "No recording needed") in new stack [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Macro' -- Executing [s@macro-exten-vm:12] Macro("SIP/3062-0a09b4c0", "dial|600|tr|3061") in new stack [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:1] Set("SIP/3062-0a09b4c0", "CDR(userfield)=1155721223.2") in new stack [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:2] GotoIf("SIP/3062-0a09b4c0", "0?5:3") in new stack -- Goto (macro-dial,s,3) [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is '0' [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1534 pbx_substitute_variables_helper_full: Function result is 'Desk2' [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial:3] GotoIf("SIP/3062-0a09b4c0", "0?6:5") in new stack -- Goto (macro-dial,s,5) [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'AGI' -- Executing [s@macro-dial:5] AGI("SIP/3062-0a09b4c0", "dialparties.agi") in new stack -- Launched AGI Script /var/lib/asterisk/agi-bin/dialparties.agi -- dialparties.agi: priority = 5 -- dialparties.agi: callingani2 = 0 -- dialparties.agi: accountcode = -- dialparties.agi: channel = SIP/3062-0a09b4c0 -- dialparties.agi: callerid = 3062 -- dialparties.agi: context = macro-dial -- dialparties.agi: callington = 0 -- dialparties.agi: dnid = 3061 -- dialparties.agi: request = dialparties.agi -- dialparties.agi: calleridname = Desk2 -- dialparties.agi: extension = s -- dialparties.agi: language = en -- dialparties.agi: uniqueid = 1155721223.2 -- dialparties.agi: callingpres = 0 -- dialparties.agi: type = SIP -- dialparties.agi: rdnis = unknown -- dialparties.agi: callingtns = 0 -- dialparties.agi: enhanced = 0.0 dialparties.agi: Caller ID name and number are '3062' dialparties.agi: Methodology of ring is 'none' -- dialparties.agi: Added extension 3061 to extension map [Aug 16 10:40:24] DEBUG[2221]: db.c:197 ast_db_get: Unable to find key '3061' in family 'CF' -- dialparties.agi: Extension 3061 cf is disabled [Aug 16 10:40:24] DEBUG[2221]: db.c:197 ast_db_get: Unable to find key '3061' in family 'DND' -- dialparties.agi: Extension 3061 do not disturb is disabled [Aug 16 10:40:24] DEBUG[2221]: db.c:197 ast_db_get: Unable to find key '3061' in family 'CW' [Aug 16 10:40:24] DEBUG[2221]: db.c:197 ast_db_get: Unable to find key '3061' in family 'CFB' > dialparties.agi: extnum: 3061 > dialparties.agi: exthascw: 0 > dialparties.agi: exthascfb: 0 > dialparties.agi: extcfb: -- dialparties.agi: Checking CW and CFB status for extension 3061 [Aug 16 10:40:24] DEBUG[2225]: manager.c:1812 process_message: Manager received command 'Login' [Aug 16 10:40:24] DEBUG[2225]: config.c:723 config_text_file_load: Parsing /etc/asterisk/manager.conf [Aug 16 10:40:24] DEBUG[2225]: config.c:723 config_text_file_load: Parsing /etc/asterisk/manager_custom.conf [Aug 16 10:40:24] DEBUG[2225]: acl.c:199 ast_append_ha: 0.0.0.0/0.0.0.0/0.0.0.0 appended to acl for peer [Aug 16 10:40:24] DEBUG[2225]: acl.c:199 ast_append_ha: 127.0.0.1/255.255.255.0/255.255.255.0 appended to acl for peer [Aug 16 10:40:24] DEBUG[2225]: acl.c:199 ast_append_ha: 10.0.0.0/255.0.0.0/255.0.0.0 appended to acl for peer [Aug 16 10:40:24] DEBUG[2225]: acl.c:199 ast_append_ha: 82.32.33.81/255.255.255.255/255.255.255.255 appended to acl for peer [Aug 16 10:40:24] DEBUG[2225]: acl.c:213 ast_apply_ha: ##### Testing 127.0.0.1 with 0.0.0.0 [Aug 16 10:40:24] DEBUG[2225]: acl.c:213 ast_apply_ha: ##### Testing 127.0.0.1 with 127.0.0.0 [Aug 16 10:40:24] DEBUG[2225]: acl.c:213 ast_apply_ha: ##### Testing 127.0.0.1 with 10.0.0.0 [Aug 16 10:40:24] DEBUG[2225]: acl.c:213 ast_apply_ha: ##### Testing 127.0.0.1 with 82.32.33.81 == Manager 'admin' logged on from 127.0.0.1 -- dialparties.agi: Correct AMPMGRUSER and AMPMGRPASS [Aug 16 10:40:24] DEBUG[2225]: manager.c:1812 process_message: Manager received command 'ExtensionState' [Aug 16 10:40:24] DEBUG[2225]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3061 [Aug 16 10:40:24] DEBUG[2225]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3061 > dialparties.agi: extstate: 16 [Aug 16 10:40:24] DEBUG[2225]: manager.c:1812 process_message: Manager received command 'Logoff' == Manager 'admin' logged off from 127.0.0.1 dialparties.agi: Extension 3061 is not available to be called dialparties.agi: Extension 3061 has call waiting disabled -- AGI Script Executing Application: (NoOp) Options: () -- AGI Script dialparties.agi completed, returning 0 [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-dial:6] NoOp("SIP/3062-0a09b4c0", "Returned from dialparties with no extensions to call") in new stack [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial:7] Set("SIP/3062-0a09b4c0", "DIALSTATUS=BUSY") in new stack [Aug 16 10:40:24] WARNING[2221]: ast_expr2.y:893 op_div: non-numeric argument [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '0' [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:13] GotoIf("SIP/3062-0a09b4c0", "0?s-BUSY|1") in new stack [Aug 16 10:40:24] DEBUG[2221]: pbx.c:5616 pbx_builtin_gotoif: Not taking any branch [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1601 pbx_substitute_variables_helper_full: Expression result is '1' [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-exten-vm:14] GotoIf("SIP/3062-0a09b4c0", "1?s-BUSY|1") in new stack -- Goto (macro-exten-vm,s-BUSY,1) [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'NoOp' -- Executing [s-BUSY@macro-exten-vm:1] NoOp("SIP/3062-0a09b4c0", "Extension is reporting BUSY and has no Voicemail") in new stack [Aug 16 10:40:24] DEBUG[2221]: pbx.c:1680 pbx_extension_helper: Launching 'Busy' -- Executing [s-BUSY@macro-exten-vm:2] Busy("SIP/3062-0a09b4c0", "") in new stack Transmitting (NAT) to 10.1.7.70:5060: SIP/2.0 486 Busy Here Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-kyPH3NwmEdY;received=10.1.7.70;rport=5060 From: ;tag=YAAN3b5CbAHb1B6K To: ;tag=as2d85446f Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@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 16 10:40:24] DEBUG[2221]: channel.c:1295 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/3062-0a09b4c0' [Aug 16 10:40:24] DEBUG[2221]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-0a09b4c0 [Aug 16 10:40:24] DEBUG[2221]: app_macro.c:244 _macro_exec: Spawn extension (macro-exten-vm,s-BUSY,2) exited non-zero on 'SIP/3062-0a09b4c0' in macro 'exten-vm' [Aug 16 10:40:24] DEBUG[2221]: pbx.c:2276 __ast_pbx_run: Spawn extension (macro-exten-vm,s-BUSY,2) exited non-zero on 'SIP/3062-0a09b4c0' [Aug 16 10:40:24] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:24] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:24] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 16 10:40:24] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:24] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:24] DEBUG[2226]: app_queue.c:543 changethread: Device 'SIP/3062' changed to state '1' (Not in use) [Aug 16 10:40:24] DEBUG[2221]: cdr_addon_mysql.c:208 mysql_log: cdr_mysql: inserting a CDR record. [Aug 16 10:40:24] DEBUG[2221]: cdr_addon_mysql.c:224 mysql_log: cdr_mysql: SQL command as follows: INSERT INTO cdr (calldate,clid,src,dst,dcontext,channel,dstchannel,lastapp,lastdata,duration,billsec,disposition,amaflags,accountcode,userfield) VALUES ('2006-08-16 10:40:23','\"Desk2\" <3062>','3062','3061','from-internal', 'SIP/3062-0a09b4c0','','Busy','',1,0,'NO ANSWER',3,'','1155721223.2') [Aug 16 10:40:24] DEBUG[2221]: channel.c:1519 ast_hangup: Hanging up channel 'SIP/3062-0a09b4c0' [Aug 16 10:40:24] DEBUG[2221]: chan_sip.c:3172 sip_hangup: Hangup call SIP/3062-0a09b4c0, SIP callid smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local) [Aug 16 10:40:24] DEBUG[2221]: chan_sip.c:3180 sip_hangup: update_call_counter(3062) - decrement call limit counter on hangup [Aug 16 10:40:24] DEBUG[2221]: chan_sip.c:2871 update_call_counter: Updating call counter for incoming call [Aug 16 10:40:24] DEBUG[2221]: chan_sip.c:3193 sip_hangup: Hanging up channel in state Busy (not UP) [Aug 16 10:40:24] DEBUG[2221]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/3062-0a09b4c0 [Aug 16 10:40:24] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:24] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:24] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3062 - state 1 (Not in use) [Aug 16 10:40:24] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3062 [Aug 16 10:40:24] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3062 [Aug 16 10:40:24] DEBUG[2227]: 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=as2d85446f From: ;tag=YAAN3b5CbAHb1B6K Contact: CSeq: 3 ACK Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-kyPH3NwmEdY;rport User-Agent: AuPix/v1.01.11 Max-Forwards: 70 Content-Length: 0 [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: ACK sip:3061@10.1.1.9 SIP/2.0 (29) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=as2d85446f (38) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: ;tag=YAAN3b5CbAHb1B6K (46) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: Contact: (43) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: CSeq: 3 ACK (11) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local (64) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Via: SIP/2.0/UDP 10.1.7.70:5060;branch=z9hG4bK-kyPH3NwmEdY;rport (64) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix/v1.01.11 (26) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received ACK (6) - Command in SIP ACK [Aug 16 10:40:24] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on 'smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local' of Response 3: Match Found Really destroying SIP dialog 'smIQfBeXORadPvf~VbvjxfQBx+D__BgN@videophone.aupix.local' Method: ACK AstDev*CLI> <-- SIP read from 10.1.1.15:2051: REGISTER sip:10.1.1.9 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-leqptfwxwyk9;rport From: "AstDev3060" ;tag=39t2whh6em To: "AstDev3060" Call-ID: 3c8554b588b8-phg18hxi61bi@snom360 CSeq: 390768 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 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: REGISTER sip:10.1.1.9 SIP/2.0 (29) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-leqptfwxwyk9;rport (65) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: "AstDev3060" ;tag=39t2whh6em (53) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: To: "AstDev3060" (36) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: Call-ID: 3c8554b588b8-phg18hxi61bi@snom360 (42) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: CSeq: 390768 REGISTER (21) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Max-Forwards: 70 (16) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 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 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: User-Agent: snom360/4.4 (23) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Supported: gruu (15) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: Allow-Events: dialog (20) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 11: X-Real-IP: 10.1.1.15 (20) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 12: WWW-Contact: (34) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 13: WWW-Contact: (36) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 14: Expires: 60 (11) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 15: Content-Length: 0 (17) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 16: (0) --- (16 headers 0 lines)--- [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for 3c8554b588b8-phg18hxi61bi@snom360 - REGISTER (No RTP) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 10.1.1.15 : 2051 (NAT) Transmitting (NAT) to 10.1.1.15:2051: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-leqptfwxwyk9;received=10.1.1.15;rport=2051 From: "AstDev3060" ;tag=39t2whh6em To: "AstDev3060" Call-ID: 3c8554b588b8-phg18hxi61bi@snom360 CSeq: 390768 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (NAT) to 10.1.1.15:2051: SIP/2.0 401 Unauthorized Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-leqptfwxwyk9;received=10.1.1.15;rport=2051 From: "AstDev3060" ;tag=39t2whh6em To: "AstDev3060" ;tag=as2883f476 Call-ID: 3c8554b588b8-phg18hxi61bi@snom360 CSeq: 390768 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="48a1a937" Content-Length: 0 --- Scheduling destruction of SIP dialog '3c8554b588b8-phg18hxi61bi@snom360' in 32000 ms (Method: REGISTER) AstDev*CLI> <-- SIP read from 10.1.1.15:2051: REGISTER sip:10.1.1.9 SIP/2.0 Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-4prjfmodcd7r;rport From: "AstDev3060" ;tag=39t2whh6em To: "AstDev3060" Call-ID: 3c8554b588b8-phg18hxi61bi@snom360 CSeq: 390769 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="48a1a937",uri="sip:10.1.1.9",response="8f259abd99b9b8c5028e31c0b88fc663",algorithm=md5 Expires: 60 Content-Length: 0 [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: REGISTER sip:10.1.1.9 SIP/2.0 (29) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-4prjfmodcd7r;rport (65) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: "AstDev3060" ;tag=39t2whh6em (53) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: To: "AstDev3060" (36) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: Call-ID: 3c8554b588b8-phg18hxi61bi@snom360 (42) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: CSeq: 390769 REGISTER (21) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Max-Forwards: 70 (16) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 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 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: User-Agent: snom360/4.4 (23) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Supported: gruu (15) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: Allow-Events: dialog (20) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 11: X-Real-IP: 10.1.1.15 (20) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 12: WWW-Contact: (34) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 13: WWW-Contact: (36) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 14: Authorization: Digest username="3060",realm="AuPixDev.aupix.com",nonce="48a1a937",uri="sip:10.1.1.9",response="8f259abd99b9b8c5028e31c0b88fc663",algorithm=md5 (158) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 15: Expires: 60 (11) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 16: Content-Length: 0 (17) [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 17: (0) --- (17 headers 0 lines)--- [Aug 16 10:40:25] DEBUG[2029]: chan_sip.c:14007 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to 10.1.1.15 : 2051 (NAT) Transmitting (NAT) to 10.1.1.15:2051: SIP/2.0 100 Trying Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-4prjfmodcd7r;received=10.1.1.15;rport=2051 From: "AstDev3060" ;tag=39t2whh6em To: "AstDev3060" Call-ID: 3c8554b588b8-phg18hxi61bi@snom360 CSeq: 390769 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- Transmitting (NAT) to 10.1.1.15:2051: SIP/2.0 200 OK Via: SIP/2.0/UDP 10.1.1.15:2051;branch=z9hG4bK-4prjfmodcd7r;received=10.1.1.15;rport=2051 From: "AstDev3060" ;tag=39t2whh6em To: "AstDev3060" ;tag=as2883f476 Call-ID: 3c8554b588b8-phg18hxi61bi@snom360 CSeq: 390769 REGISTER User-Agent: AuPix PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Wed, 16 Aug 2006 09:40:25 GMT Content-Length: 0 --- [Aug 16 10:40:25] DEBUG[2029]: 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 '3c8554b588b8-phg18hxi61bi@snom360' in 15000 ms (Method: REGISTER) [Aug 16 10:40:25] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 16 10:40:25] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3060 [Aug 16 10:40:25] DEBUG[2002]: devicestate.c:287 do_state_change: Changing state for SIP/3060 - state 1 (Not in use) [Aug 16 10:40:25] DEBUG[2002]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 3060 [Aug 16 10:40:25] DEBUG[2002]: chan_sip.c:14591 sip_devicestate: Checking device state for peer 3060 [Aug 16 10:40:25] DEBUG[2228]: 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 16 10:40:26] DEBUG[2029]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for (No Call-ID) - NOTIFY (No RTP) Scheduling destruction of SIP dialog '4feb33187c0373b72ab86fa63f637333@xx.yy.zz.203' in 32000 ms (Method: NOTIFY) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: NOTIFY sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 (52) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK2a69711f;rport (59) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: "Unknown" ;tag=as7eecfd41 (59) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: To: (43) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: Contact: (31) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: Call-ID: 4feb33187c0373b72ab86fa63f637333@xx.yy.zz.203 (56) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: CSeq: 102 NOTIFY (16) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: User-Agent: AuPix PBX (21) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 9: Event: message-summary (22) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 10: Content-Type: application/simple-message-summary (48) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 11: Content-Length: 94 (18) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 12: (0) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: Messages-Waiting: no (20) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: Message-Account: sip:asterisk@xx.yy.zz.203 (44) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4357 parse_request: Line: Voice-Message: 0/0 (0/0) (24) Reliably Transmitting (NAT) to 10.1.1.15:2051: NOTIFY sip:3060@10.1.1.15:2051;line=dk4cgjhj SIP/2.0 Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK2a69711f;rport From: "Unknown" ;tag=as7eecfd41 To: Contact: Call-ID: 4feb33187c0373b72ab86fa63f637333@xx.yy.zz.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@xx.yy.zz.203 Voice-Message: 0/0 (0/0) --- [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:1903 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #70 AstDev*CLI> <-- SIP read from 10.1.1.15:2051: SIP/2.0 200 Ok Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK2a69711f;rport=5060 From: "Unknown" ;tag=as7eecfd41 To: Call-ID: 4feb33187c0373b72ab86fa63f637333@xx.yy.zz.203 CSeq: 102 NOTIFY Content-Length: 0 [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 200 Ok (14) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 10.1.1.9:5060;branch=z9hG4bK2a69711f;rport=5060 (64) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 2: From: "Unknown" ;tag=as7eecfd41 (59) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 3: To: (43) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 4: Call-ID: 4feb33187c0373b72ab86fa63f637333@xx.yy.zz.203 (56) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 5: CSeq: 102 NOTIFY (16) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 6: Content-Length: 0 (17) [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:4325 parse_request: Header 7: (0) --- (7 headers 0 lines)--- [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:1996 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #70 [Aug 16 10:40:26] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on '4feb33187c0373b72ab86fa63f637333@xx.yy.zz.203' of Request 102: Match Not Found Really destroying SIP dialog '4feb33187c0373b72ab86fa63f637333@xx.yy.zz.203' Method: NOTIFY AstDev*CLI> sip no debug SIP Debugging Disabled [Aug 16 10:40:32] DEBUG[2029]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 16 10:40:32] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on '233dd7b25d2b73ef2591e1080a18bc23@xx.yy.zz.203' of Request 102: Match Not Found Really destroying SIP dialog '233dd7b25d2b73ef2591e1080a18bc23@xx.yy.zz.203' Method: OPTIONS [Aug 16 10:40:32] DEBUG[2029]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 16 10:40:32] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on '36e7fe6b5f422059582ba05d42ae6abc@xx.yy.zz.203' of Request 102: Match Not Found Really destroying SIP dialog '36e7fe6b5f422059582ba05d42ae6abc@xx.yy.zz.203' Method: OPTIONS [Aug 16 10:40:32] DEBUG[2029]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Aug 16 10:40:32] DEBUG[2029]: chan_sip.c:2006 __sip_ack: Stopping retransmission on '741e8138422289e024d0634a4a53b494@xx.yy.zz.203' of Request 102: Match Not Found Really destroying SIP dialog '741e8138422289e024d0634a4a53b494@xx.yy.zz.203' Method: OPTIONS AstDev*CLI> quit [root@AstDev asterisk-mytrunk]# cp /var/log/asterisk/full /tmp/full [root@AstDev asterisk-mytrunk]#