Function is printed instead of logger name

[omnibrain]

After a Chrome update ulog suddenly prints the complete formatting function instead of the logger name.

The function that is printed (function() {return fmt(rec)} function() {return fmt(rec)} function() {return fmt(rec)}) appears to be this one: https://github.com/Download/ulog/blob/master/mods/formats/formatter.js#L19

Looks like a function call is missing somewhere? Is this a known problem? I have upgraded to the latest beta version (2.0.0-beta.18) and the problem is the same.

EDIT:

Some more information: The problem only occurs with Chrome Version 92.0.4515.107. With the version I had installed before it worked correctly. Also with Firefox everything works as expected.

[the0neWhoKnocks]

Can confirm. Thought I broke something in a new project.

Not sure if it's related, but I used to be able to see logs by just having the localStorage values set, but now I have to use the query param option to see the logs.

[the0neWhoKnocks]

Hm, strange. So if I add the below code (which adds a custom formatter) the output works again

const ulog = require('ulog');
ulog.config.log_format = 'lvl noPadName message';
ulog.use({
  use: [ require('ulog/mods/formats') ],
  formats: {
    noPadName: () => {
      const fmt = (rec) => rec.name;
      fmt.color = 'logger';
      return fmt;
    },
  },
});

I was still having to use the query param after the above was added. Since the ulog.config approach worked, I decided to add something similar but for the log level. Surprise, it worked.

+ if (typeof window !== 'undefined') ulog.config.log = 'debug';
ulog.config.log_format = 'lvl noPadName message';

Since the above changes wire up ulog's formatting before any logs are emitted, I'm wondering if the issues are related to the localStorage check and how those changes are propagated.

[kollster]

The same issue also applies to the current version of Microsoft Edge: Version 92.0.902.62 (Official build) (64-bit).

It seems that the function is printed when you use only static tags e.g.:

ulog.config.log_format = "lvl name"

results in this output:

But when you use the dynamic message tag, it displays log level and name normally, but now the callstack is mangled:

ulog.config.log_format = "lvl name message"

results in this output:

It is very important for us, that we are able to use static only tags and get the correct callstack.

[Download]

I can confirm. Some update to Chrome broke the static formatting feature.

This is a shame. I love correct line numbers next to my log messages. There used to be only one way to achieve that and that was static formatting. Static means that all formatting info is present before the log call is made. I was able to get things like the perf formatter, which prints ms elapsed between calls, as static formats by using this principle:

function test(){
  // this function is static in the sense that it uses no info from the log call
  return '#' + new Date().getTime()
}

console.info('%s', { toString: test })  // logs "#1627912278891" (or whatever the current time is)

Doing this allowed us to call the log function many times and get updated time info in the call each time while preserving the call stack. It seems Chrome now forbids this.

This basically means I spent months of research and development time on this for nothing and all my claims in the tutorial no longer hold.... I am very sad now as basically this means that this project is dead in the water... 😢

[Download]

It is very important for us, that we are able to use static only tags and get the correct callstack.

Yes, it was very important to me as well and AFAIK, ulog was the only library out there that had this feature. I was very proud of that. Now.... it;s all broken. This actually worked cross-browser back all the way to Internet Explorer. I used this for colors, padding and all those great featured, without mangling the call stack. But in one fell swoop my dream was killed.

Maybe we should all report this change in behavior as a bug to the Chrome team and hope they are willing to revert that change. But I have my doubts...

[Download]

There might be hope if someone finds an alternative way to have console.info and the other native log messages call a function on one of it's parameters.

What I do to avoid messing up the call stack is this:

function test(){
  // this function is static in the sense that it uses no info from the log call
  return '#' + new Date().getTime()
}

var logFunction = console.info.bind(console, '%s %s', { toString: test })

logFunction('Hello World') // logs "#1627912278891 Hello World"

Because we use Function.bind instead of wrapping the log function, we preserve the call stack. But alas it's this very feature that Chrome seems to have broken now.

If someone finds an alternative way to get this to work there might be hope...

You can paste the above example in Firefox and see it work. Paste it in Chrome and you get:

Object Hello World

If you can find a way to get Chrome to print the right output for this sample, please explain here and I will attempt a bugfix. But I fear it's no longer possible.

[reinhard]

This prints the right output, but I'm not sure if this solves the problem completely:

function test(){
  // this function is static in the sense that it uses no info from the log call
  return '#' + new Date().getTime()
}

var logFunction = Function.prototype.bind.call(console.info, '%s %s', test())

logFunction('Hello World') // logs "#1627912278891 Hello World"

I found this at https://gist.github.com/bgrins/5108712

[kollster]

I have just tried the method #69 (comment) suggested by @reinhard in a multimodule project. It does indeed appear to work without mangling the callstack 👍

[kollster]

@Download , have you seen the findings of @reinhard ? At the moment, I am not familiar enough with the ulog codebase to try implementing a change based on this idea.

[Download]

I can't see how it could work.

The example @reinhard gave will always render the same result.
Try this in the console (try Chrome vs Firefox):

function test(){
  return '#' + Math.floor(10000 + 10000 * Math.random())
}

var rein = Function.prototype.bind.call(console.info, '%s %s', test())
rein('rein')
rein('rein')
rein('rein')
rein('rein')

var ulog = console.info.bind(console, '%s', { toString: test })
ulog('ulog')
ulog('ulog')
ulog('ulog')
ulog('ulog')

Notice how rein always prints the same number?
We need the console to call the function, not call it ourselves.

[Download]

Reported this as an issue to the Chrome developers:
https://bugs.chromium.org/p/chromium/issues/detail?id=1241395

[gonadarian]

@Download, they marked it as a duplicate of another issue which is already closed as WontFix. They say previous behavior was a bug 🥺.

[Download]

Great news!

I had a discussion about this issue with another developer (the one that created the issue mine was a dupe of) and it turns out that he was able to provide me with another approach. Details here:
https://bugs.chromium.org/p/chromium/issues/detail?id=1223452#c12

It will take some time for me to update this library to use his approach but at least there is a way forward. So expect an update of ulog to come out somewhere in the coming weeks that addresses this issue. Thank you all for reporting this and thinking with me on how to fix it.

[Download]

Published a fix in 2.0.0-beta.19

[mig8447]

Thank you for this fix, very much appreciated

[kollster]

Thank you for the fix! I will try it tomorrow 👍

[omnibrain]

works beautifully 😍 thanks for the fix!