Problem with watch device after update

Niksu5 years ago

I updated Traccar to version 4.8 (previously it was 4.1 or 4.2 i don't remember which one). Update when fine and server is up and running. But today i noticed strange issue to gps tracker device tk806 (it uses watch protocol). It connects fine and send location fine. But about once or twice in hour it disconnect from server and connect again after that. I noticed that because server send Firebase push notifications every time when device is online / offline. Before update that same device work fine without this issue almost an year.

When i look traccar logs there is that kind of lines when device disconnect / connect again.

2020-03-02 12:46:15  INFO: [b1758d59: watch < 176.72.14.248] HEX: 5b53472a393137303732333839352a303039362a55442c3032303332302c3130343631332c412c36302e3238333635372c4e2c32352e3032383337352c452c302e303030302c3030302c302c31312c38302c37302c302c35302c30303030303030302c342c312c3234342c39312c343131322c32303934392c3133372c343131322c32313135382c3133352c343131322c32323232392c3133332c343131322c32303737332c3133322c2c30305d
2020-03-02 12:46:15  INFO: [b1758d59] id: 9170723895, time: 2020-03-02 12:46:13, lat: 60.28366, lon: 25.02838, course: 0.0
2020-03-02 12:46:20  INFO: [b1758d59: watch < 176.72.14.248] HEX: 5b53472a393137303732333839352a303041352a55442c3032303332302c3130343631382c412c36302e3238333635372c4e2c32352e3032383337352c452c302e303030302c3030302c302c31312c38302c37302c302c35302c30303030303030302c352c312c3234342c39312c343131322c32303934392c3133372c343131322c32313135382c3133342c343131322c32323232392c3133332c343131322c32303737332c3133322c343131322c32
2020-03-02 12:46:20  INFO: [b1758d59: watch < 176.72.14.248] HEX: 303831372c3132382c2c30305d
2020-03-02 12:46:20  WARN: [b1758d59] error - BufferOverflowException (... < WrapperInboundHandler:57 < ... < StandardLoggingHandler:43 < ... < NetworkMessageHandler:37 < ...)
2020-03-02 12:46:20  WARN: [b1758d59] error - class io.netty.buffer.UnpooledByteBufAllocator$InstrumentedUnpooledHeapByteBuf cannot be cast to class org.traccar.NetworkMessage (io.netty.buffer.UnpooledByteBufAllocator$InstrumentedUnpooledHeapByteBuf and org.traccar.NetworkMessage are in unnamed module of loader 'app') - ClassCastException (ExtendedObjectDecoder:48 < ... < WrapperInboundHandler:50 < ... < OpenChannelHandler:38 < ...)
2020-03-02 12:46:20  INFO: [b1758d59] disconnected
2020-03-02 12:46:22  INFO: [45733a48] connected
2020-03-02 12:46:26  INFO: [45733a48: watch < 176.72.14.248] HEX: 5b53472a393137303732333839352a303041352a55442c3032303332302c3130343632332c412c36302e3238333635372c4e2c32352e3032383337352c452c302e303030302c3030302c302c31312c38302c37302c302c35302c30303030303030302c352c312c3234342c39312c343131322c32303934392c3133372c343131322c32313135382c3133362c343131322c32323232392c3133342c343131322c32303737332c3133322c343131322c32303831372c3132382c2c30305d
2020-03-02 12:46:27  INFO: [45733a48] id: 9170723895, time: 2020-03-02 12:46:23, lat: 60.28366, lon: 25.02838, course: 0.0
2020-03-02 12:46:29  INFO: [45733a48: watch < 176.72.14.248] HEX: 5b53472a393137303732333839352a303039362a55442c3032303332302c3130343632372c412c36302e3238333635372c4e2c32352e3032383337372c452c302e303030302c3030302c302c31322c38302c37302c302c35302c30303030303030302c342c312c3234342c39312c343131322c32303934392c3133372c343131322c32313135382c3133372c343131322c32323232392c3133332c343131322c32303737332c3133332c2c30305d
2020-03-02 12:46:29  INFO: [45733a48] id: 9170723895, time: 2020-03-02 12:46:27, lat: 60.28366, lon: 25.02838, course: 0.0

Anton Tananaev5 years ago

Try to set logger.fullStackTraces to true in the config.

Niksu5 years ago

Ok, i set that on and there is log.

2020-03-02 18:13:33  INFO: [ab6981be] id: 9170723895, time: 2020-03-02 18:13:22, lat: 60.28372, lon: 25.02841, course: 0.0
2020-03-02 18:13:39  INFO: [ab6981be: watch < 109.240.116.82] HEX: 5b53472a393137303732333839352a303036412a55442c3032303332302c3136313332372c562c36302e3238333731372c4e2c32352e3032383431322c452c302e303030302c3030302c32352c30302c35302c37302c302c35302c30303030303030302c312c312c3234342c39312c343131322c32303933362c3132322c2c30305d
2020-03-02 18:13:39  INFO: [ab6981be] id: 9170723895, time: 2020-03-02 18:13:27, lat: 60.28372, lon: 25.02841, course: 0.0
2020-03-02 18:13:42  INFO: [ab6981be: watch < 109.240.116.82] HEX: 5b53472a393137303732333839352a303036412a55442c3032303332302c3136313333322c562c36302e3238333731372c4e2c32352e3032383431322c452c302e303030302c3030302c32352c30302c35302c37302c302c35302c30303030303030302c312c312c3234342c39312c343131322c32303933362c3132322c2c30305d
2020-03-02 18:13:42  INFO: [ab6981be] id: 9170723895, time: 2020-03-02 18:13:32, lat: 60.28372, lon: 25.02841, course: 0.0
2020-03-02 18:13:48  INFO: [ab6981be: watch < 109.240.116.82] HEX: 5b53472a393137303732333839352a303036412a55442c3032303332302c3136313333372c562c36302e3238333731372c4e2c32352e3032383431322c452c302e303030302c3030302c32352c30302c35302c37302c302c35302c30303030303030302c312c312c3234342c39312c343131322c32303933362c3132322c2c30305d
2020-03-02 18:13:48  INFO: [ab6981be] id: 9170723895, time: 2020-03-02 18:13:37, lat: 60.28372, lon: 25.02841, course: 0.0
2020-03-02 18:13:54  INFO: [ab6981be: watch < 109.240.116.82] HEX: 5b53472a393137303732333839352a303037392a55442c3032303332302c3136313334322c562c36302e3238333731372c4e2c32352e3032383431322c452c302e303030302c3030302c32352c30302c35302c37302c302c35302c30303030303030302c322c312c3234342c39312c343131322c32303933362c3132322c343131322c32313034352c3132312c2c3030
2020-03-02 18:13:54  INFO: [ab6981be: watch < 109.240.116.82] HEX: 5d
2020-03-02 18:13:54  WARN: [ab6981be] error -
java.nio.BufferOverflowException
    at java.base/java.nio.DirectByteBuffer.put(DirectByteBuffer.java:373)
    at io.netty.buffer.PoolArena$DirectArena.memoryCopy(PoolArena.java:795)
    at io.netty.buffer.PoolArena$DirectArena.memoryCopy(PoolArena.java:704)
    at io.netty.buffer.PoolArena.reallocate(PoolArena.java:405)
    at io.netty.buffer.PooledByteBuf.capacity(PooledByteBuf.java:118)
    at io.netty.buffer.AbstractByteBuf.ensureWritable0(AbstractByteBuf.java:306)
    at io.netty.buffer.AbstractByteBuf.ensureWritable(AbstractByteBuf.java:282)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1104)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1097)
    at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1088)
    at io.netty.handler.codec.ByteToMessageDecoder$1.cumulate(ByteToMessageDecoder.java:94)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:269)
    at org.traccar.WrapperInboundHandler.channelRead(WrapperInboundHandler.java:57)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
    at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93)
    at org.traccar.handler.StandardLoggingHandler.channelRead(StandardLoggingHandler.java:43)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
    at org.traccar.handler.NetworkMessageHandler.channelRead(NetworkMessageHandler.java:37)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
    at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:163)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:615)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:578)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)
 
2020-03-02 18:13:54  WARN: [ab6981be] error -
java.lang.ClassCastException: class io.netty.buffer.UnpooledByteBufAllocator$InstrumentedUnpooledHeapByteBuf cannot be cast to class org.traccar.NetworkMessage (io.netty.buffer.UnpooledByteBufAllocator$InstrumentedUnpooledHeapByteBuf and org.traccar.NetworkMessage are in unnamed module of loader 'app')
    at org.traccar.ExtendedObjectDecoder.channelRead(ExtendedObjectDecoder.java:48)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:377)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:363)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:355)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:316)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:303)
    at io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:417)
    at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:396)
    at io.netty.handler.codec.ByteToMessageDecoder.channelInputClosed(ByteToMessageDecoder.java:363)
    at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:346)
    at org.traccar.WrapperInboundHandler.channelInactive(WrapperInboundHandler.java:50)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:260)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:246)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:239)
    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
    at org.traccar.handler.OpenChannelHandler.channelInactive(OpenChannelHandler.java:38)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:260)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:246)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:239)
    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:81)
    at io.netty.handler.timeout.IdleStateHandler.channelInactive(IdleStateHandler.java:277)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:260)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:246)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:239)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelInactive(DefaultChannelPipeline.java:1405)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:260)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:246)
    at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:901)
    at io.netty.channel.AbstractChannel$AbstractUnsafe$8.run(AbstractChannel.java:818)
    at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:472)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:497)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.base/java.lang.Thread.run(Thread.java:834)
 
2020-03-02 18:13:54  INFO: [ab6981be] disconnected
2020-03-02 18:13:55  INFO: [7ff13da5] connected
2020-03-02 18:13:56  INFO: [7ff13da5: watch < 109.240.116.82] HEX: 5b53472a393137303732333839352a303037392a55442c3032303332302c3136313334372c562c36302e3238333731372c4e2c32352e3032383431322c452c302e303030302c3030302c32352c30302c34302c37302c302c35302c30303030303030302c322c312c3234342c39312c343131322c32303933362c3132322c343131322c32313034352c3132312c2c30305d
2020-03-02 18:13:56  INFO: [7ff13da5] id: 9170723895, time: 2020-03-02 18:13:47, lat: 60.28372, lon: 25.02841, course: 0.0
2020-03-02 18:14:02  INFO: [7ff13da5: watch < 109.240.116.82] HEX: 5b53472a393137303732333839352a303036412a55442c3032303332302c3136313335322c562c36302e3238333731372c4e2c32352e3032383431322c452c302e303030302c3030302c32352c30302c34302c37302c302c35302c30303030303030302c312c312c3234342c39312c343131322c32303933362c3132322c2c30305d
2020-03-02 18:14:02  INFO: [7ff13da5] id: 9170723895, time: 2020-03-02 18:13:52, lat: 60.28372, lon: 25.02841, course: 0.0
2020-03-02 18:14:08  INFO: [7ff13da5: watch < 109.240.116.82] HEX: 5b53472a393137303732333839352a303036412a55442c3032303332302c3136313335372c562c36302e3238333731372c4e2c32352e3032383431322c452c302e303030302c3030302c32352c30302c35302c37302c302c35302c30303030303030302c312c312c3234342c39312c343131322c32303933362c3132322c2c30305d
2020-03-02 18:14:08  INFO: [7ff13da5] id: 9170723895, time: 2020-03-02 18:13:57, lat: 60.28372, lon: 25.02841, course: 0.0

Anton Tananaev5 years ago

Looks like it's Netty issue:

https://github.com/netty/netty/issues/9911

Niksu5 years ago

Ok. So i need to wait next release to get it fixed. Is there any eta for that ?

Anton Tananaev5 years ago

Don't have an ETA.