Issue with Recording feature in 2.15.0 version of openvidu version

sreedharbukya · July 28, 2020, 10:34am

I have created openvidu server using this instructions - https://docs.openvidu.io/en/2.15.0/deployment/deploying-on-premises/

I am using openvidu 2.15.0 version of node client for app server and browser for front end.

I have attached EFS volumes to store the video call data.

When I started the creation of session with these properties.

mediaMode: MediaMode.ROUTED,
recordingMode: RecordingMode.MANUAL,
defaultOutputMode: OutputMode.INDIVIDUAL

When I start the recording, I get response 200 with recorder ID, but it is failing to create record on the server. Here are the logs of the issue.

openvidu-server_1  | [INFO] 2020-07-28 10:20:04,943 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.recording.service.RecordingService - New recording id (ses_PRvBN0EXIm) and final name (e64e73dd-d5f2-40a3-a047-a976f4665b94/1595931604644/)
openvidu-server_1  | [INFO] 2020-07-28 10:20:04,943 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.recording.service.ComposedRecordingService - Starting composed (video + audio) recording ses_PRvBN0EXIm of session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:04,943 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.recording.service.ComposedRecordingService - {"id":"ses_PRvBN0EXIm","name":"e64e73dd-d5f2-40a3-a047-a976f4665b94/1595931604644/","outputMode":"COMPOSED","resolution":"1920x1080","recordingLayout":"BEST_FIT","sessionId":"ses_PRvBN0EXIm","createdAt":1595931604943,"size":0,"duration":0.0,"url":null,"hasAudio":true,"hasVideo":true,"status":"started"}
openvidu-server_1  | [INFO] 2020-07-28 10:20:04,943 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.recording.service.ComposedRecordingService - Recorder connecting to url https://OPENVIDUAPP:tqKn5nA2YYW5pQFP2u5t0@openvidu.dev.ABC.com.hk/dashboard/#/layout-best-fit/ses_PRvBN0EXIm/tqKn5nA2YYW5pQFP2u5t0/-1/false
openvidu-server_1  | [INFO] 2020-07-28 10:20:05,142 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.utils.DockerManager - Container ID: 27c79a239b76dc69814d98b35f56d530221589920ee1ed7607da08cfc63c8470
openvidu-server_1  | [INFO] 2020-07-28 10:20:05,297 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.cdr.CDRLoggerFile - {"recordingStarted":{"sessionId":"ses_PRvBN0EXIm","timestamp":1595931604943,"id":"ses_PRvBN0EXIm","name":"e64e73dd-d5f2-40a3-a047-a976f4665b94/1595931604644/","outputMode":"COMPOSED","resolution":"1920x1080","recordingLayout":"BEST_FIT","hasAudio":true,"hasVideo":true,"size":0,"duration":0.0}}
openvidu-server_1  | [INFO] 2020-07-28 10:20:05,297 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.cdr.CDRLoggerFile - {"recordingStatusChanged":{"sessionId":"ses_PRvBN0EXIm","timestamp":1595931604943,"startTime":1595931604943,"duration":0.0,"id":"ses_PRvBN0EXIm","name":"e64e73dd-d5f2-40a3-a047-a976f4665b94/1595931604644/","outputMode":"COMPOSED","resolution":"1920x1080","recordingLayout":"BEST_FIT","hasAudio":true,"hasVideo":true,"size":0,"status":"started"}}
openvidu-server_1  | [INFO] 2020-07-28 10:20:05,309 [pool-1-thread-1] io.openvidu.server.webhook.HttpWebhookSender - Event recordingStatusChanged successfully posted to uri https://videocallservice.dev.ABC.com.hk/session-events
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,489 [http-nio-0.0.0.0-5443-exec-4] io.openvidu.server.config.HttpHandshakeInterceptor - Old HttpSession 263CA7F9CB1B4616C6E4001243148560
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,508 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.rpc.RpcHandler - After connection established for WebSocket session: 6qcdu2burerfl0q5re8nsepvn4
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,510 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.coturn.CoturnCredentialsService - Creating COTURN user
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,548 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.coturn.CoturnCredentialsService - COTURN user created: true
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,549 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.core.Session - Token created for insecure user { Session: ses_PRvBN0EXIm | Tokens: [tok_XEYvZgzLXLUAd3tm] }
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,549 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.core.Session - Token consumed { Session: ses_PRvBN0EXIm | Tokens: [] }
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,550 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.kurento.core.KurentoSession - SESSION ses_PRvBN0EXIm: Added participant [participantPrivateId=6qcdu2burerfl0q5re8nsepvn4, participantPublicId=RECORDER, streaming=false]
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,629 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'subscribe' in session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,630 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Request to receive media from con_HOuyPHvQns in room ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,706 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Is now receiving video from con_HOuyPHvQns in room ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,710 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'subscribe' in session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,711 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Request to receive media from con_H4G5x896sj in room ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,736 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t41] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: GATHERING | componentId: 1 | streamId: 1 | timestamp: 1595931606723
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,766 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t41] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: GATHERING | componentId: 2 | streamId: 1 | timestamp: 1595931606743
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,822 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t41] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: CONNECTED | componentId: 1 | streamId: 1 | timestamp: 1595931606810
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,822 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t42] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: READY | componentId: 1 | streamId: 1 | timestamp: 1595931606810
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,822 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t69] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: CONNECTING | componentId: 1 | streamId: 1 | timestamp: 1595931606788
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,823 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t51] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [NewCandidatePairSelected]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | local: candidate:1 1 UDP 2015363327 10.20.0.94 41724 typ host | remote: candidate:remote1 1 UDP 1845501695 10.20.0.94 58581 typ prflx | timestamp: 1595931606810
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,842 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Is now receiving video from con_H4G5x896sj in room ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,843 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,843 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_HOuyPHvQns", sdpMid: 0, sdpMLineIndex: 0, candidate: "candidate:2514413131 1 udp 2113937151 10.20.0.94 58581 typ host generation 0 ufrag xZxg network-cost 999"}
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,845 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,845 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_HOuyPHvQns", sdpMid: 1, sdpMLineIndex: 1, candidate: "candidate:2514413131 1 udp 2113937151 10.20.0.94 53921 typ host generation 0 ufrag xZxg network-cost 999"}
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,847 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,847 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_H4G5x896sj", sdpMid: 0, sdpMLineIndex: 0, candidate: "candidate:2514413131 1 udp 2113937151 10.20.0.94 48032 typ host generation 0 ufrag NHp8 network-cost 999"}
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,849 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,850 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_H4G5x896sj", sdpMid: 1, sdpMLineIndex: 1, candidate: "candidate:2514413131 1 udp 2113937151 10.20.0.94 44416 typ host generation 0 ufrag NHp8 network-cost 999"}
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,853 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,854 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_H4G5x896sj", sdpMid: 1, sdpMLineIndex: 1, candidate: "candidate:842163049 1 udp 1677729535 54.254.56.23 44416 typ srflx raddr 10.20.0.94 rport 44416 generation 0 ufrag NHp8 network-cost 999"}
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,856 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,856 [SessionHandler-6qcdu2burerfl0q5re8nsepvn4-e18-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_H4G5x896sj", sdpMid: 0, sdpMLineIndex: 0, candidate: "candidate:842163049 1 udp 1677729535 54.254.56.23 48032 typ srflx raddr 10.20.0.94 rport 48032 generation 0 ufrag NHp8 network-cost 999"}
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,878 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t56] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | state: GATHERING | componentId: 1 | streamId: 1 | timestamp: 1595931606868
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,880 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t62] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [NewCandidatePairSelected]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | local: candidate:1 1 UDP 2015363327 10.20.0.94 41724 typ host | remote: candidate:2514413131 1 UDP 2113937151 10.20.0.94 58581 typ host | timestamp: 1595931606872
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,918 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t36] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | state: CONNECTING | componentId: 1 | streamId: 1 | timestamp: 1595931606884
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,920 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t53] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: CONNECTED | componentId: 1 | streamId: 1 | timestamp: 1595931606875
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,920 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t51] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | state: GATHERING | componentId: 2 | streamId: 1 | timestamp: 1595931606887
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,945 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t51] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [NewCandidatePairSelected]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | local: candidate:7 1 UDP 1679819007 54.254.56.23 56683 typ srflx raddr 10.20.0.94 rport 56683 | remote: candidate:842163049 1 UDP 1677729535 54.254.56.23 48032 typ srflx raddr 10.20.0.94 rport 48032 | timestamp: 1595931606944
openvidu-server_1  | [INFO] 2020-07-28 10:20:06,946 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | state: CONNECTED | componentId: 1 | streamId: 1 | timestamp: 1595931606944
openvidu-server_1  | [INFO] 2020-07-28 10:20:07,108 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [NewCandidatePairSelected]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | local: candidate:1 1 UDP 2015363327 10.20.0.94 56683 typ host | remote: candidate:2514413131 1 UDP 2113937151 10.20.0.94 48032 typ host | timestamp: 1595931607107
openvidu-server_1  | [INFO] 2020-07-28 10:20:07,709 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [ConnectionStateChanged]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | oldState: DISCONNECTED | newState: CONNECTED | timestamp: 1595931607706
openvidu-server_1  | [INFO] 2020-07-28 10:20:07,737 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaFlowInStateChange] -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: FLOWING | pad: default | mediaType: AUDIO | timestamp: 1595931607735
openvidu-server_1  | [INFO] 2020-07-28 10:20:07,798 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaFlowInStateChange] -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: FLOWING | pad: default | mediaType: VIDEO | timestamp: 1595931607797
openvidu-server_1  | [INFO] 2020-07-28 10:20:07,852 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [ConnectionStateChanged]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | oldState: DISCONNECTED | newState: CONNECTED | timestamp: 1595931607846
openvidu-server_1  | [INFO] 2020-07-28 10:20:07,866 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaFlowInStateChange] -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | state: FLOWING | pad: default | mediaType: AUDIO | timestamp: 1595931607865
openvidu-server_1  | [INFO] 2020-07-28 10:20:07,924 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaFlowInStateChange] -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | state: FLOWING | pad: default | mediaType: VIDEO | timestamp: 1595931607923
openvidu-server_1  | [INFO] 2020-07-28 10:20:08,224 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaStateChangedEvent]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | oldState: DISCONNECTED | newState: CONNECTED | timestamp: 1595931608223
openvidu-server_1  | [INFO] 2020-07-28 10:20:08,359 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaStateChangedEvent]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | oldState: DISCONNECTED | newState: CONNECTED | timestamp: 1595931608359
openvidu-server_1  | [INFO] 2020-07-28 10:20:08,766 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceGatheringDone] -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | timestamp: 1595931608765
openvidu-server_1  | [INFO] 2020-07-28 10:20:08,911 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t51] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_SEJF_con_HOuyPHvQns (subscriber) | state: READY | componentId: 1 | streamId: 1 | timestamp: 1595931608910
openvidu-server_1  | [INFO] 2020-07-28 10:20:08,911 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceGatheringDone] -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | timestamp: 1595931608910
openvidu-server_1  | [ERROR] 2020-07-28 10:20:08,918 [http-nio-0.0.0.0-5443-exec-3] io.openvidu.server.rpc.RpcHandler - Transport exception for WebSocket session: 6qcdu2burerfl0q5re8nsepvn4 - Exception: null
openvidu-server_1  | [INFO] 2020-07-28 10:20:08,924 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t39] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_YahI_con_H4G5x896sj (subscriber) | state: READY | componentId: 1 | streamId: 1 | timestamp: 1595931608924
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,920 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - After connection closed for WebSocket session: 6qcdu2burerfl0q5re8nsepvn4 - Status: null
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,920 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcNotificationService - Closed session for participant with private id 6qcdu2burerfl0q5re8nsepvn4
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,920 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcNotificationService - <PRIVATE_ID, RPC_CONNECTION>: {hilt6iv5ojm2sce53npma2ehbv=io.openvidu.server.rpc.RpcConnection@383d418d, id1d4p01qu0t15qtv4vc2lj6ep=io.openvidu.server.rpc.RpcConnection@59c3e59}
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,921 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - Evicting participant with private id 6qcdu2burerfl0q5re8nsepvn4 because its websocket unexpectedly closed in the client side
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,921 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoSessionManager - Request [LEAVE_ROOM] for participant RECORDER of session ses_PRvBN0EXIm with reason networkDisconnect
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,921 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoSession - PARTICIPANT RECORDER: Leaving session ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,921 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_H4G5x896sj: cancel receiving media from RECORDER
openvidu-server_1  | [WARN] 2020-07-28 10:20:18,921 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_H4G5x896sj: Trying to cancel receiving video from user RECORDER. But there is no such subscriber endpoint.
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,921 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_HOuyPHvQns: cancel receiving media from RECORDER
openvidu-server_1  | [WARN] 2020-07-28 10:20:18,921 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_HOuyPHvQns: Trying to cancel receiving video from user RECORDER. But there is no such subscriber endpoint.
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,922 [jsonrpcTaskScheduler-1] io.openvidu.server.coturn.CoturnCredentialsService - Deleting COTURN user
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,944 [jsonrpcTaskScheduler-1] io.openvidu.server.coturn.CoturnCredentialsService - COTURN user deleted: true
openvidu-server_1  | [ERROR] 2020-07-28 10:20:18,945 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcNotificationService - No session found for private id 6qcdu2burerfl0q5re8nsepvn4, unable to cleanup
openvidu-server_1  | [INFO] 2020-07-28 10:20:18,945 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - Evicted participant with privateId 6qcdu2burerfl0q5re8nsepvn4
openvidu-server_1  | [WARN] 2020-07-28 10:20:18,945 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - Evicting participant with private id 6qcdu2burerfl0q5re8nsepvn4 because a transport error took place and its web socket connection is now closed
openvidu-server_1  | [WARN] 2020-07-28 10:20:18,945 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - Unable to evict: No participant with private id '6qcdu2burerfl0q5re8nsepvn4' was found. Code: 102
openvidu-server_1  | [INFO] 2020-07-28 10:21:04,498 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.rest.SessionRestController - REST API: POST /api/recordings/stop/ses_PRvBN0EXIm
openvidu-server_1  | [INFO] 2020-07-28 10:21:04,498 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.cdr.CDRLoggerFile - {"recordingStatusChanged":{"sessionId":"ses_PRvBN0EXIm","timestamp":1595931664498,"startTime":1595931604943,"duration":0.0,"reason":"recordingStoppedByServer","id":"ses_PRvBN0EXIm","name":"e64e73dd-d5f2-40a3-a047-a976f4665b94/1595931604644/","outputMode":"COMPOSED","resolution":"1920x1080","recordingLayout":"BEST_FIT","hasAudio":true,"hasVideo":true,"size":0,"status":"stopped"}}
openvidu-server_1  | [INFO] 2020-07-28 10:21:04,498 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.cdr.CDRLoggerFile - {"recordingStopped":{"sessionId":"ses_PRvBN0EXIm","timestamp":1595931664498,"startTime":1595931604943,"duration":0.0,"reason":"recordingStoppedByServer","id":"ses_PRvBN0EXIm","name":"e64e73dd-d5f2-40a3-a047-a976f4665b94/1595931604644/","outputMode":"COMPOSED","resolution":"1920x1080","recordingLayout":"BEST_FIT","hasAudio":true,"hasVideo":true,"size":0}}
openvidu-server_1  | [INFO] 2020-07-28 10:21:04,513 [pool-1-thread-1] io.openvidu.server.webhook.HttpWebhookSender - Event recordingStatusChanged successfully posted to uri https://service.dev.ABC.com.hk/session-events
openvidu-server_1  | [INFO] 2020-07-28 10:21:04,517 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.RecordingService - Sealed recording metadata file at /data/openvidu/recordings/ses_PRvBN0EXIm/.recording.ses_PRvBN0EXIm with status [stopped]
openvidu-server_1  | [INFO] 2020-07-28 10:21:04,517 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.ComposedRecordingService - Stopping composed (video + audio) recording ses_PRvBN0EXIm of session ses_PRvBN0EXIm. Reason: recordingStoppedByServer
openvidu-server_1  | [ERROR] 2020-07-28 10:21:04,533 [http-nio-0.0.0.0-5443-exec-6] org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/].[dispatcherServlet] - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is com.github.dockerjava.api.exception.ConflictException: Container 27c79a239b76dc69814d98b35f56d530221589920ee1ed7607da08cfc63c8470 is not running] with root cause
openvidu-server_1  | com.github.dockerjava.api.exception.ConflictException: Container 27c79a239b76dc69814d98b35f56d530221589920ee1ed7607da08cfc63c8470 is not running
openvidu-server_1  | 	at com.github.dockerjava.jaxrs.filter.ResponseStatusExceptionFilter.filter(ResponseStatusExceptionFilter.java:57)
openvidu-server_1  | 	at org.glassfish.jersey.client.ClientFilteringStages$ResponseFilterStage.apply(ClientFilteringStages.java:133)
openvidu-server_1  | 	at org.glassfish.jersey.client.ClientFilteringStages$ResponseFilterStage.apply(ClientFilteringStages.java:121)
openvidu-server_1  | 	at org.glassfish.jersey.process.internal.Stages.process(Stages.java:171)
openvidu-server_1  | 	at org.glassfish.jersey.client.ClientRuntime.invoke(ClientRuntime.java:283)
openvidu-server_1  | 	at org.glassfish.jersey.client.JerseyInvocation.lambda$invoke$1(JerseyInvocation.java:767)
openvidu-server_1  | 	at org.glassfish.jersey.internal.Errors.process(Errors.java:316)
openvidu-server_1  | 	at org.glassfish.jersey.internal.Errors.process(Errors.java:298)
openvidu-server_1  | 	at org.glassfish.jersey.internal.Errors.process(Errors.java:229)
openvidu-server_1  | 	at ```

micael.gallego · July 29, 2020, 11:23am

The logs show that you are using COMPOSED recording.

But you are configured INVIDUAL recording.

What exactly you want to do?

pabloFuente · July 29, 2020, 11:29am

Yes, something must be wrong if you are initializing the recording with INDIVIDUAL output mode but the composed recording container is being launched,

sreedharbukya · July 30, 2020, 1:58am

@micael.gallego, I have tried to change the values to COMPOSED again and tried to start record.
In this case, we are doing manual recording

 mediaMode: MediaMode.ROUTED,
 recordingMode: RecordingMode.MANUAL,
 defaultOutputMode: OutputMode.COMPOSED

Tried to do recording , here are the logs

[INFO] 2020-07-30 01:57:34,239 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.rest.SessionRestController - REST API: POST /api/recordings/start {session=ses_LHsUujsmlQ, name=27a89472-d423-4ebd-b9e3-900c61d3660a/1596074253868/, outputMode=COMPOSED, hasAudio=true, hasVideo=true, resolution=1920x1080, recordingLayout=BEST_FIT}
[INFO] 2020-07-30 01:57:34,299 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.RecordingService - New recording id (ses_LHsUujsmlQ) and final name (27a89472-d423-4ebd-b9e3-900c61d3660a/1596074253868/)
[INFO] 2020-07-30 01:57:34,299 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.ComposedRecordingService - Starting composed (video + audio) recording ses_LHsUujsmlQ of session ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:34,299 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.ComposedRecordingService - {"id":"ses_LHsUujsmlQ","name":"27a89472-d423-4ebd-b9e3-900c61d3660a/1596074253868/","outputMode":"COMPOSED","resolution":"1920x1080","recordingLayout":"BEST_FIT","sessionId":"ses_LHsUujsmlQ","createdAt":1596074254299,"size":0,"duration":0.0,"url":null,"hasAudio":true,"hasVideo":true,"status":"started"}
[INFO] 2020-07-30 01:57:34,299 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.recording.service.ComposedRecordingService - Recorder connecting to url https://OPENVIDUAPP:tqKn5nA2YYW5pQFP2u5t0@openvidu.dev.coherent.com.hk/dashboard/#/layout-best-fit/ses_LHsUujsmlQ/tqKn5nA2YYW5pQFP2u5t0/-1/false
[INFO] 2020-07-30 01:57:34,494 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.utils.DockerManager - Container ID: 5687f34a65f2f55a05d250624fa554f7396d00ebaf86b2fa2f69b83f86c14057
[INFO] 2020-07-30 01:57:34,649 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.cdr.CDRLoggerFile - {"recordingStarted":{"sessionId":"ses_LHsUujsmlQ","timestamp":1596074254299,"id":"ses_LHsUujsmlQ","name":"27a89472-d423-4ebd-b9e3-900c61d3660a/1596074253868/","outputMode":"COMPOSED","resolution":"1920x1080","recordingLayout":"BEST_FIT","hasAudio":true,"hasVideo":true,"size":0,"duration":0.0}}
[INFO] 2020-07-30 01:57:34,649 [http-nio-0.0.0.0-5443-exec-6] io.openvidu.server.cdr.CDRLoggerFile - {"recordingStatusChanged":{"sessionId":"ses_LHsUujsmlQ","timestamp":1596074254299,"startTime":1596074254299,"duration":0.0,"id":"ses_LHsUujsmlQ","name":"27a89472-d423-4ebd-b9e3-900c61d3660a/1596074253868/","outputMode":"COMPOSED","resolution":"1920x1080","recordingLayout":"BEST_FIT","hasAudio":true,"hasVideo":true,"size":0,"status":"started"}}
[INFO] 2020-07-30 01:57:34,655 [pool-1-thread-1] io.openvidu.server.webhook.HttpWebhookSender - Event recordingStatusChanged successfully posted to uri https://videocallservice.dev.coherent.com.hk/session-events
[INFO] 2020-07-30 01:57:35,754 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.config.HttpHandshakeInterceptor - Old HttpSession 26B0C402D26BA2DF5C3F27DDED6B7093
[INFO] 2020-07-30 01:57:35,770 [http-nio-0.0.0.0-5443-exec-9] io.openvidu.server.rpc.RpcHandler - After connection established for WebSocket session: slmmpbvb9ml3801c427frf75d9
[INFO] 2020-07-30 01:57:35,771 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.coturn.CoturnCredentialsService - Creating COTURN user
[INFO] 2020-07-30 01:57:35,798 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.coturn.CoturnCredentialsService - COTURN user created: true
[INFO] 2020-07-30 01:57:35,799 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.core.Session - Token created for insecure user { Session: ses_LHsUujsmlQ | Tokens: [tok_PuRMGq5KHwnpusIx] }
[INFO] 2020-07-30 01:57:35,800 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.core.Session - Token consumed { Session: ses_LHsUujsmlQ | Tokens: [] }
[INFO] 2020-07-30 01:57:35,800 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.kurento.core.KurentoSession - SESSION ses_LHsUujsmlQ: Added participant [participantPrivateId=slmmpbvb9ml3801c427frf75d9, participantPublicId=RECORDER, streaming=false]
[INFO] 2020-07-30 01:57:35,879 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'subscribe' in session ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:35,879 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Request to receive media from con_LqSObu6Gjn in room ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:35,902 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Is now receiving video from con_LqSObu6Gjn in room ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:35,902 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'subscribe' in session ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:35,902 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Request to receive media from con_X0fJLXOX1g in room ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:35,918 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t942] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: GATHERING | componentId: 1 | streamId: 1 | timestamp: 1596074255911
[INFO] 2020-07-30 01:57:35,955 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t942] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: GATHERING | componentId: 2 | streamId: 1 | timestamp: 1596074255925
[INFO] 2020-07-30 01:57:35,978 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT RECORDER: Is now receiving video from con_X0fJLXOX1g in room ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:35,998 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: GATHERING | componentId: 1 | streamId: 1 | timestamp: 1596074255988
[INFO] 2020-07-30 01:57:36,031 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: GATHERING | componentId: 2 | streamId: 1 | timestamp: 1596074256003
[INFO] 2020-07-30 01:57:36,043 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:36,044 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_LqSObu6Gjn", sdpMid: 0, sdpMLineIndex: 0, candidate: "candidate:2514413131 1 udp 2113937151 10.20.0.94 60661 typ host generation 0 ufrag Wqge network-cost 999"}
[INFO] 2020-07-30 01:57:36,045 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:36,045 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_LqSObu6Gjn", sdpMid: 1, sdpMLineIndex: 1, candidate: "candidate:2514413131 1 udp 2113937151 10.20.0.94 40744 typ host generation 0 ufrag Wqge network-cost 999"}
[INFO] 2020-07-30 01:57:36,047 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: CONNECTING | componentId: 1 | streamId: 1 | timestamp: 1596074256046
[INFO] 2020-07-30 01:57:36,064 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: CONNECTING | componentId: 1 | streamId: 1 | timestamp: 1596074256064
[INFO] 2020-07-30 01:57:36,077 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: CONNECTED | componentId: 1 | streamId: 1 | timestamp: 1596074256077
[INFO] 2020-07-30 01:57:36,078 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: READY | componentId: 1 | streamId: 1 | timestamp: 1596074256077
[INFO] 2020-07-30 01:57:36,078 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [NewCandidatePairSelected]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | local: candidate:1 1 UDP 2015363327 10.20.0.94 47440 typ host | remote: candidate:2514413131 1 UDP 2113937151 10.20.0.94 60661 typ host | timestamp: 1596074256077
[INFO] 2020-07-30 01:57:36,088 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [NewCandidatePairSelected]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | local: candidate:1 1 UDP 2015363327 10.20.0.94 53094 typ host | remote: candidate:remote1 1 UDP 1845501695 10.20.0.94 50115 typ prflx | timestamp: 1596074256088
[INFO] 2020-07-30 01:57:36,089 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: CONNECTED | componentId: 1 | streamId: 1 | timestamp: 1596074256088
[INFO] 2020-07-30 01:57:36,089 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: READY | componentId: 1 | streamId: 1 | timestamp: 1596074256088
[INFO] 2020-07-30 01:57:36,112 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:36,112 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_X0fJLXOX1g", sdpMid: 0, sdpMLineIndex: 0, candidate: "candidate:2514413131 1 udp 2113937151 10.20.0.94 50115 typ host generation 0 ufrag jhJ5 network-cost 999"}
[INFO] 2020-07-30 01:57:36,114 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [NewCandidatePairSelected]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | local: candidate:1 1 UDP 2015363327 10.20.0.94 53094 typ host | remote: candidate:2514413131 1 UDP 2113937151 10.20.0.94 50115 typ host | timestamp: 1596074256113
[INFO] 2020-07-30 01:57:36,115 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - Participant RECORDER is calling method 'onIceCandidate' in session ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:36,115 [SessionHandler-slmmpbvb9ml3801c427frf75d9-e410-t0] io.openvidu.server.rpc.RpcHandler - New candidate received from participant RECORDER: {connectionId: "con_X0fJLXOX1g", sdpMid: 1, sdpMLineIndex: 1, candidate: "candidate:2514413131 1 udp 2113937151 10.20.0.94 36234 typ host generation 0 ufrag jhJ5 network-cost 999"}
[INFO] 2020-07-30 01:57:36,161 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: CONNECTED | componentId: 1 | streamId: 1 | timestamp: 1596074256117
[INFO] 2020-07-30 01:57:36,162 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: READY | componentId: 1 | streamId: 1 | timestamp: 1596074256117
[INFO] 2020-07-30 01:57:36,902 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [ConnectionStateChanged]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | oldState: DISCONNECTED | newState: CONNECTED | timestamp: 1596074256900
[INFO] 2020-07-30 01:57:36,916 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaFlowInStateChange] -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: FLOWING | pad: default | mediaType: AUDIO | timestamp: 1596074256915
[INFO] 2020-07-30 01:57:36,978 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [ConnectionStateChanged]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | oldState: DISCONNECTED | newState: CONNECTED | timestamp: 1596074256977
[INFO] 2020-07-30 01:57:36,998 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaFlowInStateChange] -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: FLOWING | pad: default | mediaType: AUDIO | timestamp: 1596074256998
[INFO] 2020-07-30 01:57:37,097 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaFlowInStateChange] -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: FLOWING | pad: default | mediaType: VIDEO | timestamp: 1596074257096
[INFO] 2020-07-30 01:57:37,168 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaFlowInStateChange] -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: FLOWING | pad: default | mediaType: VIDEO | timestamp: 1596074257167
[INFO] 2020-07-30 01:57:37,413 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaStateChangedEvent]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | oldState: DISCONNECTED | newState: CONNECTED | timestamp: 1596074257412
[INFO] 2020-07-30 01:57:37,488 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [MediaStateChangedEvent]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | oldState: DISCONNECTED | newState: CONNECTED | timestamp: 1596074257487
[ERROR] 2020-07-30 01:57:37,890 [http-nio-0.0.0.0-5443-exec-5] io.openvidu.server.rpc.RpcHandler - Transport exception for WebSocket session: slmmpbvb9ml3801c427frf75d9 - Exception: null
[INFO] 2020-07-30 01:57:37,939 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: CONNECTED | componentId: 1 | streamId: 1 | timestamp: 1596074257938
[INFO] 2020-07-30 01:57:37,939 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceGatheringDone] -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | timestamp: 1596074257938
[INFO] 2020-07-30 01:57:38,019 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t935] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceGatheringDone] -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | timestamp: 1596074258019
[INFO] 2020-07-30 01:57:38,019 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: CONNECTED | componentId: 1 | streamId: 1 | timestamp: 1596074258018
[INFO] 2020-07-30 01:57:39,950 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_CqBM_con_LqSObu6Gjn (subscriber) | state: READY | componentId: 1 | streamId: 1 | timestamp: 1596074259950
[INFO] 2020-07-30 01:57:40,031 [AbstractJsonRpcClientWebSocket-reqResEventExec-e2-t931] io.openvidu.server.kurento.core.KurentoParticipantEndpointConfig - KMS event [IceComponentStateChange]: -> endpoint: RECORDER_str_CAM_G8qV_con_X0fJLXOX1g (subscriber) | state: READY | componentId: 1 | streamId: 1 | timestamp: 1596074260030
[INFO] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - After connection closed for WebSocket session: slmmpbvb9ml3801c427frf75d9 - Status: null
[INFO] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcNotificationService - Closed session for participant with private id slmmpbvb9ml3801c427frf75d9
[INFO] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcNotificationService - <PRIVATE_ID, RPC_CONNECTION>: {j1q0rqdn7ds2bvs5n9q74rr4g0=io.openvidu.server.rpc.RpcConnection@73d04653, ihdin2hr0nne1n8mco71eh8jf3=io.openvidu.server.rpc.RpcConnection@4cd712d5, 94ad6sjhovi47btjvs41pg0nsk=io.openvidu.server.rpc.RpcConnection@445a726d}
[INFO] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - Evicting participant with private id slmmpbvb9ml3801c427frf75d9 because its websocket unexpectedly closed in the client side
[INFO] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoSessionManager - Request [LEAVE_ROOM] for participant RECORDER of session ses_LHsUujsmlQ with reason networkDisconnect
[INFO] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoSession - PARTICIPANT RECORDER: Leaving session ses_LHsUujsmlQ
[INFO] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_LqSObu6Gjn: cancel receiving media from RECORDER
[WARN] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_LqSObu6Gjn: Trying to cancel receiving video from user RECORDER. But there is no such subscriber endpoint.
[INFO] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_X0fJLXOX1g: cancel receiving media from RECORDER
[WARN] 2020-07-30 01:57:47,891 [jsonrpcTaskScheduler-1] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_X0fJLXOX1g: Trying to cancel receiving video from user RECORDER. But there is no such subscriber endpoint.
[INFO] 2020-07-30 01:57:47,892 [jsonrpcTaskScheduler-1] io.openvidu.server.coturn.CoturnCredentialsService - Deleting COTURN user
[INFO] 2020-07-30 01:57:47,909 [jsonrpcTaskScheduler-1] io.openvidu.server.coturn.CoturnCredentialsService - COTURN user deleted: true
[ERROR] 2020-07-30 01:57:47,910 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcNotificationService - No session found for private id slmmpbvb9ml3801c427frf75d9, unable to cleanup
[INFO] 2020-07-30 01:57:47,911 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - Evicted participant with privateId slmmpbvb9ml3801c427frf75d9
[WARN] 2020-07-30 01:57:47,911 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - Evicting participant with private id slmmpbvb9ml3801c427frf75d9 because a transport error took place and its web socket connection is now closed
[WARN] 2020-07-30 01:57:47,911 [jsonrpcTaskScheduler-1] io.openvidu.server.rpc.RpcHandler - Unable to evict: No participant with private id 'slmmpbvb9ml3801c427frf75d9' was found. Code: 102

sreedharbukya · July 30, 2020, 2:02am

I have launched video recording with both mode COMPOSED and INDIVIDUAL.

From my understanding, Recorder user (OV) is created for the session but unable to join the call for starting recording. This is my understanding from both the logs.

Please guide me if I am missing any configuration for recording feature.

I have launched the OV using on premise docker instructions. We are using node 2.15.0 client (app server) and browser (front end)

micael.gallego · July 31, 2020, 2:48pm

Please test the server installation without EFS. It is possible that it can cause some buggy behavior.

sreedharbukya · August 1, 2020, 8:24pm

I have tested the behavior without EFS, The issue is same. I suspect the issue is in RECORDER user is unable to join the call.

I have shared sent logs to your pro support email - pro.support@openvidu.io already because of security concerns.

vipin_mishra · August 2, 2020, 9:59am

This error Also seen but earlier after2.15.0 upgrade it’s gone. I say give a restart in openvidu CE server.
May be it will be remove from temporary memory of server by restart
Thanks

sreedharbukya · August 3, 2020, 5:32am

I am using openvidu 2.15.0 version. Are you also using EFS volume to store recording data?

Issue looks like Recorder user is unable to start/join the session.

Do you have any suggestions to fix it ?

vipin_mishra · August 3, 2020, 12:51pm

No
I’m trying to implement S3 buckets
Thanks

sreedharbukya · August 4, 2020, 9:41am

I have found the issue for this recording being failing!

essentially problem was. I was giving path with directory structure to name of recording.

Case ID + "/" + Date.now() + "/"+"record.mp4".

I am expecting this directory structure to be created by OV Server, but it doesn’t do that. It fails instead.

when I just give simple plain name for recording.

Case ID + "-" + Date.now() +"-"+ "record.mp4".

pabloFuente · August 4, 2020, 11:14am

This is good to know. When giving a recording a custom name, slashes should be avoided. We will update openvidu-server inner checks to ensure this.

Thank you.

vipin_mishra · August 4, 2020, 3:07pm

Nice bro
Thanks for sharing

pabloFuente · September 3, 2020, 10:04am

This is already fixed in master branch. Now recording names must be alphanumeric strings, or a 400 BAD_REQUEST error is returned upon a POST /api/recordings/start call.

Topic		Replies	Views
Recording failed after upgrade to OV 2.16 Issues developing apps	14	639	March 2, 2021
Issue with Recording After Upgrade to 2.15.1 Issues with deployment	9	584	May 12, 2022
Recording is not working on v2.17 Issues developing apps	6	283	October 1, 2021
OpenViduPro 2.15.1: Error during single session recording Issues with deployment	4	373	September 4, 2020
Start and Stop Recordings Issues developing apps	2	347	June 10, 2021

Issue with Recording feature in 2.15.0 version of openvidu version

Related Topics