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

[ycherniavskyi]

What version of Janus is this happening on? v1.2.2

Have you tested a more 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 configurable to accommodate different operational needs? Alternatively, could the buffer size be increased once more, perhaps to 4096 bytes, to prevent truncation?

[lminiero]

I still don't understand how SIP messages can get that large, when the SIP plugin doesn't even support multistream and so can only do two m-lines. Are you using event handlers (which is the only thing using those log buffers) or not (in which case we'd need to check why the errors appear in the first place)?

[ywmoyue]

Hello lminiero, I break point here found that the judgment "if(line[3] == '-')" has never been hit, and then "sofia_log[0] = '\0';" will never be executed to clear the buffer.

After executing several more sip operations, sofia_log will be full. If continue to execute sip operations, the error "Truncation occurred" will be reported.

I don’t understand sofia’s log structure. Should every log received be forwarded to the event handler without making this judgment?

[ywmoyue]

I copied the value of 'line' with a registered sip message. It is like this:

0x7fffb67eb270 "recv 361 bytes from udp/[192.168.19.59]:5060 at 14:54:04.204265:\n", '-' <repeats 72 times>, "\nSIP/2.0 200 OK\nVia: SIP/2.0/UDP 192.168.9.245:32868;rport=32868;branch=z9hG4bK3Bet6r1mgNp7p;received=192.168.9.245\nFrom: <sip:3827@192.168.19.59>;tag=3345Fm7Fj4vQB\nTo: <sip:3827@192.168.19.59>;tag=cd1747d9\nCall-ID: 6eec95a2-86e1-123d-768e-aa22c5774c0e\nCSeq: 82978630 REGISTER\nContact: \"3827\"<sip:3827@192.168.9.245:32868;transport=udp>;expires=360\nContent-Length: 0\n\n\n"

the character - is in bits 62 to 133. I guess the judgment of line[3] == '-' is actually Want to judge these characters?

[ycherniavskyi]

I suspect that the log output may be related to the sofia-sip version. Currently, I am using version 1.13.17.

[lminiero]

Yes, I think so too: there's was an issue some time ago that was opened about that, #3031. The user that opened the issue contributed a tentative PR , but then disappeared so it never went anywhere. If you have ways to replicate the problem and maybe revisit the original PR (#3063) to see if it works for you, it would help having an up-to-date fix for that.

[ycherniavskyi]

After further investigation, I concur with the assessment outlined in https://github.com/meetecho/janus-gateway/issues/3031#issuecomment-1236859550. It appears that Sofia-SIP behaves differently before and after version 1.13 (related commit https://github.com/freeswitch/sofia-sip/commit/57cb3b3f6d76b3e293e5c95679db0a912882ea85). So, to address this issue, I am going to create a pull request inspired by the https://github.com/meetecho/janus-gateway/pull/3063.

[ycherniavskyi]

In the implementation I’m currently working on, I'm going to bypass intermediate sofia_log buffer. It is not necessary in case when "siptrace logs in a single log callback". However, it’s important to note that the current buffer size of 3072 bytes may not be sufficient for handling some SIP messages. For example here is the size of general video call INVITE message:

send 3432 bytes to udp/[X.X.X.X]:5060 at 19:14:01.855117:
------------------------------------------------------------------------
INVITE sip:123@X.X.X.X SIP/2.0
...