*CLI> sip set debug ip 192.168.0.141 SIP Debugging Enabled for IP: 192.168.0.141 *CLI> [Mar 1 19:12:45] DEBUG[28444]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Returning zero codec -- Accepting UNAUTHENTICATED call from 192.168.0.77: > requested format = gsm, > requested prefs = (), > actual format = gsm, > host prefs = (), > priority = mine [Mar 1 19:12:45] DEBUG[28444]: pbx.c:1693 pbx_extension_helper: Launching 'NoOp' -- Executing [s@from-iax:1] NoOp("IAX2/192.168.0.77:4569-1", "appel ext") in new stack [Mar 1 19:12:45] DEBUG[28444]: pbx.c:1693 pbx_extension_helper: Launching 'Dial' -- Executing [s@from-iax:2] Dial("IAX2/192.168.0.77:4569-1", "Local/6666@local-extensions") in new stack [Mar 1 19:12:45] DEBUG[28444]: rtp.c:1632 ast_rtp_make_compatible: Channel 'Local/6666@local-extensions-7b8f,1' has no RTP, not doing anything [Mar 1 19:12:45] DEBUG[28444]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-iax-s-2. [Mar 1 19:12:45] DEBUG[28444]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-from-iax-s-1. [Mar 1 19:12:45] DEBUG[28444]: pbx.c:1693 pbx_extension_helper: Launching 'NoOp' -- Executing [6666@local-extensions:1] NoOp("Local/6666@local-extensions-7b8f,2", "################ENTREE QUEUE") in new stack [Mar 1 19:12:45] DEBUG[28444]: pbx.c:1693 pbx_extension_helper: Launching 'Queue' -- Executing [6666@local-extensions:2] Queue("Local/6666@local-extensions-7b8f,2", "Standard|rTt|||15") in new stack [Mar 1 19:12:45] DEBUG[28444]: app_queue.c:3438 queue_exec: NO QUEUE_PRIO variable found. Using default. [Mar 1 19:12:45] DEBUG[28444]: app_queue.c:3461 queue_exec: queue: Standard, options: rTt, url: , announce: , expires: 1172772780, priority: 0 [Mar 1 19:12:45] DEBUG[28444]: app_queue.c:1253 join_queue: Queue 'standard' Join, Channel 'Local/6666@local-extensions-7b8f,2', Position '1' -- Called 6666@local-extensions [Mar 1 19:12:45] DEBUG[28444]: channel.c:2760 set_format: Set channel IAX2/192.168.0.77:4569-1 to write format gsm [Mar 1 19:12:45] DEBUG[28444]: channel.c:2760 set_format: Set channel IAX2/192.168.0.77:4569-1 to read format gsm -- Local/6666@local-extensions-7b8f,1 is ringing [Mar 1 19:12:45] DEBUG[28444]: app_queue.c:2156 is_our_turn: It's our turn (Local/6666@local-extensions-7b8f,2). [Mar 1 19:12:45] DEBUG[28444]: app_queue.c:2409 try_calling: Local/6666@local-extensions-7b8f,2 is trying to call a queue member. [Mar 1 19:12:45] DEBUG[28444]: app_queue.c:1768 ring_one: (Parallel) Trying 'Agent/5100' with metric 0 [Mar 1 19:12:45] DEBUG[28444]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-local-extensions-6666-2. [Mar 1 19:12:45] DEBUG[28444]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-local-extensions-6666-1. [Mar 1 19:12:45] DEBUG[28444]: channel.c:3211 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. -- outgoing agentcall, to agent '5100', on 'Local/100@local-extensions-c724,1' [Mar 1 19:12:45] DEBUG[28444]: pbx.c:1693 pbx_extension_helper: Launching 'Dial' -- Executing [100@local-extensions:1] Dial("Local/100@local-extensions-c724,2", "SIP/100|30|Ttr") in new stack [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:15966 sip_request_call: Asked to create a SIP channel with formats: 0x2 (gsm) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4663 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:2842 do_setnat: Setting NAT on RTP to Off [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:1783 obproxy_get: OBPROXY: Not applying OBproxy to this call [Mar 1 19:12:45] DEBUG[28444]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4126 sip_new: *** Our native formats are 0x2 (gsm) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4127 sip_new: *** Joint capabilities are 0x2 (gsm) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4128 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Mar 1 19:12:45] DEBUG[28444]: frame.c:1157 ast_codec_choose: Could not find preferred codec - Going for the best codec [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4129 sip_new: *** AST_CODEC_CHOOSE formats are 0x2 (gsm) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4131 sip_new: *** Our preferred formats from the incoming channel are 0x2 (gsm) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4159 sip_new: This channel will not be able to handle video. [Mar 1 19:12:45] DEBUG[28444]: rtp.c:1639 ast_rtp_make_compatible: Channel 'Local/100@local-extensions-c724,2' has no RTP, not doing anything [Mar 1 19:12:45] DEBUG[28444]: channel.c:3211 ast_channel_inherit_variables: Not copying variable STACK-local-extensions-100-1. [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:3122 sip_call: Outgoing Call for 100 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:3140 sip_call: Our T38 capability (0), joint T38 capability (0) [Mar 1 19:12:45] DEBUG[28444]: app_queue.c:1768 ring_one: (Parallel) Trying 'Agent/5101' with metric 0 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:6674 add_sdp: ** Our capability: 0x8000e (gsm|ulaw|alaw|h263) Video flag: False Text flag: False [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:6676 add_sdp: ** Our prefcodec: 0x2 (gsm) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:6693 add_sdp: This call needs video offers, but there's no video support enabled! Audio is at 192.168.0.147 port 19256 Adding codec 0x2 (gsm) to SDP Adding codec 0x4 (ulaw) to SDP Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:6837 add_sdp: -- Done with adding codecs to SDP [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:6897 add_sdp: Done building SDP. Settling with this capability: 0x8000e (gsm|ulaw|alaw|h263) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:1718 initialize_initreq: Initializing initreq for method INVITE - callid 5e7325550d6db2613f313c7b118b146e@192.168.0.147 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 0 [ 55]: INVITE sip:100@192.168.0.141:2051;line=k6fmz7p1 SIP/2.0 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 1 [ 64]: Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK3354272d;rport [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 2 [ 16]: Max-Forwards: 70 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 3 [ 50]: From: "102" ;tag=as0633946a [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 4 [ 46]: To: [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 5 [ 32]: Contact: [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 6 [ 55]: Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 7 [ 16]: CSeq: 102 INVITE [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 8 [ 41]: User-Agent: Asterisk PBX SVN-trunk-r56209 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 9 [ 35]: Date: Thu, 01 Mar 2007 18:12:45 GMT [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 10 [ 66]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 11 [ 19]: Supported: replaces [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 13 [ 19]: Content-Length: 289 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 14 [ 0]: [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 1 [ 39]: o=root 28441 28441 IN IP4 192.168.0.147 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 2 [ 9]: s=session [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 3 [ 22]: c=IN IP4 192.168.0.147 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 5 [ 31]: m=audio 19256 RTP/AVP 3 0 8 101 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 6 [ 19]: a=rtpmap:3 GSM/8000 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 7 [ 20]: a=rtpmap:0 PCMU/8000 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 10 [ 15]: a=fmtp:101 0-16 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 11 [ 25]: a=silenceSupp:off - - - - [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 12 [ 10]: a=ptime:20 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 13 [ 10]: a=sendrecv Reliably Transmitting (no NAT) to 192.168.0.141:2051: INVITE sip:100@192.168.0.141:2051;line=k6fmz7p1 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK3354272d;rport Max-Forwards: 70 From: "102" ;tag=as0633946a To: Contact: Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 CSeq: 102 INVITE User-Agent: Asterisk PBX SVN-trunk-r56209 Date: Thu, 01 Mar 2007 18:12:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 289 v=0 o=root 28441 28441 IN IP4 192.168.0.147 s=session c=IN IP4 192.168.0.147 t=0 0 m=audio 19256 RTP/AVP 3 0 8 101 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 --- [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:2115 __sip_reliable_xmit: *** SIP TIMER: Initalizing retransmit timer on packet: Id #11 -- Called 100 -- Agent/5100 is ringing <--- SIP read from 192.168.0.141:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK3354272d;rport=5060 From: "102" ;tag=as0633946a To: ;tag=jg1k0f79eb Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK3354272d;rport=5060 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 2 [ 50]: From: "102" ;tag=as0633946a [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 3 [ 61]: To: ;tag=jg1k0f79eb [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 4 [ 55]: Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 9 [ 17]: Content-Length: 0 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:2268 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #11 - INVITE (got response) [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5e7325550d6db2613f313c7b118b146e@192.168.0.147' Request 102: Found [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:12287 handle_response_invite: SIP response 180 to standard invite [Mar 1 19:12:45] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-081bfc20 -- SIP/100-081bfc20 is ringing -- Agent/5100 is ringing [Mar 1 19:12:45] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 100 [Mar 1 19:12:45] DEBUG[28444]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 100 [Mar 1 19:12:45] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for SIP/100 - state 1 (Not in use) [Mar 1 19:12:45] DEBUG[28444]: app_queue.c:568 changethread: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. <--- SIP read from 192.168.0.141:2051 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK3354272d;rport=5060 From: "102" ;tag=as0633946a To: ;tag=jg1k0f79eb Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 CSeq: 102 INVITE Contact: ;flow-id=1 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Content-Length: 0 <-------------> [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 0 [ 19]: SIP/2.0 180 Ringing [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK3354272d;rport=5060 [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 2 [ 50]: From: "102" ;tag=as0633946a [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 3 [ 61]: To: ;tag=jg1k0f79eb [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 4 [ 55]: Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 7 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 8 [ 31]: Allow-Events: talk, hold, refer [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 9 [ 17]: Content-Length: 0 [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 10 [ 0]: --- (10 headers 0 lines) --- [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:2277 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '5e7325550d6db2613f313c7b118b146e@192.168.0.147' Request 102: Found [Mar 1 19:12:46] DEBUG[28444]: chan_sip.c:12287 handle_response_invite: SIP response 180 to standard invite -- SIP/100-081bfc20 is ringing [Mar 1 19:12:47] DEBUG[28444]: rtp.c:941 ast_rtcp_read: Got RTCP report of 52 bytes <--- SIP read from 192.168.0.141:2051 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK3354272d;rport=5060 From: "102" ;tag=as0633946a To: ;tag=jg1k0f79eb Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 CSeq: 102 INVITE Contact: ;flow-id=1 User-Agent: snom320/6.5.2 Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO Allow-Events: talk, hold, refer Supported: timer, 100rel, replaces, callerid Content-Type: application/sdp Content-Length: 219 v=0 o=root 149962201 149962202 IN IP4 192.168.0.141 s=call c=IN IP4 192.168.0.141 t=0 0 m=audio 59546 RTP/AVP 3 101 a=rtpmap:3 gsm/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=ptime:20 a=sendrecv <-------------> [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 0 [ 14]: SIP/2.0 200 Ok [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 1 [ 69]: Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK3354272d;rport=5060 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 2 [ 50]: From: "102" ;tag=as0633946a [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 3 [ 61]: To: ;tag=jg1k0f79eb [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 4 [ 55]: Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 5 [ 16]: CSeq: 102 INVITE [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 6 [ 61]: Contact: ;flow-id=1 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 7 [ 25]: User-Agent: snom320/6.5.2 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 8 [ 88]: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 9 [ 31]: Allow-Events: talk, hold, refer [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 10 [ 44]: Supported: timer, 100rel, replaces, callerid [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 11 [ 29]: Content-Type: application/sdp [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 12 [ 19]: Content-Length: 219 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Header 13 [ 0]: [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 0 [ 3]: v=0 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 1 [ 47]: o=root 149962201 149962202 IN IP4 192.168.0.141 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 2 [ 6]: s=call [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 3 [ 22]: c=IN IP4 192.168.0.141 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 4 [ 5]: t=0 0 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 5 [ 27]: m=audio 59546 RTP/AVP 3 101 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 6 [ 19]: a=rtpmap:3 gsm/8000 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 7 [ 33]: a=rtpmap:101 telephone-event/8000 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 8 [ 15]: a=fmtp:101 0-16 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 9 [ 10]: a=ptime:20 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:4941 parse_request: Body 10 [ 10]: a=sendrecv --- (13 headers 11 lines) --- [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:2218 __sip_ack: Acked pending invite 102 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:2234 __sip_ack: Stopping retransmission on '5e7325550d6db2613f313c7b118b146e@192.168.0.147' of Request 102: Match Found [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:12287 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 3 Found RTP audio format 101 Peer audio RTP is at port 192.168.0.141:59546 Found description format gsm for ID 3 Found description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:5524 process_sdp: T38 state changed to 0 on channel SIP/100-081bfc20 Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0x2 (gsm)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0x2 (gsm) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.0.141:59546 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:5615 process_sdp: We're settling with these formats: 0x2 (gsm) [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:5622 process_sdp: We have an owner, now see if we need to change this call [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:3305 update_call_counter: Updating call counter for outgoing call --- set_address_from_contact host '192.168.0.141' [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:8478 build_route: build_route: Contact hop: ;flow-id=1 list_route: hop: [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:6050 reqprep: Strict routing enforced for session 5e7325550d6db2613f313c7b118b146e@192.168.0.147 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.0.141, port 2051 Transmitting (no NAT) to 192.168.0.141:2051: ACK sip:100@192.168.0.141:2051;line=k6fmz7p1 SIP/2.0 Via: SIP/2.0/UDP 192.168.0.147:5060;branch=z9hG4bK310debb0;rport Max-Forwards: 70 From: "102" ;tag=as0633946a To: ;tag=jg1k0f79eb Contact: Call-ID: 5e7325550d6db2613f313c7b118b146e@192.168.0.147 CSeq: 102 ACK User-Agent: Asterisk PBX SVN-trunk-r56209 Content-Length: 0 --- -- Call on SIP/100-081bfc20 left from hold [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/100-081bfc20 -- SIP/100-081bfc20 answered Local/100@local-extensions-c724,2 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/100@local-extensions-c724,2 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for SIP - 100 [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:15897 sip_devicestate: Checking device state for peer 100 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for SIP/100 - state 1 (Not in use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:2093 wait_for_answer: Dunno what to do with control type -1 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/100@local-extensions-c724,1 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Agent/5100 -- Agent/5100 answered Local/6666@local-extensions-7b8f,2 [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:1451 leave_queue: Queue 'standard' Leave, Channel 'Local/6666@local-extensions-7b8f,2' [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'SIP/100' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Local - 100@local-extensions [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:145 local_devicestate: Checking if extension 100@local-extensions exists (devicestate) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Local/100@local-extensions - state 2 (In use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'Local/100@local-extensions' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Local - 100@local-extensions [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:145 local_devicestate: Checking if extension 100@local-extensions exists (devicestate) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Local/100@local-extensions - state 2 (In use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'Local/100@local-extensions' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Agent - 5100 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Agent/5100 - state 3 (Busy) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:574 changethread: Device 'Agent/5100' changed to state '3' (Busy) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6666@local-extensions-7b8f,2 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6666@local-extensions-7b8f,1 -- Local/6666@local-extensions-7b8f,1 answered IAX2/192.168.0.77:4569-1 [Mar 1 19:12:47] DEBUG[28444]: chan_iax2.c:3286 iax2_answer: Answering IAX2 call [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel IAX2/192.168.0.77:4569-1 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Local - 6666@local-extensions [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:145 local_devicestate: Checking if extension 6666@local-extensions exists (devicestate) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Local/6666@local-extensions - state 2 (In use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'Local/6666@local-extensions' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Local - 6666@local-extensions [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:145 local_devicestate: Checking if extension 6666@local-extensions exists (devicestate) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Local/6666@local-extensions - state 2 (In use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'Local/6666@local-extensions' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for IAX2 - 192.168.0.77:4569 [Mar 1 19:12:47] DEBUG[28444]: chan_iax2.c:9791 iax2_devicestate: Checking device state for device 192.168.0.77 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for IAX2/192.168.0.77:4569 - state 4 (Invalid) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'IAX2/192.168.0.77:4569' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: channel.c:3144 ast_channel_masquerade: Planning to masquerade channel SIP/100-081bfc20 into the structure of Local/100@local-extensions-c724,1 [Mar 1 19:12:47] DEBUG[28444]: channel.c:3158 ast_channel_masquerade: Done planning to masquerade channel SIP/100-081bfc20 into the structure of Local/100@local-extensions-c724,1 [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: channel.c:3275 ast_do_masquerade: Actually Masquerading SIP/100-081bfc20(6) into the structure of Local/100@local-extensions-c724,1(6) [Mar 1 19:12:47] DEBUG[28444]: channel.c:3290 ast_do_masquerade: Got clone lock for masquerade on 'SIP/100-081bfc20' at 0x81c1238 [Mar 1 19:12:47] DEBUG[28444]: channel.c:3485 ast_do_masquerade: Putting channel SIP/100-081bfc20 in 2/2 formats [Mar 1 19:12:47] DEBUG[28444]: chan_sip.c:3898 sip_fixup: SIP Fixup: New owner for dialogue 5e7325550d6db2613f313c7b118b146e@192.168.0.147: SIP/100-081bfc20 (Old parent: Local/100@local-extensions-c724,1) [Mar 1 19:12:47] DEBUG[28444]: channel.c:3521 ast_do_masquerade: Released clone lock on 'Local/100@local-extensions-c724,1' [Mar 1 19:12:47] DEBUG[28444]: channel.c:3531 ast_do_masquerade: Done Masquerading SIP/100-081bfc20 (6) [Mar 1 19:12:47] DEBUG[28444]: chan_agent.c:520 agent_read: Bridge on 'SIP/100-081bfc20' being set to 'Agent/5100' (3) [Mar 1 19:12:47] DEBUG[28444]: channel.c:3713 ast_generic_bridge: Didn't get a frame from channel: Local/100@local-extensions-c724,2 [Mar 1 19:12:47] DEBUG[28444]: channel.c:4041 ast_channel_bridge: Bridge stops bridging channels Local/100@local-extensions-c724,2 and Local/100@local-extensions-c724,1 [Mar 1 19:12:47] DEBUG[28444]: channel.c:1596 ast_hangup: Hanging up zombie 'Local/100@local-extensions-c724,1' [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/100@local-extensions-c724,1 [Mar 1 19:12:47] DEBUG[28444]: app_dial.c:1710 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Mar 1 19:12:47] DEBUG[28444]: pbx.c:2289 __ast_pbx_run: Spawn extension (local-extensions,100,1) exited non-zero on 'Local/100@local-extensions-c724,2' == Spawn extension (local-extensions, 100, 1) exited non-zero on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1693 pbx_extension_helper: Launching 'Hangup' -- Executing [h@local-extensions:1] Hangup("Local/100@local-extensions-c724,2", "") in new stack [Mar 1 19:12:47] DEBUG[28444]: pbx.c:2410 __ast_pbx_run: Spawn extension (local-extensions,h,1) exited non-zero on 'Local/100@local-extensions-c724,2' == Spawn extension (local-extensions, h, 1) exited non-zero on 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"102" <102>' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '102' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '100' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'local-extensions' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'SIP/100-081bfc20' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-03-01 19:12:45' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-03-01 19:12:47' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-03-01 19:12:47' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '0' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1172772765.4' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Mar 1 19:12:47] DEBUG[28444]: channel.c:1591 ast_hangup: Hanging up channel 'Local/100@local-extensions-c724,2' [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/100@local-extensions-c724,2 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Local - 100@local-extensions [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:145 local_devicestate: Checking if extension 100@local-extensions exists (devicestate) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Local/100@local-extensions - state 1 (Not in use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'Local/100@local-extensions' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Local - 100@local-extensions [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:145 local_devicestate: Checking if extension 100@local-extensions exists (devicestate) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Local/100@local-extensions - state 1 (Not in use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'Local/100@local-extensions' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: channel.c:3144 ast_channel_masquerade: Planning to masquerade channel Agent/5100 into the structure of Local/6666@local-extensions-7b8f,1 [Mar 1 19:12:47] DEBUG[28444]: channel.c:3158 ast_channel_masquerade: Done planning to masquerade channel Agent/5100 into the structure of Local/6666@local-extensions-7b8f,1 [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:294 local_write: Not posting to queue since already masked on 'Local/6666@local-extensions-7b8f,2' [Mar 1 19:12:47] DEBUG[28444]: channel.c:3275 ast_do_masquerade: Actually Masquerading Agent/5100(6) into the structure of Local/6666@local-extensions-7b8f,1(6) [Mar 1 19:12:47] DEBUG[28444]: channel.c:3290 ast_do_masquerade: Got clone lock for masquerade on 'Agent/5100' at 0x81bd5e0 [Mar 1 19:12:47] DEBUG[28444]: channel.c:3485 ast_do_masquerade: Putting channel Agent/5100 in 2/2 formats [Mar 1 19:12:47] DEBUG[28444]: channel.c:3521 ast_do_masquerade: Released clone lock on 'Local/6666@local-extensions-7b8f,1' [Mar 1 19:12:47] DEBUG[28444]: channel.c:3531 ast_do_masquerade: Done Masquerading Agent/5100 (6) [Mar 1 19:12:47] DEBUG[28444]: channel.c:3713 ast_generic_bridge: Didn't get a frame from channel: Local/6666@local-extensions-7b8f,2 [Mar 1 19:12:47] DEBUG[28444]: channel.c:4041 ast_channel_bridge: Bridge stops bridging channels Local/6666@local-extensions-7b8f,2 and Local/6666@local-extensions-7b8f,1 [Mar 1 19:12:47] DEBUG[28444]: channel.c:1596 ast_hangup: Hanging up zombie 'Local/6666@local-extensions-7b8f,1' [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6666@local-extensions-7b8f,1 [Mar 1 19:12:47] DEBUG[28444]: pbx.c:2289 __ast_pbx_run: Spawn extension (local-extensions,6666,2) exited non-zero on 'Local/6666@local-extensions-7b8f,2' == Spawn extension (local-extensions, 6666, 2) exited non-zero on 'Local/6666@local-extensions-7b8f,2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1693 pbx_extension_helper: Launching 'Hangup' -- Executing [h@local-extensions:1] Hangup("Local/6666@local-extensions-7b8f,2", "") in new stack [Mar 1 19:12:47] DEBUG[28444]: pbx.c:2410 __ast_pbx_run: Spawn extension (local-extensions,h,1) exited non-zero on 'Local/6666@local-extensions-7b8f,2' == Spawn extension (local-extensions, h, 1) exited non-zero on 'Local/6666@local-extensions-7b8f,2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '"102" <102>' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '102' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '6666' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'local-extensions' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Local/6666@local-extensions-7b8f,2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Agent/5100' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-03-01 19:12:45' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-03-01 19:12:47' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2007-03-01 19:12:47' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '0' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '1172772765.2' [Mar 1 19:12:47] DEBUG[28444]: pbx.c:1543 pbx_substitute_variables_helper_full: Function result is '' [Mar 1 19:12:47] DEBUG[28444]: channel.c:1591 ast_hangup: Hanging up channel 'Local/6666@local-extensions-7b8f,2' [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:444 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/6666@local-extensions-7b8f,2 [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Local - 6666@local-extensions [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:145 local_devicestate: Checking if extension 6666@local-extensions exists (devicestate) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Local/6666@local-extensions - state 1 (Not in use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'Local/6666@local-extensions' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:302 ast_device_state: No provider found, checking channel drivers for Local - 6666@local-extensions [Mar 1 19:12:47] DEBUG[28444]: chan_local.c:145 local_devicestate: Checking if extension 6666@local-extensions exists (devicestate) [Mar 1 19:12:47] DEBUG[28444]: devicestate.c:428 do_state_change: Changing state for Local/6666@local-extensions - state 1 (Not in use) [Mar 1 19:12:47] DEBUG[28444]: app_queue.c:568 changethread: Device 'Local/6666@local-extensions' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Mar 1 19:12:47] DEBUG[28444]: chan_iax2.c:6779 socket_process: Ooh, voice format changed to 2 [Mar 1 19:12:47] DEBUG[28444]: rtp.c:2792 ast_rtp_write: Ooh, format changed from unknown to gsm [Mar 1 19:12:47] DEBUG[28444]: rtp.c:2809 ast_rtp_write: Created smoother: format: 2 ms: 20 len: 33 [Mar 1 19:12:48] DEBUG[28444]: rtp.c:2645 ast_rtp_raw_write: Difference is 3768, ms is 491 [Mar 1 19:12:52] DEBUG[28444]: rtp.c:2645 ast_rtp_raw_write: Difference is 26136, ms is 3287 [Mar 1 19:12:52] DEBUG[28444]: rtp.c:941 ast_rtcp_read: Got RTCP report of 52 bytes *CLI> *CLI> *CLI> *CLI> [Mar 1 19:12:57] DEBUG[28444]: rtp.c:941 ast_rtcp_read: Got RTCP report of 52 bytes sip secore show channels concise[Mar 1 19:13:01] DEBUG[28444]: rtp.c:2645 ast_rtp_raw_write: Difference is 26088, ms is 3281 Segmentation fault (core dumped) #