Version: 2.14
Recording type: Composed
Ran into an issue earlier today where we were unable to stop a composed recording. Just before a call to /recording/stop the RECORDER participant left the room due to a networkDisconnect. The status of the recording is stopped. From here, calls to /recording/start resulted in
the session is not configured for using MediaMode ROUTED or it is already being recorded
When the final participant left the session, the recording seemed to stop after the timeout.
Below is what I think are the relevant log entries. My question is how can we detect this situation and what can we do to recover from it?
[INFO] 2020-07-23 21:29:13,315 [0.0-5443-exec-4] io.openvidu.server.rest.SessionRestController - REST API: POST /api/recordings/start {session=C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58, outputMode=COMPOSED, hasAudio=true, recordingLayout=CUSTOM, customLayout=ActorPlusCDSound, resolution=1280x720, name=VAAID_14631146_4, hasVideo=true}
[INFO] 2020-07-23 21:29:13,324 [0.0-5443-exec-4] io.openvidu.server.recording.service.RecordingService - New recording id (C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222) and final name (VAAID_14631146_4)
[INFO] 2020-07-23 21:29:13,324 [0.0-5443-exec-4] io.openvidu.server.recording.service.ComposedRecordingService - Starting composed (video + audio) recording C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222 of session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:13,325 [0.0-5443-exec-4] io.openvidu.server.recording.service.ComposedRecordingService - {"id":"C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222","name":"VAAID_14631146_4","outputMode":"COMPOSED","resolution":"1280x720","recordingLayout":"CUSTOM","customLayout":"ActorPlusCDSound","sessionId":"C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58","createdAt":1595539753324,"size":0,"duration":0.0,"url":null,"hasAudio":true,"hasVideo":true,"status":"started"}
[INFO] 2020-07-23 21:29:13,325 [0.0-5443-exec-4] io.openvidu.server.recording.service.ComposedRecordingService - Recorder connecting to url https://OPENVIDUAPP:TUHLTPNB7vkY2NK@rtc3.breakdownservices.com/layouts/custom/ActorPlusCDSound/index.html?sessionId=C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58&secret=TUHLTPNB7vkY2NK
[INFO] 2020-07-23 21:29:14,099 [hhfgfsh-e358-t0] io.openvidu.server.rpc.RpcHandler - Participant con_EdbTxHmrCY is calling method 'signal' in session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,224 [42hr72-e1012-t0] io.openvidu.server.core.Session - Token created for insecure user { Session: C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58 | Tokens: [tok_RjSzWukSvPdBSnkS] }
[INFO] 2020-07-23 21:29:14,224 [42hr72-e1012-t0] io.openvidu.server.core.Session - Token consumed { Session: C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58 | Tokens: [] }
[INFO] 2020-07-23 21:29:14,224 [42hr72-e1012-t0] io.openvidu.server.kurento.core.KurentoSession - SESSION C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58: Added participant [participantPrivateId=c25a18fcfmrrtjspqg4p42hr72, participantPublicId=RECORDER, streaming=false]
[INFO] 2020-07-23 21:29:14,257 [42hr72-e1012-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'subscribe' in session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,258 [42hr72-e1012-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Request to receive media from con_XEuRtZjI6f in room C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,270 [42hr72-e1012-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Is now receiving video from con_XEuRtZjI6f in room C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,270 [42hr72-e1012-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'subscribe' in session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,270 [42hr72-e1012-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Request to receive media from con_EdbTxHmrCY in room C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,288 [42hr72-e1012-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Is now receiving video from con_EdbTxHmrCY in room C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,288 [42hr72-e1012-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,288 [42hr72-e1012-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,288 [42hr72-e1012-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:14,288 [42hr72-e1012-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:25,944 [TaskScheduler-1] io.openvidu.server.kurento.core.KurentoSessionManager - Request [LEAVE_ROOM] for participant RECORDER of session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58 with reason networkDisconnect
[INFO] 2020-07-23 21:29:25,944 [TaskScheduler-1] io.openvidu.server.kurento.core.KurentoSession - PARTICIPANT RECORDER: Leaving session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58
[INFO] 2020-07-23 21:29:33,750 [0.0-5443-exec-3] io.openvidu.server.rest.SessionRestController - REST API: POST /api/recordings/stop/C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222
[INFO] 2020-07-23 21:29:33,948 [0.0-5443-exec-3] io.openvidu.server.recording.service.RecordingService - Sealed recording metadata file at /opt/openvidu/recordings/C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222/.recording.C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222 with status [stopped]
[INFO] 2020-07-23 21:29:33,948 [0.0-5443-exec-3] io.openvidu.server.recording.service.ComposedRecordingService - Stopping composed (video + audio) recording C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222 of session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58. Reason: recordingStoppedByServer
[INFO] 2020-07-23 21:29:36,696 [0.0-5443-exec-1] io.openvidu.server.rest.SessionRestController - REST API: POST /api/recordings/stop/C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222
[INFO] 2020-07-23 21:29:36,893 [0.0-5443-exec-1] io.openvidu.server.recording.service.RecordingService - Sealed recording metadata file at /opt/openvidu/recordings/C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222/.recording.C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222 with status [stopped]
[INFO] 2020-07-23 21:29:36,893 [0.0-5443-exec-1] io.openvidu.server.recording.service.ComposedRecordingService - Stopping composed (video + audio) recording C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222 of session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58. Reason: recordingStoppedByServer
----
[INFO] 2020-07-23 22:06:17,068 [pool-1-thread-1] io.openvidu.server.recording.service.RecordingManager - Stopping recording C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222 after 120 seconds wait (no publisher published before timeout)
[INFO] 2020-07-23 22:06:17,068 [pool-1-thread-1] io.openvidu.server.recording.service.RecordingManager - Closing session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58 after automatic stop of recording C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222
[INFO] 2020-07-23 22:06:17,302 [pool-1-thread-1] io.openvidu.server.webhook.HttpWebhookSender - Event recordingStatusChanged successfully posted to uri https://webservices.breakdownexpress.com/openvidu/webhooks.cfm?server_id=108
[INFO] 2020-07-23 22:06:17,302 [pool-1-thread-1] io.openvidu.server.recording.service.RecordingService - Sealed recording metadata file at /opt/openvidu/recordings/C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222/.recording.C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222 with status [stopped]
[INFO] 2020-07-23 22:06:17,302 [pool-1-thread-1] io.openvidu.server.recording.service.ComposedRecordingService - Stopping composed (video + audio) recording C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58-222 of session C061CEC9-7B15-4E5D-AF5D-D5D97CEF9F58. Reason: automaticStop