Bad escaping after fluent-bit processing

[hdiass]

Hello,

After writing on slack, will post here the issue i'm facing.
I've been using fluent-bit in several times, but this time i found out that the logs created by an application with some \n are being changed by fluent-bit adding one more "" this is leading to a lot of bad escaping on kibana, and debugging stacktraces with it is very difficult. I've attached the 2 differents logs (application raw logs, and logs parsed by fluent-bit), and the SOS report. If you can take a look and give some advices would be much appreciated. Thanks,

From application : {"@timestamp":"2017-12-11T17:22:07.421+00:00","@version":1,"message":"\nFailed events housekeeping completed in 4ms\n","logger_name":"LoadingProcessManager.[LoadingProcessManager]","thread_name":"[FR(234141)]@Wrk.80","level":"INFO","level_value":20000,"user":"adm","code":"G1000","instance":"product","layer":"converter"}
From Kibana: 
{
  "_index": "dev-logs-2017.12.11",
  "_type": "flb_type",
  "_id": "AWBGmTGR9USO52Xb23Br",
  "_version": 1,
  "_score": null,
  "_source": {
    "_@timestamp": "2017-12-11T17:22:07.424Z",
    "@timestamp": "2017-12-11T17:22:07.421+00:00",
    "@version": 1,
    "message": "\\nFailed events housekeeping completed in 4ms\\n",
    "logger_name": "LoadingProcessManager.[LoadingProcessManager]",
    "thread_name": "[FR(234141)]@Wrk.80",
    "level": "INFO",
    "level_value": 20000,
    "user": "adm",
    "code": "G1000",
    "instance": "product",
    "layer": "converter"
  },
  "fields": {
    "@timestamp": [
      1513012927421
    ]
  },
  "sort": [
    1513012927421
  ]
}

SOS Report

Customers of Treasure Data. For more details visit:                                                                                                                                                     [0/25816]

    https://fluentd.treasuredata.com


[Fluent Bit]
    Edition             Community Edition
    Version             0.12.9
    Built Flags          JSMN_PARENT_LINKS JSMN_STRICT FLB_HAVE_TLS FLB_HAVE_SQLDB FLB_HAVE_BUFFERING FLB_HAVE_TRACE FLB_HAVE_FLUSH_LIBCO FLB_HAVE_SYSTEMD FLB_HAVE_FORK FLB_HAVE_PROXY_GO FLB_HAVE_JEMALLOC JEMALLOC_MANGLE FLB_HAVE_REGEX FLB_HAVE_C_TLS FLB_HAVE_SETJMP FLB_HAVE_ACCEPT4 FLB_HAVE_INOTIFY

[Operating System]
    Name                Linux
    Release             4.4.0-1043-aws
    Version             #52-Ubuntu SMP Tue Dec 5 10:49:06 UTC 2017

[Hardware]
    Architecture        x86_64
    Processors          2

[Built Plugins]
    Inputs              cpu mem kmsg tail proc disk systemd netif dummy head health serial stdin tcp mqtt lib forward random syslog
    Filters             grep stdout kubernetes parser record_modifier
    Outputs             counter es exit file forward http influxdb kafka-rest nats null plot stdout td lib flowcounter

[SERVER] Runtime configuration
    Flush               1
    Daemon              Off
    Log_Level           Debug

[INPUT] Instance
    Name                tail.0 (tail, id=0)
    Flags               DYN_TAG
    Threaded            No
    Tag                 tail.0
    Mem_Buf_Limit       9.5M
    Path                /var/log/file.log
    Parser              json-test
    DB                  /var/log/flb_kube.db
    Buffer_Chunk_Size   8k
    Buffer_Max_Size     32k


[OUTPUT] Instance
    Name                es.0 (es, mask_id=1)
    Match               *
    TLS Active          No
    Retry Limit         no limit
    Host.TCP_Port       80
    Host.Name           elastic.host
    Logstash_Format     On
    Logstash_Prefix     dev-logs
    Index               dev-logs
    Time_Key            _@timestamp

[captainkerk]

Did you find a fix for this?

[hdiass]

@captainkerk not so far..

[captainkerk]

Ok, I'm experiencing something similar. I'm still debugging, I'll let you know if I figure anything out.

My fallback is to ditch this lightweight agent, and go back to the full fluentd agent (which doesnt have this problem).

[hdiass]

Well for me it's not a solution as in a container env i need everything as lightweight as possible, and this is not a major blocker for me.

[edsiper]

hello everyone, my apologizes for the delay on this.

@hdiass would you please provide the specific Docker log file that contains the problematic messages ?

side question, are you able to reproduce the problem with Fluent Bit v0.12.11 ?

[hdiass]

Hello,
I can't provide the entire docker log, but in the first post you can see exactly that on the application log (where fluent is tailing from) there is only "\n"in the message field(beggining and end) , and in the elasticsearch in the message field for the same log there is "\n" with one more backslash than what it should have also in the beggining and in the end of the message, btw this also happens if there is any "\n" in the middle of the message. And has there is not any app between fluent-bit and our Elasticsearch we can assum the issue is on the fluent-bit processing.
Regarding the fluent version, i'm now on the latest and same issue happens.

Thanks,

[peelandsee]

hi!

i'm experiencing the same issue using fluent/fluent-bit:0.12.11 on a 1.9 k8s cluster.

example log line from kubectl logs:
10.32.0.1 - - [18/Jan/2018:16:13:42 +0000] "GET /login/ HTTP/1.1" 200 1259 "-" "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36"

same line on elasticsearch:

{
  "_index": "logstash-2018.01.18",
  "_type": "flb_type",
  "_id": "AWEKDCLo-e7v1YXKY33t",
  "_score": null,
  "_source": {
    "@timestamp": "2018-01-18T16:13:42.203Z",
    "log": "10.32.0.1 - - [18/Jan/2018:16:13:42 +0000] \\\"GET /login/ HTTP/1.1\\\" 200 1259 \\\"-\\\" \\\"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_11_6) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36\\\"\\n",
    "stream": "stdout",
    "time": "2018-01-18T16:13:42.203127351Z",
    "kubernetes": {
      "pod_name": "insight-nginx-7f59b9c9cb-bddm6",
      "namespace_name": "insight-staging",
      "pod_id": "81e9f86e-fa11-11e7-bb88-005056970681",
      "labels": {
        "app": "insight",
        "deployment": "app",
        "pod-template-hash": "3915657576",
        "process": "nginx",
        "tier": "core"
      },
      "host": "shark-kube-node2",
      "container_name": "insight-core-nginx",
      "docker_id": "d2c21d5ffc702b397f843f5edd0d292f2ae8169eb8404f24fbc407c748aab21f"
    }
  }
}

here the full k8s fluent-bit yaml config

apiVersion: v1
kind: Namespace
metadata:
  name: logging

---

apiVersion: v1
kind: ServiceAccount
metadata:
  name: fluent-bit
  namespace: logging

---

apiVersion: rbac.authorization.k8s.io/v1beta1
kind: ClusterRole
metadata:
  name: fluent-bit-read
rules:
- apiGroups: [""]
  resources:
  - namespaces
  - pods
  verbs: ["get", "list", "watch"]

---

apiVersion: rbac.authorization.k8s.io/v1beta1
kind: ClusterRoleBinding
metadata:
  name: fluent-bit-read
roleRef:
  apiGroup: rbac.authorization.k8s.io
  kind: ClusterRole
  name: fluent-bit-read
subjects:
- kind: ServiceAccount
  name: fluent-bit
  namespace: logging

---

apiVersion: v1
kind: ConfigMap
metadata:
  name: fluent-bit-config
  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 input-kubernetes.conf
    @INCLUDE filter-kubernetes.conf
    @INCLUDE output-elasticsearch.conf

  input-kubernetes.conf: |
    [INPUT]
        Name              tail
        Tag               kube.*
        Path              /var/log/containers/*.log
        Parser            docker
        DB                /var/log/flb_kube.db
        Mem_Buf_Limit     5MB
        Skip_Long_Lines   On
        Refresh_Interval  10

  filter-kubernetes.conf: |
    [FILTER]
        Name           kubernetes
        Match          kube.*
        Kube_URL       https://kubernetes.default.svc:443
        Merge_JSON_Log On

  output-elasticsearch.conf: |
    [OUTPUT]
        Name            es
        Match           *
        Host            ${FLUENT_ELASTICSEARCH_HOST}
        Port            ${FLUENT_ELASTICSEARCH_PORT}
        Logstash_Format On
        Retry_Limit     False

  parsers.conf: |
    [PARSER]
        Name   apache
        Format regex
        Regex  ^(?<host>[^ ]*) [^ ]* (?<user>[^ ]*) \[(?<time>[^\]]*)\] "(?<method>\S+)(?: +(?<path>[^\"]*?)(?: +\S*)?)?" (?<code>[^ ]*) (?<size>[^ ]*)(?: "(?<referer>[^\"]*)" "(?<agent>[^\"]*)")?$
        Time_Key time
        Time_Format %d/%b/%Y:%H:%M:%S %z

    [PARSER]
        Name   apache2
        Format regex
        Regex  ^(?<host>[^ ]*) [^ ]* (?<user>[^ ]*) \[(?<time>[^\]]*)\] "(?<method>\S+)(?: +(?<path>[^ ]*) +\S*)?" (?<code>[^ ]*) (?<size>[^ ]*)(?: "(?<referer>[^\"]*)" "(?<agent>[^\"]*)")?$
        Time_Key time
        Time_Format %d/%b/%Y:%H:%M:%S %z

    [PARSER]
        Name   apache_error
        Format regex
        Regex  ^\[[^ ]* (?<time>[^\]]*)\] \[(?<level>[^\]]*)\](?: \[pid (?<pid>[^\]]*)\])?( \[client (?<client>[^\]]*)\])? (?<message>.*)$

    [PARSER]
        Name   nginx
        Format regex
        Regex ^(?<remote>[^ ]*) (?<host>[^ ]*) (?<user>[^ ]*) \[(?<time>[^\]]*)\] "(?<method>\S+)(?: +(?<path>[^\"]*?)(?: +\S*)?)?" (?<code>[^ ]*) (?<size>[^ ]*)(?: "(?<referer>[^\"]*)" "(?<agent>[^\"]*)")?$
        Time_Key time
        Time_Format %d/%b/%Y:%H:%M:%S %z

    [PARSER]
        Name   json-test
        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        syslog
        Format      regex
        Regex       ^\<(?<pri>[0-9]+)\>(?<time>[^ ]* {1,2}[^ ]* [^ ]*) (?<host>[^ ]*) (?<ident>[a-zA-Z0-9_\/\.\-]*)(?:\[(?<pid>[0-9]+)\])?(?:[^\:]*\:)? *(?<message>.*)$
        Time_Key    time
        Time_Format %b %d %H:%M:%S

---

apiVersion: extensions/v1beta1
kind: DaemonSet
metadata:
  name: fluent-bit
  namespace: logging
  labels:
    k8s-app: fluent-bit-logging
    version: v1
    kubernetes.io/cluster-service: "true"
spec:
  template:
    metadata:
      labels:
        k8s-app: fluent-bit-logging
        version: v1
        kubernetes.io/cluster-service: "true"
    spec:
      containers:
      - name: fluent-bit
        image: fluent/fluent-bit:0.12.11
        env:
        - name: FLUENT_ELASTICSEARCH_HOST
          value: "XXXXXXXXX"
        - name: FLUENT_ELASTICSEARCH_PORT
          value: "9200"
        volumeMounts:
        - name: varlog
          mountPath: /var/log
        - name: varlibdockercontainers
          mountPath: /var/lib/docker/containers
          readOnly: true
        - name: fluent-bit-config
          mountPath: /fluent-bit/etc/
      terminationGracePeriodSeconds: 10
      volumes:
      - name: varlog
        hostPath:
          path: /var/log
      - name: varlibdockercontainers
        hostPath:
          path: /var/lib/docker/containers
      - name: fluent-bit-config
        configMap:
          name: fluent-bit-config
      serviceAccountName: fluent-bit
      tolerations:
      - key: node-role.kubernetes.io/master
        operator: Exists
        effect: NoSchedule

fluent-bit logs some of this sometimes:

[2018/01/18 16:12:13] [ warn] [filter_kube] could not pack merged json
[2018/01/18 16:15:59] [ warn] [filter_kube] could not pack merged json

i'm available to provide more information if necessary :)

[edsiper]

In order to identify on which part of Fluent Bit the problem is happening I need to get a Docker log file. kubectl logs process the JSON map of Docker log engine, it's better to get the real source.

The log file should have the name containing "d2c21d5ffc702b397f843f5edd0d292f2ae8169eb8404f24fbc407c748aab21f" (docker id)

[peelandsee]

hi @edsiper , thanks for your interest!

I attach a docker log file and paste how some lines appear on kibana.

docker log file:
insight-nginx-7f59b9c9cb-bddm6_insight-staging_insight-core-nginx-f4cd342bda99fdee3e0af2a03bc2070343cf5d7577e106fc04b58b5cf4f4d3fa.log

first log line from kibana:

{
  "_index": "logstash-2018.01.19",
  "_type": "flb_type",
  "_id": "AWENsBEw-e7v1YXK5Szq",
  "_score": null,
  "_source": {
    "@timestamp": "2018-01-19T09:11:37.63Z",
    "log": "10.32.0.1 - - [19/Jan/2018:09:11:37 +0000] \\\"GET /dashboard HTTP/1.1\\\" 302 432 \\\"-\\\" \\\"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36\\\"\\n",
    "stream": "stdout",
    "time": "2018-01-19T09:11:37.063525473Z",
    "kubernetes": {
      "pod_name": "insight-nginx-7f59b9c9cb-bddm6",
      "namespace_name": "insight-staging",
      "pod_id": "81e9f86e-fa11-11e7-bb88-005056970681",
      "labels": {
        "app": "insight",
        "deployment": "app",
        "pod-template-hash": "3915657576",
        "process": "nginx",
        "tier": "core"
      },
      "host": "shark-kube-node2",
      "container_name": "insight-core-nginx",
      "docker_id": "f4cd342bda99fdee3e0af2a03bc2070343cf5d7577e106fc04b58b5cf4f4d3fa"
    }
  }
}

second log line from kibana:

{
  "_index": "logstash-2018.01.19",
  "_type": "flb_type",
  "_id": "AWENsBEw-e7v1YXK5Szr",
  "_score": null,
  "_source": {
    "@timestamp": "2018-01-19T09:11:37.150Z",
    "log": "10.32.0.1 - - [19/Jan/2018:09:11:37 +0000] \\\"GET /login HTTP/1.1\\\" 301 436 \\\"-\\\" \\\"Mozilla/5.0 (X11; Linux x86_64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/63.0.3239.132 Safari/537.36\\\"\\n",
    "stream": "stdout",
    "time": "2018-01-19T09:11:37.150930054Z",
    "kubernetes": {
      "pod_name": "insight-nginx-7f59b9c9cb-bddm6",
      "namespace_name": "insight-staging",
      "pod_id": "81e9f86e-fa11-11e7-bb88-005056970681",
      "labels": {
        "app": "insight",
        "deployment": "app",
        "pod-template-hash": "3915657576",
        "process": "nginx",
        "tier": "core"
      },
      "host": "shark-kube-node2",
      "container_name": "insight-core-nginx",
      "docker_id": "f4cd342bda99fdee3e0af2a03bc2070343cf5d7577e106fc04b58b5cf4f4d3fa"
    }
  }
}

hope it's enough for debugging!

[hdiass]

Hello @edsiper,

I'm approaching you on slack to send the logs privately.

Thanks,

[edsiper]

thanks everyone for reporting the problems associated to escaping.

@hdiass provided me some information that was helpful to identify the issue associated to one posted at the beginning:

Issue

When an application generate a formal JSON log, likely special ASCII characters like '\n' (note: ASCII character, one byte) is converted to JSON string format which is "\n" (two bytes: \ and n). So our JSON parser applied to the records is not converting back the string "\n" to the ASCII byte '\n', for hence when an output plugin is going to convert to JSON output, it will re-escape the original "\n" to \\n".

Ideas

I think the solution to the problem is to extend our JSON parser where we could instruct to "decode" specific fields of the record; ideally this must be optional because as you know text parsing is expensive and I would like to avoid performance penalties for scenarios where logs with special characters does not exists.

A parser could look like this:

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

As an example consider the following original record from a file:

{"@timestamp":"2018-01-19T11:38:06.225+00:00",
 "@version":1,
 "message":"\nFailed events housekeeping completed in 1ms\n",
}

in the example above it contains a stringify text in message key. Actually the \n is kept as it is and if it hits an output plugin that re-format to JSON (like elasticsearch), it will escape that character.

I've also found that if a JSON string comes with encoded UTF-8, these are not decoded and kept as they come, e.g:

{"log":"JP characters \u6628\u591c\u306e\u30b3\u30f3\u30b5"}

after processing to stdout we get:

[1516385197.832135298, {"log"=>"JP characters \u6628\u591c\u306e\u30b3\u30f3\u30b5"}]

we expected the Japanese characters 昨夜のコンサ

so a "decoding" feature at Parser level is required, either for special characters like \n and others in UTF-8.

[peelandsee]

hi @edsiper thanks for the investigation!

in the meanwhile,
do you think it is possibile to use a different docker logging driver and k8s daemonset input configuration to avoid the decoding issue?
do you have any suggestion to proceed in that way?

thanks in advance,