Hi all,
I have the following setup:
Debian 11
FreeSWITCH Version 1.10.9-release-21-a615e85afc~64bit
EXT 1001 registered via UDP/5060 (Grandstream GXP2160)
I’m experimenting with FreeSWITCH HA. I have two identically configured FS instances in active/backup with a floating virtual IP. Traffic flows correctly to and from the active instance, and immediately switches to the backup instance in case of failure.
I place a call from my registered extension to 9196, audio works. An entry for the active call shows up in the table recovery in the database. I then take down the primary instance.
When I invoke sofia recover on the backup node, after re-routed traffic starts arriving, it correctly recovers the call, but immediately after it sends a BYE to my desk phone with Reason: SIP;cause=500;text="Internal Error", and fs_cli outputs:
2023-03-15 16:05:56.002441 76.67% [DEBUG] sofia.c:7487 Channel sofia/internal-ipv6/1001@pbx.uwalkin.io entering state [terminating][500]
2023-03-15 16:05:56.002441 76.67% [NOTICE] sofia.c:8729 Hangup sofia/internal-ipv6/1001@pbx.uwalkin.io [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
Here is a complete log with sofia loglevel all 9 of this happening:
Summary
Recovered 1 call(s)
2023-03-15 16:05:55.902428 76.67% [NOTICE] switch_channel.c:1123 New Channel sofia/internal-ipv6/1001@[DOMAIN] [a9c2b55f-9082-49ca-8fd9-2eeac60ac7b9]
2023-03-15 16:05:55.902428 76.67% [NOTICE] switch_channel.c:1121 Rename Channel sofia/internal-ipv6/1001@[DOMAIN]->sofia/internal-ipv6/1001@[DOMAIN] [a9c2b55f-9082-49ca-8fd9-2eeac60ac7b9]
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_media.c:3750 Set Codec sofia/internal-ipv6/1001@[DOMAIN] G722/8000 20 ms 160 samples 64000 bits 1 channels
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_codec.c:111 sofia/internal-ipv6/1001@[DOMAIN] Original read codec set to G722:9
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_media.c:8651 AUDIO RTP [sofia/internal-ipv6/1001@[DOMAIN]] [EXTERNAL_IPv6] port 19574 -> [DESKPHONE_IPv6] port 5024 codec: 9 ms: 20
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_rtp.c:4377 Starting timer [soft] 160 bytes per 20ms
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_media.c:8963 sofia/internal-ipv6/1001@[DOMAIN] Set 2833 dtmf send payload to 101
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_media.c:8970 sofia/internal-ipv6/1001@[DOMAIN] Set 2833 dtmf receive payload to 101
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_media.c:8993 sofia/internal-ipv6/1001@[DOMAIN] Set rtp dtmf delay to 40
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_sqldb.c:3243 (sofia/internal-ipv6/1001@[DOMAIN]) State Change CS_NEW -> CS_INIT
2023-03-15 16:05:55.902428 76.67% [NOTICE] switch_core_sqldb.c:3244 Resurrecting fallen channel sofia/internal-ipv6/1001@[DOMAIN]
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[DOMAIN]) Running State Change CS_INIT (Cur 1 Tot 3)
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_channel.c:2382 (sofia/internal-ipv6/1001@[DOMAIN]) Callstate Change DOWN -> ACTIVE
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_state_machine.c:624 (sofia/internal-ipv6/1001@[DOMAIN]) State INIT
2023-03-15 16:05:55.902428 76.67% [DEBUG] mod_sofia.c:97 sofia/internal-ipv6/1001@[DOMAIN] SOFIA INIT
nua_common.c:108 nh_create_handle() nua: nh_create_handle: entering
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
2023-03-15 16:05:55.902428 76.67% [DEBUG] sofia_glue.c:1623 sip:nobody@[DESKPHONE_IPv6]:5060 Setting proxy route to sofia/internal-ipv6/1001@[DOMAIN]
2023-03-15 16:05:55.902428 76.67% [INFO] sofia_glue.c:1654 sofia/internal-ipv6/1001@[DOMAIN] sending invite call-id: 1258999644-5060-17@CGAA:GcFB:HEHf:dFCc::CBG
2023-03-15 16:05:55.902428 76.67% [DEBUG] sofia_glue.c:1657 sofia/internal-ipv6/1001@[DOMAIN] sending invite version: 1.10.9 -release-21-a615e85afc 64bit
Local SDP:
v=0
o=FreeSWITCH 1678901981 1678901983 IN IP6 [EXTERNAL_IPv6]
s=FreeSWITCH
c=IN IP6 [EXTERNAL_IPv6]
t=0 0
m=audio 19574 RTP/AVP 9 101
a=rtpmap:9 G722/8000
a=rtpmap:101 telephone-event/0
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
nua.c:632 nua_invite() nua: nua_invite: entering
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_invite
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
nua_stack.c:301 nua_stack_event() nua(0x7fda8400aa80): event i_error 900 Error storing parameters
nua_dialog.c:336 nua_dialog_usage_add() nua(0x7fda8400aa80): adding session usage
nta.c:4497 nta_leg_tcreate() nta_leg_tcreate(0x7fda7404df90)
nta.c:2716 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3290 tport_tsend() tport_tsend(0x7fda7400ddd0) tpn = */[[DESKPHONE_IPv6]]:5060
tport.c:4076 tport_resolve() tport_resolve addrinfo = [[DESKPHONE_IPv6]]:5060
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x7fda7400ddd0): not found by name */[[DESKPHONE_IPv6]]:5060
tport.c:3625 tport_vsend() tport_vsend(0x7fda7400ddd0): 894 bytes of 894 to udp/[[DESKPHONE_IPv6]]:5060
tport.c:3526 tport_send_msg() tport_vsend returned 894
send 894 bytes to udp/[[DESKPHONE_IPv6]]:5060 at 16:05:55.915862:
------------------------------------------------------------------------
INVITE sip:1001@[[DESKPHONE_IPv6]]:5060 SIP/2.0
Via: SIP/2.0/UDP [[EXTERNAL_IPv6]];rport;branch=z9hG4bKetp8rmmaDaS9m
Max-Forwards: 70
From: <sip:9196@[DOMAIN]>;tag=mU52BD9Sy08Dg
To: <sip:1001@[DOMAIN]>;tag=1408903292
Call-ID: 1258999644-5060-17@CGAA:GcFB:HEHf:dFCc::CBG
CSeq: 64906985 INVITE
Contact: <sip:1001@[[EXTERNAL_IPv6]]:5060>
User-Agent: FreeSWITCH-mod_sofia/1.10.9-release-21-a615e85afc~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, as-feature-event, dialog, line-seize, call-info, sla, include-session-description, presence.winfo, message-summary, refer
Content-Length: 0
X-FS-Support: update_display,send_info
Remote-Party-ID: "9196" <sip:9196@[DOMAIN]>;party=calling;screen=yes;privacy=off
nta.c:8400 outgoing_send() nta: sent INVITE (64906985) to */[[DESKPHONE_IPv6]]:5060
tport.c:4191 tport_pend() tport_pend(0x7fda7400ddd0): pending 0x7fda74063330 for udp/[[EXTERNAL_IPv6]]:5060 (already 0)
nta.c:1371 set_timeout() nta: timer set to 32000 ms
nta.c:1369 set_timeout() nta: timer shortened to 1000 ms
nua_session.c:4131 signal_call_state_change() nua(0x7fda8400aa80): call state changed: init -> calling
nua_stack.c:299 nua_stack_event() nua(0x7fda8400aa80): event i_state INVITE sent
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_invite
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_state_machine.c:40 sofia/internal-ipv6/1001@[DOMAIN] Standard INIT
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_state_machine.c:46 (sofia/internal-ipv6/1001@[DOMAIN]) State Change CS_INIT -> CS_EXECUTE
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_state_machine.c:624 (sofia/internal-ipv6/1001@[DOMAIN]) State INIT going to sleep
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[DOMAIN]) Running State Change CS_EXECUTE (Cur 1 Tot 3)
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
2023-03-15 16:05:55.902428 76.67% [DEBUG] sofia.c:7487 Channel sofia/internal-ipv6/1001@[DOMAIN] entering state [calling][0]
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_state_machine.c:647 (sofia/internal-ipv6/1001@[DOMAIN]) State EXECUTE
2023-03-15 16:05:55.902428 76.67% [DEBUG] mod_sofia.c:213 sofia/internal-ipv6/1001@[DOMAIN] SOFIA EXECUTE
2023-03-15 16:05:55.902428 76.67% [DEBUG] switch_core_state_machine.c:323 sofia/internal-ipv6/1001@[DOMAIN] Standard EXECUTE
EXECUTE [depth=0] sofia/internal-ipv6/1001@[DOMAIN] set(open=true)
2023-03-15 16:05:55.902428 76.67% [DEBUG] mod_dptools.c:1673 SET sofia/internal-ipv6/1001@[DOMAIN] [open]=[true]
EXECUTE [depth=0] sofia/internal-ipv6/1001@[DOMAIN] hash(insert/[DOMAIN]-spymap/1001/a9c2b55f-9082-49ca-8fd9-2eeac60ac7b9)
EXECUTE [depth=0] sofia/internal-ipv6/1001@[DOMAIN] hash(insert/[DOMAIN]-last_dial/1001/9196)
EXECUTE [depth=0] sofia/internal-ipv6/1001@[DOMAIN] hash(insert/[DOMAIN]-last_dial/global/a9c2b55f-9082-49ca-8fd9-2eeac60ac7b9)
EXECUTE [depth=0] sofia/internal-ipv6/1001@[DOMAIN] export(RFC2822_DATE=Wed, 15 Mar 2023 16:05:55 -0700)
2023-03-15 16:05:55.922434 76.67% [DEBUG] switch_channel.c:1315 EXPORT (export_vars) [RFC2822_DATE]=[Wed, 15 Mar 2023 16:05:55 -0700]
EXECUTE [depth=0] sofia/internal-ipv6/1001@[DOMAIN] answer()
EXECUTE [depth=0] sofia/internal-ipv6/1001@[DOMAIN] echo()
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x7fda7400ddd0): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x7fda7400ddd0)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x7fda7400ddd0) msg 0x7fda74058f30 from (udp/[[EXTERNAL_IPv6]]:5060) has 526 bytes, veclen = 1
recv 526 bytes from udp/[[DESKPHONE_IPv6]]:5060 at 16:05:55.982054:
------------------------------------------------------------------------
SIP/2.0 100 Trying
Via: SIP/2.0/UDP [[EXTERNAL_IPv6]];rport=5060;branch=z9hG4bKetp8rmmaDaS9m
From: <sip:9196@[DOMAIN]>;tag=mU52BD9Sy08Dg
To: <sip:1001@[DOMAIN]>;tag=1408903292
Call-ID: 1258999644-5060-17@CGAA:GcFB:HEHf:dFCc::CBG
CSeq: 64906985 INVITE
Contact: <sip:1001@[[DESKPHONE_IPv6]]:5060>
Supported: replaces, path, timer
User-Agent: Grandstream GXP2160 1.0.11.64
Require: timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Length: 0
tport.c:3055 tport_deliver() tport_deliver(0x7fda7400ddd0): msg 0x7fda74058f30 (526 bytes) from udp/[[DESKPHONE_IPv6]]:5060/sip next=(nil)
nta.c:3378 agent_recv_response() nta: received 100 Trying for INVITE (64906985)
nta.c:3445 agent_recv_response() nta: 100 Trying is going to a transaction
nta.c:9697 outgoing_estimate_delay() nta_outgoing: RTT is 66.424 ms
tport.c:4253 tport_release() tport_release(0x7fda7400ddd0): 0x7fda74063330 by 0x7fda74052900 with 0x7fda74058f30 (preliminary)
tport.c:2769 tport_wakeup_pri() tport_wakeup_pri(0x7fda7400ddd0): events IN
tport.c:2900 tport_recv_event() tport_recv_event(0x7fda7400ddd0)
tport.c:3237 tport_recv_iovec() tport_recv_iovec(0x7fda7400ddd0) msg 0x7fda7408f1f0 from (udp/[[EXTERNAL_IPv6]]:5060) has 1003 bytes, veclen = 1
recv 1003 bytes from udp/[[DESKPHONE_IPv6]]:5060 at 16:05:55.988857:
------------------------------------------------------------------------
SIP/2.0 200 OK
Via: SIP/2.0/UDP [[EXTERNAL_IPv6]];rport=5060;branch=z9hG4bKetp8rmmaDaS9m
From: <sip:9196@[DOMAIN]>;tag=mU52BD9Sy08Dg
To: <sip:1001@[DOMAIN]>;tag=1408903292
Call-ID: 1258999644-5060-17@CGAA:GcFB:HEHf:dFCc::CBG
CSeq: 64906985 INVITE
Contact: <sip:1001@[[DESKPHONE_IPv6]]:5060>
Supported: replaces, path, timer
User-Agent: Grandstream GXP2160 1.0.11.64
Session-Expires: 120;refresher=uas
Require: timer
Allow: INVITE, ACK, OPTIONS, CANCEL, BYE, SUBSCRIBE, NOTIFY, INFO, REFER, UPDATE, MESSAGE
Content-Type: application/sdp
Content-Length: 410
v=0
o=1001 8000 8001 IN IP6 [DESKPHONE_IPv6]
s=SIP Call
c=IN IP6 [DESKPHONE_IPv6]
t=0 0
m=audio 5024 RTP/AVP 9 123 0 8 97 4 2 101
a=sendrecv
a=rtpmap:9 G722/8000
a=ptime:20
a=rtpmap:123 opus/48000/2
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:4 G723/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
tport.c:3055 tport_deliver() tport_deliver(0x7fda7400ddd0): msg 0x7fda7408f1f0 (1003 bytes) from udp/[[DESKPHONE_IPv6]]:5060/sip next=(nil)
nta.c:3378 agent_recv_response() nta: received 200 OK for INVITE (64906985)
nta.c:3445 agent_recv_response() nta: 200 OK is going to a transaction
tport.c:4253 tport_release() tport_release(0x7fda7400ddd0): 0x7fda74063330 by 0x7fda74052900 with 0x7fda7408f1f0
nua_dialog.c:563 nua_dialog_usage_set_refresh_range() nua(): refresh session after 108 seconds (in [108..108])
nua_session.c:1005 nua_session_client_response() nua(0x7fda8400aa80): INVITE: got SDP offer in 200 OK (0)
nua_stack.c:301 nua_stack_event() nua(0x7fda8400aa80): event r_invite 200 OK
nua_session.c:4131 signal_call_state_change() nua(0x7fda8400aa80): call state changed: calling -> completing, received offer
nua_stack.c:301 nua_stack_event() nua(0x7fda8400aa80): event i_state 200 OK
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
2023-03-15 16:05:56.002441 76.67% [DEBUG] sofia.c:7487 Channel sofia/internal-ipv6/1001@[DOMAIN] entering state [completing][200]
2023-03-15 16:05:56.002441 76.67% [DEBUG] sofia.c:7497 Remote SDP:
v=0
o=1001 8000 8001 IN IP6 [DESKPHONE_IPv6]
s=SIP Call
c=IN IP6 [DESKPHONE_IPv6]
t=0 0
m=audio 5024 RTP/AVP 9 123 0 8 97 4 2 101
a=sendrecv
a=rtpmap:9 G722/8000
a=ptime:20
a=rtpmap:123 opus/48000/2
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:97 iLBC/8000
a=fmtp:97 mode=30
a=rtpmap:4 G723/8000
a=rtpmap:2 G726-32/8000
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
nua.c:638 nua_ack() nua: nua_ack: entering
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_ack
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:278 soa_clone() soa_clone(static::0x7fda7400abb0, 0x7fda74006370, 0x7fda8400aa80) called
soa.c:402 soa_set_params() soa_set_params(static::0x7fda7405ce50, ...) called
soa.c:402 soa_set_params() soa_set_params(static::0x7fda7405ce50, ...) called
nua_params.c:484 nua_stack_set_params() nua: nua_stack_set_params: entering
soa.c:1783 soa_terminate() soa_terminate(static::0x7fda7405ce50) called
soa.c:1301 soa_init_offer_answer() soa_init_offer_answer(static::0x7fda7405ce50) called
nta.c:2716 nta_tpn_by_url() nta: selecting scheme sip
tport.c:3290 tport_tsend() tport_tsend(0x7fda7400ddd0) tpn = */[[DESKPHONE_IPv6]]:5060
tport.c:4076 tport_resolve() tport_resolve addrinfo = [[DESKPHONE_IPv6]]:5060
tport.c:4713 tport_by_addrinfo() tport_by_addrinfo(0x7fda7400ddd0): not found by name */[[DESKPHONE_IPv6]]:5060
tport.c:3625 tport_vsend() tport_vsend(0x7fda7400ddd0): 634 bytes of 634 to udp/[[DESKPHONE_IPv6]]:5060
tport.c:3526 tport_send_msg() tport_vsend returned 634
send 634 bytes to udp/[[DESKPHONE_IPv6]]:5060 at 16:05:56.010045:
------------------------------------------------------------------------
BYE sip:1001@[[DESKPHONE_IPv6]]:5060 SIP/2.0
Via: SIP/2.0/UDP [[EXTERNAL_IPv6]];rport;branch=z9hG4bKF3F1tF5DaKFvg
Max-Forwards: 70
From: <sip:9196@[DOMAIN]>;tag=mU52BD9Sy08Dg
To: <sip:1001@[DOMAIN]>;tag=1408903292
Call-ID: 1258999644-5060-17@CGAA:GcFB:HEHf:dFCc::CBG
CSeq: 64906986 BYE
Contact: <sip:1001@[[EXTERNAL_IPv6]]:5060>
User-Agent: FreeSWITCH-mod_sofia/1.10.9-release-21-a615e85afc~64bit
Allow: INVITE, ACK, BYE, CANCEL, OPTIONS, MESSAGE, INFO, UPDATE, REGISTER, REFER, NOTIFY, PUBLISH, SUBSCRIBE
Supported: timer, path, replaces
Reason: SIP;cause=500;text="Internal Error"
Content-Length: 0
nta.c:8400 outgoing_send() nta: sent BYE (64906986) to */[[DESKPHONE_IPv6]]:5060
tport.c:4191 tport_pend() tport_pend(0x7fda7400ddd0): pending 0x7fda7404e3b0 for udp/[[EXTERNAL_IPv6]]:5060 (already 0)
nua_session.c:4131 signal_call_state_change() nua(0x7fda8400aa80): call state changed: completing -> terminating
nua_stack.c:301 nua_stack_event() nua(0x7fda8400aa80): event i_state 500 Internal Error
nua_stack.c:389 nua_application_event() nua: nua_application_event: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_ack
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
2023-03-15 16:05:56.002441 76.67% [DEBUG] sofia.c:7487 Channel sofia/internal-ipv6/1001@[DOMAIN] entering state [terminating][500]
2023-03-15 16:05:56.002441 76.67% [NOTICE] sofia.c:8729 Hangup sofia/internal-ipv6/1001@[DOMAIN] [CS_EXECUTE] [NORMAL_TEMPORARY_FAILURE]
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_destroy
nua_dialog.c:395 nua_dialog_usage_remove_at() nua(0x7fda8400aa80): removing session usage
nua_session.c:4131 signal_call_state_change() nua(0x7fda8400aa80): call state changed: terminating -> terminated
nua_stack.c:299 nua_stack_event() nua(0x7fda8400aa80): event i_state Terminated
nua_stack.c:299 nua_stack_event() nua(0x7fda8400aa80): event i_terminated Terminated
soa.c:355 soa_destroy() soa_destroy(static::0x7fda7405ce50) called
nta.c:4550 nta_leg_destroy() nta_leg_destroy(0x7fda7404df90)
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_destroy
nua.c:365 nua_handle_magic() nua: nua_handle_magic: entering
nua.c:341 nua_handle_bind() nua: nua_handle_bind: entering
nua.c:920 nua_handle_destroy() nua: nua_handle_destroy: entering
nua.c:1170 nua_handle_unref_user() nua nua_handle_unref_user(0x7fda8400aa80): entering
nua_stack.c:599 nua_stack_signal() nua(0x7fda8400aa80): recv signal r_handle_unref
nua_stack.c:558 nua_signal() nua(0x7fda8400aa80): sent signal r_handle_unref
nua.c:1157 nua_unref_user() nua: nua_unref_user: entering
nua_stack.c:599 nua_stack_signal() nua((nil)): recv signal r_unref
nua_stack.c:558 nua_signal() nua((nil)): sent signal r_unref
2023-03-15 16:05:56.002441 76.67% [DEBUG] switch_core_session.c:2973 sofia/internal-ipv6/1001@[DOMAIN] skip receive message [PHONE_EVENT] (channel is hungup already)
2023-03-15 16:05:56.002441 76.67% [DEBUG] switch_core_state_machine.c:647 (sofia/internal-ipv6/1001@[DOMAIN]) State EXECUTE going to sleep
2023-03-15 16:05:56.002441 76.67% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[DOMAIN]) Running State Change CS_HANGUP (Cur 1 Tot 3)
2023-03-15 16:05:56.002441 76.67% [DEBUG] switch_core_state_machine.c:844 (sofia/internal-ipv6/1001@[DOMAIN]) Callstate Change ACTIVE -> HANGUP
2023-03-15 16:05:56.002441 76.67% [DEBUG] switch_core_state_machine.c:846 (sofia/internal-ipv6/1001@[DOMAIN]) State HANGUP
2023-03-15 16:05:56.002441 76.67% [DEBUG] mod_sofia.c:468 Channel sofia/internal-ipv6/1001@[DOMAIN] hanging up, cause: NORMAL_TEMPORARY_FAILURE
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:59 sofia/internal-ipv6/1001@[DOMAIN] Standard HANGUP, cause: NORMAL_TEMPORARY_FAILURE
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:846 (sofia/internal-ipv6/1001@[DOMAIN]) State HANGUP going to sleep
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:616 (sofia/internal-ipv6/1001@[DOMAIN]) State Change CS_HANGUP -> CS_REPORTING
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[DOMAIN]) Running State Change CS_REPORTING (Cur 1 Tot 3)
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:932 (sofia/internal-ipv6/1001@[DOMAIN]) State REPORTING
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:168 sofia/internal-ipv6/1001@[DOMAIN] Standard REPORTING, cause: NORMAL_TEMPORARY_FAILURE
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:932 (sofia/internal-ipv6/1001@[DOMAIN]) State REPORTING going to sleep
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:607 (sofia/internal-ipv6/1001@[DOMAIN]) State Change CS_REPORTING -> CS_DESTROY
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_session.c:1743 Session 3 (sofia/internal-ipv6/1001@[DOMAIN]) Locked, Waiting on external entities
2023-03-15 16:05:56.022428 76.67% [NOTICE] switch_core_session.c:1761 Session 3 (sofia/internal-ipv6/1001@[DOMAIN]) Ended
2023-03-15 16:05:56.022428 76.67% [NOTICE] switch_core_session.c:1765 Close Channel sofia/internal-ipv6/1001@[DOMAIN] [CS_DESTROY]
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:735 (sofia/internal-ipv6/1001@[DOMAIN]) Running State Change CS_DESTROY (Cur 0 Tot 3)
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:745 (sofia/internal-ipv6/1001@[DOMAIN]) State DESTROY
2023-03-15 16:05:56.022428 76.67% [DEBUG] mod_sofia.c:379 sofia/internal-ipv6/1001@[DOMAIN] SOFIA DESTROY
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:175 sofia/internal-ipv6/1001@[DOMAIN] Standard DESTROY
2023-03-15 16:05:56.022428 76.67% [DEBUG] switch_core_state_machine.c:745 (sofia/internal-ipv6/1001@[DOMAIN]) State DESTROY going to sleep
I believe I have the database set up correctly for call recovery:
autoload_configs/switch.conf.xml
<param name="core-db-dsn" value="pgsql://host=[] dbname=[] user=[] password=[]"/>
sip_profiles/internal-ipv6.xml
<param name="track-calls" value="true"/>
<param name="odbc-dsn" value="pgsql://host=[] dbname=[] user=[] password=[]"/>
Am I doing something fundamentally wrong along the way, that’s obviously hindering FreeSWITCH’s ability to recover this call correctly?