Netty websocket client never sends websocket messages when running on Android device

1
votes

Taking an existing websocket client which runs under JDK6-8 and deploying it to Android (API 19) makes the client unable to send websocket frames to the server.

A normal http upgrade occurs and an http connection exists but any messages sent with ChannelHandlerContext.writeAndFlush() never go over the wire (I have confirmed this with Wireshark on the server).

// From the implementation of IClientConnection
public void sendBinaryMessage(FastByteArrayOutputStream stream) throws Exception { this.lock();

    try {

        if (_logger.isTraceEnabled()) {
            System.out.println("Sending binary Message:\n" + HexDump.hexDump(stream.toByteArray(), 20));
        }

        // recommended use when you already have an existing byte[] is to
        // create the ByteBuf using Unpooled, not the PooledByteBufAllocator
        ByteBuf buffer = Unpooled.wrappedBuffer(stream.getByteArray(), 0, stream.getSize());

        BinaryWebSocketFrame binaryMessage = new BinaryWebSocketFrame(buffer);
        String st = StringUtilities.toHexString(buffer.array());
        _logger.debug("SENDING AUTH MESSAGE:" + st);
        ChannelFuture promise = this.getWebSocket().writeAndFlush(binaryMessage);
        promise.await();
        _logger.debug("MESSAGE SENT");
    } finally {
        this.unlock();
    }
}

Log output

I/System.out: 14:24:18.605 [Client-EndpointMonitor-1] DEBUG io.netty.util.NetUtil - Loopback interface: lo (lo, ::1%1)
I/System.out: 14:24:18.615 [Client-EndpointMonitor-1] DEBUG io.netty.util.NetUtil - /proc/sys/net/core/somaxconn: 128
I/System.out: 14:24:18.738 [Client-EndpointMonitor-1] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: 90:68:c3:ff:fe:f1:ed:5c (auto-detected)
I/System.out: 14:24:18.751 [Client-EndpointMonitor-1] DEBUG io.netty.util.internal.ThreadLocalRandom - -Dio.netty.initialSeedUniquifier: 0x63ddb0bd5ba71d45
I/System.out: 14:24:18.835 [Client-EndpointMonitor-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: unpooled
I/System.out: 14:24:18.842 [Client-EndpointMonitor-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
I/System.out: 14:24:18.850 [Client-EndpointMonitor-1] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
I/System.out: 14:24:19.127 [NettyClient-NIO-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
D/com.thingworx.sdk.android.activity.ThingworxActivity: Waiting for initial connection...
I/System.out: 14:24:19.135 [NettyClient-NIO-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
I/System.out: 14:24:19.145 [NettyClient-NIO-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@2bea8c32
I/System.out: 14:24:19.595 [NettyClient-NIO-1] DEBUG com.thingworx.communications.client.connection.netty.NettyClientConnectionFactory - Adding compression handler to pipeline
I/System.out: 14:24:19.606 [NettyClient-NIO-1] DEBUG io.netty.handler.codec.compression.ZlibCodecFactory - -Dio.netty.noJdkZlibDecoder: true
I/System.out: 14:24:19.615 [NettyClient-NIO-1] DEBUG io.netty.handler.codec.compression.ZlibCodecFactory - -Dio.netty.noJdkZlibEncoder: false
D/com.thingworx.sdk.android.activity.ThingworxActivity: Waiting for initial connection...
I/System.out: 14:24:20.501 [NettyClient-NIO-1] DEBUG com.thingworx.communications.client.connection.netty.ThingworxClientConnectionHandler - WebSocket Channel is connected [is open: true]
D/com.thingworx.sdk.android.activity.ThingworxActivity: Waiting for initial connection...
I/System.out: 14:24:21.144 [NettyClient-NIO-1] DEBUG io.netty.handler.codec.http.websocketx.WebSocketClientHandshaker13 - WebSocket version 13 client handshake key: AAX2bRU+jf63Fhyik0HAEg==, expected response: DOFv14sfAg0+tQcv2kuDguaF1Sw=
I/System.out: 14:24:21.190 [NettyClient-NIO-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
I/System.out: 14:24:21.198 [NettyClient-NIO-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
I/System.out: 14:24:21.205 [NettyClient-NIO-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
I/System.out: 14:24:21.213 [NettyClient-NIO-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
I/System.out: 14:24:21.830 [NettyClient-NIO-1] DEBUG com.thingworx.communications.client.connection.netty.ThingworxClientConnectionHandler - [ClientHandler: 911311818] Client websocket handshake is complete
I/System.out: 14:24:21.847 [Client-EndpointMonitor-1] INFO com.thingworx.communications.client.endpoints.ClientCommunicationEndpoint - Preparing new Connection Authentication Request: DispatchingClientEndpoint [id: 0, isConnected: false, open connections: 0, max connections: 1]
I/System.out: 14:24:21.864 [Client-EndpointMonitor-1] DEBUG com.thingworx.communications.common.endpoints.CommunicationEndpoint - Sending connection authentication message, waiting for response [sync key: 1, message: AuthRequestMessage [requestId: 1, endpointId: -1, sessionId: -1, method: AUTHREQUEST]]
D/com.thingworx.sdk.android.activity.ThingworxActivity: Waiting for initial connection...
D/com.thingworx.sdk.android.activity.ThingworxActivity: Waiting for initial connection...
I/System.out: 14:24:22.694 [Client-EndpointMonitor-1] DEBUG com.thingworx.communications.client.connection.netty.NettyClientConnection - SENDING AUTH MESSAGE:011400000001ffffffffffffffff0001066170704b65792461626630333663322d373030392d343436322d386139362d363033366565376562613533
D/com.thingworx.sdk.android.activity.ThingworxActivity: Waiting for initial connection...
I/Choreographer: Skipped 206 frames!  The application may be doing too much work on its main thread.
I/System.out: 14:24:26.794 [Client-EndpointMonitor-1] DEBUG com.thingworx.communications.client.connection.netty.NettyClientConnection - MESSAGE SENT

Note that MESSAGE SENT is returned from the promise on writeAndFlush() returning true

As far as expected result, I would expect the binary websocket message to go out over the wire but it never does.

1
androidnetty
Does await().cause() return non-null ? If so what is the exception ? – Norman Maurer

1 Answers

0
votes

I have an answer.

It turns out there was a class loading exception that was being eaten on my ChannelFuture promise. Because the class loading exception was not being logged, to me just looked like a my message was not being sent.

This was the exception:

Caused by: io.netty.handler.codec.EncoderException: java.lang.NoClassDefFoundError: Failed resolution of: Lcom/jcraft/jzlib/Deflater;
    at io.netty.handler.codec.MessageToMessageEncoder.write(MessageToMessageEncoder.java:107)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite0(AbstractChannelHandlerContext.java:716)
    at io.netty.channel.AbstractChannelHandlerContext.invokeWrite(AbstractChannelHandlerContext.java:708)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:791)
    at io.netty.channel.AbstractChannelHandlerContext.write(AbstractChannelHandlerContext.java:701)

It was now clear that it was websocket compression that had to be disabled (at least in the short term) to allow websocket traffic to be sent.

I was not properly handling the promise return status.

Below is the modification to the code that allowed me to see the class loading exception.

public void waitForChannelCompletion(ChannelFuture future, String operationMessage) throws IOException {
    future.awaitUninterruptibly();

    // Now we are sure the future is completed.
    if (future.isDone()) {
        if (future.isCancelled()) {
            String errorMsg = String.format("Netty IO Operation has been cancelled [operation: %s]", operationMessage);
            throw new IOException(errorMsg);
        } else if (future.isSuccess() == false) {
            String errorMsg = String.format("Netty IO Operation failed [operation: %s]", operationMessage);
            throw new IOException(errorMsg, future.cause());
        }
    } else {
        // future should be done, otherwise there's a problem
        String errorMsg = String.format("Netty IO Operation is not done [operation: %s]", operationMessage);
        throw new IOException(errorMsg);
    }
}

        ChannelFuture promise = this.getWebSocket().writeAndFlush(binaryMessage);
        waitForChannelCompletion(promise,"MESSAGE SENT");

Hope this saves someone else from a similar problem.