Asterisk 16.6.1: PJSIP: Delayed Action Of Core Since Update To 16.6.1
Hello,
we’re running a small Asterisk appliance on a PCengine APU2C4. Base operating system is FreeBSD 12-STABLE, most recent incarnation as of today.
Since update of port net/asterisk16 to the latest bug fix revision 16.6.1, we face a severe
“slowdown” of everything that the Asterisk core performs, i.e. outgoing calls are delayed ~ 20
seconds and I guess incoming calls suffer the same until they gett patched through to an endpoint/telephone. We also register a higher load on idle asterisk process since the last update.
Here is an example when calling two attached physical phones directly, which performed prior to 16.6.1 almost immediately and now takes up to 30 seconds to make the called ednpoint ring.
The calling phone/endpoint sinals by callsound that it is calling, and the sound changes then
(some kind of different octave/tune, don’t know) when the asterisk core reports
[Nov 15 13:21:24] == Using SIP RTP Audio TOS bits 184
(see below). It is here approx 10 seconds, but there are situations were it might more (as observed). the host has no further load so far!
Incoming testcalls we made from wireless/mobile show the same. It seems, asterisk is acting as a black hole delaying device for approx 10 seconds until it decides to pass the call through to an endpoint and then it takes another 10 seconds until the endpoint starts ringing (it is in fact a group of phones ringing alltogether).
I can not see anything unusual with the underlying OS or some critical debug messages from asterisk itself.
Any ideas?
Kind regards,
O. Hartmann
[…]
==>> START [Nov 15 13:21:06] == Setting global variable ‘SIPDOMAIN’ to ‘192.168.2.1’
[Nov 15 13:21:15] == Using SIP RTP Audio TOS bits 184
[Nov 15 13:21:15] — Executing [511@internalsip_o2:1] NoOp(“PJSIP/501-00000008”, “”) in new stack
[Nov 15 13:21:15] — Executing [511@internalsip_o2:2] Progress(“PJSIP/501-00000008”, “”)
in new stack
[Nov 15 13:21:15] — Executing [511@internalsip_o2:3] Gosub(“PJSIP/501-00000008”,
“subSetChannelLocale,start,1(abschnitt211,de,de_DE)”) in new stack
[Nov 15 13:21:15] — Executing [start@subSetChannelLocale:1] Verbose(“PJSIP/501-00000008”,
“2, subSetChannelLocale: ARG1: musicclass=abschnitt211, ARG2: tonezone=de, ARG3:
language=de_DE”) in new stack [Nov 15 13:21:15] > 0x807c82000 — Strict RTP learning after remote address set to: 192.168.2.50:17702
[Nov 15 13:21:15] == subSetChannelLocale: ARG1: musicclass=abschnitt211, ARG2: tonezone=de, ARG3: language=de_DE
[Nov 15 13:21:15] — Executing [start@subSetChannelLocale:2]
Progress(“PJSIP/501-00000008”, “”) in new stack
[Nov 15 13:21:15] — Executing [start@subSetChannelLocale:3] Set(“PJSIP/501-00000008”,
“CHANNEL(musicclass)=abschnitt211”) in new stack
[Nov 15 13:21:15] — Executing [start@subSetChannelLocale:4] Set(“PJSIP/501-00000008”,
“CHANNEL(tonezone)=de”) in new stack
[Nov 15 13:21:15] — Executing [start@subSetChannelLocale:5] Set(“PJSIP/501-00000008”,
“CHANNEL(language)=de_DE”) in new stack
[Nov 15 13:21:15] — Executing [start@subSetChannelLocale:6] Return(“PJSIP/501-00000008”,
“”) in new stack
[Nov 15 13:21:15] — Executing [511@internalsip_o2:4] Dial(“PJSIP/501-00000008”,
“PJSIP/511,45,Ttr”) in new stack
[Nov 15 13:21:15] — Called PJSIP/511
[Nov 15 13:21:15] > 0x807c82000 — Strict RTP switching to RTP target address
192.168.2.50:17702 as source
[Nov 15 13:21:20] > 0x807c82000 — Strict RTP learning complete
– – – Locking on source address 192.168.2.50:17702
===>> CHANGE OF RINGING/CONNECTING [Nov 15 13:21:24] == Using SIP RTP Audio TOS bits 184
[Nov 15 13:21:25] — PJSIP/511-00000009 is ringing
[Nov 15 13:21:25] — PJSIP/511-00000009 is ringing
[Nov 15 13:21:32] — PJSIP/511-00000009 answered PJSIP/501-00000008
[Nov 15 13:21:32] > 0x807c85000 — Strict RTP learning after remote address set to:
192.168.2.51:24094
[Nov 15 13:21:32] — Channel PJSIP/511-00000009 joined ‘simple_bridge’ basic-bridge
[Nov 15 13:21:32] — Channel PJSIP/501-00000008 joined ‘simple_bridge’ basic-bridge
[Nov 15 13:21:32] > 0x807c85000 — Strict RTP switching to RTP target address
192.168.2.51:24094 as source
[Nov 15 13:21:37] — Channel PJSIP/511-00000009 left ‘simple_bridge’ basic-bridge
[Nov 15 13:21:37] — Channel PJSIP/501-00000008 left ‘simple_bridge’ basic-bridge
[Nov 15 13:21:37] == Spawn extension (internalsip_o2, 511, 4) exited non-zero on
‘PJSIP/501-00000008’
[…]
—–BEGIN PGP SIGNATURE—
2 thoughts on - Asterisk 16.6.1: PJSIP: Delayed Action Of Core Since Update To 16.6.1
Do you have a STUN server configured in rtp.conf? If you do, is it reachable, does the problem go away if you remove it?
In that specific version? No. That code itself hasn’t been touched in years, so the problem applies to every version. Using the defined STUN
server to get a server reflexive ICE candidate is a blocking process. If the server isn’t reachable or is extremely slow then it has to wait until a timeout occurs, causing a delay.