Dear FS community,
I keep encountering this issue and I can’t seem to figure out what’s causing it.
My setup is this:
Debian 11
FreeSWITCH Version 1.10.9-release-21-a615e85afc~64bit
Note: In configs and logs here I have replaced my public IPs with “EXTERNAL_IPv6” and “DESKPHONE_IPv6” for the FS server and my desk phone respectively.
- I’m runnig IPv6 only with the internal-ipv6 profile.
- I’m using a single Grandstream GXP2160 desk phone registering as EXT 1001 via UDP/5060.
- Registration works, SIP packets are exchanged without issues, RTP / audio is exchanged both ways without any issues, calling extensions like 9000 and 9198 works without any issues.
But: Seemingly any invite has almost exactly a 5 second delay. I tested this both via a second registered extension calling the first (or the other way around) and placing a call to the extension via fs_cli using
originate sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060 &echo()
Either way FS says “sending invite”, does CS_INIT → CS_ROUTING, CS_ROUTING → CS_CONSUME_MEDIA and then waits 5 seconds before actually sending out the invite to the desk phone. Here’s a log from fs_cli showing this after using originate to place a call:
Summary
2023-03-14 22:08:47.496050 99.07% [DEBUG] switch_ivr_originate.c:2291 Parsing global variables
2023-03-14 22:08:47.516010 99.07% [NOTICE] switch_channel.c:1123 New Channel sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060 [dba18b7c-a28b-41ce-ace9-47956cde1ffe]
2023-03-14 22:08:47.516010 99.07% [DEBUG] mod_sofia.c:5117 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State Change CS_NEW -> CS_INIT
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) Running State Change CS_INIT (Cur 1 Tot 6)
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:624 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State INIT
2023-03-14 22:08:47.516010 99.07% [DEBUG] mod_sofia.c:97 sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060 SOFIA INIT
2023-03-14 22:08:47.516010 99.07% [INFO] sofia_glue.c:1654 sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060 sending invite call-id: (null)
2023-03-14 22:08:47.516010 99.07% [DEBUG] sofia_glue.c:1657 sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060 sending invite version: 1.10.9 -release-21-a615e85afc 64bit
Local SDP:
v=0
o=FreeSWITCH 1678831713 1678831714 IN IP6 EXTERNAL_IPv6
s=FreeSWITCH
c=IN IP6 EXTERNAL_IPv6
t=0 0
m=audio 25214 RTP/AVP 102 9 0 8 105 101
a=rtpmap:102 opus/48000/2
a=fmtp:102 useinbandfec=1; maxaveragebitrate=30000; maxplaybackrate=48000; ptime=20; minptime=10; maxptime=40
a=rtpmap:9 G722/8000
a=rtpmap:0 PCMU/8000
a=rtpmap:8 PCMA/8000
a=rtpmap:105 telephone-event/48000
a=fmtp:105 0-15
a=rtpmap:101 telephone-event/8000
a=fmtp:101 0-15
a=ptime:20
a=sendrecv
m=video 16544 RTP/AVP 103 104
b=AS:3072
a=rtpmap:103 H264/90000
a=rtpmap:104 VP8/90000
a=sendrecv
a=rtcp-fb:103 ccm fir
a=rtcp-fb:103 ccm tmmbr
a=rtcp-fb:103 nack
a=rtcp-fb:103 nack pli
a=rtcp-fb:104 ccm fir
a=rtcp-fb:104 ccm tmmbr
a=rtcp-fb:104 nack
a=rtcp-fb:104 nack pli
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:40 sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060 Standard INIT
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:48 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State Change CS_INIT -> CS_ROUTING
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:624 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State INIT going to sleep
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) Running State Change CS_ROUTING (Cur 1 Tot 6)
2023-03-14 22:08:47.516010 99.07% [DEBUG] sofia.c:7487 Channel sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060 entering state [calling][0]
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:640 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State ROUTING
2023-03-14 22:08:47.516010 99.07% [DEBUG] mod_sofia.c:158 sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060 SOFIA ROUTING
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_ivr_originate.c:67 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State Change CS_ROUTING -> CS_CONSUME_MEDIA
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:640 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State ROUTING going to sleep
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:581 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) Running State Change CS_CONSUME_MEDIA (Cur 1 Tot 6)
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:659 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State CONSUME_MEDIA
2023-03-14 22:08:47.516010 99.07% [DEBUG] switch_core_state_machine.c:659 (sofia/internal-ipv6/1001@[DESKPHONE_IPv6]:5060) State CONSUME_MEDIA going to sleep
send 1712 bytes to udp/[DESKPHONE_IPv6]:5060 at 22:08:52.518055:
------------------------------------------------------------------------
INVITE sip:1001@[DESKPHONE_IPv6]:5060 SIP/2.0
Via: SIP/2.0/UDP [EXTERNAL_IPv6];rport;branch=z9hG4bKSmpN7pN4j18rm
Max-Forwards: 70
From: <sip:0000000000@[EXTERNAL_IPv6]>;tag=Kjc95U8m2D6XK
To: <sip:1001@[DESKPHONE_IPv6]:5060>
[...]
As you can see, the last log message before the invite is State CONSUME_MEDIA going to sleep at 22:08:47 and the next line, sending the invite is at 22:08:52
Now I have tested the exact same scenario just registering the desk phone via TCP instead of UDP and there is no delay whatsoever. For external reasons I won’t be able to use TCP though, so I would love to figure out what could be causing this delay.
If anyone has any pointers I would be extremely grateful, as I seem to not be getting anywhere in my troubleshooting.
This is my internal-ipv6 profile, just in case:
Summary
<profile name="internal-ipv6">
<settings>
<param name="context" value="default"/>
<param name="rfc2833-pt" value="101"/>
<param name="sip-port" value="$${internal_sip_port}"/>
<param name="dialplan" value="XML"/>
<param name="dtmf-duration" value="2000"/>
<param name="inbound-codec-prefs" value="$${global_codec_prefs}"/>
<param name="outbound-codec-prefs" value="$${global_codec_prefs}"/>
<param name="use-rtp-timer" value="true"/>
<param name="rtp-timer-name" value="soft"/>
<param name="rtp-ip" value="EXTERNAL_IPv6"/>
<param name="sip-ip" value="EXTERNAL_IPv6"/>
<param name="hold-music" value="$${hold_music}"/>
<param name="apply-inbound-acl" value="domains"/>
<param name="record-template" value="$${recordings_dir}/${caller_id_number}.${strftime(%Y-%m-%d-%H-%M-%S)}.wav"/>
<param name="manage-presence" value="true"/>
<param name="inbound-codec-negotiation" value="generous"/>
<param name="tls" value="$${internal_ssl_enable}"/>
<param name="tls-bind-params" value="transport=tls"/>
<param name="tls-sip-port" value="$${internal_tls_port}"/>
<param name="tls-cert-dir" value="$${internal_ssl_dir}"/>
<param name="tls-version" value="$${sip_tls_version}"/>
<param name="inbound-late-negotiation" value="true"/>
<param name="nonce-ttl" value="60"/>
<param name="auth-calls" value="$${internal_auth_calls}"/>
<param name="auth-all-packets" value="false"/>
<param name="rtp-timeout-sec" value="300"/>
<param name="rtp-hold-timeout-sec" value="1800"/>
<param name="force-register-domain" value="$${domain}"/>
<param name="force-register-db-domain" value="$${domain}"/>
<param name="debug" value="0"/>
<param name="sip-trace" value="yes"/>
<param name="track-calls" value="true"/>
<param name="odbc-dsn" value="PGSQL_CONNECTION"/>
</settings>
</profile>
And this is the output of sofia status profile internal-ipv6 reg
Summary
Registrations:
==============================================
Call-ID: 1032127981-5060-1@CGAA:GcFB:HEHf:dFCc::CBG
User: 1001@[DOMAIN]
Contact: "" <sip:1001@[DESKPHONE_IPv6]:5060;fs_nat=yes>
Agent: Grandstream GXP2160 1.0.11.64
Status: Registered(AUTO-NAT)(unknown) EXP(2023-03-14 23:02:52) EXPSECS(78)
Ping-Status: Reachable
Ping-Time: 0.00
Host: [HOSTNAME]
IP: [DESKPHONE_IPv6]
Port: 5060
Auth-User: 1001
Auth-Realm: [DOMAIN]
MWI-Account: 1001@[DOMAIN]
Total items returned: 1
==============================================