openvidu
openvidu copied to clipboard
OpenVidu
Hangs after recording error
Describe the bug After seen this in the supervisord log:
[ERROR] 2020-02-18 18:12:33,103 [-5443-exec-8] io.openvidu.server.recording.service.SingleStreamRecordingService (startRecording) - Error waiting for some recorder endpoint to start in session g5gzgg8l3hlg7dy3
Openvidu seems to hangs... every new attempt got this error:
[ERROR] 2020-02-18 19:12:48,632 [r0ch-e688-t0] org.kurento.jsonrpc.internal.JsonRpcHandlerManager (handleRequest) - Exception while processing request {"id":1,"method":"joinRoom","params":{"token":"wss://XXXXXX:4443?sessionId=c5657os4evd8bfc9&token=ekw07qlxc2go2svg&role=MODERATOR&version=2.10.0&turnUsername=TG5IFS&turnCredential=04tatw","session":"c5657os4evd8bfc9","platform":"Chrome 77.0.3865.90 on Linux 64-bit","metadata":"{}","secret":"","recorder":false},"jsonrpc":"2.0"} java.lang.RuntimeException: InterruptedException while trying to acquire lock
a restart of openvidu-server and kurento got everything working again
Expected behavior System should not hang
Wrong current behavior System hangs after recording error
OpenVidu tutorial where to replicate the error Happen in cloud enviroment, cannot replicate
OpenVidu deployment info
- AWS deployment as explained in OpenVidu Docs (https://openvidu.io/docs/deployment/deploying-aws/), version 2.10
Additional context Add any other context about the problem here. For example, attach any useful logs related to the issue.
Here is the full stack for the first error:
[ERROR] 2020-02-18 18:12:43,106 [-5443-exec-8] org.apache.catalina.core.ContainerBase.[Tomcat].[localhost].[/].[dispatcherServlet] (log) - Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.kurento.jsonrpc.JsonRpcException: [KurentoClient] Timeout of 10000 milliseconds waiting from response to request {"id":50962,"method":"subscribe","params":{"type":"Stopped","object":"876faf59-273a-4a14-a117-949fb9b25874_kurento.MediaPipeline/4b4841f7-c300-4862-a8b2-7c8a4a9a0fd0_kurento.RecorderEndpoint","sessionId":"ffdbe3f5-9110-4d18-be1f-bfca5c571f04"},"jsonrpc":"2.0"}] with root cause java.util.concurrent.TimeoutException: null at com.google.common.util.concurrent.AbstractFuture.get(AbstractFuture.java:411) at com.google.common.util.concurrent.AbstractFuture$TrustedFuture.get(AbstractFuture.java:84) at org.kurento.jsonrpc.client.AbstractJsonRpcClientWebSocket.internalSendRequestWebSocket(AbstractJsonRpcClientWebSocket.java:377) at org.kurento.jsonrpc.client.AbstractJsonRpcClientWebSocket$1.internalSendRequest(AbstractJsonRpcClientWebSocket.java:141) at org.kurento.jsonrpc.internal.JsonRpcRequestSenderHelper.sendRequest(JsonRpcRequestSenderHelper.java:75) at org.kurento.jsonrpc.internal.JsonRpcRequestSenderHelper.sendRequest(JsonRpcRequestSenderHelper.java:69) at org.kurento.jsonrpc.client.JsonRpcClient.sendRequest(JsonRpcClient.java:112) at org.kurento.client.internal.transport.jsonrpc.RomClientJsonRpcClient.sendRequest(RomClientJsonRpcClient.java:228) at org.kurento.client.internal.transport.jsonrpc.RomClientJsonRpcClient.subscribe(RomClientJsonRpcClient.java:130) at org.kurento.client.internal.transport.jsonrpc.RomClientJsonRpcClient.subscribe(RomClientJsonRpcClient.java:122) at org.kurento.client.internal.client.RomManager.subscribe(RomManager.java:190) at org.kurento.client.internal.client.RemoteObject.addEventListener(RemoteObject.java:252) at org.kurento.client.internal.client.RemoteObjectInvocationHandler.subscribeEventListener(RemoteObjectInvocationHandler.java:219) at org.kurento.client.internal.client.RemoteObjectInvocationHandler.internalInvoke(RemoteObjectInvocationHandler.java:133) at org.kurento.client.internal.client.DefaultInvocationHandler.invoke(DefaultInvocationHandler.java:39) at com.sun.proxy.$Proxy76.addStoppedListener(Unknown Source) at io.openvidu.server.recording.service.SingleStreamRecordingService.stopRecorderEndpointOfPublisherEndpoint(SingleStreamRecordingService.java:232) at io.openvidu.server.recording.service.SingleStreamRecordingService.stopRecording(SingleStreamRecordingService.java:145) at io.openvidu.server.recording.service.SingleStreamRecordingService.stopRecording(SingleStreamRecordingService.java:132) at io.openvidu.server.recording.service.RecordingService.failStartRecording(RecordingService.java:167) at io.openvidu.server.recording.service.SingleStreamRecordingService.startRecording(SingleStreamRecordingService.java:116) at io.openvidu.server.recording.service.RecordingManager.startRecording(RecordingManager.java:184) at io.openvidu.server.rest.SessionRestController.startRecordingSession(SessionRestController.java:497) at sun.reflect.GeneratedMethodAccessor80.invoke(Unknown Source) 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:220) at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:134) at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:116) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827) at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738) at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85) at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:963) at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:897) at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970) at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:872) at javax.servlet.http.HttpServlet.service(HttpServlet.java:648) at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846) at javax.servlet.http.HttpServlet.service(HttpServlet.java:729) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:230) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:317) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127) at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:115) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:169) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.authentication.www.BasicAuthenticationFilter.doFilterInternal(BasicAuthenticationFilter.java:158) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:121) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.web.filter.CorsFilter.doFilterInternal(CorsFilter.java:96) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:66) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:331) at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:214) at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177) at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346) at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) at org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:89) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:77) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197) at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:192) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:165) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:108) at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:472) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:79) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:349) at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:784) at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:802) at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1410) 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)
And for the next:
[ERROR] 2020-02-18 19:12:48,632 [r0ch-e688-t0] org.kurento.jsonrpc.internal.JsonRpcHandlerManager (handleRequest) - Exception while processing request {"id":1,"method":"joinRoom","params":{"token":"wss://XXXXXX:4443?sessionId=c5657os4evd8bfc9&token=ekw07qlxc2go2svg&role=MODERATOR&version=2.10.0&turnUsername=TG5IFS&turnCredential=04tatw","session":"c5657os4evd8bfc9","platform":"Chrome 77.0.3865.90 on Linux 64-bit","metadata":"{}","secret":"","recorder":false},"jsonrpc":"2.0"} java.lang.RuntimeException: InterruptedException while trying to acquire lock at org.kurento.commons.TimeoutReentrantLock.tryLockTimeout(TimeoutReentrantLock.java:44) at org.kurento.jsonrpc.client.AbstractJsonRpcClientWebSocket.connectIfNecessary(AbstractJsonRpcClientWebSocket.java:844) at org.kurento.jsonrpc.client.AbstractJsonRpcClientWebSocket.internalSendRequestWebSocket(AbstractJsonRpcClientWebSocket.java:352) at org.kurento.jsonrpc.client.AbstractJsonRpcClientWebSocket$1.internalSendRequest(AbstractJsonRpcClientWebSocket.java:141) at org.kurento.jsonrpc.internal.JsonRpcRequestSenderHelper.sendRequest(JsonRpcRequestSenderHelper.java:75) at org.kurento.jsonrpc.internal.JsonRpcRequestSenderHelper.sendRequest(JsonRpcRequestSenderHelper.java:69) at org.kurento.jsonrpc.client.JsonRpcClient.sendRequest(JsonRpcClient.java:112) at org.kurento.client.internal.transport.jsonrpc.RomClientJsonRpcClient.sendRequest(RomClientJsonRpcClient.java:228) at org.kurento.client.internal.transport.jsonrpc.RomClientJsonRpcClient.invoke(RomClientJsonRpcClient.java:117) at org.kurento.client.internal.transport.jsonrpc.RomClientJsonRpcClient.invoke(RomClientJsonRpcClient.java:99) at org.kurento.client.internal.client.RomManager.invoke(RomManager.java:162) at org.kurento.client.internal.client.RemoteObject.invoke(RemoteObject.java:186) at org.kurento.client.internal.client.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:182) at org.kurento.client.internal.client.RemoteObjectInvocationHandler.internalInvoke(RemoteObjectInvocationHandler.java:142) at org.kurento.client.internal.client.DefaultInvocationHandler.invoke(DefaultInvocationHandler.java:39) at com.sun.proxy.$Proxy106.getName(Unknown Source) at io.openvidu.server.kurento.core.KurentoSessionManager.createSession(KurentoSessionManager.java:522) at io.openvidu.server.kurento.core.KurentoSessionManager.joinRoom(KurentoSessionManager.java:99) at io.openvidu.server.rpc.RpcHandler.joinRoom(RpcHandler.java:259) at io.openvidu.server.rpc.RpcHandler.handleRequest(RpcHandler.java:117) at org.kurento.jsonrpc.internal.JsonRpcHandlerManager.handleRequest(JsonRpcHandlerManager.java:128) 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) Caused by: java.lang.InterruptedException: null at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireNanos(AbstractQueuedSynchronizer.java:936) at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireNanos(AbstractQueuedSynchronizer.java:1247) at java.util.concurrent.locks.ReentrantLock.tryLock(ReentrantLock.java:442) at org.kurento.commons.TimeoutReentrantLock.tryLockTimeout(TimeoutReentrantLock.java:38) ... 24 common frames omitted
Hi, Please, could you test this same scenario with openvidu version 2.11.0? If the issue still happens in 2.11.0, we will try to fix it for next release.
I've already try this issue with the master branch of OpenVidu and the server doens't hang.
I'm able to trigger your error io.openvidu.server.recording.service.SingleStreamRecordingService (startRecording) - Error waiting for some recorder endpoint to start in session g5gzgg8l3hlg7dy3 by providing a corrupted video file as an IP camera input source (this feature will be available on release 2.12.0), and when starting individual recording its RecorderEndpoint fails with that same message. But the REST API call simply returns with an error, and the server still works fine.
Maybe you can tell me how to get the error in the same manner as you do? If the error thrown is the same in my case, then the behavior should be the same for both of us. But maybe the way you are getting the error is important for this particular issue.
Hi, This is not a test of my (wish it was!)... it's something that start happening a few times a week, since we start making calls between desktop and mobile (3G/HSDPA/4G cellphone) users. I imagine that can be caused by something like you describe (corrupted video), but I don't have a way to reproduce it. Do you think upgrading to 2.11 will help ? Is there a date for 2.12 ?
Trying 2.11.0 is only to check if a simple upgrade will fix the issue. You know, new releases can fix this kind of bugs. 2.12.0 is coming very soon, we are just finishing the last details. If you can't tell me a way to replicate the issue I'm afraid I can't do much more roght now. I've already tested that whenever that exception is triggered in the master branch, OpenVidu works as expected. But again, maybe the way I trigger the exception is different enough from yours that OpenVidu's behavior is not exactly the same.