[Feb 11 13:11:42] Asterisk SVN-branch-1.4-r52647, Copyright (C) 1999 - 2006 Digium, Inc. and others. [Feb 11 13:11:42] Created by Mark Spencer [Feb 11 13:11:42] Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core show warranty' for details. [Feb 11 13:11:42] This is free software, with components licensed under the GNU General Public [Feb 11 13:11:42] License version 2 and other licenses; you are welcome to redistribute it under [Feb 11 13:11:42] certain conditions. Type 'core show license' for details. [Feb 11 13:11:42] ========================================================================= [Feb 11 13:11:42] codec_lpc10.so => (LPC10 2.4kbps Coder/Decoder) [Feb 11 13:11:42] == Parsing '/etc/asterisk/codecs.conf': [Feb 11 13:11:42] DEBUG[27825]: config.c:851 config_text_file_load: Parsing /etc/asterisk/codecs.conf [Feb 11 13:11:42] Found [Feb 11 13:11:42] -- CODEC SPEEX: Setting Quality to 3 [Feb 11 13:11:42] -- CODEC SPEEX: Setting Complexity to 2 [Feb 11 13:11:42] -- CODEC SPEEX: Perceptual Enhancement Mode. [on] [Feb 11 13:11:42] -- CODEC SPEEX: VAD Mode. [off] [Feb 11 13:11:42] -- CODEC SPEEX: VBR Mode. [off] [Feb 11 13:11:42] -- CODEC SPEEX: Disabling ABR [Feb 11 13:11:42] -- CODEC SPEEX: Setting VBR Quality to 4.000000 [Feb 11 13:11:42] -- CODEC SPEEX: DTX Mode. [off] [Feb 11 13:11:42] -- CODEC SPEEX: Preprocessing. [off] [Feb 11 13:11:42] -- CODEC SPEEX: Preprocessor VAD. [off] [Feb 11 13:11:42] -- CODEC SPEEX: Preprocessor AGC. [off] [Feb 11 13:11:42] -- CODEC SPEEX: Setting preprocessor AGC Level to 8000.000000 [Feb 11 13:11:42] -- CODEC SPEEX: Preprocessor Denoise. [off] [Feb 11 13:11:42] -- CODEC SPEEX: Preprocessor Dereverb. [off] [Feb 11 13:11:42] -- CODEC SPEEX: Setting preprocessor Dereverb Decay to 0.400000 [Feb 11 13:11:42] -- CODEC SPEEX: Setting preprocessor Dereverb Level to 0.300000 [Feb 11 13:11:42] == Registered translator 'speextolin' from format speex to slin, cost 3 [Feb 11 13:11:42] DEBUG[27825]: translate.c:425 rebuild_matrix: Resetting translation matrix *CLI> sip debug 4 Usage: sip set debug Enables dumping of SIP packets for debugging purposes sip set debug ip Enables dumping of SIP packets to and from host. sip set debug peer Enables dumping of SIP packets to and from host. Require peer to be registered. *CLI> sip set debug 4 Core debug was 5 and is now 4 The 'set debug' command is deprecated and will be removed in a future release. Please use 'core set debug' instead. *CLI> set verbose 4 Verbosity was 5 and is now 4 The 'set verbose' command is deprecated and will be removed in a future release. Please use 'core set verbose' instead. *CLI> sip debug SIP Debugging enabled The 'sip debug' command is deprecated and will be removed in a future release. Please use 'sip set debug' instead. *CLI> [Feb 11 13:12:13] <--- SIP read from 212.13.202.25:5060 ---> <-------------> [Feb 11 13:12:13] --- (0 headers 0 lines) Nat keepalive --- [Feb 11 13:12:14] DEBUG[27847]: chan_sip.c:2007 __sip_autodestruct: Auto destroying SIP dialog '0a3f102f19ad677c5ddf014917ee41ed@127.0.1.1' [Feb 11 13:12:14] DEBUG[27847]: chan_sip.c:3106 sip_destroy: Destroying SIP dialog 0a3f102f19ad677c5ddf014917ee41ed@127.0.1.1 [Feb 11 13:12:14] Really destroying SIP dialog '0a3f102f19ad677c5ddf014917ee41ed@127.0.1.1' Method: REGISTER [Feb 11 13:12:38] <-------------> [Feb 11 13:13:11] <--- SIP read from 127.0.1.1:5051 ---> INVITE sip:127.0.1.1:5070 SIP/2.0 Via: SIP/2.0/UDP 84.209.226.67:5051;rport;branch=z9hG4bK79A0A9DA2D2C5CF7900D42EAF6F323EC From: Agmund ;tag=894115659 To: Contact: Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 CSeq: 16133 INVITE Max-Forwards: 70 Content-Type: application/sdp User-Agent: X-Lite release 1105d Content-Length: 313 v=0 o=agmund 2964887338 2964887363 IN IP4 84.209.226.67 s=X-Lite c=IN IP4 84.209.226.67 t=0 0 m=audio 8000 RTP/AVP 0 8 3 98 97 101 a=rtpmap:0 pcmu/8000 a=rtpmap:8 pcma/8000 a=rtpmap:3 gsm/8000 a=rtpmap:98 iLBC/8000 a=rtpmap:97 speex/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendrecv <-------------> [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 0: INVITE sip:127.0.1.1:5070 SIP/2.0 (33) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 84.209.226.67:5051;rport;branch=z9hG4bK79A0A9DA2D2C5CF7900D42EAF6F323EC (88) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 2: From: Agmund ;tag=894115659 (54) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 3: To: (20) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 4: Contact: (40) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 5: Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 (54) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 6: CSeq: 16133 INVITE (18) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 7: Max-Forwards: 70 (16) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 8: Content-Type: application/sdp (29) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 9: User-Agent: X-Lite release 1105d (32) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 10: Content-Length: 313 (19) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 11: (0) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: v=0 (3) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: o=agmund 2964887338 2964887363 IN IP4 84.209.226.67 (51) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: s=X-Lite (8) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: c=IN IP4 84.209.226.67 (22) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: t=0 0 (5) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: m=audio 8000 RTP/AVP 0 8 3 98 97 101 (36) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: a=rtpmap:0 pcmu/8000 (20) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: a=rtpmap:3 gsm/8000 (19) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: a=rtpmap:98 iLBC/8000 (21) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: a=rtpmap:97 speex/8000 (22) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4587 parse_request: Line: a=sendrecv (10) [Feb 11 13:13:11] --- (11 headers 14 lines) --- [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:2572 do_setnat: Setting NAT on RTP to On [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:2577 do_setnat: Setting NAT on VRTP to On [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:4292 sip_alloc: Allocating new SIP dialog for 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 - INVITE (With RTP) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:14562 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Feb 11 13:13:11] Sending to 127.0.1.1 : 5051 (NAT) [Feb 11 13:13:11] Using INVITE request as basis request - 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 [Feb 11 13:13:11] Found no matching peer or user for '127.0.1.1:5051' [Feb 11 13:13:11] Found RTP audio format 0 [Feb 11 13:13:11] Found RTP audio format 8 [Feb 11 13:13:11] Found RTP audio format 3 [Feb 11 13:13:11] Found RTP audio format 98 [Feb 11 13:13:11] Found RTP audio format 97 [Feb 11 13:13:11] Found RTP audio format 101 [Feb 11 13:13:11] Peer audio RTP is at port 84.209.226.67:8000 [Feb 11 13:13:11] Found description format pcmu for ID 0 [Feb 11 13:13:11] Found description format pcma for ID 8 [Feb 11 13:13:11] Found description format gsm for ID 3 [Feb 11 13:13:11] Found description format iLBC for ID 98 [Feb 11 13:13:11] Found description format speex for ID 97 [Feb 11 13:13:11] Found description format telephone-event for ID 101 [Feb 11 13:13:11] Got unsupported a:fmtp in SDP offer [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:5097 process_sdp: T38 state changed to 0 on channel [Feb 11 13:13:11] Capabilities: us - 0x28024e (gsm|ulaw|alaw|slin|speex|h263|h264), peer - audio=0x60e (gsm|ulaw|alaw|speex|ilbc)/video=0x0 (nothing), combined - 0x20e (gsm|ulaw|alaw|speex) [Feb 11 13:13:11] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Feb 11 13:13:11] Peer audio RTP is at port 84.209.226.67:8000 [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:5177 process_sdp: We're settling with these formats: 0x20e (gsm|ulaw|alaw|speex) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:13350 handle_request_invite: Checking SIP call limits for device [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:3000 update_call_counter: Updating call counter for incoming call [Feb 11 13:13:11] Looking for s in default (domain 127.0.1.1) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:3795 sip_new: *** Our native formats are 0x200 (speex) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:3796 sip_new: *** Joint capabilities are 0x20e (gsm|ulaw|alaw|speex) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:3797 sip_new: *** Our capabilities are 0x28024e (gsm|ulaw|alaw|slin|speex|h263|h264) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:3798 sip_new: *** AST_CODEC_CHOOSE formats are 0x200 (speex) [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:3821 sip_new: This channel will not be able to handle video. [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:7940 build_route: build_route: Contact hop: [Feb 11 13:13:11] list_route: hop: [Feb 11 13:13:11] DEBUG[27847]: chan_sip.c:13425 handle_request_invite: SIP/5051-006d6680: New call is still down.... Trying... [Feb 11 13:13:11] <--- Transmitting (NAT) to 127.0.1.1:5051 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 84.209.226.67:5051;branch=z9hG4bK79A0A9DA2D2C5CF7900D42EAF6F323EC;received=127.0.1.1;rport=5051 From: Agmund ;tag=894115659 To: Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 CSeq: 16133 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 11 13:13:11] DEBUG[27847]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5051-006d6680 [Feb 11 13:13:11] DEBUG[27830]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5051 [Feb 11 13:13:11] DEBUG[27830]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 5051 [Feb 11 13:13:11] DEBUG[27830]: devicestate.c:287 do_state_change: Changing state for SIP/5051 - state 4 (Invalid) [Feb 11 13:13:11] DEBUG[27905]: pbx.c:1769 pbx_extension_helper: Launching 'Wait' [Feb 11 13:13:11] -- Executing [s@default:1] Wait("SIP/5051-006d6680", "1") in new stack [Feb 11 13:13:11] DEBUG[27906]: app_queue.c:546 changethread: Device 'SIP/5051' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 11 13:13:12] DEBUG[27905]: pbx.c:1769 pbx_extension_helper: Launching 'Answer' [Feb 11 13:13:12] -- Executing [s@default:2] Answer("SIP/5051-006d6680", "") in new stack [Feb 11 13:13:12] DEBUG[27905]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5051-006d6680 [Feb 11 13:13:12] DEBUG[27830]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5051 [Feb 11 13:13:12] DEBUG[27830]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 5051 [Feb 11 13:13:12] DEBUG[27830]: devicestate.c:287 do_state_change: Changing state for SIP/5051 - state 4 (Invalid) [Feb 11 13:13:12] DEBUG[27905]: chan_sip.c:3453 sip_answer: SIP answering channel: SIP/5051-006d6680 [Feb 11 13:13:12] DEBUG[27905]: chan_sip.c:6390 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 11 13:13:12] DEBUG[27905]: chan_sip.c:6158 add_sdp: ** Our capability: 0x20e (gsm|ulaw|alaw|speex) Video flag: True [Feb 11 13:13:12] DEBUG[27905]: chan_sip.c:6159 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 11 13:13:12] Audio is at 127.0.1.1 port 13160 [Feb 11 13:13:12] Adding codec 0x200 (speex) to SDP [Feb 11 13:13:12] Adding codec 0x2 (gsm) to SDP [Feb 11 13:13:12] Adding codec 0x4 (ulaw) to SDP [Feb 11 13:13:12] Adding codec 0x8 (alaw) to SDP [Feb 11 13:13:12] Adding non-codec 0x1 (telephone-event) to SDP [Feb 11 13:13:12] DEBUG[27905]: chan_sip.c:6290 add_sdp: -- Done with adding codecs to SDP [Feb 11 13:13:12] DEBUG[27905]: chan_sip.c:6335 add_sdp: Done building SDP. Settling with this capability: 0x20e (gsm|ulaw|alaw|speex) [Feb 11 13:13:12] <--- Reliably Transmitting (NAT) to 127.0.1.1:5051 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 84.209.226.67:5051;branch=z9hG4bK79A0A9DA2D2C5CF7900D42EAF6F323EC;received=127.0.1.1;rport=5051 From: Agmund ;tag=894115659 To: ;tag=as7746eb95 Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 CSeq: 16133 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 308 v=0 o=root 27825 27825 IN IP4 127.0.1.1 s=session c=IN IP4 127.0.1.1 t=0 0 m=audio 13160 RTP/AVP 97 3 0 8 101 a=rtpmap:97 speex/8000 a=rtpmap:3 GSM/8000 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Feb 11 13:13:12] DEBUG[27905]: chan_sip.c:1972 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #7 [Feb 11 13:13:12] DEBUG[27905]: pbx.c:1769 pbx_extension_helper: Launching 'Set' [Feb 11 13:13:12] -- Executing [s@default:3] Set("SIP/5051-006d6680", "TIMEOUT(digit)=5") in new stack [Feb 11 13:13:12] -- Digit timeout set to 5 [Feb 11 13:13:12] DEBUG[27905]: pbx.c:1769 pbx_extension_helper: Launching 'Set' [Feb 11 13:13:12] -- Executing [s@default:4] Set("SIP/5051-006d6680", "TIMEOUT(response)=10") in new stack [Feb 11 13:13:12] -- Response timeout set to 10 [Feb 11 13:13:12] DEBUG[27905]: pbx.c:1769 pbx_extension_helper: Launching 'BackGround' [Feb 11 13:13:12] -- Executing [s@default:5] BackGround("SIP/5051-006d6680", "demo-congrats") in new stack [Feb 11 13:13:12] DEBUG[27905]: channel.c:2839 set_format: Set channel SIP/5051-006d6680 to write format gsm [Feb 11 13:13:12] DEBUG[27905]: rtp.c:2670 ast_rtp_write: Ooh, format changed from unknown to speex [Feb 11 13:13:12] DEBUG[27905]: rtp.c:2687 ast_rtp_write: Created smoother: format: 512 ms: 20 len: 20 [Feb 11 13:13:12] -- Playing 'demo-congrats' (language 'en') [Feb 11 13:13:12] DEBUG[27907]: app_queue.c:546 changethread: Device 'SIP/5051' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 11 13:13:12] <--- SIP read from 127.0.1.1:5051 ---> ACK sip:s@127.0.1.1:5070 SIP/2.0 Via: SIP/2.0/UDP 84.209.226.67:5051;rport;branch=z9hG4bK4D284C721103E3D2031115ED070810F3 From: Agmund ;tag=894115659 To: ;tag=as7746eb95 Contact: Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 CSeq: 16133 ACK Max-Forwards: 70 Content-Length: 0 <-------------> [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 0: ACK sip:s@127.0.1.1:5070 SIP/2.0 (32) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 84.209.226.67:5051;rport;branch=z9hG4bK4D284C721103E3D2031115ED070810F3 (88) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 2: From: Agmund ;tag=894115659 (54) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 3: To: ;tag=as7746eb95 (35) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 4: Contact: (40) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 5: Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 (54) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 6: CSeq: 16133 ACK (15) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 7: Max-Forwards: 70 (16) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 8: Content-Length: 0 (17) [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 9: (0) [Feb 11 13:13:12] --- (9 headers 0 lines) --- [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:14562 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:2076 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #7 [Feb 11 13:13:12] DEBUG[27847]: chan_sip.c:2086 __sip_ack: Stopping retransmission on '39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4' of Response 16133: Match Not Found [Feb 11 13:13:12] DEBUG[27905]: rtp.c:866 ast_rtcp_read: RTCP NAT: Got RTCP from other end. Now sending to address 127.0.1.1:8001 [Feb 11 13:13:12] DEBUG[27905]: rtp.c:871 ast_rtcp_read: Got RTCP report of 84 bytes [Feb 11 13:13:12] DEBUG[27905]: rtp.c:1149 ast_rtp_read: RTP NAT: Got audio from other end. Now sending to address 127.0.1.1:8000 [Feb 11 13:13:12] DEBUG[27905]: rtp.c:871 ast_rtcp_read: Got RTCP report of 114 bytes [Feb 11 13:13:15] <--- SIP read from 127.0.1.1:5051 ---> BYE sip:s@127.0.1.1:5070 SIP/2.0 Via: SIP/2.0/UDP 84.209.226.67:5051;rport;branch=z9hG4bK581A0A9DB95CE79494942E4D118BCFC2 From: Agmund ;tag=894115659 To: ;tag=as7746eb95 Contact: Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 CSeq: 16134 BYE Max-Forwards: 70 User-Agent: X-Lite release 1105d Content-Length: 0 <-------------> [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 0: BYE sip:s@127.0.1.1:5070 SIP/2.0 (32) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 1: Via: SIP/2.0/UDP 84.209.226.67:5051;rport;branch=z9hG4bK581A0A9DB95CE79494942E4D118BCFC2 (88) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 2: From: Agmund ;tag=894115659 (54) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 3: To: ;tag=as7746eb95 (35) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 4: Contact: (40) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 5: Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 (54) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 6: CSeq: 16134 BYE (15) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 7: Max-Forwards: 70 (16) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 8: User-Agent: X-Lite release 1105d (32) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 9: Content-Length: 0 (17) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:4555 parse_request: Header 10: (0) [Feb 11 13:13:15] --- (10 headers 0 lines) --- [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:14562 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 11 13:13:15] Sending to 127.0.1.1 : 5051 (NAT) [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:1630 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 [Feb 11 13:13:15] DEBUG[27847]: chan_sip.c:14139 handle_request_bye: Received bye, issuing owner hangup [Feb 11 13:13:15] <--- Transmitting (NAT) to 127.0.1.1:5051 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 84.209.226.67:5051;branch=z9hG4bK581A0A9DB95CE79494942E4D118BCFC2;received=127.0.1.1;rport=5051 From: Agmund ;tag=894115659 To: ;tag=as7746eb95 Call-ID: 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4 CSeq: 16134 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Feb 11 13:13:15] DEBUG[27905]: channel.c:2839 set_format: Set channel SIP/5051-006d6680 to write format speex [Feb 11 13:13:15] DEBUG[27905]: pbx.c:2367 __ast_pbx_run: Spawn extension (default,s,5) exited non-zero on 'SIP/5051-006d6680' [Feb 11 13:13:15] == Spawn extension (default, s, 5) exited non-zero on 'SIP/5051-006d6680' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '"Agmund" ' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'agmund' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 's' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'default' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'SIP/5051-006d6680' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'BackGround' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'demo-congrats' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-11 13:13:11' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-11 13:13:12' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '2007-02-11 13:13:15' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '4' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '3' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '1171195991.0' [Feb 11 13:13:15] DEBUG[27905]: pbx.c:1622 pbx_substitute_variables_helper_full: Function result is '' [Feb 11 13:13:15] DEBUG[27905]: channel.c:1687 ast_hangup: Hanging up channel 'SIP/5051-006d6680' [Feb 11 13:13:15] DEBUG[27905]: chan_sip.c:3304 sip_hangup: Hangup call SIP/5051-006d6680, SIP callid 39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4) [Feb 11 13:13:15] DEBUG[27905]: chan_sip.c:3312 sip_hangup: update_call_counter() - decrement call limit counter on hangup [Feb 11 13:13:15] DEBUG[27905]: chan_sip.c:3000 update_call_counter: Updating call counter for incoming call [Feb 11 13:13:15] DEBUG[27905]: devicestate.c:303 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/5051-006d6680 [Feb 11 13:13:15] DEBUG[27830]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 5051 [Feb 11 13:13:15] DEBUG[27830]: chan_sip.c:15167 sip_devicestate: Checking device state for peer 5051 [Feb 11 13:13:15] DEBUG[27830]: devicestate.c:287 do_state_change: Changing state for SIP/5051 - state 4 (Invalid) [Feb 11 13:13:15] DEBUG[27909]: app_queue.c:546 changethread: Device 'SIP/5051' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Feb 11 13:13:16] Really destroying SIP dialog '39CB7DC4-4663-DC38-201B-74B5F5154FC2@10.0.0.4' Method: BYE *CLI> *CLI> exit No such command 'exit' (type 'help' for help) *CLI> stop now [Feb 11 13:13:24] Beginning asterisk shutdown.... [Feb 11 13:13:24] Executing last minute cleanups [Feb 11 13:13:24] == Destroying musiconhold processes [Feb 11 13:13:24] Asterisk cleanly ending (0). [Feb 11 13:13:24] DEBUG[27825]: asterisk.c:1192 quit_handler: Asterisk ending (0).