Should I even report this to ST Support?
Of course you should.
Is this constant or off and on?
Constant, across devices and smartapps. The problem is bigger than it may seem, these are just the ones I can catch because they are on the second(s) boundary. The resolution isn’t small enough to see exactly HOW many of them are out of order and I’m guessing most of them would be if the IDE started logging at the ms level.
Here’s a device example:
79c8ac5d-045a-4b29-a744-15821d01f71c 2:30:45 PM: info Polled: Motion Alarm Callback Notification Enabled with URL http://tinyurl.com/otjrqxk
79c8ac5d-045a-4b29-a744-15821d01f71c 2:30:44 PM: trace Status: Alarm, Armed: Off
79c8ac5d-045a-4b29-a744-15821d01f71c 2:30:44 PM: info Motion Alarm Off
79c8ac5d-045a-4b29-a744-15821d01f71c 2:30:44 PM: trace Parse called
79c8ac5d-045a-4b29-a744-15821d01f71c 2:30:45 PM: trace Sending command -> http://192.168.1.104:80/XXXX
I’m an Engineer on the Developer Tools team. I can empathize on the frustration of this issue. It has bothered me in the past as well. Our IDE logging is built on top of a distributed messaging system which does not guarantee the order of the messages. So from a system standpoint this is working as expected. However, we might be able to improve the user experience by injecting the logging messages in a chronological order in the web browser. It still might not be a perfect solution, as some messages have the same timestamp.
In response to this thread I have created a feature request ticket to investigate the previously mentioned solution. As with any feature request, it will be prioritized against all the other cool tools we are working hard to bring to the community to improve our developer experience.
As always, we appreciate the bug reports - so thank you for bringing this to our attention.
Thanks — correcting this at the browser level would be fabulous.
And if you can add the Millisecond timestamp also it would be great!
Ha! I’ve been adding ms timestamp but it takes several ms to do it
@jeffblaisdell let me know once this has been done
Also I’m seeing issues with the IDE today, not sure if something changed
Sometimes when trying to save Smartapp code it gives me an error saying null pointed exception, retrying again a few times and it goes away.
When trying to open a SmartDevice code it says oh not something went wrong etc… try again and it goes away
Thanks for the info RBoy. I’m seeing same issue under my account.
We had a deployment earlier today, and are currently investigating.
I’ll ping back here when I know more.
One of the boxes in a cluster appeared to be non responsive after the deploy. We restarted it, and the errors seem to have stopped.
Are you still seeing the issue @RBoy?
Nope it’s okay now just that the IDE is VERY slow to save.
@jeffblaisdell FYI the events are still showing up out of order. I thought this issue was fixed:
403daa9b-0761-4c8f-ae75-21bada2dbb9a 10:09:05 PM: trace Checking expired updates for code 4 on Basement Door Lock
403daa9b-0761-4c8f-ae75-21bada2dbb9a 10:09:05 PM: trace Checking expired updates for code 2 on Basement Door Lock
403daa9b-0761-4c8f-ae75-21bada2dbb9a 10:09:05 PM: trace Checking expired updates for code 6 on Basement Door Lock
It’s a simple loop checking, it this should be going 1…6 but I see 1,3,5,6,2,4
Can you add a 2 second delay to the loop. I am guessing the resolution is not granular enough to order items that execute within 1 second. To test this add at least a second delay to the loop. I would bet your events will then return in order. The events are being executed in order but ST needs to be more granular with the time stamps used for sorting.
The ordering issue is not something we’ve gotten around to updating. It is an improvement that we will add, but it is a matter of priority / timing at the moment.
The execution is happening in the proper order. However the events describing the execution, flow through a distributed messaging system which does not guarantee order. Essentially it is a performance tradeoff to be able to handle the heavy load of all the events flowing into the system from every connected device.
To @jody.albritton 's point, the timestamp precision would also need to increase in order to get more accurate sorting.
@jeffblaisdell FYI Live Logging isn’t working, as in it’s complete dead no messages from anything whatsoever.
It’s back up now…
The live logging is broken again, it’s missing debug events. The same issue posted here:
the app runs I KNOW it’s running because things are happening but in between some debug messages are going missing. I see an event happen because it’s in a simple loop from 1 to 10 but suddenly in between event 4 happens but the debug message saying event 4 happen doesn’t print. 1 to 3 and 5 to 10 print, 4 happens but doesn’t print and it’s random! Sometimes all 10 will print sometimes a few will disappear in between.
Something is wrong here.
It’s pretty bad - I’m losing messages randomly - wondering if one of the servers in the cluster is down or out of sync