log level returned by getLevel function in custom logger not being respected.

[jtoronto]

(Filling out the following with as much detail as you can provide will help us solve your issue sooner.)

Reproducible in:

The Slack SDK version

"slack/bolt": "^3.13.0",

Node.js runtime version

v18.14.0

OS info

ProductName:            macOS
ProductVersion:         13.3
BuildVersion:           22E252
Darwin Kernel Version 22.4.0: Mon Mar  6 21:00:41 PST 2023; root:xnu-8796.101.5~3/RELEASE_ARM64_T8103

Steps to reproduce:

(Share the commands to run, source code, and project settings)

1. provide a logger to the new App() constructor
2. make logger getLevel method return info as the log level.

Expected result:

boltJS client should log at INFO level.

Actual result:

Logging at the DEBUG level.

[19:08:13.919] DEBUG (28297):
    0: "initialized"
[19:08:19.237] DEBUG (28297):
    0: "Initializing HTTPReceiver"
[19:08:19.237] DEBUG (28297):
    0: "The logLevel given to OAuth was ignored as you also gave logger"
[19:08:19.238] DEBUG (28297):
    0: "The logLevel given to WebClient was ignored as you also gave logger"
[19:08:19.238] DEBUG (28297):
    0: "initialized"

It seems like it's ignoring the value returned by getLevel(). I verified that the function is being called and is returning info by using breakpoints, and that it's calling my logger's debug function when logging the above messages. The The logLevel given to OAuth was ignored as you also gave logger are also somewhat confusing.

Please read the Contributing guidelines and Code of Conduct before creating this issue or pull request. By submitting, you are agreeing to those rules.

[seratch]

Hi @jtoronto, thanks for taking the time to write in! With given information, I am still unsure about the situation you mention. Simply passing logger does not cause it. Could you share code snippet reproducing the issue?

[jtoronto]

Sure.

The 'logger' here is a Pino instance.

export const slackClientLoggerWrapper = {
  debug: (...msgs) => logger.debug(msgs),
  info: (...msgs) => logger.info(msgs),
  warn: (...msgs) => logger.warn(msgs),
  error: (...msgs) => logger.error(msgs),
  setLevel: (_level) => {
    return;
  },
  getLevel: () => {
   return LogLevel.INFO <---- LogLevel imported from '@slack/bolt'
  },
  setName: (_name) => {
    return;
  },
};

 slackClient = new App({
    clientId: appConfigHandler.get('SLACK_CLIENT_ID'),
    clientSecret: appConfigHandler.get('SLACK_CLIENT_SECRET'),
    signingSecret: appConfigHandler.get('SLACK_SIGNING_SECRET'),
    logger: slackClientLoggerWrapper,
  });

Additionally if I pass in logLevel: LogLevel.INFO, in the client constructor, it doesn't seem to make any diffference.

When the boltJS client starts up, it immediately calls getLevel on my custom logger, gets returned info and then immediately after that calls several debug messages.

Any incoming events also fire several debug messages like "ack() call begins (body: undefined)"

If the log level is set to INFO those messages should not be called at all.

[jtoronto]

Looking at the built-in consoleLogger it appears that one would need to implement something like isMoreOrEqualSevere in a custom logger if they want this behavior, otherwise the getLevel method does nothing.

https://github.com/slackapi/node-slack-sdk/blob/ea0483cb71ae22cf6c94866478df351a90f1db7f/packages/logger/src/index.ts#L119

This is something that should be documented.

[seratch]

Thanks for sharing the code. If I understand correctly, your logger implementation needs to sync the log level with the underlying pino logger like this:

const pinoLogger = require('pino')();
// You can set log level to the underlying logger
pinoLogger.level = 'info';

// You can pass this logger to App constructor
const logger: Logger = {
  debug: (...msgs) => pinoLogger.debug(msgs),
  info: (...msgs) => pinoLogger.info(msgs),
  warn: (...msgs) => pinoLogger.warn(msgs),
  error: (...msgs) => pinoLogger.error(msgs),
  setLevel: (_level) => {
    // TODO
  },
  getLevel: () => {
    // as long as the string is compatible with @slack/logger,
    // just returning the value works for this method
    return pinoLogger.level;
  },
  setName: (_name) => {
    // TODO
  },
};

I think that Logger interface is still valid while it may be helpful to add more examples to the document.

[jtoronto]

No I don't believe that will help, because when you pass in a logger, any logger.debug messages sent by code within bolt.js sends it to that logger (this.logger), and any log level comparison needs to be implemented in the logger you're passing in, similarly to how the built in consoleLogger is created.

When passing in a custom logger, the value returned from the getLevel method gets set to a variable but doesn't actually get used.

It's pretty clear here:
https://github.com/slackapi/bolt-js/blob/f5234dd7b126aa58aaae743c8d9faa080cfd4efe/src/App.ts#L308

There is no logic here for "if log message is less than current log level" and it needs to be implemented by you if you're passing in a custom logger.

That's fine but the documentation needs to reflect that.

[github-actions]

👋 It looks like this issue has been open for 30 days with no activity. We'll mark this as stale for now, and wait 10 days for an update or for further comment before closing this issue out. If you think this issue needs to be prioritized, please comment to get the thread going again! Maintainers also review issues marked as stale on a regular basis and comment or adjust status if the issue needs to be reprioritized.

[filmaj]

This seems like a legit gap in the Logger interface in the underlying node-slack-sdk.

From my perspective, I believe to address this issue, the following needs to be done:

• The Logger interface needs to be extended to include the isMoreOrEqualSevere function used to compare log levels in the logger implementation, as @jtoronto pointed out.
• The logging documentation for bolt-js (here, under the expandable "Sending log output somewhere besides the console") needs to be expanded to explain the isMoreOrEqualSevere function and what its implementation is required to do.