Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Fails to parse some messages when too much data #1

Open
Jarcionek opened this issue Feb 11, 2020 · 1 comment
Open

Fails to parse some messages when too much data #1

Jarcionek opened this issue Feb 11, 2020 · 1 comment

Comments

@Jarcionek
Copy link

Jarcionek commented Feb 11, 2020 •
edited

Hi,

Firstly, thank you for this library. It's really useful.

I have been testing it with the gpsfake and I have run into a problem. If I send messages only as fast as I can hit enter in gpsfake (using -i argument), everything is fine, but if I let it run on its own (without -i argument), it floods the socket with messages, then the library tries to parse half of the message only, which fails, which in turn sometimes causes it to disconnect and connect again.

This how I configured the GpsdClient:

gpsdClient.addErrorHandler(errorMessage -> logger.e("Jarek", errorMessage.getMessage()));

gpsdClient.addHandler(TPVReport.class, tpv -> {
    Double latitude = tpv.getLatitude();
    Double longitude = tpv.getLongitude();
    if (latitude == null || longitude == null) {
        return; // if gpsd daemon gets restarted, library reconnects but returns one TPV event with no coordinates
    }
    logger.i("Jarek", "latitude: " + latitude + ", longitude: " + longitude);
});

gpsdClient.addHandler(ATTReport.class,          x -> logger.i("Jarek", "ATTReport: "          + x.toString()));
gpsdClient.addHandler(GSTReport.class,          x -> logger.i("Jarek", "GSTReport: "          + x.toString()));
//gpsdClient.addHandler(SKYReport.class,          x -> logger.i("Jarek", "SKYReport: "          + x.toString()));
gpsdClient.addHandler(TOFFReport.class,         x -> logger.i("Jarek", "TOFFReport: "         + x.toString()));
gpsdClient.addHandler(DeviceMessage.class,      x -> logger.i("Jarek", "DeviceMessage: "      + x.toString()));
gpsdClient.addHandler(DevicesMessage.class,     x -> logger.i("Jarek", "DevicesMessage: "     + x.toString()));
gpsdClient.addHandler(ErrorMessage.class,       x -> logger.i("Jarek", "ErrorMessage: "       + x.toString()));
gpsdClient.addHandler(GpsdCommandMessage.class, x -> logger.i("Jarek", "GpsdCommandMessage: " + x.toString()));
//gpsdClient.addHandler(GpsdMessage.class,        x -> logger.i("Jarek", "GpsdMessage: "        + x.toString()));
gpsdClient.addHandler(PollMessage.class,        x -> logger.i("Jarek", "PollMessage: "        + x.toString()));
gpsdClient.addHandler(VersionMessage.class,     x -> logger.i("Jarek", "VersionMessage: "     + x.toString()));
gpsdClient.addHandler(WatchMessage.class,       x -> logger.i("Jarek", "WatchMessage: "       + x.toString()));

gpsdClient.setSuccessfulConnectionHandler(client -> {
    logger.i("Jarek", "Successful connection!!!");
    client.watch();
});

gpsdClient.start();

Here are all the logs in ~0.5s window of time:

2020-02-10T11:40:33.819Z [vert.x-worker-thread-16] INFO - Jarek latitude: 55.671483333, longitude: 12.518383333
2020-02-10T11:40:33.827Z [vert.x-worker-thread-17] INFO - Jarek latitude: 55.671493333, longitude: 12.51839
2020-02-10T11:40:33.837Z [vert.x-worker-thread-18] INFO - Jarek latitude: 55.671493333, longitude: 12.51839
2020-02-10T11:40:33.845Z [vert.x-worker-thread-19] INFO - Jarek latitude: 55.671505, longitude: 12.518386667
2020-02-10T11:40:33.871Z [vert.x-worker-thread-1] INFO - Jarek latitude: 55.671505, longitude: 12.518386667
2020-02-10T11:40:33.880Z [vert.x-worker-thread-0] INFO - Jarek latitude: 55.671515, longitude: 12.518391667
2020-02-10T11:40:33.888Z [vert.x-worker-thread-2] INFO - Jarek latitude: 55.671515, longitude: 12.518391667
2020-02-10T11:40:33.897Z [vert.x-worker-thread-3] INFO - Jarek latitude: 55.671525, longitude: 12.518385
2020-02-10T11:40:33.905Z [vert.x-worker-thread-4] INFO - Jarek latitude: 55.671525, longitude: 12.518385
2020-02-10T11:40:33.913Z [vert.x-worker-thread-5] INFO - Jarek latitude: 55.671531667, longitude: 12.518385
2020-02-10T11:40:33.921Z [vert.x-worker-thread-6] INFO - Jarek latitude: 55.671531667, longitude: 12.518385
2020-02-10T11:40:33.930Z [vert.x-worker-thread-7] INFO - Jarek latitude: 55.671538333, longitude: 12.518386667
2020-02-10T11:40:33.933Z [vert.x-eventloop-thread-0] WARN - Cannot parse JSON
com.ivkos.gpsd4j.support.GpsdParseException: Could not parse JSON: {"class":"TPV","device":"/dev/pts/9","mode":3,"time":"2012-11-04T14:03:31.000Z","ept":0.005,"lat":55.6715383
	at com.ivkos.gpsd4j.support.SerializationHelper.deserialize(SerializationHelper.java:97)
	at com.ivkos.gpsd4j.client.GpsdClient.handleJsonString(GpsdClient.java:481)
	at com.ivkos.gpsd4j.client.GpsdClient.lambda$handleConnectResult$5(GpsdClient.java:437)
	at io.vertx.core.net.impl.NetSocketImpl.handleDataReceived(NetSocketImpl.java:325)
	at io.vertx.core.net.impl.NetClientImpl.handleMsgReceived(NetClientImpl.java:101)
	at io.vertx.core.net.impl.NetClientImpl.handleMsgReceived(NetClientImpl.java:45)
	at io.vertx.core.net.impl.NetClientBase$1.handleMsgReceived(NetClientBase.java:189)
	at io.vertx.core.net.impl.VertxNetHandler.lambda$channelRead$0(VertxNetHandler.java:63)
	at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:335)
	at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:193)
	at io.vertx.core.net.impl.VertxNetHandler.channelRead(VertxNetHandler.java:63)
	at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:122)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:129)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:642)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:565)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:479)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:441)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at java.lang.Thread.run(Unknown Source)
Caused by: io.vertx.core.json.DecodeException: Failed to decode: Unexpected end-of-input: expected close marker for OBJECT (from [Source: {"class":"TPV","device":"/dev/pts/9","mode":3,"time":"2012-11-04T14:03:31.000Z","ept":0.005,"lat":55.6715383; line: 1, column: 1])
 at [Source: {"class":"TPV","device":"/dev/pts/9","mode":3,"time":"2012-11-04T14:03:31.000Z","ept":0.005,"lat":55.6715383; line: 1, column: 325]
	at io.vertx.core.json.Json.decodeValue(Json.java:123)
	at io.vertx.core.json.JsonObject.fromJson(JsonObject.java:950)
	at io.vertx.core.json.JsonObject.<init>(JsonObject.java:53)
	at com.ivkos.gpsd4j.support.SerializationHelper.deserialize(SerializationHelper.java:95)
	... 25 common frames omitted
2020-02-10T11:40:33.999Z [vert.x-eventloop-thread-0] WARN - Cannot parse JSON
com.ivkos.gpsd4j.support.GpsdParseException: Could not parse JSON: 33,"lon":12.518386667,"alt":0.500,"epx":8.824,"epy":8.912,"epv":36.800,"track":22.7100,"speed":0.370,"climb":-0.800,"eps":17.82,"epc":73.60}
	at com.ivkos.gpsd4j.support.SerializationHelper.deserialize(SerializationHelper.java:97)
	at com.ivkos.gpsd4j.client.GpsdClient.handleJsonString(GpsdClient.java:481)
	at com.ivkos.gpsd4j.client.GpsdClient.lambda$handleConnectResult$5(GpsdClient.java:437)
	at io.vertx.core.net.impl.NetSocketImpl.handleDataReceived(NetSocketImpl.java:325)
	at io.vertx.core.net.impl.NetClientImpl.handleMsgReceived(NetClientImpl.java:101)
	at io.vertx.core.net.impl.NetClientImpl.handleMsgReceived(NetClientImpl.java:45)
	at io.vertx.core.net.impl.NetClientBase$1.handleMsgReceived(NetClientBase.java:189)
	at io.vertx.core.net.impl.VertxNetHandler.lambda$channelRead$0(VertxNetHandler.java:63)
	at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:335)
	at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:193)
	at io.vertx.core.net.impl.VertxNetHandler.channelRead(VertxNetHandler.java:63)
	at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:122)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:129)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:642)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:565)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:479)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:441)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at java.lang.Thread.run(Unknown Source)
Caused by: io.vertx.core.json.DecodeException: Failed to decode: Unexpected character (',' (code 44)): Expected space separating root-level values
 at [Source: 33,"lon":12.518386667,"alt":0.500,"epx":8.824,"epy":8.912,"epv":36.800,"track":22.7100,"speed":0.370,"climb":-0.800,"eps":17.82,"epc":73.60}; line: 1, column: 4]
	at io.vertx.core.json.Json.decodeValue(Json.java:123)
	at io.vertx.core.json.JsonObject.fromJson(JsonObject.java:950)
	at io.vertx.core.json.JsonObject.<init>(JsonObject.java:53)
	at com.ivkos.gpsd4j.support.SerializationHelper.deserialize(SerializationHelper.java:95)
	... 25 common frames omitted
2020-02-10T11:40:34.009Z [vert.x-worker-thread-8] INFO - Jarek latitude: 55.671543333, longitude: 12.51838
2020-02-10T11:40:34.018Z [vert.x-worker-thread-9] INFO - Jarek latitude: 55.671543333, longitude: 12.51838
2020-02-10T11:40:34.027Z [vert.x-worker-thread-10] INFO - Jarek latitude: 55.67155, longitude: 12.518376667
2020-02-10T11:40:34.037Z [vert.x-worker-thread-11] INFO - Jarek latitude: 55.67155, longitude: 12.518376667
2020-02-10T11:40:34.045Z [vert.x-worker-thread-12] INFO - Jarek latitude: 55.671555, longitude: 12.518366667
2020-02-10T11:40:34.053Z [vert.x-worker-thread-13] INFO - Jarek latitude: 55.671555, longitude: 12.518366667
2020-02-10T11:40:34.062Z [vert.x-worker-thread-14] INFO - Jarek latitude: 55.671563333, longitude: 12.518365
2020-02-10T11:40:34.071Z [vert.x-worker-thread-15] INFO - Jarek latitude: 55.671563333, longitude: 12.518365
2020-02-10T11:40:34.079Z [vert.x-worker-thread-16] INFO - Jarek latitude: 55.671571667, longitude: 12.51837
2020-02-10T11:40:34.088Z [vert.x-worker-thread-17] INFO - Jarek latitude: 55.671571667, longitude: 12.51837
2020-02-10T11:40:34.093Z [vert.x-eventloop-thread-0] WARN - Cannot parse JSON
com.ivkos.gpsd4j.support.GpsdParseException: Could not parse JSON: {"class":"TPV","device":"/dev/pts/9","mode":3,"time":"2012-11-04T14:03:37.000Z","ept":0.005,"lat":55.671585000,
	at com.ivkos.gpsd4j.support.SerializationHelper.deserialize(SerializationHelper.java:97)
	at com.ivkos.gpsd4j.client.GpsdClient.handleJsonString(GpsdClient.java:481)
	at com.ivkos.gpsd4j.client.GpsdClient.lambda$handleConnectResult$5(GpsdClient.java:437)
	at io.vertx.core.net.impl.NetSocketImpl.handleDataReceived(NetSocketImpl.java:325)
	at io.vertx.core.net.impl.NetClientImpl.handleMsgReceived(NetClientImpl.java:101)
	at io.vertx.core.net.impl.NetClientImpl.handleMsgReceived(NetClientImpl.java:45)
	at io.vertx.core.net.impl.NetClientBase$1.handleMsgReceived(NetClientBase.java:189)
	at io.vertx.core.net.impl.VertxNetHandler.lambda$channelRead$0(VertxNetHandler.java:63)
	at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:335)
	at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:193)
	at io.vertx.core.net.impl.VertxNetHandler.channelRead(VertxNetHandler.java:63)
	at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:122)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:341)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:349)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:129)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:642)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:565)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:479)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:441)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at java.lang.Thread.run(Unknown Source)
Caused by: io.vertx.core.json.DecodeException: Failed to decode: Unexpected end-of-input within/between OBJECT entries
 at [Source: {"class":"TPV","device":"/dev/pts/9","mode":3,"time":"2012-11-04T14:03:37.000Z","ept":0.005,"lat":55.671585000,; line: 1, column: 223]
	at io.vertx.core.json.Json.decodeValue(Json.java:123)
	at io.vertx.core.json.JsonObject.fromJson(JsonObject.java:950)
	at io.vertx.core.json.JsonObject.<init>(JsonObject.java:53)
	at com.ivkos.gpsd4j.support.SerializationHelper.deserialize(SerializationHelper.java:95)
	... 25 common frames omitted
2020-02-10T11:40:34.097Z [vert.x-eventloop-thread-0] WARN - Disconnected from gpsd server 10.99.17.63:2948. Will now try to reconnect...
2020-02-10T11:40:34.097Z [vert.x-eventloop-thread-0] INFO - Connecting to gpsd server 10.99.17.63:2948...
2020-02-10T11:40:34.122Z [vert.x-eventloop-thread-0] INFO - Successfully connected to gpsd server 10.99.17.63:2948
2020-02-10T11:40:34.123Z [vert.x-worker-thread-18] INFO - Jarek Successful connection!!!

I can see that if failed to parse these two JSON objects (at 2020-02-10T11:40:33.933Z and 2020-02-10T11:40:33.999Z respectively):

{"class":"TPV","device":"/dev/pts/9","mode":3,"time":"2012-11-04T14:03:31.000Z","ept":0.005,"lat":55.6715383

33,"lon":12.518386667,"alt":0.500,"epx":8.824,"epy":8.912,"epv":36.800,"track":22.7100,"speed":0.370,"climb":-0.800,"eps":17.82,"epc":73.60}

But they are in fact a single object.

Then it continued and parsed a few more messages. And then it tried to parse half of the message again at 2020-02-10T11:40:34.093Z, which caused a disconnect.

Have I configured something wrong? Any help would be appreciated.

Best wishes,
Jarek
@pschichtel
Copy link

pschichtel commented Aug 15, 2020 •
edited

I assume this happens if the payload is larger than either gpsd4j's receive buffer (4096 byte) or gpsd's transmit buffer, resulting in 2 partial reads in the client.

When you look into the socket handler (here), you'll see that it properly handles multiple objects in a single read, but cannot handle a partial objects. The handler should only ever pass an object to the parser, if it saw a terminating line break. If there is no line break yet, the data should be buffered until more data is available.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@pschichtel @Jarcionek