Linux 2.6.18-164.el5 #1 SMP Thu Sep 3 03:28:30 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux SIP DEBUG ------ [Sep 24 12:25:45] <--- SIP read from UDP://192.168.255.37:5060 ---> INVITE sip:1000@10.80.80.120 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK4d66a47b;rport From: "Paolo Audiberti" ;tag=as5abd73be To: Contact: Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 CSeq: 102 INVITE User-Agent: Tauk Max-Forwards: 70 Date: Thu, 24 Sep 2009 19:25:45 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces Content-Type: application/sdp Content-Length: 291 v=0 o=root 24953 24953 IN IP4 192.168.255.37 s=session c=IN IP4 192.168.255.37 t=0 0 m=audio 18144 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/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 <-------------> [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 0 [ 36]: INVITE sip:1000@10.80.80.120 SIP/2.0 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK4d66a47b;rport [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 2 [ 64]: From: "Paolo Audiberti" ;tag=as5abd73be [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 3 [ 27]: To: [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 4 [ 34]: Contact: [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 5 [ 56]: Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 6 [ 16]: CSeq: 102 INVITE [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 7 [ 16]: User-Agent: Tauk [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 9 [ 35]: Date: Thu, 24 Sep 2009 19:25:45 GMT [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 11 [ 19]: Supported: replaces [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 12 [ 29]: Content-Type: application/sdp [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 13 [ 19]: Content-Length: 291 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 14 [ 0]: [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 0 [ 3]: v=0 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 1 [ 40]: o=root 24953 24953 IN IP4 192.168.255.37 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 2 [ 9]: s=session [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 3 [ 23]: c=IN IP4 192.168.255.37 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 4 [ 5]: t=0 0 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 5 [ 31]: m=audio 18144 RTP/AVP 0 3 8 101 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 6 [ 20]: a=rtpmap:0 PCMU/8000 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 7 [ 19]: a=rtpmap:3 GSM/8000 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 8 [ 20]: a=rtpmap:8 PCMA/8000 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 9 [ 33]: a=rtpmap:101 telephone-event/8000 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 10 [ 15]: a=fmtp:101 0-16 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 11 [ 25]: a=silenceSupp:off - - - - [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 12 [ 10]: a=ptime:20 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Body 13 [ 10]: a=sendrecv [Sep 24 12:25:45] --- (14 headers 14 lines) --- [Sep 24 12:25:45] DEBUG[23906]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:2815 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.80.80.120:5060 [Sep 24 12:25:45] == Using SIP RTP TOS bits 184 [Sep 24 12:25:45] == Using SIP RTP CoS mark 5 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:4076 do_setnat: Setting NAT on RTP to Off [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6220 sip_alloc: Allocating new SIP dialog for 0236c6de3a223d707489edf73507ddcd@192.168.255.37 - INVITE (With RTP) [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:19123 handle_incoming: **** Received INVITE (5) - Command in SIP INVITE [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:2534 parse_sip_options: Begin: parsing SIP "Supported: replaces" [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:2542 parse_sip_options: Found SIP option: -replaces- [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:2548 parse_sip_options: Matched SIP option: replaces [Sep 24 12:25:45] Sending to 192.168.255.37 : 5060 (no NAT) [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:17565 handle_request_invite: Initializing initreq for method INVITE - callid 0236c6de3a223d707489edf73507ddcd@192.168.255.37 [Sep 24 12:25:45] Using INVITE request as basis request - 0236c6de3a223d707489edf73507ddcd@192.168.255.37 [Sep 24 12:25:45] No user '2008' in SIP users list [Sep 24 12:25:45] Found peer 'specialai' for '2008' from 192.168.255.37:5060 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:4076 do_setnat: Setting NAT on RTP to Off [Sep 24 12:25:45] Found RTP audio format 0 [Sep 24 12:25:45] Found RTP audio format 3 [Sep 24 12:25:45] Found RTP audio format 8 [Sep 24 12:25:45] Found RTP audio format 101 [Sep 24 12:25:45] Peer audio RTP is at port 192.168.255.37:18144 [Sep 24 12:25:45] Found audio description format PCMU for ID 0 [Sep 24 12:25:45] Found audio description format GSM for ID 3 [Sep 24 12:25:45] Found audio description format PCMA for ID 8 [Sep 24 12:25:45] Found audio description format telephone-event for ID 101 [Sep 24 12:25:45] Got unsupported a:fmtp in SDP offer [Sep 24 12:25:45] Capabilities: us - 0x8000e (gsm|ulaw|alaw|h263), peer - audio=0xe (gsm|ulaw|alaw)/video=0x0 (nothing)/text=0x0 (nothing), combined - 0xe (gsm|ulaw|alaw) [Sep 24 12:25:45] Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) [Sep 24 12:25:45] Peer audio RTP is at port 192.168.255.37:18144 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:7444 process_sdp: We're settling with these formats: 0xe (gsm|ulaw|alaw) [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:17647 handle_request_invite: Checking SIP call limits for device [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:4642 update_call_counter: Updating call counter for incoming call [Sep 24 12:25:45] Looking for 1000 in inbound-calls (domain 10.80.80.120) [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:5630 sip_new: *** Our native formats are 0x4 (ulaw) [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:5631 sip_new: *** Joint capabilities are 0xe (gsm|ulaw|alaw) [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:5632 sip_new: *** Our capabilities are 0x8000e (gsm|ulaw|alaw|h263) [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:5633 sip_new: *** AST_CODEC_CHOOSE formats are 0x4 (ulaw) [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:5661 sip_new: This channel will not be able to handle video. [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:10661 build_route: build_route: Contact hop: [Sep 24 12:25:45] list_route: hop: [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:17876 handle_request_invite: SIP/specialai-1b08bbd8: New call is still down.... Trying... [Sep 24 12:25:45] <--- Transmitting (no NAT) to 192.168.255.37:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK4d66a47b;received=192.168.255.37;rport=5060 From: "Paolo Audiberti" ;tag=as5abd73be To: Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 CSeq: 102 INVITE User-Agent: Tauk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Length: 0 <------------> [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:2684 __sip_xmit: Trying to put 'SIP/2.0 10' onto UDP socket destined for 192.168.255.37:5060 [Sep 24 12:25:45] DEBUG[23906]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/specialai [Sep 24 12:25:45] DEBUG[23901]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for SIP - specialai [Sep 24 12:25:45] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'Goto' [Sep 24 12:25:45] -- Executing [1000@inbound-calls:1] Goto("SIP/specialai-1b08bbd8", "s,1") in new stack [Sep 24 12:25:45] -- Goto (inbound-calls,s,1) [Sep 24 12:25:45] DEBUG[23930]: pbx.c:2935 pbx_substitute_variables_helper_full: Function result is '2008' [Sep 24 12:25:45] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'NoOp' [Sep 24 12:25:45] -- Executing [s@inbound-calls:1] NoOp("SIP/specialai-1b08bbd8", "Answered inbound-call from 2008") in new stack [Sep 24 12:25:45] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'Goto' [Sep 24 12:25:45] -- Executing [s@inbound-calls:2] Goto("SIP/specialai-1b08bbd8", "od-welcome,s,1") in new stack [Sep 24 12:25:45] -- Goto (od-welcome,s,1) [Sep 24 12:25:45] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'NoOp' [Sep 24 12:25:45] -- Executing [s@od-welcome:1] NoOp("SIP/specialai-1b08bbd8", "WELCOME") in new stack [Sep 24 12:25:45] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'Set' [Sep 24 12:25:45] -- Executing [s@od-welcome:2] Set("SIP/specialai-1b08bbd8", "CHANNEL(language)=en") in new stack [Sep 24 12:25:45] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'Playback' [Sep 24 12:25:45] -- Executing [s@od-welcome:3] Playback("SIP/specialai-1b08bbd8", "specialai/welcome-cricket-debt") in new stack [Sep 24 12:25:45] DEBUG[23930]: devicestate.c:452 ast_devstate_changed_literal: Notification of state change to be queued on device/channel SIP/specialai [Sep 24 12:25:45] DEBUG[23930]: chan_sip.c:5189 sip_answer: SIP answering channel: SIP/specialai-1b08bbd8 [Sep 24 12:25:45] DEBUG[23930]: chan_sip.c:8897 transmit_response_with_sdp: Setting framing from config on incoming call [Sep 24 12:25:45] DEBUG[23930]: chan_sip.c:8573 add_sdp: ** Our capability: 0xe (gsm|ulaw|alaw) Video flag: True Text flag: True [Sep 24 12:25:45] DEBUG[23930]: chan_sip.c:8574 add_sdp: ** Our prefcodec: 0x0 (nothing) [Sep 24 12:25:45] Audio is at 10.80.80.120 port 15634 [Sep 24 12:25:45] Adding codec 0x4 (ulaw) to SDP [Sep 24 12:25:45] Adding codec 0x2 (gsm) to SDP [Sep 24 12:25:45] Adding codec 0x8 (alaw) to SDP [Sep 24 12:25:45] Adding non-codec 0x1 (telephone-event) to SDP [Sep 24 12:25:45] DEBUG[23930]: chan_sip.c:8706 add_sdp: -- Done with adding codecs to SDP [Sep 24 12:25:45] DEBUG[23930]: channel.c:3017 ast_internal_timing_enabled: Internal timing is disabled (option_internal_timing=0 chan->timingfd=27) [Sep 24 12:25:45] DEBUG[23930]: chan_sip.c:8841 add_sdp: Done building SDP. Settling with this capability: 0xe (gsm|ulaw|alaw) [Sep 24 12:25:45] <--- Reliably Transmitting (no NAT) to 192.168.255.37:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK4d66a47b;received=192.168.255.37;rport=5060 From: "Paolo Audiberti" ;tag=as5abd73be To: ;tag=as3f1ffc9b Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 CSeq: 102 INVITE User-Agent: Tauk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Content-Type: application/sdp Content-Length: 311 v=0 o=root 2056857934 2056857934 IN IP4 10.80.80.120 s=Asterisk PBX 1.6.0.15 c=IN IP4 10.80.80.120 t=0 0 m=audio 15634 RTP/AVP 0 3 8 101 a=rtpmap:0 PCMU/8000 a=rtpmap:3 GSM/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 <------------> [Sep 24 12:25:45] DEBUG[23930]: chan_sip.c:3037 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #10 [Sep 24 12:25:45] DEBUG[23930]: chan_sip.c:2684 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.255.37:5060 [Sep 24 12:25:45] DEBUG[23901]: chan_sip.c:20391 sip_devicestate: Checking device state for peer specialai [Sep 24 12:25:45] DEBUG[23901]: devicestate.c:443 do_state_change: Changing state for SIP/specialai - state 1 (Not in use) [Sep 24 12:25:45] DEBUG[23901]: devicestate.c:325 _ast_device_state: No provider found, checking channel drivers for SIP - specialai [Sep 24 12:25:45] DEBUG[23901]: chan_sip.c:20391 sip_devicestate: Checking device state for peer specialai [Sep 24 12:25:45] DEBUG[23901]: devicestate.c:443 do_state_change: Changing state for SIP/specialai - state 1 (Not in use) [Sep 24 12:25:45] DEBUG[23925]: app_queue.c:766 handle_statechange: Device 'SIP/specialai' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 24 12:25:45] DEBUG[23925]: app_queue.c:766 handle_statechange: Device 'SIP/specialai' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Sep 24 12:25:45] <--- SIP read from UDP://192.168.255.37:5060 ---> ACK sip:1000@10.80.80.120 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK1a096881;rport From: "Paolo Audiberti" ;tag=as5abd73be To: ;tag=as3f1ffc9b Contact: Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 CSeq: 102 ACK User-Agent: Tauk Max-Forwards: 70 Content-Length: 0 <-------------> [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 0 [ 33]: ACK sip:1000@10.80.80.120 SIP/2.0 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK1a096881;rport [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 2 [ 64]: From: "Paolo Audiberti" ;tag=as5abd73be [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 3 [ 42]: To: ;tag=as3f1ffc9b [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 4 [ 34]: Contact: [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 5 [ 56]: Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 6 [ 13]: CSeq: 102 ACK [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 7 [ 16]: User-Agent: Tauk [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 9 [ 17]: Content-Length: 0 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 10 [ 0]: [Sep 24 12:25:45] --- (10 headers 0 lines) --- [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:6286 find_call: = Found Their Call ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 Their Tag as5abd73be Our tag: as3f1ffc9b [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:19123 handle_incoming: **** Received ACK (6) - Command in SIP ACK [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:3176 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #10 [Sep 24 12:25:45] DEBUG[23906]: chan_sip.c:3205 __sip_ack: Stopping retransmission on '0236c6de3a223d707489edf73507ddcd@192.168.255.37' of Response 102: Match Found [Sep 24 12:25:46] DEBUG[23930]: channel.c:3616 set_format: Set channel SIP/specialai-1b08bbd8 to write format slin [Sep 24 12:25:46] DEBUG[23930]: rtp.c:3284 ast_rtp_write: Ooh, format changed from unknown to ulaw [Sep 24 12:25:46] DEBUG[23930]: rtp.c:3300 ast_rtp_write: Created smoother: format: 4 ms: 20 len: 160 [Sep 24 12:25:46] DEBUG[23930]: channel.c:2362 ast_settimeout: Scheduling timer at 160 sample intervals [Sep 24 12:25:46] -- Playing 'specialai/welcome-cricket-debt.slin' (language 'en') [Sep 24 12:25:49] <--- SIP read from UDP://192.168.255.37:5060 ---> OPTIONS sip:10.80.80.120 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK01010f7f;rport From: "Tauk" ;tag=as6c9b7526 To: Contact: Call-ID: 5568e89342ff3c7525171c4a388c5b9b@192.168.255.37 CSeq: 102 OPTIONS User-Agent: Tauk Max-Forwards: 70 Date: Thu, 24 Sep 2009 19:25:49 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO upported: replaces Content-Length: 0 <-------------> [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 0 [ 32]: OPTIONS sip:10.80.80.120 SIP/2.0 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK01010f7f;rport [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 2 [ 53]: From: "Tauk" ;tag=as6c9b7526 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 3 [ 22]: To: [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 4 [ 34]: Contact: [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 5 [ 56]: Call-ID: 5568e89342ff3c7525171c4a388c5b9b@192.168.255.37 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 6 [ 17]: CSeq: 102 OPTIONS [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 7 [ 16]: User-Agent: Tauk [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 8 [ 16]: Max-Forwards: 70 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 9 [ 35]: Date: Thu, 24 Sep 2009 19:25:49 GMT [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 10 [ 72]: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 11 [ 19]: Supported: replaces [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 12 [ 17]: Content-Length: 0 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 13 [ 0]: [Sep 24 12:25:49] --- (13 headers 0 lines) --- [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6286 find_call: = No match Their Call ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 Their Tag as5abd73be Our tag: as3f1ffc9b [Sep 24 12:25:49] DEBUG[23906]: acl.c:490 ast_ouraddrfor: Found IP address for this socket [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:2815 ast_sip_ouraddrfor: Setting SIP_TRANSPORT_UDP with address 10.80.80.120:5060 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6220 sip_alloc: Allocating new SIP dialog for 5568e89342ff3c7525171c4a388c5b9b@192.168.255.37 - OPTIONS (No RTP) [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:19123 handle_incoming: **** Received OPTIONS (3) - Command in SIP OPTIONS [Sep 24 12:25:49] Looking for s in bogon-calls (domain 10.80.80.120) [Sep 24 12:25:49] <--- Transmitting (no NAT) to 192.168.255.37:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK01010f7f;received=192.168.255.37;rport=5060 From: "Tauk" ;tag=as6c9b7526 To: ;tag=as31e38fde Call-ID: 5568e89342ff3c7525171c4a388c5b9b@192.168.255.37 CSeq: 102 OPTIONS User-Agent: Tauk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Contact: Accept: application/sdp Content-Length: 0 <------------> [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:2684 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.255.37:5060 [Sep 24 12:25:49] Scheduling destruction of SIP dialog '5568e89342ff3c7525171c4a388c5b9b@192.168.255.37' in 32000 ms (Method: OPTIONS) [Sep 24 12:25:49] DEBUG[23930]: channel.c:2362 ast_settimeout: Scheduling timer at 4 sample intervals [Sep 24 12:25:49] DEBUG[23930]: channel.c:2362 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 24 12:25:49] DEBUG[23930]: channel.c:2362 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 24 12:25:49] DEBUG[23930]: channel.c:3616 set_format: Set channel SIP/specialai-1b08bbd8 to write format ulaw [Sep 24 12:25:49] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'Gosub' [Sep 24 12:25:49] -- Executing [s@od-welcome:4] Gosub("SIP/specialai-1b08bbd8", "od-language,s,1") in new stack [Sep 24 12:25:49] DEBUG[23930]: app_stack.c:239 gosub_exec: Channel SIP/specialai-1b08bbd8 has no datastore, so we're allocating one. [Sep 24 12:25:49] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'BackGround' [Sep 24 12:25:49] -- Executing [s@od-language:1] BackGround("SIP/specialai-1b08bbd8", "specialai/press9-for-spanish") in new stack [Sep 24 12:25:49] DEBUG[23930]: channel.c:3616 set_format: Set channel SIP/specialai-1b08bbd8 to write format slin [Sep 24 12:25:49] DEBUG[23930]: channel.c:2362 ast_settimeout: Scheduling timer at 160 sample intervals [Sep 24 12:25:49] -- Playing 'specialai/press9-for-spanish.slin' (language 'en') [Sep 24 12:25:49] <--- SIP read from UDP://192.168.255.37:5060 ---> BYE sip:1000@10.80.80.120 SIP/2.0 Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK7a3a03d1;rport From: "Paolo Audiberti" ;tag=as5abd73be To: ;tag=as3f1ffc9b Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 CSeq: 103 BYE User-Agent: Tauk Max-Forwards: 70 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 Content-Length: 0 <-------------> [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 0 [ 33]: BYE sip:1000@10.80.80.120 SIP/2.0 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 1 [ 65]: Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK7a3a03d1;rport [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 2 [ 64]: From: "Paolo Audiberti" ;tag=as5abd73be [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 3 [ 42]: To: ;tag=as3f1ffc9b [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 4 [ 56]: Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 5 [ 13]: CSeq: 103 BYE [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 6 [ 16]: User-Agent: Tauk [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 7 [ 16]: Max-Forwards: 70 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 8 [ 39]: X-Asterisk-HangupCause: Normal Clearing [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 9 [ 30]: X-Asterisk-HangupCauseCode: 16 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 10 [ 17]: Content-Length: 0 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6536 parse_request: Header 11 [ 0]: [Sep 24 12:25:49] --- (11 headers 0 lines) --- [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6286 find_call: = No match Their Call ID: 5568e89342ff3c7525171c4a388c5b9b@192.168.255.37 Their Tag as6c9b7526 Our tag: as31e38fde [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:6286 find_call: = Found Their Call ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 Their Tag as5abd73be Our tag: as3f1ffc9b [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:19123 handle_incoming: **** Received BYE (8) - Command in SIP BYE [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:18588 handle_request_bye: Initializing initreq for method BYE - callid 0236c6de3a223d707489edf73507ddcd@192.168.255.37 [Sep 24 12:25:49] Sending to 192.168.255.37 : 5060 (no NAT) [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:2432 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 0236c6de3a223d707489edf73507ddcd@192.168.255.37 [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:18645 handle_request_bye: Received bye, issuing owner hangup [Sep 24 12:25:49] <--- Transmitting (no NAT) to 192.168.255.37:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.255.37:5060;branch=z9hG4bK7a3a03d1;received=192.168.255.37;rport=5060 From: "Paolo Audiberti" ;tag=as5abd73be To: ;tag=as3f1ffc9b Call-ID: 0236c6de3a223d707489edf73507ddcd@192.168.255.37 CSeq: 103 BYE User-Agent: Tauk Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY, INFO Supported: replaces, timer Content-Length: 0 <------------> [Sep 24 12:25:49] DEBUG[23906]: chan_sip.c:2684 __sip_xmit: Trying to put 'SIP/2.0 20' onto UDP socket destined for 192.168.255.37:5060 [Sep 24 12:25:49] DEBUG[23930]: channel.c:2362 ast_settimeout: Scheduling timer at 0 sample intervals [Sep 24 12:25:49] DEBUG[23930]: channel.c:3616 set_format: Set channel SIP/specialai-1b08bbd8 to write format ulaw [Sep 24 12:25:49] DEBUG[23930]: pbx.c:3687 __ast_pbx_run: Extension ÿ, priority 0 returned normally even though call was hung up [Sep 24 12:25:49] DEBUG[23930]: channel.c:1610 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/specialai-1b08bbd8' [Sep 24 12:25:49] DEBUG[23930]: pbx.c:2935 pbx_substitute_variables_helper_full: Function result is '2008' [Sep 24 12:25:49] DEBUG[23930]: pbx.c:2935 pbx_substitute_variables_helper_full: Function result is '1000' [Sep 24 12:25:49] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'NoOp' [Sep 24 12:25:49] -- Executing [h@od-language:1] NoOp("SIP/specialai-1b08bbd8", "Hangup call from 2008 to 1000") in new stack [Sep 24 12:25:49] DEBUG[23930]: pbx.c:3101 pbx_extension_helper: Launching 'Hangup' [Sep 24 12:25:49] -- Executing [h@od-language:2] Hangup("SIP/specialai-1b08bbd8", "") in new stack [Sep 24 12:25:49] DEBUG[23930]: pbx.c:3842 __ast_pbx_run: Spawn extension (od-language,h,2) exited non-zero on 'SIP/specialai-1b08bbd8' [Sep 24 12:25:49] == Spawn extension (od-language, h, 2) exited non-zero on 'SIP/specialai-1b08bbd8' [Sep 24 12:25:49] DEBUG[23930]: channel.c:1703 ast_hangup: Hanging up channel 'SIP/specialai-1b08bbd8' [Sep 24 12:25:49] DEBUG[23930]: chan_sip.c:5011 sip_hangup: Hangup call SIP/specialai-1b08bbd8, SIP callid 0236c6de3a223d707489edf73507ddcd@192.168.255.37 vapp01*CLI> Disconnected from Asterisk server [Sep 24 12:25:49] Executing last minute cleanups Asterisk ending (0). Asterisk ended with exit status 127 Asterisk died with code 127. Automatically restarting Asterisk.