h02 device message decoding error

Hi there!

I'm building the git version and it was working until Jun 14 (last time I built from git). Today, after rebuilding the project, I'm getting this in the logs:

2022-06-17 20:49:10  INFO: [T8fa8f9a6] connected
2022-06-17 20:49:10 DEBUG: -Dio.netty.recycler.maxCapacityPerThread: 4096
2022-06-17 20:49:10 DEBUG: -Dio.netty.recycler.maxSharedCapacityFactor: 2
2022-06-17 20:49:10 DEBUG: -Dio.netty.recycler.linkCapacity: 16
2022-06-17 20:49:10 DEBUG: -Dio.netty.recycler.ratio: 8
2022-06-17 20:49:10 DEBUG: -Dio.netty.recycler.delayedQueue.ratio: 8
2022-06-17 20:49:10 DEBUG: -Dio.netty.buffer.checkAccessible: true
2022-06-17 20:49:10 DEBUG: -Dio.netty.buffer.checkBounds: true
2022-06-17 20:49:10 DEBUG: Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@1b53819
2022-06-17 20:49:10  INFO: [T8fa8f9a6: h02 < 179.175.176.92] 2a48512c363032383136393734312c56312c3233343930392c412c323932332e383735372c532c30353135362e393139352c572c3030302e30302c3030302c3137303632322c46464646464246462c3732342c30362c323635312c31313236332c31312c313223
2022-06-17 20:49:11  INFO: [T8fa8f9a6: h02 > 179.175.176.92] 2a48512c363032383136393734312c56342c56312c323032323036313732333439313123
2022-06-17 20:49:11  INFO: [T8fa8f9a6] error - NullPointerException (CacheManager:91 < ... < *:92 < ConnectionManager:301 < *:269 < BaseProtocolDecoder:193 < ...)
2022-06-17 20:49:11  INFO: [T8fa8f9a6] disconnected
2022-06-17 20:49:11  INFO: [T8fa8f9a6] error - NullPointerException (CacheManager:91 < ... < *:92 < ConnectionManager:301 < *:269 < *:185 < MainEventHandler:139 < ...)
2022-06-17 20:49:12  INFO: [T9c15703d] connected
2022-06-17 20:49:36 DEBUG: HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2022-06-17 20:49:36 DEBUG: HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0).
2022-06-17 20:50:03  INFO: [T58808a31] connected
2022-06-17 20:50:03  INFO: [T58808a31: h02 < 179.175.178.187] 2a48512c363032383136393734312c56312c3233353030322c412c323932332e383930312c532c30353135362e393331312c572c3030302e30302c3036302c3137303632322c46464646464246462c3732342c30362c323635312c31313236332c31312c313123
2022-06-17 20:50:03  INFO: [T58808a31] error - NullPointerException (ConnectionManager:131 < BaseProtocolDecoder:137 < H02ProtocolDecoder:322 < ...)
2022-06-17 20:50:03  INFO: [T58808a31] disconnected
2022-06-17 20:50:04  INFO: [T028a6ac9] connected
2022-06-17 20:50:06 DEBUG: HikariPool-1 - Pool stats (total=10, active=0, idle=10, waiting=0)
2022-06-17 20:50:06 DEBUG: HikariPool-1 - Fill pool skipped, pool has sufficient level or currently being filled (queueDepth=0).

Any clues on what can be wrong? Maybe H02ProtocolDecoder is messed up?

Note: I'm using all source code directly from git, without touching any files.

Thanks!

Anton Tananaev3 years ago

More likely an issue with the code. You shouldn't use master if you want a stable version.

Yes, for sure. I'm using master exactly to be able to contribute. :) Any hints on how to debug that? H02ProtocolDecoder:322 is:

DeviceSession deviceSession = getDeviceSession(channel, remoteAddress, id);

Can you give me some pointers on how to help you debugging and fixing this?

Thanks, Anton.

Anton Tananaev3 years ago

I'm already working on a fix. It's related to the recent changes to caching.

Ok then. Thanks again.

Anton Tananaev3 years ago

This should fix it:

https://github.com/traccar/traccar/commit/316ef36ca8bf6425df5a6186da2e7901dcb23c0e

Next time you can create a GitHub ticket if you see any crashes. That way I can link fixes to tickets.

Great! Will do for sure.

Just a feedback: everything working properly again.

2022-06-17 21:53:52  INFO: [Tc0eb7d1b] connected
2022-06-17 21:53:52  INFO: [Tc0eb7d1b: h02 < 179.175.186.15] 2a48512c363032383136393734312c56312c3030353335302c412c323932332e383930312c532c30353135362e393331312c572c3030302e30302c3132362c3138303632322c46464646464246462c3732342c30362c323635312c31313236332c30392c313423
2022-06-17 21:53:52  INFO: [Tc0eb7d1b: h02 > 179.175.186.15] 2a48512c363032383136393734312c56342c56312c323032323036313830303533353223
2022-06-17 21:53:53  INFO: [Tc0eb7d1b] id: 6028169741, time: 2022-06-17 21:53:50, lat: -29.39817, lon: -51.94885, course: 126.0

Best wishes!

Alex.

Anton Tananaev3 years ago

There could be more problem. We're are making very big changes to caching.