Negative delays when saving dump to file

[timower]

While I was sending a dump file I got a python exception that sleep requested negative delays. When I searched the output file, I found that the difference between the timestamp of some lines was indeed negative.

For example:

Timestamp: 1541504408.838742        ID: 0191    S          DLC: 7    01 00 10 a1 41 00 1a
Timestamp: 1541504408.838750        ID: 0133    S          DLC: 5    00 00 00 00 b6
Timestamp: 1541504408.838748        ID: 0244    S          DLC: 5    00 00 00 01 44
Timestamp: 1541504408.838758        ID: 0136    S          DLC: 8    00 02 00 00 00 00 00 39
Timestamp: 1541504408.839845        ID: 013a    S          DLC: 8    00 00 00 00 00 00 00 37

[kasperkarlsson]

The issue has been verified.

Patched in https://github.com/CaringCaribou/caringcaribou/commit/ad6b145a7e8ff3c777c57852b9271ee2f754e873 - if the delay is smaller than 0, the delay will simply be ignored. Can you verify that this resolves the issue on your end as well?

[timower]

Yes, works better now! Still seems strange, either the timestamp is wrong or the order in the file is wrong. Both of which indicate a bug no?

[kasperkarlsson]

The dump module previously ran a callback function which wrote to the dump file in a separate thread for each incoming message. Due to this, race conditions could occur; causing messages to be handled and logged in the wrong order.

This should no longer happen after changes introduced in https://github.com/CaringCaribou/caringcaribou/commit/59a9bee4e1d07664317ec472f4c6fc3cafddc6dc, where the handling of incoming messages was refactored to run sequentially in a single thread instead.

To summarize the difference in behavior:

Old dump module structure:

• Main thread sets up callback handler and then just hangs around consuming CPU while waiting for the user to terminate
• For each incoming message, spawn another thread running a callback handler which will write the message to the file
• The OS handles threading prioritization (usually within a single process, due to GIL) which may cause them to be run in another order than the messages were received in (i.e. a race condition)

New dump module structure (as of https://github.com/CaringCaribou/caringcaribou/commit/59a9bee4e1d07664317ec472f4c6fc3cafddc6dc):

• The main thread itself reads from the queue of incoming messages
• Each message is processed and written to file in order

As such, the race condition which could cause messages to end up in the wrong order in the dump file should already be solved. Feel free to open a new issue if you encounter anything strange related to this.