KMS 6.16.0 not responding on socket interface anymore

[neilyoung]

I'm having an older KMS 6.16.0 installation running since months now. No issues so far. Yesterday evening it all stoped out of the sudden with a "request timeout" seen from my Node JS server in the attempt to communicate with KMS (as so many successful times before).

Kurento Media Server version: 6.16.0
Found modules:
	'core' version 6.16.0
	'elements' version 6.16.0
	'filters' version 6.16.0
	'webrtcarucocode' version 0.1.6~14.g7bb9038
	'webrtcbarcode' version 0.1.6~5.gfd167d4
	'webrtccbr' version 0.1.6~7.gb9ddf5e

I examined the KMS log and my Node server log and found nothing really disturbing. It seems, that the KMS really stopped responding on the socket interface.

I can recognise starting sessions in KMS log like so (TURN/STUN IP obfuscated):

2023-05-30T20:47:34,242596 21680 0x00007f7f32066700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:110 remove_not_supported_codecs_from_array() <kmswebrtcendpoint3450>  Removing not supported codec 'AMR/8000'
2023-05-30T20:47:34,242828 21680 0x00007f7f32066700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:578 WebRtcEndpointImpl()  STUN port not found in config; using default value: 3478
2023-05-30T20:47:34,242874 21680 0x00007f7f32066700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:589 WebRtcEndpointImpl()  Using STUN reflexive server: 127.0.0.1:3478
2023-05-30T20:47:34,242924 21680 0x00007f7f32066700    info KurentoWebRtcEndpointImpl WebRtcEndpointImpl.cpp:604 WebRtcEndpointImpl()  Using TURN relay server: <user:password>@xx.xx.xx.xx:3478?transport=udp
2023-05-30T20:47:34,247858 21680 0x00007f7f3406a700 warning KurentoMediaElementImpl   MediaElementImpl.cpp:1261 setOutputBitrate()  setOutputBitrate method is deprecated, use properties minOutputBitrate and maxOutputBitrate
2023-05-30T20:47:34,247964 21680 0x00007f7f3406a700 warning kmselement                kmselement.c:1258 kms_element_set_property() <kmswebrtcendpoint3450>  Trying to set min > max. Setting 3000000

In my Node log, which triggers the attempt, this looks like so (in fact, this one was the last successful):

2023-05-30T20:47:34.236Z info: publisher/4504295908: Issued command 'publish': sdp: null, filter: undefined, uri: undefined, stream: vx, record: undefined
2023-05-30T20:47:34.295Z info: publisher/4504295908: GenerateOffer({"offerToReceiveAudio":false})

So I'm making KMS generating an OFFER, which I send back to the desired publisher

At this time not more than 5 users where active in the system and this session was the last one succeeding. No further errors in both logs.

But all subsequent publish attempts end like so for me:

2023-05-30T20:55:38.599Z info: publisher/9635190936: Issued command 'publish': sdp: null, filter: null, uri: null, stream: vx, record: null
2023-05-30T20:55:58.601Z error: publisher/9635190936: error Error: Request has timed out
2023-05-30T20:55:58.601Z error: publisher/9635190936: Command 'publish' failed. Error: Media Server reports error: Error: Request has timed out

...while the KMS log jabbers happily, not seeing any further request:

023-05-30T20:49:34,497185 21680 0x00007f7f3506c700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:34,497317 21680 0x00007f7f3506c700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint696>  Trying to set request_key_frame
2023-05-30T20:49:34,497414 21680 0x00007f7f3506c700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint696>  Keyframe request not handled
2023-05-30T20:49:37,159852 21680 0x00007f7f33068700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:37,159986 21680 0x00007f7f33068700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint695>  Trying to set request_key_frame
2023-05-30T20:49:37,160080 21680 0x00007f7f33068700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint695>  Keyframe request not handled
2023-05-30T20:49:39,497309 21680 0x00007f7f33869700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:39,497439 21680 0x00007f7f33869700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint696>  Trying to set request_key_frame
2023-05-30T20:49:39,497530 21680 0x00007f7f33869700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint696>  Keyframe request not handled
2023-05-30T20:49:42,159390 21680 0x00007f7f32867700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:42,159526 21680 0x00007f7f32867700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint695>  Trying to set request_key_frame
2023-05-30T20:49:42,159619 21680 0x00007f7f32867700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint695>  Keyframe request not handled
2023-05-30T20:49:44,497489 21680 0x00007f7f3406a700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:44,497574 21680 0x00007f7f3406a700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint696>  Trying to set request_key_frame
2023-05-30T20:49:44,497631 21680 0x00007f7f3406a700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint696>  Keyframe request not handled
2023-05-30T20:49:47,161291 21680 0x00007f7f33068700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:47,161373 21680 0x00007f7f33068700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint695>  Trying to set request_key_frame
2023-05-30T20:49:47,161430 21680 0x00007f7f33068700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint695>  Keyframe request not handled
2023-05-30T20:49:49,501501 21680 0x00007f7f31064700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:49,501627 21680 0x00007f7f31064700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint696>  Trying to set request_key_frame
2023-05-30T20:49:49,501721 21680 0x00007f7f31064700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint696>  Keyframe request not handled
2023-05-30T20:49:52,161412 21680 0x00007f7f3586d700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:52,161540 21680 0x00007f7f3586d700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint695>  Trying to set request_key_frame
2023-05-30T20:49:52,161632 21680 0x00007f7f3586d700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint695>  Keyframe request not handled
2023-05-30T20:49:54,500038 21680 0x00007f7f32066700    info KurentoBaseRtpEndpointImpl BaseRtpEndpointImpl.cpp:392 setMtu()  Set MTU for RTP: 1
2023-05-30T20:49:54,500169 21680 0x00007f7f32066700 warning basertpendpoint           kmsbasertpendpoint.c:2463 kms_base_rtp_endpoint_set_property() <kmsrtpendpoint696>  Trying to set request_key_frame
2023-05-30T20:49:54,500265 21680 0x00007f7f32066700 warning basertpendpoint           kmsbasertpendpoint.c:1150 kms_base_rtp_endpoint_request_local_key_frame() <kmsrtpendpoint696>  Keyframe request not handled
2023-05-30T20:50:01,834944 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:51:01,835190 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:52:01,835443 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:53:01,835695 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:54:01,835949 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:55:01,836158 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:56:01,836416 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:57:01,836666 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:57:47,705447 21680 0x00007f7f3606e700 warning KurentoMediaSet           MediaSet.cpp:129 doGarbageCollection()  Removing inactive session: 
2023-05-30T20:58:01,836915 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T20:59:01,837160 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:00:01,837429 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:01:01,837695 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:02:01,837977 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:03:01,838228 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:04:01,838501 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:05:01,838766 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:06:01,839019 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:07:01,839283 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:08:01,839545 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:09:01,839786 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:10:01,840043 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:11:01,840301 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:12:01,840555 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:13:01,840811 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:14:01,841068 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:15:01,841314 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:16:01,841568 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:17:01,841819 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:18:01,842068 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:19:01,842319 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:20:01,842579 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:21:01,842835 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'
2023-05-30T21:22:01,843086 21680 0x00007f7f30863700    info KurentoWebSocketTransport WebSocketTransport.cpp:346 keepAliveSessions()  Keep-Alive for session '57a98796-c122-4351-89e8-65b48c54e3f8'

In the end somebody killed the server (I suppose restarting the KMS would have been the better option).

Anyway, my log settings for KMS are as follows:

/usr/bin/kurento-media-server --gst-debug-level=2 --gst-debug=Kurento*:4,kms*:4 --logs-path=/home/ubuntu/kms-logs

I'm now looking for a better logging setup, which would allow to see the root of the problem. Any suggestions?

[RaistGH]

Can you check if it can be an issue like this?
We're still facing the same issue. Still not being able to reproduce it, but that happens when a bunch of users connect at the same time and start to record several videos. Then sometimes, after a while, the ports start to get blocked, not releasing.

[neilyoung]

Thanks, but I don't longer use KMS 6.