[New Platform / LoggerFactory] Debug messages are not appearing

[tsullivan]

In #55442 Reporting Services team is re-instrumenting the plugin to use the new logging service from the New Platform.

In that test branch, I see almost all of the log messages that can be seen in master, except for debug-level messages.

CSV export has a few debug messages. In master, a CSV export job could log this:

server    log   [11:43:32.340] [debug][esqueue][queue-worker][reporting] k5o88fof21n67a3f11cncpbn - Job created in index .reporting-2020.01.19
server    log   [11:43:32.363] [debug][esqueue][queue-worker][reporting] k5o88fof21n67a3f11cncpbn - Job index refreshed .reporting-2020.01.19
server    log   [11:43:32.364] [info][queue-job][reporting] Successfully queued job: k5o88fof21n67a3f11cncpbn
server    log   [11:43:34.475] [debug][esqueue][queue-worker][reporting] k5o7yx7y21n67a3f11ebtyjb - 1 outstanding jobs returned
server    log   [11:43:34.494] [info][esqueue][queue-worker][reporting] k5o7yx7y21n67a3f11ebtyjb - Job marked as claimed: /.reporting-2020.01.19/k5o88fof21n67a3f11cncpbn
server    log   [11:43:34.494] [info][esqueue][queue-worker][reporting] k5o7yx7y21n67a3f11ebtyjb - Starting job
server    log   [11:43:34.558] [warning][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] Kibana Advanced Setting "dateFormat:tz" is set to "Browser". Dates will be formatted as UTC to avoid ambiguity.
server    log   [11:43:34.559] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] executing search request
server    log   [11:43:34.706] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] executing scroll request
server    log   [11:43:34.858] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] executing scroll request
server    log   [11:43:34.995] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] executing scroll request
server    log   [11:43:35.160] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] executing scroll request
server    log   [11:43:35.417] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] executing scroll request
server    log   [11:43:35.586] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] executing scroll request
server    log   [11:43:35.601] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] executing clearScroll request
server    log   [11:43:35.616] [debug][csv][execute-job][k5o88fof21n67a3f11cncpbn][reporting] finished generating, total size in bytes: 446137
server    log   [11:43:35.618] [info][esqueue][queue-worker][reporting] k5o7yx7y21n67a3f11ebtyjb - Job execution completed successfully
server    log   [11:43:35.794] [debug][queue-worker][reporting] Worker completed: (k5o88fof21n67a3f11cncpbn)
server    log   [11:43:35.794] [info][esqueue][queue-worker][reporting] k5o7yx7y21n67a3f11ebtyjb - Job data saved successfully: /.reporting-2020.01.19/k5o88fof21n67a3f11cncpbn

In the New Platform logger, only the info log messages appear:

server    log   [11:33:40.589] [info][queue-job][reporting] Successfully queued job: k5o7vqy7219v7a3f11crntxa
server    log   [11:33:41.693] [info][info][esqueue][queue-worker][reporting] k5o7qvh2219v7a3f115wezue - Job marked as claimed: /.reporting-2020.01.19/k5o7vqy7219v7a3f11crntxa
server    log   [11:33:41.695] [info][info][esqueue][queue-worker][reporting] k5o7qvh2219v7a3f115wezue - Starting job
server    log   [11:33:41.760] [warning][csv][execute-job][k5o7vqy7219v7a3f11crntxa][reporting] Kibana Advanced Setting "dateFormat:tz" is set to "Browser". Dates will be formatted as UTC to avoid ambiguity.
server    log   [11:33:42.774] [info][info][esqueue][queue-worker][reporting] k5o7qvh2219v7a3f115wezue - Job execution completed successfully
server    log   [11:33:42.976] [info][info][esqueue][queue-worker][reporting] k5o7qvh2219v7a3f115wezue - Job data saved successfully: /.reporting-2020.01.19/k5o7vqy7219v7a3f11crntxa

[tsullivan]

Reproducing the issue with a simpler test.

This should enable debug logging for Reporting in kibana.yml:
logging.events.log: ['warning', 'error', 'fatal', 'info', 'reporting']

Add a debug log and info in reporting/server/plugin.ts

  return new (class ReportingPlugin implements ReportingPlugin {
    private initializerContext: ReportingInitializerContext;

    constructor(context: ReportingInitializerContext) {
      this.initializerContext = context;
      const simpleLog = this.initializerContext.logger.get('reporting');
      simpleLog.debug('this is a reporting debug log');
      simpleLog.info('this is a reporting info log');
    }

Only info line is logged:

[elasticmachine]

Pinging @elastic/kibana-platform (Team:Platform)

[tsullivan]

Hi, just want to call out that this is blocking https://github.com/elastic/kibana/pull/55442

[joshdover]

@tsullivan In your example you don't have debug in the logging config. Am I right in saying that in the legacy platform, if you configure a specific tag (eg. reporting), then all logs with that tag get logged, regardless of level?

[tsullivan]

@tsullivan In your example you don't have debug in the logging config. Am I right in saying that in the legacy platform, if you configure a specific tag (eg. reporting), then all logs with that tag get logged, regardless of level?

That is correct. If my logging configuration in kibana.yml looks like:

logging.events.log: ['warning', 'error', 'fatal', 'info', 'reporting']

Any log line with the reporting tag should get printed.

This is a good alternative to enabling full verbose logging for all parts of Kibana, when all I care about is verbose logging for Reporting.

[tsullivan]

Since the workaround for this issue is just to enable plain verbose logging, I'll take off the blocker label. But I think it's important to have some way of whitelisting logging tags so they'd be logged even if they are low-level.

[pgayvallet]

logging.events.log: ['warning', 'error', 'fatal', 'info', 'reporting']

this.initializerContext.logger.get('reporting');

This actually creates a plugins.reporting logger context

@joshdover I don't know very well our implementation, but we follow more or less log4j api, isn't the solution just to declare a specific logger for plugins.reporting in the configuration file (and associated appender) and set the it's logLevel to 'all'/debug' ?

[mshustov]

but we follow more or less log4j api,

We will follow when #41956 lands.

[joshdover]

Since the workaround for this issue is just to enable plain verbose logging, I'll take off the blocker label. But I think it's important to have some way of whitelisting logging tags so they'd be logged even if they are low-level.

Once #41956 is done and we enable the new logging configuration, this will be possible. However, I also think it's important that logging configurations don't break during 7.x, so if this logging config worked before migrating to the New Platform, then it needs to be fixed as well.

I'm working on this today and should have a fix up soon.

[tsullivan]

Hi, this issue has re-appeared in the past couple of weeks.

My logging config:

logging.events.log: ['warning', 'error', 'fatal', 'info', 'reporting']

"Debug" level Reporting logs are not showing up.

[joshdover]

@restrry I know the receiveAllLevels option was removed, did we break this?

[mshustov]

@tsullivan my bad, I forgot to warn you that NP logging config is available and I removed receiveAllLevels flag since it's incompatible with the LP logging system.
you could enable logging for all reporting messages via NP logging config

logging:
  loggers:
      - context: reporting
        appenders: [console]
        level: debug

More about NP logging config https://github.com/elastic/kibana/blob/master/src/core/server/logging/README.md
Let me know if the proposed setup works for you