Bug with log statement ordering

[blueyetisoftware]

I am doing some trace logging in Edge and have noticed the log statements are not always ordered correctly. I have not found a reason for it yet, but I’m hoping there is a quick explanation. After I noticed the ordering, I dropped 3 log statements on consecutive lines:

log.warn('scan_access_dni1 = ', access_dni)
log.warn('scan_access_dni2 = ', access_dni)
log.warn('scan_access_dni3 = ', access_dni)

Resulting in this reverse order in the log. Check out the timestamps as well.

2023-03-15T23:20:50.838937610+00:00 WARN scan_access_dni3 =        ZZDJXXXXX
2023-03-15T23:20:50.840501943+00:00 WARN scan_access_dni2 =        ZZDJXXXXX
2023-03-15T23:20:50.842528610+00:00 WARN scan_access_dni1 =        ZZDJXXXXX

I saw the same thing using print instead, so it doesn’t seem to be an issue with log. Maybe it is a side effect of something related to the use of coroutines? Stumped on this one.

I saw a groovy era post from @dorfl and @orangebucket that was similar, but not sure it is relevant. In my case the order is strictly reversed and not random. Seems like the log statements are placed in a dequeue and being popped off from the wrong end.

Log.debug order (new here_

I created a simple code to learn for (def i = 0; i <256; i++) { log.debug “${i}” } The output is random: 192, 244,238, 236, 188,234, … you get the picture How am I supposed to trace events with this? hints and ideas?

Edit:
When it occurs, the reverse order also occurs down inside nested function calls. The log will be properly ordered, then at some point flips for a small amount of time before returning to normal.

[orangebucket (Graham)]

@blueyetisoftware

I saw a groovy era post from @dorfl and @orangebucket that was similar, but not sure it is relevant

I guess it may be. I don’t know if logging has evolved much over the last few years, or even decades. I can remember that lines used to be dropped from the live logging in the IDE, but can’t remember about any issue with ordering.

I’ve not looked closely at the history in the Android app lately, but as I recall it is common to see them as batches in the ‘wrong’ order. So if the order of events was e.g. 1, 2, 3 ... 4, 5 ... 6, 7, 8 what you see is (latest first):

6
7
8
4
5
1
2
3

Now the question with your example is do the timestamps belong to the log lines they are written alongside?

[blueyetisoftware]

That’s a tough one to answer without being able to trust trace logging

[blueyetisoftware]

@orangebucket

I’ve not looked closely at the history in the Android app lately,

I would also clarify that the logs in this case are directly in the CLI connected to the hub and not through the app history.

[orangebucket (Graham)]

@blueyetisoftware

I would also clarify that the logs in this case are directly in the CLI connected to the hub and not through the app history.

Yes, I was really bringing in other examples of odd ordering of log messages as they may have something in common.

[posborne (Paul Osborne)]

@blueyetisoftware We discussed this issue internally and will look to rectify the problem in future firmware releases (0.48+). Several versions back, a change was made behind the covers to change log messages from drivers to be delivered to emitted out of the sandbox asynchronous to code execution within the sandbox; this seems to have resulted in the potential for there to be a change in scheduling of the logging of messages emitted within a small window to have the potential to be ordered differently when they make it through that layers outside of the sandbox.

This potential issue is isolated to the pattern used for emitting log messages and we don’t have any concerns about out-of-order execution of other things like zigbee commands or device events (though, in general, exact ordering of device events in the larger smartthings platform is not guaranteed).

Thanks for reporting the issue!

[blueyetisoftware]

Perfect explanation. Thank you very much