Open Bug 755555 Opened 8 years ago Updated 11 months ago

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


(DevTools :: Console, defect, P2)



(Not tracked)


(Reporter: ehsan, Unassigned)




(1 file)

444 bytes, application/xhtml+xml
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.
What type of messages are the webgl warnings? We show messages as they arrive in the webconsole output.

Can we get a testcase?
Priority: -- → P3
WebGL warnings are JS warnings.
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?
Depends on: console-output
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.
Duplicate of this bug: 884059
Duplicate of this bug: 1039464
Duplicate of this bug: 854435
Attached file 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.
Priority: P3 → P2
> 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).
Product: Firefox → DevTools
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?
Flags: needinfo?(nchevobbe)
How did you test that Harald?
Flags: needinfo?(nchevobbe) → needinfo?(hkirschner)
- With Console closed open
- Open Console and check last log: Array [ 0 ]
- Refresh
- Check last console log: Array []

ER: Always log `Array []` as last
Flags: needinfo?(hkirschner)
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.
You need to log in before you can comment on or make changes to this bug.