-- Executing [408@calldist-16:3] Dial("SIP/502-08ab6e80", "Local/408@!SIP&Local/102@!SIP|10|g") in new stack [Feb 13 08:42:37] DEBUG[3221]: rtp.c:1579 ast_rtp_make_compatible: Channel 'Local/408@!SIP-cef1,1' has no RTP, not doing anything [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALDEVICES. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDDEVICES. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable COUNT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDDEVICESX. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable EXTENX. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DEVICEX. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable TOTALCALLS. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable RINGING. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable START. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDEXTSTATES. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALSTATUSORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CDL. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLTIME. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable IGNORECALENDAR. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable RINGTIME. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable EXTTYPE. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDDEV. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CONNGROUPORIG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLORIGINORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLORIGIN. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDNAMEORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDEXTORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDCHANNEL. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDNAME. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDEXT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGNAMEORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGEXTORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGCHANNEL. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGNAME. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGEXT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLID. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable ABBRRESULT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CONTEXTORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CONTEXTDEST. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable DIALEDEXTEN. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable DIALEDCONTEXT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called 408@!SIP [Feb 13 08:42:37] DEBUG[3221]: rtp.c:1579 ast_rtp_make_compatible: Channel 'Local/102@!SIP-e5e3,1' has no RTP, not doing anything [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALDEVICES. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDDEVICES. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable COUNT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDDEVICESX. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable EXTENX. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DEVICEX. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable TOTALCALLS. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable RINGING. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable START. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDEXTSTATES. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALSTATUSORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CDL. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLTIME. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable IGNORECALENDAR. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable RINGTIME. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable EXTTYPE. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDDEV. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CONNGROUPORIG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLORIGINORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLORIGIN. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDNAMEORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDEXTORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDCHANNEL. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDNAME. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLEDEXT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGNAMEORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGEXTORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGCHANNEL. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGNAME. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLINGEXT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLID. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable ABBRRESULT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CONTEXTORG. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CONTEXTDEST. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable DIALEDEXTEN. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable DIALEDCONTEXT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 13 08:42:37] DEBUG[3221]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called 102@!SIP [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:1] Set("Local/408@!SIP-cef1,2", "_LOCALSOURCECHANNEL=Local/408@!SIP-cef1,2") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:2] Set("Local/408@!SIP-cef1,2", "CALLEDPEER=408") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:3] Set("Local/408@!SIP-cef1,2", "CALLCHANNEL=SIP/408") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:4] Set("Local/408@!SIP-cef1,2", "GROUP(RING_EXT)=408") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:5] Set("Local/408@!SIP-cef1,2", "CONNGROUPDEST=") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [408@!SIP:6] GotoIf("Local/408@!SIP-cef1,2", "1?CCG") in new stack -- Goto (!SIP,408,8) [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'MacroIf' -- Executing [408@!SIP:8] MacroIf("Local/408@!SIP-cef1,2", "0?conngroup|||0|0|1") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Gosub' -- Executing [408@!SIP:9] Gosub("Local/408@!SIP-cef1,2", "!SIP-sring|408|1") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'snom360/6.5.15' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP-sring:1] Set("Local/408@!SIP-cef1,2", "ARRAY(PEERAGENT|ORG)=snom360/6.5.15,INT") in new stack [Feb 13 08:42:37] DEBUG[3223]: func_strings.c:197 array: array (PEERAGENT|ORG=snom360/6.5.15,INT) [Feb 13 08:42:37] DEBUG[3223]: func_strings.c:210 array: array set value (PEERAGENT=snom360/6.5.15) [Feb 13 08:42:37] DEBUG[3223]: func_strings.c:210 array: array set value (ORG=INT) [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '5' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [408@!SIP-sring:2] GotoIf("Local/408@!SIP-cef1,2", "5?NEXT") in new stack -- Goto (!SIP-sring,408,6) [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'ExecIf' -- Executing [408@!SIP-sring:6] ExecIf("Local/408@!SIP-cef1,2", "0|Set|ORG=EXT") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [408@!SIP-sring:7] GotoIf("Local/408@!SIP-cef1,2", "1?DEFAULT") in new stack -- Goto (!SIP-sring,408,11) [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'ExecIf' -- Executing [408@!SIP-sring:11] ExecIf("Local/408@!SIP-cef1,2", "0|Return|") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'ExecIf' -- Executing [408@!SIP-sring:12] ExecIf("Local/408@!SIP-cef1,2", "0|Return") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'SIPAddHeader' -- Executing [408@!SIP-sring:13] SIPAddHeader("Local/408@!SIP-cef1,2", "Alert-Info: ") in new stack [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:17704 sip_addheader: SIP Header added "Alert-Info: " as _SIPADDHEADER01 [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Return' -- Executing [408@!SIP-sring:14] Return("Local/408@!SIP-cef1,2", "") in new stack [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '11' [Feb 13 08:42:37] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Dial' -- Executing [408@!SIP:10] Dial("Local/408@!SIP-cef1,2", "SIP/408|11|gM(!CONNECTEXT^408)") in new stack [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:15939 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4518 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:2738 do_setnat: Setting NAT on RTP to Off [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4002 sip_new: *** Our native formats are 0x8 (alaw) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4003 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4004 sip_new: *** Our capabilities are 0x8 (alaw) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4005 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4007 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4028 sip_new: This channel will not be able to handle video. [Feb 13 08:42:37] DEBUG[3223]: rtp.c:1586 ast_rtp_make_compatible: Channel 'Local/408@!SIP-cef1,2' has no RTP, not doing anything [Feb 13 08:42:37] DEBUG[3223]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER01. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable ORG. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable PEERAGENT. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CONNGROUPDEST. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLCHANNEL. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDPEER. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable LOCALSOURCECHANNEL. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDDEVICES. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CDL. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLTIME. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable IGNORECALENDAR. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable RINGTIME. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable EXTTYPE. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDDEV. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CONNGROUPORIG. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLORIGINORG. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLORIGIN. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDNAMEORG. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDEXTORG. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDCHANNEL. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDNAME. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDEXT. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLINGNAMEORG. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLINGEXTORG. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLINGCHANNEL. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLINGNAME. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLINGEXT. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLID. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CONTEXTORG. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CONTEXTDEST. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALEDEXTEN. [Feb 13 08:42:37] DEBUG[3223]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALEDCONTEXT. [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:2996 sip_call: Outgoing Call for 408 [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:3182 update_call_counter: Updating call counter for outgoing call [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:3259 update_call_counter: Call to peer '408' is 1 out of 30 [Feb 13 08:42:37] DEBUG[3223]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408 [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:3011 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:7076 transmit_invite: Adding SIP Header "Alert-Info" with content :: [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:6430 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:6431 add_sdp: ** Our prefcodec: 0x8 (alaw) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:6562 add_sdp: -- Done with adding codecs to SDP [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:6607 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 0: INVITE sip:408@192.168.161.233:5060;line=oiiau83k SIP/2.0 (57) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfee308;rport (66) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as69752b41 (61) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 3: To: (48) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 4: Contact: (34) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 5: Call-ID: 79994a780c7a93a1489b392116fe0c34@pbx.example.net (57) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 9: Remote-Party-ID: "Handset Theo" ;privacy=off;screen=no (79) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 10: Date: Wed, 13 Feb 2008 07:42:37 GMT (35) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 12: Supported: replaces (19) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 13: Alert-Info: (43) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 14: Content-Type: application/sdp (29) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 15: Content-Length: 244 (19) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4783 parse_request: Header 16: (0) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: v=0 (3) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: o=root 2414 2414 IN IP4 192.168.161.100 (39) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: s=session (9) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: c=IN IP4 192.168.161.100 (24) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: t=0 0 (5) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: m=audio 13036 RTP/AVP 8 101 (27) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: a=ptime:20 (10) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:37] DEBUG[3223]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #311 -- Called 408 [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:1] Set("Local/102@!SIP-e5e3,2", "_LOCALSOURCECHANNEL=Local/102@!SIP-e5e3,2") in new stack [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:2] Set("Local/102@!SIP-e5e3,2", "CALLEDPEER=102") in new stack [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:3] Set("Local/102@!SIP-e5e3,2", "CALLCHANNEL=SIP/102") in new stack [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:4] Set("Local/102@!SIP-e5e3,2", "GROUP(RING_EXT)=408") in new stack [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:5] Set("Local/102@!SIP-e5e3,2", "CONNGROUPDEST=") in new stack [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [102@!SIP:6] GotoIf("Local/102@!SIP-e5e3,2", "1?CCG") in new stack -- Goto (!SIP,102,8) [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'MacroIf' -- Executing [102@!SIP:8] MacroIf("Local/102@!SIP-e5e3,2", "0?conngroup|||0|0|1") in new stack [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Gosub' -- Executing [102@!SIP:9] Gosub("Local/102@!SIP-e5e3,2", "!SIP-sring|102|1") in new stack [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'acMP114/v.5.20A.018.008' [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP-sring:1] Set("Local/102@!SIP-e5e3,2", "ARRAY(PEERAGENT|ORG)=acMP114/v.5.20A.018.008,INT") in new stack [Feb 13 08:42:37] DEBUG[3224]: func_strings.c:197 array: array (PEERAGENT|ORG=acMP114/v.5.20A.018.008,INT) [Feb 13 08:42:37] DEBUG[3224]: func_strings.c:210 array: array set value (PEERAGENT=acMP114/v.5.20A.018.008) [Feb 13 08:42:37] DEBUG[3224]: func_strings.c:210 array: array set value (ORG=INT) [Feb 13 08:42:37] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 6 (Ringing) [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 Reliably Transmitting (no NAT) to 192.168.161.242:1037: NOTIFY sip:406@192.168.161.242:1037;line=fqekjdfm SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3cb14b2e;rport From: ;tag=as6a985741 To: ;tag=txmy8j3apc Contact: Call-ID: 3c26702882dd-ttiu7ql9fviz CSeq: 103 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 223 early --- [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #315 Extension Changed 408[subscriptions] new state Ringing for Notify User 406 [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 6 (Ringing) [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:37] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:37] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:37] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/408' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 13 08:42:37] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/102' changed to state '6' (Ringing) but we don't care because they're not a member of any queue. [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK47b5e74c;rport (66) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as0f557d85 (61) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=1c1642311888 (46) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 711342964141ad5f2c3e1a213f3fb324@pbx.example.net (57) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Supported: em,timer,replaces,path,early-session,resource-priority (65) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Server: acMP114/v.5.20A.018.008 (31) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Content-Length: 0 (17) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: (0) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:2208 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #313 - INVITE (got response) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:2217 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '711342964141ad5f2c3e1a213f3fb324@pbx.example.net' Request 102: Found [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:12012 handle_response_invite: SIP response 100 to standard invite [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK47b5e74c;rport (66) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as0f557d85 (61) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=1c1642311888 (46) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 711342964141ad5f2c3e1a213f3fb324@pbx.example.net (57) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Contact: (34) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Supported: em,timer,replaces,path,early-session,resource-priority (65) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Server: acMP114/v.5.20A.018.008 (31) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Content-Length: 0 (17) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: (0) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:2217 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '711342964141ad5f2c3e1a213f3fb324@pbx.example.net' Request 102: Found [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:12012 handle_response_invite: SIP response 180 to standard invite [Feb 13 08:42:37] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102-08adc6f8 -- SIP/102-08adc6f8 is ringing [Feb 13 08:42:37] DEBUG[3224]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/102@!SIP-e5e3,2' has no RTP, not doing anything [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bK5rNupPyTxGzq4K.J (63) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=gkC.OK (42) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: (31) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: ZE2PWjAMHf@pbx.example.net (35) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 3896 SUBSCRIBE (20) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Accept: application/simple-message-summary (42) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Allow-Events: dialog,message-summary (36) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Event: message-summary (22) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Expires: 3600 (13) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: Supported: replaces (19) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 14: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 15: Content-Type: text/plain (24) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 16: Content-Length: 0 (17) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 17: (0) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4518 sip_alloc: Allocating new SIP dialog for ZE2PWjAMHf@pbx.example.net - SUBSCRIBE (No RTP) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKvTPoVXlacjVJ1kGXJ (64) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=gkC.OK (42) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: (31) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: ZE2PWjAMHf@pbx.example.net (35) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 3897 SUBSCRIBE (20) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Allow-Events: dialog,message-summary (36) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Authorization: Digest username="503", realm="siprealm", nonce="721630bd", uri="sip:Voice@pbx.example.net", response="1e56aa24aaace3e8bc8773e4642f5c58", algorithm=MD5 (165) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Event: message-summary (22) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Expires: 3600 (13) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: Content-Length: 0 (17) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 14: (0) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Really destroying SIP dialog 'ZE2PWjAMHf@pbx.example.net' Method: SUBSCRIBE [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfee308;rport=5060 (71) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as69752b41 (61) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=rm7sc5n1th (63) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 79994a780c7a93a1489b392116fe0c34@pbx.example.net (57) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Content-Length: 0 (17) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: (0) [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:2217 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '79994a780c7a93a1489b392116fe0c34@pbx.example.net' Request 102: Found [Feb 13 08:42:37] DEBUG[3198]: chan_sip.c:12012 handle_response_invite: SIP response 180 to standard invite -- SIP/408-08ad5e60 is ringing [Feb 13 08:42:37] DEBUG[3223]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-cef1,2' has no RTP, not doing anything [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKdroONPmQgsJxR2W3OZIBchuQ.7Ay5 (76) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=MfEvs5VbV0b9e (49) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: (31) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: kJ44X9j0GgZ6BV50E@pbx.example.net (42) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 14237 SUBSCRIBE (21) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Accept: application/simple-message-summary (42) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Allow-Events: dialog,message-summary (36) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Event: message-summary (22) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Expires: 3600 (13) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: Supported: replaces (19) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 14: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 15: Content-Type: text/plain (24) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 16: Content-Length: 0 (17) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 17: (0) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4518 sip_alloc: Allocating new SIP dialog for kJ44X9j0GgZ6BV50E@pbx.example.net - SUBSCRIBE (No RTP) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKPYR80w4rogHA (59) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=MfEvs5VbV0b9e (49) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: (31) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: kJ44X9j0GgZ6BV50E@pbx.example.net (42) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 14238 SUBSCRIBE (21) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Allow-Events: dialog,message-summary (36) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Authorization: Digest username="501", realm="siprealm", nonce="557e32d7", uri="sip:Voice@pbx.example.net", response="2aa2e3593ab09e48a87846e32c5043f7", algorithm=MD5 (165) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Event: message-summary (22) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Expires: 3600 (13) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: Content-Length: 0 (17) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 14: (0) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Really destroying SIP dialog 'kJ44X9j0GgZ6BV50E@pbx.example.net' Method: SUBSCRIBE [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:405@pbx.example.net;user=phone SIP/2.0 (52) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.248:5060;branch=z9hG4bK-q7pq772bn9oh;rport (71) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=wv2jth0wgx (46) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=as75c2f844 (55) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670175091-swg7kfgu6h6e@snom320-0004132496DC (55) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 41 SUBSCRIBE (18) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Event: dialog (13) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Accept: application/dialog-info+xml (35) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Expires: 60 (11) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Length: 0 (17) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: (0) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:405@pbx.example.net;user=phone SIP/2.0 (52) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.248:5060;branch=z9hG4bK-ch8rl1mi4czj;rport (71) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=wv2jth0wgx (46) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=as75c2f844 (55) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670175091-swg7kfgu6h6e@snom320-0004132496DC (55) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 42 SUBSCRIBE (18) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Event: dialog (13) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Accept: application/dialog-info+xml (35) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Authorization: Digest username="403",realm="siprealm",nonce="64ca6c4e",uri="sip:405@pbx.example.net;user=phone",response="f2cfda670aa31730d4288639363abf06",algorithm=MD5 (169) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Expires: 60 (11) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Length: 0 (17) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: (0) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:15032 handle_request_subscribe: Adding subscription for extension 405 context subscriptions for peer 403 [Feb 13 08:42:38] DEBUG[3198]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 405 [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 405 [Feb 13 08:42:38] DEBUG[3198]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 405 [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 405 [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #320 [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK056dbbef;rport=5060 (71) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as75c2f844 (57) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=wv2jth0wgx (44) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670175091-swg7kfgu6h6e@snom320-0004132496DC (55) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 106 NOTIFY (16) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Content-Length: 0 (17) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: (0) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 106 [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #320 [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '3c2670175091-swg7kfgu6h6e@snom320-0004132496DC' of Request 106: Match Not Found [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfee308;rport=5060 (71) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as69752b41 (61) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=rm7sc5n1th (63) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 79994a780c7a93a1489b392116fe0c34@pbx.example.net (57) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Content-Length: 0 (17) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: (0) [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:2217 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '79994a780c7a93a1489b392116fe0c34@pbx.example.net' Request 102: Found [Feb 13 08:42:38] DEBUG[3198]: chan_sip.c:12012 handle_response_invite: SIP response 180 to standard invite -- SIP/408-08ad5e60 is ringing [Feb 13 08:42:38] DEBUG[3223]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-cef1,2' has no RTP, not doing anything [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bK2lRk8SjcNUNxCZsN3pWWxWLp (71) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=SRfZHAYQEQHqA5 (50) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: (29) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: pCjuFHkwfwRgDzoeZQbQrPHfqnexAe (39) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 5337 REGISTER (19) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Expires: 60 (11) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Length: 0 (17) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: (0) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bK4F5xWyaSMnV6 (59) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=SRfZHAYQEQHqA5 (50) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: (29) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: pCjuFHkwfwRgDzoeZQbQrPHfqnexAe (39) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 5338 REGISTER (19) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Authorization: Digest username="501", realm="siprealm", nonce="12b6aa7e", uri="sip:pbx.example.net", response="123fbd6729d53c125a421f172099ab53", algorithm=MD5 (159) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Expires: 60 (11) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Length: 0 (17) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: (0) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 13 08:42:40] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/501 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 501 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 501 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/501 - state 1 (Not in use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 501 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 501 [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/501' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfee308;rport=5060 (71) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as69752b41 (61) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=rm7sc5n1th (63) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 79994a780c7a93a1489b392116fe0c34@pbx.example.net (57) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Content-Length: 0 (17) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: (0) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2217 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '79994a780c7a93a1489b392116fe0c34@pbx.example.net' Request 102: Found [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:12012 handle_response_invite: SIP response 180 to standard invite -- SIP/408-08ad5e60 is ringing [Feb 13 08:42:40] DEBUG[3223]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-cef1,2' has no RTP, not doing anything [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfee308;rport=5060 (71) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as69752b41 (61) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=rm7sc5n1th (63) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 79994a780c7a93a1489b392116fe0c34@pbx.example.net (57) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: User-Agent: snom360/6.5.15 (26) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Allow-Events: talk, hold, refer (31) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Supported: timer, 100rel, replaces, callerid (44) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Type: application/sdp (29) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Length: 226 (19) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: (0) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: v=0 (3) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: o=root 1086124800 1086124801 IN IP4 192.168.161.233 (51) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: s=call (6) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: c=IN IP4 192.168.161.233 (24) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: t=0 0 (5) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: m=audio 17608 RTP/AVP 8 101 (27) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=ptime:20 (10) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 102 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '79994a780c7a93a1489b392116fe0c34@pbx.example.net' of Request 102: Match Not Found [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:12012 handle_response_invite: SIP response 200 to standard invite [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:5397 process_sdp: T38 state changed to 0 on channel SIP/408-08ad5e60 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:5477 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:5484 process_sdp: We have an owner, now see if we need to change this call [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:3182 update_call_counter: Updating call counter for outgoing call [Feb 13 08:42:40] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:8265 build_route: build_route: Contact hop: ;flow-id=1 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:5880 reqprep: Strict routing enforced for session 79994a780c7a93a1489b392116fe0c34@pbx.example.net [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 2 (In use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 Reliably Transmitting (no NAT) to 192.168.161.242:1037: NOTIFY sip:406@192.168.161.242:1037;line=fqekjdfm SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK4d4d7126;rport From: ;tag=as6a985741 To: ;tag=txmy8j3apc Contact: Call-ID: 3c26702882dd-ttiu7ql9fviz CSeq: 104 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 223 early --- [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #324 Extension Changed 408[subscriptions] new state InUse&Ringing for Notify User 406 [Feb 13 08:42:40] DEBUG[3223]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408-08ad5e60 -- SIP/408-08ad5e60 answered Local/408@!SIP-cef1,2 [Feb 13 08:42:40] DEBUG[3223]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-cef1,2' has no RTP, not doing anything [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-!CONNECTEXT:1] GotoIf("SIP/408-08ad5e60", "0?END") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '2' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/408' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-!CONNECTEXT:2] GotoIf("SIP/408-08ad5e60", "0?SKIP") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '2' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/408' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-!CONNECTEXT:3] Set("SIP/408-08ad5e60", "CALLCHANNEL=SIP/408") in new stack [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '2' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/408-08ad5e60' [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/408' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 2 (In use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/408' changed to state '2' (In use) but we don't care because they're not a member of any queue. > Found no rows [SELECT nr FROM viewextensiondata WHERE devicename = 'SIP/408-08ad5e60' LIMIT 1] [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-!CONNECTEXT:4] Set("SIP/408-08ad5e60", "ARG1=") in new stack [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-!CONNECTEXT:5] Set("SIP/408-08ad5e60", "GROUP(DEST_EXT)=") in new stack [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '408' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-!CONNECTEXT:6] Set("SIP/408-08ad5e60", "CONNGROUPDEST=") in new stack [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-!CONNECTEXT:7] GotoIf("SIP/408-08ad5e60", "1?SETLAST") in new stack -- Goto (macro-!CONNECTEXT,s,9) [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-!CONNECTEXT:9] GotoIf("SIP/408-08ad5e60", "1?END") in new stack -- Goto (macro-!CONNECTEXT,s,11) [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-!CONNECTEXT:11] NoOp("SIP/408-08ad5e60", "Call 1202888557.5 on channel SIP/408-08ad5e60 to SIP/408 was answered.") in new stack [Feb 13 08:42:40] DEBUG[3223]: app_macro.c:337 _macro_exec: Executed application: NoOp [Feb 13 08:42:40] DEBUG[3223]: app_dial.c:1609 dial_exec_full: Macro exited with status 0 [Feb 13 08:42:40] DEBUG[3223]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/408@!SIP-cef1,2 -- Local/408@!SIP-cef1,1 stopped sounds [Feb 13 08:42:40] DEBUG[3221]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/408@!SIP-cef1,1 -- Local/408@!SIP-cef1,1 answered SIP/502-08ab6e80 [Feb 13 08:42:40] DEBUG[3221]: rtp.c:1504 ast_rtp_early_bridge: Channel 'Local/408@!SIP-cef1,1' has no RTP, not doing anything [Feb 13 08:42:40] DEBUG[3221]: channel.c:1789 ast_hangup: Hanging up channel 'Local/102@!SIP-e5e3,1' [Feb 13 08:42:40] DEBUG[3221]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/102@!SIP-e5e3,1 [Feb 13 08:42:40] DEBUG[3221]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 13 08:42:40] DEBUG[3221]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502-08ab6e80 [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:3656 sip_answer: SIP answering channel: SIP/502-08ab6e80 [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6666 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6430 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6431 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6562 add_sdp: -- Done with adding codecs to SDP [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6607 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #325 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 408@!SIP [Feb 13 08:42:40] DEBUG[3180]: chan_local.c:145 local_devicestate: Checking if extension 408@!SIP exists (devicestate) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for Local/408@!SIP - state 2 (In use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 408@!SIP [Feb 13 08:42:40] DEBUG[3180]: chan_local.c:145 local_devicestate: Checking if extension 408@!SIP exists (devicestate) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for Local/408@!SIP - state 2 (In use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 102@!SIP [Feb 13 08:42:40] DEBUG[3180]: chan_local.c:145 local_devicestate: Checking if extension 102@!SIP exists (devicestate) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for Local/102@!SIP - state 2 (In use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 2 (In use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:40] DEBUG[3224]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/102@!SIP-e5e3,2' has no RTP, not doing anything [Feb 13 08:42:40] DEBUG[3224]: channel.c:1789 ast_hangup: Hanging up channel 'SIP/102-08adc6f8' [Feb 13 08:42:40] DEBUG[3224]: chan_sip.c:3494 sip_hangup: Hangup call SIP/102-08adc6f8, SIP callid 711342964141ad5f2c3e1a213f3fb324@pbx.example.net) [Feb 13 08:42:40] DEBUG[3224]: chan_sip.c:3503 sip_hangup: update_call_counter(102) - decrement call limit counter on hangup [Feb 13 08:42:40] DEBUG[3224]: chan_sip.c:3182 update_call_counter: Updating call counter for outgoing call [Feb 13 08:42:40] DEBUG[3224]: chan_sip.c:3233 update_call_counter: Call to peer '102' removed from call limit 30 [Feb 13 08:42:40] DEBUG[3224]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102 [Feb 13 08:42:40] DEBUG[3224]: chan_sip.c:3517 sip_hangup: Hanging up channel in state Ringing (not UP) [Feb 13 08:42:40] DEBUG[3224]: chan_sip.c:2157 __sip_ack: Acked pending invite 102 [Feb 13 08:42:40] DEBUG[3224]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '711342964141ad5f2c3e1a213f3fb324@pbx.example.net' of Request 102: Match Not Found [Feb 13 08:42:40] DEBUG[3224]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #327 [Feb 13 08:42:40] DEBUG[3224]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102-08adc6f8 [Feb 13 08:42:40] DEBUG[3224]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 13 08:42:40] DEBUG[3224]: app_dial.c:1770 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Feb 13 08:42:40] DEBUG[3224]: pbx.c:2443 __ast_pbx_run: Spawn extension (!SIP,102,10) exited non-zero on 'Local/102@!SIP-e5e3,2' == Spawn extension (!SIP, 102, 10) exited non-zero on 'Local/102@!SIP-e5e3,2' [Feb 13 08:42:40] DEBUG[3224]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'Local/102@!SIP-e5e3,2' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'GosubIf' -- Executing [h@!SIP:1] GosubIf("Local/102@!SIP-e5e3,2", "1?s|CDR") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.649932' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.649932' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.580668' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:2] Set("Local/102@!SIP-e5e3,2", "RINGINGTIME=3.580668") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '502' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'Local/408@!SIP' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'Local/408@!SIP' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'Local/102@!SIP' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/502' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 Extension Changed 408[subscriptions] new state InUse for Notify User 406 (queued) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 -- Executing [s@!SIP:3] Set("Local/102@!SIP-e5e3,2", "CALLINGEXT2=502") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'NULL' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:4] Set("Local/102@!SIP-e5e3,2", "TRUNKID2=NULL") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Return' -- Executing [s@!SIP:5] Return("Local/102@!SIP-e5e3,2", "") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@!SIP:2] GotoIf("Local/102@!SIP-e5e3,2", "1?!SIP-evaluate|s|CANCEL") in new stack -- Goto (!SIP-evaluate,s,6) [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@!SIP-evaluate:6] GotoIf("Local/102@!SIP-e5e3,2", "0?NOANSWER") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@!SIP-evaluate:7] GotoIf("Local/102@!SIP-e5e3,2", "0?PICKUPALT") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'NoOp' -- Executing [s@!SIP-evaluate:8] NoOp("Local/102@!SIP-e5e3,2", ".... Call 1202888557 on channel Local/102@!SIP-e5e3,2 to SIP/102 Cancelled by the Calling Party ....") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888557.209025' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/102-08adc6f8' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/102-08adc6f8' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '"Handset Theo" <502>' [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@!SIP-evaluate:9] ExecIf("Local/102@!SIP-e5e3,2", "1|Set|ODBC_CDR()=1202888557,NULL,1202888557.209025,1202888560.902262,'502','408','SIP/502-08ab6e80','SIP/102-08adc6f8','user-01','user-08','CANCELLED',3.580668,0,'','"Handset Theo" <502>','phone','','16'") in new stack [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: ACK sip:408@192.168.161.100 SIP/2.0 (35) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKPUmTTBrQtNHPt5zkznBmOZmm (71) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: "502 Theo" ;tag=XtDm8c23Z4 (57) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: ;tag=as3e31d487 (44) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (50) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 63983 ACK (15) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Proxy-Authorization: Digest username="502", realm="siprealm", nonce="08439df2", uri="sip:408@192.168.161.100", response="998efac997c8006919f01372eb933f6d", algorithm=MD5 (169) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Content-Length: 0 (17) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: (0) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #325 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' of Response 63983: Match Not Found <--- SIP read from 192.168.161.242:1037 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK4d4d7126;rport=5060 From: ;tag=as6a985741 To: ;tag=txmy8j3apc Call-ID: 3c26702882dd-ttiu7ql9fviz CSeq: 104 NOTIFY Content-Length: 0 <-------------> [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK4d4d7126;rport=5060 (71) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as6a985741 (57) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=txmy8j3apc (44) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c26702882dd-ttiu7ql9fviz (34) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 104 NOTIFY (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Content-Length: 0 (17) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: (0) --- (7 headers 0 lines) --- [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 104 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #324 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '3c26702882dd-ttiu7ql9fviz' of Request 104: Match Not Found SIP Response message for INCOMING dialog NOTIFY arrived [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 487 Request Terminated (30) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK47b5e74c;rport (66) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as0f557d85 (61) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=1c1642311888 (46) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 711342964141ad5f2c3e1a213f3fb324@pbx.example.net (57) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Supported: em,timer,replaces,path,early-session,resource-priority (65) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Server: acMP114/v.5.20A.018.008 (31) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Reason: SIP ;cause=487 ;text="487 Request Terminated" (53) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Content-Length: 0 (17) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: (0) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '711342964141ad5f2c3e1a213f3fb324@pbx.example.net' of Request 102: Match Found [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:12012 handle_response_invite: SIP response 487 to standard invite [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:3182 update_call_counter: Updating call counter for outgoing call [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:3233 update_call_counter: Call to peer '102' removed from call limit 30 [Feb 13 08:42:40] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:1657 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 711342964141ad5f2c3e1a213f3fb324@pbx.example.net [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:40] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/102' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK47b5e74c;rport (66) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as0f557d85 (61) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=1c1642311888 (46) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 711342964141ad5f2c3e1a213f3fb324@pbx.example.net (57) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 CANCEL (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Contact: (34) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Supported: em,timer,replaces,path,early-session,resource-priority (65) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Server: acMP114/v.5.20A.018.008 (31) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Content-Length: 0 (17) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: (0) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #327 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '711342964141ad5f2c3e1a213f3fb324@pbx.example.net' of Request 102: Match Not Found Really destroying SIP dialog '711342964141ad5f2c3e1a213f3fb324@pbx.example.net' Method: INVITE [Feb 13 08:42:40] DEBUG[3224]: pbx.c:1847 pbx_extension_helper: Launching 'Hangup' -- Executing [s@!SIP-evaluate:10] Hangup("Local/102@!SIP-e5e3,2", "") in new stack [Feb 13 08:42:40] DEBUG[3224]: pbx.c:2566 __ast_pbx_run: Spawn extension (!SIP-evaluate,s,10) exited non-zero on 'Local/102@!SIP-e5e3,2' == Spawn extension (!SIP-evaluate, s, 10) exited non-zero on 'Local/102@!SIP-e5e3,2' [Feb 13 08:42:40] DEBUG[3224]: channel.c:1789 ast_hangup: Hanging up channel 'Local/102@!SIP-e5e3,2' [Feb 13 08:42:40] DEBUG[3224]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/102@!SIP-e5e3,2 [Feb 13 08:42:40] DEBUG[3224]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 102@!SIP [Feb 13 08:42:40] DEBUG[3180]: chan_local.c:145 local_devicestate: Checking if extension 102@!SIP exists (devicestate) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for Local/102@!SIP - state 1 (Not in use) [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'Local/102@!SIP' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3223]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 13 08:42:40] DEBUG[3223]: rtp.c:2776 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Feb 13 08:42:40] DEBUG[3223]: channel.c:3512 ast_channel_masquerade: Planning to masquerade channel SIP/408-08ad5e60 into the structure of Local/408@!SIP-cef1,1 [Feb 13 08:42:40] DEBUG[3223]: channel.c:3526 ast_channel_masquerade: Done planning to masquerade channel SIP/408-08ad5e60 into the structure of Local/408@!SIP-cef1,1 [Feb 13 08:42:40] DEBUG[3223]: chan_local.c:295 local_write: Not posting to queue since already masked on 'Local/408@!SIP-cef1,2' [Feb 13 08:42:40] DEBUG[3221]: channel.c:3637 ast_do_masquerade: Actually Masquerading SIP/408-08ad5e60(6) into the structure of Local/408@!SIP-cef1,1(6) [Feb 13 08:42:40] DEBUG[3221]: channel.c:3649 ast_do_masquerade: Got clone lock for masquerade on 'SIP/408-08ad5e60' at 0x8ad9fe8 [Feb 13 08:42:40] DEBUG[3221]: channel.c:3852 ast_do_masquerade: Putting channel SIP/408-08ad5e60 in 8/8 formats [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:3781 sip_fixup: SIP Fixup: New owner for dialogue 79994a780c7a93a1489b392116fe0c34@pbx.example.net: SIP/408-08ad5e60 (Old parent: Local/408@!SIP-cef1,1) [Feb 13 08:42:40] DEBUG[3221]: channel.c:3892 ast_do_masquerade: Released clone lock on 'Local/408@!SIP-cef1,1' [Feb 13 08:42:40] DEBUG[3221]: channel.c:3902 ast_do_masquerade: Done Masquerading SIP/408-08ad5e60 (6) -- Native bridging SIP/502-08ab6e80 and SIP/408-08ad5e60 [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:17590 sip_set_rtp_peer: Sending reinvite on SIP 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' - It's audio soon redirected to IP 192.168.161.233 [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:5880 reqprep: Strict routing enforced for session WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6430 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6431 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6562 add_sdp: -- Done with adding codecs to SDP [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6607 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:1645 initialize_initreq: Initializing already initialized SIP dialog WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (presumably reinvite) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 0: INVITE sip:502@192.168.161.227 SIP/2.0 (38) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK7573ee8d;rport (66) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as3e31d487 (46) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 3: To: "502 Theo" ;tag=XtDm8c23Z4 (55) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 4: Contact: (34) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 5: Call-ID: WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (50) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 10: Supported: replaces (19) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 13: Content-Length: 244 (19) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 14: (0) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: v=0 (3) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: o=root 2414 2415 IN IP4 192.168.161.233 (39) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: s=session (9) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: c=IN IP4 192.168.161.233 (24) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: t=0 0 (5) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: m=audio 17608 RTP/AVP 8 101 (27) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=ptime:20 (10) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #331 [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:17590 sip_set_rtp_peer: Sending reinvite on SIP '79994a780c7a93a1489b392116fe0c34@pbx.example.net' - It's audio soon redirected to IP 192.168.161.227 [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:5880 reqprep: Strict routing enforced for session 79994a780c7a93a1489b392116fe0c34@pbx.example.net [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6430 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6431 add_sdp: ** Our prefcodec: 0x8 (alaw) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6562 add_sdp: -- Done with adding codecs to SDP [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:6607 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:1645 initialize_initreq: Initializing already initialized SIP dialog 79994a780c7a93a1489b392116fe0c34@pbx.example.net (presumably reinvite) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 0: INVITE sip:408@192.168.161.233:5060;line=oiiau83k SIP/2.0 (57) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK2e4dcaab;rport (66) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as69752b41 (61) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=rm7sc5n1th (63) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 4: Contact: (34) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 5: Call-ID: 79994a780c7a93a1489b392116fe0c34@pbx.example.net (57) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 6: CSeq: 103 INVITE (16) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 9: Remote-Party-ID: "Handset Theo" ;privacy=off;screen=no (79) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 11: Supported: replaces (19) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 12: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 13: Content-Type: application/sdp (29) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 14: Content-Length: 244 (19) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 15: (0) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: v=0 (3) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: o=root 2414 2415 IN IP4 192.168.161.227 (39) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: s=session (9) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: c=IN IP4 192.168.161.227 (24) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: t=0 0 (5) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: m=audio 10012 RTP/AVP 8 101 (27) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=ptime:20 (10) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:40] DEBUG[3221]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #332 [Feb 13 08:42:40] DEBUG[3223]: channel.c:4088 ast_generic_bridge: Didn't get a frame from channel: Local/408@!SIP-cef1,2 [Feb 13 08:42:40] DEBUG[3223]: channel.c:4413 ast_channel_bridge: Bridge stops bridging channels Local/408@!SIP-cef1,2 and Local/408@!SIP-cef1,1 [Feb 13 08:42:40] DEBUG[3223]: channel.c:1794 ast_hangup: Hanging up zombie 'Local/408@!SIP-cef1,1' [Feb 13 08:42:40] DEBUG[3223]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/408@!SIP-cef1,1 [Feb 13 08:42:40] DEBUG[3223]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-cef1,2' has no RTP, not doing anything [Feb 13 08:42:40] DEBUG[3223]: app_dial.c:1770 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 13 08:42:40] DEBUG[3223]: pbx.c:2443 __ast_pbx_run: Spawn extension (!SIP,408,10) exited non-zero on 'Local/408@!SIP-cef1,2' == Spawn extension (!SIP, 408, 10) exited non-zero on 'Local/408@!SIP-cef1,2' [Feb 13 08:42:40] DEBUG[3223]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'Local/408@!SIP-cef1,2' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GosubIf' -- Executing [h@!SIP:1] GosubIf("Local/408@!SIP-cef1,2", "1?s|CDR") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.741844' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.741844' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.672580' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:2] Set("Local/408@!SIP-cef1,2", "RINGINGTIME=3.672580") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '502' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:3] Set("Local/408@!SIP-cef1,2", "CALLINGEXT2=502") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'NULL' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:4] Set("Local/408@!SIP-cef1,2", "TRUNKID2=NULL") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'Return' -- Executing [s@!SIP:5] Return("Local/408@!SIP-cef1,2", "") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@!SIP:2] GotoIf("Local/408@!SIP-cef1,2", "0?!SIP-evaluate|s|ANSWER") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:40] DEBUG[3223]: pbx.c:1847 pbx_extension_helper: Launching 'ExecIf' -- Executing [h@!SIP:3] ExecIf("Local/408@!SIP-cef1,2", "1|Hangup") in new stack [Feb 13 08:42:40] DEBUG[3223]: pbx.c:2566 __ast_pbx_run: Spawn extension (!SIP,h,3) exited non-zero on 'Local/408@!SIP-cef1,2' == Spawn extension (!SIP, h, 3) exited non-zero on 'Local/408@!SIP-cef1,2' [Feb 13 08:42:40] DEBUG[3223]: channel.c:1789 ast_hangup: Hanging up channel 'Local/408@!SIP-cef1,2' [Feb 13 08:42:40] DEBUG[3223]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/408@!SIP-cef1,2 [Feb 13 08:42:40] DEBUG[3223]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 408@!SIP [Feb 13 08:42:40] DEBUG[3180]: chan_local.c:145 local_devicestate: Checking if extension 408@!SIP exists (devicestate) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for Local/408@!SIP - state 1 (Not in use) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 408@!SIP [Feb 13 08:42:40] DEBUG[3180]: chan_local.c:145 local_devicestate: Checking if extension 408@!SIP exists (devicestate) [Feb 13 08:42:40] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for Local/408@!SIP - state 1 (Not in use) [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'Local/408@!SIP' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'Local/408@!SIP' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:40] DEBUG[3221]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 13 08:42:40] DEBUG[3221]: rtp.c:2776 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport=5060;branch=z9hG4bK7573ee8d (66) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as3e31d487 (46) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: "502 Theo" ;tag=XtDm8c23Z4 (55) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (50) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Content-Length: 0 (17) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: (0) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2208 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #331 - INVITE (got response) [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:2217 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' Request 102: Found [Feb 13 08:42:40] DEBUG[3198]: chan_sip.c:12010 handle_response_invite: SIP response 100 to RE-invite on outgoing call WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport;branch=z9hG4bK7573ee8d (61) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=as3e31d487 (46) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: "502 Theo" ;tag=XtDm8c23Z4 (55) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (50) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Accept: application/sdp (23) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Content-Disposition: session (28) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Type: application/SDP (29) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: Content-Length: 258 (19) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 14: (0) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: v=0 (3) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: o=502 409720241 409720242 IN IP4 192.168.161.227 (48) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: s=- (3) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: c=IN IP4 192.168.161.227 (24) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: t=0 0 (5) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: m=audio 10012 RTP/AVP 8 0 101 (29) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtcp:10013 (12) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 102 [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' of Request 102: Match Not Found [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:12010 handle_response_invite: SIP response 200 to RE-invite on outgoing call WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:5397 process_sdp: T38 state changed to 0 on channel SIP/502-08ab6e80 [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:5477 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:5484 process_sdp: We have an owner, now see if we need to change this call [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:3182 update_call_counter: Updating call counter for incoming call [Feb 13 08:42:41] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502 [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:8265 build_route: build_route: Contact hop: [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:12144 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:12149 handle_response_invite: T38 state changed to 0 on channel SIP [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:12152 handle_response_invite: T38 state changed to 0 on channel SIP/502-08ab6e80 [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:5880 reqprep: Strict routing enforced for session WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net [Feb 13 08:42:41] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:41] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:41] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 2 (In use) [Feb 13 08:42:41] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:41] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:41] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/502' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK2e4dcaab;rport=5060 (71) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Handset Theo" ;tag=as69752b41 (61) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=rm7sc5n1th (63) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 79994a780c7a93a1489b392116fe0c34@pbx.example.net (57) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 103 INVITE (16) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: User-Agent: snom360/6.5.15 (26) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Allow-Events: talk, hold, refer (31) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Supported: timer, 100rel, replaces, callerid (44) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Type: application/sdp (29) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Length: 226 (19) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: (0) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: v=0 (3) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: o=root 1086124800 1086124802 IN IP4 192.168.161.233 (51) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: s=call (6) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: c=IN IP4 192.168.161.233 (24) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: t=0 0 (5) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: m=audio 17608 RTP/AVP 8 101 (27) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=ptime:20 (10) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 103 [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #332 [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '79994a780c7a93a1489b392116fe0c34@pbx.example.net' of Request 103: Match Not Found [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:12010 handle_response_invite: SIP response 200 to RE-invite on outgoing call 79994a780c7a93a1489b392116fe0c34@pbx.example.net [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:5397 process_sdp: T38 state changed to 0 on channel SIP/408-08ad5e60 [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:5477 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:5484 process_sdp: We have an owner, now see if we need to change this call [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:3182 update_call_counter: Updating call counter for outgoing call [Feb 13 08:42:41] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408 [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:8204 build_route: build_route: Retaining previous route: [Feb 13 08:42:41] DEBUG[3198]: chan_sip.c:5880 reqprep: Strict routing enforced for session 79994a780c7a93a1489b392116fe0c34@pbx.example.net [Feb 13 08:42:41] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:41] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:41] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 2 (In use) [Feb 13 08:42:41] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:41] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:41] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:41] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:41] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/408' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 13 08:42:42] DEBUG[3198]: chan_sip.c:2096 __sip_autodestruct: Auto destroying SIP dialog '59854272110122007171049@192.168.161.237' [Feb 13 08:42:42] DEBUG[3198]: chan_sip.c:3291 sip_destroy: Destroying SIP dialog 59854272110122007171049@192.168.161.237 Really destroying SIP dialog '59854272110122007171049@192.168.161.237' Method: REGISTER [Feb 13 08:42:42] DEBUG[3198]: chan_sip.c:2096 __sip_autodestruct: Auto destroying SIP dialog '59854337510122007171049@192.168.161.237' [Feb 13 08:42:42] DEBUG[3198]: chan_sip.c:3291 sip_destroy: Destroying SIP dialog 59854337510122007171049@192.168.161.237 Really destroying SIP dialog '59854337510122007171049@192.168.161.237' Method: REGISTER [Feb 13 08:42:42] DEBUG[3198]: chan_sip.c:2096 __sip_autodestruct: Auto destroying SIP dialog '59854140910122007171049@192.168.161.237' [Feb 13 08:42:42] DEBUG[3198]: chan_sip.c:3291 sip_destroy: Destroying SIP dialog 59854140910122007171049@192.168.161.237 Really destroying SIP dialog '59854140910122007171049@192.168.161.237' Method: REGISTER [Feb 13 08:42:42] DEBUG[3198]: chan_sip.c:2096 __sip_autodestruct: Auto destroying SIP dialog '59854207210122007171049@192.168.161.237' [Feb 13 08:42:42] DEBUG[3198]: chan_sip.c:3291 sip_destroy: Destroying SIP dialog 59854207210122007171049@192.168.161.237 Really destroying SIP dialog '59854207210122007171049@192.168.161.237' Method: REGISTER [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:404@pbx.example.net;user=phone SIP/2.0 (52) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.248:5060;branch=z9hG4bK-c6v5i8wpx6g4;rport (71) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=9t67p2jojg (46) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=as4131d43b (55) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670175091-eywxgfwja4q1@snom320-0004132496DC (55) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 41 SUBSCRIBE (18) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Event: dialog (13) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Accept: application/dialog-info+xml (35) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Expires: 60 (11) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Length: 0 (17) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: (0) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:404@pbx.example.net;user=phone SIP/2.0 (52) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.248:5060;branch=z9hG4bK-rb1gtvcannf8;rport (71) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=9t67p2jojg (46) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=as4131d43b (55) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670175091-eywxgfwja4q1@snom320-0004132496DC (55) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 42 SUBSCRIBE (18) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Event: dialog (13) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Accept: application/dialog-info+xml (35) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Authorization: Digest username="403",realm="siprealm",nonce="1fcf97a3",uri="sip:404@pbx.example.net;user=phone",response="684e1fe844e58135189b6ac7ac7704fd",algorithm=MD5 (169) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Expires: 60 (11) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Length: 0 (17) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: (0) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:15032 handle_request_subscribe: Adding subscription for extension 404 context subscriptions for peer 403 [Feb 13 08:42:43] DEBUG[3198]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 404 [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 404 [Feb 13 08:42:43] DEBUG[3198]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 404 [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 404 [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #335 [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK10cf5b2f;rport=5060 (71) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as4131d43b (57) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=9t67p2jojg (44) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670175091-eywxgfwja4q1@snom320-0004132496DC (55) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 105 NOTIFY (16) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Content-Length: 0 (17) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: (0) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 105 [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #335 [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '3c2670175091-eywxgfwja4q1@snom320-0004132496DC' of Request 105: Match Not Found [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKBQqIGhfSNbSc4i5iKAr6zvvsx (72) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=VQSWuWhRm (45) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: (29) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: JJqMebZAwokZXBX (24) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 5337 REGISTER (19) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Expires: 60 (11) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Length: 0 (17) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: (0) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKszX7mKtSgdExkU (61) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=VQSWuWhRm (45) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: (29) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: JJqMebZAwokZXBX (24) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 5338 REGISTER (19) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Authorization: Digest username="502", realm="siprealm", nonce="0103508d", uri="sip:pbx.example.net", response="26d5300dbf13c9f91ae86fbac0dd7128", algorithm=MD5 (159) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Expires: 60 (11) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Length: 0 (17) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: (0) [Feb 13 08:42:43] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 13 08:42:43] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502 [Feb 13 08:42:43] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:43] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:43] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 2 (In use) [Feb 13 08:42:43] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:43] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:43] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/502' changed to state '2' (In use) but we don't care because they're not a member of any queue. [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:401@pbx.example.net;user=phone SIP/2.0 (52) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.248:5060;branch=z9hG4bK-tyd5xg1nb754;rport (71) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=quuutqv5di (46) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=as697626cb (55) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670174e20-2wznh9y60whj@snom320-0004132496DC (55) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 41 SUBSCRIBE (18) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Event: dialog (13) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Accept: application/dialog-info+xml (35) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Expires: 60 (11) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Length: 0 (17) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: (0) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:401@pbx.example.net;user=phone SIP/2.0 (52) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.248:5060;branch=z9hG4bK-eldvq5mlqme6;rport (71) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=quuutqv5di (46) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=as697626cb (55) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670174e20-2wznh9y60whj@snom320-0004132496DC (55) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 42 SUBSCRIBE (18) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Event: dialog (13) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Accept: application/dialog-info+xml (35) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Authorization: Digest username="403",realm="siprealm",nonce="778ef4c9",uri="sip:401@pbx.example.net;user=phone",response="ddf22dde5f8403204c51bbbc51f81c65",algorithm=MD5 (169) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Expires: 60 (11) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Length: 0 (17) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: (0) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:15032 handle_request_subscribe: Adding subscription for extension 401 context subscriptions for peer 403 [Feb 13 08:42:44] DEBUG[3198]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 401 [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 401 [Feb 13 08:42:44] DEBUG[3198]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 401 [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 401 [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #341 [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK57153cbd;rport=5060 (71) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as697626cb (57) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=quuutqv5di (44) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c2670174e20-2wznh9y60whj@snom320-0004132496DC (55) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 105 NOTIFY (16) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Content-Length: 0 (17) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: (0) [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 105 [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #341 [Feb 13 08:42:44] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '3c2670174e20-2wznh9y60whj@snom320-0004132496DC' of Request 105: Match Not Found [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-qj25we16d21i;rport (71) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Rámon" ;tag=06c47mdens (55) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: "Rámon" (38) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c26700cc0df-7jgiqsngeaqp@snom360-000413231BC4 (55) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 5 REGISTER (16) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1;q=1.0;+sip.instance="" (133) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: User-Agent: snom360/6.5.15 (26) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Supported: gruu (15) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Allow-Events: dialog (20) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: X-Real-IP: 192.168.161.250 (26) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: WWW-Contact: (40) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: WWW-Contact: (42) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 14: Expires: 600 (12) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 15: Content-Length: 0 (17) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 16: (0) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:4518 sip_alloc: Allocating new SIP dialog for 3c26700cc0df-7jgiqsngeaqp@snom360-000413231BC4 - REGISTER (No RTP) [Feb 13 08:42:45] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-ekrhrr7adw7r;rport (71) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: "Rámon" ;tag=06c47mdens (55) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: "Rámon" (38) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c26700cc0df-7jgiqsngeaqp@snom360-000413231BC4 (55) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 6 REGISTER (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1;q=1.0;+sip.instance="" (133) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: User-Agent: snom360/6.5.15 (26) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Supported: gruu (15) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Allow-Events: dialog (20) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: X-Real-IP: 192.168.161.250 (26) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: WWW-Contact: (40) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: WWW-Contact: (42) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 14: Authorization: Digest username="401",realm="siprealm",nonce="2cf7fd97",uri="sip:pbx.example.net",response="87c227e1e9e868f76b64556efd2fd92a",algorithm=MD5 (154) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 15: Expires: 600 (12) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 16: Content-Length: 0 (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 17: (0) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER -- Saved useragent "snom360/6.5.15" for peer 401 [Feb 13 08:42:46] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/401 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 401 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 401 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/401 - state 1 (Not in use) [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 401 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 401 [Feb 13 08:42:46] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/401' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-wyatwzgyge2r;rport (71) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=aht0fvq0fp (46) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: (31) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c26715b2e63-2fqx6a12okiq@snom360-000413231BC4 (55) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 1 SUBSCRIBE (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Event: message-summary (22) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Accept: application/simple-message-summary (42) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Expires: 60 (11) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Length: 0 (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: (0) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4518 sip_alloc: Allocating new SIP dialog for 3c26715b2e63-2fqx6a12okiq@snom360-000413231BC4 - SUBSCRIBE (No RTP) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-t27nf3u71cw6;rport (71) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=aht0fvq0fp (46) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: (31) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c26715b2e63-2fqx6a12okiq@snom360-000413231BC4 (55) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 2 SUBSCRIBE (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Event: message-summary (22) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Accept: application/simple-message-summary (42) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Authorization: Digest username="401",realm="siprealm",nonce="7adb192e",uri="sip:Voice@pbx.example.net",response="46e6659d24495b728ac57a3715b9f356",algorithm=MD5 (160) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Expires: 60 (11) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Length: 0 (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: (0) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Really destroying SIP dialog '3c26715b2e63-2fqx6a12okiq@snom360-000413231BC4' Method: SUBSCRIBE [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: BYE sip:502@192.168.161.100 SIP/2.0 (35) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-gqfba07bz9b6;rport (71) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=rm7sc5n1th (65) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: "Handset Theo" ;tag=as69752b41 (59) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 79994a780c7a93a1489b392116fe0c34@pbx.example.net (57) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 1 BYE (11) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: User-Agent: snom360/6.5.15 (26) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: RTP-RxStat: Total_Rx_Pkts=261,Rx_Pkts=261,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 (78) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: RTP-TxStat: Total_Tx_Pkts=281,Tx_Pkts=281,Remote_Tx_Pkts=0 (58) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: Content-Length: 0 (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: (0) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:15236 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:1657 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 79994a780c7a93a1489b392116fe0c34@pbx.example.net [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:14788 handle_request_bye: Received bye, issuing owner hangup [Feb 13 08:42:46] DEBUG[3221]: rtp.c:2951 bridge_native_loop: Oooh, got a hangup [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:17590 sip_set_rtp_peer: Sending reinvite on SIP 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' - It's audio soon redirected to IP 192.168.161.100 [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:5880 reqprep: Strict routing enforced for session WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:6430 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:6431 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:6562 add_sdp: -- Done with adding codecs to SDP [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:6607 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:1645 initialize_initreq: Initializing already initialized SIP dialog WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (presumably reinvite) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 0: INVITE sip:502@192.168.161.227 SIP/2.0 (38) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK18c8ea26;rport (66) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as3e31d487 (46) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 3: To: "502 Theo" ;tag=XtDm8c23Z4 (55) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 4: Contact: (34) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 5: Call-ID: WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (50) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 6: CSeq: 103 INVITE (16) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 10: Supported: replaces (19) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 13: Content-Length: 244 (19) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4783 parse_request: Header 14: (0) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: v=0 (3) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: o=root 2414 2416 IN IP4 192.168.161.100 (39) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: s=session (9) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: c=IN IP4 192.168.161.100 (24) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: t=0 0 (5) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: m=audio 17916 RTP/AVP 8 101 (27) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=ptime:20 (10) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #346 [Feb 13 08:42:46] DEBUG[3221]: channel.c:4343 ast_channel_bridge: Returning from native bridge, channels: SIP/502-08ab6e80, SIP/408-08ad5e60 [Feb 13 08:42:46] DEBUG[3221]: channel.c:1789 ast_hangup: Hanging up channel 'SIP/408-08ad5e60' [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:3494 sip_hangup: Hangup call SIP/408-08ad5e60, SIP callid 79994a780c7a93a1489b392116fe0c34@pbx.example.net) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:3503 sip_hangup: update_call_counter(408) - decrement call limit counter on hangup [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:3182 update_call_counter: Updating call counter for outgoing call [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:3233 update_call_counter: Call to peer '408' removed from call limit 30 [Feb 13 08:42:46] DEBUG[3221]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408 [Feb 13 08:42:46] DEBUG[3221]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408-08ad5e60 [Feb 13 08:42:46] DEBUG[3221]: rtp.c:1504 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 13 08:42:46] DEBUG[3221]: app_dial.c:1770 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Macro' -- Executing [408@calldist-16:4] Macro("SIP/502-08ab6e80", "endcall|ANSWER|N|0") in new stack [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:1] GotoIf("SIP/502-08ab6e80", "0?user-08||1") in new stack [Feb 13 08:42:46] DEBUG[3221]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-endcall:2] ExecIf("SIP/502-08ab6e80", "0|Set|ARRAY(ARG1|ARG2|ARG3)=,N,") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: ExecIf [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Goto' -- Executing [s@macro-endcall:3] Goto("SIP/502-08ab6e80", "ANSWER") in new stack -- Goto (macro-endcall,s,4) [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Goto [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:4] GotoIf("SIP/502-08ab6e80", "0?ANSWER-EXIT") in new stack [Feb 13 08:42:46] DEBUG[3221]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:5] GotoIf("SIP/502-08ab6e80", "0?ANSWER-EXIT") in new stack [Feb 13 08:42:46] DEBUG[3221]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:6] GotoIf("SIP/502-08ab6e80", "0?ANSWER-EXIT") in new stack [Feb 13 08:42:46] DEBUG[3221]: pbx.c:6079 pbx_builtin_gotoif: Not taking any branch [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:7] GotoIf("SIP/502-08ab6e80", "0?ANSWER-CALLING:ANSWER-CALLED") in new stack -- Goto (macro-endcall,s,11) [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-endcall:11] NoOp("SIP/502-08ab6e80", ".... Called Party Hungup .... ") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: NoOp [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'GosubIf' -- Executing [s@macro-endcall:12] GosubIf("SIP/502-08ab6e80", "1?ANSWER-CDR") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: GosubIf [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:350 _macro_exec: Incrementing gosub_level [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '2' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/408-08ad5e60' [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 1 (Not in use) [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 Reliably Transmitting (no NAT) to 192.168.161.242:1037: NOTIFY sip:406@192.168.161.242:1037;line=fqekjdfm SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK55073515;rport From: ;tag=as6a985741 To: ;tag=txmy8j3apc Contact: Call-ID: 3c26702882dd-ttiu7ql9fviz CSeq: 105 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 206 terminated --- [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #347 Extension Changed 408[subscriptions] new state Idle for Notify User 406 (queued) [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 1 (Not in use) [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 408 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 102 [Feb 13 08:42:46] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/408' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:46] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/408' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport=5060;branch=z9hG4bK18c8ea26 (66) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as3e31d487 (46) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: "502 Theo" ;tag=XtDm8c23Z4 (55) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (50) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 103 INVITE (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Content-Length: 0 (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: (0) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2208 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #346 - INVITE (got response) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2217 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' Request 103: Found [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:12010 handle_response_invite: SIP response 100 to RE-invite on outgoing call WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net Really destroying SIP dialog '79994a780c7a93a1489b392116fe0c34@pbx.example.net' Method: BYE > Found no rows [SELECT nr,name,usercontext FROM viewextensiondata WHERE devicename = 'SIP/408-08ad5e60' LIMIT 1] [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-endcall:18] ExecIf("SIP/502-08ab6e80", "0|Set|ARRAY(CALLEDEXT|CALLEDNAME)=") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: ExecIf [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '2' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/408-08ad5e60' [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport;branch=z9hG4bK18c8ea26 (61) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=as3e31d487 (46) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: "502 Theo" ;tag=XtDm8c23Z4 (55) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (50) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 103 INVITE (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: Contact: (34) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Accept: application/sdp (23) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 10: Content-Disposition: session (28) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 11: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 12: Content-Type: application/SDP (29) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 13: Content-Length: 258 (19) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 14: (0) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: v=0 (3) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: o=502 409720241 409720243 IN IP4 192.168.161.227 (48) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: s=- (3) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: c=IN IP4 192.168.161.227 (24) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: t=0 0 (5) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: m=audio 10012 RTP/AVP 8 0 101 (29) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=sendrecv (10) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4815 parse_request: Line: a=rtcp:10013 (12) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 103 [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' of Request 103: Match Not Found [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:12010 handle_response_invite: SIP response 200 to RE-invite on outgoing call WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:5397 process_sdp: T38 state changed to 0 on channel SIP/502-08ab6e80 [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:5477 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:5484 process_sdp: We have an owner, now see if we need to change this call [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:3182 update_call_counter: Updating call counter for incoming call [Feb 13 08:42:46] DEBUG[3198]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502 [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:8204 build_route: build_route: Retaining previous route: [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:5880 reqprep: Strict routing enforced for session WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 2 (In use) [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:46] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/502' changed to state '2' (In use) but we don't care because they're not a member of any queue. > Found no rows [SELECT nr,name,usercontext FROM viewextensiondata WHERE devicename = 'SIP/408-08ad5e60' LIMIT 1] [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888560.879936' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888557.065374' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888557.134638' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.745298' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:19] Set("SIP/502-08ab6e80", "RINGTIMECORR=0") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888557.065374' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888557.134638' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888557.134638' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:20] Set("SIP/502-08ab6e80", "STARTTIME=1202888557.134638") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888560.879936' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888557.065374' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888557.134638' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.745298' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '3.745298' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:21] Set("SIP/502-08ab6e80", "RINGINGTIME=3.745298") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '1202888560.879936' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '5.975190' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:22] Set("SIP/502-08ab6e80", "DURATION=5.975190") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'ANSWERED1' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:23] Set("SIP/502-08ab6e80", "DISPOSITION=ANSWERED1") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '502' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:24] Set("SIP/502-08ab6e80", "CALLINGEXT2=502") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'NULL' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:25] Set("SIP/502-08ab6e80", "TRUNKID2=NULL") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/502-08ab6e80' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'SIP/502-08ab6e80' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is '"Handset Theo" <502>' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:26] Set("SIP/502-08ab6e80", "ODBC_CDR()=1202888557,NULL,1202888557.134638,1202888566.856325,'502','408','SIP/502-08ab6e80','SIP/408-08ad5e60','user-01','user-08','ANSWERED1',3.745298,5.975190,'','"Handset Theo" <502>','phone','','16'") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'ResetCDR' -- Executing [s@macro-endcall:27] ResetCDR("SIP/502-08ab6e80", "w") in new stack [Feb 13 08:42:46] DEBUG[3221]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: ResetCDR [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Return' -- Executing [s@macro-endcall:28] Return("SIP/502-08ab6e80", "") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:337 _macro_exec: Executed application: Return [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:360 _macro_exec: Decrementing gosub_level [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'Hangup' -- Executing [s@macro-endcall:13] Hangup("SIP/502-08ab6e80", "") in new stack [Feb 13 08:42:46] DEBUG[3221]: app_macro.c:329 _macro_exec: Spawn extension (macro-endcall,s,13) exited non-zero on 'SIP/502-08ab6e80' in macro 'endcall' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:2443 __ast_pbx_run: Spawn extension (macro-endcall,s,13) exited non-zero on 'SIP/502-08ab6e80' == Spawn extension (macro-endcall, s, 13) exited non-zero on 'SIP/502-08ab6e80' [Feb 13 08:42:46] DEBUG[3221]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/502-08ab6e80' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1696 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1764 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'ExecIf' -- Executing [h@macro-endcall:1] ExecIf("SIP/502-08ab6e80", "0|Goto|s|VOICEMAIL-CDR") in new stack [Feb 13 08:42:46] DEBUG[3221]: pbx.c:1847 pbx_extension_helper: Launching 'NoOp' -- Executing [h@macro-endcall:2] NoOp("SIP/502-08ab6e80", ".... End of call .... 1202888557") in new stack [Feb 13 08:42:46] DEBUG[3221]: channel.c:1789 ast_hangup: Hanging up channel 'SIP/502-08ab6e80' [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:3494 sip_hangup: Hangup call SIP/502-08ab6e80, SIP callid WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net) [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:3503 sip_hangup: update_call_counter(502) - decrement call limit counter on hangup [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:3182 update_call_counter: Updating call counter for incoming call [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:3233 update_call_counter: Call from peer '502' removed from call limit 30 [Feb 13 08:42:46] DEBUG[3221]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502 [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:5880 reqprep: Strict routing enforced for session WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net [Feb 13 08:42:46] DEBUG[3221]: chan_sip.c:2046 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #349 [Feb 13 08:42:46] DEBUG[3221]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502-08ab6e80 [Feb 13 08:42:46] DEBUG[3221]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 1 (Not in use) [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 1 (Not in use) [Feb 13 08:42:46] DEBUG[3180]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 13 08:42:46] DEBUG[3180]: chan_sip.c:15870 sip_devicestate: Checking device state for peer 502 [Feb 13 08:42:46] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/502' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:46] DEBUG[3200]: app_queue.c:595 handle_statechange: Device 'SIP/502' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport=5060;branch=z9hG4bK082268ab (66) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: From: ;tag=as3e31d487 (46) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: To: "502 Theo" ;tag=XtDm8c23Z4 (55) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: Call-ID: WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net (50) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: CSeq: 104 BYE (13) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 8: Content-Length: 0 (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 9: (0) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #349 [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' of Request 104: Match Not Found Really destroying SIP dialog 'WPtYNPQnxFlqAvCea96hryZ.6@pbx.example.net' Method: ACK <--- SIP read from 192.168.161.242:1037 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK55073515;rport=5060 From: ;tag=as6a985741 To: ;tag=txmy8j3apc Call-ID: 3c26702882dd-ttiu7ql9fviz CSeq: 105 NOTIFY Content-Length: 0 <-------------> [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK55073515;rport=5060 (71) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 2: From: ;tag=as6a985741 (57) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 3: To: ;tag=txmy8j3apc (44) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 4: Call-ID: 3c26702882dd-ttiu7ql9fviz (34) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 5: CSeq: 105 NOTIFY (16) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 6: Content-Length: 0 (17) [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:4783 parse_request: Header 7: (0) --- (7 headers 0 lines) --- [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2157 __sip_ack: Acked pending invite 105 [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2165 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #347 [Feb 13 08:42:46] DEBUG[3198]: chan_sip.c:2175 __sip_ack: Stopping retransmission on '3c26702882dd-ttiu7ql9fviz' of Request 105: Match Not Found SIP Response message for INCOMING dialog NOTIFY arrived