Fluentd own log not always formatted as json ignoring explicit system configuration

Fluentd own log not always formatted as json ignoring explicit system configuration. Given following config:

<system>
  <log>
    format json
    time_format %FT%T.%L%z
  </log>
</system>
...

It sometimes produce non-json log entries in standard output (file buffer is always fine). E.g.:

...
2020-01-31 14:52:48 +0000 [info]: Worker 0 finished with status 0
{"time":"2020-01-31T14:54:09.501+0000","level":"info","message":"parsing config file is succeeded path=\"/fluentd/etc/fluent.conf\""}
{"time":"2020-01-31T14:54:09.509+0000","level":"info","message":"gem 'fluent-plugin-concat' version '2.4.0'"}
{"time":"2020-01-31T14:54:09.511+0000","level":"info","message":"gem 'fluentd' version '1.9.0'"}
...

To reproduce I just used config as above and latest docker fluentd image, but probably also reproducible in 1.7.0. When started container with fluend I've connected to it using docker logs -f <my-container-id> and saw these messages. Even when fluentd log is entirely suppressed like this:

<label @FLUENT_LOG>
  <match fluent.*>
    @type null
  </match>
</label>

These messages are still appear in stdout

Expected behavior Either no such messages or they should be properly json formatted.

Your Environment fluent/fluentd:v1.9-1 docker image from dockerhub with one additional plugin installed - fluent-plugin-concat, though I doubt it have anything to do with that.

Fluentd or td-agent version: 1.9.0

Operating system:

NAME="Alpine Linux"
ID=alpine
VERSION_ID=3.9.4
PRETTY_NAME="Alpine Linux v3.9"
HOME_URL="https://alpinelinux.org/"
BUG_REPORT_URL="https://bugs.alpinelinux.org/"

Kernel version: 4.15.0-1052-kvm

If you hit the problem with older fluentd version, try latest version first.

Your Configuration See above. Other parts of configuration are irrelevant. I've used exactly same config with 1.6.0 and didn't have this problem.

<system>
  <log>
    format json
    time_format %FT%T.%L%z
  </log>
</system>

<source>
  @type dummy
  tag test
</source>

<match>
  @type stdout
</match>

$ be fluentd -c example/debug/log_time_format.conf                                                                                                                                                [10:56:23]
{"time":"2020-02-03T10:56:25.289+0900","level":"info","message":"parsing config file is succeeded path=\"example/debug/log_time_format.conf\""}
{"time":"2020-02-03T10:56:25.289+0900","level":"info","message":"gem 'fluentd' version '1.8.0.rc1'"}
{"time":"2020-02-03T10:56:25.312+0900","level":"warn","message":"both of Plugin @id and path for <storage> are not specified. Using on-memory store."}
{"time":"2020-02-03T10:56:25.312+0900","level":"warn","message":"both of Plugin @id and path for <storage> are not specified. Using on-memory store."}
{"time":"2020-02-03T10:56:25.313+0900","level":"info","message":"using configuration file: <ROOT>\n  <system>\n    <log>\n      format json\n      time_format \"%FT%T.%L%z\"\n    </log>\n  </system>\n  <source>\n    @type dummy\n    tag \"test\"\n  </source>\n  <match>\n    @type stdout\n  </match>\n</ROOT>"}
{"time":"2020-02-03T10:56:25.313+0900","level":"info","message":"starting fluentd-1.8.0.rc1 pid=94876 ruby=\"2.5.7\""}
{"time":"2020-02-03T10:56:25.313+0900","level":"info","message":"spawn command to main:  cmdline=[\"/Users/yuta.iwama/.rbenv/versions/2.5.7/bin/ruby\", \"-Eascii-8bit:ascii-8bit\", \"-r/Users/yuta.iwama/.rbenv/versions/2.5.7/lib/ruby/gems/2.5.0/gems/bundler-2.1.4/lib/bundler/setup\", \"/Users/yuta.iwama/.rbenv/versions/2.5.7/lib/ruby/gems/2.5.0/bin/fluentd\", \"-c\", \"example/debug/log_time_format.conf\", \"--under-supervisor\"]"}
{"time":"2020-02-03T10:56:25.951+0900","level":"info","message":"adding match pattern=\"**\" type=\"stdout\""}
{"time":"2020-02-03T10:56:25.969+0900","level":"info","message":"adding source type=\"dummy\""}
{"time":"2020-02-03T10:56:25.972+0900","level":"warn","message":"both of Plugin @id and path for <storage> are not specified. Using on-memory store.","worker_id":0}
{"time":"2020-02-03T10:56:25.972+0900","level":"warn","message":"both of Plugin @id and path for <storage> are not specified. Using on-memory store.","worker_id":0}
{"time":"2020-02-03T10:56:25.972+0900","level":"info","message":"starting fluentd worker pid=94890 ppid=94876 worker=0","worker_id":0}
{"time":"2020-02-03T10:56:25.973+0900","level":"info","message":"fluentd worker is now running worker=0","worker_id":0}
2020-02-03 10:56:25.972880000 +0900 fluent.info: {"pid":94890,"ppid":94876,"worker":0,"message":"starting fluentd worker pid=94890 ppid=94876 worker=0"}
2020-02-03 10:56:25.973236000 +0900 fluent.info: {"worker":0,"message":"fluentd worker is now running worker=0"}
2020-02-03 10:56:26.076047000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:27.004296000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:28.030830000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:29.061835000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:30.086931000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:31.013652000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:32.043223000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:33.077829000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:34.001474000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:35.034242000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:36.060201000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:37.082423000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:38.010856000 +0900 test: {"message":"dummy"}
^C2020-02-03 10:56:38 +0900 [info]: Received graceful stop
2020-02-03 10:56:39.048042000 +0900 test: {"message":"dummy"}
2020-02-03 10:56:39.599201000 +0900 fluent.info: {"worker":0,"message":"fluentd worker is now stopping worker=0"}
{"time":"2020-02-03T10:56:39.599+0900","level":"info","message":"fluentd worker is now stopping worker=0","worker_id":0}
{"time":"2020-02-03T10:56:39.599+0900","level":"info","message":"shutting down fluentd worker worker=0","worker_id":0}
{"time":"2020-02-03T10:56:39.600+0900","level":"info","message":"shutting down input plugin type=:dummy plugin_id=\"object:3fcd4c4e1534\"","worker_id":0}
{"time":"2020-02-03T10:56:39.601+0900","level":"info","message":"shutting down output plugin type=:stdout plugin_id=\"object:3fcd4c4f82fc\"","worker_id":0}
2020-02-03 10:56:39 +0900 [info]: Worker 0 finished with status 0

I've confirmed it doesn't work. It's caused by failing to pass the format value to serverengine's logger. I'll fix it.

https://github.com/treasure-data/serverengine/blob/99d44a0989ab3e64e14ac0367aadf76aa13b3583/lib/serverengine/multi_process_server.rb#L136

fluent / fluentd

Fluentd own log not always formatted as json ignoring explicit system configuration #2811