[BUG] Multiline in CRI logs: Chunks from stdout and stderr are incorrectly combined

[skirino]

Agent version

7.80.1, 7.81.1

Bug Report

After container runtime splits long log lines emitted from a container into <=16KB chunks, datadog agent by default combines the chunks to restore the original log lines. However, when combining chunks in CRI log files, (IIUC) datadog agent does not honor which stream the chunk came from (stdout or stderr), and regards F (Full) chunk as the end of the currently-buffered log line. I think this is problematic if we have the following interleaved chunks in a CRI log file:

2024-01-01T...Z stderr P long log line chunk 1...
2024-01-01T...Z stdout F short log line
2024-01-01T...Z stderr F long log line chunk 2...

We get the following 2 unexpected log messages in datadog UI:

long log line chunk 1...short log line
long log line chunk 2...

We expect the following 2 log messages:

short log line
long log line chunk 1...long log line chunk 2...

To my best knowledge, the issue lies in

• MultiLineParser has only 1 buffer
• MultiLineParser.process() accumulates the messages without looking at the type of stream (stdout or stderr)

I found both 7.80.1 and 7.81.1 have the same issue. Given that the relevant code has not been modified, I think the issue exists in the current main.

Reproduction Steps

I used a local kind cluster to reproduce.

kind create cluster

Install datadog-agent with helm (according to https://docs.datadoghq.com/ja/containers/kubernetes/installation/?tab=helm )

helm repo add datadog https://helm.datadoghq.com/
helm repo update
kubectl create secret generic datadog-secret --from-literal api-key='****'

Create a values file:

datadog:
  apiKeyExistingSecret: datadog-secret
  clusterName: local
  site: ap1.datadoghq.com
  tags:
    - env:local
  logs:
    enabled: true
    containerCollectAll: true
  kubelet:
    tlsVerify: false # For kind
  apm:
    portEnabled: false
clusterAgent:
  enabled: false

Install the agent:

helm --kube-context kind-kind install datadog-agent -f datadog-values.yaml datadog/datadog

Run a pod that concurrently writes large strings to stderr and short strings to stdout.

apiVersion: v1
kind: Pod
metadata:
  name: logwriter
  namespace: default
spec:
  containers:
    - image: debian:latest
      name: bash
      command: ["/bin/bash", "-c"]
      args:
        - |
          LARGE_STRING=$(printf '%20000s' | sed 's/ /0123456789/g')
          dump_large_string_to_stderr() {
            for _ in {1..10}; do
              echo "${LARGE_STRING}" >&2
            done
          }
          dump_large_string_to_stderr&
          sleep 0.0005
          for _ in {1..100}; do
            echo "a"
          done
          sleep 1000 # The CRI log file is deleted on pod termination; keep it for a while

Then we get in datadog UI, among correctly-combined 200000-digit messages, the following messages:

0123456789...(98304 digits)...0123a
456789...(remaining 101696 digits)...789

The behavior of logwriter is of course not deterministic; it may require some retries and/or adjustments in sleep duration, length of strings etc.

Agent configuration

Please see values.yaml in the repro steps.

Operating System

Linux

Other environment details

No response

[soberpeach]

@skirino Thanks for bringing this up!

We're looking into it now