755555 - console.log messages and webgl verbose errors are not interleaved correctly

Status: RESOLVED WORKSFORME

(DevTools :: Console, defect, P2)

Description

[(no longer active)]

If you have a WebGL app which does a bunch of console.log calls and also generates a bunch of webgl warnings, the warnings are displayed first, and then all of the console.log messages are displayed.  This makes it impossible to use console.log for printf-debugging.  Chrome 20 doesn't seem to have the same problem.

Comment 1

[Mihai Sucan [:msucan]]

What type of messages are the webgl warnings? We show messages as they arrive in the webconsole output.

Can we get a testcase?

Comment 2

[Benoit Jacob [:bjacob] (mostly away)]

WebGL warnings are JS warnings.

Comment 3

[Mihai Sucan [:msucan]]

I've been thinking about why this bug might occur and here's why: we have listeners for script errors and console API messages, and we send all these messages from the server to the client console. Messages arrive async and I believe it is possible that they arrive out of order (we have no explicit mechanism to ensure the order of messages we display).

To keep from blocking content scripts the console API implementation returns as early as possible and we queue the sending of those messages to the server, which in turn sends messages to the client (async again).  See for example the ConsoleAPI.js implementation - this is probably not the only source of irregularities.

Rob, we discussed the idea of sorting messages in the console output. We don't need any sorting UI but to fix this bug we probably need a way to insert messages in correct order (some logic for sorting). This problem keeps coming back to us.

Any thoughts?

Comment 4

[Rob Campbell [:rc] (:robcee)]

assuming they're coming in with accurate timestamps, we should probably be inserting them into the correct position when adding them. The timeline should be accurate and in order.

Comment 8

[sworddragon2]

Attachment: Testcase

The asynchronous behavior causes also that the content of objects could be shown incorrectly. In the attachments is a testcase which demonstrates both problems. Unfortunately both issues are making debugging complex problems in web applications unnecessary difficult compared to other browsers.

Comment 9

[sworddragon2]

> compared to other browsers

Just to correct this a little: Chrome shows sometimes a filled array too (on my tests always the first time the testcase gets loaded).

Comment 10

[:Harald Kirschner :digitarald]

Seems like this affects the console when its closed on logging. I get the same behavior for Chrome and Firefox.

Nicolas, is there a way that we can report the correct object state without adding overhead to logging when console is closed?

Comment 11

[Nicolas Chevobbe [:nchevobbe]]

How did you test that Harald?

Comment 12

[:Harald Kirschner :digitarald]

STR:
- With Console closed open https://bug755555.bmoattachments.org/attachment.cgi?id=8461750
- Open Console and check last log: Array [ 0 ]
- Refresh
- Check last console log: Array []

ER: Always log `Array []` as last

Comment 13

[Nicolas Chevobbe [:nchevobbe]]

So it looks like cached messages are affected by later alterations, but this does not really match the original report I think.
I filed Bug 1513978 for that problem.
For the original bug, I'm not sure how to reproduce it/if this is still valid.

Comment 14

[BugBot [:suhaib / :marco/ :calixte]]

The severity field for this bug is relatively low, S3. However, the bug has 3 duplicates.
:nchevobbe, could you consider increasing the bug severity?

For more information, please visit auto_nag documentation.

Comment 15

[Nicolas Chevobbe [:nchevobbe]]

we have some mechanism to re-order messages based on a microsecond-precise timestamp, so this shouldn't be an issue anymore