Skip to content

480 Temporarily Unavailable from second leg is not propagated to originating leg (first leg remains in limbo) #2962

New issue
New issue
Open
Open
480 Temporarily Unavailable from second leg is not propagated to originating leg (first leg remains in limbo)#2962
Labels
bugSomething isn't working
@rakesh-voiger

Description

@rakesh-voiger
rakesh-voiger
opened on Dec 6, 2025

When the B-leg (external gateway) returns a SIP 480 Temporarily Unavailable, FreeSWITCH does not propagate this failure back to the originating A-leg. Instead, only the B-leg hangs up while the A-leg remains active in a “limbo” state until it eventually times out due to missing media.

To Reproduce

  • Register a SIP client to a Sofia profile.
  • Place an outbound call from the client.
  • In the dialplan, bridge the call to an external gateway, e.g.:
<action application="set" data="hangup_after_bridge=true"/>
<action application="bridge" data="sofia/gateway/<gateway>/<number>"/>
  • Have the external gateway return a 480 response.

Expected Behavior:
When the gateway sends a 480, FreeSWITCH should:

  • Immediately hang up the B-leg and
  • Propagate the same or mapped failure back to the A-leg
  • Result in the caller receiving a hangup event (e.g., 480 or mapped cause)
  • End both channels cleanly

Actual Behavior

  • B-leg hangs up normally with cause 480.
  • A-leg stays active and becomes stuck in a limbo state (no media).
  • Eventually the A-leg hangs up only because of media timeout, not because of the received SIP failure.
  • The caller receives no hangup signal at the moment of the 480.

It works totally fine on other statuses like 486 Busy.

Package version

  • Version 1.10.12

❌ Bad Case
480 is not propagated to the caller; A-leg remains active.
ℹ️ Notice here, the 480 or any other status of hangup is not sent to the caller. The client had to later cancel the call.
Image

✅ Good Case
486 propagates correctly and A-leg hangs up immediately.
ℹ️ Notice here, hangup is sent to the caller thus first channel is ended as well.
Image

Log lines

2025-12-06 16:53:15.155855 98.40% [NOTICE] switch_channel.c:1142 New Channel sofia/internal/9208@ws-self [2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.155855 98.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/9208@ws-self) Running State Change CS_NEW (Cur 1 Tot 25)
2025-12-06 16:53:15.155855 98.40% [INFO] sofia.c:10464 sofia/internal/9208@ws-self receiving invite from 172.18.0.4:5065 version: 1.10.12-release git 8ab7fed 2025-12-01 15:23:51Z 64bit call-id: b2nk9tm1l6rdlg68np0m
2025-12-06 16:53:15.155855 98.40% [DEBUG] sofia.c:10558 verifying acl "domains" for ip/port 172.18.0.4:0.
2025-12-06 16:53:15.175664 98.40% [DEBUG] switch_core_state_machine.c:600 (sofia/internal/9208@ws-self) State NEW
2025-12-06 16:53:15.175664 98.40% [DEBUG] sofia.c:2419 detaching session 2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f
2025-12-06 16:53:15.175664 98.40% [DEBUG] sofia.c:2532 Re-attaching to session 2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f
2025-12-06 16:53:15.195703 98.40% [INFO] sofia.c:10464 sofia/internal/9208@ws-self receiving invite from 172.18.0.4:5065 version: 1.10.12-release git 8ab7fed 2025-12-01 15:23:51Z 64bit call-id: b2nk9tm1l6rdlg68np0m
2025-12-06 16:53:15.195703 98.40% [DEBUG] sofia.c:10558 verifying acl "domains" for ip/port 172.18.0.4:0.
2025-12-06 16:53:15.295747 98.40% [DEBUG] sofia.c:7497 Channel sofia/internal/9208@ws-self entering state [received][100]
2025-12-06 16:53:15.295747 98.40% [DEBUG] sofia.c:7507 Remote SDP:
v=0
o=- 8408075020840420268 2 IN IP4 127.0.0.1
s=-
t=0 0
a=group:BUNDLE 0
a=extmap-allow-mixed
a=msid-semantic: WMS 1d511ce8-7b32-45ea-a674-69c59a2fd8f7
m=audio 55866 UDP/TLS/RTP/SAVPF 111 63 9 0 8 13 110 126
c=IN IP4 92.98.195.153
a=rtpmap:111 opus/48000/2
a=fmtp:111 minptime=10;useinbandfec=1
a=rtpmap:63 red/48000/2
a=fmtp:63 111/111
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:13 CN/8000
a=rtpmap:110 telephone-event/48000
a=rtpmap:126 telephone-event/8000
a=rtcp:9 IN IP4 0.0.0.0
a=candidate:3943867384 1 udp 2122194688 192.168.1.10 55866 typ host generation 0 network-id 1 network-cost 10
a=candidate:2884161873 1 udp 1685987072 92.98.195.153 55866 typ srflx raddr 192.168.1.10 rport 55866 generation 0 network-id 1 network-cost 10
a=ice-ufrag:+BaG
a=ice-pwd:fW9NQgoPBOtlMy6++MknSQrt
a=ice-options:trickle
a=fingerprint:sha-256 20:47:BA:63:BB:A2:BF:F0:E2:E9:68:52:80:99:66:B6:06:D0:1A:DC:12:09:29:9D:43:5D:FC:23:C7:10:CC:CB
a=setup:actpass
a=mid:0
a=extmap:1 urn:ietf:params:rtp-hdrext:ssrc-audio-level
a=extmap:2 http://www.webrtc.org/experiments/rtp-hdrext/abs-send-time
a=extmap:3 http://www.ietf.org/id/draft-holmer-rmcat-transport-wide-cc-extensions-01
a=extmap:4 urn:ietf:params:rtp-hdrext:sdes:mid
a=msid:1d511ce8-7b32-45ea-a674-69c59a2fd8f7 e21a654e-dfe7-4fac-a57f-1cf3f412c17e
a=rtcp-mux
a=rtcp-rsize
a=rtcp-fb:111 transport-cc
a=ssrc:2187706315 cname:xLucavL94nnfHYgz
a=ssrc:2187706315 msid:1d511ce8-7b32-45ea-a674-69c59a2fd8f7 e21a654e-dfe7-4fac-a57f-1cf3f412c17e

2025-12-06 16:53:15.295747 98.40% [DEBUG] sofia.c:7910 (sofia/internal/9208@ws-self) State Change CS_NEW -> CS_INIT
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/9208@ws-self) Running State Change CS_INIT (Cur 1 Tot 25)
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/9208@ws-self) State INIT
2025-12-06 16:53:15.295747 98.40% [DEBUG] mod_sofia.c:97 sofia/internal/9208@ws-self SOFIA INIT
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:40 sofia/internal/9208@ws-self Standard INIT
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:48 (sofia/internal/9208@ws-self) State Change CS_INIT -> CS_ROUTING
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:624 (sofia/internal/9208@ws-self) State INIT going to sleep
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/9208@ws-self) Running State Change CS_ROUTING (Cur 1 Tot 25)
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_channel.c:2399 (sofia/internal/9208@ws-self) Callstate Change DOWN -> RINGING
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/9208@ws-self) State ROUTING
2025-12-06 16:53:15.295747 98.40% [DEBUG] mod_sofia.c:158 sofia/internal/9208@ws-self SOFIA ROUTING
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:230 sofia/internal/9208@ws-self Standard ROUTING
2025-12-06 16:53:15.295747 98.40% [INFO] mod_dialplan_xml.c:639 Processing 9208 <9208>->+97350000010 in context default
Dialplan: sofia/internal/9208@ws-self parsing [default->echo] continue=false
Dialplan: sofia/internal/9208@ws-self Regex (FAIL) [echo] destination_number(+97350000010) =~ /^\+?9196$/ break=on-false
Dialplan: sofia/internal/9208@ws-self parsing [default->eavesdrop] continue=false
Dialplan: sofia/internal/9208@ws-self Regex (FAIL) [eavesdrop] destination_number(+97350000010) =~ /^eavesdrop-[0-9a-fA-F-]+$/ break=on-false
Dialplan: sofia/internal/9208@ws-self parsing [default->queue-id] continue=false
Dialplan: sofia/internal/9208@ws-self Regex (FAIL) [queue-id] destination_number(+97350000010) =~ /^queue-[0-9a-fA-F-]+$/ break=on-false
Dialplan: sofia/internal/9208@ws-self parsing [default->agent-id] continue=false
Dialplan: sofia/internal/9208@ws-self Regex (FAIL) [agent-id] destination_number(+97350000010) =~ /^agent-[0-9a-fA-F-]+$/ break=on-false
Dialplan: sofia/internal/9208@ws-self parsing [default->contact-id] continue=false
Dialplan: sofia/internal/9208@ws-self Regex (FAIL) [contact-id] destination_number(+97350000010) =~ /^contact-[0-9a-fA-F-]+$/ break=on-false
Dialplan: sofia/internal/9208@ws-self parsing [default->phone-id] continue=false
Dialplan: sofia/internal/9208@ws-self Regex (FAIL) [phone-id] destination_number(+97350000010) =~ /^phone-[0-9a-fA-F-]+$/ break=on-false
Dialplan: sofia/internal/9208@ws-self parsing [default->outbound] continue=false
Dialplan: sofia/internal/9208@ws-self Regex (PASS) [outbound] destination_number(+97350000010) =~ /^\+\d+$/ break=on-false
Dialplan: sofia/internal/9208@ws-self Action export(core_direction=outbound)
Dialplan: sofia/internal/9208@ws-self Action socket(core:9999 async)
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:281 (sofia/internal/9208@ws-self) State Change CS_ROUTING -> CS_EXECUTE
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:640 (sofia/internal/9208@ws-self) State ROUTING going to sleep
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:581 (sofia/internal/9208@ws-self) Running State Change CS_EXECUTE (Cur 1 Tot 25)
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:647 (sofia/internal/9208@ws-self) State EXECUTE
2025-12-06 16:53:15.295747 98.40% [DEBUG] mod_sofia.c:213 sofia/internal/9208@ws-self SOFIA EXECUTE
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_core_state_machine.c:323 sofia/internal/9208@ws-self Standard EXECUTE
EXECUTE [depth=0] sofia/internal/9208@ws-self export(core_direction=outbound)
2025-12-06 16:53:15.295747 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [core_direction]=[outbound]
EXECUTE [depth=0] sofia/internal/9208@ws-self socket(core:9999 async)
2025-12-06 16:53:15.295747 98.40% [NOTICE] mod_event_socket.c:452 Trying host: core:9999
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=0] export(core_direction=outbound)
EXECUTE [depth=0] sofia/internal/9208@ws-self export(core_direction=outbound)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [core_direction]=[outbound]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_ph_X-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_ph_X-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_ph_X-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_rh_X-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_rh_X-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_rh_X-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_h_X-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_h_X-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_h_X-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(core_call_id=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(core_call_id=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [core_call_id]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_ph_X-Contact-ID=da544727-1dec-44dd-9bec-210f8123fbba)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_ph_X-Contact-ID=da544727-1dec-44dd-9bec-210f8123fbba)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_ph_X-Contact-ID]=[da544727-1dec-44dd-9bec-210f8123fbba]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_rh_X-Contact-ID=da544727-1dec-44dd-9bec-210f8123fbba)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_rh_X-Contact-ID=da544727-1dec-44dd-9bec-210f8123fbba)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_rh_X-Contact-ID]=[da544727-1dec-44dd-9bec-210f8123fbba]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_h_X-Contact-ID=da544727-1dec-44dd-9bec-210f8123fbba)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_h_X-Contact-ID=da544727-1dec-44dd-9bec-210f8123fbba)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_h_X-Contact-ID]=[da544727-1dec-44dd-9bec-210f8123fbba]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(core_contact_id=da544727-1dec-44dd-9bec-210f8123fbba)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(core_contact_id=da544727-1dec-44dd-9bec-210f8123fbba)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [core_contact_id]=[da544727-1dec-44dd-9bec-210f8123fbba]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(core_workspace_code=ws-self)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(core_workspace_code=ws-self)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [core_workspace_code]=[ws-self]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_h_X-Root-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_h_X-Root-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_h_X-Root-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_ph_X-Root-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_ph_X-Root-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_ph_X-Root-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_rh_X-Root-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_rh_X-Root-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_rh_X-Root-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(hangup_after_bridge=true)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(hangup_after_bridge=true)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [hangup_after_bridge]=[true]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(RECORD_STEREO=true)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(RECORD_STEREO=true)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [RECORD_STEREO]=[true]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(execute_on_media_1=export core_recording_path_full=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(execute_on_media_1=export core_recording_path_full=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [execute_on_media_1]=[export core_recording_path_full=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(execute_on_answer_1=export core_recording_path_voice=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/voice.mp3)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(execute_on_answer_1=export core_recording_path_voice=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/voice.mp3)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [execute_on_answer_1]=[export core_recording_path_voice=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/voice.mp3]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(execute_on_media_2=record_session ${shared_dir}/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(execute_on_media_2=record_session /mnt/shared/freeswitch/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [execute_on_media_2]=[record_session /mnt/shared/freeswitch/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(execute_on_answer_2=record_session ${shared_dir}/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/voice.mp3)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(execute_on_answer_2=record_session /mnt/shared/freeswitch/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/voice.mp3)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [execute_on_answer_2]=[record_session /mnt/shared/freeswitch/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/voice.mp3]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_ph_X-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_ph_X-Call-ID=2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_ph_X-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(sip_ph_X-Contact-ID=da544727-1dec-44dd-9bec-210f8123fbba)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(sip_ph_X-Contact-ID=da544727-1dec-44dd-9bec-210f8123fbba)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [sip_ph_X-Contact-ID]=[da544727-1dec-44dd-9bec-210f8123fbba]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] export(core_contact_id=da544727-1dec-44dd-9bec-210f8123fbba)
EXECUTE [depth=1] sofia/internal/9208@ws-self export(core_contact_id=da544727-1dec-44dd-9bec-210f8123fbba)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [core_contact_id]=[da544727-1dec-44dd-9bec-210f8123fbba]
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] callcenter_track(9208@ws-self)
EXECUTE [depth=1] sofia/internal/9208@ws-self callcenter_track(9208@ws-self)
2025-12-06 16:53:15.315716 98.40% [DEBUG] mod_callcenter.c:993 Get Info Agent 9208@ws-self status = Available
2025-12-06 16:53:15.315716 98.40% [DEBUG] mod_callcenter.c:1182 Updated Agent 9208@ws-self set state = In an external call
2025-12-06 16:53:15.315716 98.40% [DEBUG] mod_callcenter.c:3429 Tracking this call for agent 9208@ws-self
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr.c:632 sofia/internal/9208@ws-self Command Execute [depth=1] bridge({sip_from_uri=+97350000009@ws-self,origination_caller_id_number=+97350000009,origination_caller_id_name=}sofia/gateway/default_ws-self/+97350000010)
EXECUTE [depth=1] sofia/internal/9208@ws-self bridge({sip_from_uri=+97350000009@ws-self,origination_caller_id_number=+97350000009,origination_caller_id_name=}sofia/gateway/default_ws-self/+97350000010)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [core_direction]=[outbound] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [core_direction]=[outbound] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_ph_X-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_rh_X-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_h_X-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [core_call_id]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_ph_X-Contact-ID]=[da544727-1dec-44dd-9bec-210f8123fbba] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_rh_X-Contact-ID]=[da544727-1dec-44dd-9bec-210f8123fbba] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_h_X-Contact-ID]=[da544727-1dec-44dd-9bec-210f8123fbba] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [core_contact_id]=[da544727-1dec-44dd-9bec-210f8123fbba] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [core_workspace_code]=[ws-self] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_h_X-Root-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_ph_X-Root-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_rh_X-Root-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [hangup_after_bridge]=[true] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [RECORD_STEREO]=[true] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [execute_on_media_1]=[export core_recording_path_full=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [execute_on_answer_1]=[export core_recording_path_voice=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/voice.mp3] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [execute_on_media_2]=[record_session /mnt/shared/freeswitch/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [execute_on_answer_2]=[record_session /mnt/shared/freeswitch/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/voice.mp3] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_ph_X-Call-ID]=[2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [sip_ph_X-Contact-ID]=[da544727-1dec-44dd-9bec-210f8123fbba] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_channel.c:1288 sofia/internal/9208@ws-self EXPORTING[export_vars] [core_contact_id]=[da544727-1dec-44dd-9bec-210f8123fbba] to event
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr_originate.c:2301 Parsing global variables
2025-12-06 16:53:15.315716 98.40% [NOTICE] switch_channel.c:1142 New Channel sofia/external/+97350000010 [a436821a-dd36-4b52-9259-20a88374d12a]
2025-12-06 16:53:15.315716 98.40% [DEBUG] mod_sofia.c:5110 (sofia/external/+97350000010) State Change CS_NEW -> CS_INIT
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:581 (sofia/external/+97350000010) Running State Change CS_INIT (Cur 2 Tot 26)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:624 (sofia/external/+97350000010) State INIT
2025-12-06 16:53:15.315716 98.40% [DEBUG] mod_sofia.c:97 sofia/external/+97350000010 SOFIA INIT
2025-12-06 16:53:15.315716 98.40% [INFO] sofia_glue.c:1659 sofia/external/+97350000010 sending invite call-id: (null)
2025-12-06 16:53:15.315716 98.40% [DEBUG] sofia_glue.c:1662 sofia/external/+97350000010 sending invite version: 1.10.12-release git 8ab7fed 2025-12-01 15:23:51Z 64bit
Local SDP:
v=0
o=FreeSWITCH 1765007235 1765007236 IN IP4 172.18.0.7
s=FreeSWITCH
c=IN IP4 172.18.0.7
t=0 0
m=audio 32760 RTP/AVP 102 9 0 8 103 101
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40; stereo=1
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-15
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv

2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:40 sofia/external/+97350000010 Standard INIT
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:48 (sofia/external/+97350000010) State Change CS_INIT -> CS_ROUTING
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:624 (sofia/external/+97350000010) State INIT going to sleep
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:581 (sofia/external/+97350000010) Running State Change CS_ROUTING (Cur 2 Tot 26)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:640 (sofia/external/+97350000010) State ROUTING
2025-12-06 16:53:15.315716 98.40% [DEBUG] mod_sofia.c:158 sofia/external/+97350000010 SOFIA ROUTING
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_ivr_originate.c:67 (sofia/external/+97350000010) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:640 (sofia/external/+97350000010) State ROUTING going to sleep
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:581 (sofia/external/+97350000010) Running State Change CS_CONSUME_MEDIA (Cur 2 Tot 26)
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:659 (sofia/external/+97350000010) State CONSUME_MEDIA
2025-12-06 16:53:15.315716 98.40% [DEBUG] switch_core_state_machine.c:659 (sofia/external/+97350000010) State CONSUME_MEDIA going to sleep
2025-12-06 16:53:15.315716 98.40% [DEBUG] sofia.c:7497 Channel sofia/external/+97350000010 entering state [calling][0]
2025-12-06 16:53:16.437264 98.27% [INFO] sofia.c:1348 sofia/external/+97350000010 Update Callee ID to "+97350000010" <sip:+97350000010@carrier>
2025-12-06 16:53:16.437264 98.27% [DEBUG] sofia.c:7497 Channel sofia/external/+97350000010 entering state [proceeding][183]
2025-12-06 16:53:16.437264 98.27% [DEBUG] sofia.c:7507 Remote SDP:
v=0
o=FreeSWITCH 1765007990 1765007991 IN IP4 172.18.0.2
s=FreeSWITCH
c=IN IP4 172.18.0.2
t=0 0
m=audio 32006 RTP/AVP 102 103
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; ptime=20; minptime=10; maxptime=40; stereo=1
a=rtpmap:103 telephone-event/48000
a=fmtp:103 0-15
a=ptime:20

2025-12-06 16:53:16.437264 98.27% [NOTICE] sofia.c:7510 Pre-Answer sofia/external/+97350000010!
EXECUTE [depth=1] sofia/external/+97350000010 export(core_recording_path_full=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3)
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [core_recording_path_full]=[recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3]
EXECUTE [depth=1] sofia/external/+97350000010 record_session(/mnt/shared/freeswitch/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3)
2025-12-06 16:53:16.437264 98.27% [ERR] switch_ivr_async.c:2954 Can not record session.  Media not enabled on channel
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_channel.c:3585 (sofia/external/+97350000010) Callstate Change DOWN -> EARLY
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [opus:102:48000:20:0:2]/[opus:116:48000:20:0:2]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [opus:116:48000:20:0:2] ++++ is saved as a match
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [opus:102:48000:20:0:2]/[G722:9:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [opus:102:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5438 Set telephone-event payload to 103@48000
2025-12-06 16:53:16.437264 98.27% [DEBUG] mod_opus.c:629 Opus encoder: set bitrate to local settings [120000bps]
2025-12-06 16:53:16.437264 98.27% [DEBUG] mod_opus.c:629 Opus encoder: set bitrate to local settings [120000bps]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:3731 Set Codec sofia/external/+97350000010 opus/48000 20 ms 960 samples 0 bits 2 channels
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_codec.c:111 sofia/external/+97350000010 Original read codec set to opus:116
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5798 Set telephone-event payload to 103@48000
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5856 sofia/external/+97350000010 Set 2833 dtmf send payload to 103 recv payload to 103
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:8660 AUDIO RTP [sofia/external/+97350000010] 172.18.0.7 port 32760 -> 172.18.0.2 port 32006 codec: 102 ms: 20
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_rtp.c:4566 Starting timer [soft] 960 bytes per 20ms
2025-12-06 16:53:16.437264 98.27% [INFO] switch_ivr_originate.c:3862 Sending early media
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [opus:111:48000:20:0:1]/[opus:116:48000:20:0:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [opus:116:48000:20:0:1] ++++ is saved as a match
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [opus:111:48000:20:0:1]/[G722:9:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMU:0:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [opus:111:48000:20:0:1]/[PCMA:8:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [red:63:48000:20:0:2]/[opus:116:48000:20:0:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [red:63:48000:20:0:2]/[G722:9:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [red:63:48000:20:0:2]/[PCMU:0:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [red:63:48000:20:0:2]/[PCMA:8:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G722:9:8000:20:64000:1]/[opus:116:48000:20:0:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G722:9:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [G722:9:8000:20:64000:1] ++++ is saved as a match
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [G722:9:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[opus:116:48000:20:0:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [PCMU:0:8000:20:64000:1] ++++ is saved as a match
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMU:0:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[opus:116:48000:20:0:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[G722:9:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMU:0:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5526 Audio Codec Compare [PCMA:8:8000:20:64000:1]/[PCMA:8:8000:20:64000:1]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5588 Audio Codec Compare [PCMA:8:8000:20:64000:1] ++++ is saved as a match
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5438 Set telephone-event payload to 110@48000
2025-12-06 16:53:16.437264 98.27% [DEBUG] mod_opus.c:629 Opus encoder: set bitrate to local settings [72000bps]
2025-12-06 16:53:16.437264 98.27% [DEBUG] mod_opus.c:629 Opus encoder: set bitrate to local settings [72000bps]
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:3731 Set Codec sofia/internal/9208@ws-self opus/48000 20 ms 960 samples 0 bits 1 channels
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_codec.c:111 sofia/internal/9208@ws-self Original read codec set to opus:116
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:4211 Save audio Candidate cid: 1 proto: udp type: host addr: 192.168.1.10:55866
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:4211 Save audio Candidate cid: 1 proto: udp type: srflx addr: 92.98.195.153:55866
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:4256 Searching for rtp candidate.
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:4265 Choose rtp candidate, index 1, 92.98.195.153:55866
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:4000 sofia/internal/9208@ws-self choosing family v4
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:4276 Choose same candidate, index 0, for rtcp based on rtcp-mux attribute 92.98.195.153:55866
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:4328 setting remote audio ice addr to index 1 92.98.195.153:55866 based on candidate
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:4363 Setting remote rtcp audio addr to 92.98.195.153:55866 based on candidate
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5798 Set telephone-event payload to 110@48000
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:5856 sofia/internal/9208@ws-self Set 2833 dtmf send payload to 110 recv payload to 110
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:8660 AUDIO RTP [sofia/internal/9208@ws-self] 172.18.0.7 port 32676 -> 92.98.195.153 port 55866 codec: 111 ms: 20
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_rtp.c:4566 Starting timer [soft] 960 bytes per 20ms
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:8973 sofia/external/+97350000010 Set 2833 dtmf send payload to 103
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:8980 sofia/external/+97350000010 Set 2833 dtmf receive payload to 103
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:9003 sofia/external/+97350000010 Set rtp dtmf delay to 40
2025-12-06 16:53:16.437264 98.27% [INFO] switch_core_media.c:8841 Activating Audio ICE
2025-12-06 16:53:16.437264 98.27% [NOTICE] switch_rtp.c:5006 Activating RTP audio ICE: +BaG:pKVRPUn19Kj5OKTl 92.98.195.153:55866
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_core_media.c:8881 Activating RTCP PORT 55866
2025-12-06 16:53:16.437264 98.27% [DEBUG] switch_rtp.c:4898 RTCP send rate is: 1000 and packet rate is: 20000 Remote Port: 55866
2025-12-06 16:53:16.437264 98.27% [INFO] switch_core_media.c:8892 Skipping RTCP ICE (Same as RTP)
2025-12-06 16:53:16.437264 98.27% [INFO] switch_rtp.c:3857 Activate RTP/RTCP audio DTLS client
2025-12-06 16:53:16.455698 98.27% [INFO] switch_rtp.c:4045 Changing audio DTLS state from OFF to HANDSHAKE
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_core_media.c:8973 sofia/internal/9208@ws-self Set 2833 dtmf send payload to 110
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_core_media.c:8980 sofia/internal/9208@ws-self Set 2833 dtmf receive payload to 110
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_core_media.c:9003 sofia/internal/9208@ws-self Set rtp dtmf delay to 40
2025-12-06 16:53:16.455698 98.27% [NOTICE] sofia_media.c:90 Pre-Answer sofia/internal/9208@ws-self!
EXECUTE [depth=1] sofia/internal/9208@ws-self export(core_recording_path_full=recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3)
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_channel.c:1334 EXPORT (export_vars) [core_recording_path_full]=[recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3]
EXECUTE [depth=1] sofia/internal/9208@ws-self record_session(/mnt/shared/freeswitch/recordings/ws-self/2025/12/6/2c8862cc-e1c6-4bcb-b58e-e5e59153fb6f/full.mp3)
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_ivr_async.c:1504 Record session sample rate: 48000 -> 48000
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_core_media_bug.c:976 Attaching BUG to sofia/internal/9208@ws-self
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_channel.c:3585 (sofia/internal/9208@ws-self) Callstate Change RINGING -> EARLY
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_core_media.c:8642 Audio params are unchanged for sofia/internal/9208@ws-self.
2025-12-06 16:53:16.455698 98.27% [DEBUG] mod_sofia.c:2607 Ring SDP:
v=0
o=FreeSWITCH 1765007320 1765007321 IN IP4 172.18.0.7
s=FreeSWITCH
c=IN IP4 172.18.0.7
t=0 0
a=msid-semantic: WMS 7hfBTr8HRBrzwpy6NUS1GXYxrZ431p52
m=audio 32676 UDP/TLS/RTP/SAVPF 111 110
a=rtpmap:111 opus/48000/2
a=fmtp:111 useinbandfec=1; minptime=10
a=rtpmap:110 telephone-event/48000
a=ptime:20
a=sendrecv
a=fingerprint:sha-256 AC:C9:EC:89:55:DD:D3:90:C1:A2:84:FA:60:F3:6A:A2:2C:8D:14:D1:9E:94:C0:A3:98:EE:08:31:82:82:CD:38
a=setup:active
a=rtcp-mux
a=rtcp:32676 IN IP4 172.18.0.7
a=ice-ufrag:pKVRPUn19Kj5OKTl
a=ice-pwd:OaRtgbM2MvibvWJ0kUXy8KW1
a=candidate:0944044357 1 udp 2130706431 172.18.0.7 32676 typ host generation 0
a=end-of-candidates
a=ssrc:3375836197 cname:dReR2AxuyGT3Q7u0
a=ssrc:3375836197 msid:7hfBTr8HRBrzwpy6NUS1GXYxrZ431p52 a0
a=ssrc:3375836197 mslabel:7hfBTr8HRBrzwpy6NUS1GXYxrZ431p52
a=ssrc:3375836197 label:7hfBTr8HRBrzwpy6NUS1GXYxrZ431p52a0

2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_ivr_originate.c:3913 Originate Resulted in Success: [sofia/external/+97350000010] Peer UUID: a436821a-dd36-4b52-9259-20a88374d12a
2025-12-06 16:53:16.455698 98.27% [DEBUG] sofia.c:7497 Channel sofia/internal/9208@ws-self entering state [early][183]
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_ivr_bridge.c:1791 (sofia/external/+97350000010) State Change CS_CONSUME_MEDIA -> CS_EXCHANGE_MEDIA
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_core_state_machine.c:581 (sofia/external/+97350000010) Running State Change CS_EXCHANGE_MEDIA (Cur 2 Tot 26)
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_core_state_machine.c:650 (sofia/external/+97350000010) State EXCHANGE_MEDIA
2025-12-06 16:53:16.455698 98.27% [DEBUG] mod_sofia.c:672 SOFIA EXCHANGE_MEDIA
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_ivr_async.c:1778 No silence detection configured; assuming start of speech
2025-12-06 16:53:16.455698 98.27% [DEBUG] switch_core_media.c:16246 Engaging Write Buffer at 1920 bytes to accommodate 1920->1920
2025-12-06 16:53:16.475870 98.27% [NOTICE] switch_rtp.c:1440 Auto Changing audio stun/rtp/dtls port from 92.98.195.153:55866 to 172.18.0.1:60234 idx:-1
2025-12-06 16:53:16.496556 98.27% [DEBUG] switch_rtp.c:7698 Correct audio ip/port confirmed.
2025-12-06 16:53:16.496556 98.27% [DEBUG] mod_opus.c:735 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2025-12-06 16:53:16.496556 98.27% [DEBUG] mod_opus.c:750 Opus encoder stats: Frames[2] Bytes encoded[123] Encoded length ms[40] Average encoded bitrate bps[0]
2025-12-06 16:53:16.496556 98.27% [DEBUG] mod_opus.c:629 Opus encoder: set bitrate to local settings [72000bps]
2025-12-06 16:53:16.496556 98.27% [DEBUG] mod_opus.c:735 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2025-12-06 16:53:16.496556 98.27% [DEBUG] mod_opus.c:750 Opus encoder stats: Frames[0] Bytes encoded[0] Encoded length ms[0] Average encoded bitrate bps[0]
2025-12-06 16:53:16.496556 98.27% [DEBUG] mod_opus.c:629 Opus encoder: set bitrate to local settings [72000bps]
2025-12-06 16:53:16.555773 98.27% [INFO] switch_rtp.c:3341 Changing audio DTLS state from HANDSHAKE to SETUP
2025-12-06 16:53:16.576053 98.27% [INFO] switch_rtp.c:3248 audio Fingerprint Verified.
2025-12-06 16:53:16.576053 98.27% [INFO] switch_rtp.c:4369 Activating audio Secure RTP SEND
2025-12-06 16:53:16.576053 98.27% [INFO] switch_rtp.c:4347 Activating audio Secure RTP RECV
2025-12-06 16:53:16.576053 98.27% [INFO] switch_rtp.c:3290 Changing audio DTLS state from SETUP to READY
2025-12-06 16:53:16.576053 98.27% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
2025-12-06 16:53:16.576053 98.27% [DEBUG] switch_core_sqldb.c:2778 Secure Type: srtp:dtls:AES_CM_128_HMAC_SHA1_80
2025-12-06 16:53:16.576053 98.27% [DEBUG] switch_core_io.c:448 Setting BUG Codec opus:116
2025-12-06 16:53:16.576053 98.27% [DEBUG] mod_opus.c:629 Opus encoder: set bitrate to local settings [72000bps]
2025-12-06 16:53:16.576053 98.27% [DEBUG] switch_core_media.c:16246 Engaging Write Buffer at 3840 bytes to accommodate 3840->3840
2025-12-06 16:53:16.596514 98.27% [DEBUG] switch_rtp.c:1934 rtcp_stats_init: audio ssrc[2187706315] base_seq[28270]
2025-12-06 16:53:16.976114 98.27% [INFO] mod_shout.c:337 LAME 3.100 64bits (http://lame.sf.net)
2025-12-06 16:53:16.976114 98.27% [INFO] mod_shout.c:337 Using polyphase lowpass filter, transition band: 18774 Hz - 19355 Hz
2025-12-06 16:53:34.435737 97.60% [DEBUG] sofia.c:6676 Remote Reason: 18
2025-12-06 16:53:34.435737 97.60% [DEBUG] sofia.c:7497 Channel sofia/external/+97350000010 entering state [terminated][480]
2025-12-06 16:53:34.435737 97.60% [NOTICE] sofia.c:8740 Hangup sofia/external/+97350000010 [CS_EXCHANGE_MEDIA] [NO_USER_RESPONSE]
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_ivr_bridge.c:825 sofia/external/+97350000010 ending bridge by request from read function
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/external/+97350000010]
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:650 (sofia/external/+97350000010) State EXCHANGE_MEDIA going to sleep
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:581 (sofia/external/+97350000010) Running State Change CS_HANGUP (Cur 2 Tot 26)
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:844 (sofia/external/+97350000010) Callstate Change EARLY -> HANGUP
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:846 (sofia/external/+97350000010) State HANGUP
2025-12-06 16:53:34.435737 97.60% [DEBUG] mod_sofia.c:469 Channel sofia/external/+97350000010 hanging up, cause: NO_USER_RESPONSE
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:59 sofia/external/+97350000010 Standard HANGUP, cause: NO_USER_RESPONSE
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:846 (sofia/external/+97350000010) State HANGUP going to sleep
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:616 (sofia/external/+97350000010) State Change CS_HANGUP -> CS_REPORTING
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:581 (sofia/external/+97350000010) Running State Change CS_REPORTING (Cur 2 Tot 26)
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:932 (sofia/external/+97350000010) State REPORTING
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:168 sofia/external/+97350000010 Standard REPORTING, cause: NO_USER_RESPONSE
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:932 (sofia/external/+97350000010) State REPORTING going to sleep
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_state_machine.c:607 (sofia/external/+97350000010) State Change CS_REPORTING -> CS_DESTROY
2025-12-06 16:53:34.435737 97.60% [DEBUG] switch_core_session.c:1744 Session 26 (sofia/external/+97350000010) Locked, Waiting on external entities
2025-12-06 16:53:34.455821 97.53% [DEBUG] switch_ivr_bridge.c:819 sofia/external/+97350000010 ending bridge by request from write function
2025-12-06 16:53:34.455821 97.53% [DEBUG] switch_ivr_bridge.c:911 BRIDGE THREAD DONE [sofia/internal/9208@ws-self]
2025-12-06 16:53:34.455821 97.53% [NOTICE] switch_core_session.c:1762 Session 26 (sofia/external/+97350000010) Ended
2025-12-06 16:53:34.455821 97.53% [NOTICE] switch_core_session.c:1766 Close Channel sofia/external/+97350000010 [CS_DESTROY]
2025-12-06 16:53:34.455821 97.53% [DEBUG] switch_ivr.c:1032 Codec Activated L16@48000hz 1 channels 20ms
2025-12-06 16:53:34.455821 97.53% [DEBUG] switch_core_state_machine.c:735 (sofia/external/+97350000010) Running State Change CS_DESTROY (Cur 1 Tot 26)
2025-12-06 16:53:34.455821 97.53% [DEBUG] switch_core_state_machine.c:745 (sofia/external/+97350000010) State DESTROY
2025-12-06 16:53:34.455821 97.53% [DEBUG] mod_sofia.c:380 sofia/external/+97350000010 SOFIA DESTROY
2025-12-06 16:53:34.455821 97.53% [DEBUG] mod_opus.c:735 Opus decoder stats: Frames[900] PLC[0] FEC[0]
2025-12-06 16:53:34.455821 97.53% [DEBUG] mod_opus.c:750 Opus encoder stats: Frames[2] Bytes encoded[170] Encoded length ms[40] Average encoded bitrate bps[0]
2025-12-06 16:53:34.455821 97.53% [DEBUG] mod_opus.c:735 Opus decoder stats: Frames[0] PLC[0] FEC[0]
2025-12-06 16:53:34.455821 97.53% [DEBUG] mod_opus.c:750 Opus encoder stats: Frames[892] Bytes encoded[90413] Encoded length ms[17840] Average encoded bitrate bps[42547]
2025-12-06 16:53:34.455821 97.53% [DEBUG] switch_core_state_machine.c:175 sofia/external/+97350000010 Standard DESTROY
2025-12-06 16:53:34.455821 97.53% [DEBUG] switch_core_state_machine.c:745 (sofia/external/+97350000010) State DESTROY going to sleep

Metadata

Metadata

Assignees

No one assigned

    Labels

    bugSomething isn't working

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions