Docker log concatenated

Bug Report

Describe the bug Docker log lines get concatenated, thus later when sending with http/gelf they some messages got ignored.

To Reproduce

Example log message:

{"log":"[10:36:40 CALCULATIONWORK INF] OnMessageRequest.\r\n","stream":"stdout","time":"2020-11-18T10:36:40.1226117Z"}
{"log":"[10:36:40 CALCULATIONWORK INF] Received message: {}\r\n","stream":"stdout","time":"2020-11-18T10:36:40.1941871Z"}    
{"log":"[10:36:41 CALCULATIONWORK WRN] Message, status code: NotFound\r\n","stream":"stdout","time":"2020-11-18T10:36:41.8346958Z"}
{"log":"[10:36:42 CALCULATIONWORK WRN] Message, status code: NotFound\r\n","stream":"stdout","time":"2020-11-18T10:36:42.0074699Z"}
{"log":"[10:36:55 CALCULATIONWORK INF] Message \r\n","stream":"stdout","time":"2020-11-18T10:36:55.3790879Z"}
{"log":"[10:36:55 CALCULATIONWORK INF] Message \r\n","stream":"stdout","time":"2020-11-18T10:36:55.8596215Z"}
{"log":"[10:36:55 CALCULATIONWORK INF] Message \r\n","stream":"stdout","time":"2020-11-18T10:36:55.9288131Z"}
{"log":"[10:36:55 CALCULATIONWORK INF] Message \r\n","stream":"stdout","time":"2020-11-18T10:36:55.9908154Z"}
{"log":"[10:36:56 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:56.061887Z"}
{"log":"[10:36:56 CALCULATIONWORK INF] Message \r\n","stream":"stdout","time":"2020-11-18T10:36:56.1320838Z"}
{"log":"[10:36:56 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:56.1956686Z"}
{"log":"[10:36:56 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:56.267939Z"}
{"log":"[10:36:56 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:56.3320141Z"}
{"log":"[10:36:56 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:56.4451448Z"}
{"log":"[10:36:56 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:56.5202363Z"}
{"log":"[10:36:57 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:57.1868469Z"}
{"log":"[10:36:57 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:57.2504293Z"}
{"log":"[10:36:57 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:57.3375884Z"}
{"log":"[10:36:57 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:57.4065477Z"}
{"log":"[10:36:57 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:57.4692753Z"}
{"log":"[10:36:57 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:57.5185604Z"}
{"log":"[10:36:57 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:57.5960827Z"}
{"log":"[10:36:57 CALCULATIONWORK INF] Message\r\n","stream":"stdout","time":"2020-11-18T10:36:57.6559984Z"}
{"log":"[10:36:58 CALCULATIONWORK INF] Completed message: {}\r\n","stream":"stdout","time":"2020-11-18T10:36:58.118793Z"}    
{"log":"[10:51:01 CALCULATIONWORK INF] OnMessageCalculationRequest.\r\n","stream":"stdout","time":"2020-11-18T10:51:01.7863301Z"}

Steps to reproduce the problem: Went through the Kubernetes configuration available in the docs with configuration below. https://docs.fluentbit.io/manual/installation/kubernetes

Expected behavior Each line of log in separate message transmitted to http/gelf output. Noticed when using stdout format json that lines from docker get concatenated and when switching to http or gelf output only first log key gets sent, rest are ignored. Notice the second square bracket having two log keys.

2020-11-18T11: 09: 55.638890700Z [
    {
        "date": 1605697794.580902,
        "log": "[11:09:54 CALCULATIONWORK INF] OnMessageCalculationRequest.\r\n",
        "stream": "stdout",
        "time": "2020-11-18T11:09:54.5809018Z",
        "pod_name": "",
        "namespace_name": "development",
        "pod_id": "",
        "host": "windows",
        "container_name": "",
        "docker_id": "",
        "container_hash": "",
        "container_image": ""
    }
]
2020-11-18T11: 09: 56.625512600Z [
    {
        "date": 1605697794.639122,
        "log": "[11:09:54 CALCULATIONWORK INF] Received message: {}\r\n",
        "stream": "stdout",
        "time": "2020-11-18T11:09:54.6391224Z",
        "pod_name": "",
        "namespace_name": "development",
        "pod_id": "",
        "host": "windows",
        "container_name": "",
        "docker_id": "",
        "container_hash": "",
        "container_image": ""
    },
    {
        "date": 1605697795.932223,
        "log": "[11:09:55 CALCULATIONWORK WRN] Response from API, status code: NotFound\r\n",
        "stream": "stdout",
        "time": "2020-11-18T11:09:55.9322229Z",
        "pod_name": "",
        "namespace_name": "development",
        "pod_id": "",
        "host": "windows",
        "container_name": "",
        "docker_id": "",
        "container_hash": "",
        "container_image": ""
    }
]...

In graylog I end up seeing two messages instead of three or more.

Your Environment

Version used: 1.6.3

Configuration:


apiVersion: v1
kind: ConfigMap
metadata:
name: fluentbit-config-windows
namespace: logging
labels:
k8s-app: fluent-bit
data:
# Configuration files: server, input, filters and output
# ======================================================
fluent-bit.conf: |
[SERVICE]
    Flush         1
    Log_Level     info
    Daemon        off
    Parsers_File  parsers.conf

@INCLUDE c:\config\input-kubernetes.conf
@INCLUDE c:\config\filter-kubernetes.conf
@INCLUDE c:\config\output-graylog.conf

input-kubernetes.conf: |
[INPUT]
    Name                tail
    Tag                 kube.*
    Path                c:\var\log\containers\calculation*.log
    Parser              docker
    DB                  c:\var\log\flb_kube.db
    Mem_Buf_Limit       10MB
    Refresh_Interval    10
    Skip_Long_Lines     Off
    Docker_Mode         On
    Docker_Mode_Flush   5
    Docker_Mode_Parser  docker_multiline_match
    Ignore_Older        300s

filter-kubernetes.conf: |
[FILTER]
    Name                kubernetes
    Match               kube.*
    Kube_URL            https://kubernetes.default.svc.cluster.local:443
    Kube_CA_File        c:\var\run\secrets\kubernetes.io\serviceaccount\ca.crt
    Kube_Token_File     c:\var\run\secrets\kubernetes.io\serviceaccount\token
    Merge_Log           On
    Merge_Log_Key       log_merged
    Merge_Log_Trim      On
    Keep_Log            On
    K8S-Logging.Parser  Off
    K8S-Logging.Exclude On
    DNS_Retries         6
    DNS_Wait_Time       5
    Labels              Off
    Annotations         Off

[FILTER]
    Name nest
    Match kube.*
    Operation lift
    Nested_under kubernetes

[FILTER]
    name        expect
    match       kube.*
    key_exists  pod_name
    key_exists  log
    action      warn

output-graylog.conf: |
[OUTPUT]
    name  stdout
    match *
    format json
# [OUTPUT]
#     Name                    http
#     Match                   *
#     Host                    graylog.graylog.svc.cluster.local
#     Port                    12204
#     URI                     /gelf
#     Format                  gelf
#     Gelf_host_key           pod_name
#     Gelf_short_message_key  log
#     Gelf_full_message_key   log

parsers.conf: |
[PARSER]
    Name   json
    Format json
    Time_Key time
    Time_Format %d/%b/%Y:%H:%M:%S %z

[PARSER]
    Name        docker
    Format      json
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L
    Time_Keep   On

[PARSER]
    Name        docker_multiline_no_match
    Format      regex
    Regex       (?<log>^{"log":"\d{4}-\d{2}-\d{2}.*)

[PARSER]
    Name        docker_multiline_match
    Format      regex
    Regex       (?<log>^{"log":".*})

apiVersion: apps/v1 kind: DaemonSet metadata: name: fluent-bit-windows namespace: logging labels: k8s-app: fluent-bit-logging version: v1 kubernetes.io/cluster-service: "true" annotations: fluentbit.io/exclude: "true" spec: selector: matchLabels: k8s-app: fluent-bit-logging version: v1 kubernetes.io/cluster-service: "true" template: metadata: labels: k8s-app: fluent-bit-logging version: v1 kubernetes.io/cluster-service: "true" annotations: fluentbit.io/exclude: "true" prometheus.io/scrape: "true" prometheus.io/port: "2020" prometheus.io/path: /api/v1/metrics/prometheus spec: containers:

name: fluent-bit image: fluent-bit:1.6.3-nanoserver imagePullPolicy: Always ports:
- containerPort: 2020 volumeMounts:
  - name: varlog mountPath: c:\var\log
  - name: programdatadockercontainers mountPath: c:\ProgramData\docker\containers readOnly: true
  - name: config mountPath: c:\config terminationGracePeriodSeconds: 10 volumes:
name: varlog hostPath: path: c:\var\log
name: programdatadockercontainers hostPath: path: c:\ProgramData\docker\containers\
name: config configMap: name: fluentbit-config-windows serviceAccountName: fluent-bit tolerations:
key: node-role.kubernetes.io/master operator: Exists effect: NoSchedule
operator: "Exists" effect: "NoExecute"
operator: "Exists" effect: "NoSchedule" nodeSelector: beta.kubernetes.io/os: windows

Environment name and version (e.g. Kubernetes? What version?): Azure Kubernetes Service 1.17.11
Server type and version: Windows 2019 Datacenter
Filters and plugins: as mentioned in configuration above

fluent / fluent-bit

Docker log concatenated #2784

Bug Report