Plugin log time format not in sync with system config

[ods94065]

Front matter

• fluentd 1.4.1 (tested via Docker: fluentd/fluentd:1.4-onbuild)
• OS: Alpine 3.8 (see above)
• Ruby: 2.5.2 (via Alpine 3.8 per)

Configuration

This is a simplification of my configuration, enough I hope to illustrate the problem I'm having.

<source>
  @type                 my_plugin
  @id                   my_plugin
  @log_level            debug
  tag                   my_plugin
</source>

<system>
  <log>
    format json
    time_format %FT%T.%6N%:z
  </log>
</system>

<match my_plugin>
  @type copy
  <store>
    @type elasticsearch
    ...
  </store>
</match>

Description

I am writing a custom plugin to pull logs from S3 and publish them to Elasticsearch. That processing works well! However, the internal logs generated by my plugin, and by the fluentd system, have inconsistent formats of timestamps in them that confuse our downstream log aggregators (ironically, also fluentd instances :-) ).

Examples:

A. This is a system logging statement with the timestamp format I want – good old RFC3339 date/time.

{"time":"2019-03-28T21:11:56.827082+00:00","level":"info","message":"parsing config file is succeeded path=\"/fluentd/etc/fluent.conf\""}

B. This is a log statement from my plugin:

{"time":"2019-03-28 21:11:58 +0000","level":"debug","message":"[my_plugin] log_bucket: logs"}

It is generated by code that looks like this:

def configure(conf)
  super
  log.debug("log_bucket: logs")
end

Note the default timestamp format, instead of the system-configured time format that I want. I was expecting my specified time format to be used.

Interestingly, if I do this from within my plugin:

log.time_format = '%FT%T.%6N%:z'
log.debug("log_bucket: logs")

the time format doesn't change!

Analysis

I have determined the root cause, which I believe to be a bug. (That being said, I'm a newcomer to the fluentd code base, so do double-check my analysis.)

The fundamental issue, I think, is that Fluent::PluginLogger both inherits from Fluent::Log (i.e. contains internal log state of its own) and wraps around a "parent" logger (the @logger instance variable). This creates lots of opportunities for mischief.

Some, but not all, methods delegate to the parent logger. In particular, #puts and #<< delegate to the parent logger, but #debug, for example, does not. This means that all the formatting of log messages is handled by the PluginLogger, not by the parent logger.

Some attempt is made to make sure that a PluginLogger uses the same format as its parent logger, by synchronizing the state between the two. @format is synced whenever #format= is called, for example. However, @time_format is not synced, and it retains its default value whenever a PluginLogger is constructed. I believe this is why I'm seeing an inconsistent time format coming from my plugin.

Now, the reason that #time_format= has no effect is that both #time_format and #time_format= are delegated to the parent logger – they do not read from or modify the plugin logger's internal state. This would be fine if PluginLogger were using #time_format to format time objects instead of using its own @time_format instance variable. However, its definition of #debug et al are inherited from Fluent::Log, and they use #format_time to do the formatting – which, unsurprisingly, uses @time_format under the hood.

Syncing @time_format is not sufficient, I discovered. If the time format is compatible with the performance-optimized strptime library, Fluent::Log will create a @time_formatter object to format times instead of Ruby's Time#strftime implementation. Thus, we must synchronize @time_formatter as well.

I think the best fix, although perhaps the most dangerous from a backwards compatibility standpoint, might be to remove the inheritance relationship between PluginLogger and Fluent::Log, and just have PluginLogger delegate everything to its parent logger. At least, the mixture of inheritance, composition, and partial delegation really ought to be revisited.

The most immediate fix, though, would be to ensure that @time_format and @time_formatter are synchronized properly with the parent logger.

Edit: I discovered another nuance: the issue only arises in the case of JSON output. Why? Because the plugin logger's text formatter doesn't format time. Instead, it calls #caller_line, which is in fact delegated to the parent logger. By comparison, the JSON formatter calls #format_time itself.

Here's a test case that reproduces the situation. It works on the "text" case but fails on the "json" one:

    data(
      text: [:text, "2016 [info]: yaaay\n"],
      json: [:json, %Q({"time":"2016","level":"info","message":"yaaay"}\n)],
    )
    def test_time_format(data)
      fmt, expected_log_line = data
      @log.format = fmt
      @log.time_format = "%Y"
      @log.info "yaaay"
      assert{ @log_device.logs.include? expected_log_line }
    end