obelix:~# asterisk -r Asterisk 1.4.19, Copyright (C) 1999 - 2008 Digium, Inc. and others. Created by Mark Spencer Asterisk comes with ABSOLUTELY NO WARRANTY; type 'core 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 'core show license' for details. ========================================================================= Connected to Asterisk 1.4.19 currently running on obelix (pid = 2211) Verbosity is at least 4 Core debug is at least 4 obelix*CLI> <--- SIP read from 192.168.119.225:57162 ---> INVITE sip:809961@192.168.119.251:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.225:5060;branch=z9hG4bK21E2C49D Remote-Party-ID: "Wywolanie" ;party=calling;screen=yes;privacy=off From: "Wywolanie" ;tag=7E7F32FC-933 To: Date: Thu, 10 Apr 2008 14:29:11 GMT Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 Supported: 100rel,timer,resource-priority,replaces Min-SE: 1800 Cisco-Guid: 1379381102-104927709-2459172877-3989561264 User-Agent: Cisco-SIPGateway/IOS-12.x Accept-Language: pl Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER CSeq: 101 INVITE Max-Forwards: 70 Timestamp: 1207837751 Contact: Expires: 180 Allow-Events: telephone-event Content-Type: application/sdp Content-Disposition: session;handling=required Content-Length: 290 v=0 o=CiscoSystemsSIP-GW-UserAgent 7620 870 IN IP4 192.168.119.225 s=SIP Call c=IN IP4 192.168.119.225 t=0 0 m=audio 17462 RTP/AVP 18 8 101 c=IN IP4 192.168.119.225 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 <-------------> [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: INVITE sip:809961@192.168.119.251:5060 SIP/2.0 (49) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.119.225:5060;branch=z9hG4bK21E2C49D (60) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: Remote-Party-ID: "Wywolanie" ;party=calling;screen=yes;privacy=off (97) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: From: "Wywolanie" ;tag=7E7F32FC-933 (66) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: To: (35) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Date: Thu, 10 Apr 2008 14:29:11 GMT (35) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 (59) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Supported: 100rel,timer,resource-priority,replaces (50) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Min-SE: 1800 (13) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Cisco-Guid: 1379381102-104927709-2459172877-3989561264 (54) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: User-Agent: Cisco-SIPGateway/IOS-12.x (37) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 11: Accept-Language: pl (19) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 12: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER (97) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 13: CSeq: 101 INVITE (16) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 14: Max-Forwards: 70 (16) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 15: Timestamp: 1207837751 (21) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 16: Contact: (45) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 17: Expires: 180 (12) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 18: Allow-Events: telephone-event (29) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 19: Content-Type: application/sdp (29) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 20: Content-Disposition: session;handling=required (46) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 21: Content-Length: 290 (19) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 22: (0) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: v=0 (3) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 7620 870 IN IP4 192.168.119.225 (62) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: s=SIP Call (10) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: c=IN IP4 192.168.119.225 (24) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: t=0 0 (5) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: m=audio 17462 RTP/AVP 18 8 101 (30) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: c=IN IP4 192.168.119.225 (24) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=fmtp:18 annexb=no (19) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=fmtp:101 0-16 (15) --- (22 headers 12 lines) --- [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to Off [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:2770 do_setnat: Setting NAT on UDPTL to Off [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 - INVITE (With RTP) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:15258 handle_request: **** Received INVITE (5) - Command in SIP INVITE [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1703 parse_sip_options: Begin: parsing SIP "Supported: 100rel,timer,resource-priority,replaces" [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1711 parse_sip_options: Found SIP option: -100rel- [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1717 parse_sip_options: Matched SIP option: 100rel [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1711 parse_sip_options: Found SIP option: -timer- [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1717 parse_sip_options: Matched SIP option: timer [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1711 parse_sip_options: Found SIP option: -resource-priority- [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1717 parse_sip_options: Matched SIP option: resource-priority [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1711 parse_sip_options: Found SIP option: -replaces- [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:1717 parse_sip_options: Matched SIP option: replaces Sending to 192.168.119.225 : 5060 (no NAT) Using INVITE request as basis request - 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 Found peer 'kabaty-v' [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to Off [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:2770 do_setnat: Setting NAT on UDPTL to Off Found RTP audio format 18 Found RTP audio format 8 Found RTP audio format 101 [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:5191 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.119.225:17462 Found audio description format G729 for ID 18 Got unsupported a:fmtp in SDP offer Found audio description format PCMA for ID 8 Found audio description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:5451 process_sdp: T38 state changed to 0 on channel Capabilities: us - 0x8 (alaw), peer - audio=0x108 (alaw|g729)/video=0x0 (nothing), combined - 0x8 (alaw) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.119.225:17462 [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:5531 process_sdp: We're settling with these formats: 0x8 (alaw) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:13927 handle_request_invite: Checking SIP call limits for device [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:3205 update_call_counter: Updating call counter for incoming call Looking for 809961 in remote (domain 192.168.119.251) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4032 sip_new: *** Our native formats are 0x8 (alaw) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4033 sip_new: *** Joint capabilities are 0x8 (alaw) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4034 sip_new: *** Our capabilities are 0x8 (alaw) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4035 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4058 sip_new: This channel will not be able to handle video. [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:8305 build_route: build_route: Contact hop: list_route: hop: [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:14006 handle_request_invite: SIP/192.168.119.225-081da6b0: New call is still down.... Trying... <--- Transmitting (no NAT) to 192.168.119.225:5060 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.119.225:5060;branch=z9hG4bK21E2C49D;received=192.168.119.225 From: "Wywolanie" ;tag=7E7F32FC-933 To: Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 10 16:21:05] DEBUG[17555]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/192.168.119.225-081da6b0 [Apr 10 16:21:05] DEBUG[17555]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/192.168.119.225 [Apr 10 16:21:05] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 192.168.119.225-081da6b0 [Apr 10 16:21:05] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 192.168.119.225-081da6b0 [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1842 pbx_extension_helper: Launching 'Set' -- Executing [809961@remote:1] Set("SIP/192.168.119.225-081da6b0", "__TRANSFER_CONTEXT=test_1") in new stack [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1842 pbx_extension_helper: Launching 'Goto' -- Executing [809961@remote:2] Goto("SIP/192.168.119.225-081da6b0", "test_1|809961|1") in new stack -- Goto (test_1,809961,1) [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1842 pbx_extension_helper: Launching 'Macro' -- Executing [809961@test_1:1] Macro("SIP/192.168.119.225-081da6b0", "dial-cfbu|809961|50") in new stack [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1842 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial-cfbu:1] Set("SIP/192.168.119.225-081da6b0", "TECH=SIP") in new stack [Apr 10 16:21:05] DEBUG[21582]: app_macro.c:337 _macro_exec: Executed application: Set [Apr 10 16:21:05] DEBUG[21582]: db.c:198 ast_db_get: Unable to find key '809961' in family 'CF' [Apr 10 16:21:05] DEBUG[21582]: func_db.c:70 function_db_read: DB: CF/809961 not found in database. [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1842 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-dial-cfbu:2] Set("SIP/192.168.119.225-081da6b0", "CF=") in new stack [Apr 10 16:21:05] DEBUG[21582]: app_macro.c:337 _macro_exec: Executed application: Set [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1759 pbx_substitute_variables_helper_full: Expression result is '1' [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1842 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-dial-cfbu:3] GotoIf("SIP/192.168.119.225-081da6b0", "1?1000") in new stack -- Goto (macro-dial-cfbu,s,1000) [Apr 10 16:21:05] DEBUG[21582]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Apr 10 16:21:05] DEBUG[21582]: pbx.c:1842 pbx_extension_helper: Launching 'Dial' -- Executing [s@macro-dial-cfbu:1000] Dial("SIP/192.168.119.225-081da6b0", "SIP/809961|50|tT") in new stack [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:15963 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:2806 create_addr_from_peer: Our T38 capability (3856) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to On [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:2770 do_setnat: Setting NAT on UDPTL to On [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4032 sip_new: *** Our native formats are 0x100 (g729) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4033 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4034 sip_new: *** Our capabilities are 0x100 (g729) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4035 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4037 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4058 sip_new: This channel will not be able to handle video. [Apr 10 16:21:05] DEBUG[21582]: rtp.c:1633 ast_rtp_make_compatible: Seeded SDP of 'SIP/809961-081d73d8' with that of 'SIP/192.168.119.225-081da6b0' [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable CF. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable TECH. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable ARG2. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable ARG1. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_PRIORITY. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_CONTEXT. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable MACRO_EXTEN. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3294 ast_channel_inherit_variables: Copying hard-transferable variable TRANSFER_CONTEXT. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Apr 10 16:21:05] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPURI. [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:3018 sip_call: Outgoing Call for 809961 [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:3033 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:6490 add_sdp: ** Our capability: 0x100 (g729) Video flag: False [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x8 (alaw) Audio is at 192.168.119.251 port 14966 Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0x100 (g729) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 0: INVITE sip:809961@192.168.165.3:5160 SIP/2.0 (45) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK08e3aa8a;rport (66) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 2: From: "Wywolanie" ;tag=as18a58f7d (64) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 3: To: (36) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 4: Contact: (40) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 (57) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 6: CSeq: 102 INVITE (16) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 9: Date: Thu, 10 Apr 2008 14:21:05 GMT (35) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 11: Supported: replaces (19) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 13: Content-Length: 267 (19) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4813 parse_request: Header 14: (0) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: v=0 (3) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: o=root 2211 2211 IN IP4 192.168.119.251 (39) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: s=session (9) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: c=IN IP4 192.168.119.251 (24) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: t=0 0 (5) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: m=audio 14966 RTP/AVP 18 101 (28) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: a=fmtp:18 annexb=no (19) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: a=fmtp:101 0-16 (15) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: a=silenceSupp:off - - - - (25) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: a=ptime:20 (10) [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:4845 parse_request: Line: a=sendrecv (10) Reliably Transmitting (NAT) to 192.168.165.3:5160: INVITE sip:809961@192.168.165.3:5160 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK08e3aa8a;rport From: "Wywolanie" ;tag=as18a58f7d To: Contact: Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 10 Apr 2008 14:21:05 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 267 v=0 o=root 2211 2211 IN IP4 192.168.119.251 s=session c=IN IP4 192.168.119.251 t=0 0 m=audio 14966 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 10 16:21:05] DEBUG[21582]: chan_sip.c:2044 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 -- Called 809961 [Apr 10 16:21:05] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/809961-081d73d8 to read format slin [Apr 10 16:21:05] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/192.168.119.225-081da6b0 to write format slin [Apr 10 16:21:05] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/192.168.119.225-081da6b0 to read format slin [Apr 10 16:21:05] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/809961-081d73d8 to write format slin [Apr 10 16:21:05] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/192.168.119.225-081da6b0 - state 4 (Invalid) [Apr 10 16:21:05] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 192.168.119.225 [Apr 10 16:21:05] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 192.168.119.225 [Apr 10 16:21:05] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/192.168.119.225 - state 2 (In use) [Apr 10 16:21:05] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/192.168.119.225-081da6b0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:05] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/192.168.119.225' changed to state '2' (In use) but we don't care because they're not a member of any queue. obelix*CLI> <--- SIP read from 192.168.165.3:5160 ---> SIP/2.0 100 Trying To: From: "Wywolanie" ;tag=as18a58f7d Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK08e3aa8a Server: Linksys/SPA8000-5.1.9 Content-Length: 0 <-------------> [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 100 Trying (18) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: To: (36) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "Wywolanie" ;tag=as18a58f7d (64) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 (57) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: CSeq: 102 INVITE (16) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK08e3aa8a (60) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Server: Linksys/SPA8000-5.1.9 (29) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Content-Length: 0 (17) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:2228 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #15104 - INVITE (got response) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:2236 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7707b22b6fac589e4d176c9143e4f64c@192.168.119.251' Request 102: Found [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:12062 handle_response_invite: SIP response 100 to standard invite obelix*CLI> <--- SIP read from 192.168.165.3:5160 ---> SIP/2.0 180 Ringing To: ;tag=aded5b814ef805d9i0 From: "Wywolanie" ;tag=as18a58f7d Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK08e3aa8a Server: Linksys/SPA8000-5.1.9 Remote-Party-ID: 809961 ;screen=yes;party=called Content-Length: 0 <-------------> [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: To: ;tag=aded5b814ef805d9i0 (59) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "Wywolanie" ;tag=as18a58f7d (64) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 (57) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: CSeq: 102 INVITE (16) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK08e3aa8a (60) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Server: Linksys/SPA8000-5.1.9 (29) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Remote-Party-ID: 809961 ;screen=yes;party=called (82) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Content-Length: 0 (17) [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:2236 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7707b22b6fac589e4d176c9143e4f64c@192.168.119.251' Request 102: Found [Apr 10 16:21:05] DEBUG[17555]: chan_sip.c:12062 handle_response_invite: SIP response 180 to standard invite [Apr 10 16:21:05] DEBUG[17555]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809961-081d73d8 [Apr 10 16:21:05] DEBUG[17555]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809961 -- SIP/809961-081d73d8 is ringing [Apr 10 16:21:05] DEBUG[21582]: rtp.c:1562 ast_rtp_early_bridge: Setting early bridge SDP of 'SIP/192.168.119.225-081da6b0' with that of 'SIP/809961-081d73d8' <--- Transmitting (no NAT) to 192.168.119.225:5060 ---> SIP/2.0 180 Ringing Via: SIP/2.0/UDP 192.168.119.225:5060;branch=z9hG4bK21E2C49D;received=192.168.119.225 From: "Wywolanie" ;tag=7E7F32FC-933 To: ;tag=as35a8b3ee Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 10 16:21:05] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809961-081d73d8 [Apr 10 16:21:05] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809961-081d73d8 [Apr 10 16:21:05] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809961-081d73d8 - state 4 (Invalid) [Apr 10 16:21:05] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809961 [Apr 10 16:21:05] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809961 [Apr 10 16:21:05] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809961 - state 1 (Not in use) [Apr 10 16:21:05] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809961-081d73d8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:05] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809961' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. obelix*CLI> <--- SIP read from 192.168.165.3:5160 ---> SIP/2.0 200 OK To: ;tag=aded5b814ef805d9i0 From: "Wywolanie" ;tag=as18a58f7d Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK08e3aa8a Contact: 809961 Server: Linksys/SPA8000-5.1.9 Remote-Party-ID: 809961 ;screen=yes;party=called Content-Length: 273 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura, replaces Content-Type: application/sdp v=0 o=- 57575 57575 IN IP4 192.168.165.3 s=- c=IN IP4 192.168.165.3 t=0 0 m=audio 17466 RTP/AVP 18 100 101 a=rtpmap:18 G729a/8000 a=fmtp:18 annexb=no a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: To: ;tag=aded5b814ef805d9i0 (59) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "Wywolanie" ;tag=as18a58f7d (64) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 (57) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: CSeq: 102 INVITE (16) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK08e3aa8a (60) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Contact: 809961 (51) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Server: Linksys/SPA8000-5.1.9 (29) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Remote-Party-ID: 809961 ;screen=yes;party=called (82) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Content-Length: 273 (19) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 11: Supported: x-sipura, replaces (29) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 13: (0) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: v=0 (3) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: o=- 57575 57575 IN IP4 192.168.165.3 (34) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: s=- (3) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: c=IN IP4 192.168.165.3 (20) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: t=0 0 (5) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: m=audio 17466 RTP/AVP 18 100 101 (32) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=fmtp:18 annexb=no (19) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:100 NSE/8000 (21) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=fmtp:100 192-193 (18) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=fmtp:101 0-15 (15) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=ptime:30 (10) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=sendrecv (10) --- (13 headers 14 lines) --- [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:2159 __sip_ack: Acked pending invite 102 [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '7707b22b6fac589e4d176c9143e4f64c@192.168.119.251' of Request 102: Match Found [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:12062 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 18 Found RTP audio format 100 Found RTP audio format 101 [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:5191 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.165.3:17466 Found audio description format G729a for ID 18 Got unsupported a:fmtp in SDP offer Found unknown media description format NSE for ID 100 Got unsupported a:fmtp in SDP offer Found audio description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:5451 process_sdp: T38 state changed to 0 on channel SIP/809961-081d73d8 Capabilities: us - 0x100 (g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.165.3:17466 [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:5531 process_sdp: We're settling with these formats: 0x100 (g729) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:5538 process_sdp: We have an owner, now see if we need to change this call [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:8305 build_route: build_route: Contact hop: 809961 list_route: hop: [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:5934 reqprep: Strict routing enforced for session 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.165.3, port 5160 Transmitting (NAT) to 192.168.165.3:5160: ACK sip:809961@192.168.165.3:5160 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK670d9f3e;rport From: "Wywolanie" ;tag=as18a58f7d To: ;tag=aded5b814ef805d9i0 Contact: Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 10 16:21:08] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809961-081d73d8 [Apr 10 16:21:08] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809961 -- SIP/809961-081d73d8 answered SIP/192.168.119.225-081da6b0 [Apr 10 16:21:08] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/192.168.119.225-081da6b0 [Apr 10 16:21:08] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/192.168.119.225 [Apr 10 16:21:08] DEBUG[21582]: chan_sip.c:3678 sip_answer: SIP answering channel: SIP/192.168.119.225-081da6b0 [Apr 10 16:21:08] DEBUG[21582]: chan_sip.c:6726 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 10 16:21:08] DEBUG[21582]: chan_sip.c:6490 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Apr 10 16:21:08] DEBUG[21582]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x0 (nothing) Audio is at 192.168.119.251 port 13272 Adding codec 0x8 (alaw) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 10 16:21:08] DEBUG[21582]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP [Apr 10 16:21:08] DEBUG[21582]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) <--- Reliably Transmitting (no NAT) to 192.168.119.225:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.119.225:5060;branch=z9hG4bK21E2C49D;received=192.168.119.225 From: "Wywolanie" ;tag=7E7F32FC-933 To: ;tag=as35a8b3ee Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 244 v=0 o=root 2211 2211 IN IP4 192.168.119.251 s=session c=IN IP4 192.168.119.251 t=0 0 m=audio 13272 RTP/AVP 8 101 a=rtpmap:8 PCMA/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 10 16:21:08] DEBUG[21582]: chan_sip.c:2044 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 10 16:21:08] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809961-081d73d8 [Apr 10 16:21:08] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809961-081d73d8 [Apr 10 16:21:08] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809961-081d73d8 - state 4 (Invalid) [Apr 10 16:21:08] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809961 [Apr 10 16:21:08] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809961 [Apr 10 16:21:08] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809961 - state 1 (Not in use) [Apr 10 16:21:08] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 192.168.119.225-081da6b0 [Apr 10 16:21:08] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 192.168.119.225-081da6b0 [Apr 10 16:21:08] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809961-081d73d8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:08] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809961' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. obelix*CLI> <--- SIP read from 192.168.119.225:57162 ---> ACK sip:809961@192.168.119.251:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.225:5060;branch=z9hG4bK21E2D19D3 From: "Wywolanie" ;tag=7E7F32FC-933 To: ;tag=as35a8b3ee Date: Thu, 10 Apr 2008 14:29:11 GMT Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 Max-Forwards: 70 CSeq: 101 ACK Allow-Events: telephone-event Content-Length: 0 <-------------> [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: ACK sip:809961@192.168.119.251:5060 SIP/2.0 (46) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.119.225:5060;branch=z9hG4bK21E2D19D3 (61) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "Wywolanie" ;tag=7E7F32FC-933 (66) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: ;tag=as35a8b3ee (50) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Date: Thu, 10 Apr 2008 14:29:11 GMT (35) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 (59) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: CSeq: 101 ACK (13) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Allow-Events: telephone-event (29) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Content-Length: 0 (17) [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:15258 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:2167 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15106 [Apr 10 16:21:08] DEBUG[17555]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '5238E857-64111DD-85439444-EDFCF770@192.168.119.225' of Response 101: Match Found [Apr 10 16:21:08] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/192.168.119.225-081da6b0 - state 4 (Invalid) [Apr 10 16:21:08] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 192.168.119.225 [Apr 10 16:21:08] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 192.168.119.225 [Apr 10 16:21:08] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/192.168.119.225 - state 2 (In use) [Apr 10 16:21:08] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/192.168.119.225-081da6b0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:08] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/192.168.119.225' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 10 16:21:08] DEBUG[21582]: rtp.c:2772 ast_rtp_write: Ooh, format changed from unknown to g729 [Apr 10 16:21:08] DEBUG[21582]: rtp.c:2789 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Apr 10 16:21:08] DEBUG[21582]: rtp.c:2772 ast_rtp_write: Ooh, format changed from unknown to alaw [Apr 10 16:21:08] DEBUG[21582]: rtp.c:2789 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Apr 10 16:21:09] DEBUG[21582]: rtp.c:880 ast_rtcp_read: Got RTCP report of 136 bytes [Apr 10 16:21:10] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Apr 10 16:21:10] DEBUG[21582]: rtp.c:627 send_dtmf: Sending dtmf: 35 (#), at 192.168.165.3 [Apr 10 16:21:10] DEBUG[21582]: channel.c:3828 ast_generic_bridge: Got DTMF begin on channel (SIP/809961-081d73d8) [Apr 10 16:21:10] DEBUG[21582]: channel.c:4115 ast_channel_bridge: Bridge stops bridging channels SIP/192.168.119.225-081da6b0 and SIP/809961-081d73d8 [Apr 10 16:21:10] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Apr 10 16:21:10] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Apr 10 16:21:10] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Apr 10 16:21:10] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Apr 10 16:21:10] DEBUG[21582]: rtp.c:627 send_dtmf: Sending dtmf: 35 (#), at 192.168.165.3 [Apr 10 16:21:10] DEBUG[21582]: channel.c:3828 ast_generic_bridge: Got DTMF end on channel (SIP/809961-081d73d8) [Apr 10 16:21:10] DEBUG[21582]: channel.c:4115 ast_channel_bridge: Bridge stops bridging channels SIP/192.168.119.225-081da6b0 and SIP/809961-081d73d8 [Apr 10 16:21:10] DEBUG[21582]: res_features.c:1081 ast_feature_interpret: Feature interpret: chan=SIP/192.168.119.225-081da6b0, peer=SIP/809961-081d73d8, code=#, sense=2, features=2 dynamic=(null) [Apr 10 16:21:10] DEBUG[21582]: res_features.c:779 builtin_atxfer: Executing Attended Transfer SIP/192.168.119.225-081da6b0, SIP/809961-081d73d8 (sense=2) -- Started music on hold, class 'default', on SIP/192.168.119.225-081da6b0 [Apr 10 16:21:10] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/809961-081d73d8 to write format gsm -- Playing 'pbx-transfer' (language 'en') [Apr 10 16:21:10] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Apr 10 16:21:10] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 0000000b (len = 4) [Apr 10 16:21:10] DEBUG[21321]: res_musiconhold.c:275 ast_moh_files_next: SIP/192.168.119.225-081da6b0 Opened file 1 '/var/lib/asterisk/moh/fpm-world-mix' [Apr 10 16:21:10] DEBUG[21321]: rtp.c:2635 ast_rtp_raw_write: Difference is 936, ms is 137 [Apr 10 16:21:11] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/809961-081d73d8 to write format slin [Apr 10 16:21:11] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 10 16:21:11] DEBUG[21582]: rtp.c:627 send_dtmf: Sending dtmf: 54 (6), at 192.168.165.3 [Apr 10 16:21:11] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 10 16:21:11] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 10 16:21:11] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 10 16:21:11] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 10 16:21:11] DEBUG[21582]: rtp.c:627 send_dtmf: Sending dtmf: 54 (6), at 192.168.165.3 [Apr 10 16:21:11] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 10 16:21:11] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000006 (len = 4) [Apr 10 16:21:12] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Apr 10 16:21:12] DEBUG[21582]: rtp.c:627 send_dtmf: Sending dtmf: 50 (2), at 192.168.165.3 [Apr 10 16:21:12] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Apr 10 16:21:12] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Apr 10 16:21:12] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Apr 10 16:21:12] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Apr 10 16:21:12] DEBUG[21582]: rtp.c:627 send_dtmf: Sending dtmf: 50 (2), at 192.168.165.3 [Apr 10 16:21:12] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable BRIDGEPEER. [Apr 10 16:21:12] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Apr 10 16:21:12] DEBUG[21582]: channel.c:3299 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Apr 10 16:21:12] DEBUG[21582]: channel.c:3294 ast_channel_inherit_variables: Copying hard-transferable variable TRANSFER_CONTEXT. [Apr 10 16:21:12] DEBUG[21582]: channel.c:2372 ast_indicate_data: Driver for channel 'SIP/809961-081d73d8' does not support indication 3, emulating it [Apr 10 16:21:12] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Apr 10 16:21:12] DEBUG[21582]: rtp.c:728 process_rfc2833: - RTP 2833 Event: 00000002 (len = 4) [Apr 10 16:21:12] DEBUG[21583]: pbx.c:1842 pbx_extension_helper: Launching 'Dial' -- Executing [62@test_1:1] Dial("Local/62@test_1-c36b,2", "SIP/809962") in new stack [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:15963 sip_request_call: Asked to create a SIP channel with formats: 0x100 (g729) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:2806 create_addr_from_peer: Our T38 capability (3856) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:2760 do_setnat: Setting NAT on RTP to On [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:2770 do_setnat: Setting NAT on UDPTL to On [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4032 sip_new: *** Our native formats are 0x100 (g729) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4033 sip_new: *** Joint capabilities are 0x0 (nothing) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4034 sip_new: *** Our capabilities are 0x100 (g729) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4035 sip_new: *** AST_CODEC_CHOOSE formats are 0x100 (g729) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4037 sip_new: *** Our preferred formats from the incoming channel are 0x100 (g729) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4058 sip_new: This channel will not be able to handle video. [Apr 10 16:21:12] DEBUG[21583]: rtp.c:1593 ast_rtp_make_compatible: Channel 'Local/62@test_1-c36b,2' has no RTP, not doing anything [Apr 10 16:21:12] DEBUG[21583]: channel.c:3299 ast_channel_inherit_variables: Not copying variable TRANSFERERNAME. [Apr 10 16:21:12] DEBUG[21583]: channel.c:3294 ast_channel_inherit_variables: Copying hard-transferable variable TRANSFER_CONTEXT. [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:3018 sip_call: Outgoing Call for 809962 [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:3033 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:6490 add_sdp: ** Our capability: 0x100 (g729) Video flag: False [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x100 (g729) Audio is at 192.168.119.251 port 19436 Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0x100 (g729) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 0: INVITE sip:809962@192.168.165.3:5161 SIP/2.0 (45) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK06d787c4;rport (66) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 2: From: "809961" ;tag=as56c04e1e (64) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 3: To: (36) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 4: Contact: (40) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 6: CSeq: 102 INVITE (16) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 9: Date: Thu, 10 Apr 2008 14:21:12 GMT (35) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 11: Supported: replaces (19) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 13: Content-Length: 267 (19) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4813 parse_request: Header 14: (0) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: v=0 (3) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: o=root 2211 2211 IN IP4 192.168.119.251 (39) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: s=session (9) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: c=IN IP4 192.168.119.251 (24) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: t=0 0 (5) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: m=audio 19436 RTP/AVP 18 101 (28) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: a=rtpmap:18 G729/8000 (21) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: a=fmtp:18 annexb=no (19) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: a=fmtp:101 0-16 (15) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: a=silenceSupp:off - - - - (25) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: a=ptime:20 (10) [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:4845 parse_request: Line: a=sendrecv (10) Reliably Transmitting (NAT) to 192.168.165.3:5161: INVITE sip:809962@192.168.165.3:5161 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK06d787c4;rport From: "809961" ;tag=as56c04e1e To: Contact: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 INVITE User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 10 Apr 2008 14:21:12 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Type: application/sdp Content-Length: 267 v=0 o=root 2211 2211 IN IP4 192.168.119.251 s=session c=IN IP4 192.168.119.251 t=0 0 m=audio 19436 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv --- [Apr 10 16:21:12] DEBUG[21583]: chan_sip.c:2044 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 -- Called 809962 [Apr 10 16:21:12] DEBUG[21582]: rtp.c:2635 ast_rtp_raw_write: Difference is 4616, ms is 597 obelix*CLI> <--- SIP read from 192.168.165.3:5161 ---> SIP/2.0 100 Trying To: From: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK06d787c4 Server: Linksys/SPA8000-5.1.9 Content-Length: 0 <-------------> [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 100 Trying (18) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: To: (36) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "809961" ;tag=as56c04e1e (64) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: CSeq: 102 INVITE (16) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK06d787c4 (60) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Server: Linksys/SPA8000-5.1.9 (29) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Content-Length: 0 (17) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: (0) --- (8 headers 0 lines) --- [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:2228 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #15109 - INVITE (got response) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:2236 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7e95227048e39f3343b06e5e59ba5224@192.168.119.251' Request 102: Found [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:12062 handle_response_invite: SIP response 100 to standard invite obelix*CLI> <--- SIP read from 192.168.165.3:5161 ---> SIP/2.0 180 Ringing To: ;tag=aca214bea085d865i1 From: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK06d787c4 Server: Linksys/SPA8000-5.1.9 Remote-Party-ID: 809962 ;screen=yes;party=called Content-Length: 0 <-------------> [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: To: ;tag=aca214bea085d865i1 (59) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "809961" ;tag=as56c04e1e (64) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: CSeq: 102 INVITE (16) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK06d787c4 (60) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Server: Linksys/SPA8000-5.1.9 (29) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Remote-Party-ID: 809962 ;screen=yes;party=called (82) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Content-Length: 0 (17) [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:2236 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '7e95227048e39f3343b06e5e59ba5224@192.168.119.251' Request 102: Found [Apr 10 16:21:12] DEBUG[17555]: chan_sip.c:12062 handle_response_invite: SIP response 180 to standard invite [Apr 10 16:21:12] DEBUG[17555]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809962-081d8d58 [Apr 10 16:21:12] DEBUG[17555]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809962 -- SIP/809962-081d8d58 is ringing [Apr 10 16:21:12] DEBUG[21583]: rtp.c:1503 ast_rtp_early_bridge: Channel 'Local/62@test_1-c36b,2' has no RTP, not doing anything -- Local/62@test_1-c36b,1 is ringing [Apr 10 16:21:12] DEBUG[21582]: channel.c:2372 ast_indicate_data: Driver for channel 'SIP/809961-081d73d8' does not support indication 3, emulating it [Apr 10 16:21:12] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809962-081d8d58 [Apr 10 16:21:12] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809962-081d8d58 [Apr 10 16:21:12] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809962-081d8d58 - state 4 (Invalid) [Apr 10 16:21:12] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809962 [Apr 10 16:21:12] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809962 [Apr 10 16:21:12] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809962 - state 1 (Not in use) [Apr 10 16:21:12] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809962-081d8d58' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:12] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809962' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:21:13] DEBUG[21321]: rtp.c:880 ast_rtcp_read: Got RTCP report of 136 bytes obelix*CLI> <--- SIP read from 192.168.165.3:5161 ---> SIP/2.0 200 OK To: ;tag=aca214bea085d865i1 From: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 INVITE Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK06d787c4 Contact: 809962 Server: Linksys/SPA8000-5.1.9 Remote-Party-ID: 809962 ;screen=yes;party=called Content-Length: 273 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura, replaces Content-Type: application/sdp v=0 o=- 58252 58252 IN IP4 192.168.165.3 s=- c=IN IP4 192.168.165.3 t=0 0 m=audio 17468 RTP/AVP 18 100 101 a=rtpmap:18 G729a/8000 a=fmtp:18 annexb=no a=rtpmap:100 NSE/8000 a=fmtp:100 192-193 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=ptime:30 a=sendrecv <-------------> [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: To: ;tag=aca214bea085d865i1 (59) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "809961" ;tag=as56c04e1e (64) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: CSeq: 102 INVITE (16) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK06d787c4 (60) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Contact: 809962 (51) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Server: Linksys/SPA8000-5.1.9 (29) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Remote-Party-ID: 809962 ;screen=yes;party=called (82) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Content-Length: 273 (19) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 11: Supported: x-sipura, replaces (29) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 13: (0) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: v=0 (3) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: o=- 58252 58252 IN IP4 192.168.165.3 (34) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: s=- (3) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: c=IN IP4 192.168.165.3 (20) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: t=0 0 (5) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: m=audio 17468 RTP/AVP 18 100 101 (32) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:18 G729a/8000 (22) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=fmtp:18 annexb=no (19) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:100 NSE/8000 (21) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=fmtp:100 192-193 (18) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=fmtp:101 0-15 (15) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=ptime:30 (10) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=sendrecv (10) --- (13 headers 14 lines) --- [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:2159 __sip_ack: Acked pending invite 102 [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '7e95227048e39f3343b06e5e59ba5224@192.168.119.251' of Request 102: Match Found [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:12062 handle_response_invite: SIP response 200 to standard invite Found RTP audio format 18 Found RTP audio format 100 Found RTP audio format 101 [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:5191 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.165.3:17468 Found audio description format G729a for ID 18 Got unsupported a:fmtp in SDP offer Found unknown media description format NSE for ID 100 Got unsupported a:fmtp in SDP offer Found audio description format telephone-event for ID 101 Got unsupported a:fmtp in SDP offer [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:5451 process_sdp: T38 state changed to 0 on channel SIP/809962-081d8d58 Capabilities: us - 0x100 (g729), peer - audio=0x100 (g729)/video=0x0 (nothing), combined - 0x100 (g729) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x1 (telephone-event), combined - 0x1 (telephone-event) Peer audio RTP is at port 192.168.165.3:17468 [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:5531 process_sdp: We're settling with these formats: 0x100 (g729) [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:5538 process_sdp: We have an owner, now see if we need to change this call [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:3205 update_call_counter: Updating call counter for outgoing call [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:8305 build_route: build_route: Contact hop: 809962 list_route: hop: [Apr 10 16:21:17] DEBUG[17555]: chan_sip.c:5934 reqprep: Strict routing enforced for session 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.165.3, port 5161 Transmitting (NAT) to 192.168.165.3:5161: ACK sip:809962@192.168.165.3:5161 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK4f4ad3d8;rport From: "809961" ;tag=as56c04e1e To: ;tag=aca214bea085d865i1 Contact: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 ACK User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 10 16:21:17] DEBUG[21583]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809962-081d8d58 [Apr 10 16:21:17] DEBUG[21583]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809962 -- SIP/809962-081d8d58 answered Local/62@test_1-c36b,2 [Apr 10 16:21:17] DEBUG[21583]: rtp.c:1503 ast_rtp_early_bridge: Channel 'Local/62@test_1-c36b,2' has no RTP, not doing anything [Apr 10 16:21:17] DEBUG[21583]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/62@test_1-c36b,2 [Apr 10 16:21:17] DEBUG[21583]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/62@test_1 [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809962-081d8d58 [Apr 10 16:21:17] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809962-081d8d58 [Apr 10 16:21:17] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/62@test_1-c36b,1 [Apr 10 16:21:17] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/62@test_1 [Apr 10 16:21:17] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/809961-081d73d8 to read format g729 [Apr 10 16:21:17] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/809961-081d73d8 to write format g729 [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809962-081d8d58 - state 4 (Invalid) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809962 [Apr 10 16:21:17] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809962 [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809962 - state 1 (Not in use) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 62@test_1-c36b,2 [Apr 10 16:21:17] DEBUG[17530]: chan_local.c:145 local_devicestate: Checking if extension 62@test_1-c36b,2 exists (devicestate) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Local/62@test_1-c36b,2 - state 4 (Invalid) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 62@test_1 [Apr 10 16:21:17] DEBUG[17530]: chan_local.c:145 local_devicestate: Checking if extension 62@test_1 exists (devicestate) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Local/62@test_1 - state 2 (In use) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 62@test_1-c36b,1 [Apr 10 16:21:17] DEBUG[17530]: chan_local.c:145 local_devicestate: Checking if extension 62@test_1-c36b,1 exists (devicestate) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Local/62@test_1-c36b,1 - state 4 (Invalid) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 62@test_1 [Apr 10 16:21:17] DEBUG[17530]: chan_local.c:145 local_devicestate: Checking if extension 62@test_1 exists (devicestate) [Apr 10 16:21:17] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Local/62@test_1 - state 2 (In use) [Apr 10 16:21:17] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809962-081d8d58' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:17] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809962' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:21:17] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Local/62@test_1-c36b,2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:17] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Local/62@test_1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 10 16:21:17] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Local/62@test_1-c36b,1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:17] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Local/62@test_1' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Apr 10 16:21:17] DEBUG[21583]: rtp.c:2772 ast_rtp_write: Ooh, format changed from unknown to g729 [Apr 10 16:21:17] DEBUG[21583]: rtp.c:2789 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Apr 10 16:21:18] DEBUG[21321]: rtp.c:880 ast_rtcp_read: Got RTCP report of 136 bytes obelix*CLI> <--- SIP read from 192.168.165.3:5160 ---> BYE sip:808200@192.168.119.251 SIP/2.0 Via: SIP/2.0/UDP 192.168.165.3:5160;branch=z9hG4bK-96786771 From: ;tag=aded5b814ef805d9i0 To: "Wywolanie" ;tag=as18a58f7d Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 CSeq: 101 BYE Max-Forwards: 70 User-Agent: Linksys/SPA8000-5.1.9 Content-Length: 0 <-------------> [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: BYE sip:808200@192.168.119.251 SIP/2.0 (41) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.165.3:5160;branch=z9hG4bK-96786771 (57) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: ;tag=aded5b814ef805d9i0 (61) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: "Wywolanie" ;tag=as18a58f7d (62) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 (57) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: CSeq: 101 BYE (13) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: User-Agent: Linksys/SPA8000-5.1.9 (33) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Content-Length: 0 (17) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:15258 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.165.3 : 5160 (NAT) [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:1656 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 [Apr 10 16:21:19] DEBUG[17555]: chan_sip.c:14798 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 192.168.165.3:5160 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.165.3:5160;branch=z9hG4bK-96786771;received=192.168.165.3 From: ;tag=aded5b814ef805d9i0 To: "Wywolanie" ;tag=as18a58f7d Call-ID: 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251 CSeq: 101 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 10 16:21:19] DEBUG[21582]: channel.c:3781 ast_generic_bridge: Didn't get a frame from channel: SIP/809961-081d73d8 [Apr 10 16:21:19] DEBUG[21582]: channel.c:4115 ast_channel_bridge: Bridge stops bridging channels SIP/809961-081d73d8 and Local/62@test_1-c36b,1 [Apr 10 16:21:19] DEBUG[21582]: channel.c:2784 set_format: Set channel Local/62@test_1-c36b,1 to write format slin [Apr 10 16:21:19] DEBUG[21582]: channel.c:2784 set_format: Set channel Local/62@test_1-c36b,1 to read format slin -- Stopped music on hold on SIP/192.168.119.225-081da6b0 [Apr 10 16:21:19] DEBUG[21582]: channel.c:3232 ast_channel_masquerade: Planning to masquerade channel SIP/192.168.119.225-081da6b0 into the structure of Transfered/SIP/192.168.119.225-081da6b0 [Apr 10 16:21:19] DEBUG[21582]: channel.c:3246 ast_channel_masquerade: Done planning to masquerade channel SIP/192.168.119.225-081da6b0 into the structure of Transfered/SIP/192.168.119.225-081da6b0 [Apr 10 16:21:19] DEBUG[21582]: channel.c:3355 ast_do_masquerade: Actually Masquerading SIP/192.168.119.225-081da6b0(6) into the structure of Transfered/SIP/192.168.119.225-081da6b0(6) [Apr 10 16:21:19] DEBUG[21582]: channel.c:3367 ast_do_masquerade: Got clone lock for masquerade on 'SIP/192.168.119.225-081da6b0' at 0x8205070 [Apr 10 16:21:19] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/192.168.119.225-081da6b0 to write format slin [Apr 10 16:21:19] DEBUG[21582]: channel.c:2784 set_format: Set channel SIP/192.168.119.225-081da6b0 to read format slin [Apr 10 16:21:19] DEBUG[21582]: channel.c:3545 ast_do_masquerade: Putting channel SIP/192.168.119.225-081da6b0 in 64/64 formats [Apr 10 16:21:19] DEBUG[21582]: chan_sip.c:3805 sip_fixup: SIP Fixup: New owner for dialogue 5238E857-64111DD-85439444-EDFCF770@192.168.119.225: SIP/192.168.119.225-081da6b0 (Old parent: Transfered/SIP/192.168.119.225-081da6b0) [Apr 10 16:21:19] DEBUG[21582]: channel.c:3585 ast_do_masquerade: Released clone lock on 'Transfered/SIP/192.168.119.225-081da6b0' [Apr 10 16:21:19] DEBUG[21582]: channel.c:3595 ast_do_masquerade: Done Masquerading SIP/192.168.119.225-081da6b0 (6) [Apr 10 16:21:19] DEBUG[21582]: channel.c:2784 set_format: Set channel Local/62@test_1-c36b,1 to write format gsm -- Playing 'beep' (language 'en') [Apr 10 16:21:19] DEBUG[21583]: rtp.c:2635 ast_rtp_raw_write: Difference is 1200, ms is 170 [Apr 10 16:21:20] DEBUG[21582]: channel.c:2784 set_format: Set channel Local/62@test_1-c36b,1 to write format slin [Apr 10 16:21:20] DEBUG[21582]: channel.c:1483 ast_hangup: Hanging up channel 'SIP/809961-081d73d8' [Apr 10 16:21:20] DEBUG[21582]: chan_sip.c:3517 sip_hangup: Hangup call SIP/809961-081d73d8, SIP callid 7707b22b6fac589e4d176c9143e4f64c@192.168.119.251) [Apr 10 16:21:20] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809961-081d73d8 [Apr 10 16:21:20] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809961 [Apr 10 16:21:20] DEBUG[21582]: rtp.c:1503 ast_rtp_early_bridge: Channel 'Transfered/SIP/192.168.119.225-081da6b0' has no RTP, not doing anything [Apr 10 16:21:20] DEBUG[21582]: app_dial.c:1728 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 10 16:21:20] DEBUG[21582]: app_macro.c:329 _macro_exec: Spawn extension (macro-dial-cfbu,s,1000) exited non-zero on 'Transfered/SIP/192.168.119.225-081da6b0' in macro 'dial-cfbu' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:2438 __ast_pbx_run: Spawn extension (macro-dial-cfbu,s,1000) exited non-zero on 'Transfered/SIP/192.168.119.225-081da6b0' == Spawn extension (macro-dial-cfbu, s, 1000) exited non-zero on 'Transfered/SIP/192.168.119.225-081da6b0' [Apr 10 16:21:20] DEBUG[21582]: channel.c:1384 ast_softhangup_nolock: Soft-Hanging up channel 'Transfered/SIP/192.168.119.225-081da6b0' [Apr 10 16:21:20] DEBUG[21582]: channel.c:1488 ast_hangup: Hanging up zombie 'Transfered/SIP/192.168.119.225-081da6b0' [Apr 10 16:21:20] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Transfered/SIP/192.168.119.225-081da6b0 [Apr 10 16:21:20] DEBUG[21582]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Transfered/SIP/192.168.119.225 [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '809961' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'test_1' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Transfered/SIP/192.168.119.225-081da6b0' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Local/62@test_1-c36b,1' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Local/62@test_1/n' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:05' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:08' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:17' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '12' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '9' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1207837265.131' [Apr 10 16:21:20] DEBUG[21582]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809961-081d73d8 [Apr 10 16:21:20] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809961-081d73d8 [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809961-081d73d8 - state 4 (Invalid) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809961 [Apr 10 16:21:20] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809961 [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809961 - state 1 (Not in use) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Transfered - SIP/192.168.119.225-081da6b0 [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Transfered/SIP/192.168.119.225-081da6b0 - state 4 (Invalid) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Transfered - SIP/192.168.119.225 [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Transfered/SIP/192.168.119.225 - state 4 (Invalid) [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809961-081d73d8' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809961' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Transfered/SIP/192.168.119.225-081da6b0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Transfered/SIP/192.168.119.225' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! obelix*CLI> <--- SIP read from 192.168.165.3:5161 ---> INVITE sip:809961@192.168.119.251 SIP/2.0 Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-d84ef08b From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Remote-Party-ID: 809962 ;screen=yes;party=called Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 101 INVITE Max-Forwards: 70 Contact: 809962 Expires: 30 User-Agent: Linksys/SPA8000-5.1.9 Content-Length: 261 Content-Type: application/sdp v=0 o=- 59081 59081 IN IP4 192.168.165.3 s=- c=IN IP4 192.168.165.3 t=0 0 m=image 17468 udptl t38 a=T38FaxVersion:0 a=T38MaxBitRate:14400 a=T38FaxRateManagement:transferredTCF a=T38FaxMaxBuffer:200 a=T38FaxMaxDatagram:200 a=T38FaxUdpEC:t38UDPRedundancy <-------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: INVITE sip:809961@192.168.119.251 SIP/2.0 (44) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-d84ef08b (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: ;tag=aca214bea085d865i1 (61) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: "809961" ;tag=as56c04e1e (62) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Remote-Party-ID: 809962 ;screen=yes;party=called (82) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: CSeq: 101 INVITE (16) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Max-Forwards: 70 (16) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Contact: 809962 (51) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Expires: 30 (11) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: User-Agent: Linksys/SPA8000-5.1.9 (33) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 11: Content-Length: 261 (19) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 13: (0) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: v=0 (3) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: o=- 59081 59081 IN IP4 192.168.165.3 (34) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: s=- (3) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: c=IN IP4 192.168.165.3 (20) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: t=0 0 (5) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: m=image 17468 udptl t38 (23) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=T38FaxVersion:0 (17) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=T38MaxBitRate:14400 (21) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=T38FaxRateManagement:transferredTCF (37) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=T38FaxMaxBuffer:200 (21) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=T38FaxMaxDatagram:200 (23) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=T38FaxUdpEC:t38UDPRedundancy (30) --- (13 headers 12 lines) --- [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:15258 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.165.3 : 5161 (NAT) Got T.38 offer in SDP in dialog 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5133 process_sdp: T38 state changed to 4 on channel SIP/809962-081d8d58 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5187 process_sdp: Peer T.38 UDPTL is at port 192.168.165.3:17468 Got T.38 Re-invite without audio. Keeping RTP active during T.38 session. Callid 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5383 process_sdp: FaxVersion: 0 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5359 process_sdp: T38MaxBitRate: 14400 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5416 process_sdp: RateManagement: transferredTCF [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5355 process_sdp: MaxBufferSize:200 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5391 process_sdp: FaxMaxDatagram: 200 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5424 process_sdp: UDP EC: t38UDPRedundancy [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5444 process_sdp: Our T38 capability = (3856), peer T38 capability (16160), joint T38 capability (3872) Capabilities: us - 0x100 (g729), peer - audio=0x0 (nothing)/video=0x0 (nothing), combined - 0x0 (nothing) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5486 process_sdp: Have T.38 but no audio codecs, accepting offer anyway [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:13983 handle_request_invite: Got a SIP re-invite for call 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:14080 handle_request_invite: SIP/809962-081d8d58: This call is UP.... obelix*CLI> <--- Transmitting (NAT) to 192.168.165.3:5161 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-d84ef08b;received=192.168.165.3 From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> obelix*CLI> <--- Reliably Transmitting (NAT) to 192.168.165.3:5161 ---> SIP/2.0 488 Not acceptable here Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-d84ef08b;received=192.168.165.3 From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 101 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 X-Asterisk-HangupCause: Normal Clearing X-Asterisk-HangupCauseCode: 16 <------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:2044 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:14125 handle_request_invite: T38 state changed to 0 on channel SIP/809962-081d8d58 Really destroying SIP dialog '7707b22b6fac589e4d176c9143e4f64c@192.168.119.251' Method: BYE [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! obelix*CLI> <--- SIP read from 192.168.165.3:5161 ---> ACK sip:809961@192.168.119.251 SIP/2.0 Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-d84ef08b From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 101 ACK Max-Forwards: 70 Contact: 809962 User-Agent: Linksys/SPA8000-5.1.9 Content-Length: 0 <-------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: ACK sip:809961@192.168.119.251 SIP/2.0 (41) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-d84ef08b (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: ;tag=aca214bea085d865i1 (61) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: "809961" ;tag=as56c04e1e (62) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: CSeq: 101 ACK (13) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Contact: 809962 (51) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: User-Agent: Linksys/SPA8000-5.1.9 (33) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Content-Length: 0 (17) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:15258 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:2167 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15112 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '7e95227048e39f3343b06e5e59ba5224@192.168.119.251' of Response 101: Match Found obelix*CLI> <--- SIP read from 192.168.165.3:5161 ---> INVITE sip:809961@192.168.119.251 SIP/2.0 Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-c42f6a41 From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Remote-Party-ID: 809962 ;screen=yes;party=called Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 INVITE Max-Forwards: 70 Contact: 809962 Expires: 30 User-Agent: Linksys/SPA8000-5.1.9 Content-Length: 146 Content-Type: application/sdp v=0 o=- 59089 59089 IN IP4 192.168.165.3 s=- c=IN IP4 192.168.165.3 t=0 0 m=audio 17468 RTP/AVP 0 a=rtpmap:0 PCMU/8000 a=ptime:30 a=sendrecv <-------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: INVITE sip:809961@192.168.119.251 SIP/2.0 (44) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-c42f6a41 (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: ;tag=aca214bea085d865i1 (61) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: "809961" ;tag=as56c04e1e (62) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Remote-Party-ID: 809962 ;screen=yes;party=called (82) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: CSeq: 102 INVITE (16) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Max-Forwards: 70 (16) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Contact: 809962 (51) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Expires: 30 (11) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: User-Agent: Linksys/SPA8000-5.1.9 (33) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 11: Content-Length: 146 (19) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 13: (0) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: v=0 (3) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: o=- 59089 59089 IN IP4 192.168.165.3 (34) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: s=- (3) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: c=IN IP4 192.168.165.3 (20) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: t=0 0 (5) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: m=audio 17468 RTP/AVP 0 (23) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=ptime:30 (10) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: a=sendrecv (10) --- (13 headers 9 lines) --- [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:15258 handle_request: **** Received INVITE (5) - Command in SIP INVITE Sending to 192.168.165.3 : 5161 (NAT) Found RTP audio format 0 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5191 process_sdp: Peer doesn't provide T.38 UDPTL Peer audio RTP is at port 192.168.165.3:17468 Found audio description format PCMU for ID 0 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5451 process_sdp: T38 state changed to 0 on channel SIP/809962-081d8d58 Capabilities: us - 0x100 (g729), peer - audio=0x4 (ulaw)/video=0x0 (nothing), combined - 0x0 (nothing) Non-codec capabilities (dtmf): us - 0x1 (telephone-event), peer - 0x0 (nothing), combined - 0x0 (nothing) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:5486 process_sdp: Have T.38 but no audio codecs, accepting offer anyway [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:13983 handle_request_invite: Got a SIP re-invite for call 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:14080 handle_request_invite: SIP/809962-081d8d58: This call is UP.... <--- Transmitting (NAT) to 192.168.165.3:5161 ---> SIP/2.0 100 Trying Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-c42f6a41;received=192.168.165.3 From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:6726 transmit_response_with_sdp: Setting framing from config on incoming call [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:6490 add_sdp: ** Our capability: 0x100 (g729) Video flag: True [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:6491 add_sdp: ** Our prefcodec: 0x100 (g729) Audio is at 192.168.119.251 port 19436 Adding codec 0x100 (g729) to SDP Adding non-codec 0x1 (telephone-event) to SDP [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:6622 add_sdp: -- Done with adding codecs to SDP [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:6667 add_sdp: Done building SDP. Settling with this capability: 0x100 (g729) <--- Reliably Transmitting (NAT) to 192.168.165.3:5161 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-c42f6a41;received=192.168.165.3 From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 INVITE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Type: application/sdp Content-Length: 267 v=0 o=root 2211 2212 IN IP4 192.168.119.251 s=session c=IN IP4 192.168.119.251 t=0 0 m=audio 19436 RTP/AVP 18 101 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=silenceSupp:off - - - - a=ptime:20 a=sendrecv <------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:2044 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! [Apr 10 16:21:20] DEBUG[21583]: rtp.c:2789 ast_rtp_write: Created smoother: format: 256 ms: 20 len: 20 [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:4323 sip_rtp_read: Bogus frame of format 'ulaw' received from 'SIP/809962-081d8d58'! obelix*CLI> <--- SIP read from 192.168.165.3:5161 ---> ACK sip:809961@192.168.119.251 SIP/2.0 Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-809f4c0e From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 102 ACK Max-Forwards: 70 Contact: 809962 User-Agent: Linksys/SPA8000-5.1.9 Content-Length: 0 <-------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: ACK sip:809961@192.168.119.251 SIP/2.0 (41) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-809f4c0e (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: ;tag=aca214bea085d865i1 (61) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: "809961" ;tag=as56c04e1e (62) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: CSeq: 102 ACK (13) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Contact: 809962 (51) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: User-Agent: Linksys/SPA8000-5.1.9 (33) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Content-Length: 0 (17) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:15258 handle_request: **** Received ACK (6) - Command in SIP ACK [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:2167 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15113 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '7e95227048e39f3343b06e5e59ba5224@192.168.119.251' of Response 102: Match Found <--- SIP read from 192.168.165.3:5161 ---> BYE sip:809961@192.168.119.251 SIP/2.0 Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-17f18ca5 From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 103 BYE Max-Forwards: 70 User-Agent: Linksys/SPA8000-5.1.9 Content-Length: 0 <-------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: BYE sip:809961@192.168.119.251 SIP/2.0 (41) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-17f18ca5 (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: ;tag=aca214bea085d865i1 (61) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: "809961" ;tag=as56c04e1e (62) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 (57) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: CSeq: 103 BYE (13) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Max-Forwards: 70 (16) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: User-Agent: Linksys/SPA8000-5.1.9 (33) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Content-Length: 0 (17) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: (0) --- (9 headers 0 lines) --- [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:15258 handle_request: **** Received BYE (8) - Command in SIP BYE Sending to 192.168.165.3 : 5161 (NAT) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:1656 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:14798 handle_request_bye: Received bye, issuing owner hangup <--- Transmitting (NAT) to 192.168.165.3:5161 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.165.3:5161;branch=z9hG4bK-17f18ca5;received=192.168.165.3 From: ;tag=aca214bea085d865i1 To: "809961" ;tag=as56c04e1e Call-ID: 7e95227048e39f3343b06e5e59ba5224@192.168.119.251 CSeq: 103 BYE User-Agent: Asterisk PBX Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Contact: Content-Length: 0 <------------> [Apr 10 16:21:20] DEBUG[21583]: channel.c:3781 ast_generic_bridge: Didn't get a frame from channel: SIP/809962-081d8d58 [Apr 10 16:21:20] DEBUG[21583]: channel.c:4115 ast_channel_bridge: Bridge stops bridging channels Local/62@test_1-c36b,2 and SIP/809962-081d8d58 [Apr 10 16:21:20] DEBUG[21583]: channel.c:1483 ast_hangup: Hanging up channel 'SIP/809962-081d8d58' [Apr 10 16:21:20] DEBUG[21583]: chan_sip.c:3517 sip_hangup: Hangup call SIP/809962-081d8d58, SIP callid 7e95227048e39f3343b06e5e59ba5224@192.168.119.251) [Apr 10 16:21:20] DEBUG[21583]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809962-081d8d58 [Apr 10 16:21:20] DEBUG[21583]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/809962 [Apr 10 16:21:20] DEBUG[21583]: rtp.c:1503 ast_rtp_early_bridge: Channel 'Local/62@test_1-c36b,2' has no RTP, not doing anything [Apr 10 16:21:20] DEBUG[21583]: app_dial.c:1728 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Apr 10 16:21:20] DEBUG[21583]: pbx.c:2438 __ast_pbx_run: Spawn extension (test_1,62,1) exited non-zero on 'Local/62@test_1-c36b,2' == Spawn extension (test_1, 62, 1) exited non-zero on 'Local/62@test_1-c36b,2' [Apr 10 16:21:20] DEBUG[21583]: channel.c:1384 ast_softhangup_nolock: Soft-Hanging up channel 'Local/62@test_1-c36b,2' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1842 pbx_extension_helper: Launching 'NoOp' -- Executing [h@test_1:1] NoOp("Local/62@test_1-c36b,2", "RTPAUDIOQOS = ") in new stack [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1842 pbx_extension_helper: Launching 'Hangup' -- Executing [h@test_1:2] Hangup("Local/62@test_1-c36b,2", "") in new stack [Apr 10 16:21:20] DEBUG[21583]: pbx.c:2561 __ast_pbx_run: Spawn extension (test_1,h,2) exited non-zero on 'Local/62@test_1-c36b,2' == Spawn extension (test_1, h, 2) exited non-zero on 'Local/62@test_1-c36b,2' [Apr 10 16:21:20] DEBUG[21583]: channel.c:1483 ast_hangup: Hanging up channel 'Local/62@test_1-c36b,2' [Apr 10 16:21:20] DEBUG[21583]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/62@test_1-c36b,2 [Apr 10 16:21:20] DEBUG[21583]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/62@test_1 [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '809961' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '809961' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '62' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'test_1' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Local/62@test_1-c36b,2' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/809962-081d8d58' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/809962' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:12' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:17' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:20' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '8' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '3' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1207837272.134' [Apr 10 16:21:20] DEBUG[21583]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:20] DEBUG[21584]: channel.c:3781 ast_generic_bridge: Didn't get a frame from channel: Local/62@test_1-c36b,1 [Apr 10 16:21:20] DEBUG[21584]: channel.c:4115 ast_channel_bridge: Bridge stops bridging channels SIP/192.168.119.225-081da6b0 and Local/62@test_1-c36b,1 [Apr 10 16:21:20] DEBUG[21584]: channel.c:1483 ast_hangup: Hanging up channel 'Local/62@test_1-c36b,1' [Apr 10 16:21:20] DEBUG[21584]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/62@test_1-c36b,1 [Apr 10 16:21:20] DEBUG[21584]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/62@test_1 [Apr 10 16:21:20] DEBUG[21584]: channel.c:1483 ast_hangup: Hanging up channel 'SIP/192.168.119.225-081da6b0' [Apr 10 16:21:20] DEBUG[21584]: chan_sip.c:3517 sip_hangup: Hangup call SIP/192.168.119.225-081da6b0, SIP callid 5238E857-64111DD-85439444-EDFCF770@192.168.119.225) Scheduling destruction of SIP dialog '5238E857-64111DD-85439444-EDFCF770@192.168.119.225' in 6400 ms (Method: ACK) [Apr 10 16:21:20] DEBUG[21584]: chan_sip.c:5934 reqprep: Strict routing enforced for session 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 set_destination: Parsing for address/port to send to set_destination: set destination to 192.168.119.225, port 5060 Reliably Transmitting (no NAT) to 192.168.119.225:5060: BYE sip:808200@192.168.119.225:5060 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK0cc6af51;rport From: ;tag=as35a8b3ee To: "Wywolanie" ;tag=7E7F32FC-933 Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 CSeq: 102 BYE User-Agent: Asterisk PBX Max-Forwards: 70 Content-Length: 0 --- [Apr 10 16:21:20] DEBUG[21584]: chan_sip.c:2044 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 [Apr 10 16:21:20] DEBUG[21584]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/192.168.119.225-081da6b0 [Apr 10 16:21:20] DEBUG[21584]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/192.168.119.225 [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '"Wywolanie" <808200>' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '808200' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 's' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'macro-dial-cfbu' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/192.168.119.225-081da6b0' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Local/62@test_1-c36b,1' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'Dial' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'SIP/809961|50|tT' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:20' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:20' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '2008-04-10 16:21:20' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '0' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'ANSWERED' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is 'DOCUMENTATION' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '1207837279.136' [Apr 10 16:21:20] DEBUG[21584]: pbx.c:1691 pbx_substitute_variables_helper_full: Function result is '' [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809962-081d8d58 [Apr 10 16:21:20] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809962-081d8d58 obelix*CLI> <--- SIP read from 192.168.119.225:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK0cc6af51;rport From: ;tag=as35a8b3ee To: "Wywolanie" ;tag=7E7F32FC-933 Date: Thu, 10 Apr 2008 14:29:26 GMT Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 BYE Reason: Q.850;cause=16 Content-Length: 0 <-------------> [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK0cc6af51;rport (66) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: ;tag=as35a8b3ee (52) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: "Wywolanie" ;tag=7E7F32FC-933 (64) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Date: Thu, 10 Apr 2008 14:29:26 GMT (35) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 5238E857-64111DD-85439444-EDFCF770@192.168.119.225 (59) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: CSeq: 102 BYE (13) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Reason: Q.850;cause=16 (22) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Content-Length: 0 (17) [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:2167 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15115 [Apr 10 16:21:20] DEBUG[17555]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '5238E857-64111DD-85439444-EDFCF770@192.168.119.225' of Request 102: Match Found SIP Response message for INCOMING dialog BYE arrived Really destroying SIP dialog '7e95227048e39f3343b06e5e59ba5224@192.168.119.251' Method: BYE Really destroying SIP dialog '5238E857-64111DD-85439444-EDFCF770@192.168.119.225' Method: ACK [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809962-081d8d58 - state 4 (Invalid) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 809962 [Apr 10 16:21:20] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 809962 [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/809962 - state 1 (Not in use) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 62@test_1-c36b,2 [Apr 10 16:21:20] DEBUG[17530]: chan_local.c:145 local_devicestate: Checking if extension 62@test_1-c36b,2 exists (devicestate) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Local/62@test_1-c36b,2 - state 4 (Invalid) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 62@test_1 [Apr 10 16:21:20] DEBUG[17530]: chan_local.c:145 local_devicestate: Checking if extension 62@test_1 exists (devicestate) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Local/62@test_1 - state 1 (Not in use) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 62@test_1-c36b,1 [Apr 10 16:21:20] DEBUG[17530]: chan_local.c:145 local_devicestate: Checking if extension 62@test_1-c36b,1 exists (devicestate) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Local/62@test_1-c36b,1 - state 4 (Invalid) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 62@test_1 [Apr 10 16:21:20] DEBUG[17530]: chan_local.c:145 local_devicestate: Checking if extension 62@test_1 exists (devicestate) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for Local/62@test_1 - state 1 (Not in use) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 192.168.119.225-081da6b0 [Apr 10 16:21:20] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 192.168.119.225-081da6b0 [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809962-081d8d58' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/809962' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Local/62@test_1-c36b,2' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Local/62@test_1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Local/62@test_1-c36b,1' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'Local/62@test_1' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/192.168.119.225-081da6b0 - state 4 (Invalid) [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 192.168.119.225 [Apr 10 16:21:20] DEBUG[17530]: chan_sip.c:15894 sip_devicestate: Checking device state for peer 192.168.119.225 [Apr 10 16:21:20] DEBUG[17530]: devicestate.c:287 do_state_change: Changing state for SIP/192.168.119.225 - state 1 (Not in use) [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/192.168.119.225-081da6b0' changed to state '4' (Invalid) but we don't care because they're not a member of any queue. [Apr 10 16:21:20] DEBUG[17552]: app_queue.c:659 handle_statechange: Device 'SIP/192.168.119.225' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: OPTIONS sip:809962@192.168.165.3:5161 SIP/2.0 (46) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK16fb84e7;rport (66) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "asterisk" ;tag=as76d14826 (62) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: (36) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Contact: (39) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 1497d5e3411127bc1ac855da2da1bd99@192.168.119.251 (57) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Date: Thu, 10 Apr 2008 14:21:43 GMT (35) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 11: Supported: replaces (19) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (NAT) to 192.168.165.3:5161: OPTIONS sip:809962@192.168.165.3:5161 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK16fb84e7;rport From: "asterisk" ;tag=as76d14826 To: Contact: Call-ID: 1497d5e3411127bc1ac855da2da1bd99@192.168.119.251 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 10 Apr 2008 14:21:43 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:2044 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 obelix*CLI> <--- SIP read from 192.168.165.3:5161 ---> SIP/2.0 486 Busy Here To: ;tag=dbd98811a89e6553i1 From: "asterisk" ;tag=as76d14826 Call-ID: 1497d5e3411127bc1ac855da2da1bd99@192.168.119.251 CSeq: 102 OPTIONS Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK16fb84e7 Server: Linksys/SPA8000-5.1.9 Content-Length: 0 Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER Supported: x-sipura, replaces <-------------> [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 486 Busy Here (21) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: To: ;tag=dbd98811a89e6553i1 (59) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "asterisk" ;tag=as76d14826 (62) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: Call-ID: 1497d5e3411127bc1ac855da2da1bd99@192.168.119.251 (57) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: CSeq: 102 OPTIONS (17) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK16fb84e7 (60) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Server: Linksys/SPA8000-5.1.9 (29) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: Content-Length: 0 (17) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Allow: ACK, BYE, CANCEL, INFO, INVITE, NOTIFY, OPTIONS, REFER (61) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Supported: x-sipura, replaces (29) [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: (0) --- (10 headers 0 lines) --- [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:2167 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15116 [Apr 10 16:21:43] DEBUG[17555]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '1497d5e3411127bc1ac855da2da1bd99@192.168.119.251' of Request 102: Match Found Really destroying SIP dialog '1497d5e3411127bc1ac855da2da1bd99@192.168.119.251' Method: OPTIONS [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4548 sip_alloc: Allocating new SIP dialog for (No Call-ID) - OPTIONS (No RTP) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: OPTIONS sip:192.168.119.225 SIP/2.0 (35) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK7ac5b4d2;rport (66) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "asterisk" ;tag=as05ce56f5 (62) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: (25) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Contact: (39) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 1a6756e528d2056212436af55faa8a73@192.168.119.251 (57) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: CSeq: 102 OPTIONS (17) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: User-Agent: Asterisk PBX (24) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Max-Forwards: 70 (16) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Date: Thu, 10 Apr 2008 14:21:51 GMT (35) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 11: Supported: replaces (19) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 12: Content-Length: 0 (17) Reliably Transmitting (no NAT) to 192.168.119.225:5060: OPTIONS sip:192.168.119.225 SIP/2.0 Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK7ac5b4d2;rport From: "asterisk" ;tag=as05ce56f5 To: Contact: Call-ID: 1a6756e528d2056212436af55faa8a73@192.168.119.251 CSeq: 102 OPTIONS User-Agent: Asterisk PBX Max-Forwards: 70 Date: Thu, 10 Apr 2008 14:21:51 GMT Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY Supported: replaces Content-Length: 0 --- [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:2044 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #-1 obelix*CLI> <--- SIP read from 192.168.119.225:5060 ---> SIP/2.0 200 OK Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK7ac5b4d2;rport From: "asterisk" ;tag=as05ce56f5 To: ;tag=7E7FE8D8-1309 Date: Thu, 10 Apr 2008 14:29:56 GMT Call-ID: 1a6756e528d2056212436af55faa8a73@192.168.119.251 Server: Cisco-SIPGateway/IOS-12.x CSeq: 102 OPTIONS Supported: 100rel,resource-priority,replaces Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER Allow-Events: telephone-event Accept: application/sdp Content-Type: application/sdp Content-Length: 155 v=0 o=CiscoSystemsSIP-GW-UserAgent 4305 164 IN IP4 10.10.0.2 s=SIP Call c=IN IP4 10.10.0.2 t=0 0 m=audio 0 RTP/AVP 18 0 8 4 15 3 c=IN IP4 10.10.0.2 <-------------> [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 0: SIP/2.0 200 OK (14) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.119.251:5060;branch=z9hG4bK7ac5b4d2;rport (66) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 2: From: "asterisk" ;tag=as05ce56f5 (62) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 3: To: ;tag=7E7FE8D8-1309 (43) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 4: Date: Thu, 10 Apr 2008 14:29:56 GMT (35) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 5: Call-ID: 1a6756e528d2056212436af55faa8a73@192.168.119.251 (57) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 6: Server: Cisco-SIPGateway/IOS-12.x (33) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 7: CSeq: 102 OPTIONS (17) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 8: Supported: 100rel,resource-priority,replaces (44) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 9: Allow: INVITE, OPTIONS, BYE, CANCEL, ACK, PRACK, UPDATE, REFER, SUBSCRIBE, NOTIFY, INFO, REGISTER (97) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 10: Allow-Events: telephone-event (29) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 11: Accept: application/sdp (23) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 12: Content-Type: application/sdp (29) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 13: Content-Length: 155 (19) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4813 parse_request: Header 14: (0) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: v=0 (3) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: o=CiscoSystemsSIP-GW-UserAgent 4305 164 IN IP4 10.10.0.2 (56) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: s=SIP Call (10) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: c=IN IP4 10.10.0.2 (18) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: t=0 0 (5) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: m=audio 0 RTP/AVP 18 0 8 4 15 3 (31) [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:4845 parse_request: Line: c=IN IP4 10.10.0.2 (18) --- (14 headers 7 lines) --- [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:2167 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #15119 [Apr 10 16:21:51] DEBUG[17555]: chan_sip.c:2195 __sip_ack: Stopping retransmission on '1a6756e528d2056212436af55faa8a73@192.168.119.251' of Request 102: Match Found Really destroying SIP dialog '1a6756e528d2056212436af55faa8a73@192.168.119.251' Method: OPTIONS obelix*CLI> obelix*CLI> obelix*CLI> obelix*CLI> exit obelix:~#