Supporting docker log splitting in Kubernetes logging integrations

[crassirostris]

Follow-up of #52433

Docker 1.13 introduced a change into the logging mechanism (moby/moby#22982), that split the log lines longer than 16K into chunks of no more than that. Current default logging integrations (fluentd-gcp and fluentd-es addons) do not support that and this might result in broken ingestion, i.e. when JSON parsing is broken for entries longer than 16K.

One possible solution is introducing a fluentd plugin to the configuration to concat such entries in the similar way https://github.com/GoogleCloudPlatform/fluent-plugin-detect-exceptions does it (assuming there is one out there, cc @tagomoris @repeatedly @edsiper for that)

/cc @igorpeshansky @fgrzadkowski @piosz

[igorpeshansky]

Presumably this should be done in the Docker fluentd logging driver... The discussion on moby/moby#34620 seems to be leaning that way...

[repeatedly]

In fluentd logging driver side, journald driver approach is better: https://github.com/moby/moby/blob/80edccda708c6771824c245b4d634c2a9ce29795/daemon/logger/journald/journald.go#L110
I'm not sure buffering partial message in logging driver is good or not...

In fluentd side, implementing in_docker_forward or filter_docker_xxx is needed.

[dims]

@crassirostris @repeatedly @igorpeshansky do we need to block 1.8 release? can we please move this out of 1.8 if it's not?

[crassirostris]

@dims Moved to 1.9, since it's not specific for 1.8

[JorritSalverda]

Is there any way this can be fixed by running a custom fluentd? Or is there a fluentd docker driver github issue I can follow for updates on when they expect to have this fixed? Txh

[k8s-github-robot]

[MILESTONENOTIFIER] Milestone Issue Needs Approval

@crassirostris @kubernetes/sig-instrumentation-misc

Action required: This issue must have the status/approved-for-milestone label applied by a SIG maintainer.

Issue Labels

• sig/instrumentation: Issue will be escalated to these SIGs if needed.
• priority/critical-urgent: Never automatically move out of a release milestone; continually escalate to contributor and SIG through all available channels.
• kind/bug: Fixes a bug discovered during the current release.

Help

• Additional instructions
• Commands for setting labels

[crassirostris]

Is there any way this can be fixed by running a custom fluentd?

Problem is that there's no fluentd plugin to fix the problem, so running a custom fluentd won't help, there's nothing to add to the configuration to make it work (unless you want to write your own solution)

is there a fluentd docker driver github issue I can follow for updates on when they expect to have this fixed

moby/moby#34855

They don't think it's a docker problem and don't plan to fix it. However, it will be fixed in GKE

[JorritSalverda]

That seems fair from Docker's perspective. I'd rather have stable containers as well :)

So you're thinking of switching from the current log drive json-file - at least that's what my Google Container Optimized image in GKE 1.8.1 uses - to the journald driver to circumvent the problem? And then use a plugin like https://github.com/okushchenko/fluent-plugin-docker-journald-concat to recombine the partial messages?

[crassirostris]

@JorritSalverda

So you're thinking of switching from the current log drive json-file

No, that's not the case. Solution is TBD, but if you export your logs to Stackdriver (that has a limit of 100KB per entry) you won't see the difference

[JorritSalverda]

I think there's still a difference in that the 100KB stackdriver logging limit is larger than the 16KB docker limit at which the partial messaging starts, so without proper recombination of those chunked messages you'll lose the ability to send log lines larger than 16KB into stackdriver.

However we're also running our own fluentd that sends messages straight into pub/sub, which has a limit of 10MB per message. And although we're trying to keep the messages much smaller than 16KB it would be nice to be able to send bigger messages without instrumenting our applications to push the messages into pub/sub themselves.

I hope you find a nice solution that will make this possible :)

[fejta-bot]

Issues go stale after 90d of inactivity.
Mark the issue as fresh with /remove-lifecycle stale.
Stale issues rot after an additional 30d of inactivity and eventually close.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle stale

[fejta-bot]

Stale issues rot after 30d of inactivity.
Mark the issue as fresh with /remove-lifecycle rotten.
Rotten issues close after an additional 30d of inactivity.

If this issue is safe to close now please do so with /close.

Send feedback to sig-testing, kubernetes/test-infra and/or fejta.
/lifecycle rotten
/remove-lifecycle stale

[crassirostris]

/remove-lifecycle rotten

Still relevant, hasn't been fixed

[desaintmartin]

Would using the "concat" fluentd plugin be relevant?
https://github.com/fluent-plugins-nursery/fluent-plugin-concat
It seems to have explicit support for our specific use case.

Edit: For EFK, Adding fluentd-plugin-concat to fluentd-es image (https://github.com/wiremind/kubernetes/tree/fluentd-concat/cluster/addons/fluentd-elasticsearch/fluentd-es-image, https://hub.docker.com/r/wiremind/fluentd-elasticsearch-concat/) and adding

<filter **>
  @type concat
  key log
  multiline_end_regexp /\n$/
</filter>

to the ConfigMap
Works well.

Would a PR with those changes be acceptable?

[liangjacky]

trying to solve this as well. Having the same issue as @abedwardsw where long lines are being truncated and MDC gone.

[ju-la-berger]

Please see

• Concat does not work correctly for partial messages fluent-plugins-nursery/fluent-plugin-concat#59
• Missing partial metadata for fluentd moby/moby#37889

The big problem here is concurrency. Just concatenating all partial log messages as they arrive may be wrong. Let's say your app logs two events, called a and b here. Then the Docker log messages may be written to the JSON log file (or whatever Docker logging driver is used, e.g. in plain Docker or Docker Swarm) in this order:

a (first 16 KB)
b (first 16 KB)
a (another 5 KB)
b (another 16 KB)
b (another 13 KB)

The fluentd concat plugin cannot decide what to do. What records belong together?

The good message is: This can be solved (similar to moby/moby#37889) as Docker logs contain all the needed information here:

https://github.com/moby/moby/blob/8e610b2b55bfd1bfa9436ab110d311f5e8a74dcb/api/types/backend/backend.go#L32

So you just have to extend these methods and the JSONLogs struct by the partial log meta data:

https://github.com/moby/moby/blob/8e610b2b55bfd1bfa9436ab110d311f5e8a74dcb/daemon/logger/jsonfilelog/jsonfilelog.go#L143
https://github.com/moby/moby/blob/8e610b2b55bfd1bfa9436ab110d311f5e8a74dcb/daemon/logger/jsonfilelog/jsonlog/jsonlogbytes.go#L22

Then you have to fix fluent-plugins-nursery/fluent-plugin-concat#59: Mind the ID and ordinal of the partial log metadata so that you concatenate the right records in the correct order.

[ju-la-berger]

I just edited my above comment because I am not sure how the case of linebreaks (i.e. those written by the application) in log messages relate to this issue.

However, often you can control the logging of your application and let it write JSON to STDOUT (e.g. https://github.com/logstash/logstash-logback-encoder for Java / Spring Boot applications) so you do not have linebreaks.

Back to the original issue:

@desaintmartin: I have serious doubts that #68012 will do it under load with a lot of concurrent partial messages. I observed this in a Docker Swarm setup with fluentd and the concat plugin configured analogously.

[ju-la-berger]

@crassirostris Could you please reopen this issue?

The concurrency is the problem here: Let your container simultaneously produce two log messages of >16KB (let's say 20 KB). Then fluentd will concatenate all four messages to one large (16+16+4+4 KB = 40 KB) message. The fluentd (or whatever you use) needs to know the ID of the partial log metadata to concatenate only those messages with identical IDs. So this needs to be implemented in the (default) local JSON file log driver in Docker (moby).

[desaintmartin]

Problem is that ID comes with Docker 18.06 if I'm not wrong, this is why I didn't use it: do we want to require a docker version which is 2 months old?

[coffeepac]

@crassirostris is no longer much involved with the project. if you would like to open this back up to alter the implementation, please file a new issue @ju-la-berger.

[desaintmartin]

If you do so, please ping me as well.

[kahootali]

@desaintmartin I have added the concat plugin

      <filter **.log>
          @type concat
          key log
          multiline_end_regexp /\n$/
      </filter>

but still it is not concatenating, Any Idea?

[desaintmartin]

No idea why it does not work. For up-to-date information, I have inserted:

    # Concatenate multi-line logs (>=16KB)
    <filter kubernetes.var.log.containers.**>
      @type concat
      key log
      multiline_end_regexp /\n$/
      separator ""
    </filter>

Just after the kubernetes_metadate injection.