console input/output timestamps OK, message timestamps always incorrect

RESOLVED FIXED in Firefox 30

Status

defect
RESOLVED FIXED
5 years ago
a year ago

People

(Reporter: anaran, Assigned: baku)

Tracking

30 Branch
Firefox 32
Dependency tree / graph
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

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