Errors stopping recording

OpenVidu v2 Issues developing apps
1

I am getting errors lately when stopping recordings. Below are some examples. I’ve also noticed that if I try to stop a recording that already has a status of ready I get a 404 which doesn’t seem right. Let me know if you need more info. Thanks.

[ERROR] 2020-04-08 22:26:05,776 [0.0-4443-exec-2] 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 java.lang.NullPointerException] with root cause
java.lang.NullPointerException: null
        at io.openvidu.server.recording.service.SingleStreamRecordingService.stopRecorderEndpointOfPublisherEndpoint(SingleStreamRecordingService.java:275)
        at io.openvidu.server.recording.service.RecordingManager.stopOneIndividualStreamRecording(RecordingManager.java:346)
        at io.openvidu.server.kurento.core.KurentoParticipant.releasePublisherEndpoint(KurentoParticipant.java:400)
        at io.openvidu.server.kurento.core.KurentoParticipant.close(KurentoParticipant.java:346)
        at io.openvidu.server.kurento.core.KurentoSession.leave(KurentoSession.java:134)
        at io.openvidu.server.kurento.core.KurentoSessionManager.leaveRoom(KurentoSessionManager.java:162)
        at io.openvidu.server.kurento.core.KurentoSessionManager.evictParticipant(KurentoSessionManager.java:548)
        at io.openvidu.server.core.SessionManager.closeSession(SessionManager.java:447)
        at io.openvidu.server.rest.SessionRestController.closeSession(SessionRestController.java:230)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:888)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793)
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
        at org.springframework.web.servlet.FrameworkServlet.doDelete(FrameworkServlet.java:931)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:666)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:126)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:90)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:118)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:158)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:203)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:92)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:92)
        at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:77)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1598)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)

[ERROR] 2020-04-08 22:26:05,171 [0.0-4443-exec-9] 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 java.lang.NullPointerException] with root cause
java.lang.NullPointerException: null
        at java.util.HashMap.putMapEntries(HashMap.java:501)
        at java.util.HashMap.<init>(HashMap.java:490)
        at io.openvidu.server.recording.service.SingleStreamRecordingService.stopRecording(SingleStreamRecordingService.java:152)
        at io.openvidu.server.recording.service.SingleStreamRecordingService.stopRecording(SingleStreamRecordingService.java:143)
        at io.openvidu.server.recording.service.RecordingManager.stopRecording(RecordingManager.java:283)
        at io.openvidu.server.rest.SessionRestController.stopRecordingSession(SessionRestController.java:570)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:190)
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138)
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:888)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:793)
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1040)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
        at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:660)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:741)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:126)
        at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:90)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:118)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:158)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:203)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:92)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:92)
        at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:77)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334)
        at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215)
        at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178)
        at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:358)
        at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:271)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:541)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:367)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:860)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1598)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.lang.Thread.run(Thread.java:748)
2

Thank you for reporting.

Do you have any way to reproduce the issue please?

3

It’s inconsistent. My use case requires stopping and then immediately restarting recording very often… every 10 to 60 seconds. I’m running into various issues related to this, such as API calls timing out, so I’ll assume recording didn’t start, but then I’ll get a webhook update that the recording is ready.

Sometimes recordings or sessions will get stuck and I won’t even be able to delete them using the API. So I’ll have to restart the video server.

It may just be that I’m pushing my dev machine too hard, but I’m not sure how to troubleshoot this. If I test with just one user, it’s less likely to break. But when I test with 2 users (same machine) I have issues.

I have the same issues on AWS even with just 2 users, but not as often.

Thanks.

4

What kind of recordings are you using? COMPOSED or INDIVIDUAL? Can you share with us CPU load when issues arise?

5

I am using individual recordings. My CPU is at around 60-70% when this happens. It seems to be around there the whole time I’m running a session, not just when it breaks. My test session has 2 participants. The error seems to happen pretty consistently when stopping the recording the second time… start, stop, start, stop… 500 error.

Even though I get the 500 error, I still get the recording status webhook with a status of stopped.

Another thing that’s weird is that I use the stopped webhook to fire off a API call to start another recording. When I do this I get a 409 error which the docs says means the session is already being recorded. I then use the API to pull all recordings… there are two… one is ready and the other is stopped. So I’m confused as to why I’m getting the 409.

I am running everything on my local machine… MacBook Pro w/ 16g RAM.

Below are the video server logs around the error. Let me know if you need more or anything else. Thanks again.

2020-04-21 19:03:12,352 DEBG 'kms' stdout output:
0:08:02.202595400     8 0x7fa184007b90 DEBUG   KurentoWebSocketTransport WebSocketTransport.cpp:460:processMessage: Message: {"id":192,"method":"release","params":{"object":"5f7e6cc1-462d-4cdb-9a5b-1bde52159554_kurento.MediaPipeline/703ec984-6c22-473e-b53c-1279c2514067_kurento.WebRtcEndpoint","sessionId":"03e72dce-15c3-4d81-851a-5566d040bc36"},"jsonrpc":"2.0"}

2020-04-21 19:03:12,353 DEBG 'kms' stdout output:
0:08:02.203002100     8 0x7fa184007b90 DEBUG   KurentoWebSocketTransport WebSocketTransport.cpp:462:processMessage: Response: {"id":192,"jsonrpc":"2.0","result":{"sessionId":"03e72dce-15c3-4d81-851a-5566d040bc36"}}
0:08:02.203463800     8 0x7fa18c0018f0 DEBUG   KurentoMediaElementImpl MediaElementImpl.cpp:1056:disconnect: Disconnecting 5f7e6cc1-462d-4cdb-9a5b-1bde52159554_kurento.MediaPipeline/ce2f327f-e952-4d1e-b0bb-e76a185e6d5c_kurento.PassThrough - con_E2I9xdiP2t_str_CAM_EOzs_con_He209H9rAw params AUDIO default default

2020-04-21 19:03:12,354 DEBG 'kms' stdout output:
0:08:02.203946600     8 0x7fa18c0018f0 DEBUG   KurentoMediaElementImpl MediaElementImpl.cpp:1056:disconnect: Disconnecting 5f7e6cc1-462d-4cdb-9a5b-1bde52159554_kurento.MediaPipeline/ce2f327f-e952-4d1e-b0bb-e76a185e6d5c_kurento.PassThrough - con_E2I9xdiP2t_str_CAM_EOzs_con_He209H9rAw params DATA default default
0:08:02.204097500     8 0x7fa18c0018f0 DEBUG   KurentoMediaElementImpl MediaElementImpl.cpp:1056:disconnect: Disconnecting 5f7e6cc1-462d-4cdb-9a5b-1bde52159554_kurento.MediaPipeline/ce2f327f-e952-4d1e-b0bb-e76a185e6d5c_kurento.PassThrough - con_E2I9xdiP2t_str_CAM_EOzs_con_He209H9rAw params VIDEO default default

2020-04-21 19:03:12,355 DEBG 'kms' stdout output:
0:08:02.204823100     8 0x7fa18c0018f0 DEBUG        KurentoMediaSet MediaSet.cpp:470:async_delete: Destroying WebRtcEndpoint -> 5f7e6cc1-462d-4cdb-9a5b-1bde52159554_kurento.MediaPipeline/703ec984-6c22-473e-b53c-1279c2514067_kurento.WebRtcEndpoint

2020-04-21 19:03:12,360 DEBG 'openvidu-server' stdout output:
[INFO] 2020-04-21 19:03:12,358 [kdmruemmi-e5-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_E2I9xdiP2t: stopped receiving media from con_He209H9rAw in room 1587495648-t-1-r-1-m-1

2020-04-21 19:03:12,362 DEBG 'openvidu-server' stdout output:
[WARN] 2020-04-21 19:03:12,359 [kdmruemmi-e5-t0] io.openvidu.server.kurento.core.KurentoParticipant - PARTICIPANT con_He209H9rAw: Trying to close subscriber endpoint to con_E2I9xdiP2t. But the endpoint was never instantiated.

2020-04-21 19:03:12,362 DEBG 'openvidu-server' stdout output:
[INFO] 2020-04-21 19:03:12,361 [kdmruemmi-e5-t0] io.openvidu.server.recording.service.RecordingManager - Stopping RecorderEndpoint in session 1587495648-t-1-r-1-m-1 for stream of participant str_CAM_EOzs_con_He209H9rAw
[INFO] 2020-04-21 19:03:12,362 [kdmruemmi-e5-t0] io.openvidu.server.recording.service.SingleStreamRecordingService - Stopping single stream recorder for stream str_CAM_EOzs_con_He209H9rAw in session 1587495648-t-1-r-1-m-1

2020-04-21 19:03:12,363 DEBG 'openvidu-server' stdout output:
[ERROR] 2020-04-21 19:03:12,362 [kdmruemmi-e5-t0] org.kurento.jsonrpc.internal.JsonRpcHandlerManager - Exception while processing request {"id":45,"method":"leaveRoom","params":{},"jsonrpc":"2.0"}
java.lang.NullPointerException: null
        at io.openvidu.server.recording.service.SingleStreamRecordingService.stopRecorderEndpointOfPublisherEndpoint(SingleStreamRecordingService.java:275)
        at io.openvidu.server.recording.service.RecordingManager.stopOneIndividualStreamRecording(RecordingManager.java:346)
        at io.openvidu.server.kurento.core.KurentoParticipant.releasePublisherEndpoint(KurentoParticipant.java:400)
        at io.openvidu.server.kurento.core.KurentoParticipant.close(KurentoParticipant.java:346)
        at io.openvidu.server.kurento.core.KurentoSession.leave(KurentoSession.java:134)
        at io.openvidu.server.kurento.core.KurentoSessionManager.leaveRoom(KurentoSessionManager.java:162)
        at io.openvidu.server.rpc.RpcHandler.leaveRoom(RpcHandler.java:308)
        at io.openvidu.server.rpc.RpcHandler.handleRequest(RpcHandler.java:121)
        at org.kurento.jsonrpc.internal.JsonRpcHandlerManager.handleRequest(JsonRpcHandlerManager.java:142)
        at org.kurento.jsonrpc.internal.server.ProtocolManager$3.run(ProtocolManager.java:218)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

2020-04-21 19:03:15,212 DEBG 'openvidu-server' stdout output:
[INFO] 2020-04-21 19:03:15,211 [amtbfjadc-e4-t0] io.openvidu.server.rpc.RpcHandler - Participant con_E2I9xdiP2t is calling method 'disconnect' in session 1587495648-t-1-r-1-m-1

2020-04-21 19:03:15,212 DEBG 'openvidu-server' stdout output:
[INFO] 2020-04-21 19:03:15,211 [amtbfjadc-e4-t0] io.openvidu.server.core.Session - PARTICIPANT con_E2I9xdiP2t: Leaving session 1587495648-t-1-r-1-m-1
[INFO] 2020-04-21 19:03:15,212 [amtbfjadc-e4-t0] io.openvidu.server.recording.service.RecordingManager - Stopping RecorderEndpoint in session 1587495648-t-1-r-1-m-1 for stream of participant str_CAM_HgMS_con_E2I9xdiP2t
[INFO] 2020-04-21 19:03:15,212 [amtbfjadc-e4-t0] io.openvidu.server.recording.service.SingleStreamRecordingService - Stopping single stream recorder for stream str_CAM_HgMS_con_E2I9xdiP2t in session 1587495648-t-1-r-1-m-1

2020-04-21 19:03:15,214 DEBG 'openvidu-server' stdout output:
[ERROR] 2020-04-21 19:03:15,212 [amtbfjadc-e4-t0] org.kurento.jsonrpc.internal.JsonRpcHandlerManager - Exception while processing request {"id":110,"method":"leaveRoom","params":{},"jsonrpc":"2.0"}
java.lang.NullPointerException: null
        at io.openvidu.server.recording.service.SingleStreamRecordingService.stopRecorderEndpointOfPublisherEndpoint(SingleStreamRecordingService.java:275)
        at io.openvidu.server.recording.service.RecordingManager.stopOneIndividualStreamRecording(RecordingManager.java:346)
        at io.openvidu.server.kurento.core.KurentoParticipant.releasePublisherEndpoint(KurentoParticipant.java:400)
        at io.openvidu.server.kurento.core.KurentoParticipant.close(KurentoParticipant.java:346)
        at io.openvidu.server.kurento.core.KurentoSession.leave(KurentoSession.java:134)
        at io.openvidu.server.kurento.core.KurentoSessionManager.leaveRoom(KurentoSessionManager.java:162)
        at io.openvidu.server.rpc.RpcHandler.leaveRoom(RpcHandler.java:308)
        at io.openvidu.server.rpc.RpcHandler.handleRequest(RpcHandler.java:121)
        at org.kurento.jsonrpc.internal.JsonRpcHandlerManager.handleRequest(JsonRpcHandlerManager.java:142)
        at org.kurento.jsonrpc.internal.server.ProtocolManager$3.run(ProtocolManager.java:218)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
        at java.lang.Thread.run(Thread.java:748)

2020-04-21 19:03:15,347 DEBG 'openvidu-server' stdout output:
[INFO] 2020-04-21 19:03:15,346 [0.0-4443-exec-4] io.openvidu.server.config.HttpHandshakeInterceptor - Old HttpSession 8176F44AA07045892004B15F113E5C2A

2020-04-21 19:03:15,385 DEBG 'openvidu-server' stdout output:
[INFO] 2020-04-21 19:03:15,384 [0.0-4443-exec-8] io.openvidu.server.rpc.RpcHandler - After reconnection for WebSocket session: 670vemd1r8dm4oj3camtbfjadc

2020-04-21 19:03:15,425 DEBG 'openvidu-server' stdout output:
[INFO] 2020-04-21 19:03:15,425 [0.0-4443-exec-9] io.openvidu.server.config.HttpHandshakeInterceptor - Old HttpSession 8176F44AA07045892004B15F113E5C2A

2020-04-21 19:03:18,269 DEBG 'kms' stdout output:
0:08:08.119508800     8 0x7fa16c001930 DEBUG   KurentoWebSocketTransport WebSocketTransport.cpp:460:processMessage: Message: {"id":193,"method":"ping","jsonrpc":"2.0","params":{"sessionId":"03e72dce-15c3-4d81-851a-5566d040bc36"}}
0:08:08.119686100     8 0x7fa16c001930 INFO    KurentoServerMethods ServerMethods.cpp:814:ping: WebSocket Ping/Pong with sessionId 03e72dce-15c3-4d81-851a-5566d040bc36

2020-04-21 19:03:18,270 DEBG 'kms' stdout output:
0:08:08.119863700     8 0x7fa16c001930 DEBUG   KurentoWebSocketTransport WebSocketTransport.cpp:462:processMessage: Response: {"id":193,"jsonrpc":"2.0","result":{"sessionId":"03e72dce-15c3-4d81-851a-5566d040bc36","value":"pong"}}
6

Doing some more testing I’m seeing that sometimes after receiving the webhook with recording status of stopped if I immediately make an API call to get the recording, it has a status of started.

So it seems to be a timing issue. The status in the webhook is updated before the status returned by the /recordings API endpoint. The delay may only be a few seconds, but it’s enough to cause the 409 if you try to start a recording immediately when receiving stopped in the webhook.

EDIT: just did some more testing and it can actually last much longer. I tried pausing after stopped before restarting for as much as 30 seconds and still get the 409 and a status of started even though I’ve already gotten stopped in the webhook.

It seems like 409 happens if the video is being processed (ie. set to ready status). Once it’s set to ready everything is ok. Should 409 happen if a recording has status of stopped and is being processed?

7

Thank you for the detailed analysis.

We will focus on bug fixing just after we release 2.13 version (tomorrow).

8

Hi,

We’ve actually found a bug that was causing the webhook “stopped” recordingStatusChanged event to be sent before the recording metadata on disk was updated, ledding to a discordance between these 2 data sources. This has already been addresed in master branch.

Regarding the 409 CONFLICT error when trying to start the recording of a session with an active recording in “stopped” status: the 409 error should only be returned in case the new recording cannot be initalized with guarantees. This doesn’t mean that the you must wait to “ready” status. With INDIVIDUAL recordings it is true that there may be a short time period when the previous recording is “stopped” and a new recording cannot be initiated, but that shouldn’t be longer than a short moment. The post-processing period through which INDIVIDUAL recordings pass is just a download process to the master node in OpenVidu Pro. And during this time new recordings can be started (not needed to wait until the downloading process has finished and recording status is set to “ready”).

9

Thanks for looking into that. I’ve actually changed this part of my app since I reported this and am no longer starting and stopping as often/quickly, so I haven’t been seeing this issue. If I see it again I will let you know.