New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 737463 link

Starred by 4 users

Issue metadata

Status: Fixed
Owner:
Closed: Aug 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Mac
Pri: 2
Type: Bug-Regression



Sign in to add a comment

DevTools: Correct timestamp not shown for console evaluations

Reported by starbala...@gmail.com, Jun 28 2017

Issue description

UserAgent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10_12_4) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/59.0.3071.115 Safari/537.36

Steps to reproduce the problem:
1. In console settings -> Console -> Show timestamp should be checked
2. Open console and execute any js statement

What is the expected behavior?
Current timestamp should be shown along the result of the executed statement

What went wrong?
Some stale timestamp is shown. Check the attached image.

Did this work before? Yes 

Chrome version: 59.0.3071.115  Channel: stable
OS Version: OS X 10.12.4
Flash Version: 

Correct timestamp shown for logs triggered from loaded js/logs triggered from executed script (like setTimeout -> put log). Incorrect timestamp comes only for live statements alone.
 
Screen Shot 2017-06-28 at 1.14.59 PM.png
94.3 KB View Download

Comment 1 by woxxom@gmail.com, Jun 28 2017

Repro:
1. open devtools, open console, make sure "[x] show timestamps" is enabled either in console's own options (gear icon) or in devtools options (three-dot icon)
2. type 1 and press Enter
3. type 2 and press Enter
4. type 3 and press Enter
EXPECTED: the timestamps are different or no timestamps at all
OBSERVED: the timestamps are the same or invalid

Bisect: 447062 (good) - 447078 (bad), 58.0.2998.0
https://chromium.googlesource.com/chromium/src/+log/a65347a0..f77ebec0?pretty=fuller
Suspecting r447065 "DevTools: update console timestamp style"

Notes:
* Previously timestamps weren't shown for manually typed input, now they are. Probably an intended change.
* The timestamps for manually typed input were always incorrect internally, we just didn't see them.
* The suspected CL was partially reverted in r449051, but it didn't affect the bug.
Labels: Needs-Triage-M59
Cc: sandeepkumars@chromium.org
Labels: hasbisect
Owner: l...@chromium.org
Status: Assigned (was: Unconfirmed)
@woxxom: Thanks for providing the bisect information.

CHANGELOG URL:
https://chromium.googlesource.com/chromium/src/+log/a65347a0..f77ebec0?pretty=fuller

Review-Url: https://codereview.chromium.org/2651843003

@luoe: Could you please look into the issue, pardon me if it has nothing to do with your changes and if possible please assign it to concern owner.

Thanks!!

Comment 4 by l...@chromium.org, Jun 29 2017

Labels: -Needs-Triage-M59
Summary: DevTools: Correct timestamp not shown for console evaluations (was: Correct timestamp not shown in console log)
Thanks for the report and the bisect.  For evaluated commands (typing and pressing enter), these timestamps are incorrect.

DevTools rewrites the timestamp for evaluated commands and their results, to preserve their order when sorting by time.  We can either add a "display timestamp" and keep sorting internally, stop sorting entirely, or hide result timestamps entirely.

For reference, Firefox can show messages with timestamps out of order.

Comment 5 by l...@chromium.org, Jun 29 2017

Cc: einbinder@chromium.org l...@chromium.org
 Issue 695770  has been merged into this issue.
Project Member

Comment 6 by bugdroid1@chromium.org, Aug 7 2017

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

commit f2911d6203ee076f5cf1d7b26fee8972361922d3
Author: Erik Luo <luoe@chromium.org>
Date: Mon Aug 07 21:35:11 2017

DevTools: preserve console timestamps and sort on logical timestamps

Before, evaluated command and result console messages had their timestamps
overwritten to appear next to each other. This led to misleading times
that were incorrect, making commands seem to execute immediately.

This CL preserves their original timestamp for display, and introduces logical
timestamps for sorting purposes. Now, commands and results have more
useful times, even though their timestamps come from frontend, not backend.

BUG= 737463 

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

Comment 7 by l...@chromium.org, Aug 14 2017

Status: Fixed (was: Assigned)

Comment 8 by woxxom@gmail.com, Aug 20 2017

loue@ one case when the order is still incorrect:

1. disable timestamps in devtools console settings
2. clear the console (Ctrl-L)
3. run some async code, for example:
   fetch(location).then(r => r.text()).then(t => console.log('got %d bytes', t.length))

The result sometimes/often will be on top of the log.
I can submit a new bug report if required.

Comment 9 by l...@chromium.org, Aug 20 2017

Yes, please! A new crbug report about the ordering of messages would be great.  Feel free to tag me as owner.  If it is a bug that occurs sometimes but not always it sounds like a different root cause.

Comment 10 by woxxom@gmail.com, Aug 20 2017

loue@, I'm doubtful because your r492419 is within bisected range:
https://chromium.googlesource.com/chromium/src/+log/62f41748..f768b8da?pretty=fuller 
and I can repro reliably after clearing the console via Ctrl-L so I thought maybe it's some missed edge case.

Comment 11 by woxxom@gmail.com, Aug 20 2017

Submitted it as  issue 757245  and found the correlation: the async console.log output displays the moment the console was cleared instead of the correct timestamp.

Sign in to add a comment