[Bug]: occasional NullPointerException on local WebRTC client connection

[fishface60]

Describe the Bug

After starting a WebRTC server it failed to start properly.

18:27:52.457 (ClientHandshake.java:145) [Thread-16] INFO  - skullman :send: CLIENT_INIT_MSG
Exception in thread "Thread-16" java.lang.NullPointerException: Cannot invoke "dev.onvoid.webrtc.RTCPeerConnection.getConnectionState()" because "this.peerConnection" is null
        at net.rptools.clientserver.simple.client.WebRTCClientConnection.sendMessage(WebRTCClientConnection.java:185)
        at net.rptools.clientserver.simple.client.WebRTCClientConnection.sendMessage(WebRTCClientConnection.java:178)
        at net.rptools.clientserver.hessian.client.MethodClientDecorator.sendMessage(MethodClientDecorator.java:42)
        at net.rptools.maptool.server.ClientHandshake.sendMessage(ClientHandshake.java:146)
        at net.rptools.maptool.server.ClientHandshake.startHandshake(ClientHandshake.java:139)
        at net.rptools.maptool.client.MapToolConnection.start(MapToolConnection.java:76)
        at net.rptools.maptool.client.MapTool.createConnection(MapTool.java:1227)
        at net.rptools.maptool.client.AppActions$62.lambda$executeAction$1(AppActions.java:2326)
        at net.rptools.maptool.client.AppActions$ClientAction.lambda$runBackground$0(AppActions.java:3496)
        at java.base/java.lang.Thread.run(Thread.java:831)
18:27:52.546 (WebRTCServerConnection.java:70) [WebSocketConnectReadThread-81] INFO  - S WebSocket connected

18:27:52.762 (WebRTCClientConnection.java:136) [WebSocketConnectReadThread-84] INFO  - C WebSocket connected

18:27:52.922 (WebRTCClientConnection.java:408) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onRenegotiationNeeded
18:27:52.926 (WebRTCClientConnection.java:305) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onSignalingChange: HAVE_LOCAL_OFFER
18:27:52.936 (WebRTCClientConnection.java:344) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onIceGatheringChange GATHERING
[sentry-pool-1-thread-2] WARN io.sentry.connection.AbstractConnection.lockdown - Initiated a temporary lockdown because of exception: {"detail":"bad sentry DSN public key"}
[sentry-pool-1-thread-2] ERROR io.sentry.connection.AsyncConnection - An exception occurred while sending the event to Sentry.
io.sentry.connection.ConnectionException: {"detail":"bad sentry DSN public key"}
        at io.sentry.connection.HttpConnection.doSend(HttpConnection.java:216)
        at io.sentry.connection.AbstractConnection.send(AbstractConnection.java:88)
        at io.sentry.connection.AsyncConnection$EventSubmitter.run(AsyncConnection.java:187)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630)
        at java.base/java.lang.Thread.run(Thread.java:831)
Caused by: java.io.IOException: Server returned HTTP response code: 400 for URL: https://sentry.io/api/1404248/store/
        at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1985)
        at java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1577)
        at java.base/sun.net.www.protocol.https.HttpsURLConnectionImpl.getInputStream(HttpsURLConnectionImpl.java:224)
        at io.sentry.connection.HttpConnection.doSend(HttpConnection.java:172)
        ... 5 more
18:27:53.094 (WebRTCClientConnection.java:305) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onSignalingChange: HAVE_REMOTE_OFFER
18:27:53.096 (WebRTCClientConnection.java:73) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S  setRemoteDescription success.
18:27:53.098 (WebRTCClientConnection.java:305) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onSignalingChange: STABLE
18:27:53.100 (WebRTCClientConnection.java:344) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onIceGatheringChange GATHERING
18:27:53.240 (WebRTCClientConnection.java:305) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onSignalingChange: STABLE
18:27:53.240 (WebRTCClientConnection.java:329) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onIceConnectionChange CHECKING
18:27:53.241 (WebRTCClientConnection.java:243) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C  setRemoteDescription success.
18:27:53.256 (WebRTCClientConnection.java:310) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onConnectionChange CONNECTING
18:27:53.256 (WebRTCClientConnection.java:310) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onConnectionChange CONNECTING
18:27:53.257 (WebRTCClientConnection.java:344) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onIceGatheringChange COMPLETE
18:27:53.257 (WebRTCClientConnection.java:329) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onIceConnectionChange CHECKING
18:27:53.257 (WebRTCClientConnection.java:344) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onIceGatheringChange COMPLETE
18:27:53.258 (WebRTCClientConnection.java:310) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onConnectionChange CONNECTED
18:27:53.258 (WebRTCClientConnection.java:310) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onConnectionChange CONNECTED
18:27:53.258 (WebRTCClientConnection.java:329) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onIceConnectionChange CONNECTED
18:27:53.258 (WebRTCClientConnection.java:329) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onIceConnectionChange CONNECTED
18:27:53.258 (WebRTCClientConnection.java:329) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C PeerConnection.onIceConnectionChange COMPLETED
18:27:53.261 (WebRTCClientConnection.java:440) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - C localDataChannel onStateChange OPEN
18:27:53.261 (WebRTCClientConnection.java:395) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S PeerConnection.onDataChannel
18:27:53.262 (WebRTCClientConnection.java:440) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - S localDataChannel onStateChange OPEN
18:27:53.264 (ServerHandshake.java:212) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - skullman@Draconis :got: CLIENT_INIT_MSG
18:27:53.266 (ServerHandshake.java:202) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - skullman@Draconis :send: USE_AUTH_TYPE_MSG
18:27:53.267 (ClientHandshake.java:155) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - skullman :got: USE_AUTH_TYPE_MSG
18:27:53.271 (ClientHandshake.java:145) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - skullman :send: CLIENT_AUTH_MESSAGE
18:27:53.272 (ServerHandshake.java:212) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - skullman@Draconis :got: CLIENT_AUTH_MESSAGE
18:27:53.272 (ServerHandshake.java:202) [WebRTCClientConnection.WebRTCThread_skullman@Draconis] INFO  - skullman@Draconis :send: CONNECTION_SUCCESSFUL_MSG
18:27:53.277 (ClientHandshake.java:155) [WebRTCClientConnection.WebRTCThread_skullman] INFO  - skullman :got: CONNECTION_SUCCESSFUL_MSG

To Reproduce

Start a WebRTC server a bunch of times and get unlucky.

Expected Behaviour

Local client is always able to send messages.

Screenshots

No response

MapTool Info

1.11.4 with WebRTC patch

Desktop

Linux[Debian]

Additional Context

No response

[thelsing]

should also be resolved by #3331 and #3321

[Phergus]

@fishface60 can you test this with the 1.12.0 Alpha release?

[fishface60]

@fishface60 can you test this with the 1.12.0 Alpha release?

Sorry I didn't reply sooner. I didn't test the alpha because the beta came out before I got around to it.
I've tried to reproduce this a bunch more times than it took for me to happen on its own and couldn't get it to happen, so I think this error is fixed.

While trying I got a bunch of this error though:

17:39:55.078 (WebRTCClientConnection.java:442) [WebRTCClientConnection.WebRTCThread_Mike@test] INFO  - S localDataChannel onStateChange CLOSING
17:39:55.078 (WebRTCClientConnection.java:442) [WebRTCClientConnection.WebRTCThread_Mike@test] INFO  - S localDataChannel onStateChange CLOSED
Exception in thread "WebRTCClientConnection.handleDisconnect" java.lang.NullPointerException: Cannot invoke "net.rptools.maptool.model.player.Player.getTransferablePlayer()" because the return value of "java.util.Map.get(Object)" is null
	at net.rptools.maptool.server.MapToolServerConnection.connectionRemoved(MapToolServerConnection.java:121)
	at net.rptools.clientserver.simple.server.AbstractServerConnection.fireClientDisconnect(AbstractServerConnection.java:128)
	at net.rptools.clientserver.simple.server.AbstractServerConnection.handleDisconnect(AbstractServerConnection.java:137)
	at net.rptools.clientserver.simple.AbstractConnection.fireDisconnect(AbstractConnection.java:113)
	at net.rptools.clientserver.simple.client.WebRTCClientConnection.lambda$fireDisconnectAsync$0(WebRTCClientConnection.java:477)
	at java.base/java.lang.Thread.run(Unknown Source)

I think this is handling a disconnect from a previous connection since it has happened before any clients have joined the current connection, and data channels close may happen after the client has closed, since the existing WebRTC connections aren't closed when the client times out, only when the server is taken down.

It also seems that FAILED isn't the terminal state for a WebRTC connection, since I experimented with suspending my MapTool client to cause it to disconnect and discovered that if I resumed the process after it went into FAILED it could return to DISCONNECTED and then back to FAILED which also causes that exception.

I'll open an issue after I have a better idea of what's going on.

[Phergus]

Thanks!