1006027 - console input/output timestamps OK, message timestamps always incorrect

Status: RESOLVED FIXED

(DevTools :: Console, defect)

Description

[Adrian Aichner [:anaran]]

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"

Comment 1

[Adrian Aichner [:anaran]]

Restarted with all addons disabled in safe mode BTW.

Comment 2

[Adrian Aichner [:anaran]]

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"

Comment 3

[Adrian Aichner [:anaran]]

Also exists in Firefox 30.

Comment 5

[Adrian Aichner [:anaran]]

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?

Comment 6

[Panos Astithas (he/him) [:past] (please ni?)]

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

Comment 7

[Adrian Aichner [:anaran]]

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

Comment 8

[Adrian Aichner [:anaran]]

Attachment: browser_webconsole_bug_1006027_message_timestamps_incorrect.patch

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

Comment 9

[Adrian Aichner [:anaran]]

Attachment: browser_webconsole_bug_1006027_message_timestamps_incorrect.log

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

Comment 10

[Adrian Aichner [:anaran]]

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"

Comment 11

[Adrian Aichner [:anaran]]

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

Comment 12

[Adrian Aichner [:anaran]]

Attachment: Bug1005471-workaround-fix.patch

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

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

Comment 13

[Adrian Aichner [:anaran]]

Attachment: browser_webconsole_bug_1006027_message_timestamps_incorrect-20140511T164216+0000.txt

Tests pass with
8420674: Bug1005471-workaround-fix.patch
applied.

Comment 14

[Panos Astithas (he/him) [:past] (please ni?)]

I wonder if this is a regression from bug 965860, which landed in version 30. Andrea, could you take a look?

Comment 15

[Andrea Marchesini [:baku]]

(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.

Comment 16

[Adrian Aichner [:anaran]]

(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.

Comment 17

[Adrian Aichner [:anaran]]

Attachment: Bug1006027-workaround-fix.patch

Just renamed patch to refer to correct bug number.

Comment 18

[Andrea Marchesini [:baku]]

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

Yep. Sorry. Patch ready in a couple of minutes.

Comment 19

[Andrea Marchesini [:baku]]

Attachment: patch

This patch uses your mochitest.

Comment 20

[Adrian Aichner [:anaran]]

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.

Comment 21

[Adrian Aichner [:anaran]]

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

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

Superseded by patch patch by @baku.

Comment 22

[Andrea Marchesini [:baku]]

Comment on attachment 8421048 [details] [diff] [review]
patch

I think I need a review from a DOM peer for this patch.

Comment 23

[Boris Zbarsky [:bzbarsky]]

Comment on attachment 8421048 [details] [diff] [review]
patch

r=me

Comment 24

[Boris Zbarsky [:bzbarsky]]

Adrian, thank you for reporting this!

Comment 25

[Panos Astithas (he/him) [:past] (please ni?)]

There are a bunch of leftover comments in Adrian's nice test that we should remove before landing.

Comment 26

[Adrian Aichner [:anaran]]

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.

Comment 27

[Andrea Marchesini [:baku]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/583b57401285

Thanks again, Adrian!

Comment 28

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/583b57401285

Comment 29

[Adrian Aichner [:anaran]]

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

Comment 30

[Panos Astithas (he/him) [:past] (please ni?)]

I'll take care of the mode changes in bug 1004562, where I have a patch ready to land.

Comment 31

[Sylvestre Ledru [:Sylvestre]]

Tracking because developers tools are important features of Firefox.

Comment 32

[Lukas Blakk [:lsblakk] use ?needinfo]

Can we get an uplift nomination here, and if necessary as well - in bug 1004562?

Comment 33

[Panos Astithas (he/him) [:past] (please ni?)]

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 34

[Andrea Marchesini [:baku]]

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

Comment 35

[Lukas Blakk [:lsblakk] use ?needinfo]

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.

Comment 36

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/7bf1e1e774e5
https://hg.mozilla.org/releases/mozilla-beta/rev/5608c1796eee

Comment 37

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-b2g30_v1_4/rev/5608c1796eee