-- Executing [408@calldist-16:3] Dial("SIP/502-09bb7680", "Local/408@!SIP&Local/102@!SIP|10|g") in new stack [Feb 6 10:06:29] DEBUG[10403]: rtp.c:1579 ast_rtp_make_compatible: Channel 'Local/408@!SIP-dd13,1' has no RTP, not doing anything [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALDEVICES. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDDEVICES. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable COUNT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDDEVICESX. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable EXTENX. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DEVICEX. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable TOTALCALLS. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable RINGING. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable START. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDEXTSTATES. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALSTATUSORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CDL. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLTIME. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONTEXTDEST. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable IGNORECALENDAR. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable RINGTIME. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable EXTTYPE. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDDEV. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONNGROUPORIG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLID. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDNAMEORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDEXTORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGCHANNEL. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGNAME. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGEXT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDNAME. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDEXT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable ABBRRESULT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLORIGINORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLORIGIN. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONTEXTORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable RINGTIMECORR. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable DIALEDEXTEN. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable DIALEDCONTEXT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called 408@!SIP [Feb 6 10:06:29] DEBUG[10403]: rtp.c:1579 ast_rtp_make_compatible: Channel 'Local/102@!SIP-bc76,1' has no RTP, not doing anything [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable MACRO_DEPTH. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALDEVICES. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDDEVICES. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable COUNT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDDEVICESX. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable EXTENX. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DEVICEX. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable TOTALCALLS. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable RINGING. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable START. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDEXTSTATES. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALSTATUSORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CDL. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLTIME. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONTEXTDEST. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable IGNORECALENDAR. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable RINGTIME. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable EXTTYPE. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDDEV. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONNGROUPORIG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLID. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDNAMEORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDEXTORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGCHANNEL. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGNAME. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGEXT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDNAME. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDEXT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable ABBRRESULT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLORIGINORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLORIGIN. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONTEXTORG. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable RINGTIMECORR. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable DIALEDEXTEN. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable DIALEDCONTEXT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPCALLID. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPUSERAGENT. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPDOMAIN. [Feb 6 10:06:29] DEBUG[10403]: channel.c:3579 ast_channel_inherit_variables: Not copying variable SIPURI. -- Called 102@!SIP [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:1] Set("Local/408@!SIP-dd13,2", "CALLEDPEER=408") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:2] Set("Local/408@!SIP-dd13,2", "_CALLCHANNEL=SIP/408") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:3] Set("Local/408@!SIP-dd13,2", "GROUP(RING_EXT)=408") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP:4] Set("Local/408@!SIP-dd13,2", "_CONNGROUPDEST=") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [408@!SIP:5] GotoIf("Local/408@!SIP-dd13,2", "1?CCG") in new stack -- Goto (!SIP,408,7) [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'MacroIf' -- Executing [408@!SIP:7] MacroIf("Local/408@!SIP-dd13,2", "0?conngroup|||0|0|1") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Gosub' -- Executing [408@!SIP:8] Gosub("Local/408@!SIP-dd13,2", "!SIP-sring|408|1") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'snom360/6.5.15' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [408@!SIP-sring:1] Set("Local/408@!SIP-dd13,2", "ARRAY(PEERAGENT|ORG)=snom360/6.5.15,INT") in new stack [Feb 6 10:06:29] DEBUG[10404]: func_strings.c:197 array: array (PEERAGENT|ORG=snom360/6.5.15,INT) [Feb 6 10:06:29] DEBUG[10404]: func_strings.c:210 array: array set value (PEERAGENT=snom360/6.5.15) [Feb 6 10:06:29] DEBUG[10404]: func_strings.c:210 array: array set value (ORG=INT) [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '5' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [408@!SIP-sring:2] GotoIf("Local/408@!SIP-dd13,2", "5?NEXT") in new stack -- Goto (!SIP-sring,408,6) [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [408@!SIP-sring:6] ExecIf("Local/408@!SIP-dd13,2", "0|Set|ORG=EXT") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [408@!SIP-sring:7] GotoIf("Local/408@!SIP-dd13,2", "1?DEFAULT") in new stack -- Goto (!SIP-sring,408,11) [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [408@!SIP-sring:11] ExecIf("Local/408@!SIP-dd13,2", "0|Return|") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [408@!SIP-sring:12] ExecIf("Local/408@!SIP-dd13,2", "0|Return") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'SIPAddHeader' -- Executing [408@!SIP-sring:13] SIPAddHeader("Local/408@!SIP-dd13,2", "Alert-Info: ") in new stack [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:17655 sip_addheader: SIP Header added "Alert-Info: " as _SIPADDHEADER01 [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Return' -- Executing [408@!SIP-sring:14] Return("Local/408@!SIP-dd13,2", "") in new stack [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '11' [Feb 6 10:06:29] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Dial' -- Executing [408@!SIP:9] Dial("Local/408@!SIP-dd13,2", "SIP/408|11|gM(!CONNECTEXT^408)") in new stack [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:15890 sip_request_call: Asked to create a SIP channel with formats: 0x8 (alaw) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for (No Call-ID) - INVITE (With RTP) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:2733 do_setnat: Setting NAT on RTP to Off [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:3993 sip_new: *** Our native formats are 0x8 (alaw) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:3994 sip_new: *** Joint capabilities are 0x0 (nothing) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:3995 sip_new: *** Our capabilities are 0x8 (alaw) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:3996 sip_new: *** AST_CODEC_CHOOSE formats are 0x8 (alaw) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:3998 sip_new: *** Our preferred formats from the incoming channel are 0x8 (alaw) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4019 sip_new: This channel will not be able to handle video. [Feb 6 10:06:29] DEBUG[10404]: rtp.c:1586 ast_rtp_make_compatible: Channel 'Local/408@!SIP-dd13,2' has no RTP, not doing anything [Feb 6 10:06:29] DEBUG[10404]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable SIPADDHEADER01. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3579 ast_channel_inherit_variables: Not copying variable ORG. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3579 ast_channel_inherit_variables: Not copying variable PEERAGENT. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CONNGROUPDEST. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3566 ast_channel_inherit_variables: Copying soft-transferable variable CALLCHANNEL. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3579 ast_channel_inherit_variables: Not copying variable CALLEDPEER. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3579 ast_channel_inherit_variables: Not copying variable DIALEDPEERNUMBER. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDDEVICES. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CDL. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLTIME. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONTEXTDEST. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable IGNORECALENDAR. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable RINGTIME. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable EXTTYPE. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDDEV. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONNGROUPORIG. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLID. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGCHANNEL. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGNAME. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLINGEXT. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDNAME. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLEDEXT. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable ABBRRESULT. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLORIGINORG. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CALLORIGIN. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable CONTEXTORG. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable RINGTIMECORR. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable DIALEDEXTEN. [Feb 6 10:06:29] DEBUG[10404]: channel.c:3574 ast_channel_inherit_variables: Copying hard-transferable variable DIALEDCONTEXT. [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:2991 sip_call: Outgoing Call for 408 [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:3250 update_call_counter: Call to peer '408' is 1 out of 30 [Feb 6 10:06:29] DEBUG[10404]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408 [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:3006 sip_call: Our T38 capability (3856), joint T38 capability (3856) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:7067 transmit_invite: Adding SIP Header "Alert-Info" with content :: [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:6421 add_sdp: ** Our capability: 0x8 (alaw) Video flag: False [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:6422 add_sdp: ** Our prefcodec: 0x8 (alaw) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:6553 add_sdp: -- Done with adding codecs to SDP [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:6598 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 0: INVITE sip:408@192.168.161.233:5060;line=ujb4rgep SIP/2.0 (57) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK40642cc6;rport (66) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as23febd86 (61) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 3: To: (48) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 4: Contact: (34) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 5: Call-ID: 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (57) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 9: Remote-Party-ID: "Handset Theo" ;privacy=off;screen=no (79) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 10: Date: Wed, 06 Feb 2008 09:06:29 GMT (35) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 11: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 12: Supported: replaces (19) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 13: Alert-Info: (43) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 14: Content-Type: application/sdp (29) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 15: Content-Length: 246 (19) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4774 parse_request: Header 16: (0) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: v=0 (3) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: o=root 23079 23079 IN IP4 192.168.161.100 (41) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: s=session (9) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.161.100 (24) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: t=0 0 (5) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: m=audio 14728 RTP/AVP 8 101 (27) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: a=ptime:20 (10) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:29] DEBUG[10404]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3702 -- Called 408 [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:1] Set("Local/102@!SIP-bc76,2", "CALLEDPEER=102") in new stack [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:2] Set("Local/102@!SIP-bc76,2", "_CALLCHANNEL=SIP/102") in new stack [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:3] Set("Local/102@!SIP-bc76,2", "GROUP(RING_EXT)=408") in new stack [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP:4] Set("Local/102@!SIP-bc76,2", "_CONNGROUPDEST=") in new stack [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [102@!SIP:5] GotoIf("Local/102@!SIP-bc76,2", "1?CCG") in new stack -- Goto (!SIP,102,7) [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'MacroIf' -- Executing [102@!SIP:7] MacroIf("Local/102@!SIP-bc76,2", "0?conngroup|||0|0|1") in new stack [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Gosub' -- Executing [102@!SIP:8] Gosub("Local/102@!SIP-bc76,2", "!SIP-sring|102|1") in new stack [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'acMP114/v.5.20A.018.008' [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [102@!SIP-sring:1] Set("Local/102@!SIP-bc76,2", "ARRAY(PEERAGENT|ORG)=acMP114/v.5.20A.018.008,INT") in new stack [Feb 6 10:06:29] DEBUG[10405]: func_strings.c:197 array: array (PEERAGENT|ORG=acMP114/v.5.20A.018.008,INT) [Feb 6 10:06:29] DEBUG[10405]: func_strings.c:210 array: array set value (PEERAGENT=acMP114/v.5.20A.018.008) [Feb 6 10:06:29] DEBUG[10405]: func_strings.c:210 array: array set value (ORG=INT) [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [102@!SIP-sring:2] GotoIf("Local/102@!SIP-bc76,2", "0?NEXT") in new stack [Feb 6 10:06:29] DEBUG[10405]: pbx.c:6038 pbx_builtin_gotoif: Not taking any branch [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '4' [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [102@!SIP-sring:3] GotoIf("Local/102@!SIP-bc76,2", "4?NEXT") in new stack -- Goto (!SIP-sring,102,6) [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:29] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 6 (Ringing) [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 Reliably Transmitting (no NAT) to 192.168.161.243:5060: NOTIFY sip:406@192.168.161.243:5060;line=u8pkfgw2 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK06696d41;rport From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Contact: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 145 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 224 early --- [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3706 Extension Changed 408 new state Ringing for Notify User 406 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 6 (Ringing) [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:29] DEBUG[10235]: 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 6 10:06:29] DEBUG[10235]: 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 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfe5357;rport (66) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as18f019c4 (61) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=1c1188360039 (46) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 6feda9f5702731b6618aa78559f36e99@pbx.example.net (57) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Supported: em,timer,replaces,path,early-session,resource-priority (65) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Server: acMP114/v.5.20A.018.008 (31) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Content-Length: 0 (17) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: (0) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:2203 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #3704 - INVITE (got response) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6feda9f5702731b6618aa78559f36e99@pbx.example.net' Request 102: Found [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:11980 handle_response_invite: SIP response 100 to standard invite [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfe5357;rport (66) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as18f019c4 (61) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=1c1188360039 (46) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 6feda9f5702731b6618aa78559f36e99@pbx.example.net (57) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Contact: (34) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Supported: em,timer,replaces,path,early-session,resource-priority (65) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Server: acMP114/v.5.20A.018.008 (31) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Content-Length: 0 (17) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: (0) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '6feda9f5702731b6618aa78559f36e99@pbx.example.net' Request 102: Found [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:11980 handle_response_invite: SIP response 180 to standard invite [Feb 6 10:06:29] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102-09bc3a08 -- SIP/102-09bc3a08 is ringing [Feb 6 10:06:29] DEBUG[10405]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/102@!SIP-bc76,2' has no RTP, not doing anything [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 6 (Ringing) [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 -- Local/102@!SIP-bc76,1 is ringing [Feb 6 10:06:29] DEBUG[10235]: 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. pbx*CLI> <--- SIP read from 192.168.161.243:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK06696d41;rport=5060 From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 145 NOTIFY Content-Length: 0 <-------------> [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK06696d41;rport=5060 (71) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as6a83460e (57) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=dbag2a82z5 (44) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 (55) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 145 NOTIFY (16) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) --- (7 headers 0 lines) --- [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3706 [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '3c26701788b8-rc29mso7ycw8@snom320-0004132429F1' of Request 145: Match Not Found SIP Response message for INCOMING dialog NOTIFY arrived [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK40642cc6;rport=5060 (71) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as23febd86 (61) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=t5hkiya27s (63) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (57) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Content-Length: 0 (17) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: (0) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:2203 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #3702 - INVITE (got response) [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net' Request 102: Found [Feb 6 10:06:29] DEBUG[10233]: chan_sip.c:11980 handle_response_invite: SIP response 180 to standard invite [Feb 6 10:06:29] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408-09bd7b78 -- SIP/408-09bd7b78 is ringing [Feb 6 10:06:29] DEBUG[10404]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-dd13,2' has no RTP, not doing anything [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 6 (Ringing) [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:29] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:29] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 -- Local/408@!SIP-dd13,1 is ringing [Feb 6 10:06:29] DEBUG[10235]: 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 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK40642cc6;rport=5060 (71) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as23febd86 (61) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=t5hkiya27s (63) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (57) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net' Request 102: Found [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:11980 handle_response_invite: SIP response 180 to standard invite -- SIP/408-09bd7b78 is ringing [Feb 6 10:06:30] DEBUG[10404]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-dd13,2' has no RTP, not doing anything [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-ozzcz29dsemi;rport (71) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Rámon" ;tag=bp14rclc9v (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: "Rámon" (38) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26700c2981-gymuxqqxcs4v@snom360-000413231BC4 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 3404 REGISTER (19) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1;q=1.0;+sip.instance="" (133) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: User-Agent: snom360/6.5.15 (26) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Supported: gruu (15) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Allow-Events: dialog (20) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: X-Real-IP: 192.168.161.250 (26) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: WWW-Contact: (40) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: WWW-Contact: (42) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: Expires: 600 (12) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 15: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 16: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 3c26700c2981-gymuxqqxcs4v@snom360-000413231BC4 - REGISTER (No RTP) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-1qra3qynaumw;rport (71) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Rámon" ;tag=bp14rclc9v (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: "Rámon" (38) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26700c2981-gymuxqqxcs4v@snom360-000413231BC4 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 3405 REGISTER (19) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1;q=1.0;+sip.instance="" (133) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: User-Agent: snom360/6.5.15 (26) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Supported: gruu (15) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Allow-Events: dialog (20) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: X-Real-IP: 192.168.161.250 (26) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: WWW-Contact: (40) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: WWW-Contact: (42) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: Authorization: Digest username="401",realm="siprealm",nonce="027a86fc",uri="sip:pbx.example.net",response="7674c052f6a2b1a4a4220b689dce7eda",algorithm=MD5 (154) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 15: Expires: 600 (12) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 16: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 17: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 6 10:06:30] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/401 [Feb 6 10:06:30] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 401 [Feb 6 10:06:30] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 401 [Feb 6 10:06:30] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/401 - state 1 (Not in use) [Feb 6 10:06:30] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 401 [Feb 6 10:06:30] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 401 [Feb 6 10:06:30] DEBUG[10235]: 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 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-80blx57r391u;rport (71) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=zv0tif1cg5 (46) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: (31) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c2e39949c40-bpqup0og5oo2@snom360-000413231BC4 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 1 SUBSCRIBE (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Event: message-summary (22) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Accept: application/simple-message-summary (42) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Expires: 60 (11) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 3c2e39949c40-bpqup0og5oo2@snom360-000413231BC4 - SUBSCRIBE (No RTP) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.250:5060;branch=z9hG4bK-o5lbfzxbmxz7;rport (71) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=zv0tif1cg5 (46) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: (31) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c2e39949c40-bpqup0og5oo2@snom360-000413231BC4 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 2 SUBSCRIBE (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Event: message-summary (22) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Accept: application/simple-message-summary (42) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Authorization: Digest username="401",realm="siprealm",nonce="19228145",uri="sip:Voice@pbx.example.net",response="d96576523a3e9d1f4998eaa841d9dbc9",algorithm=MD5 (160) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Expires: 60 (11) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Really destroying SIP dialog '3c2e39949c40-bpqup0og5oo2@snom360-000413231BC4' Method: SUBSCRIBE [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKwjL0o6LzkI5idw4AKpQUg3B (70) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=pXt2KRUVx (45) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: (31) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: EF8z7TqD1Ahvwd5LtTi9Ws@pbx.example.net (47) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 25330 SUBSCRIBE (21) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: (34) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Accept: application/simple-message-summary (42) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Allow-Events: dialog,message-summary (36) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Event: message-summary (22) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Expires: 3600 (13) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: Supported: replaces (19) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 15: Content-Type: text/plain (24) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 16: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 17: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for EF8z7TqD1Ahvwd5LtTi9Ws@pbx.example.net - SUBSCRIBE (No RTP) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKVzqJpTydQe0Xad8o8y5m4ds (70) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=pXt2KRUVx (45) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: (31) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: EF8z7TqD1Ahvwd5LtTi9Ws@pbx.example.net (47) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 25331 SUBSCRIBE (21) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: (34) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow-Events: dialog,message-summary (36) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Authorization: Digest username="503", realm="siprealm", nonce="0b8739b9", uri="sip:Voice@pbx.example.net", response="cc3bf7c4e9c3ed40d336e9b97e202993", algorithm=MD5 (165) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Event: message-summary (22) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Expires: 3600 (13) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Really destroying SIP dialog 'EF8z7TqD1Ahvwd5LtTi9Ws@pbx.example.net' Method: SUBSCRIBE [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:404@pbx.example.net;user=phone SIP/2.0 (52) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.249:5060;branch=z9hG4bK-e5rker3tkgh5;rport (71) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=esk05h7ki2 (46) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=as475fea11 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c30fbca35b6-uwqvkb3ioray@snom360-000413231BA0 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 4313 SUBSCRIBE (20) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Event: dialog (13) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Accept: application/dialog-info+xml (35) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Expires: 60 (11) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:404@pbx.example.net;user=phone SIP/2.0 (52) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.249:5060;branch=z9hG4bK-vtlcadooc7xt;rport (71) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=esk05h7ki2 (46) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=as475fea11 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c30fbca35b6-uwqvkb3ioray@snom360-000413231BA0 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 4314 SUBSCRIBE (20) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Event: dialog (13) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Accept: application/dialog-info+xml (35) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Authorization: Digest username="402",realm="siprealm",nonce="51f1c09a",uri="sip:404@pbx.example.net;user=phone",response="e4297d7b2bd78f6f27f2e75f31bb43fe",algorithm=MD5 (169) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Expires: 60 (11) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:14983 handle_request_subscribe: Adding subscription for extension 404 context subscriptions for peer 402 [Feb 6 10:06:30] DEBUG[10233]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 404 [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 404 [Feb 6 10:06:30] DEBUG[10233]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 404 [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 404 [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3714 [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bK2es6eE0VZb0FJRPON4E (66) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=JeujrUb89XupU (49) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: (31) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: brrfoymOAYbBQSkgxAR@pbx.example.net (44) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 15359 SUBSCRIBE (21) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: (34) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Accept: application/simple-message-summary (42) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Allow-Events: dialog,message-summary (36) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Event: message-summary (22) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Expires: 3600 (13) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: Supported: replaces (19) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 15: Content-Type: text/plain (24) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 16: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 17: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for brrfoymOAYbBQSkgxAR@pbx.example.net - SUBSCRIBE (No RTP) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKEE0lU7vbDJCufdUHMLOJeDaWJcJyvjZ (78) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=JeujrUb89XupU (49) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: (31) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: brrfoymOAYbBQSkgxAR@pbx.example.net (44) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 15360 SUBSCRIBE (21) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: (34) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow-Events: dialog,message-summary (36) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Authorization: Digest username="501", realm="siprealm", nonce="58572720", uri="sip:Voice@pbx.example.net", response="e0c6fa5b0242dea22726485bee790983", algorithm=MD5 (165) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Event: message-summary (22) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Expires: 3600 (13) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Really destroying SIP dialog 'brrfoymOAYbBQSkgxAR@pbx.example.net' Method: SUBSCRIBE [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK2f51e63e;rport=5060 (71) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as475fea11 (57) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=esk05h7ki2 (44) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c30fbca35b6-uwqvkb3ioray@snom360-000413231BA0 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 136 NOTIFY (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3714 [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '3c30fbca35b6-uwqvkb3ioray@snom360-000413231BA0' of Request 136: Match Not Found [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: REGISTER sip:pbx.example.net:5060;transport=UDP SIP/2.0 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: From: ;tag=eea1a8c0-13c4-dfe22-36a8854e-5c51 (69) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: To: (34) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: Call-ID: eea1a8c0-13c4-dfe22-36a8854c-7edb (42) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: CSeq: 2765 REGISTER (19) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.161.238:5060;rport;branch=z9hG4bK-f437b-3b9f4d56-663b (78) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Supported: replaces,100rel,timer (32) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: User-Agent: Swissvoice IP10 SP v1.0.1 (Build 4) 3.0.5.1 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Contact: (39) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Expires: 120 (12) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Authorization: Digest username="405", realm="siprealm", nonce="2df44f37", uri="sip:pbx.example.net:5060;transport=UDP", response="9712aac2d5f266f446649d0562fa4143", algorithm=MD5 (178) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for eea1a8c0-13c4-dfe22-36a8854c-7edb - REGISTER (No RTP) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: REGISTER sip:pbx.example.net:5060;transport=UDP SIP/2.0 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: From: ;tag=eea1a8c0-13c4-dfe22-36a8854e-5c51 (69) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: To: (34) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: Call-ID: eea1a8c0-13c4-dfe22-36a8854c-7edb (42) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: CSeq: 2766 REGISTER (19) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Via: SIP/2.0/UDP 192.168.161.238:5060;rport;branch=z9hG4bK-f437b-3b9f4dc4-2b1 (77) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Supported: replaces,100rel,timer (32) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: User-Agent: Swissvoice IP10 SP v1.0.1 (Build 4) 3.0.5.1 (55) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Contact: (39) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Expires: 120 (12) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Authorization: Digest username="405", realm="siprealm", nonce="4e369ce4", uri="sip:pbx.example.net:5060;transport=UDP", response="bc93ae472727576af4fd191ec8ddb6c1", algorithm=MD5 (178) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Content-Length: 0 (17) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: (0) [Feb 6 10:06:30] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 6 10:06:30] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/405 [Feb 6 10:06:30] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 405 [Feb 6 10:06:30] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 405 [Feb 6 10:06:30] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/405 - state 1 (Not in use) [Feb 6 10:06:30] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 405 [Feb 6 10:06:30] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 405 [Feb 6 10:06:30] DEBUG[10235]: app_queue.c:595 handle_statechange: Device 'SIP/405' changed to state '1' (Not in use) but we don't care because they're not a member of any queue. [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKfqAe3vaCd1XTT (60) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=XpOB9qjjU6VB4 (49) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: (31) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: SxwHyBHmZYrh.SGQZaJ737eCqI6WK5R@pbx.example.net (56) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 48019 SUBSCRIBE (21) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: (34) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Accept: application/simple-message-summary (42) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Allow-Events: dialog,message-summary (36) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Event: message-summary (22) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Expires: 3600 (13) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: Supported: replaces (19) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 15: Content-Type: text/plain (24) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 16: Content-Length: 0 (17) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 17: (0) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for SxwHyBHmZYrh.SGQZaJ737eCqI6WK5R@pbx.example.net - SUBSCRIBE (No RTP) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SUBSCRIBE sip:Voice@pbx.example.net SIP/2.0 (43) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bKdGwD253oCp7YhfuePmgiH0IF (71) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=XpOB9qjjU6VB4 (49) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: (31) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: SxwHyBHmZYrh.SGQZaJ737eCqI6WK5R@pbx.example.net (56) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 48020 SUBSCRIBE (21) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: (34) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow-Events: dialog,message-summary (36) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Authorization: Digest username="502", realm="siprealm", nonce="65da46fb", uri="sip:Voice@pbx.example.net", response="6ad861ce9b311ef5a2326a0baaea63e1", algorithm=MD5 (165) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Event: message-summary (22) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Expires: 3600 (13) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: Content-Length: 0 (17) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: (0) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received SUBSCRIBE (10) - Command in SIP SUBSCRIBE Really destroying SIP dialog 'SxwHyBHmZYrh.SGQZaJ737eCqI6WK5R@pbx.example.net' Method: SUBSCRIBE [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 180 Ringing (19) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK40642cc6;rport=5060 (71) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as23febd86 (61) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=t5hkiya27s (63) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (57) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow-Events: talk, hold, refer (31) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Content-Length: 0 (17) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: (0) [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on '73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net' Request 102: Found [Feb 6 10:06:31] DEBUG[10233]: chan_sip.c:11980 handle_response_invite: SIP response 180 to standard invite -- SIP/408-09bd7b78 is ringing [Feb 6 10:06:31] DEBUG[10404]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-dd13,2' has no RTP, not doing anything [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK40642cc6;rport=5060 (71) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as23febd86 (61) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=t5hkiya27s (63) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (57) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: User-Agent: snom360/6.5.15 (26) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow-Events: talk, hold, refer (31) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Supported: timer, 100rel, replaces, callerid (44) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Content-Type: application/sdp (29) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Content-Length: 226 (19) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: (0) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: v=0 (3) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: o=root 1068170766 1068170767 IN IP4 192.168.161.233 (51) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: s=call (6) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.161.233 (24) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: t=0 0 (5) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: m=audio 15798 RTP/AVP 8 101 (27) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=ptime:20 (10) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2152 __sip_ack: Acked pending invite 102 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net' of Request 102: Match Not Found [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:11980 handle_response_invite: SIP response 200 to standard invite [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel SIP/408-09bd7b78 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:5475 process_sdp: We have an owner, now see if we need to change this call [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call [Feb 6 10:06:32] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:8241 build_route: build_route: Contact hop: ;flow-id=1 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:5871 reqprep: Strict routing enforced for session 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 2 (In use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 Reliably Transmitting (no NAT) to 192.168.161.243:5060: NOTIFY sip:406@192.168.161.243:5060;line=u8pkfgw2 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Contact: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 146 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 224 early --- [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3720 Extension Changed 408 new state InUse&Ringing for Notify User 406 [Feb 6 10:06:32] DEBUG[10404]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408-09bd7b78 -- SIP/408-09bd7b78 answered Local/408@!SIP-dd13,2 [Feb 6 10:06:32] DEBUG[10404]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-dd13,2' has no RTP, not doing anything [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-!CONNECTEXT:1] GotoIf("SIP/408-09bd7b78", "0?END") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:6038 pbx_builtin_gotoif: Not taking any branch [Feb 6 10:06:32] DEBUG[10404]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '2' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'SIP/408' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-!CONNECTEXT:2] GotoIf("SIP/408-09bd7b78", "1?SKIP") in new stack -- Goto (macro-!CONNECTEXT,s,5) [Feb 6 10:06:32] DEBUG[10404]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-!CONNECTEXT:5] Set("SIP/408-09bd7b78", "GROUP(DEST_EXT)=408") in new stack [Feb 6 10:06:32] DEBUG[10404]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '408' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-!CONNECTEXT:6] Set("SIP/408-09bd7b78", "CONNGROUPDEST=") in new stack [Feb 6 10:06:32] DEBUG[10404]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-!CONNECTEXT:7] GotoIf("SIP/408-09bd7b78", "1?SETLAST") in new stack -- Goto (macro-!CONNECTEXT,s,9) [Feb 6 10:06:32] DEBUG[10404]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-!CONNECTEXT:9] GotoIf("SIP/408-09bd7b78", "1?END") in new stack -- Goto (macro-!CONNECTEXT,s,11) [Feb 6 10:06:32] DEBUG[10404]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-!CONNECTEXT:11] NoOp("SIP/408-09bd7b78", "Call 1202288789.19 on channel SIP/408-09bd7b78 to SIP/408 was answered.") in new stack [Feb 6 10:06:32] DEBUG[10404]: app_macro.c:337 _macro_exec: Executed application: NoOp [Feb 6 10:06:32] DEBUG[10404]: app_dial.c:1609 dial_exec_full: Macro exited with status 0 [Feb 6 10:06:32] DEBUG[10404]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/408@!SIP-dd13,2 [Feb 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 2 (In use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 408@!SIP [Feb 6 10:06:32] DEBUG[10213]: chan_local.c:145 local_devicestate: Checking if extension 408@!SIP exists (devicestate) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for Local/408@!SIP - state 2 (In use) -- Local/408@!SIP-dd13,1 stopped sounds [Feb 6 10:06:32] DEBUG[10403]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/408@!SIP-dd13,1 -- Local/408@!SIP-dd13,1 answered SIP/502-09bb7680 [Feb 6 10:06:32] DEBUG[10403]: rtp.c:1504 ast_rtp_early_bridge: Channel 'Local/408@!SIP-dd13,1' has no RTP, not doing anything [Feb 6 10:06:32] DEBUG[10403]: channel.c:1789 ast_hangup: Hanging up channel 'Local/102@!SIP-bc76,1' [Feb 6 10:06:32] DEBUG[10403]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/102@!SIP-bc76,1 [Feb 6 10:06:32] DEBUG[10403]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 6 10:06:32] DEBUG[10403]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502-09bb7680 [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:3647 sip_answer: SIP answering channel: SIP/502-09bb7680 [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6657 transmit_response_with_sdp: Setting framing from config on incoming call [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6421 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6422 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6553 add_sdp: -- Done with adding codecs to SDP [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6598 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3721 [Feb 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 408@!SIP [Feb 6 10:06:32] DEBUG[10213]: chan_local.c:145 local_devicestate: Checking if extension 408@!SIP exists (devicestate) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for Local/408@!SIP - state 2 (In use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 102@!SIP [Feb 6 10:06:32] DEBUG[10213]: chan_local.c:145 local_devicestate: Checking if extension 102@!SIP exists (devicestate) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for Local/102@!SIP - state 2 (In use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 2 (In use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:32] DEBUG[10405]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/102@!SIP-bc76,2' has no RTP, not doing anything [Feb 6 10:06:32] DEBUG[10405]: channel.c:1789 ast_hangup: Hanging up channel 'SIP/102-09bc3a08' [Feb 6 10:06:32] DEBUG[10405]: chan_sip.c:3485 sip_hangup: Hangup call SIP/102-09bc3a08, SIP callid 6feda9f5702731b6618aa78559f36e99@pbx.example.net) [Feb 6 10:06:32] DEBUG[10405]: chan_sip.c:3494 sip_hangup: update_call_counter(102) - decrement call limit counter on hangup [Feb 6 10:06:32] DEBUG[10405]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call [Feb 6 10:06:32] DEBUG[10405]: chan_sip.c:3224 update_call_counter: Call to peer '102' removed from call limit 30 [Feb 6 10:06:32] DEBUG[10405]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102 [Feb 6 10:06:32] DEBUG[10405]: chan_sip.c:3508 sip_hangup: Hanging up channel in state Ringing (not UP) [Feb 6 10:06:32] DEBUG[10405]: chan_sip.c:2152 __sip_ack: Acked pending invite 102 [Feb 6 10:06:32] DEBUG[10405]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '6feda9f5702731b6618aa78559f36e99@pbx.example.net' of Request 102: Match Not Found [Feb 6 10:06:32] DEBUG[10405]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3723 [Feb 6 10:06:32] DEBUG[10405]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102-09bc3a08 [Feb 6 10:06:32] DEBUG[10405]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 6 10:06:32] DEBUG[10405]: app_dial.c:1770 dial_exec_full: Exiting with DIALSTATUS=CANCEL. [Feb 6 10:06:32] DEBUG[10405]: pbx.c:2431 __ast_pbx_run: Spawn extension (!SIP,102,9) exited non-zero on 'Local/102@!SIP-bc76,2' == Spawn extension (!SIP, 102, 9) exited non-zero on 'Local/102@!SIP-bc76,2' [Feb 6 10:06:32] DEBUG[10405]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'Local/102@!SIP-bc76,2' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [h@!SIP:1] ExecIf("Local/102@!SIP-bc76,2", "0|Hangup") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'GosubIf' -- Executing [h@!SIP:2] GosubIf("Local/102@!SIP-bc76,2", "1?s|CDR") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.224503' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.224503' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.168447' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:2] Set("Local/102@!SIP-bc76,2", "RINGINGTIME=3.168447") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '502' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:3] Set("Local/102@!SIP-bc76,2", "CALLINGEXT2=502") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'NULL' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:4] Set("Local/102@!SIP-bc76,2", "TRUNKID2=NULL") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Return' -- Executing [s@!SIP:5] Return("Local/102@!SIP-bc76,2", "") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@!SIP:3] GotoIf("Local/102@!SIP-bc76,2", "1?!SIP-evaluate|s|CANCEL") in new stack -- Goto (!SIP-evaluate,s,6) [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@!SIP-evaluate:6] GotoIf("Local/102@!SIP-bc76,2", "0?NOANSWER") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:6038 pbx_builtin_gotoif: Not taking any branch [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@!SIP-evaluate:7] GotoIf("Local/102@!SIP-bc76,2", "0?PICKUPALT") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:6038 pbx_builtin_gotoif: Not taking any branch [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'NoOp' -- Executing [s@!SIP-evaluate:8] NoOp("Local/102@!SIP-bc76,2", ".... Call 1202288789 on channel Local/102@!SIP-bc76,2 to SIP/102 Cancelled by the Calling Party ....") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288789.537414' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'SIP/102-09bc3a08' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'SIP/102-09bc3a08' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '"Handset Theo" <502>' [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@!SIP-evaluate:9] ExecIf("Local/102@!SIP-bc76,2", "1|Set|ODBC_CDR()=1202288789,NULL,1202288789.537414,1202288792.815931,'502','408','SIP/502-09bb7680','SIP/102-09bc3a08','user-01','user-08','CANCELLED',3.168447,0,'','"Handset Theo" <502>','phone','','16'") in new stack [Feb 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 Reliably Transmitting (no NAT) to 192.168.161.243:5060: NOTIFY sip:406@192.168.161.243:5060;line=u8pkfgw2 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK14d4e654;rport From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Contact: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 147 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 206 confirmed --- [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3725 Extension Changed 408 new state InUse for Notify User 406 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: ACK sip:408@192.168.161.100 SIP/2.0 (35) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.227;branch=z9hG4bK.UhkHvh9gypm (59) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: "502 Theo" ;tag=Det3djlMWgg3 (59) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: ;tag=as79e2d181 (44) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: do6S475OGBk9tB5Jx4gpt@pbx.example.net (46) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 6215 ACK (14) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Proxy-Authorization: Digest username="502", realm="siprealm", nonce="0d3e289a", uri="sip:408@192.168.161.100", response="46a20ac5ed0be1af1fbd26ab7c417ce2", algorithm=MD5 (169) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Content-Length: 0 (17) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: (0) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received ACK (6) - Command in SIP ACK [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3721 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' of Response 6215: Match Not Found [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 487 Request Terminated (30) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfe5357;rport (66) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as18f019c4 (61) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=1c1188360039 (46) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 6feda9f5702731b6618aa78559f36e99@pbx.example.net (57) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Supported: em,timer,replaces,path,early-session,resource-priority (65) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Server: acMP114/v.5.20A.018.008 (31) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Reason: SIP ;cause=487 ;text="487 Request Terminated" (53) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Content-Length: 0 (17) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: (0) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '6feda9f5702731b6618aa78559f36e99@pbx.example.net' of Request 102: Match Found [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:11980 handle_response_invite: SIP response 487 to standard invite [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:3224 update_call_counter: Call to peer '102' removed from call limit 30 [Feb 6 10:06:32] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/102 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:1652 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 6feda9f5702731b6618aa78559f36e99@pbx.example.net [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/102 - state 1 (Not in use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK3bfe5357;rport (66) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as18f019c4 (61) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=1c1188360039 (46) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 6feda9f5702731b6618aa78559f36e99@pbx.example.net (57) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 CANCEL (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Contact: (34) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Supported: em,timer,replaces,path,early-session,resource-priority (65) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow: REGISTER,OPTIONS,INVITE,ACK,CANCEL,BYE,NOTIFY,PRACK,REFER,INFO,SUBSCRIBE,UPDATE (86) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Server: acMP114/v.5.20A.018.008 (31) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Content-Length: 0 (17) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: (0) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3723 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '6feda9f5702731b6618aa78559f36e99@pbx.example.net' of Request 102: Match Not Found Really destroying SIP dialog '6feda9f5702731b6618aa78559f36e99@pbx.example.net' Method: INVITE [Feb 6 10:06:32] DEBUG[10405]: pbx.c:1835 pbx_extension_helper: Launching 'Hangup' -- Executing [s@!SIP-evaluate:10] Hangup("Local/102@!SIP-bc76,2", "") in new stack [Feb 6 10:06:32] DEBUG[10405]: pbx.c:2554 __ast_pbx_run: Spawn extension (!SIP-evaluate,s,10) exited non-zero on 'Local/102@!SIP-bc76,2' == Spawn extension (!SIP-evaluate, s, 10) exited non-zero on 'Local/102@!SIP-bc76,2' [Feb 6 10:06:32] DEBUG[10405]: channel.c:1789 ast_hangup: Hanging up channel 'Local/102@!SIP-bc76,2' [Feb 6 10:06:32] DEBUG[10405]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/102@!SIP-bc76,2 [Feb 6 10:06:32] DEBUG[10405]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 102@!SIP [Feb 6 10:06:32] DEBUG[10213]: chan_local.c:145 local_devicestate: Checking if extension 102@!SIP exists (devicestate) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for Local/102@!SIP - state 1 (Not in use) [Feb 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10404]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 6 10:06:32] DEBUG[10404]: rtp.c:2776 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 <--- SIP read from 192.168.161.243:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport=5060 From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 146 NOTIFY Content-Length: 0 <-------------> [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport=5060 (71) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as6a83460e (57) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=dbag2a82z5 (44) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 (55) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 146 NOTIFY (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) --- (7 headers 0 lines) --- pbx*CLI> <--- SIP read from 192.168.161.243:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK14d4e654;rport=5060 From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 147 NOTIFY Content-Length: 0 <-------------> [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK14d4e654;rport=5060 (71) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as6a83460e (57) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=dbag2a82z5 (44) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 (55) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 147 NOTIFY (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) --- (7 headers 0 lines) --- [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3725 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '3c26701788b8-rc29mso7ycw8@snom320-0004132429F1' of Request 147: Match Not Found SIP Response message for INCOMING dialog NOTIFY arrived [Feb 6 10:06:32] DEBUG[10404]: channel.c:3512 ast_channel_masquerade: Planning to masquerade channel SIP/408-09bd7b78 into the structure of Local/408@!SIP-dd13,1 [Feb 6 10:06:32] DEBUG[10404]: channel.c:3526 ast_channel_masquerade: Done planning to masquerade channel SIP/408-09bd7b78 into the structure of Local/408@!SIP-dd13,1 [Feb 6 10:06:32] DEBUG[10404]: chan_local.c:295 local_write: Not posting to queue since already masked on 'Local/408@!SIP-dd13,2' [Feb 6 10:06:32] DEBUG[10403]: channel.c:3637 ast_do_masquerade: Actually Masquerading SIP/408-09bd7b78(6) into the structure of Local/408@!SIP-dd13,1(6) [Feb 6 10:06:32] DEBUG[10403]: channel.c:3649 ast_do_masquerade: Got clone lock for masquerade on 'SIP/408-09bd7b78' at 0x9bafbb8 [Feb 6 10:06:32] DEBUG[10403]: channel.c:3852 ast_do_masquerade: Putting channel SIP/408-09bd7b78 in 8/8 formats [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:3772 sip_fixup: SIP Fixup: New owner for dialogue 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net: SIP/408-09bd7b78 (Old parent: Local/408@!SIP-dd13,1) [Feb 6 10:06:32] DEBUG[10403]: channel.c:3892 ast_do_masquerade: Released clone lock on 'Local/408@!SIP-dd13,1' [Feb 6 10:06:32] DEBUG[10403]: channel.c:3902 ast_do_masquerade: Done Masquerading SIP/408-09bd7b78 (6) -- Native bridging SIP/502-09bb7680 and SIP/408-09bd7b78 [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:17541 sip_set_rtp_peer: Sending reinvite on SIP 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' - It's audio soon redirected to IP 192.168.161.233 [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:5871 reqprep: Strict routing enforced for session do6S475OGBk9tB5Jx4gpt@pbx.example.net [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6421 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6422 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6553 add_sdp: -- Done with adding codecs to SDP [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6598 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:1640 initialize_initreq: Initializing already initialized SIP dialog do6S475OGBk9tB5Jx4gpt@pbx.example.net (presumably reinvite) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 0: INVITE sip:502@192.168.161.227 SIP/2.0 (38) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK119f9906;rport (66) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as79e2d181 (46) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 3: To: "502 Theo" ;tag=Det3djlMWgg3 (57) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 4: Contact: (34) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 5: Call-ID: do6S475OGBk9tB5Jx4gpt@pbx.example.net (46) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 10: Supported: replaces (19) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 13: Content-Length: 246 (19) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 14: (0) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: v=0 (3) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: o=root 23079 23080 IN IP4 192.168.161.233 (41) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: s=session (9) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.161.233 (24) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: t=0 0 (5) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: m=audio 15798 RTP/AVP 8 101 (27) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=ptime:20 (10) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3728 [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:17541 sip_set_rtp_peer: Sending reinvite on SIP '73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net' - It's audio soon redirected to IP 192.168.161.227 [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:5871 reqprep: Strict routing enforced for session 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6421 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6422 add_sdp: ** Our prefcodec: 0x8 (alaw) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6553 add_sdp: -- Done with adding codecs to SDP [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:6598 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:1640 initialize_initreq: Initializing already initialized SIP dialog 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (presumably reinvite) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 0: INVITE sip:408@192.168.161.233:5060;line=ujb4rgep SIP/2.0 (57) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK4b52bf40;rport (66) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as23febd86 (61) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=t5hkiya27s (63) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 4: Contact: (34) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 5: Call-ID: 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (57) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 6: CSeq: 103 INVITE (16) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 9: Remote-Party-ID: "Handset Theo" ;privacy=off;screen=no (79) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 10: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 11: Supported: replaces (19) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 12: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 13: Content-Type: application/sdp (29) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 14: Content-Length: 246 (19) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 15: (0) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: v=0 (3) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: o=root 23079 23080 IN IP4 192.168.161.227 (41) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: s=session (9) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.161.227 (24) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: t=0 0 (5) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: m=audio 10000 RTP/AVP 8 101 (27) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=ptime:20 (10) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:32] DEBUG[10403]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3729 [Feb 6 10:06:32] DEBUG[10403]: rtp.c:2759 ast_rtp_write: Ooh, format changed from unknown to alaw [Feb 6 10:06:32] DEBUG[10403]: rtp.c:2776 ast_rtp_write: Created smoother: format: 8 ms: 20 len: 160 [Feb 6 10:06:32] DEBUG[10404]: channel.c:4088 ast_generic_bridge: Didn't get a frame from channel: Local/408@!SIP-dd13,2 [Feb 6 10:06:32] DEBUG[10404]: channel.c:4413 ast_channel_bridge: Bridge stops bridging channels Local/408@!SIP-dd13,2 and Local/408@!SIP-dd13,1 [Feb 6 10:06:32] DEBUG[10404]: channel.c:1794 ast_hangup: Hanging up zombie 'Local/408@!SIP-dd13,1' [Feb 6 10:06:32] DEBUG[10404]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/408@!SIP-dd13,1 [Feb 6 10:06:32] DEBUG[10404]: rtp.c:1496 ast_rtp_early_bridge: Channel 'Local/408@!SIP-dd13,2' has no RTP, not doing anything [Feb 6 10:06:32] DEBUG[10404]: app_dial.c:1770 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 6 10:06:32] DEBUG[10404]: pbx.c:2431 __ast_pbx_run: Spawn extension (!SIP,408,9) exited non-zero on 'Local/408@!SIP-dd13,2' == Spawn extension (!SIP, 408, 9) exited non-zero on 'Local/408@!SIP-dd13,2' [Feb 6 10:06:32] DEBUG[10404]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'Local/408@!SIP-dd13,2' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [h@!SIP:1] ExecIf("Local/408@!SIP-dd13,2", "0|Hangup") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GosubIf' -- Executing [h@!SIP:2] GosubIf("Local/408@!SIP-dd13,2", "1?s|CDR") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.313105' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.313105' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.257049' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:2] Set("Local/408@!SIP-dd13,2", "RINGINGTIME=3.257049") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '502' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:3] Set("Local/408@!SIP-dd13,2", "CALLINGEXT2=502") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'NULL' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@!SIP:4] Set("Local/408@!SIP-dd13,2", "TRUNKID2=NULL") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'Return' -- Executing [s@!SIP:5] Return("Local/408@!SIP-dd13,2", "") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [h@!SIP:3] GotoIf("Local/408@!SIP-dd13,2", "0?!SIP-evaluate|s|ANSWER") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:6038 pbx_builtin_gotoif: Not taking any branch [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:32] DEBUG[10404]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [h@!SIP:4] ExecIf("Local/408@!SIP-dd13,2", "1|Hangup") in new stack [Feb 6 10:06:32] DEBUG[10404]: pbx.c:2554 __ast_pbx_run: Spawn extension (!SIP,h,4) exited non-zero on 'Local/408@!SIP-dd13,2' == Spawn extension (!SIP, h, 4) exited non-zero on 'Local/408@!SIP-dd13,2' [Feb 6 10:06:32] DEBUG[10404]: channel.c:1789 ast_hangup: Hanging up channel 'Local/408@!SIP-dd13,2' [Feb 6 10:06:32] DEBUG[10404]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel Local/408@!SIP-dd13,2 [Feb 6 10:06:32] DEBUG[10404]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 408@!SIP [Feb 6 10:06:32] DEBUG[10213]: chan_local.c:145 local_devicestate: Checking if extension 408@!SIP exists (devicestate) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for Local/408@!SIP - state 1 (Not in use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for Local - 408@!SIP [Feb 6 10:06:32] DEBUG[10213]: chan_local.c:145 local_devicestate: Checking if extension 408@!SIP exists (devicestate) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for Local/408@!SIP - state 1 (Not in use) [Feb 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10235]: 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 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport=5060;branch=z9hG4bK119f9906 (66) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as79e2d181 (46) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: "502 Theo" ;tag=Det3djlMWgg3 (57) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: do6S475OGBk9tB5Jx4gpt@pbx.example.net (46) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 102 INVITE (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2203 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #3728 - INVITE (got response) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' Request 102: Found [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:11978 handle_response_invite: SIP response 100 to RE-invite on outgoing call do6S475OGBk9tB5Jx4gpt@pbx.example.net [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport;branch=z9hG4bK119f9906 (61) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=as79e2d181 (46) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: "502 Theo" ;tag=Det3djlMWgg3 (57) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: do6S475OGBk9tB5Jx4gpt@pbx.example.net (46) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 102 INVITE (16) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: (34) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Accept: application/sdp (23) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Content-Disposition: session (28) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Content-Type: application/SDP (29) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: Content-Length: 258 (19) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: (0) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: v=0 (3) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: o=502 992550869 992550870 IN IP4 192.168.161.227 (48) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: s=- (3) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.161.227 (24) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: t=0 0 (5) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: m=audio 10000 RTP/AVP 8 0 101 (29) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtcp:10001 (12) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2152 __sip_ack: Acked pending invite 102 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' of Request 102: Match Not Found [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:11978 handle_response_invite: SIP response 200 to RE-invite on outgoing call do6S475OGBk9tB5Jx4gpt@pbx.example.net [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel SIP/502-09bb7680 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:5475 process_sdp: We have an owner, now see if we need to change this call [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call [Feb 6 10:06:32] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:8241 build_route: build_route: Contact hop: [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:12112 handle_response_invite: Strange... The other side of the bridge does not have a udptl struct [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:12117 handle_response_invite: T38 state changed to 0 on channel SIP [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:12120 handle_response_invite: T38 state changed to 0 on channel SIP/502-09bb7680 [Feb 6 10:06:32] DEBUG[10233]: chan_sip.c:5871 reqprep: Strict routing enforced for session do6S475OGBk9tB5Jx4gpt@pbx.example.net [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 2 (In use) [Feb 6 10:06:32] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:32] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:32] DEBUG[10235]: 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 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK4b52bf40;rport=5060 (71) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Handset Theo" ;tag=as23febd86 (61) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=t5hkiya27s (63) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (57) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 103 INVITE (16) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Contact: ;flow-id=1 (63) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: User-Agent: snom360/6.5.15 (26) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Allow: INVITE, ACK, CANCEL, BYE, REFER, OPTIONS, NOTIFY, SUBSCRIBE, PRACK, MESSAGE, INFO (88) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow-Events: talk, hold, refer (31) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Supported: timer, 100rel, replaces, callerid (44) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Content-Type: application/sdp (29) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Content-Length: 226 (19) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: (0) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: v=0 (3) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: o=root 1068170766 1068170768 IN IP4 192.168.161.233 (51) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: s=call (6) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.161.233 (24) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: t=0 0 (5) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: m=audio 15798 RTP/AVP 8 101 (27) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 pcma/8000 (20) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=ptime:20 (10) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:2152 __sip_ack: Acked pending invite 103 [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3729 [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net' of Request 103: Match Not Found [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:11978 handle_response_invite: SIP response 200 to RE-invite on outgoing call 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel SIP/408-09bd7b78 [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:5475 process_sdp: We have an owner, now see if we need to change this call [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call [Feb 6 10:06:33] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408 [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:8180 build_route: build_route: Retaining previous route: [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:5871 reqprep: Strict routing enforced for session 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net [Feb 6 10:06:33] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:33] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:33] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 2 (In use) [Feb 6 10:06:33] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:33] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:33] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:33] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:33] DEBUG[10235]: 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 6 10:06:33] DEBUG[10233]: chan_sip.c:1908 retrans_pkt: SIP TIMER: Rescheduling retransmission #3720 (1) NOTIFY - 4 [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:1922 retrans_pkt: ** SIP timers: Rescheduling retransmission 2 to 1000 ms (t1 500 ms (Retrans id #3720)) Retransmitting #1 (no NAT) to 192.168.161.243:5060: NOTIFY sip:406@192.168.161.243:5060;line=u8pkfgw2 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Contact: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 146 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 224 early --- pbx*CLI> <--- SIP read from 192.168.161.243:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport=5060 From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 146 NOTIFY Content-Length: 0 <-------------> [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport=5060 (71) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as6a83460e (57) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=dbag2a82z5 (44) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 (55) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 146 NOTIFY (16) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:33] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) --- (7 headers 0 lines) --- [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:1908 retrans_pkt: SIP TIMER: Rescheduling retransmission #3720 (2) NOTIFY - 4 [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:1922 retrans_pkt: ** SIP timers: Rescheduling retransmission 3 to 2000 ms (t1 500 ms (Retrans id #3720)) Retransmitting #2 (no NAT) to 192.168.161.243:5060: NOTIFY sip:406@192.168.161.243:5060;line=u8pkfgw2 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Contact: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 146 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 224 early --- pbx*CLI> <--- SIP read from 192.168.161.243:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport=5060 From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 146 NOTIFY Content-Length: 0 <-------------> [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport=5060 (71) [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as6a83460e (57) [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=dbag2a82z5 (44) [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 (55) [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 146 NOTIFY (16) [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:34] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) --- (7 headers 0 lines) --- [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:1908 retrans_pkt: SIP TIMER: Rescheduling retransmission #3720 (3) NOTIFY - 4 [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:1922 retrans_pkt: ** SIP timers: Rescheduling retransmission 4 to 4000 ms (t1 500 ms (Retrans id #3720)) Retransmitting #3 (no NAT) to 192.168.161.243:5060: NOTIFY sip:406@192.168.161.243:5060;line=u8pkfgw2 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Contact: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 146 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 224 early --- pbx*CLI> <--- SIP read from 192.168.161.243:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport=5060 From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 146 NOTIFY Content-Length: 0 <-------------> [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK27228435;rport=5060 (71) [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as6a83460e (57) [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=dbag2a82z5 (44) [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 (55) [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 146 NOTIFY (16) [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:36] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) --- (7 headers 0 lines) --- [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: BYE sip:502@192.168.161.100 SIP/2.0 (35) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.233:5060;branch=z9hG4bK-x9z7um6z87g1;rport (71) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=t5hkiya27s (65) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: "Handset Theo" ;tag=as23febd86 (59) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net (57) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 1 BYE (11) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1 (63) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: User-Agent: snom360/6.5.15 (26) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: RTP-RxStat: Total_Rx_Pkts=239,Rx_Pkts=239,Rx_Pkts_Lost=0,Remote_Rx_Pkts_Lost=0 (78) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: RTP-TxStat: Total_Tx_Pkts=258,Tx_Pkts=258,Remote_Tx_Pkts=0 (58) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: Content-Length: 0 (17) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: (0) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received BYE (8) - Command in SIP BYE [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:1652 sip_alreadygone: Setting SIP_ALREADYGONE on dialog 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:14739 handle_request_bye: Received bye, issuing owner hangup [Feb 6 10:06:38] DEBUG[10403]: rtp.c:2951 bridge_native_loop: Oooh, got a hangup [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:17541 sip_set_rtp_peer: Sending reinvite on SIP 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' - It's audio soon redirected to IP 192.168.161.100 [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:5871 reqprep: Strict routing enforced for session do6S475OGBk9tB5Jx4gpt@pbx.example.net [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:6421 add_sdp: ** Our capability: 0x8 (alaw) Video flag: True [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:6422 add_sdp: ** Our prefcodec: 0x0 (nothing) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:6553 add_sdp: -- Done with adding codecs to SDP [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:6598 add_sdp: Done building SDP. Settling with this capability: 0x8 (alaw) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:1640 initialize_initreq: Initializing already initialized SIP dialog do6S475OGBk9tB5Jx4gpt@pbx.example.net (presumably reinvite) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 0: INVITE sip:502@192.168.161.227 SIP/2.0 (38) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK6b51eb0e;rport (66) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as79e2d181 (46) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 3: To: "502 Theo" ;tag=Det3djlMWgg3 (57) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 4: Contact: (34) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 5: Call-ID: do6S475OGBk9tB5Jx4gpt@pbx.example.net (46) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 6: CSeq: 103 INVITE (16) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 8: Max-Forwards: 70 (16) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 9: Allow: INVITE, ACK, CANCEL, OPTIONS, BYE, REFER, SUBSCRIBE, NOTIFY (66) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 10: Supported: replaces (19) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 11: X-asterisk-Info: SIP re-invite (External RTP bridge) (52) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 12: Content-Type: application/sdp (29) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 13: Content-Length: 246 (19) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4774 parse_request: Header 14: (0) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: v=0 (3) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: o=root 23079 23081 IN IP4 192.168.161.100 (41) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: s=session (9) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.161.100 (24) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: t=0 0 (5) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: m=audio 10662 RTP/AVP 8 101 (27) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-16 (15) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=silenceSupp:off - - - - (25) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=ptime:20 (10) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3730 [Feb 6 10:06:38] DEBUG[10403]: channel.c:4343 ast_channel_bridge: Returning from native bridge, channels: SIP/502-09bb7680, SIP/408-09bd7b78 [Feb 6 10:06:38] DEBUG[10403]: channel.c:1789 ast_hangup: Hanging up channel 'SIP/408-09bd7b78' [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:3485 sip_hangup: Hangup call SIP/408-09bd7b78, SIP callid 73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:3494 sip_hangup: update_call_counter(408) - decrement call limit counter on hangup [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:3173 update_call_counter: Updating call counter for outgoing call [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:3224 update_call_counter: Call to peer '408' removed from call limit 30 [Feb 6 10:06:38] DEBUG[10403]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408 [Feb 6 10:06:38] DEBUG[10403]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/408-09bd7b78 [Feb 6 10:06:38] DEBUG[10403]: rtp.c:1504 ast_rtp_early_bridge: Channel '' has no RTP, not doing anything [Feb 6 10:06:38] DEBUG[10403]: app_dial.c:1770 dial_exec_full: Exiting with DIALSTATUS=ANSWER. [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Macro' -- Executing [408@calldist-16:4] Macro("SIP/502-09bb7680", "endcall|ANSWER|N|0") in new stack [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-endcall:1] ExecIf("SIP/502-09bb7680", "0|Set|ARRAY(ARG1|ARG2|ARG3)=,N,") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: ExecIf [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Goto' -- Executing [s@macro-endcall:2] Goto("SIP/502-09bb7680", "ANSWER") in new stack -- Goto (macro-endcall,s,3) [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Goto [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:3] GotoIf("SIP/502-09bb7680", "0?ANSWER-EXIT") in new stack [Feb 6 10:06:38] DEBUG[10403]: pbx.c:6038 pbx_builtin_gotoif: Not taking any branch [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:4] GotoIf("SIP/502-09bb7680", "0?ANSWER-EXIT") in new stack [Feb 6 10:06:38] DEBUG[10403]: pbx.c:6038 pbx_builtin_gotoif: Not taking any branch [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:5] GotoIf("SIP/502-09bb7680", "0?ANSWER-EXIT") in new stack [Feb 6 10:06:38] DEBUG[10403]: pbx.c:6038 pbx_builtin_gotoif: Not taking any branch [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'GotoIf' -- Executing [s@macro-endcall:6] GotoIf("SIP/502-09bb7680", "0?ANSWER-CALLING:ANSWER-CALLED") in new stack -- Goto (macro-endcall,s,10) [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: GotoIf [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'NoOp' -- Executing [s@macro-endcall:10] NoOp("SIP/502-09bb7680", ".... Called Party Hungup .... ") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: NoOp [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'GosubIf' -- Executing [s@macro-endcall:11] GosubIf("SIP/502-09bb7680", "1?ANSWER-CDR") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: GosubIf [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:350 _macro_exec: Incrementing gosub_level [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'SIP/408' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '408' [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 1 (Not in use) [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 Reliably Transmitting (no NAT) to 192.168.161.243:5060: NOTIFY sip:406@192.168.161.243:5060;line=u8pkfgw2 SIP/2.0 Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK7d0e2adc;rport From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Contact: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 148 NOTIFY User-Agent: atCOM PBX Max-Forwards: 70 Event: dialog Content-Type: application/dialog-info+xml Subscription-State: active Content-Length: 207 terminated --- [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3731 Extension Changed 408 new state Idle for Notify User 406 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/408 - state 1 (Not in use) [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 408 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 408 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 102 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 102 [Feb 6 10:06:38] DEBUG[10235]: 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 6 10:06:38] DEBUG[10235]: 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 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 100 Trying (18) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport=5060;branch=z9hG4bK6b51eb0e (66) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as79e2d181 (46) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: "502 Theo" ;tag=Det3djlMWgg3 (57) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: do6S475OGBk9tB5Jx4gpt@pbx.example.net (46) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 103 INVITE (16) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:2203 __sip_semi_ack: *** SIP TIMER: Cancelling retransmission #3730 - INVITE (got response) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:2212 __sip_semi_ack: (Provisional) Stopping retransmission (but retaining packet) on 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' Request 103: Found [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:11978 handle_response_invite: SIP response 100 to RE-invite on outgoing call do6S475OGBk9tB5Jx4gpt@pbx.example.net Really destroying SIP dialog '73d3309200ffa8382f3c272b0aa7b2d7@pbx.example.net' Method: BYE [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '408' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [s@macro-endcall:17] ExecIf("SIP/502-09bb7680", "0|Set|CALLEDEXT=408") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: ExecIf [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'SIP/408' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '408' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '408' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288792.806183' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288789.408168' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288789.464224' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.341959' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:18] Set("SIP/502-09bb7680", "RINGTIMECORR=0") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '2' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '1' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '408-09bd7b78' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '408' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'user-08' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:19] Set("SIP/502-09bb7680", "CONTEXTDEST=user-08") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288789.408168' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288789.464224' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288789.464224' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:20] Set("SIP/502-09bb7680", "STARTTIME=1202288789.464224") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288792.806183' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288789.408168' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288789.464224' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.341959' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '3.341959' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:21] Set("SIP/502-09bb7680", "RINGINGTIME=3.341959") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '1202288792.806183' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '5.529034' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:22] Set("SIP/502-09bb7680", "DURATION=5.529034") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'ANSWERED1' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:23] Set("SIP/502-09bb7680", "DISPOSITION=ANSWERED1") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '502' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:24] Set("SIP/502-09bb7680", "CALLINGEXT2=502") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'NULL' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:25] Set("SIP/502-09bb7680", "TRUNKID2=NULL") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'SIP/502-09bb7680' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'SIP/502-09bb7680' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is '"Handset Theo" <502>' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Set' -- Executing [s@macro-endcall:26] Set("SIP/502-09bb7680", "ODBC_CDR()=1202288789,NULL,1202288789.464224,1202288798.336693,'502','408','SIP/502-09bb7680','SIP/408-09bd7b78','user-01','user-08','ANSWERED1',3.341959,5.529034,'','"Handset Theo" <502>','phone','','16'") in new stack [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport;branch=z9hG4bK6b51eb0e (61) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=as79e2d181 (46) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: "502 Theo" ;tag=Det3djlMWgg3 (57) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: do6S475OGBk9tB5Jx4gpt@pbx.example.net (46) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 103 INVITE (16) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: (34) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Accept: application/sdp (23) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Allow: INVITE, CANCEL, BYE, ACK, REGISTER, OPTIONS, REFER, SUBSCRIBE, NOTIFY, MESSAGE, INFO, PRACK (98) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Content-Disposition: session (28) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: User-Agent: snom-m3-SIP/01.07 (MAC=0004132A084B; HW=1) (54) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: Content-Type: application/SDP (29) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: Content-Length: 258 (19) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: (0) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: v=0 (3) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: o=502 992550869 992550871 IN IP4 192.168.161.227 (48) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: s=- (3) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: c=IN IP4 192.168.161.227 (24) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: t=0 0 (5) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: m=audio 10000 RTP/AVP 8 0 101 (29) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:8 PCMA/8000 (20) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:0 PCMU/8000 (20) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtpmap:101 telephone-event/8000 (33) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=fmtp:101 0-15 (15) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=sendrecv (10) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4806 parse_request: Line: a=rtcp:10001 (12) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:2152 __sip_ack: Acked pending invite 103 [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' of Request 103: Match Not Found [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:11978 handle_response_invite: SIP response 200 to RE-invite on outgoing call do6S475OGBk9tB5Jx4gpt@pbx.example.net [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:5388 process_sdp: T38 state changed to 0 on channel SIP/502-09bb7680 [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:5468 process_sdp: We're settling with these formats: 0x8 (alaw) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:5475 process_sdp: We have an owner, now see if we need to change this call [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call [Feb 6 10:06:38] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502 [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:8180 build_route: build_route: Retaining previous route: [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:5871 reqprep: Strict routing enforced for session do6S475OGBk9tB5Jx4gpt@pbx.example.net [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 2 (In use) [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:38] DEBUG[10235]: 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 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Set [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'ResetCDR' -- Executing [s@macro-endcall:27] ResetCDR("SIP/502-09bb7680", "w") in new stack [Feb 6 10:06:38] DEBUG[10403]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: ResetCDR [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Return' -- Executing [s@macro-endcall:28] Return("SIP/502-09bb7680", "") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:337 _macro_exec: Executed application: Return [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:360 _macro_exec: Decrementing gosub_level [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'Hangup' -- Executing [s@macro-endcall:12] Hangup("SIP/502-09bb7680", "") in new stack [Feb 6 10:06:38] DEBUG[10403]: app_macro.c:329 _macro_exec: Spawn extension (macro-endcall,s,12) exited non-zero on 'SIP/502-09bb7680' in macro 'endcall' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:2431 __ast_pbx_run: Spawn extension (macro-endcall,s,12) exited non-zero on 'SIP/502-09bb7680' == Spawn extension (macro-endcall, s, 12) exited non-zero on 'SIP/502-09bb7680' [Feb 6 10:06:38] DEBUG[10403]: channel.c:1570 ast_softhangup_nolock: Soft-Hanging up channel 'SIP/502-09bb7680' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1684 pbx_substitute_variables_helper_full: Function result is 'Hangup' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1752 pbx_substitute_variables_helper_full: Expression result is '0' [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'ExecIf' -- Executing [h@macro-endcall:1] ExecIf("SIP/502-09bb7680", "0|Goto|s|VOICEMAIL-CDR") in new stack [Feb 6 10:06:38] DEBUG[10403]: pbx.c:1835 pbx_extension_helper: Launching 'NoOp' -- Executing [h@macro-endcall:2] NoOp("SIP/502-09bb7680", ".... End of call .... 1202288789") in new stack [Feb 6 10:06:38] DEBUG[10403]: channel.c:1789 ast_hangup: Hanging up channel 'SIP/502-09bb7680' [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:3485 sip_hangup: Hangup call SIP/502-09bb7680, SIP callid do6S475OGBk9tB5Jx4gpt@pbx.example.net) [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:3494 sip_hangup: update_call_counter(502) - decrement call limit counter on hangup [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:3173 update_call_counter: Updating call counter for incoming call [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:3224 update_call_counter: Call from peer '502' removed from call limit 30 [Feb 6 10:06:38] DEBUG[10403]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502 [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:5871 reqprep: Strict routing enforced for session do6S475OGBk9tB5Jx4gpt@pbx.example.net [Feb 6 10:06:38] DEBUG[10403]: chan_sip.c:2041 __sip_reliable_xmit: *** SIP TIMER: Initializing retransmit timer on packet: Id #3733 [Feb 6 10:06:38] DEBUG[10403]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/502-09bb7680 [Feb 6 10:06:38] DEBUG[10403]: cdr.c:1170 ast_cdr_detach: Dropping CDR ! [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 1 (Not in use) [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/502 - state 1 (Not in use) [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 502 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 502 [Feb 6 10:06:38] DEBUG[10235]: 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 6 10:06:38] DEBUG[10235]: 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 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 OK (14) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100;rport=5060;branch=z9hG4bK19c4cf99 (66) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: Max-Forwards: 70 (16) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: From: ;tag=as79e2d181 (46) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: To: "502 Theo" ;tag=Det3djlMWgg3 (57) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: Call-ID: do6S475OGBk9tB5Jx4gpt@pbx.example.net (46) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: CSeq: 104 BYE (13) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: User-Agent: atCOM PBX (21) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: Content-Length: 0 (17) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: (0) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3733 [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' of Request 104: Match Not Found Really destroying SIP dialog 'do6S475OGBk9tB5Jx4gpt@pbx.example.net' Method: ACK <--- SIP read from 192.168.161.243:5060 ---> SIP/2.0 200 Ok Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK7d0e2adc;rport=5060 From: ;tag=as6a83460e To: ;tag=dbag2a82z5 Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 CSeq: 148 NOTIFY Content-Length: 0 <-------------> [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: SIP/2.0 200 Ok (14) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.100:5060;branch=z9hG4bK7d0e2adc;rport=5060 (71) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: ;tag=as6a83460e (57) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: ;tag=dbag2a82z5 (44) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26701788b8-rc29mso7ycw8@snom320-0004132429F1 (55) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 148 NOTIFY (16) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Content-Length: 0 (17) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: (0) --- (7 headers 0 lines) --- [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:2160 __sip_ack: ** SIP TIMER: Cancelling retransmit of packet (reply received) Retransid #3731 [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:2170 __sip_ack: Stopping retransmission on '3c26701788b8-rc29mso7ycw8@snom320-0004132429F1' of Request 148: Match Not Found SIP Response message for INCOMING dialog NOTIFY arrived [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.249:5060;branch=z9hG4bK-t2n6m37bu24z;rport (71) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Ramon 2" ;tag=nja2lv8vq4 (56) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: "Ramon 2" (39) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26700c493e-5d9p8mhfls9t@snom360-000413231BA0 (55) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 5041 REGISTER (19) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1;q=1.0;+sip.instance="" (133) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: User-Agent: snom360/6.5.15 (26) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Supported: gruu (15) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Allow-Events: dialog (20) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: X-Real-IP: 192.168.161.249 (26) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: WWW-Contact: (40) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: WWW-Contact: (42) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: Expires: 600 (12) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 15: Content-Length: 0 (17) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 16: (0) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4509 sip_alloc: Allocating new SIP dialog for 3c26700c493e-5d9p8mhfls9t@snom360-000413231BA0 - REGISTER (No RTP) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 0: REGISTER sip:pbx.example.net SIP/2.0 (36) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 1: Via: SIP/2.0/UDP 192.168.161.249:5060;branch=z9hG4bK-k76jyqw0d2m1;rport (71) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 2: From: "Ramon 2" ;tag=nja2lv8vq4 (56) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 3: To: "Ramon 2" (39) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 4: Call-ID: 3c26700c493e-5d9p8mhfls9t@snom360-000413231BA0 (55) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 5: CSeq: 5042 REGISTER (19) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 6: Max-Forwards: 70 (16) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 7: Contact: ;flow-id=1;q=1.0;+sip.instance="" (133) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 8: User-Agent: snom360/6.5.15 (26) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 9: Supported: gruu (15) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 10: Allow-Events: dialog (20) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 11: X-Real-IP: 192.168.161.249 (26) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 12: WWW-Contact: (40) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 13: WWW-Contact: (42) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 14: Authorization: Digest username="402",realm="siprealm",nonce="75edd285",uri="sip:pbx.example.net",response="61205af46df3cd75dadc4171310cda3a",algorithm=MD5 (154) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 15: Expires: 600 (12) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 16: Content-Length: 0 (17) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:4774 parse_request: Header 17: (0) [Feb 6 10:06:38] DEBUG[10233]: chan_sip.c:15187 handle_request: **** Received REGISTER (2) - Command in SIP REGISTER [Feb 6 10:06:38] DEBUG[10233]: devicestate.c:304 __ast_device_state_changed_literal: Notification of state change to be queued on device/channel SIP/402 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 402 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 402 [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:287 do_state_change: Changing state for SIP/402 - state 1 (Not in use) [Feb 6 10:06:38] DEBUG[10213]: devicestate.c:161 ast_device_state: No provider found, checking channel drivers for SIP - 402 [Feb 6 10:06:38] DEBUG[10213]: chan_sip.c:15821 sip_devicestate: Checking device state for peer 402 [Feb 6 10:06:38] DEBUG[10235]: app_queue.c:600 handle_statechange: Device 'SIP/402' changed to state '1' (Not in use)