Server.log() out of order


#1

(the category is still called planner, but i guess IDE stuff goes here too)

i noticed that server.log() messages arrive out-of-order. i made my own wrapper that puts a counter in front of the text.
here is a snipped of the log:

2013-11-16 13:04:06 UTC+1: [Device] 0 : Writing HostCmd 00 0000
2013-11-16 13:04:06 UTC+1: [Device] 1 : Writing HostCmd 44 0000
2013-11-16 13:04:06 UTC+1: [Device] 2 : EVE not found!: ><
2013-11-16 13:04:06 UTC+1: [Device] 3 : Chip detected – continuing with init
2013-11-16 13:04:06 UTC+1: [Device] 4 : Writing 00000000 to adr 102490
2013-11-16 13:04:06 UTC+1: [Device] 5 : Writing 00000080 to adr 1024c4
2013-11-16 13:04:06 UTC+1: [Device] 6 : Writing 00000000 to adr 10246c
2013-11-16 13:04:06 UTC+1: [Device] 7 : Writing 00000001 to adr 102468
2013-11-16 13:04:06 UTC+1: [Device] 8 : Writing 000001e0 to adr 102430
2013-11-16 13:04:06 UTC+1: [Device] 9 : Writing 00000224 to adr 102428
2013-11-16 13:04:06 UTC+1: [Device] 10 : Writing 0000002b to adr 10242c
2013-11-16 13:04:06 UTC+1: [Device] 12 : Writing 00000029 to adr 102438
2013-11-16 13:04:06 UTC+1: [Device] 11 : Writing 00000000 to adr 102434
2013-11-16 13:04:06 UTC+1: [Device] 14 : Writing 00000124 to adr 10243c
2013-11-16 13:04:06 UTC+1: [Device] 13 : Writing 00000110 to adr 102444
2013-11-16 13:04:06 UTC+1: [Device] 15 : Writing 0000000c to adr 102440
2013-11-16 13:04:06 UTC+1: [Device] 16 : Writing 00000000 to adr 102448
2013-11-16 13:04:06 UTC+1: [Device] 22 : Writing 00000002 to adr 102450
2013-11-16 13:04:06 UTC+1: [Device] 21 : Writing 00000000 to adr 100008
2013-11-16 13:04:06 UTC+1: [Device] 20 : Writing 26000007 to adr 100004
2013-11-16 13:04:06 UTC+1: [Device] 19 : Writing 02004000 to adr 100000
2013-11-16 13:04:06 UTC+1: [Device] 18 : Writing 00000000 to adr 102464
2013-11-16 13:04:06 UTC+1: [Device] 17 : Writing 0000000a to adr 10244c
2013-11-16 13:04:06 UTC+1: [Device] 24 : Writing 00000005 to adr 10246c
2013-11-16 13:04:06 UTC+1: [Device] 23 : Writing 00000080 to adr 102490
2013-11-16 13:04:09 UTC+1: [Device] 25 : Writing 1f000002 to adr 100000
2013-11-16 13:04:09 UTC+1: [Device] 28 : Writing 00000000 to adr 10000c
2013-11-16 13:04:09 UTC+1: [Device] 27 : Writing 21000000 to adr 100008
2013-11-16 13:04:09 UTC+1: [Device] 26 : Writing 86405000 to adr 100004
2013-11-16 13:04:09 UTC+1: [Device] 29 : Writing 00000002 to adr 102450
2013-11-16 13:04:12 UTC+1: [Device] 30 : Init completed
2013-11-16 13:02:38 UTC+1: [Device] 26 : Writing 86405000 to adr 100004
2013-11-16 13:02:38 UTC+1: [Device] 27 : Writing 21000000 to adr 100008

i have no idea where the last 2 lines came from, as the timestamp is 2 minutes before the other logs.


#2

coming-back logs happen to me too.
Very frustrating


#3

it happens to me. I could be wrong but I think I have cleared the log only to have it refresh later - and then it is ordered correctly. it is something you might try. of course copy out the log before you try it.


#4

I clear those logs over and over, but they keep coming back…


#5

I’ve also noted a bit of strange log behavior for the past couple of weeks or so that might be related to the “log out of order” observation.

I have an app that does a server log once a minute. If I scroll thru the log, I’ll note whole sections (perhaps 15-30 minute chunks) will often repeat. (This is distinct from the duplicate/triplicate individual log entries that have been previously reported, which can be removed by refreshing).

It had me going for a bit as it looked like things were out of order occasionally, until I recognized these long repeat sequences. (Clearing or refresh does not eliminate this).


#6

Yep, there’s a bug here - refreshing gets them back in order. Likely related to the new protocol used between the browser & the backend. Being worked on.


#7

glad to hear