Asterisk SVN-trunk-r38389M, Copyright (C) 1999 - 2006 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'show warranty' for details. This is free software, with components licensed under the GNU General Public License version 2 and other licenses; you are welcome to redistribute it under certain conditions. Type 'show license' for details. ========================================================================= Connected to Asterisk SVN-trunk-r38389M currently running on my (pid = 1304) my*CLI> Verbosity is at least 100 my*CLI> [2006-08-01 17:29:40] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:40] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:41] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:41] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:42] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:42] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:43] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:1942 __sip_autodestruct: Auto destroying call 'e334eacc-2f826642@SPA2100_IP' [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:2984 sip_destroy: Destroying SIP dialog e334eacc-2f826642@SPA2100_IP Really destroying SIP dialog 'e334eacc-2f826642@SPA2100_IP' Method: REGISTER [2006-08-01 17:29:43] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> <-- SIP read from AT320_IP:5060: INVITE sip:1005@pbx.varna.net SIP/2.0 Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKfYS35O4zpeEnbxrc Max-Forwards: 70 User-Agent: phone V1.49.002 CFG0 From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP Contact: CSeq: 1 INVITE Supported: replaces Content-Type: application/sdp Content-Length: 294 v=0 o=- 11500177 82894142 IN IP4 AT320_IP s=SIP CALL c=IN IP4 AT320_IP t=0 0 m=audio 10722 RTP/AVP 8 0 18 4 3 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:18 G729/8000 a=rtpmap:4 G723/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: INVITE sip:1005@pbx.varna.net SIP/2.0 (37) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKfYS35O4zpeEnbxrc (67) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: Max-Forwards: 70 (16) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: User-Agent: phone V1.49.002 CFG0 (33) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: From: "1070" ;tag=fe8KJeaRHeh0lHO7 (58) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: To: "1005" (35) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP (40) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Contact: (39) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: CSeq: 1 INVITE (14) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: Supported: replaces (19) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 10: Content-Type: application/sdp (29) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 11: Content-Length: 294 (19) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 12: (0) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: v=0 (3) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: o=- 11500177 82894142 IN IP4 AT320_IP (43) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: s=SIP CALL (10) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: c=IN IP4 AT320_IP (23) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: m=audio 10722 RTP/AVP 8 0 18 4 3 101 (36) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:18 G729/8000 (21) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:4 G723/8000 (20) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-15 (15) --- (12 headers 13 lines)--- [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for 4Bn2DyAlBQhsdnjN@AT320_IP - INVITE (With RTP) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:13974 handle_request: **** Received INVITE (5) - Command in SIP INVITE [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:1619 parse_sip_options: Begin: parsing SIP "Supported: replaces" [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:1627 parse_sip_options: Found SIP option: -replaces- [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:1633 parse_sip_options: Matched SIP option: replaces Sending to AT320_IP : 5060 (no NAT) Using INVITE request as basis request - 4Bn2DyAlBQhsdnjN@AT320_IP [2006-08-01 17:29:43] DEBUG[1310]: acl.c:213 ast_apply_ha: ##### Testing AT320_IP with 0.0.0.0 [2006-08-01 17:29:43] DEBUG[1310]: acl.c:213 ast_apply_ha: ##### Testing AT320_IP with AT320_IP [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:8620 check_user_full: Setting NAT on RTP to Off Found user '1070' Found RTP audio format 8 Found RTP audio format 0 Found RTP audio format 18 Found RTP audio format 4 Found RTP audio format 3 Found RTP audio format 101 Peer audio RTP is at port AT320_IP:10722 Found description format PCMA for ID 8 Found description format PCMU for ID 0 Found description format G729 for ID 18 Found description format G723 for ID 4 Found description format GSM for ID 3 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4830 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc), peer - audio=0x10f (g723|gsm|ulaw|alaw|g729)/video=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw) my*CLI> Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port AT320_IP:10722 [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4900 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:12787 handle_request_invite: Checking SIP call limits for device 1070 [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:2878 update_call_counter: Updating call counter for incoming call Looking for 1005 in Internal (domain pbx.varna.net) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:3607 sip_new: *** Our native formats are 0x8 (alaw) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:3608 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:3609 sip_new: *** Our capabilities are 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:3610 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:3633 sip_new: This channel will not be able to handle video. [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:7586 build_route: build_route: Contact hop: list_route: hop: [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:12857 handle_request_invite: SIP/1070-006b3b2c: New call is still down.... Trying... Transmitting (no NAT) to AT320_IP:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKfYS35O4zpeEnbxrc;received=AT320_IP From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 1 INVITE User-Agent: PBX.Varna.Net Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [2006-08-01 17:29:43] DEBUG[1310]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1070-006b3b2c my*CLI> [2006-08-01 17:29:43] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1070 [2006-08-01 17:29:43] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1070 [2006-08-01 17:29:43] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1070 - state 1 (Not in use) [2006-08-01 17:29:43] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1070 [2006-08-01 17:29:43] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1070 [2006-08-01 17:29:43] DEBUG[1354]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' -- Executing [1005@Internal:1] Dial("SIP/1070-006b3b2c", "SIP/1005||TWHKtwhk") in new stack [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:14594 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:2519 create_addr_from_peer: Setting NAT on RTP to Off [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:3607 sip_new: *** Our native formats are 0x8 (alaw) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:3608 sip_new: *** Joint capabilities are 0x0 (nothing) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:3609 sip_new: *** Our capabilities are 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:3610 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:3612 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:3633 sip_new: This channel will not be able to handle video. my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: channel.c:2980 ast_channel_inherit_variables: Not copying variable STACK-Internal-1005-1. my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: channel.c:2980 ast_channel_inherit_variables: Not copying variable SIPCALLID. my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: channel.c:2980 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: channel.c:2980 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: channel.c:2980 ast_channel_inherit_variables: Not copying variable SIPURI. my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:2717 sip_call: Outgoing Call for 1005 my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:2878 update_call_counter: Updating call counter for outgoing call my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:2725 sip_call: Our T38 capability (0), joint T38 capability (0) my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:5805 add_sdp: ** Our capability: 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc) Video flag: False my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:5806 add_sdp: ** Our prefcodec: 0x8 (alaw) my*CLI> Audio is at 217.145.81.12 port 45076 my*CLI> Adding codec 0x8 (alaw) to SDP my*CLI> Adding codec 0x4 (ulaw) to SDP [2006-08-01 17:29:43] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> Adding codec 0x2 (gsm) to SDP Adding codec 0x800 (g726) to SDP Adding codec 0x20 (adpcm) to SDP Adding codec 0x400 (ilbc) to SDP Adding non-codec 0x1 (telephone-event) to SDP [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:5958 add_sdp: -- Done with adding codecs to SDP [2006-08-01 17:29:43] DEBUG[1354]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=21) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:5997 add_sdp: Done building SDP. Settling with this capability: 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 0: INVITE sip:1005@SPA2100_IP:5060 SIP/2.0 (43) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK42bd22d0;rport (64) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 2: From: "1070" ;tag=as07dc353d (52) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 3: To: (34) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 4: Contact: (33) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 5: Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 (55) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 6: CSeq: 102 INVITE (16) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 7: User-Agent: PBX.Varna.Net (25) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 9: Date: Tue, 01 Aug 2006 14:29:43 GMT (35) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 11: Supported: replaces (19) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 12: Content-Type: application/sdp (29) my*CLI> [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 13: Content-Length: 348 (19) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4325 parse_request: Header 14: (0) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: v=0 (3) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: o=root 1304 1304 IN IP4 217.145.81.12 (37) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: s=session (9) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: c=IN IP4 217.145.81.12 (22) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: m=audio 45076 RTP/AVP 8 0 3 111 5 97 101 (40) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=rtpmap:3 GSM/8000 (19) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=rtpmap:111 G726-32/8000 (25) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=rtpmap:5 DVI4/8000 (20) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=fmtp:97 mode=20 (17) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-16 (15) [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:4357 parse_request: Line: a=sendrecv (10) my*CLI> Reliably Transmitting (no NAT) to SPA2100_IP:5060: INVITE sip:1005@SPA2100_IP:5060 SIP/2.0 Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK42bd22d0;rport From: "1070" ;tag=as07dc353d To: Contact: Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 CSeq: 102 INVITE User-Agent: PBX.Varna.Net Max-Forwards: 70 Date: Tue, 01 Aug 2006 14:29:43 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 348 v=0 o=root 1304 1304 IN IP4 217.145.81.12 s=session c=IN IP4 217.145.81.12 t=0 0 m=audio 45076 RTP/AVP 8 0 3 111 5 97 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv --- [2006-08-01 17:29:43] DEBUG[1354]: sched.c:218 ast_sched_add_variable: ast_sched_add() [2006-08-01 17:29:43] DEBUG[1354]: chan_sip.c:1910 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #76 [2006-08-01 17:29:43] DEBUG[1354]: sched.c:218 ast_sched_add_variable: ast_sched_add() -- Called 1005 my*CLI> <-- SIP read from SPA2100_IP:5060: SIP/2.0 100 Trying To: From: "1070" ;tag=as07dc353d Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 CSeq: 102 INVITE Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK42bd22d0 Server: Sipura/SPA2100-3.2.5(d) Content-Length: 0 my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 100 Trying (18) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: To: (34) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: "1070" ;tag=as07dc353d (52) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 (55) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: CSeq: 102 INVITE (16) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK42bd22d0 (58) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Server: Sipura/SPA2100-3.2.5(d) (31) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Content-Length: 0 (17) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: (0) my*CLI> --- (8 headers 0 lines)--- my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag Our tag: as07dc353d my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:2046 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #76 - INVITE (got response) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:2055 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '31fc97b82a708cfa72a725f700c8cac8@217.145.81.12' Request 102: Found my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:11148 handle_response_invite: SIP response 100 to standard invite my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> <-- SIP read from SPA2100_IP:5060: SIP/2.0 180 Ringing To: ;tag=fbc941a5141918e6i0 From: "1070" ;tag=as07dc353d Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 CSeq: 102 INVITE Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK42bd22d0 Server: Sipura/SPA2100-3.2.5(d) Remote-Party-ID: 1005 ;screen=yes;party=called Content-Length: 0 my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 180 Ringing (19) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=fbc941a5141918e6i0 (57) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: "1070" ;tag=as07dc353d (52) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 (55) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: CSeq: 102 INVITE (16) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK42bd22d0 (58) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Server: Sipura/SPA2100-3.2.5(d) (31) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Remote-Party-ID: 1005 ;screen=yes;party=called (70) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: Content-Length: 0 (17) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: (0) my*CLI> --- (9 headers 0 lines)--- my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag Our tag: as07dc353d my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:2055 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '31fc97b82a708cfa72a725f700c8cac8@217.145.81.12' Request 102: Found my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: chan_sip.c:11148 handle_response_invite: SIP response 180 to standard invite my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() -- SIP/1005-006b8c0c is ringing Transmitting (no NAT) to AT320_IP:5060: SIP/2.0 180 Ringing Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKfYS35O4zpeEnbxrc;received=AT320_IP From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" ;tag=as124df05b Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 1 INVITE User-Agent: PBX.Varna.Net Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- my*CLI> [2006-08-01 17:29:43] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1005 my*CLI> [2006-08-01 17:29:43] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1005 my*CLI> [2006-08-01 17:29:43] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1005 - state 1 (Not in use) my*CLI> [2006-08-01 17:29:43] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:44] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:44] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> <-- SIP read from SPA2100_IP:5060: SIP/2.0 200 OK To: ;tag=fbc941a5141918e6i0 From: "1070" ;tag=as07dc353d Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 CSeq: 102 INVITE Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK42bd22d0 Contact: 1005 Server: Sipura/SPA2100-3.2.5(d) Remote-Party-ID: 1005 ;screen=yes;party=called Content-Length: 261 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura Content-Type: application/sdp v=0 o=- 43729864 43729864 IN IP4 SPA2100_IP s=- c=IN IP4 SPA2100_IP t=0 0 m=audio 16468 RTP/AVP 8 100 101 a=rtpmap:8 PCMA/8000 a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:20 a=sendrecv my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 200 OK (14) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=fbc941a5141918e6i0 (57) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: "1070" ;tag=as07dc353d (52) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 (55) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: CSeq: 102 INVITE (16) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK42bd22d0 (58) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Contact: 1005 (44) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Server: Sipura/SPA2100-3.2.5(d) (31) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: Remote-Party-ID: 1005 ;screen=yes;party=called (70) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 261 (19) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 10: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 11: Supported: x-sipura (19) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 12: Content-Type: application/sdp (29) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 13: (0) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: v=0 (3) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: o=- 43729864 43729864 IN IP4 SPA2100_IP (43) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: s=- (3) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: c=IN IP4 SPA2100_IP (23) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: m=audio 16468 RTP/AVP 8 100 101 (31) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:100 NSE/8000 (21) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=fmtp:100 192-193 (18) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-15 (15) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=ptime:20 (10) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4357 parse_request: Line: a=sendrecv (10) my*CLI> --- (13 headers 13 lines)--- my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag fbc941a5141918e6i0 Our tag: as07dc353d my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:1995 __sip_ack: Acked pending invite 102 my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:2013 __sip_ack: Stopping retransmission on '31fc97b82a708cfa72a725f700c8cac8@217.145.81.12' of Request 102: Match Not Found my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:11148 handle_response_invite: SIP response 200 to standard invite my*CLI> Found RTP audio format 8 my*CLI> Found RTP audio format 100 my*CLI> Found RTP audio format 101 my*CLI> Peer audio RTP is at port SPA2100_IP:16468 my*CLI> Found description format PCMA for ID 8 my*CLI> Found description format NSE for ID 100 my*CLI> Got unsupported a:fmtp in SDP offer my*CLI> Found description format telephone-event for ID 101 my*CLI> Got unsupported a:fmtp in SDP offer my*CLI> Got unsupported a:ptime in SDP offer my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4830 process_sdp: T38 state changed to 0 on channel SIP/1005-006b8c0c my*CLI> Capabilities: us - 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc), peer - audio=0x8 (alaw)/video=0x0 (nothing), combined - 0x8 (alaw) my*CLI> Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) my*CLI> Peer audio RTP is at port SPA2100_IP:16468 my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4900 process_sdp: We're settling with these formats: 0x8 (alaw) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4907 process_sdp: We have an owner, now see if we need to change this call my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:2878 update_call_counter: Updating call counter for outgoing call my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:7586 build_route: build_route: Contact hop: 1005 my*CLI> list_route: hop: my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:5336 reqprep: Strict routing enforced for session 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 my*CLI> set_destination: Parsing for address/port to send to my*CLI> set_destination: set destination to SPA2100_IP, port 5060 my*CLI> Transmitting (no NAT) to SPA2100_IP:5060: ACK sip:1005@SPA2100_IP:5060 SIP/2.0 Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK656e3eab;rport From: "1070" ;tag=as07dc353d To: ;tag=fbc941a5141918e6i0 Contact: Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 CSeq: 102 ACK User-Agent: PBX.Varna.Net Max-Forwards: 70 Content-Length: 0 --- my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1005-006b8c0c my*CLI> -- SIP/1005-006b8c0c answered SIP/1070-006b3b2c my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1070-006b3b2c my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: chan_sip.c:3318 sip_answer: SIP answering channel: SIP/1070-006b3b2c my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: chan_sip.c:5805 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: chan_sip.c:5806 add_sdp: ** Our prefcodec: 0x0 (nothing) my*CLI> Audio is at 217.145.81.12 port 47472 Adding codec 0x8 (alaw) to SDP my*CLI> Adding codec 0x4 (ulaw) to SDP my*CLI> Adding codec 0x2 (gsm) to SDP my*CLI> Adding non-codec 0x1 (telephone-event) to SDP my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: chan_sip.c:5958 add_sdp: -- Done with adding codecs to SDP my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=18) my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: chan_sip.c:5997 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) my*CLI> Reliably Transmitting (no NAT) to AT320_IP:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKfYS35O4zpeEnbxrc;received=AT320_IP From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" ;tag=as124df05b Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 1 INVITE User-Agent: PBX.Varna.Net Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 248 v=0 o=root 1304 1304 IN IP4 217.145.81.12 s=session c=IN IP4 217.145.81.12 t=0 0 m=audio 47472 RTP/AVP 8 0 3 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv --- my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: sched.c:218 ast_sched_add_variable: ast_sched_add() my*CLI> [2006-08-01 17:29:45] DEBUG[1354]: chan_sip.c:1910 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #78 my*CLI> [2006-08-01 17:29:45] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1005 my*CLI> [2006-08-01 17:29:45] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1005 my*CLI> [2006-08-01 17:29:45] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1005 - state 1 (Not in use) my*CLI> [2006-08-01 17:29:45] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1070 my*CLI> [2006-08-01 17:29:45] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1070 my*CLI> [2006-08-01 17:29:45] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1070 - state 1 (Not in use) my*CLI> [2006-08-01 17:29:45] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1070 my*CLI> [2006-08-01 17:29:45] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1070 my*CLI> <-- SIP read from AT320_IP:5060: ACK sip:1005@217.145.81.12 SIP/2.0 Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKl5pc8ilNFGOFAe6A Max-Forwards: 70 User-Agent: phone V1.49.002 CFG0 From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" ;tag=as124df05b Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP Contact: CSeq: 1 ACK Content-Length: 0 my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: ACK sip:1005@217.145.81.12 SIP/2.0 (34) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKl5pc8ilNFGOFAe6A (67) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: Max-Forwards: 70 (16) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: User-Agent: phone V1.49.002 CFG0 (33) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: From: "1070" ;tag=fe8KJeaRHeh0lHO7 (58) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: To: "1005" ;tag=as124df05b (50) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP (40) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Contact: (39) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: CSeq: 1 ACK (11) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 10: (0) my*CLI> --- (10 headers 0 lines)--- my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag fbc941a5141918e6i0 Our tag: as07dc353d my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 4Bn2DyAlBQhsdnjN@AT320_IP Their Tag fe8KJeaRHeh0lHO7 Our tag: as124df05b my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:13974 handle_request: **** Received ACK (6) - Command in SIP ACK my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:2003 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #78 my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: chan_sip.c:2013 __sip_ack: Stopping retransmission on '4Bn2DyAlBQhsdnjN@AT320_IP' of Response 1: Match Not Found my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:45] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:46] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:46] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:47] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:47] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:48] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:48] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> <-- SIP read from AT320_IP:5060: REFER sip:1005@217.145.81.12 SIP/2.0 Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKPa1Gy6oERI9Kq9oN Max-Forwards: 70 User-Agent: phone V1.49.002 CFG0 From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" ;tag=as124df05b Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP Contact: CSeq: 2 REFER Refer-To: "1007" Referred-By: Content-Length: 0 my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: REFER sip:1005@217.145.81.12 SIP/2.0 (36) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKPa1Gy6oERI9Kq9oN (67) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: Max-Forwards: 70 (16) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: User-Agent: phone V1.49.002 CFG0 (33) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: From: "1070" ;tag=fe8KJeaRHeh0lHO7 (58) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: To: "1005" ;tag=as124df05b (50) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP (40) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Contact: (39) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: CSeq: 2 REFER (13) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: Refer-To: "1007" (41) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 10: Referred-By: (37) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 11: Content-Length: 0 (17) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 12: (0) my*CLI> --- (12 headers 0 lines)--- my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag fbc941a5141918e6i0 Our tag: as07dc353d my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 4Bn2DyAlBQhsdnjN@AT320_IP Their Tag fe8KJeaRHeh0lHO7 Our tag: as124df05b my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:13974 handle_request: **** Received REFER (9) - Command in SIP REFER my*CLI> Call 4Bn2DyAlBQhsdnjN@AT320_IP got a SIP call transfer from caller: (REFER)! my*CLI> SIP transfer to extension 1007@Internal by 1070@pbx.varna.net my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:13325 handle_request_refer: SIP blind transfer: Transferer channel SIP/1070-006b3b2c, transferee channel SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:13341 handle_request_refer: Got SIP transfer, applying to bridged peer 'SIP/1005-006b8c0c' my*CLI> Transmitting (no NAT) to AT320_IP:5060: SIP/2.0 202 Accepted Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bKPa1Gy6oERI9Kq9oN;received=AT320_IP From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" ;tag=as124df05b Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 2 REFER User-Agent: PBX.Varna.Net Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:13379 handle_request_refer: chan1->name: SIP/1070-006b3b2c my*CLI> [2006-08-01 17:29:49] ERROR[1310]: ../include/asterisk/lock.h:405 __ast_pthread_mutex_unlock: chan_sip.c line 13414 (handle_request_refer): mutex '¤t.chan2->lock' freed more times than we've locked! my*CLI> [2006-08-01 17:29:49] ERROR[1310]: ../include/asterisk/lock.h:418 __ast_pthread_mutex_unlock: chan_sip.c line 13414 (handle_request_refer): Error releasing mutex: Operation not permitted my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:5336 reqprep: Strict routing enforced for session 4Bn2DyAlBQhsdnjN@AT320_IP my*CLI> set_destination: Parsing for address/port to send to my*CLI> set_destination: set destination to AT320_IP, port 5060 my*CLI> Reliably Transmitting (no NAT) to AT320_IP:5060: NOTIFY sip:1070@AT320_IP:5060 SIP/2.0 Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK72bd9841;rport From: "1005" ;tag=as124df05b To: "1070" ;tag=fe8KJeaRHeh0lHO7 Contact: Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 102 NOTIFY User-Agent: PBX.Varna.Net Max-Forwards: 70 Event: refer;id=2 Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 21 SIP/2.0 183 Ringing --- my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: sched.c:218 ast_sched_add_variable: ast_sched_add() my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:1910 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #79 my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel AsyncGoto/SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: channel.c:2914 ast_channel_masquerade: Planning to masquerade channel SIP/1005-006b8c0c into the structure of AsyncGoto/SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: channel.c:2927 ast_channel_masquerade: Done planning to masquerade channel SIP/1005-006b8c0c into the structure of AsyncGoto/SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: channel.c:3042 ast_do_masquerade: Actually Masquerading SIP/1005-006b8c0c(6) into the structure of AsyncGoto/SIP/1005-006b8c0c(6) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: channel.c:3054 ast_do_masquerade: Got clone lock for masquerade on 'SIP/1005-006b8c0c' at 0x6bd614 my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: channel.c:3219 ast_do_masquerade: Putting channel SIP/1005-006b8c0c in 8/8 formats my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:3435 sip_fixup: SIP Fixup: New owner for dialogue 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12: SIP/1005-006b8c0c (Old parent: AsyncGoto/SIP/1005-006b8c0c) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: channel.c:3254 ast_do_masquerade: Released clone lock on 'AsyncGoto/SIP/1005-006b8c0c' my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: channel.c:3264 ast_do_masquerade: Done Masquerading SIP/1005-006b8c0c (6) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:13450 handle_request_refer: Blind transfer succeeded. Telling transferer. my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:5336 reqprep: Strict routing enforced for session 4Bn2DyAlBQhsdnjN@AT320_IP my*CLI> set_destination: Parsing for address/port to send to my*CLI> set_destination: set destination to AT320_IP, port 5060 my*CLI> Reliably Transmitting (no NAT) to AT320_IP:5060: NOTIFY sip:1070@AT320_IP:5060 SIP/2.0 Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK05f30df4;rport From: "1005" ;tag=as124df05b To: "1070" ;tag=fe8KJeaRHeh0lHO7 Contact: Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 103 NOTIFY User-Agent: PBX.Varna.Net Max-Forwards: 70 Event: refer;id=2 Subscription-state: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 16 SIP/2.0 200 Ok --- my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: sched.c:218 ast_sched_add_variable: ast_sched_add() my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:1910 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #80 my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for AsyncGoto - SIP/1005 my*CLI> [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for AsyncGoto/SIP/1005 - state 4 (Invalid) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: pbx.c:1675 pbx_extension_helper: Launching 'Dial' my*CLI> -- Executing [1007@Internal:1] Dial("SIP/1005-006b8c0c", "SIP/1006||TWHKtwhk") in new stack my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:14594 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:2519 create_addr_from_peer: Setting NAT on RTP to Off my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:3607 sip_new: *** Our native formats are 0x8 (alaw) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:3608 sip_new: *** Joint capabilities are 0x0 (nothing) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:3609 sip_new: *** Our capabilities are 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:3610 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:3612 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:3633 sip_new: This channel will not be able to handle video. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2980 ast_channel_inherit_variables: Not copying variable STACK-Internal-1007-1. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2967 ast_channel_inherit_variables: Copying soft-transferable variable SIPTRANSFER_REFERER. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2967 ast_channel_inherit_variables: Copying soft-transferable variable SIPTRANSFER. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2980 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2980 ast_channel_inherit_variables: Not copying variable BLINDTRANSFER. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2980 ast_channel_inherit_variables: Not copying variable BRIDGEPEER. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2980 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2980 ast_channel_inherit_variables: Not copying variable SIPCALLID. my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:2709 sip_call: Call for 1006 transfered by 1070@pbx.varna.net my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:2717 sip_call: Outgoing Call for 1006 my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:2878 update_call_counter: Updating call counter for outgoing call my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:2725 sip_call: Our T38 capability (0), joint T38 capability (0) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:5805 add_sdp: ** Our capability: 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc) Video flag: False my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:5806 add_sdp: ** Our prefcodec: 0x8 (alaw) my*CLI> Audio is at 217.145.81.12 port 26068 my*CLI> Adding codec 0x8 (alaw) to SDP my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: channel.c:3443 ast_generic_bridge: Didn't get a frame from channel: AsyncGoto/SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: channel.c:3814 ast_channel_bridge: Bridge stops bridging channels SIP/1070-006b3b2c and AsyncGoto/SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: channel.c:1514 ast_hangup: Hanging up zombie 'AsyncGoto/SIP/1005-006b8c0c' my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel AsyncGoto/SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: rtp.c:1317 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=ANSWER. my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: pbx.c:2271 __ast_pbx_run: Spawn extension (Internal,1005,1) exited non-zero on 'SIP/1070-006b3b2c' my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: pbx.c:1675 pbx_extension_helper: Launching 'Goto' my*CLI> Adding codec 0x4 (ulaw) to SDP my*CLI> -- Executing [h@Internal:1] Goto("SIP/1070-006b3b2c", "100") in new stack [2006-08-01 17:29:49] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for AsyncGoto - SIP/1005 my*CLI> [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for AsyncGoto/SIP/1005 - state 4 (Invalid) my*CLI> Adding codec 0x2 (gsm) to SDP my*CLI> Adding codec 0x800 (g726) to SDP my*CLI> -- Goto (Internal,h,100) Adding codec 0x20 (adpcm) to SDP Adding codec 0x400 (ilbc) to SDP my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: cdr.c:894 ast_cdr_detach: Dropping CDR ! my*CLI> Adding non-codec 0x1 (telephone-event) to SDP [2006-08-01 17:29:49] DEBUG[1354]: channel.c:1509 ast_hangup: Hanging up channel 'SIP/1070-006b3b2c' my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:5958 add_sdp: -- Done with adding codecs to SDP my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=25) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:5997 add_sdp: Done building SDP. Settling with this capability: 0xc2e (gsm|ulaw|alaw|g726|adpcm|ilbc) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 0: INVITE sip:1006@SPA2100_IP:5061 SIP/2.0 (43) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7;rport (64) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 2: From: "1005" ;tag=as1a92c62f (52) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 3: To: (34) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 4: Contact: (33) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 5: Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 (55) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 6: CSeq: 102 INVITE (16) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 7: User-Agent: PBX.Varna.Net (25) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 8: Max-Forwards: 70 (16) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 9: Date: Tue, 01 Aug 2006 14:29:49 GMT (35) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 11: Supported: replaces (19) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 12: Content-Type: application/sdp (29) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 13: Content-Length: 348 (19) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4325 parse_request: Header 14: (0) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: v=0 (3) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: o=root 1304 1304 IN IP4 217.145.81.12 (37) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: s=session (9) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: c=IN IP4 217.145.81.12 (22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: t=0 0 (5) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: m=audio 26068 RTP/AVP 8 0 3 111 5 97 101 (40) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=rtpmap:3 GSM/8000 (19) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=rtpmap:111 G726-32/8000 (25) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=rtpmap:5 DVI4/8000 (20) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=rtpmap:97 iLBC/8000 (21) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=fmtp:97 mode=20 (17) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=fmtp:101 0-16 (15) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:4357 parse_request: Line: a=sendrecv (10) [2006-08-01 17:29:49] DEBUG[1354]: chan_sip.c:3165 sip_hangup: Reliably Transmitting (no NAT) to SPA2100_IP:5061: INVITE sip:1006@SPA2100_IP:5061 SIP/2.0 Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7;rport From: "1005" ;tag=as1a92c62f To: Contact: Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 CSeq: 102 INVITE User-Agent: PBX.Varna.Net Max-Forwards: 70 Date: Tue, 01 Aug 2006 14:29:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 348 v=0 o=root 1304 1304 IN IP4 217.145.81.12 s=session c=IN IP4 217.145.81.12 t=0 0 m=audio 26068 RTP/AVP 8 0 3 111 5 97 101 a=rtpmap:8 PCMA/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/8000 a=rtpmap:111 G726-32/8000 a=rtpmap:5 DVI4/8000 a=rtpmap:97 iLBC/8000 a=fmtp:97 mode=20 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=sendrecv --- SIP Transfer: Not hanging up right now... Rescheduling hangup for 4Bn2DyAlBQhsdnjN@AT320_IP. my*CLI> Scheduling destruction of SIP dialog '4Bn2DyAlBQhsdnjN@AT320_IP' in 32000 ms (Method: REFER) [2006-08-01 17:29:49] DEBUG[1355]: sched.c:218 ast_sched_add_variable: ast_sched_add() [2006-08-01 17:29:49] DEBUG[1355]: chan_sip.c:1910 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #81 my*CLI> [2006-08-01 17:29:49] DEBUG[1354]: sched.c:218 ast_sched_add_variable: ast_sched_add() [2006-08-01 17:29:49] DEBUG[1355]: sched.c:218 ast_sched_add_variable: ast_sched_add() my*CLI> -- Called 1006 [2006-08-01 17:29:49] DEBUG[1354]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1070-006b3b2c [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1070 [2006-08-01 17:29:49] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1070 [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1070 - state 1 (Not in use) [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1070 [2006-08-01 17:29:49] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1070 my*CLI> <-- SIP read from SPA2100_IP:5061: SIP/2.0 100 Trying To: From: "1005" ;tag=as1a92c62f Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 CSeq: 102 INVITE Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7 Server: Sipura/SPA2100-3.2.5(d) Content-Length: 0 my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 100 Trying (18) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: To: (34) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: "1005" ;tag=as1a92c62f (52) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 (55) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: CSeq: 102 INVITE (16) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7 (58) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Server: Sipura/SPA2100-3.2.5(d) (31) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Content-Length: 0 (17) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: (0) my*CLI> --- (8 headers 0 lines)--- my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag Our tag: as1a92c62f my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:2046 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #81 - INVITE (got response) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:2055 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12' Request 102: Found my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:11148 handle_response_invite: SIP response 100 to standard invite my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> <-- SIP read from SPA2100_IP:5061: SIP/2.0 180 Ringing To: ;tag=3476607f273df9d5i1 From: "1005" ;tag=as1a92c62f Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 CSeq: 102 INVITE Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7 Server: Sipura/SPA2100-3.2.5(d) Remote-Party-ID: 1006 ;screen=yes;party=called Content-Length: 0 my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 180 Ringing (19) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=3476607f273df9d5i1 (57) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: "1005" ;tag=as1a92c62f (52) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 (55) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: CSeq: 102 INVITE (16) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7 (58) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Server: Sipura/SPA2100-3.2.5(d) (31) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Remote-Party-ID: 1006 ;screen=yes;party=called (70) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: Content-Length: 0 (17) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: (0) --- (9 headers 0 lines)--- [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag Our tag: as1a92c62f [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:2055 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12' Request 102: Found [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:11148 handle_response_invite: SIP response 180 to standard invite [2006-08-01 17:29:49] DEBUG[1310]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1006-0079bdfc [2006-08-01 17:29:49] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:49] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> -- SIP/1006-0079bdfc is ringing [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2188 ast_indicate_data: Driver for channel 'SIP/1005-006b8c0c' does not support indication 3, emulating it [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2515 set_format: Set channel SIP/1005-006b8c0c to write format slin [2006-08-01 17:29:49] DEBUG[1355]: channel.c:1809 ast_settimeout: Scheduling timer at 160 sample intervals my*CLI> [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1006 [2006-08-01 17:29:49] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1006 [2006-08-01 17:29:49] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1006 - state 1 (Not in use) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: rtp.c:2346 ast_rtp_write: Ooh, format changed from unknown to alaw [2006-08-01 17:29:49] DEBUG[1355]: sched.c:218 ast_sched_add_variable: ast_sched_add() my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> <-- SIP read from AT320_IP:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK72bd9841;rport Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 102 NOTIFY From: "1005" ;tag=as124df05b To: "1070" ;tag=fe8KJeaRHeh0lHO7 Contact: Content-Length: 0 [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 200 OK (14) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK72bd9841;rport (64) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP (40) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: CSeq: 102 NOTIFY (16) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: From: "1005" ;tag=as124df05b (52) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: To: "1070" ;tag=fe8KJeaRHeh0lHO7 (56) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Contact: (39) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Content-Length: 0 (17) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag 3476607f273df9d5i1 Our tag: as1a92c62f [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag fbc941a5141918e6i0 Our tag: as07dc353d [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 4Bn2DyAlBQhsdnjN@AT320_IP Their Tag fe8KJeaRHeh0lHO7 Our tag: as124df05b [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:2003 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #79 [2006-08-01 17:29:49] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:2013 __sip_ack: Stopping retransmission on '4Bn2DyAlBQhsdnjN@AT320_IP' of Request 102: Match Not Found SIP Response message for INCOMING dialog NOTIFY arrived [2006-08-01 17:29:49] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:49] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> <-- SIP read from AT320_IP:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK05f30df4;rport Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 103 NOTIFY From: "1005" ;tag=as124df05b To: "1070" ;tag=fe8KJeaRHeh0lHO7 Contact: Content-Length: 0 [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 200 OK (14) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK05f30df4;rport (64) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP (40) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: CSeq: 103 NOTIFY (16) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: From: "1005" ;tag=as124df05b (52) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: To: "1070" ;tag=fe8KJeaRHeh0lHO7 (56) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Contact: (39) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Content-Length: 0 (17) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag 3476607f273df9d5i1 Our tag: as1a92c62f [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag fbc941a5141918e6i0 Our tag: as07dc353d [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 4Bn2DyAlBQhsdnjN@AT320_IP Their Tag fe8KJeaRHeh0lHO7 Our tag: as124df05b [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:2003 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #80 [2006-08-01 17:29:49] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:2013 __sip_ack: Stopping retransmission on '4Bn2DyAlBQhsdnjN@AT320_IP' of Request 103: Match Not Found SIP Response message for INCOMING dialog NOTIFY arrived [2006-08-01 17:29:49] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:49] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> <-- SIP read from AT320_IP:5060: BYE sip:1005@217.145.81.12 SIP/2.0 Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bK0JsnWRTckcKrI9kw Max-Forwards: 70 User-Agent: phone V1.49.002 CFG0 From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" ;tag=as124df05b Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP Contact: CSeq: 3 BYE Content-Length: 0 my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: BYE sip:1005@217.145.81.12 SIP/2.0 (34) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bK0JsnWRTckcKrI9kw (67) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: Max-Forwards: 70 (16) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: User-Agent: phone V1.49.002 CFG0 (33) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: From: "1070" ;tag=fe8KJeaRHeh0lHO7 (58) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: To: "1005" ;tag=as124df05b (50) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP (40) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Contact: (39) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: CSeq: 3 BYE (11) [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) my*CLI> [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag 3476607f273df9d5i1 Our tag: as1a92c62f [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag fbc941a5141918e6i0 Our tag: as07dc353d [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 4Bn2DyAlBQhsdnjN@AT320_IP Their Tag fe8KJeaRHeh0lHO7 Our tag: as124df05b [2006-08-01 17:29:49] DEBUG[1310]: chan_sip.c:13974 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to AT320_IP : 5060 (no NAT) Transmitting (no NAT) to AT320_IP:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP AT320_IP:5060;branch=z9hG4bK0JsnWRTckcKrI9kw;received=AT320_IP From: "1070" ;tag=fe8KJeaRHeh0lHO7 To: "1005" ;tag=as124df05b Call-ID: 4Bn2DyAlBQhsdnjN@AT320_IP CSeq: 3 BYE User-Agent: PBX.Varna.Net Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [2006-08-01 17:29:49] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() my*CLI> Really destroying SIP dialog '4Bn2DyAlBQhsdnjN@AT320_IP' Method: BYE [2006-08-01 17:29:49] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() [2006-08-01 17:29:49] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:49] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:50] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:50] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:51] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:51] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:52] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:52] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:53] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> <-- SIP read from SPA2100_IP:5060: REGISTER sip:my2.varna.net SIP/2.0 Via: SIP/2.0/UDP SPA2100_IP:5060;branch=z9hG4bK-28c1809a From: 1005 ;tag=219e2a6956ce63f8o0 To: 1005 Call-ID: 25a92732-5d99e514@SPA2100_IP CSeq: 37346 REGISTER Max-Forwards: 70 Contact: 1005 ;expires=60 User-Agent: Sipura/SPA2100-3.2.5(d) Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: REGISTER sip:my2.varna.net SIP/2.0 (34) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP SPA2100_IP:5060;branch=z9hG4bK-28c1809a (60) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: 1005 ;tag=219e2a6956ce63f8o0 (58) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: To: 1005 (33) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: Call-ID: 25a92732-5d99e514@SPA2100_IP (41) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: CSeq: 37346 REGISTER (20) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Max-Forwards: 70 (16) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Contact: 1005 ;expires=60 (55) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: User-Agent: Sipura/SPA2100-3.2.5(d) (35) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 10: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 11: Supported: x-sipura (19) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 12: (0) --- (12 headers 0 lines)--- [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag 3476607f273df9d5i1 Our tag: as1a92c62f [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag fbc941a5141918e6i0 Our tag: as07dc353d [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:4105 sip_alloc: Allocating new SIP dialog for 25a92732-5d99e514@SPA2100_IP - REGISTER (No RTP) [2006-08-01 17:29:53] DEBUG[1310]: chan_sip.c:13974 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER Using latest REGISTER request as basis request Sending to SPA2100_IP : 5060 (no NAT) [2006-08-01 17:29:53] DEBUG[1310]: acl.c:213 ast_apply_ha: ##### Testing SPA2100_IP with 0.0.0.0 [2006-08-01 17:29:53] DEBUG[1310]: acl.c:213 ast_apply_ha: ##### Testing SPA2100_IP with SPA2100_IP Transmitting (no NAT) to SPA2100_IP:5060: SIP/2.0 100 Trying Via: SIP/2.0/UDP SPA2100_IP:5060;branch=z9hG4bK-28c1809a;received=SPA2100_IP From: 1005 ;tag=219e2a6956ce63f8o0 To: 1005 Call-ID: 25a92732-5d99e514@SPA2100_IP CSeq: 37346 REGISTER User-Agent: PBX.Varna.Net Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- [2006-08-01 17:29:53] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() [2006-08-01 17:29:53] DEBUG[1310]: sched.c:218 ast_sched_add_variable: ast_sched_add() my*CLI> Transmitting (no NAT) to SPA2100_IP:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP SPA2100_IP:5060;branch=z9hG4bK-28c1809a;received=SPA2100_IP From: 1005 ;tag=219e2a6956ce63f8o0 To: 1005 ;tag=as4bffd4ff Call-ID: 25a92732-5d99e514@SPA2100_IP CSeq: 37346 REGISTER User-Agent: PBX.Varna.Net Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Expires: 60 Contact: ;expires=60 Date: Tue, 01 Aug 2006 14:29:53 GMT Content-Length: 0 --- [2006-08-01 17:29:53] DEBUG[1310]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1005 Scheduling destruction of SIP dialog '25a92732-5d99e514@SPA2100_IP' in 15000 ms (Method: REGISTER) [2006-08-01 17:29:53] DEBUG[1310]: sched.c:218 ast_sched_add_variable: ast_sched_add() [2006-08-01 17:29:53] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:53] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:53] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1005 [2006-08-01 17:29:53] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1005 [2006-08-01 17:29:53] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1005 - state 1 (Not in use) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:53] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:54] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() [2006-08-01 17:29:54] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:54] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2135 ast_internal_timing_enabled: Internal timing is enabled (option_internal_timing=1048576 chan->timingfd=22) my*CLI> <-- SIP read from SPA2100_IP:5060: BYE sip:1070@217.145.81.12 SIP/2.0 Via: SIP/2.0/UDP SPA2100_IP:5060;branch=z9hG4bK-9d86627f From: ;tag=fbc941a5141918e6i0 To: "1070" ;tag=as07dc353d Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 CSeq: 101 BYE Max-Forwards: 70 User-Agent: Sipura/SPA2100-3.2.5(d) P-RTP-Stat: PS=443,OS=70880,PR=258,OR=41280,PL=0,JI=0,LA=0,DU=9,EN=G711a,DE=G711a Content-Length: 0 [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: BYE sip:1070@217.145.81.12 SIP/2.0 (34) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: Via: SIP/2.0/UDP SPA2100_IP:5060;branch=z9hG4bK-9d86627f (60) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: ;tag=fbc941a5141918e6i0 (59) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: To: "1070" ;tag=as07dc353d (50) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 (55) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: CSeq: 101 BYE (13) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Max-Forwards: 70 (16) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: User-Agent: Sipura/SPA2100-3.2.5(d) (35) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: P-RTP-Stat: PS=443,OS=70880,PR=258,OR=41280,PL=0,JI=0,LA=0,DU=9,EN=G711a,DE=G711a (81) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 9: Content-Length: 0 (17) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 10: (0) --- (10 headers 0 lines)--- [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 25a92732-5d99e514@SPA2100_IP Their Tag 219e2a6956ce63f8o0 Our tag: as4bffd4ff [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag 3476607f273df9d5i1 Our tag: as1a92c62f [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 Their Tag fbc941a5141918e6i0 Our tag: as07dc353d [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:13974 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to SPA2100_IP : 5060 (no NAT) [2006-08-01 17:29:54] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() my*CLI> Transmitting (no NAT) to SPA2100_IP:5060: SIP/2.0 200 OK Via: SIP/2.0/UDP SPA2100_IP:5060;branch=z9hG4bK-9d86627f;received=SPA2100_IP From: ;tag=fbc941a5141918e6i0 To: "1070" ;tag=as07dc353d Call-ID: 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12 CSeq: 101 BYE User-Agent: PBX.Varna.Net Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 --- my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:54] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() [2006-08-01 17:29:54] DEBUG[1355]: channel.c:2515 set_format: Set channel SIP/1005-006b8c0c to write format alaw [2006-08-01 17:29:54] DEBUG[1355]: channel.c:1809 ast_settimeout: Scheduling timer at 0 sample intervals [2006-08-01 17:29:54] DEBUG[1355]: rtp.c:1317 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [2006-08-01 17:29:54] DEBUG[1355]: channel.c:1509 ast_hangup: Hanging up channel 'SIP/1006-0079bdfc' [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:3179 sip_hangup: Hangup call SIP/1006-0079bdfc, SIP callid 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12) [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:3187 sip_hangup: update_call_counter(1006) - decrement call limit counter on hangup [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:2878 update_call_counter: Updating call counter for outgoing call [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:3200 sip_hangup: Hanging up channel in state Ringing (not UP) [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:1995 __sip_ack: Acked pending invite 102 [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:2013 __sip_ack: Stopping retransmission on '3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12' of Request 102: Match Not Found Reliably Transmitting (no NAT) to SPA2100_IP:5061: CANCEL sip:1006@SPA2100_IP:5061 SIP/2.0 Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7;rport From: "1005" ;tag=as1a92c62f To: Contact: Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 CSeq: 102 CANCEL User-Agent: PBX.Varna.Net Max-Forwards: 70 Content-Length: 0 --- [2006-08-01 17:29:54] DEBUG[1355]: sched.c:218 ast_sched_add_variable: ast_sched_add() [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:1910 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #87 Scheduling destruction of SIP dialog '3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12' in 32000 ms (Method: INVITE) [2006-08-01 17:29:54] DEBUG[1355]: sched.c:218 ast_sched_add_variable: ast_sched_add() my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1006-0079bdfc my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: app_dial.c:1643 dial_exec_full: Exiting with DIALSTATUS=CANCEL. my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: pbx.c:2271 __ast_pbx_run: Spawn extension (Internal,1007,1) exited non-zero on 'SIP/1005-006b8c0c' my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: pbx.c:1675 pbx_extension_helper: Launching 'Goto' my*CLI> -- Executing [h@Internal:1] Goto("SIP/1005-006b8c0c", "100") in new stack my*CLI> -- Goto (Internal,h,100) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: cdr.c:894 ast_cdr_detach: Dropping CDR ! my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: channel.c:1509 ast_hangup: Hanging up channel 'SIP/1005-006b8c0c' my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:3179 sip_hangup: Hangup call SIP/1005-006b8c0c, SIP callid 31fc97b82a708cfa72a725f700c8cac8@217.145.81.12) my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:3187 sip_hangup: update_call_counter(1005) - decrement call limit counter on hangup my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: chan_sip.c:2878 update_call_counter: Updating call counter for outgoing call my*CLI> [2006-08-01 17:29:54] DEBUG[1355]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/1005-006b8c0c my*CLI> [2006-08-01 17:29:54] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1006 my*CLI> [2006-08-01 17:29:54] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1006 my*CLI> [2006-08-01 17:29:54] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1006 - state 1 (Not in use) my*CLI> [2006-08-01 17:29:54] DEBUG[1307]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 1005 my*CLI> [2006-08-01 17:29:54] DEBUG[1307]: chan_sip.c:14538 sip_devicestate: Checking device state for peer 1005 my*CLI> [2006-08-01 17:29:54] DEBUG[1307]: devicestate.c:287 do_state_change: Changing state for SIP/1005 - state 1 (Not in use) my*CLI> <-- SIP read from SPA2100_IP:5061: SIP/2.0 487 Request Terminated To: ;tag=3476607f273df9d5i1 From: "1005" ;tag=as1a92c62f Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 CSeq: 102 INVITE Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7 Server: Sipura/SPA2100-3.2.5(d) Content-Length: 0 my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 487 Request Terminated (30) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=3476607f273df9d5i1 (57) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: "1005" ;tag=as1a92c62f (52) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 (55) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: CSeq: 102 INVITE (16) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7 (58) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Server: Sipura/SPA2100-3.2.5(d) (31) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Content-Length: 0 (17) my*CLI> [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: (0) my*CLI> --- (8 headers 0 lines)--- [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 25a92732-5d99e514@SPA2100_IP Their Tag 219e2a6956ce63f8o0 Our tag: as4bffd4ff [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag 3476607f273df9d5i1 Our tag: as1a92c62f [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:2013 __sip_ack: Stopping retransmission on '3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12' of Request 102: Match Found [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:2878 update_call_counter: Updating call counter for outgoing call Transmitting (no NAT) to SPA2100_IP:5061: ACK sip:1006@SPA2100_IP:5061 SIP/2.0 Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7;rport From: "1005" ;tag=as1a92c62f To: ;tag=3476607f273df9d5i1 Contact: Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 CSeq: 102 ACK User-Agent: PBX.Varna.Net Max-Forwards: 70 Content-Length: 0 --- [2006-08-01 17:29:54] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() Really destroying SIP dialog '31fc97b82a708cfa72a725f700c8cac8@217.145.81.12' Method: BYE [2006-08-01 17:29:54] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> <-- SIP read from SPA2100_IP:5061: SIP/2.0 200 OK To: ;tag=3476607f273df9d5i1 From: "1005" ;tag=as1a92c62f Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 CSeq: 102 CANCEL Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7 Server: Sipura/SPA2100-3.2.5(d) Content-Length: 0 [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 0: SIP/2.0 200 OK (14) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 1: To: ;tag=3476607f273df9d5i1 (57) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 2: From: "1005" ;tag=as1a92c62f (52) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 3: Call-ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 (55) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 4: CSeq: 102 CANCEL (16) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 5: Via: SIP/2.0/UDP 217.145.81.12:5060;branch=z9hG4bK6ab638b7 (58) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 6: Server: Sipura/SPA2100-3.2.5(d) (31) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 7: Content-Length: 0 (17) [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4325 parse_request: Header 8: (0) --- (8 headers 0 lines)--- [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4153 find_call: = No match Their Call ID: 25a92732-5d99e514@SPA2100_IP Their Tag 219e2a6956ce63f8o0 Our tag: as4bffd4ff [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:4153 find_call: = Found Their Call ID: 3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12 Their Tag 3476607f273df9d5i1 Our tag: as1a92c62f [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:2003 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #87 [2006-08-01 17:29:54] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() [2006-08-01 17:29:54] DEBUG[1310]: chan_sip.c:2013 __sip_ack: Stopping retransmission on '3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12' of Request 102: Match Not Found [2006-08-01 17:29:54] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() Really destroying SIP dialog '3fb4e36b3869d2be0793679e7f75e0d4@217.145.81.12' Method: INVITE [2006-08-01 17:29:54] DEBUG[1310]: sched.c:262 ast_sched_del: ast_sched_del() [2006-08-01 17:29:54] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:55] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:55] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:56] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:56] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:57] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:57] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait() my*CLI> [2006-08-01 17:29:58] DEBUG[1310]: sched.c:331 ast_sched_runq: ast_sched_runq() [2006-08-01 17:29:58] DEBUG[1310]: sched.c:152 ast_sched_wait: ast_sched_wait()