Closed Bug 1006027 Opened 6 years ago Closed 6 years ago

console input/output timestamps OK, message timestamps always incorrect

Categories

(DevTools :: Console, defect)

30 Branch
defect
Not set
normal

Tracking

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

RESOLVED FIXED
Firefox 32
Tracking Status
firefox29 --- unaffected
firefox30 + fixed
firefox31 + fixed
firefox32 + fixed
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed

People

(Reporter: anaran, Assigned: baku)

References

Details

Attachments

(5 files, 1 obsolete file)

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"
Restarted with all addons disabled in safe mode BTW.
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"
Also exists in Firefox 30.
Version: 32 Branch → 30 Branch
Duplicate of this bug: 1006159
Status: UNCONFIRMED → NEW
Ever confirmed: true
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
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
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
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
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"
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
Attached patch Bug1005471-workaround-fix.patch (obsolete) — Splinter Review
This fixes the test failure, but just fixes the symptom, not the cause.

I am hoping for so feedback and guidance on my findings.
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)
(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)
(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.
Just renamed patch to refer to correct bug number.
Attachment #8420674 - Attachment is obsolete: true
> 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
Attached patch patchSplinter Review
This patch uses your mochitest.
Attachment #8421048 - Flags: review?(adrian)
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+
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-
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.
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
Closed: 6 years ago
Flags: in-testsuite+
Resolution: --- → FIXED
Target Milestone: --- → Firefox 32
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.
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+
Depends on: 1016024
Product: Firefox → DevTools
You need to log in before you can comment on or make changes to this bug.