[Freeswitch-users] Playback file stopping abruptly from freeswitch 1.10.5 and onwards

Wed Feb 2 13:21:37 UTC 2022

Hi All,

Recently we have moved from freeswitch 1.10.3 to 1.10.5. and we
observed that while executing the following command through ESL
Command Execute playback(random.wav)
freeswitch is stopping the playback earlier than the file playback
duration.In this setup  we are using freeswitch to generate the call
as well. Our setup looks similar to this.

Freeswitch_1------>opensips------>Freeswitch_2

Freeswitch_1: a) Originate and park b) playback some file on park
(Using command though ESL)
Freeswitch_2: a) playback some file on park  (Using command though ESL)

In Attached logs freeswitch has stopped the playback after 3 seconds
but the file is of 10 seconds.

But in another scenario where  we replace the freeswitch_1 with a
manual call using a softphone, Freeswitch_2 plays the file for the
whole 10 seconds.

Please let me know if anyone has faced the same issue or any insight
regarding it. We observed the same issue with 1.10.7 but working fine
in our old 1.10.3 setup.

Thanks & Regards,
Shahnawaj
-------------- next part --------------
2021-10-20 12:18:03.036893 [DEBUG] switch_ivr_originate.c:2242 Parsing global variables
2021-10-20 12:18:03.036893 [NOTICE] switch_channel.c:1118 New Channel sofia/3clogic_external/009911 at randomdomain.com:5507 [c5d6f887-319f-11ec-bf87-0265fdb72ff7]
2021-10-20 12:18:03.036893 [DEBUG] mod_sofia.c:5089 (sofia/3clogic_external/009911 at randomdomain.com:5507) State Change CS_NEW -> CS_INIT
2021-10-20 12:18:03.036893 [DEBUG] switch_core_session.c:641 sofia/3clogic_external/009911 at randomdomain.com:5507 set UUID=c5d6f887-319f-11ec-bf87-0265fdb72ff7
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:585 (sofia/3clogic_external/009911 at randomdomain.com:5507) Running State Change CS_INIT (Cur 1 Tot 6)
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:628 (sofia/3clogic_external/009911 at randomdomain.com:5507) State INIT
2021-10-20 12:18:03.036893 [DEBUG] mod_sofia.c:93 sofia/3clogic_external/009911 at randomdomain.com:5507 SOFIA INIT
2021-10-20 12:18:03.036893 [DEBUG] sofia_glue.c:1618 sofia/3clogic_external/009911 at randomdomain.com:5507 sending invite version: 1.10.5-release git 25569c1 2020-08-18 18:51:21Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1634702247 1634702248 IN IP4 X.X.X.X
s=FreeSWITCH
c=IN IP4 X.X.X.X
t=0 0
m=audio 30036 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
a=sendrecv

2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:40 sofia/3clogic_external/009911 at randomdomain.com:5507 Standard INIT
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:48 (sofia/3clogic_external/009911 at randomdomain.com:5507) State Change CS_INIT -> CS_ROUTING
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:628 (sofia/3clogic_external/009911 at randomdomain.com:5507) State INIT going to sleep
send 1053 bytes to udp/[X.X.X.X]:5507 at 12:18:03.041869:
------------------------------------------------------------------------
INVITE sip:009911 at randomdomain.com:5507 SIP/2.0
Via: SIP/2.0/UDP X.X.X.X:5080;rport;branch=z9hG4bKvp1p031Krm5Za
Max-Forwards: 70
From: <sip:test23 at X.X.X.X>;tag=jeK6trDeyj31g
To: <sip:009911 at randomdomain.com:5507>
Call-ID: 9d356e34-ac42-123a-0fa2-0265fdb72ff7
CSeq: 42812349 INVITE
Contact: <sip:mod_sofia at X.X.X.X:5080>
User-Agent: FreeSWITCH-mod_sofia/1.10.5-release+git~20200818T185121Z~25569c1631~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 220
X-FS-Support: update_display,send_info
Remote-Party-ID: <sip:test23 at X.X.X.X>;party=calling;screen=yes;privacy=off

v=0
o=FreeSWITCH 1634702247 1634702248 IN IP4 X.X.X.X
s=FreeSWITCH
c=IN IP4 X.X.X.X
t=0 0
m=audio 30036 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:585 (sofia/3clogic_external/009911 at randomdomain.com:5507) Running State Change CS_ROUTING (Cur 1 Tot 6)
2021-10-20 12:18:03.036893 [DEBUG] sofia.c:7326 Channel sofia/3clogic_external/009911 at randomdomain.com:5507 entering state [calling][0]
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:644 (sofia/3clogic_external/009911 at randomdomain.com:5507) State ROUTING
2021-10-20 12:18:03.036893 [DEBUG] mod_sofia.c:154 sofia/3clogic_external/009911 at randomdomain.com:5507 SOFIA ROUTING
2021-10-20 12:18:03.036893 [DEBUG] switch_ivr_originate.c:67 (sofia/3clogic_external/009911 at randomdomain.com:5507) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:644 (sofia/3clogic_external/009911 at randomdomain.com:5507) State ROUTING going to sleep
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:585 (sofia/3clogic_external/009911 at randomdomain.com:5507) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 6)
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:663 (sofia/3clogic_external/009911 at randomdomain.com:5507) State CONSUME_MEDIA
2021-10-20 12:18:03.036893 [DEBUG] switch_core_state_machine.c:663 (sofia/3clogic_external/009911 at randomdomain.com:5507) State CONSUME_MEDIA going to sleep
recv 361 bytes from udp/[X.X.X.X]:5507 at 12:18:03.042319:
------------------------------------------------------------------------
SIP/2.0 100 Giving a try
Via: SIP/2.0/UDP X.X.X.X:5080;received=X.X.X.X;rport=5080;branch=z9hG4bKvp1p031Krm5Za
From: <sip:test23 at X.X.X.X>;tag=jeK6trDeyj31g
To: <sip:009911 at randomdomain.com:5507>
Call-ID: 9d356e34-ac42-123a-0fa2-0265fdb72ff7
CSeq: 42812349 INVITE
Server: OpenSIPS (2.2.4 (x86_64/linux))
Content-Length: 0

recv 1353 bytes from udp/[X.X.X.X]:5507 at 12:18:03.047406:
------------------------------------------------------------------------
SIP/2.0 183 Session Progress
Via: SIP/2.0/UDP X.X.X.X:5080;received=X.X.X.X;rport=5080;branch=z9hG4bKvp1p031Krm5Za
Record-Route: <sip:X.X.X.X:5507;lr;ftag=jeK6trDeyj31g;did=c7d.dd62d71>
Record-Route: <sip:X.X.X.X:5507;lr;ftag=jeK6trDeyj31g;did=c7d.1c418d3>
From: <sip:test23 at X.X.X.X>;tag=jeK6trDeyj31g
To: <sip:009911 at randomdomain.com:5507>;tag=Z8aHy6Xjc6jBe
Call-ID: 9d356e34-ac42-123a-0fa2-0265fdb72ff7
CSeq: 42812349 INVITE
Contact: <sip:009911 at X.X.X.X:5080;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.10.5-release+git~20200818T185121Z~25569c1631~64bit
Accept: application/sdp
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 218
X-FS-Display-Name: 009911
X-FS-Display-Number: sip:009911 at randomdomain.com
X-FS-Support: update_display,send_info
Remote-Party-ID: "009911" <sip:009911 at randomdomain.com>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1634701115 1634701116 IN IP4 X.X.X.X
s=FreeSWITCH
c=IN IP4 X.X.X.X
t=0 0
m=audio 31168 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
2021-10-20 12:18:03.036893 [INFO] sofia.c:1369 sofia/3clogic_external/009911 at randomdomain.com:5507 Update Callee ID to "009911" <sip:009911 at randomdomain.com>
2021-10-20 12:18:03.036893 [DEBUG] sofia.c:7326 Channel sofia/3clogic_external/009911 at randomdomain.com:5507 entering state [proceeding][183]
2021-10-20 12:18:03.036893 [DEBUG] sofia.c:7336 Remote SDP:
v=0
o=FreeSWITCH 1634701115 1634701116 IN IP4 X.X.X.X
s=FreeSWITCH
c=IN IP4 X.X.X.X
t=0 0
m=audio 31168 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

2021-10-20 12:18:03.036893 [NOTICE] sofia.c:7339 Pre-Answer sofia/3clogic_external/009911 at randomdomain.com:5507!
2021-10-20 12:18:03.036893 [DEBUG] switch_channel.c:3565 (sofia/3clogic_external/009911 at randomdomain.com:5507) Callstate Change DOWN -> EARLY
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:5594 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:5649 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:5510 Set telephone-event payload to 101 at 8000
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:3839 Set Codec sofia/3clogic_external/009911 at randomdomain.com:5507 PCMU/8000 20 ms 160 samples 64000 bits 1 channels
2021-10-20 12:18:03.036893 [DEBUG] switch_core_codec.c:111 sofia/3clogic_external/009911 at randomdomain.com:5507 Original read codec set to PCMU:0
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:5853 Set telephone-event payload to 101 at 8000
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:5911 sofia/3clogic_external/009911 at randomdomain.com:5507 Set 2833 dtmf send payload to 101 recv payload to 101
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:8663 AUDIO RTP [sofia/3clogic_external/009911 at randomdomain.com:5507] 20.1.155.222 port 30036 -> X.X.X.X port 31168 codec: 0 ms: 20
2021-10-20 12:18:03.036893 [DEBUG] switch_rtp.c:4472 Not using a timer
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:2554 Setting Jitterbuffer to 60ms (3 frames) (150 max frames)
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:8977 sofia/3clogic_external/009911 at randomdomain.com:5507 Set 2833 dtmf send payload to 101
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:8984 sofia/3clogic_external/009911 at randomdomain.com:5507 Set 2833 dtmf receive payload to 101
2021-10-20 12:18:03.036893 [DEBUG] switch_core_media.c:9007 sofia/3clogic_external/009911 at randomdomain.com:5507 Set rtp dtmf delay to 40
2021-10-20 12:18:03.056895 [DEBUG] switch_ivr_originate.c:3852 Originate Resulted in Success: [sofia/3clogic_external/009911 at randomdomain.com:5507]
2021-10-20 12:18:03.056895 [INFO] switch_channel.c:3213 sofia/3clogic_external/009911 at randomdomain.com:5507 Flipping CID from "" <test23> to "009911" <009911>
2021-10-20 12:18:03.056895 [DEBUG] mod_commands.c:5094 (sofia/3clogic_external/009911 at randomdomain.com:5507) State Change CS_CONSUME_MEDIA -> CS_EXECUTE
2021-10-20 12:18:03.056895 [DEBUG] switch_core_state_machine.c:585 (sofia/3clogic_external/009911 at randomdomain.com:5507) Running State Change CS_EXECUTE (Cur 1 Tot 6)
2021-10-20 12:18:03.056895 [DEBUG] switch_core_state_machine.c:651 (sofia/3clogic_external/009911 at randomdomain.com:5507) State EXECUTE
2021-10-20 12:18:03.056895 [DEBUG] mod_sofia.c:209 sofia/3clogic_external/009911 at randomdomain.com:5507 SOFIA EXECUTE
2021-10-20 12:18:03.056895 [DEBUG] switch_core_state_machine.c:329 sofia/3clogic_external/009911 at randomdomain.com:5507 Standard EXECUTE
EXECUTE [depth=0] sofia/3clogic_external/009911 at randomdomain.com:5507 park()
2021-10-20 12:18:03.076894 [DEBUG] switch_ivr.c:632 sofia/3clogic_external/009911 at randomdomain.com:5507 Command Execute [depth=1] set(parent_verb=1)
EXECUTE [depth=1] sofia/3clogic_external/009911 at randomdomain.com:5507 set(parent_verb=1)
2021-10-20 12:18:03.076894 [DEBUG] mod_dptools.c:1672 SET sofia/3clogic_external/009911 at randomdomain.com:5507 [parent_verb]=[1]
2021-10-20 12:18:03.076894 [DEBUG] switch_ivr.c:632 sofia/3clogic_external/009911 at randomdomain.com:5507 Command Execute [depth=1] set(playback_terminators=none)
EXECUTE [depth=1] sofia/3clogic_external/009911 at randomdomain.com:5507 set(playback_terminators=none)
2021-10-20 12:18:03.076894 [DEBUG] mod_dptools.c:1672 SET sofia/3clogic_external/009911 at randomdomain.com:5507 [playback_terminators]=[none]
2021-10-20 12:18:03.076894 [DEBUG] switch_ivr.c:632 sofia/3clogic_external/009911 at randomdomain.com:5507 Command Execute [depth=1] set(queue_id=c5dabd54-319f-11ec-bf87-0265fdb72ff7)
EXECUTE [depth=1] sofia/3clogic_external/009911 at randomdomain.com:5507 set(queue_id=c5dabd54-319f-11ec-bf87-0265fdb72ff7)
2021-10-20 12:18:03.076894 [DEBUG] mod_dptools.c:1672 SET sofia/3clogic_external/009911 at randomdomain.com:5507 [queue_id]=[c5dabd54-319f-11ec-bf87-0265fdb72ff7]
2021-10-20 12:18:03.076894 [DEBUG] switch_ivr.c:632 sofia/3clogic_external/009911 at randomdomain.com:5507 Command Execute [depth=1] playback(random.wav)
EXECUTE [depth=1] sofia/3clogic_external/009911 at randomdomain.com:5507 playback(random.wav)
2021-10-20 12:18:03.076894 [WARNING] switch_core_file.c:424 File has 2 channels, muxing to 1 channel will occur.
2021-10-20 12:18:03.076894 [DEBUG] switch_ivr_play_say.c:1488 Codec Activated L16 at 8000hz 1 channels 20ms
recv 1314 bytes from udp/[X.X.X.X]:5507 at 12:18:03.450121:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP X.X.X.X:5080;received=X.X.X.X;rport=5080;branch=z9hG4bKvp1p031Krm5Za
Record-Route: <sip:X.X.X.X:5507;lr;ftag=jeK6trDeyj31g;did=c7d.dd62d71>
Record-Route: <sip:X.X.X.X:5507;lr;ftag=jeK6trDeyj31g;did=c7d.1c418d3>
From: <sip:test23 at X.X.X.X>;tag=jeK6trDeyj31g
To: <sip:009911 at randomdomain.com:5507>;tag=Z8aHy6Xjc6jBe
Call-ID: 9d356e34-ac42-123a-0fa2-0265fdb72ff7
CSeq: 42812349 INVITE
Contact: <sip:009911 at X.X.X.X:5080;transport=udp>
User-Agent: FreeSWITCH-mod_sofia/1.10.5-release+git~20200818T185121Z~25569c1631~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Allow-Events: talk, hold, conference, refer
Content-Type: application/sdp
Content-Disposition: session
Content-Length: 218
X-FS-Display-Name: 009911
X-FS-Display-Number: sip:009911 at randomdomain.com
X-FS-Support: update_display,send_info
Remote-Party-ID: "009911" <sip:009911 at randomdomain.com>;party=calling;privacy=off;screen=no

v=0
o=FreeSWITCH 1634701115 1634701116 IN IP4 X.X.X.X
s=FreeSWITCH
c=IN IP4 X.X.X.X
t=0 0
m=audio 31168 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20
2021-10-20 12:18:03.436893 [INFO] sofia.c:1358 sofia/3clogic_external/009911 at randomdomain.com:5507 Update Caller ID to "009911" <sip:009911 at randomdomain.com>
2021-10-20 12:18:03.436893 [DEBUG] sofia.c:7326 Channel sofia/3clogic_external/009911 at randomdomain.com:5507 entering state [completing][200]
2021-10-20 12:18:03.436893 [DEBUG] sofia.c:7333 Duplicate SDP
v=0
o=FreeSWITCH 1634701115 1634701116 IN IP4 X.X.X.X
s=FreeSWITCH
c=IN IP4 X.X.X.X
t=0 0
m=audio 31168 RTP/AVP 0 101
a=rtpmap:0 PCMU/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-16
a=ptime:20

send 540 bytes to udp/[X.X.X.X]:5507 at 12:18:03.450901:
------------------------------------------------------------------------
ACK sip:009911 at X.X.X.X:5080;transport=udp SIP/2.0
Via: SIP/2.0/UDP X.X.X.X:5080;rport;branch=z9hG4bKXZtF2yjQNXUjp
Route: <sip:X.X.X.X:5507;lr;ftag=jeK6trDeyj31g;did=c7d.1c418d3>
Route: <sip:X.X.X.X:5507;lr;ftag=jeK6trDeyj31g;did=c7d.dd62d71>
Max-Forwards: 70
From: <sip:test23 at X.X.X.X>;tag=jeK6trDeyj31g
To: <sip:009911 at randomdomain.com:5507>;tag=Z8aHy6Xjc6jBe
Call-ID: 9d356e34-ac42-123a-0fa2-0265fdb72ff7
CSeq: 42812349 ACK
Contact: <sip:mod_sofia at X.X.X.X:5080>
Content-Length: 0

2021-10-20 12:18:03.436893 [DEBUG] sofia.c:7326 Channel sofia/3clogic_external/009911 at randomdomain.com:5507 entering state [ready][200]
2021-10-20 12:18:03.436893 [NOTICE] sofia.c:8445 Channel [sofia/3clogic_external/009911 at randomdomain.com:5507] has been answered
2021-10-20 12:18:03.436893 [DEBUG] switch_channel.c:3865 (sofia/3clogic_external/009911 at randomdomain.com:5507) Callstate Change EARLY -> ACTIVE
2021-10-20 12:18:05.936893 [DEBUG] switch_rtp.c:7759 Correct audio ip/port confirmed.
2021-10-20 12:18:06.036893 [DEBUG] switch_ivr_play_say.c:1933 done playing file random.wav
2021-10-20 12:18:06.416892 [DEBUG] switch_ivr.c:632 sofia/3clogic_external/009911 at randomdomain.com:5507 Command Execute [depth=1] hangup(Queue is Empty)
EXECUTE [depth=1] sofia/3clogic_external/009911 at randomdomain.com:5507 hangup(Queue is Empty)
2021-10-20 12:18:06.416892 [NOTICE] mod_dptools.c:1380 Hangup sofia/3clogic_external/009911 at randomdomain.com:5507 [CS_EXECUTE] [NORMAL_CLEARING]
2021-10-20 12:18:06.416892 [DEBUG] switch_core_session.c:2905 sofia/3clogic_external/009911 at randomdomain.com:5507 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2021-10-20 12:18:06.416892 [DEBUG] switch_core_session.c:2905 sofia/3clogic_external/009911 at randomdomain.com:5507 skip receive message [APPLICATION_EXEC_COMPLETE] (channel is hungup already)
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:651 (sofia/3clogic_external/009911 at randomdomain.com:5507) State EXECUTE going to sleep
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:585 (sofia/3clogic_external/009911 at randomdomain.com:5507) Running State Change CS_HANGUP (Cur 1 Tot 6)
2021-10-20 12:18:06.416892 [DEBUG] switch_ivr.c:679 sofia/3clogic_external/009911 at randomdomain.com:5507 skip receive message [AUDIO_SYNC] (channel is hungup already)
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:848 (sofia/3clogic_external/009911 at randomdomain.com:5507) Callstate Change ACTIVE -> HANGUP
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:850 (sofia/3clogic_external/009911 at randomdomain.com:5507) State HANGUP
2021-10-20 12:18:06.416892 [DEBUG] mod_sofia.c:453 Channel sofia/3clogic_external/009911 at randomdomain.com:5507 hanging up, cause: NORMAL_CLEARING
2021-10-20 12:18:06.416892 [DEBUG] mod_sofia.c:507 Sending BYE to sofia/3clogic_external/009911 at randomdomain.com:5507
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:60 sofia/3clogic_external/009911 at randomdomain.com:5507 Standard HANGUP, cause: NORMAL_CLEARING
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:850 (sofia/3clogic_external/009911 at randomdomain.com:5507) State HANGUP going to sleep
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:620 (sofia/3clogic_external/009911 at randomdomain.com:5507) State Change CS_HANGUP -> CS_REPORTING
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:585 (sofia/3clogic_external/009911 at randomdomain.com:5507) Running State Change CS_REPORTING (Cur 1 Tot 6)
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:936 (sofia/3clogic_external/009911 at randomdomain.com:5507) State REPORTING
send 754 bytes to udp/[X.X.X.X]:5507 at 12:18:06.432892:
------------------------------------------------------------------------
BYE sip:009911 at X.X.X.X:5080;transport=udp SIP/2.0
Via: SIP/2.0/UDP X.X.X.X:5080;rport;branch=z9hG4bKy8K83S3tj6H5H
Route: <sip:X.X.X.X:5507;lr;ftag=jeK6trDeyj31g;did=c7d.1c418d3>
Route: <sip:X.X.X.X:5507;lr;ftag=jeK6trDeyj31g;did=c7d.dd62d71>
Max-Forwards: 70
From: <sip:test23 at X.X.X.X>;tag=jeK6trDeyj31g
To: <sip:009911 at randomdomain.com:5507>;tag=Z8aHy6Xjc6jBe
Call-ID: 9d356e34-ac42-123a-0fa2-0265fdb72ff7
CSeq: 42812350 BYE
User-Agent: FreeSWITCH-mod_sofia/1.10.5-release+git~20200818T185121Z~25569c1631~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Reason: Q.850;cause=16;text="NORMAL_CLEARING"
Content-Length: 0

2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:174 sofia/3clogic_external/009911 at randomdomain.com:5507 Standard REPORTING, cause: NORMAL_CLEARING
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:936 (sofia/3clogic_external/009911 at randomdomain.com:5507) State REPORTING going to sleep
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:611 (sofia/3clogic_external/009911 at randomdomain.com:5507) State Change CS_REPORTING -> CS_DESTROY
2021-10-20 12:18:06.416892 [DEBUG] switch_core_session.c:1726 Session 6 (sofia/3clogic_external/009911 at randomdomain.com:5507) Locked, Waiting on external entities
2021-10-20 12:18:06.416892 [NOTICE] switch_core_session.c:1744 Session 6 (sofia/3clogic_external/009911 at randomdomain.com:5507) Ended
2021-10-20 12:18:06.416892 [NOTICE] switch_core_session.c:1748 Close Channel sofia/3clogic_external/009911 at randomdomain.com:5507 [CS_DESTROY]
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:739 (sofia/3clogic_external/009911 at randomdomain.com:5507) Running State Change CS_DESTROY (Cur 0 Tot 6)
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:749 (sofia/3clogic_external/009911 at randomdomain.com:5507) State DESTROY
2021-10-20 12:18:06.416892 [DEBUG] mod_sofia.c:364 sofia/3clogic_external/009911 at randomdomain.com:5507 SOFIA DESTROY
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:181 sofia/3clogic_external/009911 at randomdomain.com:5507 Standard DESTROY
2021-10-20 12:18:06.416892 [DEBUG] switch_core_state_machine.c:749 (sofia/3clogic_external/009911 at randomdomain.com:5507) State DESTROY going to sleep
recv 536 bytes from udp/[X.X.X.X]:5507 at 12:18:06.454758:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP X.X.X.X:5080;received=X.X.X.X;rport=5080;branch=z9hG4bKy8K83S3tj6H5H
From: <sip:test23 at X.X.X.X>;tag=jeK6trDeyj31g
To: <sip:009911 at randomdomain.com:5507>;tag=Z8aHy6Xjc6jBe
Call-ID: 9d356e34-ac42-123a-0fa2-0265fdb72ff7
CSeq: 42812350 BYE
User-Agent: FreeSWITCH-mod_sofia/1.10.5-release+git~20200818T185121Z~25569c1631~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY
Supported: timer, path, replaces
Content-Length: 0