RPCNotificationService exception with closed ws

Issues developing apps
1

Hi,

We have some strange logs related with websocket sessions, when this exception is thrown the thumbnail is not created in participant. Any ideas?

 [INFO] 2020-04-28 11:43:02,568 [4ilbdl3-e136-t0] io.openvidu.server.kurento.core.KurentoSession - SESSION app_9574: Added participant [participantPrivateId=o9e45ua8sojqibut1m04ilbdl3, participantPublicId=con_DM7duhSSCX, streaming=false]
    [INFO] 2020-04-28 11:43:02,568 [4ilbdl3-e136-t0] io.openvidu.server.cdr.CDRLoggerFile - {"participantJoined":{"sessionId":"app_9574","timestamp":1588074182568,"participantId":"con_DM7duhSSCX","location":"unknown","platform":"Chrome 81.0.4044.129 on Windows 10 64-bit","clientData":"","serverData":"{\"userName\": \"Fuentes\", \"role\": \"PUBLISHER\", \"participantId\": \"5ea7db624b02c238b531ae55\"}"}}
    [INFO] 2020-04-28 11:43:02,642 [4ilbdl3-e136-t0] io.openvidu.server.webhook.HttpWebhookSender - Event participantJoined successfully posted to uri https://apicmp.fffffff.com/cdr/webhook
    [ERROR] 2020-04-28 11:43:02,642 [4ilbdl3-e136-t0] io.openvidu.server.rpc.RpcNotificationService - Exception sending notification 'participantJoined': {"id":"con_DM7duhSSCX","createdAt":1588074182568,"metadata":"{\"userName\": \"Fuentes\", \"role\": \"PUBLISHER\", \"participantId\": \"5ea7db624b02c238b531ae55\"}"} to participant with private id tmja8omealu4qkiil4rmeg3ln6
    org.kurento.commons.exception.KurentoException: Exception while sending message '{"method":"participantJoined","params":{"id":"con_DM7duhSSCX","createdAt":1588074182568,"metadata":"{\"userName\": \"Fuentes\", \"role\": \"PUBLISHER\", \"participantId\": \"5ea7db624b02c238b531ae55\"}"},"jsonrpc":"2.0"}' to websocket with native sessionId '6100d391-78f1-206d-c415-986ed0521fed'
    	at org.kurento.jsonrpc.internal.ws.WebSocketServerSession.sendRequestWebSocket(WebSocketServerSession.java:123)
    	at org.kurento.jsonrpc.internal.ws.WebSocketServerSession.access$000(WebSocketServerSession.java:49)
    	at org.kurento.jsonrpc.internal.ws.WebSocketServerSession$1.internalSendRequest(WebSocketServerSession.java:74)
    	at org.kurento.jsonrpc.internal.JsonRpcRequestSenderHelper.sendRequest(JsonRpcRequestSenderHelper.java:75)
    	at org.kurento.jsonrpc.internal.JsonRpcRequestSenderHelper.sendNotification(JsonRpcRequestSenderHelper.java:156)
    	at org.kurento.jsonrpc.internal.server.ServerSession.sendNotification(ServerSession.java:121)
    	at io.openvidu.server.rpc.RpcNotificationService.sendNotification(RpcNotificationService.java:105)
    	at io.openvidu.server.core.SessionEventsHandler.onParticipantJoined(SessionEventsHandler.java:152)
    	at io.openvidu.server.kurento.core.KurentoSessionManager.joinRoom(KurentoSessionManager.java:160)
    	at io.openvidu.server.rpc.RpcHandler.joinRoom(RpcHandler.java:276)
    	at io.openvidu.server.rpc.RpcHandler.handleRequest(RpcHandler.java:118)
    	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)
    Caused by: java.lang.IllegalStateException: The WebSocket session [2c] has been closed and no method (apart from close()) may be called on a closed session
    	at org.apache.tomcat.websocket.WsSession.checkState(WsSession.java:836)
2

What thumbnail? Are you referring to OpenVidu Call application?

Do you have any way to reproduce the error?

3

This was related to: https://github.com/OpenVidu/openvidu/issues/455

4

Then, lets way if the other issue solves this one. Please test it when openvidu-server alpha container is published.

5

Hi Michael,

Unfortunately these errors have not disappeared with the last openvidu-server alpha container.

I don’t know how to debug it. I attached logs from today: https://drive.google.com/open?id=1Fznp4I92x38VMwgBzdICLS6bt1L6rUVG

Any indication will be appreciated.

BR,
Alberto

6

In that logs we see at least two strange lines:

line 3044: [ERROR] 2020-05-04 08:00:58,008 [0.0-4443-exec-3] io.openvidu.server.rpc.RpcHandler - Transport exception for WebSocket session: h7p93l8q8afqgkpumg6643tspr - Exception: Unable to unwrap data, invalid status [CLOSED]

We also see that OV tries to send a message (JSONRPC) to a closed session … (concurrent problem??)

image
image2040×372 131 KB

7

Maybe is better follow this issue in github: https://github.com/OpenVidu/openvidu/issues/459

8 
2020-06-09T07:10:24.356450448Z [ERROR] 2020-06-09 07:10:24,356 [TaskScheduler-1] io.openvidu.server.rpc.RpcNotificationService - Exception sending notification 'participantLeft': {"connectionId":"con_XXXXXX","reason":"networkDisconnect"} to participant with private id xxxxxxxxxxxxxxx
2020-06-09T07:10:24.356465126Z org.kurento.commons.exception.KurentoException: Exception while sending message '{"method":"participantLeft","params":{"connectionId":"con_XXXXXX","reason":"networkDisconnect"},"jsonrpc":"2.0"}' to websocket with native sessionId 'xxxxxxxxx-xxxxx-xxxx-xxxx'
2020-06-09T07:10:24.356471002Z  at org.kurento.jsonrpc.internal.ws.WebSocketServerSession.sendRequestWebSocket(WebSocketServerSession.java:123)
2020-06-09T07:10:24.356475656Z  at org.kurento.jsonrpc.internal.ws.WebSocketServerSession.access$000(WebSocketServerSession.java:49)
2020-06-09T07:10:24.356480179Z  at org.kurento.jsonrpc.internal.ws.WebSocketServerSession$1.internalSendRequest(WebSocketServerSession.java:74)
2020-06-09T07:10:24.356484302Z  at org.kurento.jsonrpc.internal.JsonRpcRequestSenderHelper.sendRequest(JsonRpcRequestSenderHelper.java:75)
2020-06-09T07:10:24.356488498Z  at org.kurento.jsonrpc.internal.JsonRpcRequestSenderHelper.sendNotification(JsonRpcRequestSenderHelper.java:156)
2020-06-09T07:10:24.356492392Z  at org.kurento.jsonrpc.internal.server.ServerSession.sendNotification(ServerSession.java:121)
2020-06-09T07:10:24.356496311Z  at io.openvidu.server.rpc.RpcNotificationService.sendNotification(RpcNotificationService.java:105)
2020-06-09T07:10:24.356500137Z  at io.openvidu.server.core.SessionEventsHandler.onParticipantLeft(SessionEventsHandler.java:181)
2020-06-09T07:10:24.356504123Z  at io.openvidu.server.kurento.core.KurentoSessionManager.leaveRoom(KurentoSessionManager.java:247)
2020-06-09T07:10:24.356516953Z  at io.openvidu.server.kurento.core.KurentoSessionManager.evictParticipant(KurentoSessionManager.java:628)
2020-06-09T07:10:24.356520687Z  at io.openvidu.server.rpc.RpcHandler.leaveRoomAfterConnClosed(RpcHandler.java:631)
2020-06-09T07:10:24.356524609Z  at io.openvidu.server.rpc.RpcHandler.afterConnectionClosed(RpcHandler.java:684)
2020-06-09T07:10:24.356528339Z  at org.kurento.jsonrpc.internal.JsonRpcHandlerManager.afterConnectionClosed(JsonRpcHandlerManager.java:65)
2020-06-09T07:10:24.356532099Z  at org.kurento.jsonrpc.internal.server.ProtocolManager.closeSession(ProtocolManager.java:446)
2020-06-09T07:10:24.356535857Z  at org.kurento.jsonrpc.internal.server.ProtocolManager$4.run(ProtocolManager.java:421)
2020-06-09T07:10:24.356540419Z  at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
2020-06-09T07:10:24.356544446Z  at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
2020-06-09T07:10:24.356548289Z  at java.util.concurrent.FutureTask.run(FutureTask.java:266)
2020-06-09T07:10:24.356551966Z  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
2020-06-09T07:10:24.356556513Z  at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
2020-06-09T07:10:24.356560271Z  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
2020-06-09T07:10:24.356563893Z  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
2020-06-09T07:10:24.356567493Z  at java.lang.Thread.run(Thread.java:748)
2020-06-09T07:10:24.356571448Z Caused by: java.lang.IllegalStateException: Message will not be sent because the WebSocket session has been closed
2020-06-09T07:10:24.356575246Z  at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.writeMessagePart(WsRemoteEndpointImplBase.java:430)
2020-06-09T07:10:24.356579048Z  at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:309)
2020-06-09T07:10:24.356582746Z  at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendMessageBlock(WsRemoteEndpointImplBase.java:250)
2020-06-09T07:10:24.356586570Z  at org.apache.tomcat.websocket.WsRemoteEndpointImplBase.sendPartialString(WsRemoteEndpointImplBase.java:223)
2020-06-09T07:10:24.356590470Z  at org.apache.tomcat.websocket.WsRemoteEndpointBasic.sendText(WsRemoteEndpointBasic.java:49)
2020-06-09T07:10:24.356594367Z  at org.springframework.web.socket.adapter.standard.StandardWebSocketSession.sendTextMessage(StandardWebSocketSession.java:215)
2020-06-09T07:10:24.356598140Z  at org.springframework.web.socket.adapter.AbstractWebSocketSession.sendMessage(AbstractWebSocketSession.java:106)
2020-06-09T07:10:24.356601910Z  at org.kurento.jsonrpc.internal.ws.WebSocketServerSession.sendRequestWebSocket(WebSocketServerSession.java:119)
2020-06-09T07:10:24.356609273Z  ... 22 common frames omitted

I am facing recurring session drops on my setup,
the above is what i found from logs?

9

Can you describe your problem in more detail? Can you share a more complete OpenVidu server log?

10

Hi Micael, here is the link to more detail logs, shared on github issue as well
let us know if you need any further information

https://cloud.techblue.co.uk/s/8PLdi1bP1WllqGb/download