23 Mar
2017
23 Mar
'17
3:07 p.m.
Hi all, we are experiencing a strange issue during call transfer (REFER) after a SIP 302 MOVED. Please find below a brief description of our test environment. Extensions involved: - 8911 (original caller) - 8910 (forwarded to 5536 through phone ui) - 5536 (originator of call transfer) - 5532 (destination of call transfer) Step to reproduce the issue: - 8911 calls 8910 which is forwarded on 5536 (call fwd is configured directly on phone gui) - 5536 correctly answer the call from 8911 - 5536 begins a consult transfer to 5532: Hold step is ok but call drops when 5536 completes the transfer. >From the SIP signaling point of view: - 8910 answers to 8911 with a SIP MOVED. - Freeswitch send an invite to 5536 as 8911. - Call transfer from 5536 to 5532 is managed with a refer. - When 5536 complete the transfer, Freeswitch send a bye first to 8911 (original caller) and then to 5536. On Freeswitch dialplan we manage refer on a different context, setting "sip_redirect_context" variables. Without MOVED involved, all call transfer are correctly managed. It seems that we need to keep alive a-leg after the bridge and then perform the transfer. We tried all the following settings on redirect context: - set + export of variables: force_transfer_context + force_transfer_dialplan - set + export park_after_bridge=true - set continue_on_fail=true - unset of sip_redirect_context But all without success! Please find below fscli log. Thanks in advance for help. Regards Francesco freeswitch@default> freeswitch@default> freeswitch@default> freeswitch@default> sofia global siptrace on +OK Global siptrace on recv 1047 bytes from udp/[172.25.248.82]:5060 at 10:56:05.728805: ------------------------------------------------------------------------ INVITE sip:mod_sofia@172.25.248.83:5060 SIP/2.0 Record-Route: <sip:172.25.248.82;lr;ftag=507421845> Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bK961e.b1e68771.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK2041699543 From: <sip:5536@172.22.27.137:5062>;tag=507421845 To: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754016 INVITE Contact: <sip:5536@172.22.27.137:5062> Content-Type: application/sdp Allow: INVITE, INFO, PRACK, ACK, BYE, CANCEL, OPTIONS, NOTIFY, REGISTER, SUBSCRIBE, REFER, PUBLISH, UPDATE, MESSAGE Max-Forwards: 69 User-Agent: Yealink SIP-T21P 34.72.0.75 Allow-Events: talk,hold,conference,refer,check-sync Content-Length: 308 v=0 o=- 20014 20016 IN IP4 172.22.27.137 s=SDP data c=IN IP4 172.22.27.137 t=0 0 m=audio 11786 RTP/AVP 0 8 18 9 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:9 G722/8000 a=fmtp:101 0-15 a=rtpmap:101 telephone-event/8000 a=ptime:20 a=sendonly ------------------------------------------------------------------------ send 487 bytes to udp/[172.25.248.82]:5060 at 10:56:05.729233: ------------------------------------------------------------------------ SIP/2.0 100 Trying Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bK961e.b1e68771.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK2041699543 Record-Route: <sip:172.25.248.82;lr;ftag=507421845> From: <sip:5536@172.22.27.137:5062>;tag=507421845 To: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754016 INVITE User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140910T073219Z~bbe2531cb0~64bit Content-Length: 0 ------------------------------------------------------------------------ 2017-03-22 11:56:05.713101 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:05.713101 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:05.733132 [DEBUG] sofia.c:5847 Channel sofia/internal/sip:5536@172.22.27.137:5062 entering state [received][100] 2017-03-22 11:56:05.733132 [DEBUG] sofia.c:5860 Remote SDP: v=0 o=- 20014 20016 IN IP4 172.22.27.137 s=SDP data c=IN IP4 172.22.27.137 t=0 0 m=audio 11786 RTP/AVP 0 8 18 9 101 a=rtpmap:0 PCMU/8000 a=rtpmap:8 PCMA/8000 a=rtpmap:18 G729/8000 a=fmtp:18 annexb=no a=rtpmap:9 G722/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-15 a=sendonly a=ptime:20 2017-03-22 11:56:05.733132 [DEBUG] switch_channel.c:1783 (sofia/internal/sip:5536@172.22.27.137:5062) Callstate Change ACTIVE -> HELD 2017-03-22 11:56:05.733132 [DEBUG] switch_core_session.c:1151 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:05.753091 [DEBUG] switch_core_session.c:871 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:05.873149 [DEBUG] switch_ivr.c:614 sofia/internal/8911@insiel.fvgvoipcoll.it Command Execute playback(local_stream://moh) EXECUTE sofia/internal/8911@insiel.fvgvoipcoll.it playback(local_stream://moh) 2017-03-22 11:56:05.873149 [DEBUG] mod_local_stream.c:498 Opening Stream [moh/8000] 8000hz 2017-03-22 11:56:05.873149 [DEBUG] switch_ivr_play_say.c:1305 Codec Activated L16@8000hz 1 channels 20ms 2017-03-22 11:56:05.973127 [DEBUG] sofia_glue.c:5284 Audio Codec Compare [PCMU:0:8000:20:64000]/[PCMU:0:8000:20:64000] 2017-03-22 11:56:05.973127 [DEBUG] sofia_glue.c:3121 Already using PCMU 2017-03-22 11:56:05.973127 [DEBUG] sofia_glue.c:5444 Set 2833 dtmf send payload to 101 2017-03-22 11:56:05.973127 [DEBUG] sofia_glue.c:3421 Audio params are unchanged for sofia/internal/sip:5536@172.22.27.137:5062. 2017-03-22 11:56:05.973127 [DEBUG] sofia_glue.c:3431 sofia/internal/sip:5536@172.22.27.137:5062 Setting audio receive payload in Re-INVITE to 0 2017-03-22 11:56:05.973127 [DEBUG] sofia.c:6426 Processing updated SDP send 994 bytes to udp/[172.25.248.82]:5060 at 10:56:05.984830: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bK961e.b1e68771.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK2041699543 Record-Route: <sip:172.25.248.82;lr;ftag=507421845> From: <sip:5536@172.22.27.137:5062>;tag=507421845 To: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754016 INVITE Contact: <sip:mod_sofia@172.25.248.83:5060> User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140910T073219Z~bbe2531cb0~64bit Accept: application/sdp Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Type: application/sdp Content-Disposition: session Content-Length: 234 v=0 o=FreeSWITCH 1490161741 1490161743 IN IP4 172.25.248.83 s=FreeSWITCH c=IN IP4 172.25.248.83 t=0 0 m=audio 18418 RTP/AVP 0 101 a=rtpmap:0 PCMU/8000 a=rtpmap:101 telephone-event/8000 a=fmtp:101 0-16 a=recvonly a=ptime:20 ------------------------------------------------------------------------ 2017-03-22 11:56:05.973127 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:05.973127 [DEBUG] sofia.c:5847 Channel sofia/internal/sip:5536@172.22.27.137:5062 entering state [completed][200] recv 530 bytes from udp/[172.25.248.82]:5060 at 10:56:06.036465: ------------------------------------------------------------------------ ACK sip:mod_sofia@172.25.248.83:5060 SIP/2.0 Record-Route: <sip:172.25.248.82;lr;ftag=507421845> Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bK961e.b1e68771.2 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK1912144644 From: <sip:5536@172.22.27.137:5062>;tag=507421845 To: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754016 ACK Contact: <sip:5536@172.22.27.137:5062> Max-Forwards: 69 User-Agent: Yealink SIP-T21P 34.72.0.75 Content-Length: 0 ------------------------------------------------------------------------ 2017-03-22 11:56:06.033119 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:06.033119 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:06.033119 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:06.053107 [DEBUG] sofia.c:5847 Channel sofia/internal/sip:5536@172.22.27.137:5062 entering state [ready][200] recv 622 bytes from udp/[172.25.248.82]:5060 at 10:56:10.086826: ------------------------------------------------------------------------ SUBSCRIBE sip:5536@insiel.fvgvoipcoll.it:5060 SIP/2.0 Record-Route: <sip:172.25.248.82;lr;ftag=1995003817> Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bKcd5.bbf6e311.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK2046226047 From: "5536 Agente PN" <sip:5536@insiel.fvgvoipcoll.it>;tag=1995003817 To: "5536 Agente PN" <sip:5536@insiel.fvgvoipcoll.it> Call-ID: 1353578327@172.22.27.137 CSeq: 1 SUBSCRIBE Contact: <sip:5536@172.22.27.137:5062> Accept: application/x-as-feature-event+xml Max-Forwards: 69 User-Agent: Yealink SIP-T21P 34.72.0.75 Expires: 3630 Event: as-feature-event Content-Length: 0 ------------------------------------------------------------------------ send 747 bytes to udp/[172.25.248.82]:5060 at 10:56:10.087100: ------------------------------------------------------------------------ SIP/2.0 489 Bad Event Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bKcd5.bbf6e311.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK2046226047 From: "5536 Agente PN" <sip:5536@insiel.fvgvoipcoll.it>;tag=1995003817 To: "5536 Agente PN" <sip:5536@insiel.fvgvoipcoll.it>;tag=7p57cDp7DXNSF Call-ID: 1353578327@172.22.27.137 CSeq: 1 SUBSCRIBE User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140910T073219Z~bbe2531cb0~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 ------------------------------------------------------------------------ recv 583 bytes from udp/[172.25.248.82]:5060 at 10:56:10.938465: ------------------------------------------------------------------------ REFER sip:mod_sofia@172.25.248.83:5060 SIP/2.0 Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bKa61e.a30dbb65.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK1759603587 From: <sip:5536@172.22.27.137:5062>;tag=507421845 To: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754017 REFER Contact: <sip:5536@172.22.27.137:5062> Max-Forwards: 69 User-Agent: Yealink SIP-T21P 34.72.0.75 Refer-To: <sip:5532@insiel.fvgvoipcoll.it> Referred-By: <sip:5536@172.22.27.137:5062> Event: refer Content-Length: 0 ------------------------------------------------------------------------ 2017-03-22 11:56:10.933089 [DEBUG] switch_core_session.c:1016 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] send 790 bytes to udp/[172.25.248.82]:5060 at 10:56:10.953457: ------------------------------------------------------------------------ SIP/2.0 202 Accepted Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bKa61e.a30dbb65.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK1759603587 From: <sip:5536@172.22.27.137:5062>;tag=507421845 To: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754017 REFER Contact: <sip:mod_sofia@172.25.248.83:5060> Expires: 60 User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140910T073219Z~bbe2531cb0~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Content-Length: 0 ------------------------------------------------------------------------ 2017-03-22 11:56:10.953129 [DEBUG] switch_core_session.c:933 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:10.953129 [DEBUG] sofia.c:6924 Process REFER to [5532@insiel.fvgvoipcoll.it] send 959 bytes to udp/[172.25.248.82]:5060 at 10:56:10.953825: ------------------------------------------------------------------------ NOTIFY sip:5536@172.22.27.137:5062 SIP/2.0 Via: SIP/2.0/UDP 172.25.248.83;rport;branch=z9hG4bKDapFc3UKFFtcr Route: <sip:172.25.248.82;lr;ftag=4USX7U3vp2j1c;did=51d.6c2982e6> Max-Forwards: 70 From: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c To: <sip:5536@172.22.27.137:5062>;tag=507421845 Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754017 NOTIFY Contact: <sip:mod_sofia@172.25.248.83:5060> User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140910T073219Z~bbe2531cb0~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Event: refer;id=104754017 Allow-Events: talk, hold, conference, presence, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer Subscription-State: terminated;reason=noresource Content-Type: message/sipfrag;version=2.0 Content-Length: 16 SIP/2.0 200 OK ------------------------------------------------------------------------ 2017-03-22 11:56:10.953129 [DEBUG] switch_ivr.c:1834 (sofia/internal/8911@insiel.fvgvoipcoll.it) State Change CS_EXECUTE -> CS_ROUTING 2017-03-22 11:56:10.953129 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:10.953129 [DEBUG] switch_core_session.c:871 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:10.953129 [NOTICE] switch_ivr.c:1841 Transfer sofia/internal/8911@insiel.fvgvoipcoll.it to XML[5532@redir] 2017-03-22 11:56:10.973121 [DEBUG] switch_ivr_play_say.c:1708 done playing file local_stream://moh 2017-03-22 11:56:10.973121 [DEBUG] switch_core_session.c:871 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:10.973121 [DEBUG] switch_ivr_bridge.c:386 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:10.973121 [DEBUG] switch_ivr_bridge.c:645 BRIDGE THREAD DONE [sofia/internal/sip:5536@172.22.27.137:5062] 2017-03-22 11:56:10.973121 [DEBUG] switch_channel.c:1951 (sofia/internal/sip:5536@172.22.27.137:5062) Callstate Change HELD -> UNHELD 2017-03-22 11:56:10.973121 [DEBUG] switch_ivr_bridge.c:675 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:10.973121 [NOTICE] switch_ivr_bridge.c:739 Hangup sofia/internal/sip:5536@172.22.27.137:5062 [CS_EXCHANGE_MEDIA] [NORMAL_CLEARING] 2017-03-22 11:56:10.973121 [DEBUG] switch_channel.c:3189 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [KILL] 2017-03-22 11:56:10.973121 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:681 (sofia/internal/sip:5536@172.22.27.137:5062) Callstate Change UNHELD -> HANGUP 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:683 (sofia/internal/sip:5536@172.22.27.137:5062) State HANGUP 2017-03-22 11:56:10.973121 [DEBUG] mod_sofia.c:506 Channel sofia/internal/sip:5536@172.22.27.137:5062 hanging up, cause: NORMAL_CLEARING 2017-03-22 11:56:10.973121 [DEBUG] mod_sofia.c:558 Sending BYE to sofia/internal/sip:5536@172.22.27.137:5062 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:48 sofia/internal/sip:5536@172.22.27.137:5062 Standard HANGUP, cause: NORMAL_CLEARING 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:683 (sofia/internal/sip:5536@172.22.27.137:5062) State HANGUP going to sleep 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:484 (sofia/internal/sip:5536@172.22.27.137:5062) State EXCHANGE_MEDIA going to sleep 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:418 (sofia/internal/sip:5536@172.22.27.137:5062) Running State Change CS_HANGUP 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:450 (sofia/internal/sip:5536@172.22.27.137:5062) State Change CS_HANGUP -> CS_REPORTING 2017-03-22 11:56:10.973121 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:418 (sofia/internal/sip:5536@172.22.27.137:5062) Running State Change CS_REPORTING 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:767 (sofia/internal/sip:5536@172.22.27.137:5062) State REPORTING 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:92 sofia/internal/sip:5536@172.22.27.137:5062 Standard REPORTING, cause: NORMAL_CLEARING 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:767 (sofia/internal/sip:5536@172.22.27.137:5062) State REPORTING going to sleep 2017-03-22 11:56:10.973121 [DEBUG] switch_core_state_machine.c:444 (sofia/internal/sip:5536@172.22.27.137:5062) State Change CS_REPORTING -> CS_DESTROY 2017-03-22 11:56:10.973121 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:10.973121 [DEBUG] switch_core_session.c:1559 Session 717 (sofia/internal/sip:5536@172.22.27.137:5062) Locked, Waiting on external entities 2017-03-22 11:56:10.993102 [DEBUG] switch_ivr_bridge.c:645 BRIDGE THREAD DONE [sofia/internal/8911@insiel.fvgvoipcoll.it] 2017-03-22 11:56:10.993102 [DEBUG] switch_ivr_bridge.c:675 Send signal sofia/internal/sip:5536@172.22.27.137:5062 [BREAK] 2017-03-22 11:56:10.993102 [DEBUG] switch_core_session.c:871 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:10.993102 [DEBUG] switch_cpp.cpp:670 CoreSession::hangup 2017-03-22 11:56:10.993102 [NOTICE] switch_cpp.cpp:672 Hangup sofia/internal/8911@insiel.fvgvoipcoll.it [CS_ROUTING] [NORMAL_CLEARING] 2017-03-22 11:56:10.993102 [DEBUG] switch_channel.c:3189 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [KILL] 2017-03-22 11:56:10.993102 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:681 (sofia/internal/8911@insiel.fvgvoipcoll.it) Callstate Change ACTIVE -> HANGUP 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:683 (sofia/internal/8911@insiel.fvgvoipcoll.it) State HANGUP 2017-03-22 11:56:10.993102 [DEBUG] mod_sofia.c:506 Channel sofia/internal/8911@insiel.fvgvoipcoll.it hanging up, cause: NORMAL_CLEARING 2017-03-22 11:56:10.993102 [NOTICE] switch_core_session.c:1577 Session 717 (sofia/internal/sip:5536@172.22.27.137:5062) Ended 2017-03-22 11:56:10.993102 [NOTICE] switch_core_session.c:1581 Close Channel sofia/internal/sip:5536@172.22.27.137:5062 [CS_DESTROY] 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:572 (sofia/internal/sip:5536@172.22.27.137:5062) Running State Change CS_DESTROY 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:582 (sofia/internal/sip:5536@172.22.27.137:5062) State DESTROY 2017-03-22 11:56:10.993102 [DEBUG] mod_sofia.c:399 sofia/internal/sip:5536@172.22.27.137:5062 SOFIA DESTROY 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:99 sofia/internal/sip:5536@172.22.27.137:5062 Standard DESTROY 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:582 (sofia/internal/sip:5536@172.22.27.137:5062) State DESTROY going to sleep 2017-03-22 11:56:10.993102 [DEBUG] mod_sofia.c:558 Sending BYE to sofia/internal/8911@insiel.fvgvoipcoll.it send 737 bytes to udp/[172.25.248.82]:5060 at 10:56:11.000090: ------------------------------------------------------------------------ BYE sip:8911@10.200.0.21:65399;ob SIP/2.0 Via: SIP/2.0/UDP 172.25.248.83;rport;branch=z9hG4bKeKF8DycQcrgZK Route: <sip:172.25.248.82;lr;ftag=aT40JNloInEWtNO93asJLx1fr99asBMY;did=e2e.3240d2d1> Max-Forwards: 70 From: <sip:8910@insiel.fvgvoipcoll.it>;tag=0Qmt0F0e2ySpe To: "8911@insiel.fvgvoipcoll.it" <sip:8911@insiel.fvgvoipcoll.it>;tag=aT40JNloInEWtNO93asJLx1fr99asBMY Call-ID: i2cuGU.0L-OgWpqyHD9302-wfE3Nqgaq CSeq: 104754021 BYE Contact: <sip:8910@172.25.248.83:5060;transport=udp> User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140910T073219Z~bbe2531cb0~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Content-Length: 0 ------------------------------------------------------------------------ 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:48 sofia/internal/8911@insiel.fvgvoipcoll.it Standard HANGUP, cause: NORMAL_CLEARING 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:683 (sofia/internal/8911@insiel.fvgvoipcoll.it) State HANGUP going to sleep 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:614 Hangup Command with no Session luarun(functions/clean_pickup.lua 9e982efc-42c4-489c-9fef-012a443fbd4a): +OK 2017-03-22 11:56:10.993102 [DEBUG] freeswitch_lua.cpp:377 DBH handle 0x17b5b20 released. 2017-03-22 11:56:10.993102 [DEBUG] switch_cpp.cpp:1051 sofia/internal/8911@insiel.fvgvoipcoll.it destroy/unlink session from object 2017-03-22 11:56:10.993102 [DEBUG] switch_core_session.c:2822 sofia/internal/8911@insiel.fvgvoipcoll.it skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already) 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:481 (sofia/internal/8911@insiel.fvgvoipcoll.it) State EXECUTE going to sleep 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:418 (sofia/internal/8911@insiel.fvgvoipcoll.it) Running State Change CS_HANGUP 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:450 (sofia/internal/8911@insiel.fvgvoipcoll.it) State Change CS_HANGUP -> CS_REPORTING 2017-03-22 11:56:10.993102 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:418 (sofia/internal/8911@insiel.fvgvoipcoll.it) Running State Change CS_REPORTING 2017-03-22 11:56:10.993102 [DEBUG] switch_core_state_machine.c:767 (sofia/internal/8911@insiel.fvgvoipcoll.it) State REPORTING 2017-03-22 11:56:10.993102 [INFO] switch_cpp.cpp:1288 @@@@@@@@@@@@@@@@@@@@@@@ clean_pickup.lua 2017-03-22 11:56:10.993102 [DEBUG] freeswitch_lua.cpp:360 DBH handle 0x1768f10 Connected. 2017-03-22 11:56:10.993102 [DEBUG] freeswitch_lua.cpp:377 DBH handle 0x1768f10 released. recv 358 bytes from udp/[172.25.248.82]:5060 at 10:56:11.024086: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.25.248.83;rport=5060;received=172.25.248.83;branch=z9hG4bKeKF8DycQcrgZK Call-ID: i2cuGU.0L-OgWpqyHD9302-wfE3Nqgaq From: <sip:8910@insiel.fvgvoipcoll.it>;tag=0Qmt0F0e2ySpe To: "8911@insiel.fvgvoipcoll.it" <sip:8911@insiel.fvgvoipcoll.it>;tag=aT40JNloInEWtNO93asJLx1fr99asBMY CSeq: 104754021 BYE Content-Length: 0 ------------------------------------------------------------------------ 2017-03-22 11:56:11.033093 [DEBUG] switch_core_state_machine.c:92 sofia/internal/8911@insiel.fvgvoipcoll.it Standard REPORTING, cause: NORMAL_CLEARING 2017-03-22 11:56:11.033093 [DEBUG] switch_core_state_machine.c:767 (sofia/internal/8911@insiel.fvgvoipcoll.it) State REPORTING going to sleep 2017-03-22 11:56:11.033093 [DEBUG] switch_core_state_machine.c:444 (sofia/internal/8911@insiel.fvgvoipcoll.it) State Change CS_REPORTING -> CS_DESTROY 2017-03-22 11:56:11.033093 [DEBUG] switch_core_session.c:1351 Send signal sofia/internal/8911@insiel.fvgvoipcoll.it [BREAK] 2017-03-22 11:56:11.033093 [DEBUG] switch_core_session.c:1559 Session 715 (sofia/internal/8911@insiel.fvgvoipcoll.it) Locked, Waiting on external entities 2017-03-22 11:56:11.033093 [NOTICE] switch_core_session.c:1577 Session 715 (sofia/internal/8911@insiel.fvgvoipcoll.it) Ended 2017-03-22 11:56:11.033093 [NOTICE] switch_core_session.c:1581 Close Channel sofia/internal/8911@insiel.fvgvoipcoll.it [CS_DESTROY] 2017-03-22 11:56:11.033093 [DEBUG] switch_core_state_machine.c:572 (sofia/internal/8911@insiel.fvgvoipcoll.it) Running State Change CS_DESTROY 2017-03-22 11:56:11.033093 [DEBUG] switch_core_state_machine.c:582 (sofia/internal/8911@insiel.fvgvoipcoll.it) State DESTROY 2017-03-22 11:56:11.033093 [DEBUG] mod_sofia.c:399 sofia/internal/8911@insiel.fvgvoipcoll.it SOFIA DESTROY 2017-03-22 11:56:11.033093 [DEBUG] switch_core_state_machine.c:99 sofia/internal/8911@insiel.fvgvoipcoll.it Standard DESTROY 2017-03-22 11:56:11.033093 [DEBUG] switch_core_state_machine.c:582 (sofia/internal/8911@insiel.fvgvoipcoll.it) State DESTROY going to sleep recv 397 bytes from udp/[172.25.248.82]:5060 at 10:56:11.078961: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.25.248.83;received=172.25.248.83;rport=5060;branch=z9hG4bKDapFc3UKFFtcr From: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c To: <sip:5536@172.22.27.137:5062>;tag=507421845 Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754017 NOTIFY Contact: <sip:5536@172.22.27.137:5062> User-Agent: Yealink SIP-T21P 34.72.0.75 Content-Length: 0 ------------------------------------------------------------------------ send 710 bytes to udp/[172.25.248.82]:5060 at 10:56:11.079572: ------------------------------------------------------------------------ BYE sip:5536@172.22.27.137:5062 SIP/2.0 Via: SIP/2.0/UDP 172.25.248.83;rport;branch=z9hG4bKFv80FSXt906HF Route: <sip:172.25.248.82;lr;ftag=4USX7U3vp2j1c;did=51d.6c2982e6> Max-Forwards: 70 From: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c To: <sip:5536@172.22.27.137:5062>;tag=507421845 Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754018 BYE Contact: <sip:mod_sofia@172.25.248.83:5060> User-Agent: FreeSWITCH-mod_sofia/1.2.24+git~20140910T073219Z~bbe2531cb0~64bit Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE Supported: timer, path, replaces Reason: Q.850;cause=16;text="NORMAL_CLEARING" Content-Length: 0 ------------------------------------------------------------------------ recv 476 bytes from udp/[172.25.248.82]:5060 at 10:56:11.082051: ------------------------------------------------------------------------ BYE sip:mod_sofia@172.25.248.83:5060 SIP/2.0 Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bK871e.65384514.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK384278620 From: <sip:5536@172.22.27.137:5062>;tag=507421845 To: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754018 BYE Contact: <sip:5536@172.22.27.137:5062> Max-Forwards: 69 User-Agent: Yealink SIP-T21P 34.72.0.75 Content-Length: 0 ------------------------------------------------------------------------ recv 354 bytes from udp/[172.25.248.82]:5060 at 10:56:11.117925: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.25.248.83;received=172.25.248.83;rport=5060;branch=z9hG4bKFv80FSXt906HF From: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c To: <sip:5536@172.22.27.137:5062>;tag=507421845 Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754018 BYE User-Agent: Yealink SIP-T21P 34.72.0.75 Content-Length: 0 ------------------------------------------------------------------------ send 347 bytes to udp/[172.25.248.82]:5060 at 10:56:11.118238: ------------------------------------------------------------------------ SIP/2.0 200 OK Via: SIP/2.0/UDP 172.25.248.82:5060;branch=z9hG4bK871e.65384514.0 Via: SIP/2.0/UDP 172.22.27.137:5062;branch=z9hG4bK384278620 From: <sip:5536@172.22.27.137:5062>;tag=507421845 To: "8911" <sip:8911@insiel.fvgvoipcoll.it>;tag=4USX7U3vp2j1c Call-ID: f9313c57-8990-1235-e48f-005056886d47 CSeq: 104754018 BYE Content-Length: 0