As per suspected CL from comment #0, assigning it to the luoe@ for further triage.

Thanks for the report.  Unfortunately, I'm not able to reproduce the wrong message order on my machine with the fetch example.  Waiting a second, or evaluating immediately on step 4 doesn't do anything different for me, I still see 'fetch...' then 'Promise...' then 'got N bytes'.

Timestamps should not be different if the last console clear was 1s ago or 10s ago. 
 Could you please help explain what you mean by "The 1st line's displays the moment the console was cleared instead of the correct timestamp"?  After I can repro this case, I should be able to more effectively find a fix.

It is possible for the 'got N bytes' message to have a timestamp earlier than the 'Promise...' message, but that shouldn't be affecting the visual order you see the messages in.

>Could you please help explain what you mean by "The 1st line's displays the moment the console was cleared instead of the correct timestamp"?

The word "timestamp" was missing.
I thought the 1st line's timestamp displays the moment the console was cleared, but actually it's simply ~1 second behind the correct time.

As you can see on the screenshot of devtools-for-devtools below, the timestamp of the result is the smallest of the three, and it's displayed on top.
The repro sequence in #0 is 100% working here on the default empty profile used by chromium snapshots during bisecting.

Deleted: devtools-for-devtools.png 57.1 KB

	devtools-for-devtools.png 57.1 KB View Download

...and by "result" I mean what's displayed by the command's explicit console.log whereas in terms of ConsoleView class it's the "log" line.

Anyway, I've debugged ConsoleView._addConsoleMessage.

* this._consoleMessages in good builds after clearing console:
  type:"command", timestamp:0
  type:"result",  timestamp:0
  type:"log",     timestamp:1503386144158.216

* this._consoleMessages in bad builds:
  type:"log",     timestamp:1503386444383.6008
  type:"command", timeForSorting:1503386445057 
  type:"result",  timeForSorting:1503386445057 

The obvious difference is that previously "command" and "result" didn't have a timestamp so the "log" message got inserted at the end correctly.
r492419 changes that in _addConsoleMessage [1] by introducing an additional timestamp property, which seems intended and correct, but the underlying issue is the wrong incoming timestamp of "log", which is smaller (why? seems like a bug somewhere else) than those of "command" and "result" so it gets inserted at the top.

Note, for reliable repro an exactly 1 second pause after clearing the console and running the command is crucial to mess the timing. Not 2 or more. Not less than 1. In other words, Ctrl-L, wait for two blinks of input cursor, paste (or Up key if repeating) and run the command.

  [1]: https://chromium-review.googlesource.com/c/chromium/src/+/590502/8/third_party/WebKit/Source/devtools/front_end/console/ConsoleView.js#413

Further investigation shows that timestamps for console.log messages were always incorrect as observed since around M38 where the feature was introduced: the displayed time precedes the actual time by as much as several seconds when running the following code:

var d = new Date(); console.log(d.toLocaleTimeString('fr') + '.' + ('00' + d.getMilliseconds()).slice(-3));

Bisect info: 286925 (good) - 286930 (bad)
https://chromium.googlesource.com/chromium/src/+log/c618c920..1d76598c?pretty=fuller
Suspecting r286928 "Use HighResNow whenever possible on Windows"
Landed in 38.0.2111.0

More investigation.
The console.log timestamp bug from #6 is still present in canary but only in case I don't press anything in devtools for 1 second before running the following:

fetch(location).then(r => r.text()).then(t => { var d = new Date(); console.log('%s: got %d bytes', d.toLocaleTimeString('fr') + '.' + ('00' + d.getMilliseconds()).slice(-3), t.length); })

It looks like console.log gets its timestamp from a network event such as fetch or XHR, and these timestamps are set incorrectly judging by the OS system time displayed in the date/time control panel.

I'm attaching a screenshot that shows:
1. the original bug in #0 ("log" line on top after clearing the console and waiting for 1 second)
2. the bug found in #6-7 (incorrect timestamps of "log" lines in case I don't do anything in devtools for a second).

Deleted: time-deviation.png 19.2 KB

	time-deviation.png 19.2 KB View Download

I really appreciate your thorough investigation, the timeForSorting numbers in comment #5 suggests to me that I introduced a bug when calculating timeForSorting.  The 'after' CL numbers show command/result with nonzero timeForSorting, which is not intended if command/result arrive to the console first.

My guess is that instead of doing this on ConsoleView.js L458:
`return viewMessage[Console.ConsoleView._messageSortingTimeSymbol] || viewMessage.consoleMessage().timestamp;`

We should be doing something like this, in case the value in the symbol is 0:
`return (typeof viewMessage[Console.ConsoleView._messageSortingTimeSymbol] === 'undefined') ? viewMessage.consoleMessage().timestamp : viewMessage[Console.ConsoleView._messageSortingTimeSymbol];`

woxxom@, I have a favor to ask of you, could you please help me verify that this is the correct fix?  Here are the steps:
- In a Canary/bad build, open DevTools on DevTools
- In the second DevTools, open the Console
- Evaluate the contents of the 'timestampSortingSpecFix.txt' in the Console, which should override _addConsoleMessage()
- Back in the first DevTools, try to reproduce the bug

If my hypothesis is correct, the speculative fix should address the original issue.  I'll work on a CL and a test in the meantime.


As for the points about incorrect timestamps in comments #6 and #7, some of those drifts >1 sec seem extreme.  I'd rather file yet another crbug to address that issue.

Deleted: timestampSortingSpecFix.txt 1.5 KB

timestampSortingSpecFix.txt 1.5 KB View Download

timestampSortingSpecFix.txt evidently fixes the issue for me. 
Can't repro with the fix applied and can repro after resetting back to the shipped code by reopening devtools.

Filed  issue 757950  for the timestamp drifts.

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/18970acca31c1d3b8587d8b5248098d452104fa8

commit 18970acca31c1d3b8587d8b5248098d452104fa8
Author: Erik Luo <luoe@chromium.org>
Date: Wed Aug 23 03:28:26 2017

DevTools: fix console timestamp sorting bug for initial command result

Console sorts messages by timestamp, except for Command/Result messages,
which are kept in arrival order. Before, a bug allowed a message with an
earlier timestamp to appear above the first command message, even though
the command message arrived to the console first.

After this CL, DevTools correctly checks for the adjusted time, so later
messages will not be able to appear before the first command/results.

Bug:  757245 
Change-Id: I228d8774b96da36d218330fd11c9c94f11656893
Reviewed-on: https://chromium-review.googlesource.com/626945
Commit-Queue: Erik Luo <luoe@chromium.org>
Reviewed-by: Andrey Lushnikov <lushnikov@chromium.org>
Cr-Commit-Position: refs/heads/master@{#496579}
[modify] https://crrev.com/18970acca31c1d3b8587d8b5248098d452104fa8/third_party/WebKit/LayoutTests/inspector/console/console-timestamp-expected.txt
[modify] https://crrev.com/18970acca31c1d3b8587d8b5248098d452104fa8/third_party/WebKit/LayoutTests/inspector/console/console-timestamp.html
[modify] https://crrev.com/18970acca31c1d3b8587d8b5248098d452104fa8/third_party/WebKit/Source/devtools/front_end/console/ConsoleView.js

Thanks for the help in fixing this!