Temporary deadlock when attempting to add the first IP-camera connection to session after a recording session has been started.

[edvardno]

Describe the bug There is a temporary deadlock in openvidu-server when publishing the first ip camera after a recording session has been started. I believe this is unintended and it causes the server to take unnecessary long to execute the request. It will also not be responsive to other calls that attempts to writelock() the same lock.

Expected behavior The call "/session/{sessionId}/connection" to the SessionRestController in openvidu-server should not wait for a writelock().trylock() for 15 seconds on code that never will execute because the same call has executed a readlock() before this. Instead this synchronoization should be created in a way so the lock doesn't block for 15seconds unnecessary.

Wrong current behavior

• When a recording session is started with a call to "/recordings/start" without any publishers active the recorder starts a timeout for publishers to connect before the session should be terminated.
• After this an IP-camera connection is added with a call to "/sessions/{sessionId}/connection" which runs
• SessionRestController.initializeConnection().
• SessionRestController.initializeConnection() then calls SessionRestController.newIpcamConnection()

• newIpCamConnection() is executing: "session.closingLock.readlock().tryLock()" before calling KurrentoSessionManager.publishIpcam()
• KurrentoSessionManager.publishIpcam() is calling KurrentoSessionManager.publishVideo()
• KurrentoSessionManager.publishVideo() does have an ongoing recording session and no active publishers since this is the first connection to be added. Therefore the code shown above is executed and a call to recordingManager.abortAutomaticRecordingStopThread() is called. recordingManager.abortAutomaticRecordingStopThread() is then executing "session.closingLock.writeLock().tryLock()" attempting to writelock the same lock that has been read-locked further up the call chain. The code bellow will then never execute and the lock will always block for 15seconds.

OpenVidu tutorial where to replicate the error I don't have a tutorial, but should be pretty easy to reproduce. Start a recording and then attempt to add an IpCamera connection.

OpenVidu deployment info I've debugged by reading in repo version 2.29 Used version 2.28 when found bug.

Log of issue: [INFO] 2023-11-02 12:39:36,385 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.rest.SessionRestController - REST API: POST /openvidu/api/recordings/start {name=PitMonitoringSession_2023-11-02T123936Z, hasAudio=false, hasVideo=true, outputMode=INDIVIDUAL, ignoreFailedStreams=true, session=PitMonitoringSession} [INFO] 2023-11-02 12:39:36,385 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.recording.service.RecordingManager - Getting free recording id for session PitMonitoringSession [INFO] 2023-11-02 12:39:36,389 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.recording.service.RecordingManager - Free recording id got for session PitMonitoringSession: PitMonitoringSession [INFO] 2023-11-02 12:39:36,389 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.recording.service.RecordingService - New recording id (PitMonitoringSession) and final name (PitMonitoringSession_2023-11-02T123936Z) [INFO] 2023-11-02 12:39:36,389 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.recording.service.SingleStreamRecordingService - Starting individual (video-only) recording PitMonitoringSession of session PitMonitoringSession [INFO] 2023-11-02 12:39:36,389 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.recording.service.SingleStreamRecordingService - Ignoring failed streams in recording PitMonitoringSession. Some streams may not be immediately or ever recorded [INFO] 2023-11-02 12:39:36,389 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.recording.service.RecordingService - New folder /opt/openvidu/recordings/PitMonitoringSession created for recording PitMonitoringSession [INFO] 2023-11-02 12:39:36,389 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.recording.service.RecordingService - Generated recording metadata file at /opt/openvidu/recordings/PitMonitoringSession/.recording.PitMonitoringSession [INFO] 2023-11-02 12:39:36,389 [http-nio-0.0.0.0-5443-exec-7] io.openvidu.server.recording.service.RecordingManager - No publisher in session PitMonitoringSession. Starting 120 seconds countdown for stopping recording [INFO] 2023-11-02 12:39:38,479 [http-nio-0.0.0.0-5443-exec-8] io.openvidu.server.rest.SessionRestController - REST API: GET /openvidu/api/sessions/PitMonitoringSession [INFO] 2023-11-02 12:39:38,487 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.rest.SessionRestController - REST API: POST /openvidu/api/sessions/PitMonitoringSession/connection {session=PitMonitoringSession, type=IPCAM, data=Visual1, record=null, role=null, kurentoOptions=null, customIceServers=[], rtspUri=rtsp://127.0.0.1:8554/Visual1, adaptativeBitrate=true, onlyPlayWithSubscribers=true, networkCache=0} [INFO] 2023-11-02 12:39:38,489 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.kurento.core.KurentoSession - SESSION PitMonitoringSession: Added participant [participantPrivateId=ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1, participantPublicId=ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1, streaming=false] [INFO] 2023-11-02 12:39:38,548 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1: Request to publish video in room PitMonitoringSession) [INFO] 2023-11-02 12:39:38,548 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1: Is now publishing video in room PitMonitoringSession [INFO] 2023-11-02 12:39:38,548 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.RecordingManager - Starting new RecorderEndpoint in session PitMonitoringSession for new stream of participant ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1 [INFO] 2023-11-02 12:39:38,549 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.SingleStreamRecordingService - Starting single stream recorder for stream str_IPC_HQ3e_ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1 in session PitMonitoringSession [INFO] 2023-11-02 12:39:38,600 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.kurento.endpoint.PublisherEndpoint - IP Camera stream str_IPC_HQ3e_ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1 feed is now enabled [INFO] 2023-11-02 12:39:38,602 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t31] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [UriEndpointStateChangedEvent]: -> endpoint: str_IPC_HQ3e_ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1 (publisher) | state: START | timestamp: 1698928778600 [INFO] 2023-11-02 12:39:38,643 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.kurento.core.KurentoSessionManager - Participant ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1 published before timeout finished. Aborting automatic recording stop [WARN] 2023-11-02 12:39:38,656 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t32] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1: Media error encountered: INVALID_URI: Invalid URI(errCode=0) [WARN] 2023-11-02 12:39:38,656 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t31] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1: Media error encountered: INVALID_URI: Invalid URI(errCode=0) [ERROR] 2023-11-02 12:39:38,674 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t32] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [ERROR]: -> endpoint: str_IPC_HQ3e_ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1 (publisher) | errorCode: 0 | description: Invalid URI | timestamp: 1698928778604 [ERROR] 2023-11-02 12:39:38,674 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t31] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [ERROR]: -> endpoint: str_IPC_HQ3e_ipc_IPCAM_rtsp_MKWP_127_0_0_1_8554_Visual1 (publisher) | errorCode: 0 | description: Invalid URI | timestamp: 1698928778604 [ERROR] 2023-11-02 12:39:53,644 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.RecordingManager - Timeout waiting for Session PitMonitoringSession closing lock to be available for aborting automatic recording stop thred [INFO] 2023-11-02 12:39:53,644 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.kurento.core.KurentoSessionManager - Automatic recording stopped successfully aborted

Notice the 15sec timeout from 12:39:38 to 12:39:53 from add connection call until the abort automatic recording is timed out.

[pabloFuente]

Thanks for reporting this in such a detailed way. The issue has been confirmed and fixed in this commit: https://github.com/OpenVidu/openvidu/commit/a83003338888507ac64bc7c8a53a8f539aabad6b Just by modifying the order of operations the issue has been addressed:

• Before: first the lock was acquired and then the session was being checked to see if it should be closed.
• After: first the session is checked to see if it has to be closed and only then the lock is acquired.