WebsocketNotConnectedException in Timer-0 ping

[hackermike]

While running about 16 websocket connection threads, Timer-0 thread notified that 3 had disconnected then later logged the following exception. After that point, Timer-0 did not report anything else.

Exception in thread "Timer-0" org.java_websocket.exceptions.WebsocketNotConnectedException
at org.java_websocket.WebSocketImpl.send(WebSocketImpl.java:606)
at org.java_websocket.WebSocketImpl.sendFrame(WebSocketImpl.java:632)
at org.java_websocket.WebSocketImpl.sendPing(WebSocketImpl.java:639)
at org.java_websocket.AbstractWebSocket$1.run(AbstractWebSocket.java:132)
at java.util.TimerThread.mainLoop(Timer.java:555)
at java.util.TimerThread.run(Timer.java:505)

• Version used: 1.3.5
• Java version: 1.8.0_144
• Operating System and version: Docker under Ubuntu 16.04

[marci4]

Hello @hackermike,
This issue should be solved with 1.3.6

Greetings
marci4

[mwfrandsen]

Thank you! I'll give the update a try in the morning.

[hackermike]

The line numbers have changed but I see the same exception:

Exception in thread "Timer-0" org.java_websocket.exceptions.WebsocketNotConnectedException
at org.java_websocket.WebSocketImpl.send(WebSocketImpl.java:598)
at org.java_websocket.WebSocketImpl.sendFrame(WebSocketImpl.java:624)
at org.java_websocket.WebSocketImpl.sendPing(WebSocketImpl.java:631)
at org.java_websocket.AbstractWebSocket$1.run(AbstractWebSocket.java:142)
at java.util.TimerThread.mainLoop(Timer.java:555)
at java.util.TimerThread.run(Timer.java:505)

[hackermike]

I haven't been able to reproduce this except the first time so perhaps I didn't run the correct update on the first try. (?)

[amerp]

Can confirm, I'm also getting exception in version 1.3.6
Fatal Exception: org.java_websocket.exceptions.WebsocketNotConnectedException
at org.java_websocket.WebSocketImpl.send(WebSocketImpl.java:598)
at org.java_websocket.WebSocketImpl.sendFrame(WebSocketImpl.java:624)
at org.java_websocket.WebSocketImpl.sendPing(WebSocketImpl.java:631)
at org.java_websocket.AbstractWebSocket$1.run(AbstractWebSocket.java:142)
at java.util.Timer$TimerImpl.run(Timer.java:284)

[mwfrandsen]

This might be wild speculation but I'll put this here in case related - not sure I have enough to give it as an issue itself. I have about 16 connections coming and going that last a few seconds to a few minutes. Maybe 10 in 6000 of these seems to get a "disconnected" message for no reason. (I don't set timeouts but typically is 90-100 seconds after client stops sending and is waiting for server to return all results.) Wild speculation is that perhaps client m disconnects but timer looking over lost connections gives client n the disconnect message while it's still connected(?) (Or, similar, maybe loop of the ping above gets a disconnected client since some data structure changes and it thinks it has a connected client when it doesn't.) I can remove this or put it somewhere else if I learn more...

[marci4]

Could you guys provide some steps to repeat?
I cannot reproduce this in my development setup.

Greetings
marci4

[hackermike]

I will try to send more when I have it. Since this seems related to some close/open mismatch, here are a couple logs from onClose() where isOpen() returned true:
org.java_websocket.WebSocketImpl@74690a93 id=conn3 isClosing=false closed=false reported as closed but is marked open. Not removing!
org.java_websocket.WebSocketImpl@908bb2 id=conn13 isClosing=false closed=false reported as closed but is marked open. Not removing!

@Override
public void onClose(WebSocket conn, int code, String reason, boolean remote) {
    if (conn.isOpen()) {
       logger.error(conn + " id=" + id + " isClosing=" + conn.isClosing() + " closed=" + conn.isClosed() + " reported as closed but is marked open. Not removing!");
    } else ...

[marci4]

Do both of these issues still exist with this version?
https://www.dropbox.com/s/o9vdm7iwyvcxia8/java-websocket-1.3.7-dev.jar

Greetings
marci4

[hackermike]

Thanks again! I started a test with this but it will take a couple hours to run and I won't be able to check it more until morning. I am seeing some errors already, though.

So far: two cases show websocket closed that is still marked as open - and then errors later trying to write to it.

FYI: The other endpoint is JavaScript running through node directly. It sends a stream to the server and reads the results. I don't see anywhere that it would be timing out or closing the connection. The connections are local so shouldn't be getting lost. But, there are a lot of simultaneous connections managed that are coming and going. On the server, I bumped the timeout from 60 seconds to 600 seconds so hopefully any ping/pong issues triggering a timeout can be eliminated.

org.java_websocket.WebSocketImpl@12ce95da id=conn47 isClosing=false closed=false reported as closed but is marked open. Not removing!
org.java_websocket.WebSocketImpl@12ce95da id=conn47 Unexpected exception sending message: org.java_websocket.exceptions.WebsocketNotConnectedException

org.java_websocket.WebSocketImpl@5d4543aa id=conn221 isClosing=false closed=false reported as closed but is marked open. Not removing!
org.java_websocket.WebSocketImpl@5d4543aa id=conn221 Unexpected exception sending message: org.java_websocket.exceptions.WebsocketNotConnectedException

[marci4]

This feature requires the endpoint to implement the specification correctly!
Just having a normal socket running will of course cause the connection to be closed!

Greetings
marci4

[hackermike]

Is there a known issue with websockets in Javascript? I was simply setting a long timeout so I could assume a disconnect was due to a dropped connection instead of a timeout. Or, do you mean to suggest I should set the timeout to 0 to disable the feature entirely?

In any case, shouldn't querying a connection in onClose() be marked as closed or closing instead of open?

[hackermike]

Example just to give more detail of Javascript websocket endpoint:

const WebSocket = require('ws');

this._ws = new WebSocket("ws://...");
this._ws.on('error', (e) => this.emit('error', e));
this._ws.on('open', () => this._ws.send(INT_MESSAGE));
this._ws.on('message', (data) => {
  var message = JSON.parse(data);
  ...
});
this._ws.on('close', () => console.log('Connection was closed.'));

[marci4]

Well you said something about streams and not a websocket so I expected something different.

Yeah, on onClose the WebSocket should not be open!
If you can provide some steps to repeat, which always work, I would really appreciate that! If you think it is releated to this issue, please post it here, otherwise open a separate issue!

Greetings
marci4

[hackermike]

Oh, stream of audio via base64 encoded audio chunk messages.

I don't yet have a small standalone example and will need to work on that. I won't have that right away, though.

[marci4]

Hello @hackermike,

I found a possible cause for your problem.
Could you check this please? https://www.dropbox.com/s/o9vdm7iwyvcxia8/java-websocket-1.3.7-dev.jar?dl=0
This should not cause any problems any more!

Greetings
marci4

[hackermike]

Looking better so far! I'm about halfway through (6000+ inputs) and the only logged issues are:

23:29:46.920 org.java_websocket.WebSocketImpl@75b08bbf id=conn92 Unexpected exception sending message: org.java_websocket.exceptions.WebsocketNotConnectedException
23:29:47.799 org.java_websocket.WebSocketImpl@75b08bbf id=conn92 has disconnected! code=1000 reason='' remote=true isOpen=false isClosing=true closed=false

23:58:16.978 org.java_websocket.WebSocketImpl@6f7a7a17 id=conn2609 Unexpected exception sending message: org.java_websocket.exceptions.WebsocketNotConnectedException
23:58:18.094 org.java_websocket.WebSocketImpl@6f7a7a17 id=conn2609 has disconnected! code=1000 reason='' remote=true isOpen=false isClosing=true closed=false

I'll need to see if the other end might have timed out though. But, no extraneous onClose calls yet.

In the above two cases, I assume it's unknown that the websocket is down until the send (or goes down during the send) and then the onClose is within about a second. So, that's all reasonable if it's the other end closing the connection for some reason.

[hackermike]

Thanks! It's looking like those two cases above, processing of stream has ended and client has closed stream. Server just happens to send its periodic status message thinking the connection is still live and might get another audio stream - but fails since client has already closed the connection. So, I wouldn't consider either of those problems.

I'm not seeing any suspicious onClose() calls but still have other issues to work through.

[marci4]

Any update?

[hackermike]

The extraneous onClose() with wrong state is no longer an issue. So, this part can be closed. Thanks!

But, a different issue started that looks like a "stalled" websocket that I haven't been able to track down. I haven't seen this before so it could be that some bug was introduced or could be unrelated. (In previous cases, the websocket might get closed for no reason. It seems it might stop responding at a similar point in time which makes me wonder if it's related. If everything is pushed, maybe a code diff would be worthwhile for me to look at.)

[marci4]

Hello @hackermike,

thank you for your feedback. I closed the corresponding issue #609 due to your feedback!

Could you open a separate issue for that issue?

Just to make this clear, this main issue (Exception during sendPing()) did not yet happen again?
Greetings
marci4

[szuwest]

I met this problem,too. it happens when server is stop(crash), but client does not know.Then client send ping, it crash

[hackermike]

@szuwest Can you elaborate? The issue that I'm currently seeing is that websocket seems to simply stop responding for no reason. I'm not sure how to submit that as a bug as as I don't have a crash or exception - but it seems to be a new behavior after these recent fixes.

[fagnerng]

I had the same problem when on a poor connection, (hspa connection).
I "solved" this problem calling setConnectionLostTimeout(0) on WebSocketClient

[marci4]

Hello @fagnerng,

could you check if this issue still occurs with the current master branch?

Greetings
marci4

[hackermike]

Building from master as of this morning fails with the following on Ubuntu 16.04, java version "1.8.0_151".

Running org.java_websocket.issues.Issue621Test
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.001 sec - in org.java_websocket.issues.Issue621Test

Results :

Failed tests:
Issue580Test.runNoCloseBlockingTestScenario0 Found 3 zombie thread(s)
Issue580Test.runNoCloseBlockingTestScenario1 Found 3 zombie thread(s)
Issue580Test.runNoCloseBlockingTestScenario5 Found 3 zombie thread(s)
Issue580Test.runNoCloseBlockingTestScenario7 Found 3 zombie thread(s)

Tests run: 118, Failures: 4, Errors: 0, Skipped: 0

[marci4]

Hello @hackermike,

just skip the tests. They are for me (jenkins checking against every commit)
Build it with -Dmaven.test.skip=true clean package

Greetings
marci4

[marci4]

Hello @hackermike,

you can also use this version. https://www.dropbox.com/s/um5gcwy9ax5imiu/Java-WebSocket-1.3.7-dev.jar?dl=0

Greetings
marci4

[marci4]

This issue should be solved in the latest version.

Closing issue!
Greetings
marci4