console input/output timestamps OK, message timestamps always incorrect

RESOLVED FIXED in Firefox 30

Status

defect
RESOLVED FIXED
5 years ago
10 months ago

People

(Reporter: anaran, Assigned: baku)

Tracking

30 Branch
Firefox 32
Bug Flags:
in-testsuite +

Firefox Tracking Flags

(firefox29 unaffected, firefox30+ fixed, firefox31+ fixed, firefox32+ fixed, b2g-v1.4 fixed, b2g-v2.0 fixed)

Details

Attachments

(5 attachments, 1 obsolete attachment)

(Reporter)

Description

5 years ago
to witness:

   19:21:48.684 console.log((new Date()).toString())
   19:21:48.689 undefined
-> 13:31:31.217 "Mon May 05 2014 19:21:48 GMT+0200"

   19:22:38.189 console.warn((new Date()).toString())
   19:22:38.191 undefined
-> 03:16:33.889 "Mon May 05 2014 19:22:38 GMT+0200"

   19:22:45.794 console.error((new Date()).toString())
   19:22:45.800 undefined
-> 05:23:22.218 "Mon May 05 2014 19:22:45 GMT+0200"

   19:23:01.681 console.debug((new Date()).toString())
   19:23:01.687 undefined
-> 09:48:09.077 "Mon May 05 2014 19:23:01 GMT+0200"

   19:23:09.467 console.count((new Date()).toString())
   19:23:09.473 undefined
-> 11:57:55.131 "Mon May 05 2014 19:23:09 GMT+0200: 1"
(Reporter)

Comment 1

5 years ago
Restarted with all addons disabled in safe mode BTW.
(Reporter)

Comment 2

5 years ago
Look what I found :-)

19:41:41.032 console.log((new Date(Date.now() * 1000)).toString())
19:41:41.034 undefined
08:43:54.716 "Tue Jun 04 46312 08:43:54 GMT+0200"
(Reporter)

Comment 3

5 years ago
Also exists in Firefox 30.
Version: 32 Branch → 30 Branch
Duplicate of this bug: 1006159
Status: UNCONFIRMED → NEW
Ever confirmed: true
(Reporter)

Comment 5

5 years ago
Hi Panos, @past,
I guess a test case to detect this bug could use an approach similar to
https://bugzilla.mozilla.org/attachment.cgi?id=8381501&action=diff#a/browser/devtools/webconsole/test/browser_webconsole_start_netmon_first.js_sec2

Is it possible to submit and test tests without building firefox locally?
Yes, something like that should be a good starting point for a test. Unfortunately you would have to build firefox after adding the test to the manifest first, like this:

https://bugzilla.mozilla.org/attachment.cgi?id=8381501&action=diff#a/browser/devtools/webconsole/test/browser.ini_sec2
(Reporter)

Comment 7

5 years ago
I am now working on a test for this bug.

message with incorrect timestamp appears right after line 1065 is executed.

I have not been able to spot the cause of the incorrect timestamp.

Using a usec value as an argument for new Date(microSecondsInsteadOfMilliMaybe) would also produce this symptom.

1065      result = dbgWindow.evalInGlobalWithBindings(aString, bindings, evalOptions);
1066    }
1067
1068    let helperResult = helpers.helperResult;

23:34:54.189 new Error()
23:34:54.196 Error: 
Stack trace:
@debugger eval code:1:1
WCA_evalWithDebugger@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/actors/webconsole.js:1065:7
WCA_onEvaluateJS@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/actors/webconsole.js:730:9
DSC_onPacket@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/server/main.js:1098:9
LDT_send/<@resource://gre/modules/devtools/dbg-client.jsm -> resource://gre/modules/devtools/server/transport.js:279:11
makeInfallible/<@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/DevToolsUtils.js:84:7
(Reporter)

Comment 8

5 years ago
Test coverage for this bug.

Highlight of sample test log:

 0:20.36 TEST-PASS | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_bug_1006027_message_timestamps_incorrect.js | matched rule: console.log
 0:20.36 TEST-INFO | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_bug_1006027_message_timestamps_incorrect.js | hud.outputNode.textContent:
 0:20.36 03:13:10.800 console.log('bug1006027')
 0:20.36 03:13:10.814 undefined
 0:20.36 20:40:16.044 "bug1006027"1
 0:20.36
 0:20.36 TEST-UNEXPECTED-FAIL | chrome://mochitests/content/browser/browser/devtools/webconsole/test/browser_webconsole_bug_1006027_message_timestamps_incorrect.js | console.log message timestamp spread < 1000ms confirmed
(Reporter)

Comment 9

5 years ago
Complete test log for

./mach mochitest-devtools ./browser/devtools/webconsole/test/browser_webconsole_bug_1006027_message_timestamps_incorrect.js > browser_webconsole_bug_1006027_message_timestamps_incorrect.log
(Reporter)

Comment 10

5 years ago
Another piece of information from the Browser Console:

14:09:23.779 let consoleService = Cc["@mozilla.org/consoleservice;1"].getService(Ci.nsIConsoleService);
14:09:23.785 undefined
14:10:15.598 consoleService.logStringMessage('correct timestamp!')
14:10:15.600 undefined
14:10:15.601 correct timestamp!
14:10:39.471 console.log('incorrect timestamp')
14:10:39.476 undefined
10:37:59.025 "incorrect timestamp"
(Reporter)

Comment 11

5 years ago
Here is where the incorrect timestamp comes in (seems to be in us instead of ms:

1352  observe: function CAL_observe(aMessage, aTopic)
1353  {
1354    if (!this.owner) {
1355      return;
1356    }
1357
1358    let apiMessage = aMessage.wrappedJSObject;
1359    if (this.window) {

I am out of ideas looking for the culprit.

I have inspected JS_Now() in
git.mozilla.org/gecko-dev/js/src/prmjtime.cpp
git.mozilla.org/gecko-dev/xpcom/base/nsConsoleMessage.cpp
and it all looks correct, agrees with comments in .idl as well.

Here's proof, while trapped at line 1359:

apiMessage.timeStamp
16:36:47.251 1399818920606778
16:37:01.027 new Date(apiMessage.timeStamp)
16:37:01.020 Date 46328-06-30T21:03:26.778Z
16:37:37.543 console.log(new Error)
16:37:37.537 undefined
16:37:37.538 Error: 
Stack trace:
@debugger eval code:1:1
CAL_observe@resource://gre/modules/commonjs/toolkit/loader.js -> resource://gre/modules/devtools/toolkit/webconsole/utils.js:1359:1
(Reporter)

Comment 12

5 years ago
This fixes the test failure, but just fixes the symptom, not the cause.

I am hoping for so feedback and guidance on my findings.
(Reporter)

Comment 13

5 years ago
Tests pass with
8420674: Bug1005471-workaround-fix.patch
applied.
I wonder if this is a regression from bug 965860, which landed in version 30. Andrea, could you take a look?
Flags: needinfo?(amarchesini)
(Assignee)

Comment 15

5 years ago
(In reply to adrian from comment #0)
> to witness:
> 
>    19:21:48.684 console.log((new Date()).toString())
>    19:21:48.689 undefined
> -> 13:31:31.217 "Mon May 05 2014 19:21:48 GMT+0200"

It seems correct to me. The "new Date()" runs when console.log is executed:

Here: 19:21:48.684 console.log((new Date()).toString())

But the console API schedules the printing of the log messages any X milliseconds:

> -> 13:31:31.217 "Mon May 05 2014 19:21:48 GMT+0200"

but it still prints the correct value: 19:21:48.684.
Flags: needinfo?(amarchesini)
(Reporter)

Comment 16

5 years ago
(In reply to Andrea Marchesini (:baku) from comment #15)
> (In reply to adrian from comment #0)
> > to witness:
> > 
> >    19:21:48.684 console.log((new Date()).toString())
> >    19:21:48.689 undefined
> > -> 13:31:31.217 "Mon May 05 2014 19:21:48 GMT+0200"
> 
> It seems correct to me. The "new Date()" runs when console.log is executed:
> 
> Here: 19:21:48.684 console.log((new Date()).toString())
> 
> But the console API schedules the printing of the log messages any X
> milliseconds:
> 
> > -> 13:31:31.217 "Mon May 05 2014 19:21:48 GMT+0200"
> 
> but it still prints the correct value: 19:21:48.684.

Yeah, except that the console timestamp (13:31:31.217) is almost 6h off!
Please read my full analysis of the problem.

Perhaps you could enlighten me where the object with the imcorrect (usec instead of msec) timestamp is constructed and wrapped up.
(Reporter)

Comment 17

5 years ago
Just renamed patch to refer to correct bug number.
Attachment #8420674 - Attachment is obsolete: true
(Assignee)

Comment 18

5 years ago
> Yeah, except that the console timestamp (13:31:31.217) is almost 6h off!

Yep. Sorry. Patch ready in a couple of minutes.
Assignee: nobody → amarchesini
OS: Windows XP → All
Hardware: x86 → All
(Assignee)

Comment 19

5 years ago
Posted patch patchSplinter Review
This patch uses your mochitest.
Attachment #8421048 - Flags: review?(adrian)
(Reporter)

Comment 20

5 years ago
Comment on attachment 8421048 [details] [diff] [review]
patch

Review of attachment 8421048 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good, thanks for the quick fix!

::: dom/base/Console.cpp
@@ +140,5 @@
>  public:
>    ConsoleCallData()
>      : mMethodName(Console::MethodLog)
>      , mPrivate(false)
> +    , mTimeStamp(JS_Now() / PR_USEC_PER_MSEC)

Yeah, that looks right.

Too bad I wasn't able to find the spot on my own.
Attachment #8421048 - Flags: review?(adrian) → review+
(Reporter)

Comment 21

5 years ago
Comment on attachment 8420981 [details] [diff] [review]
Bug1006027-workaround-fix.patch

Review of attachment 8420981 [details] [diff] [review]:
-----------------------------------------------------------------

Superseded by patch patch by @baku.
Attachment #8420981 - Flags: review-
(Assignee)

Comment 22

5 years ago
Comment on attachment 8421048 [details] [diff] [review]
patch

I think I need a review from a DOM peer for this patch.
Attachment #8421048 - Flags: review?(bzbarsky)
Comment on attachment 8421048 [details] [diff] [review]
patch

r=me
Attachment #8421048 - Flags: review?(bzbarsky) → review+
Adrian, thank you for reporting this!
There are a bunch of leftover comments in Adrian's nice test that we should remove before landing.
(Reporter)

Comment 26

5 years ago
Comment on attachment 8420601 [details] [diff] [review]
browser_webconsole_bug_1006027_message_timestamps_incorrect.patch

Review of attachment 8420601 [details] [diff] [review]:
-----------------------------------------------------------------

::: browser/devtools/webconsole/test/browser_webconsole_bug_1006027_message_timestamps_incorrect.js
@@ +32,5 @@
> +    let timestampNodes = hud.outputNode.querySelectorAll('span.timestamp');
> +    let aTimestampMilliseconds = Array.prototype.map.call(timestampNodes,
> +      function (value) {
> +        // We are parsing timestamps as local time, relative to the begin of the epoch.
> +        // This is not the correct value of the timestamp, but good enough for comparison.

I think this is the only comment which should stay in the test function.
The header comment I would also like to keep.
I can provide a patch if needed.
https://hg.mozilla.org/mozilla-central/rev/583b57401285
Status: NEW → RESOLVED
Last Resolved: 5 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → Firefox 32
(Reporter)

Comment 29

5 years ago
Please be warned of the file mode changes my original patches introduced.

Perhaps this needs to be fixed in mercurial now?

See
     1.1 old mode 100644
     1.2 new mode 100755
     1.3 --- a/browser/devtools/webconsole/test/browser.ini
     1.4 +++ b/browser/devtools/webconsole/test/browser.ini

     2.1 new file mode 100755
     2.2 --- /dev/null
     2.3 +++ b/browser/devtools/webconsole/test/browser_webconsole_bug_1006027_message_timestamps_incorrect.js

in https://hg.mozilla.org/mozilla-central/rev/583b57401285
I'll take care of the mode changes in bug 1004562, where I have a patch ready to land.
Tracking because developers tools are important features of Firefox.
Can we get an uplift nomination here, and if necessary as well - in bug 1004562?
Flags: needinfo?(amarchesini)
The file mode changes from bug 1004562 don't seem important enough to warrant an uplift, but I can do it if you disagree.
(Assignee)

Comment 34

5 years ago
Comment on attachment 8421048 [details] [diff] [review]
patch

[Approval Request Comment]
Bug caused by (feature/regressing bug #): 965860
User impact if declined: the timer of console events is wrong
Testing completed (on m-c, etc.): m-c
Risk to taking this patch (and alternatives if risky): none
String or IDL/UUID changes made by this patch: none
Attachment #8421048 - Flags: approval-mozilla-beta?
Flags: needinfo?(amarchesini)
Attachment #8421048 - Flags: approval-mozilla-beta? → approval-mozilla-beta+
No, I don't see a reason to do the file mode changes if those are not as important to uplift. They can ride the trains.
Attachment #8421048 - Flags: approval-mozilla-aurora+

Updated

5 years ago
Depends on: 1016024

Updated

10 months ago
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.