OVP 2.22.0 Delay in Starting Recording : Intermittent Issue [14-15 Sec to Start Recording]

[mallikarjungurav]

Describe the bug
We have a Java based service application which makes use of OVP 2.22.0 start recording API (/recordings/start) to start the recording. Once we hit this start recording API we expect to get quick response back from OVP where recording would start eventually. However, most of the times, we get quick response within milliseconds and sometimes we get response back in 2-3 seconds which works for our business case.

But intermittently, sometimes, it takes 14-15 seconds to give response back and after 15 seconds the recording would start at OVP end.
We need to understand why this much of delay in starting the recording? We don’t have exact steps to reproduce the behavior since its intermittent issue.

Expected behavior
Recording should start within milliseconds or max 2~3 seconds.

Wrong current behavior
Taking about 15 seconds to start recording intermittently for few sessions.

OpenVidu tutorial where to replicate the error
Since this is an intermittent issue, there are no particular steps involved to reproduce the issue. We have seen this issue with 2 way audio-video session where 2 participants [both publisher] are in a session.

OpenVidu deployment info
How is your OpenVidu Server instance deployed when you get the bug. A couple of possible examples are listed below:

• Docker container as explained in OpenVidu tutorials, run with command docker run ... on macOS Catalina 10.15.1
• AWS deployment as explained in OpenVidu Docs (https://docs.openvidu.io/en/stable/deployment/deploying-aws/)

IMPORTANT NOTE: please, if you think the bug might be related to OpenVidu Server side, specify here if you are also getting the error by using OpenVidu Server Demos instance. This instance is publicly available (use it only for this test, because it is not secure!!!): URL: https://demos.openvidu.io:4443, SECRET: MY_SECRET

Client device info (if applicable)
Any android or iPhone device.

Screenshots
If applicable, add screenshots to help explain your problem.

Additional context
Add any other context about the problem here. For example, attach any useful logs related to the issue.

[pabloFuente]

Is this issue related to COMPOSED or INDIVIDUAL recording?

[mallikarjungurav]

It was produced with both COMOSED_QUICK_STSRT and INDIVIDUAL recording.

[pabloFuente]

For INDIVIDUAL recording, the problem with the timeout could be caused by this simple reason: if the streams to be recorded are not sending data to the media server yet, the recording process will wait for it (and throw an error in 10 seconds if no data is received any some of the streams to be recorded). You can use recording property ignoreFailedStreams to simply ignore streams that have no data yet (they will be recorded as soon as media reaches the media server, but you won't know which stream is being recorded and which isn't). You can check out this property here: https://docs.openvidu.io/en/2.23.0/reference-docs/REST-API/#post-recording-start

For COMPOSED recording, if it is not a simple problem of resources (CPU load, disk space), I really don't know what could be happening. COMPOSED recording returns the API call just after the video file has been created and its size is greater than 0 bytes. In this case it doesn't even matter if the recording module is actually receiving the actual media stream from the publishers of the session: whenever the MP4 file exists and has at least 1 byte of data, the response to /openvidu/api/recordings/start is sent back.

[mallikarjungurav]

I understand the meaning of the flag "ignoreFailedStreams" and I do use that flag. I even understand that if OVP is not receiving the data to start recording, due to this "ignoreFailedStreams" flag, OVP waits to get that data in order to start recording.

In case of COMPOSED recording, you said this flag doesn't wait to get data and starts recording once OVP receives start recording API call? If so then in the case where I have emailed you the OVP sessionId "ses_IgkU112JM2", why recording has started after 15 seconds of time?
I have also attached OVP logs in that email to prove that the time elapsed between API request received and response timestamp when recording was started. Could you please analyse the OVP logs and comment your thoughts on it please?

[peprberlin]

Openvidu Pro - Version 2.23.0 - on Debian 11

We have also observed this problem and can contribute the following observations.

We have had this problem for some time (since version 2.22.0) and often have the first recording broken in our sessions.

This problem only occurs sporadically for us, mostly when there is a day in between a restart.
We have analysed the chrome.debug and with the faulty recordings the chrome seems to try an update.
Other recordings then run without errors and have no update calls in chrome.debug log.

This part of log is only found in the delayed recording
.... [50:50:1006/072517.281003:VERBOSE1:request_sender.cc(181)] Request completed from url: https://update.googleapis.com/service/update2/json [87:103:1006/072517.281961:VERBOSE1:network_delegate.cc(34)] NetworkDelegate::NotifyBeforeURLRequest: http://edgedl.me.gvt1.com/edgedl/chromewebstore/L2Nocm9tZV9leHRlbnNpb24vYmxvYnMvODJiQUFYYVJaZ0k5di1hUFlXS1prX2xDZw/1.0.0.13_llkgjffcdpffmhiakmfcdcblohccpfmo.crx [50:50:1006/072517.312852:VERBOSE1:url_fetcher_downloader.cc(136)] url fetcher response started for: http://edgedl.me.gvt1.com/edgedl/chromewebstore/L2Nocm9tZV9leHRlbnNpb24vYmxvYnMvODJiQUFYYVJaZ0k5di1hUFlXS1prX2xDZw/1.0.0.13_llkgjffcdpffmhiakmfcdcblohccpfmo.crx [50:50:1006/072517.313900:VERBOSE1:url_fetcher_downloader.cc(113)] Downloaded 2876 bytes in 32ms from http://edgedl.me.gvt1.com/edgedl/chromewebstore/L2Nocm9tZV9leHRlbnNpb24vYmxvYnMvODJiQUFYYVJaZ0k5di1hUFlXS1prX2xDZw/1.0.0.13_llkgjffcdpffmhiakmfcdcblohccpfmo.crx to /tmp/.com.google.Chrome.9yy80Y/1.0.0.13_llkgjffcdpffmhiakmfcdcblohccpfmo.crx [50:70:1006/072517.314310:VERBOSE1:component_unpacker.cc(57)] Verifying component: /tmp/.com.google.Chrome.9yy80Y/1.0.0.13_llkgjffcdpffmhiakmfcdcblohccpfmo.crx [50:70:1006/072517.315058:VERBOSE1:component_unpacker.cc(75)] Verification successful: /tmp/.com.google.Chrome.9yy80Y/1.0.0.13_llkgjffcdpffmhiakmfcdcblohccpfmo.crx [50:70:1006/072517.315184:VERBOSE1:component_unpacker.cc(88)] Unpacking in: /tmp/.com.google.Chrome.zW1jAZ [50:70:1006/072517.331659:VERBOSE1:component_unpacker.cc(101)] Unpacked successfully [50:70:1006/072517.332117:VERBOSE1:component_installer.cc(129)] Install: version=1.0.0.13 current version=0.0.0.0 [50:70:1006/072517.332174:VERBOSE1:component_installer.cc(147)] unpack_path=/tmp/.com.google.Chrome.zW1jAZ install_path=/root/.config/google-chrome/OriginTrials/1.0.0.13 [50:50:1006/072517.332349:VERBOSE1:component_installer.cc(463)] Component ready, version 1.0.0.13 in /root/.config/google-chrome/OriginTrials/1.0.0.13 [87:103:1006/072517.333138:VERBOSE1:network_delegate.cc(34)] NetworkDelegate::NotifyBeforeURLRequest: https://update.googleapis.com/service/update2/json ....

[pabloFuente]

Hello @peprberlin

Thank you for your comment. After a little research I have found a rather obscure Chromium flag that seems to disable automatic component updates: --disable-component-update. I am thinking that adding it to the list of flags used to launch the dockerized recording browser may help with this issue.

This commit introduces these changes in the master branch: 74e68ea

I have created a new openvidu-recording image with these new flags. I have also created it based on the last LTS Ubuntu 22.04, instead of basing it on Ubuntu 20.04. For the first tests I have performed, everything seems to be working smoothly.

Please, give it a try and come back with your thoughts. To use this new recording container, pass configuration parameter:

-DOPENVIDU_RECORDING_VERSION=2.24.0-beta1

[peprberlin]

Hello,
thank you very much for the prompt reply. Unfortunately the import of the docker image did not work in our test version.
We are running the CE version (2.23.0) on the test server.
We have added in the .env file this line:
OPENVIDU_RECORDING_VERSION=2.24.0-beta1

In the logfile it seems that openvidu tries to download the new version. But here comes an error.
Extract from the logfile (openvidu-server.log) - somehow contradicting itself.
`
...
Oct 7 09:21:02 vs02 openvidu/openvidu-server/2.23.0[3619289]: [INFO] 2022-10-07 07:21:02,101 [main] io.openvidu.server.recording.service.RecordingManager - Recording module required: Downloading openvidu/openvidu-recording:2.24.0-beta1 Docker image (350MB aprox)

Oct 7 09:21:02 vs02 openvidu/openvidu-server/2.23.0[3619289]: [INFO] 2022-10-07 07:21:02,145 [Thread-1] io.openvidu.server.recording.service.RecordingManager - Downloading

Oct 7 09:21:36 vs02 openvidu/openvidu-server/2.23.0[3619289]: ..................................[INFO] 2022-10-07 07:21:36,009 [main] io.openvidu.server.utils.DockerManager - Error on Pulling 'openvidu/openvidu-recording:2.24.0-beta1' image. Probably because the user has stopped the execution

Oct 7 09:21:36 vs02 openvidu/openvidu-server/2.23.0[3619289]: [ERROR] 2022-10-07 07:21:36,010 [main] io.openvidu.server.recording.service.RecordingManager - Error downloading docker image openvidu/openvidu-recording:2.24.0-beta1

Oct 7 09:21:36 vs02 openvidu/openvidu-server/2.23.0[3619289]: [INFO] 2022-10-07 07:21:36,010 [Thread-1] io.openvidu.server.recording.service.RecordingManager -

Oct 7 09:21:36 vs02 openvidu/openvidu-server/2.23.0[3619289]: Download complete

Oct 7 09:21:36 vs02 openvidu/openvidu-server/2.23.0[3619289]: [INFO] 2022-10-07 07:21:36,010 [main] io.openvidu.server.recording.service.RecordingManager - Docker image available
...
`

Later when trying to start record:

`
...

Oct 7 09:23:13 vs02 openvidu/openvidu-server/2.23.0[3619289]: [ERROR] 2022-10-07 07:23:13,166 [http-nio-0.0.0.0-5443-exec-9] io.openvidu.server.utils.DockerManager - Docker image openvidu/openvidu-recording:2.24.0-beta1 couldn't be found in docker host

Oct 7 09:23:13 vs02 openvidu/openvidu-server/2.23.0[3619289]: [ERROR] 2022-10-07 07:23:13,166 [http-nio-0.0.0.0-5443-exec-9] io.openvidu.server.recording.service.RecordingService - Recording start failed for session ca579c46-76cf-4efe-a83a-e394e550d831: Couldn't initialize recording container. Error: Status 404: No such image: openvidu/openvidu-recording:2.24.0-beta1
...
`
we tried this 3 times.

On our productive system ( PRO - version - 1 master node with 3 media nodes) we have not tested it yet.
Is it correct that we have to include the changes in the /opt/kms/docker-compose.yml for the media-nodes.
Do we need to put this in the .env of the master server as well?

[pabloFuente]

Try forcing a docker pull openvidu/openvidu-recording:2.24.0-beta1 in your server's terminal before launching OpenVidu. I think that was just a transient networking problem.

[peprberlin]

Hello,

now it seems to work. First recording after complete re-setup now went smoothly. Next week we will try this on the productive pro system and will report then.

thx

[pabloFuente]

Nice to hear. Cloing the issue for now. If this problem keeps happening with INDIVIDUAL recodings, it will be better to open a different issue to track it on its own.

[mallikarjungurav]

Hi @pabloFuente

This issue was raised by us and we are still facing this issue. @peprberlin just tried to help us with the issue as they too faced the similar issue. As the issue is still there, so please open the original issue so that we can keep a track on it.

[pabloFuente]

Just to be clear, you stated that the problem appeared with COMPOSED_QUICK_START recording and with INDIVIDUAL recording. If you can test COMPOSED_QUICK_START recording with the new openvidu-recording container, we may be able to consider the issue fixed for COMPOSED recordings (quick start uses the same module as regular composed). And as I said, if the problem still persists with INDIVIDUAL recordings, then we can open a new issue dedicated specifically to it.

[mallikarjungurav]

That's correct. Problem is faced both with COMPOSED_QUICK_START recording and INDIVIDUAL recording. We are working on it and will update you with the results.

[mallikarjungurav]

@pabloFuente

We have tested and analysed the chrome debug logs and in our case where start recording (COMPOSED_QUICK_START) is delayed by 14~15 sec, chrome browser was not updating. So the flag change --disable-component-update will not help us.

Also we are facing delay in start recording API which is different issue than @peprberlin where complete recording was broken.
Could you please advice and reopen the issue again?

[mallikarjungurav]

@pabloFuente

Could you please reopen the issue to analyse more from OVP side?

[mallikarjungurav]

@pabloFuente

Could you please update any findings with this issue?