Freedom logging not getting to stdout w/chrome --enable-logging

[agallant]

Original issue courtesy of @mollyling -

"Freedom logging doesn't save very much to stdout. Our current theory is the color codes. For example, if you run chrome with --enable-logging --v=1, you get console messages to a file called chrome_debug.log (in your profile dir). Which works for everything but freedom log messages. In the chrome inspector, I get messages like:"

freedom-for-chrome.js:1232  RtcToNet I [Feb 26 23:39:30.866] snapshot: {"sessions":
[{"name":"c1036","channel":{"sent":1254,"received":68,"buffered":0,"queue":
{"size":0,"handling":true}},"socket":{"sent":68,"received":1254,"queue":{"size":0,"handling":true}}}]}

In the console log file, I get:

[17934:17934:0226/232501:INFO:CONSOLE(1232)] "%c RtcToNet", source: chrome-
extension://cefipnmgppdcaidhlciklmgbmgdnffod/lib/freedom/freedom-for-chrome.js (1232)

[agallant]

Initial investigation:
Logging happens in freedom at https://github.com/freedomjs/freedom/blob/master/providers/core/core.console.js#L108 and https://github.com/uProxy/uproxy-networking/blob/dev/src/rtc-to-net/rtc-to-net.ts#L178 is where the log message comes from.

Tentatively, the issue looks to be with color codes, or more specifically that the chrome_debug.log format is only logging the first argument and thus when freedom formats the logs (adding parameters to the string array https://github.com/freedomjs/freedom/blob/master/providers/core/core.console.js#L71) the message ends up truncated. Per @willscott we are formatting logs in a standard way (and in a way that works with the actual Chrome console), so there are two likely resolutions:

• Special case handling, i.e. "if this is chrome and logging to stdout/command line debug, then format differently"
• File a bug for Chrome requesting that stdout logging accepts the same formatting as dev console logging

I'll investigate the former a bit more in the near future - the latter is likely the "right" solution but admittedly may not be possible short-term, so if there's a quicker temporary fix we'll try that.

[agallant]

I'm not finding a good way to check command line flags at runtime, and there's some suggestion by poking around that this may not be possible (https://groups.google.com/a/chromium.org/forum/#!topic/chromium-dev/0PnVBl5Hldk). Experimentally, starting chrome with command line flags didn't lead to any obvious differences in the console object, at least the one exposed in the dev console.

I may revisit after a bit but I currently don't see a good way to do special case handling for this, meaning it may be a good idea to file a request for Chrome accept log formatting consistently across stdout/dev console.

[iislucas]

What benefit do the colour codes provide? I actually find them rather distracting. Maybe we could add an option in the top level freedom config json that allows them to be turned off? That would solve this, I think in the short term. Longer term, we'd like chrome to support them, but no need to slow ourselves down that much I think.

[willscott]

I've found the hilighting of the module to be hugely useful when debugging. Especially since the sources are all freedom-for-chrome.js or similar, it's very nice to clearly differentiate modules. Perhaps this isn't as key at the moment, but i feel like that differntiation will be critical once UWNetworksLab/uProxy-p2p#648 is resolved.

Worth noting that in the interactive chrome console you can filter, and that does work correctly.

The prefixed source tag is only added when a 'source' is set. if you don't set tag in the uproxy-lib custom logger it will also not add that prefix.

This does seem like an option we could have configurable for the console. I'm happy to go with @soycode and mark this current bug as as a problem with chrome though - it isn't logging things (to stdout) that we're calling console.log on - only the first argument is sent to stdout.

[iislucas]

The colouring isn't useful to me, but the module name is already very important, I use filtering all the time.

+1 for a workaround and filing a chrome bug.

[willscott]

The coloring is a foil, and removing it won't solve the problem unfortunately. Right now we prefix the logged arguments with 2 things, a thing that says "make the next argument red", which is what we're seeing now, and then the module name. We can remove the "make the next argument red" item, but then all that will printed out is the module name. We still won't get the actual message.

We really want to print these out as separate arguments, rather than flattening the log message to a single string. This is because you can log objects or other things like window, and if we flatten it to a string it will appear different than if the object is logged directly. That seems to necessitate args.unshift('[module]');. It also means that if chrome's stdout only logs the first thing it's given we won't be in a great place.

So we can add an option to flatten but we'll be losing log message quality, which is why that isn't a great final solution.

[mollyling]

That'd all be nice if it worked. But it doesn't. Perhaps stringify now
and go back when chrome's behaving better. Perhaps a top-level config
option to stringify, and leave it on by default until chrome's behaving
better. Also, I'd be interested in seeing the memory usage changes due to
that. I suspect string reps are smaller than retaining larger JS objects.
Probably even smaller than small JS objects.

Cheers,
$ ls

Lally Singh | Google Ideas http://www.google.com/ideas/ | Engineering |
[email protected]

On Tue, Mar 3, 2015 at 12:58 PM, Will [email protected] wrote:

The coloring is a foil, and removing it won't solve the problem
unfortunately. Right now we prefix the logged arguments with 2 things, a
thing that says "make the next argument red", which is what we're seeing
now, and then the module name. We can remove the "make the next argument
red" item, but then all that will printed out is the module name. We still
won't get the actual message.

We really want to print these out as separate arguments, rather than
flattening the log message to a single string. This is because you can log
objects or other things like window, and if we flatten it to a string it
will appear different than if the object is logged directly. That seems to
necessitate args.unshift('[module]');. It also means that if chrome's
stdout only logs the first thing it's given we won't be in a great place.

So we can add an option to flatten but we'll be losing log message
quality, which is why that isn't a great final solution.

—
Reply to this email directly or view it on GitHub
#239 (comment).

[trevj]

Just to say that I like the colouring and find it useful.

That said, I don't like it more than having these things working! It also doesn't look very good on the console when I'm testing Firefox with cfx run. That hasn't been a big issue until now, but soon will be.