Websocket closes right after openning

[Konstantyn Smirnov]

I have the following groovy code for 3.5.3:

    def options = [ connectTimeout:10000, defaultPort:443, keepAlive:true, ssl:true, defaultHost:someHost ]
    HttpClient client = vertx.createHttpClient options

    MultiMap h = MultiMap.caseInsensitiveMultiMap()
    h.add 'Authorization', "Bearer $access_token"

    client.websocket( '/some/path', h, { WebSocket socket ->
      log.info "succesfully got socket $socket / $options"
      socket.exceptionHandler{ close it }
      socket.endHandler{
        log.warn "closing $pathShort"
        close()
      }
      socket.handler this
     
    }, { Throwable t ->
      log.error t.message
    } )

After running I see something like that in the logs:

15:29:32.774 [vert.x-eventloop-thread-2] INFO i.m.g.http.continuous.Websocket - succesfully got socket io.vertx.core.http.impl.WebSocketImpl@36337c9f / [connectTimeout:10000, defaultPort:443, keepAlive:true, ssl:true, defaultHost:some.host ]
15:29:32.984 [vert.x-eventloop-thread-2] WARN i.m.g.http.continuous.Websocket - closing /api/ws
15:29:32.987 [vert.x-eventloop-thread-2] INFO i.m.g.http.continuous.Websocket - connection for 5b7ae11af3717058500685fa - /api/ws closed

So, approx after 100ms after connecting the socket gets gracefully closed as done per endHandler.

If I connect using the same code to a demo app like: stream-chat-demo.herokuapp.com (with ssl:false ), everything works just fine. 

What am I missing? What makes the websocket close?

[Julien Viet]

Hi,

you can you wireshark to troubleshoot

or you can provide a reproducer.

Julien

--
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.
To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/acca7e5b-de2b-40be-9b1b-8bcb70269e8a%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Konstantyn Smirnov]

Hi, the websocket is openned over wss:// so I can't really use any sniffer.

Are there any examples of verx Websocket clients over wss?

Now I can't even connect to simple demos like https://html5demos.com/web-socket/, using ssl:true. only ws:// works fine

[Konstantyn Smirnov]

Now I'm getting a Netty exception:

14:32:08.741 [vert.x-eventloop-thread-2] WARN i.m.g.http.continuous.Websocket - connect for 5b7ea1b5f3717064d05f1b3a - / failed: Failed to create SSL connection
14:32:08.741 [vert.x-eventloop-thread-2] WARN i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.handler.codec.DecoderException: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 485454502f312e31203430302042616420526571756573740d0a5365727665723a20617773656c622f322e300d0a446174653a205468752c2032332041756720323031382031323a33323a313120474d540d0a436f6e74656e742d547970653a20746578742f68746d6c0d0a436f6e74656e742d4c656e6774683a203133380d0a436f6e6e656374696f6e3a20636c6f73650d0a0d0a3c68746d6c3e0d0a3c686561643e3c7469746c653e3430302042616420526571756573743c2f7469746c653e3c2f686561643e0d0a3c626f6479206267636f6c6f723d227768697465223e0d0a3c63656e7465723e3c68313e3430302042616420526571756573743c2f68313e3c2f63656e7465723e0d0a3c2f626f64793e0d0a3c2f68746d6c3e0d0a
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:459)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:141)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)

That "Not an SSL Record" part when decoded from hex looks like:

HTTP/1.1 400 Bad Request
Server: awselb/2.0
Date: Thu, 23 Aug 2018 12:21:36 GMT
Content-Type: text/html
Content-Length: 138
Connection: close

<html>
<head><title>400 Bad Request</title></head>
<body bgcolor="white">
<center><h1>400 Bad Request</h1></center>
</body>
</html>

[Konstantyn Smirnov]

I created a simple reproducer:

import groovy.util.logging.Log4j
import io.vertx.core.AbstractVerticle
import io.vertx.core.http.HttpClientOptions
import io.vertx.core.http.WebSocket

@Log4j
class GatewayVerticle extends AbstractVerticle {
 
  @Override
  void start() throws Exception {
    HttpClientOptions o = new HttpClientOptions( defaultHost:'remy-ws.glitch.me', ssl:true )
    log.info "creating client with $o.properties"
    WebSocket socket
    vertx.createHttpClient( o ).websocket( '' ){ WebSocket ws ->
      socket = ws
      log.info "connected to $socket"
      ws.handler{ log.info "<< $it "}
      ws.closeHandler{ log.warn "closing << $socket" }
      ws.exceptionHandler{ log.error 'oops', it }
    }
  }

}

when running, it produces the output:

12:04:10.658 [vert.x-eventloop-thread-2] INFO i.m.gateway.http.GatewayVerticle - creating client with [http2KeepAliveTimeout:60, crlValues:[], pemTrustOptions:null, defaultHost:remy-ws.glitch.me, http2ClearTextUpgrade:true, maxRedirects:16, pfxKeyCertOptions:null, jdkSslEngineOptions:null, usePooledBuffers:false, verifyHost:true, openSslEngineOptions:null, defaultPort:80, crlPaths:[], maxWebsocketFrameSize:65536, logActivity:false, metricsName:, keepAliveTimeout:60, pipelining:false, maxWaitQueueSize:-1, maxPoolSize:5, tcpNoDelay:true, keepAlive:true, pipeliningLimit:10, pfxTrustOptions:null, trustOptions:null, tcpCork:false, localAddress:null, maxInitialLineLength:4096, poolCleanerPeriod:1000, sslEngineOptions:null, forceSni:false, sendBufferSize:-1, connectTimeout:60000, maxWebsocketMessageSize:262144, enabledSecureTransportProtocols:[TLSv1, TLSv1.1, TLSv1.2], trustAll:false, sendUnmaskedFrames:false, tcpFastOpen:false, http2MaxPoolSize:1, protocolVersion:HTTP_1_1, maxHeaderSize:8192, http2MultiplexingLimit:-1, trustStoreOptions:null, reuseAddress:true, reusePort:false, class:class io.vertx.core.http.HttpClientOptions, tcpKeepAlive:false, trafficClass:-1, idleTimeout:0, receiveBufferSize:-1, http2ConnectionWindowSize:-1, decoderInitialBufferSize:128, keyStoreOptions:null, enabledCipherSuites:[], useAlpn:false, tryUseCompression:false, proxyOptions:null, pemKeyCertOptions:null, soLinger:-1, alpnVersions:[], tcpQuickAck:false, ssl:true, keyCertOptions:null, maxChunkSize:8192, initialSettings:{"headerTableSize":4096,"initialWindowSize":65535,"maxConcurrentStreams":4294967295,"maxFrameSize":16384,"maxHeaderListSize":2147483647,"pushEnabled":true}]
Aug 24, 2018 12:04:10 PM io.vertx.core.impl.launcher.commands.VertxIsolatedDeployer
INFORMATION: Succeeded in deploying verticle
Aug 24, 2018 12:04:11 PM io.vertx.core.http.impl.HttpClientImpl
SCHWERWIEGEND: javax.net.ssl.SSLHandshakeException: Failed to create SSL connection
12:04:11.135 [vert.x-eventloop-thread-2] WARN i.n.channel.DefaultChannelPipeline - An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
io.netty.handler.codec.DecoderException: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 485454502f312e31203430302042616420526571756573740d0a5365727665723a20617773656c622f322e300d0a446174653a204672692c2032342041756720323031382031303a30343a313120474d540d0a436f6e74656e742d547970653a20746578742f68746d6c0d0a436f6e74656e742d4c656e6774683a203133380d0a436f6e6e656374696f6e3a20636c6f73650d0a0d0a3c68746d6c3e0d0a3c686561643e3c7469746c653e3430302042616420526571756573743c2f7469746c653e3c2f686561643e0d0a3c626f6479206267636f6c6f723d227768697465223e0d0a3c63656e7465723e3c68313e3430302042616420526571756573743c2f68313e3c2f63656e7465723e0d0a3c2f626f64793e0d0a3c2f68746d6c3e0d0a

    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:459)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:265)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1359)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:935)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:141)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)

    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
    at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)
Caused by: io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: 485454502f312e31203430302042616420526571756573740d0a5365727665723a20617773656c622f322e300d0a446174653a204672692c2032342041756720323031382031303a30343a313120474d540d0a436f6e74656e742d547970653a20746578742f68746d6c0d0a436f6e74656e742d4c656e6774683a203133380d0a436f6e6e656374696f6e3a20636c6f73650d0a0d0a3c68746d6c3e0d0a3c686561643e3c7469746c653e3430302042616420526571756573743c2f7469746c653e3c2f686561643e0d0a3c626f6479206267636f6c6f723d227768697465223e0d0a3c63656e7465723e3c68313e3430302042616420526571756573743c2f68313e3c2f63656e7465723e0d0a3c2f626f64793e0d0a3c2f68746d6c3e0d0a
    at io.netty.handler.ssl.SslHandler.decodeJdkCompatible(SslHandler.java:1138)
    at io.netty.handler.ssl.SslHandler.decode(SslHandler.java:1194)
    at io.netty.handler.codec.ByteToMessageDecoder.decodeRemovalReentryProtection(ByteToMessageDecoder.java:489)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:428)
    ... 16 common frames omitted

 

the content of io.netty.handler.ssl.NotSslRecordException: not an SSL/TLS record: decodes to:

HTTP/1.1 400 Bad Request
Server: awselb/2.0

Date: Fri, 24 Aug 2018 09:56:14 GMT

Content-Type: text/html
Content-Length: 138
Connection: close

<html>
<head><title>400 Bad Request</title></head>
<body bgcolor="white">
<center><h1>400 Bad Request</h1></center>
</body>
</html>

If I change ssl:true to ssl:false, then the websocket runs smoothly

[Julien Viet]

Hi,

this is because you are missing the default 443 port, your client options should have a "defaultPort: 443" declaration.

Julien

--
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/59439d65-33e5-4c5c-8793-5912c2f57896%40googlegroups.com.

[Konstantyn Smirnov]

Ok, thanks for the tip with defaultPort, now I can connect to other wss server.

The original problem remains: with that specific server the websocket connection gets closed after 100 ms.

What makes the websocket think that the connection is over? I see that the websocket's closeHandler is invoked, but why?

[Julien Viet]

can you connect with a vertx client and log all the frames received ?

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/4f192460-068b-4c54-b66b-cc527978fde8%40googlegroups.com.

[Julien Viet]

my experience with unexpected server close, is that sometimes the server close the connection when the client is inactive, i.e it does not send a PING frame .

[Konstantyn Smirnov]

Can you elaborate on that?

[Julien Viet]

you create a vertx client websocket and you set 

1/ a frame handler on the websocket

2/ an exception handler

and you log what you receive from the server.

Julien

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/1fa76749-7a5a-4970-9be4-bca6ab8a95cd%40googlegroups.com.

[Konstantyn Smirnov]

That is what I started with...

The code:

    client.websocket( path, h, { WebSocket ws ->
      socket = ws
      log.info "got socket $options / $h"
      socket.exceptionHandler{ close it }
      socket.closeHandler{ log.info "closing..."; close() }
      socket.frameHandler{ log.info "<< $it" }

      socket.handler this
     
    }, { Throwable t ->

      log.info 'oops', t
    } )

produces the log:

18:23:02.440 [vert.x-eventloop-thread-3] INFO i.m.g.http.continuous.Websocket - got socket [defaultPort:443, keepAlive:true, defaultHost:some.host, connectTimeout:10000, trustAll:true, ssl:true] / Authorization: Bearer eyJ0eXAiOiJK...jadajada...CHgd9fx9YSTrJkA

18:23:02.441 [vert.x-eventloop-thread-3] INFO i.m.g.http.continuous.Websocket - connected 5b84105df091e50b005c6876 - /api/ws ok
18:23:02.471 [vert.x-eventloop-thread-3] INFO i.m.g.http.continuous.Websocket - closing...
18:23:02.473 [vert.x-eventloop-thread-3] INFO i.m.g.http.continuous.Websocket - connection for 5b84105df091e50b005c6876 - /api/ws closed

No other ouput comes out...

[Julien Viet]

Hi,

I think we can activate logging to get more info:

https://vertx.io/docs/vertx-core/java/#_logging_network_client_activity

it might be just the server closing the connection...

Julien

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/93ca6e75-657f-4e5b-8932-576c4feb8ba9%40googlegroups.com.

[Konstantyn Smirnov]

I turned the logs on and got the following output:

16:16:42.696 [vert.x-eventloop-thread-2] INFO i.m.g.http.continuous.Websocket - connected 5b8552f1f091e50b005c6877 - /api/ws ok
16:16:42.697 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 - R:fhapi.my.busch-jaeger.de/157.97.106.77:443] READ COMPLETE
16:16:42.907 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 - R:fhapi.my.busch-jaeger.de/157.97.106.77:443] READ: 3967B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 81 7f 00 00 00 00 00 01 29 c1 7b 0a 20 20 22 31 |........).{.  "1|
|00000010| 38 33 39 62 66 64 36 2d 65 65 33 31 2d 34 39 63 |839bfd6-ee31-49c|
|00000020| 38 2d 61 65 30 35 2d 62 66 35 37 33 39 30 37 31 |8-ae05-bf5739071|
|00000030| 62 35 39 22 3a 0a 20 20 7b 0a 20 20 20 20 22 64 |b59":.  {.    "d|
|00000040| 65 76 69 63 65 73 22 3a 0a 20 20 20 20 7b 0a 20 |evices":.    {. |
|00000050| 20 20 20 20 20 22 36 30 30 30 30 39 38 44 34 41 |     "6000098D4A|
|00000060| 37 43 22 3a 0a 20 20 20 20 20 20 7b 0a 20 20 20 |7C":.      {.   |
|00000070| 20 20 20 20 20 22 63 68 61 6e 6e 65 6c 73 22 3a |     "channels":|
|00000080| 0a 20 20 20 20 20 20 20 20 7b 0a 20 20 20 20 20 |.        {.     |
|00000090| 20 20 20 20 20 22 63 68 30 30 30 30 22 3a 0a 20 |     "ch0000":. |
|000000a0| 20 20 20 20 20 20 20 20 20 7b 0a 20 20 20 20 20 |         {.     |
|000000b0| 20 20 20 20 20 20 20 22 64 69 73 70 6c 61 79 4e |       "displayN|
|000000c0| 61 6d 65 22 3a 22 4b c3 bc 68 6c 73 63 68 72 61 |ame":"K..hlschra|
|000000d0| 6e 6b 22 2c 0a 20 20 20 20 20 20 20 20 20 20 20 |nk",.           |
|000000e0| 20 22 66 6c 6f 6f 72 22 3a 22 30 30 22 2c 0a 20 | "floor":"00",. |
|000000f0| 20 20 20 20 20 20 20 20 20 20 20 22 66 75 6e 63 |           "func|
+--------+-------------------------------------------------+----------------+
16:16:42.910 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 - R:fhapi.my.busch-jaeger.de/157.97.106.77:443] WRITE: CloseWebSocketFrame(data: UnpooledByteBufAllocator$InstrumentedUnpooledUnsafeHeapByteBuf(ridx: 0, widx: 2, cap: 2)), 2B
         +-------------------------------------------------+
         |  0  1  2  3  4  5  6  7  8  9  a  b  c  d  e  f |
+--------+-------------------------------------------------+----------------+
|00000000| 03 ea                                           |..              |
+--------+-------------------------------------------------+----------------+
16:16:42.911 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 - R:fhapi.my.busch-jaeger.de/157.97.106.77:443] FLUSH
16:16:42.912 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 - R:fhapi.my.busch-jaeger.de/157.97.106.77:443] CLOSE
16:16:42.922 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 ! R:fhapi.my.busch-jaeger.de/157.97.106.77:443] READ COMPLETE
16:16:42.922 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 ! R:fhapi.my.busch-jaeger.de/157.97.106.77:443] USER_EVENT: SslCloseCompletionEvent(java.nio.channels.ClosedChannelException)
16:16:42.922 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 ! R:fhapi.my.busch-jaeger.de/157.97.106.77:443] INACTIVE
16:16:42.923 [vert.x-eventloop-thread-2] DEBUG i.n.handler.logging.LoggingHandler - [id: 0x6e1175f2, L:/10.2.40.60:62879 ! R:fhapi.my.busch-jaeger.de/157.97.106.77:443] UNREGISTERED
16:16:42.923 [vert.x-eventloop-thread-2] INFO i.m.g.http.continuous.Websocket - closing...
16:16:42.923 [vert.x-eventloop-thread-2] INFO i.m.g.http.continuous.Websocket - connection for 5b8552f1f091e50b005c6877 - /api/ws closed

So it turns out, that the server upon connection sends some statical init-data as JSON.

My 1st question is why no handler gets this data packet?

Then my client closes the connection by writing CloseWebSocketFrame and my 2nd question is why?

Is this happening  because the read buffer was not completely read out?

[Julien Viet]

Hi,

indeed that's what we can observe from the log.

it might be a bug, hard to speculate.

can you set a breakpoint on the channel and debug what happens when these frames are received / emitted ?

i.e when it's received, trace the dispatch and why it does not end up in the applicaiton

i.e when it's emitted (close), capture a stack trace to know the origin.

Julien

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/fb18899c-ff08-4ef8-9536-91db0e151bc9%40googlegroups.com.

[Konstantyn Smirnov]

I started with debugging, but had no time to complete it and I postponed it. 

I used another ws-client instead -> https://github.com/TakahikoKawasaki/nv-websocket-client and that had no problem with WSS connection and initial data whatsoever.