Janus 1.2.2 Truncation occurred / Destroying WebSocket client

GoodGreg · July 18, 2024, 7:47am

Hello, we have recently upgraded the Janus to multistream 1.2.2 and passed it into production.
We had no issues for couple of days, but this morning janus have stopped working.
When i looked in the logs i see this kind of errors:

[Thu Jul 18 06:46:22 2024] Detaching handle from JANUS SIP plugin; 0x7fc024004640 0x7fc0242617d0 0x7fc024004640 0x7fc02431f290
[Thu Jul 18 06:46:22 2024] [3949090083237678] Handle and related resources freed; 0x7fc024004640 0x7fc02405ea80
[Thu Jul 18 06:46:22 2024] [WARN] [6997971002090419] Failed to add some remote candidates (added 0, expected 1)
[Thu Jul 18 06:46:22 2024] Detaching handle from JANUS SIP plugin; 0x7fc02405e8c0 0x7fbfe42994d0 0x7fc02405e8c0 0x7fc024388f60
[Thu Jul 18 06:46:22 2024] [ERR] [janus.c:janus_process_incoming_request:1204] Couldn't find any handle 3949090083237678 in session 5183542955289812...
[Thu Jul 18 06:46:22 2024] [ERR] [janus.c:janus_process_incoming_request:1204] Couldn't find any handle 4257418977286048 in session 5183542955289812...
[Thu Jul 18 06:46:22 2024] Destroying session 5183542955289812; 0x7fc02405ea80
[Thu Jul 18 06:46:22 2024] [WSS-0x7fbfe4072e10] Destroying WebSocket client
[Thu Jul 18 06:46:23 2024] [6997971002090419] The DTLS handshake has been completed
[Thu Jul 18 06:46:23 2024] [janus.plugin.sip-0x7fbfe4109500] WebRTC media is now available
[Thu Jul 18 06:46:23 2024] [ERR] [janus.c:janus_process_incoming_request:1194] Couldn't find any session 5183542955289812...
[Thu Jul 18 06:46:23 2024] [WARN] [5233341533389917] Failed to add some remote candidates (added 1, expected 2)
[Thu Jul 18 06:46:24 2024] [5233341533389917] The DTLS handshake has been completed
[Thu Jul 18 06:46:24 2024] [janus.plugin.sip-0x7fbfe4155ad0] WebRTC media is now available
[Thu Jul 18 06:46:27 2024] [765965805225229] Creating ICE agent (ICE Full mode, controlled)
[Thu Jul 18 06:46:28 2024] [5233341533389917] Negotiation update, checking what changed...
[Thu Jul 18 06:46:29 2024] [WSS-0x7fbfe4328e10] Destroying WebSocket client
[Thu Jul 18 06:46:29 2024] [WARN] [765965805225229] Agent already exists?
[Thu Jul 18 06:46:29 2024] [ERR] [janus.c:janus_process_incoming_request:1542] Error setting ICE locally
[Thu Jul 18 06:46:31 2024] [5233341533389917] Negotiation update, checking what changed...
[Thu Jul 18 06:46:31 2024] [WARN] [765965805225229] Agent already exists?
[Thu Jul 18 06:46:31 2024] [ERR] [janus.c:janus_process_incoming_request:1542] Error setting ICE locally
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3211 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3137 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3073 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3173 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3073 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3178 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3211 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3090 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3137 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3073 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3073 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3173 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3073 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3088 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3178 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3211 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3073 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3211 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3137 >= 3072
[Thu Jul 18 06:46:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3137 >= 3072
[Thu Jul 18 06:46:35 2024] [janus.plugin.sip-0x7fc02439e320] No WebRTC media anymore
[Thu Jul 18 06:46:37 2024] [WARN] [3076862552071213] Failed to add some remote candidates (added 0, expected 1)
[Thu Jul 18 06:46:37 2024] [3076862552071213] The DTLS handshake has been completed
[Thu Jul 18 06:46:37 2024] [janus.plugin.sip-0x7fbfe4073360] WebRTC media is now available
[Thu Jul 18 06:46:37 2024] [WARN] [765965805225229] Agent already exists?
[Thu Jul 18 06:46:37 2024] [ERR] [janus.c:janus_process_incoming_request:1542] Error setting ICE locally
[Thu Jul 18 06:46:41 2024] [3076862552071213] Negotiation update, checking what changed...
[Thu Jul 18 06:46:41 2024] [WSS-0x7fbfe42f2150] Destroying WebSocket client
[Thu Jul 18 06:46:41 2024] Creating new session: 7454079443562388; 0x7fc0242452f0
[Thu Jul 18 06:46:41 2024] Creating new handle in session 7454079443562388: 1526572434264663; 0x7fc0242452f0 0x7fc024004640
[Thu Jul 18 06:46:50 2024] [WSS-0x7fbfe4318400] Destroying WebSocket client
[Thu Jul 18 06:46:50 2024] Destroying session 6744827339019990; 0x7fc024021530
[Thu Jul 18 06:46:50 2024] Detaching handle from JANUS SIP plugin; 0x7fc024083000 0x7fbfe4073360 0x7fc024083000 0x7fc02438d040
[Thu Jul 18 06:46:50 2024] Detaching handle from JANUS SIP plugin; 0x7fc0242b5400 0x7fbfe4104fd0 0x7fc0242b5400 0x7fc0241adb60
[Thu Jul 18 06:46:53 2024] Timeout expired for session 7862307986559497...
[Thu Jul 18 06:46:53 2024] Detaching handle from JANUS SIP plugin; 0x7fc02415d970 0x7fbfe42c0540 0x7fc02415d970 0x7fc024187800
[Thu Jul 18 06:46:53 2024] Detaching handle from JANUS SIP plugin; 0x7fc024083610 0x7fbfec1b3440 0x7fc024083610 0x7fc0242fdb80
[Thu Jul 18 06:46:53 2024] Destroying session 7862307986559497; 0x7fc024249190
[Thu Jul 18 06:46:55 2024] [WSS-0x7fbfe40559b0] Destroying WebSocket client
[Thu Jul 18 06:46:55 2024] Destroying session 8518593380900947; 0x7fc0240629a0
[Thu Jul 18 06:46:55 2024] Detaching handle from JANUS SIP plugin; 0x7fc024384870 0x7fbfe4109a50 0x7fc024384870 0x7fc024194580
[Thu Jul 18 06:46:55 2024] Detaching handle from JANUS SIP plugin; 0x7fc0241bd1d0 0x7fbfe4109500 0x7fc0241bd1d0 0x7fc02411d1a0
[Thu Jul 18 06:47:03 2024] Timeout expired for session 62991785566501...
[Thu Jul 18 06:47:03 2024] Detaching handle from JANUS SIP plugin; 0x7fc0241d12a0 0x7fc02406e7d0 0x7fc0241d12a0 0x7fc02404da00
[Thu Jul 18 06:47:03 2024] Detaching handle from JANUS SIP plugin; 0x7fc024083290 0x7fc02404ebe0 0x7fc024083290 0x7fc02423aa80
[Thu Jul 18 06:47:03 2024] Destroying session 62991785566501; 0x7fc024295ae0
[Thu Jul 18 06:47:14 2024] [WSS-0x7fbfe41bfa00] Destroying WebSocket client
[Thu Jul 18 06:47:14 2024] [WSS-0x7fbfe41381b0] Destroying WebSocket client
[Thu Jul 18 06:47:14 2024] Destroying session 8490949601665775; 0x7fc0243be280
[Thu Jul 18 06:47:14 2024] Detaching handle from JANUS SIP plugin; 0x7fc0243bae00 0x7fbfe4276cf0 0x7fc0243bae00 0x7fc0243bf910
[Thu Jul 18 06:47:14 2024] Detaching handle from JANUS SIP plugin; 0x7fc0240fc130 0x7fbfe40909a0 0x7fc0240fc130 0x7fc0243bfe60
[Thu Jul 18 06:47:17 2024] Timeout expired for session 2470797347256853...
[Thu Jul 18 06:47:17 2024] Detaching handle from JANUS SIP plugin; 0x7fc0242c1c90 0x7fbfec005a50 0x7fc0242c1c90 0x7fc0240cbe90
[Thu Jul 18 06:47:17 2024] Detaching handle from JANUS SIP plugin; 0x7fc024205400 0x7fbfe41d09a0 0x7fc024205400 0x7fc02428d000
[Thu Jul 18 06:47:17 2024] Destroying session 2470797347256853; 0x7fc024168a70
[Thu Jul 18 06:47:24 2024] [WSS-0x7fbfe40e6460] Destroying WebSocket client
[Thu Jul 18 06:47:24 2024] [WSS-0x7fbfe4096c00] Destroying WebSocket client

The logs are spammed with the lines:
[Thu Jul 18 07:22:41 2024] [WSS-0x7fbfe42c76d0] Destroying WebSocket client
[Thu Jul 18 07:22:41 2024] [WSS-0x7fbfe41989a0] Destroying WebSocket client
[Thu Jul 18 06:47:33 2024] [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3087 >= 3072

We were not able to create new webrtc peerconnexions during that period.
After Janus restart the services went back online.
I am not sure where to search as the error is not self explanatory to me.
Any ideas ?

lorenzo · July 18, 2024, 9:26am

github.com/meetecho/janus-gateway

[1.x] Increased event handlers SIP logging buffer size one more time or make it configurable

opened 11:49AM - 02 May 24 UTC

closed 08:24AM - 01 Jul 24 UTC

ycherniavskyi

enhancement multistream

**What version of Janus is this happening on?** v1.2.2 **Have you tested a m…ore recent version of Janus too?** - **Was this working before?** No. **Is there a gdb or libasan trace of the issue?** - **Additional context** After enabling the Event Handlers mechanism, I started receiving numerous error messages indicating log truncation. Here's a sample of the log errors: ``` ... 2024-05-01T20:31:12.176557169Z Creating new handle in session 1508735635354590: 7576670150389404; 0x7fa3592ec7f0 0x7fa3592d6490 2024-05-01T20:31:12.280057472Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.373323775Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.373323775Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.434606151Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.434606151Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.434606151Z Registering as a helper 2024-05-01T20:31:12.473137075Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.583697369Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.651736579Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.651736579Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 2024-05-01T20:31:12.651736579Z [ERR] [utils.c:janus_strlcat:278] Truncation occurred, 3322 >= 3072 ... ``` It appears that the current buffer size of 3072 bytes is insufficient under certain environmental conditions, leading to frequent log truncation errors. A similar issue already was solved within #3060. Would it be reasonable to make the buffer size for [`sofia_log`](https://github.com/meetecho/janus-gateway/blob/master/src/plugins/janus_sip.c#L1688) configurable to accommodate different operational needs? Alternatively, could the buffer size be increased once more, perhaps to 4096 bytes, to prevent truncation?

Already fixed upstream.

GoodGreg · July 18, 2024, 9:31am

I have found this, but as far i understood its for sofia 1.13 and i am using
libsofia-sip-ua-dev/now 1.12.11+20110422.1-2.1+deb10u4 amd64 [installed,local]
Do this issue block janus process ? do you recommend to upgrade sofia lib ?
Thank you

lorenzo · July 18, 2024, 9:34am

It’s definitely recommended to upgrade Sofia. 1.12.11 is from a century ago, the FreeSWITCH team updated it and is mantaining it.

GoodGreg · July 18, 2024, 10:19am

In this case i will follow your recommendation and let you know if everything is fine after the upgrade.

GoodGreg · July 22, 2024, 8:36am

Good day, we have deployed new version and as for now we dont have the problem anymore, but i think we need to wait for couple of days to be sure.
Thank you for your help.

Topic		Replies	Views
Websocket can't connect? General	5	1024	July 17, 2023
Janus websocket closes every 300 seconds on pi 5 General	1	34	March 21, 2025
ICE Connectivity Issues with Janus Server: Unable to Establish Component 1 Stream 1 General	4	865	July 14, 2023
Janus Error: only sent -1 bytes? General	2	253	January 11, 2024
Libnice related crash : libnice:ERROR:../agent/conncheck.c:3056:priv_prune_pending_checks: assertion failed: (priority > 0) General	6	282	February 8, 2024

Janus 1.2.2 Truncation occurred / Destroying WebSocket client

Related topics