search

SwellRT / swellrt

SwellRT main project. Server, JavaScript and Java clients
http://swellrt.org/
Apache License 2.0
234 stars 34 forks source link

SwellRT's communication is broken after websocket is closed #25

Closed pablojan closed 9 years ago

pablojan commented 9 years ago

This issue refers to wave.p2pvalue.eu server.

Symptoms:

pablojan commented 9 years ago

@atd please, could you check why "https://wave.p2pvalue.eu/atmosphere" gets a 504 Time-out? thanks

atd commented 9 years ago

Of course! A quick first look shows people saying that 5 minutes tied to a client is too much, and it can be used for DOS attacks:

http://howtounix.info/howto/110-connection-timed-out-error-in-nginx

atd commented 9 years ago

Looking at nginx log messages, it seems wave has closed the connection:

2015/06/06 10:58:58 [error] 24315#0: *201704 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 188.78.198.66, server: wave.p2pvalue.eu, request: "GET /atmosphere?X-Atmosphere-Transport=close&X-Atmosphere-tracking-id=635d8452-2915-4a1c-974e-3d4c28be593a&_=1433580703948 HTTP/1.1", upstream: "http://192.168.101.2:9898/atmosphere?X-Atmosphere-Transport=close&X-Atmosphere-tracking-id=635d8452-2915-4a1c-974e-3d4c28be593a&_=1433580703948", host: "wave.p2pvalue.eu", referrer: "https://p.p2pvalue.eu/"
2015/06/06 11:36:23 [error] 24316#0: *201875 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 159.147.99.146, server: wave.p2pvalue.eu, request: "GET /atmosphere?X-Atmosphere-Transport=close&X-Atmosphere-tracking-id=25eb24a9-1c8b-473a-ba6c-5ffda035d402&_=1433582948755 HTTP/1.1", upstream: "http://192.168.101.2:9898/atmosphere?X-Atmosphere-Transport=close&X-Atmosphere-tracking-id=25eb24a9-1c8b-473a-ba6c-5ffda035d402&_=1433582948755", host: "wave.p2pvalue.eu", referrer: "http://showcase.net:9009/"
2015/06/06 12:17:19 [error] 24316#0: *201900 upstream timed out (110: Connection timed out) while reading response header from upstream, client: 159.147.99.146, server: wave.p2pvalue.eu, request: "GET /atmosphere HTTP/1.1", upstream: "http://192.168.101.2:9898/atmosphere", host: "wave.p2pvalue.eu"
atd commented 9 years ago

However, this is what I get in pear2pear:

nvoking executeWebSocket
wave.p2pvalue.eu/atmosphere/atmosphere.js:2898 Using URL: wss://wave.p2pvalue.eu/atmosphere?X-Atmosphere-tracking-id=0&X-Atmosphere-F…cript&X-Atmosphere-Transport=websocket&X-Cache-Date=0&X-atmo-protocol=true
wave.p2pvalue.eu/atmosphere/atmosphere.js:2898 Websocket successfully opened
wave.p2pvalue.eu/atmosphere/atmosphere.js:2898 Atmosphere Connection Open
wave.p2pvalue.eu/atmosphere/atmosphere.js:2898 Atmosphere Message received: {"messageType":"ProtocolWaveletUpdate","sequenceNumber":0,"message":{"1":"prototype.p2pvalue.eu/s+vc7wVvici7A/~/user+usuariotesttimeline@prototype.p2pvalue.eu","2":[],"3":{"1":1.0,"2":"5E3CE9B1F4058731AF5C01AC6C2474C6620E90EA"},"4":{"1":1.0,"2":"5E3CE9B1F4058731AF5C01AC6C2474C6620E90EA"},"5":{"1":"prototype.p2pvalue.eu/user+usuariotesttimeline@prototype.p2pvalue.eu","2":["usuariotesttimeline@prototype.p2pvalue.eu"],"3":[],"4":{"1":1.0,"2":"5E3CE9B1F4058731AF5C01AC6C2474C6620E90EA"},"5":[-1181071919,333],"6":"usuariotesttimeline@prototype.p2pvalue.eu","7":[-1181071919,333]},"7":"ch3"}}
wave.p2pvalue.eu/atmosphere/atmosphere.js:2898 Atmosphere Message received: {"messageType":"ProtocolWaveletUpdate","sequenceNumber":0,"message":{"1":"prototype.p2pvalue.eu/s+vc7wVvici7A/~/dummy+root","2":[],"6":true}}
wave.p2pvalue.eu/atmosphere/atmosphere.js:2898 Atmosphere Message received: {"messageType":"ProtocolSubmitResponse","sequenceNumber":1,"message":{"1":0,"2":"usuariotesttimeline@prototype.p2pvalue.eu is not a participant of [WaveletName prototype.p2pvalue.eu/s+vc7wVvici7A/prototype.p2pvalue.eu/swl+root]"}}
swellrt-1.js:2897 Uncaught java.lang.RuntimeException: org.waveprotocol.wave.concurrencycontrol.common.CorruptionDetail: [INVALID_OPERATION] Channel Exception
atmosphere.js:2898 Atmosphere Connection Close
atmosphere.js:2898 Atmosphere Connection Reconnect
atmosphere.js:2898 Reconnect request.transport: websocket
atmosphere.js:2898 Reconnect request.enableXDR: true
atmosphere.js:2898 Reconnect request.readResponsesHeaders: false
atmosphere.js:2898 Reconnect request.withCredentials: true
atmosphere.js:2898 Reconnect request.maxReconnectOnClose: 5
atmosphere.js:2898 Invoking executeWebSocket
atmosphere.js:2898 Using URL: wss://wave.p2pvalue.eu/atmosphere?X-Atmosphere-tracking-id=04a0e694-7d69-41…sphere-Transport=websocket&X-Cache-Date=1433588054525&X-atmo-protocol=true
atmosphere.js:2898 Websocket successfully opened
atmosphere.js:2898 Atmosphere Connection ReOpen
atmosphere.js:2898 Atmosphere Connection Close
atmosphere.js:2898 Atmosphere Connection Reconnect
atmosphere.js:2898 Reconnect request.transport: websocket
atmosphere.js:2898 Reconnect request.enableXDR: true
atmosphere.js:2898 Reconnect request.readResponsesHeaders: false
atmosphere.js:2898 Reconnect request.withCredentials: true
atmosphere.js:2898 Reconnect request.maxReconnectOnClose: 5
atmosphere.js:2898 Invoking executeWebSocket
atmosphere.js:2898 Using URL: wss://wave.p2pvalue.eu/atmosphere?X-Atmosphere-tracking-id=04a0e694-7d69-41…sphere-Transport=websocket&X-Cache-Date=1433588114725&X-atmo-protocol=true
atmosphere.js:2898 Websocket successfully opened
atmosphere.js:2898 Atmosphere Connection ReOpen
atmosphere.js:2898 Atmosphere Connection Close
atmosphere.js:2898 Atmosphere Connection Reconnect
atmosphere.js:2898 Reconnect request.transport: websocket
atmosphere.js:2898 Reconnect request.enableXDR: true
atmosphere.js:2898 Reconnect request.readResponsesHeaders: false
atmosphere.js:2898 Reconnect request.withCredentials: true
atmosphere.js:2898 Reconnect request.maxReconnectOnClose: 5
atmosphere.js:2898 Invoking executeWebSocket
atmosphere.js:2898 Using URL: wss://wave.p2pvalue.eu/atmosphere?X-Atmosphere-tracking-id=04a0e694-7d69-41…sphere-Transport=websocket&X-Cache-Date=1433588174924&X-atmo-protocol=true
atmosphere.js:2898 Websocket successfully opened
atmosphere.js:2898 Atmosphere Connection ReOpen
atmosphere.js:2898 Atmosphere Connection Close
atmosphere.js:2898 Atmosphere Connection Reconnect
atmosphere.js:2898 Reconnect request.transport: websocket
atmosphere.js:2898 Reconnect request.enableXDR: true
atmosphere.js:2898 Reconnect request.readResponsesHeaders: false
atmosphere.js:2898 Reconnect request.withCredentials: true
atmosphere.js:2898 Reconnect request.maxReconnectOnClose: 5
atmosphere.js:2898 Invoking executeWebSocket
atmosphere.js:2898 Using URL: wss://wave.p2pvalue.eu/atmosphere?X-Atmosphere-tracking-id=04a0e694-7d69-41…sphere-Transport=websocket&X-Cache-Date=1433588235124&X-atmo-protocol=true
atmosphere.js:2898 Websocket successfully opened
atmosphere.js:2898 Atmosphere Connection ReOpen
atmosphere.js:2898 Atmosphere Connection Close
atmosphere.js:2898 Atmosphere Connection Reconnect
atmosphere.js:2898 Reconnect request.transport: websocket
atmosphere.js:2898 Reconnect request.enableXDR: true
atmosphere.js:2898 Reconnect request.readResponsesHeaders: false
atmosphere.js:2898 Reconnect request.withCredentials: true
atmosphere.js:2898 Reconnect request.maxReconnectOnClose: 5
atmosphere.js:2898 Invoking executeWebSocket
atmosphere.js:2898 Using URL: wss://wave.p2pvalue.eu/atmosphere?X-Atmosphere-tracking-id=04a0e694-7d69-41…sphere-Transport=websocket&X-Cache-Date=1433588295384&X-atmo-protocol=true
atmosphere.js:2898 Websocket successfully opened
atmosphere.js:2898 Atmosphere Connection ReOpen
atmosphere.js:2898 Atmosphere Connection Close
atmosphere.js:2898 Websocket reconnect maximum try reached 0
atmosphere.js:2898 Atmosphere Connection Error
atd commented 9 years ago

Have you seen this error in swellrt?

java.lang.NullPointerException: Null delta application version
        at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:209)
        at org.waveprotocol.box.server.frontend.WaveViewSubscription.submitResponse(WaveViewSubscription.java:141)
        at org.waveprotocol.box.server.frontend.UserManager.submitResponse(UserManager.java:136)
        at org.waveprotocol.box.server.frontend.ClientFrontendImpl$1.onFailure(ClientFrontendImpl.java:207)
        at org.waveprotocol.box.server.waveserver.WaveServerImpl$3.onFailure(WaveServerImpl.java:372)
        at org.waveprotocol.box.server.waveserver.WaveServerImpl.submitDelta(WaveServerImpl.java:553)
        at org.waveprotocol.box.server.waveserver.WaveServerImpl.submitRequest(WaveServerImpl.java:369)
        at org.waveprotocol.box.server.frontend.ClientFrontendImpl.submitRequest(ClientFrontendImpl.java:194)
        at org.waveprotocol.box.server.frontend.WaveClientRpcImpl.submit(WaveClientRpcImpl.java:166)
        at org.waveprotocol.box.common.comms.WaveClientRpc$ProtocolWaveClientRpc$1.submit(WaveClientRpc.java:11213)
        at org.waveprotocol.box.common.comms.WaveClientRpc$ProtocolWaveClientRpc.callMethod(WaveClientRpc.java:11352)
        at org.waveprotocol.box.server.rpc.ServerRpcControllerImpl.run(ServerRpcControllerImpl.java:202)
        at org.waveprotocol.box.server.executor.RequestScopeExecutor$1.run(RequestScopeExecutor.java:69)
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
        at java.util.concurrent.FutureTask.run(FutureTask.java:262)
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
        at java.lang.Thread.run(Thread.java:745)
pablojan commented 9 years ago

So I see some issues here..

I keep investigating...

pablojan commented 9 years ago

@atd, that "java.lang.NullPointerException: Null delta application version" is a side-effect of the disfuctional connection between client and server. It doesn't clarify the issue.

I will add log traces of atmosphere in the server

atd commented 9 years ago

AFAIK is not that Nginx is closing the socket connection. The 504 error has to do with a new HTTP request, which is not answered by SwellRT

pablojan commented 9 years ago

I agree, that is 2nd point in the previous answer. Thank you

pablojan commented 9 years ago

After last commit, client is not receiving heart beat messages through the Atmosphere WebSocket when testing wave.p2pvalue.eu. However in local env tests, WebSockets frames with whitespaces (heart beat signals) were received. @atd, could the nginx be preventing these heartbeats to reach Web clients?

atd commented 9 years ago

@pablojan I would check if atmosphere.js is loading in the first place :wink:

atd commented 9 years ago

Why don't distribute it inside swellrt.js?

pablojan commented 9 years ago

atmosphere.js is of course loaded, if not, websockets couldn't work at all. Sorry but I didn't get your point.

atd commented 9 years ago

Ok, I was checking https://wave.p2pvalue.eu, where atmosphere.js is requested to https://wave.p2pvalue.eu:9898/atmosphere/atmosphere.js and not loaded.

I will check Pear2Pear, where it is loaded

atd commented 9 years ago

I cannot test it now in local. I get a 403 Forbidden when Pear2Pear tries to log into SwellRT

pablojan commented 9 years ago

I guess you are accessing the classic IU (https://wave.p2pvalue.eu/). The atmoshphere.js is not loaded because that URL refers to port 9898, what it is a wrong configuration of that specific classic IU, please don't get it as a reference to test comms.

Using the swellrt-showcase example you can try the SwelRT API properly. In that case, you can see the WebSocket issue.

I guess we need a face-to-face talk to clarify this issue ;)

pablojan commented 9 years ago

Some features has been already added to avoid this issue.

However, Atmosphere server's part is not handling reconnection properly: on reconnect, on the next Wave Protocol's request reaching the server, it should be linked to the previously dropped Wave view connection.