[asterisk-users] Asterisk 16.6.1: PJSIP: delayed action of core since update to 16.6.1

[O. Hartmann]

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA256


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 at internalsip_o2:1] NoOp("PJSIP/501-00000008", "") in
new stack
[Nov 15 13:21:15]     -- Executing [511 at internalsip_o2:2] Progress("PJSIP/501-00000008", "")
in new stack
[Nov 15 13:21:15]     -- Executing [511 at internalsip_o2:3] Gosub("PJSIP/501-00000008",
"subSetChannelLocale,start,1(abschnitt211,de,de_DE)") in new stack
[Nov 15 13:21:15]     -- Executing [start at 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 at subSetChannelLocale:2]
Progress("PJSIP/501-00000008", "") in new stack
[Nov 15 13:21:15]     -- Executing [start at subSetChannelLocale:3] Set("PJSIP/501-00000008",
"CHANNEL(musicclass)=abschnitt211") in new stack
[Nov 15 13:21:15]     -- Executing [start at subSetChannelLocale:4] Set("PJSIP/501-00000008",
"CHANNEL(tonezone)=de") in new stack
[Nov 15 13:21:15]     -- Executing [start at subSetChannelLocale:5] Set("PJSIP/501-00000008",
"CHANNEL(language)=de_DE") in new stack
[Nov 15 13:21:15]     -- Executing [start at subSetChannelLocale:6] Return("PJSIP/501-00000008",
"") in new stack
[Nov 15 13:21:15]     -- Executing [511 at 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
<ba7ffb28-a952-407a-8552-c027f1794ea1>
[Nov 15 13:21:32]     -- Channel PJSIP/501-00000008 joined 'simple_bridge' basic-bridge
<ba7ffb28-a952-407a-8552-c027f1794ea1>
[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
<ba7ffb28-a952-407a-8552-c027f1794ea1>
[Nov 15 13:21:37]     -- Channel PJSIP/501-00000008 left 'simple_bridge' basic-bridge
<ba7ffb28-a952-407a-8552-c027f1794ea1>
[Nov 15 13:21:37]   == Spawn extension (internalsip_o2, 511, 4) exited non-zero on
'PJSIP/501-00000008'
[...]

-----BEGIN PGP SIGNATURE-----

iHUEARYIAB0WIQSy8IBxAPDkqVBaTJ44N1ZZPba5RwUCXc+tWQAKCRA4N1ZZPba5
R4nQAQD56LR+gi78iUVjvolqX05wVB87SsHmHphayX4ST20hkwD9FMMgb6/QLW/S
qPnh7b3VB5qanVQFW7XFcrL4e0lXsAQ=
=VCPx
-----END PGP SIGNATURE-----