Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Logs with json and escaped " are not parsed #615

Closed
rgomesf opened this issue Jun 5, 2018 · 32 comments · Fixed by #769
Closed

Logs with json and escaped " are not parsed #615

rgomesf opened this issue Jun 5, 2018 · 32 comments · Fixed by #769
Assignees

Comments

@rgomesf
Copy link

rgomesf commented Jun 5, 2018

Hi.

I'm using fluent-bit 13.2 daemonset with the following configuration:

[SERVICE]
    Flush          1
    Daemon         Off
    Log_Level      info
    Parsers_File   parsers.conf

[INPUT]
    Name              tail
    Tag               kube.*
    Path              /var/log/containers/*.log
    Exclude_Path      ${FLUENT_ELASTICSEARCH_EXCLUDE}
    Parser            docker
    DB                /var/log/${FLUENT_INTERNAL_DB}
    Mem_Buf_Limit     20MB
    Buffer_Chunk_Size 32k
    Buffer_Max_Size   128k

[FILTER]
    Name           kubernetes
    Match          kube.*
    Kube_URL       https://kubernetes.default.svc:443
    Merge_Log On

[OUTPUT]
    Name   es
    Match  *
    Host   ${FLUENT_ELASTICSEARCH_HOST}
    Port   ${FLUENT_ELASTICSEARCH_PORT}
    Logstash_DateFormat ${FLUENT_ELASTICSEARCH_INDEX_DATE_FORMAT}
    Logstash_Format On
    Retry_Limit False
    Logstash_Prefix ${FLUENT_ELASTICSEARCH_INDEX}
    Index ${FLUENT_ELASTICSEARCH_INDEX}
    Time_Key _@timestamp
    Generate_ID On

In logs with " like this one, fluent-bit doesn't parse the log.

{"@timestamp":"2018-06-04T16:40:04.732+00:00","@version":1,"message":"Error processing (flow.ProcessErrorException: Failed to aggregate fields in Task from event -> Dimension HOME_NETWORK_ID has an empty value) event ->EventImpl [_internalMap=\nRD_ACCESS_POINT_NAME_NI (String) \"abc \"\nRD_CALL_EVENTS_COUNT (Long) 5\nRD_CALL_EVENT_DURATION (Long) 1084\nRD_CALL_EVENT_START_TIMESTAMP (String) \"20170101180000\"\nRD_CAUSE_FOR_TERMINATION (Long) 0\nRD_CHARGING_ID (Long) 00000000\nRD_DATA_VOLUME_INCOMING (Long) 0\nRD_DATA_VOLUME_OUTGOING (Long) 0\nRD_EVENT_TYPE (String) \"GPRS\"\nRD_EVENT_UTC_TIME_OFFSET (String) \"+0100\"\nRD_GGSN_ADDRESS (String) \"0.0.0.0\"\nRD_IMEI (String) \"9999999999999999\"\nRD_IMSI (String) \"9999999999999999\"\nRD_SGSN_ADDRESS (String) \"0.0.0.0\"\n, eventType=REGULAR, inputEntry=ControlId [3 - NXXXXXXXXXXC0010000] at position 5 5]","logger_name":"loading.services.LoadingProcessManager.[LoadingProcessManager]","thread_name":"LP(286)-P(0)-E(0)","level":"WARN","level_value":30000,"code":"G1000","instance":"product","layer":"backend"}

It seems related to "abc " inside the field message value. I was using the docker parser. Also tried changing the parser to:

[PARSER]
    Name         docker
    Format       json
    Time_Key     time
    Time_Format  %Y-%m-%dT%H:%M:%S.%L
    Time_Keep    On
    # Command      |  Decoder | Field | Optional Action
    # =============|==================|=================
    Decode_Field_As   json    log    try_next
    Decode_Field_As   escaped    log

but the result is the same.

I was using version 11 and it was working ok with this kind of logs.

@randude
Copy link

randude commented Jun 5, 2018

I'm having the same issue at the moment. If anyone can assist, it'd be great.

@rgomesf
Copy link
Author

rgomesf commented Jun 5, 2018

I've been trying with all the Decode_Field_As combinations I can imagine without success. I need to find a way to keep the " escaped inside the message field

@edsiper
Copy link
Member

edsiper commented Jun 7, 2018

@rgomesf would you please paste (in formatted mode) your docker parser content that comes from your configmap ?

@edsiper
Copy link
Member

edsiper commented Jun 7, 2018

Found the problem in your config, in your docker parser you are processing a key named log, but in your log example the content is inside the key called message. Just put something like this in your docker parser:

[PARSER]
    Name         docker
    Format       json
    Time_Key     time
    Time_Format  %Y-%m-%dT%H:%M:%S.%L
    Time_Keep    On
    # Command      |  Decoder | Field | Optional Action
    # =============|==================|=================
    Decode_Field_As   escaped    message

@rgomesf
Copy link
Author

rgomesf commented Jun 7, 2018

Hi @edsiper .

I already tried with that config and it also didn't work

I found two outcomes:

Decode_Field_As escaped json
The log isn't parsed as json when the message field has " in the value.
It seems that it removes the escaping from the original " and then the json is not valid.

Decode_Field_As escaped message
The log is parsed as json but the " are represented stored as \", and shown as " in kibana.

@edsiper
Copy link
Member

edsiper commented Jun 7, 2018

1 Decode_Field_As escaped json

that means: unescape field named json

2 Decode_Field_As escaped message

that means: unescape field named message

also there is something required to be clarified:

if your original message contains a byte ", by JSON spec it needs to be escaped so it becomes \". So if your message was packed inside a JSON map likely by docker you will get:

test "message"

in JSON becomes

{"log": "test \"message\""}

the decoders in Fluent Bit allows to avoid double escaping when processing the text messages, but when sending the same message to elasticsearch or kibana by JSON spec it needs to be escaped, otherwise it's an invalid JSON message and will not be accepted.

For short: if you see double escaped in elasticsearch/kibana means something needs to be fixed, otherwise single escaped is by spec.

@rgomesf
Copy link
Author

rgomesf commented Jun 7, 2018

The exact same logs are parser correctly with fluentbit 0.11.11

I see \\\" in kibana JSON view

@chlunde
Copy link
Contributor

chlunde commented Jun 12, 2018

When using in_tail, docker json-logs, kubernetes-filter and outputing to splunk, and applications logging JSON to stdout, it seems we got everything right by not having any Decode_Field_As at all in the parsers config.

@rgomesf
Copy link
Author

rgomesf commented Jun 13, 2018

@edsiper is there anything else I can provide you to help find a fix for this? Right now I reverted to 0.11.11 version.

@marckamerbeek
Copy link

Dealing with the same urgent problem here. Would be glad to help testing or whatever

@kristofferahl
Copy link

We're having the same issue...

If a container writes the following to stdout, it is parsed correctly by Elasticsearch.

{"timestamp":"2016-12-01T02:23:12.236543Z","level":"info","message":"Hello busybox"}

However, if the same log line contains \" , it does not get indexed properly in Elasticsearch.

{"timestamp":"2016-12-01T02:23:12.236543Z","level":"info","message":"Hello \"busybox\""}

We're using the docker parser with the log field escaped.

[PARSER]
    Name        docker
    Format      json
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L
    Time_Keep   Off
    # Command      |  Decoder | Field | Optional Action
    # =============|==================|=================
    Decode_Field_As   escaped    log

In essence:

  • Our log field contains escaped JSON.
  • The JSON string in the log field occasionally contains a property with escaped quotes in it's string value.

I would expect the property containing the escaped quotes to be left as is but it seems that the backslashes are removed when the log field is escaped resulting in invalid JSON.

{"timestamp":"2016-12-01T02:23:12.236543Z","level":"info","message":"Hello "busybox""}

What's the proper way of configuring fluent-bit to handle this? We're using fluent-bit 13.2.

@therealdwright
Copy link

therealdwright commented Jul 18, 2018

I'm also facing a similar challenge and would like to know the correct approach. Steps to reproduce as follows. Run a container that outputs the following:

{"Message": "Hello from Kubernetes!"}

This can be achieved by performing the command:

kubectl run hi --quiet --restart=Never --image=alpine -- sh -c 'sleep 3; echo "{\"Message\": \"Hello from Kubernetes!\"}"'

I then have a docker kubernetes input setup as follows:

[INPUT]
    Name              tail
    Tag               kube.*
    Path              /var/log/containers/*.log
    Parser            docker
    DB                /var/log/flb_kube.db

Which is parsed by the docker parser configured as:

[PARSER]
    Name        docker
    Format      json
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L
    Time_Keep   On
    # Command      |  Decoder | Field   | Optional Action
    # =============|==========|=========|=================
    Decode_Field_As   escaped    log

The JSON payload is then sent to logz.io as:

{
  "_index": "logz_io_index",
  "_type": "http-bulk",
  "_id": "foo",
  "_version": 1,
  "_score": null,
  "_source": {
    "kubernetes": {
      "container_name": "hi",
      "host": "1.2.3.4",
      "annotations": {
        "kubernetes.io/limit-ranger": "LimitRanger plugin set: cpu request for container hi"
      },
      "docker_id": "9d5c453d097cfb63f3ca237f0c9d8938147674c9b7bf8956a8b930f476b34e51",
      "pod_id": "d7e18544-8a6e-11e8-b430-0a948d0850cc",
      "pod_name": "hi",
      "namespace_name": "default",
      "labels": {
        "run": "hi"
      }
    },
    "@timestamp": "2018-07-18T09:45:28.000+00:00",
    "log": "{\"Message\": \"Hello from Kubernetes!\"}\n",
    "stream": "stdout",
    "@log_name": "kube.var.log.containers.hi_default_hi-9d5c453d097cfb63f3ca237f0c9d8938147674c9b7bf8956a8b930f476b34e51.log",
    "time": "2018-07-18T09:45:28.626181368Z",
    "type": "http-bulk",
    "tags": [
      "_logz_http_bulk_json_8070"
    ]
  },
  "fields": {
    "@timestamp": [
      1531907128000
    ]
  },
  "sort": [
    1531907128000
  ]
}

This causes the end result of the field displaying in elasticsearch/logz.io being an incorrectly indexed JSON field of:

{"Message": "Hello from Kubernetes!"}

I have spent many days pulling my hair out trying to work this out, I'm wondering if someone can suggest the right configuration to have these JSON messages correctly indexed in elasticsearch?

@meggarr
Copy link
Contributor

meggarr commented Jul 23, 2018

I have the same issue here, if UTF8 chars are inside JSON which is the log field, it cannot be parsed correctly. I think the dilemma here is that if it escape UTF8 firstly, it cannot parse JSON correctly, if it parse JSON firstly, it cannot parse escaped utf8 inside json. 😒 Any suggestions? Is it a bug? I was thinking if decode as json in the first, and then escape utf8 would work, but it doesn't.

@therealdwright
Copy link

@meggarr your assessment is exactly what I'm seeing and it appears to be a limitation per the fluent-bit docs. I am having the same problem of an escaped json in the log field, which I can't parse as JSON as it's escaped, and when I use the do_next after parsing the JSON object is not parsed. I have a ticket in #691 which is a specific representation of my use case.

I've included below an excerpt from the docs that suggest that you can only use multiple decoders on a field that is unstructured raw text.

Perhaps this is a feature request and not a ug?

Optional Actions

By default if a decoder fails to decode the field or want to try a next decoder, is possible to define an optional action. Available actions are:

Name Description
try_next if the decoder failed, apply the next Decoder in the list for the same field.
do_next if the decoder succeeded or failed, apply the next Decoder in the list for the same field.

Note that actions are affected by some restrictions:

on Decode_Field_As, if succeeded, another decoder of the same type in the same field can be applied only if the data continue being a unstructed message (raw text).
on Decode_Field, if succeeded, can only be applied once for the same field. By nature Decode_Field aims to decode a structured message.

@meggarr
Copy link
Contributor

meggarr commented Jul 24, 2018

Maybe this is a bug, what I am thinking is that parsing it as JSON should only care double quotes, but apparently, it transforms UTF8 chars as well, e.g. in my case, after JSON decoding, \u003e is changed to u003e.

@edsiper

@meggarr
Copy link
Contributor

meggarr commented Jul 25, 2018

After several minutes investigation in the code I think the UTF8 decoding part is good except that it reads \\n as a JSON escaped char which results the decoded string cannot be encoded as JSON. A sample log is like,

{"log":"{\"timeMillis\":1532502611649,\"message\":\"Response \u003eGET /abc/xyz, 69ms, \u003e200 OK, \u003e{\\n  \\\"_id\\\" : \\\"50-CCBE59-261712046121\\\",\\n  \\\"manufacturer\\\" : \\\"BigBang\\\",\\n}\\n\",\"threadId\":64,\"threadPriority\":5}\r\n","stream":"stdout","time":"2018-07-25T07:10:11.650537766Z"}

The UTF8 will read \\n as new line, but it is really not a new line yet at the time to do UTF8 decoding.

meggarr added a commit to meggarr/fluent-bit that referenced this issue Jul 25, 2018
In the UTF-8 decoder, it tries to read escaped char for general
purpose. Escaping a new-line is valid in JSON encoding, if it
lines a UTF-8 decoder and then a JSON decoder, the JSON decoder
will fail, as the escaped new-line is treated as a real newline
in the first UTF-8 decoder.

This fixes the issue in fluent#615

Signed-off-by: Richard Meng <[email protected]>
edsiper pushed a commit that referenced this issue Aug 16, 2018
In the UTF-8 decoder, it tries to read escaped char for general
purpose. Escaping a new-line is valid in JSON encoding, if it
lines a UTF-8 decoder and then a JSON decoder, the JSON decoder
will fail, as the escaped new-line is treated as a real newline
in the first UTF-8 decoder.

This fixes the issue in #615

Signed-off-by: Richard Meng <[email protected]>
edsiper pushed a commit that referenced this issue Aug 16, 2018
@HarishHothi
Copy link

Hi @edsiper,
I am trying with the below log message {"Message":"Hi Does double quotes \" work\"","severity":"info"}.
In my kibana I see the below result
image

I can not see Message and severity key as a indexable in elastic search.
My parser config is below, using docker image as fluent/fluent-bit:0.14.1 and kubernetes version 1.11.1
Does this behavior is fixed? Am I doing some wrong configuration?
`[PARSER]

    Name        docker
    Format      json
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L
    Time_Keep   On
    # Command      |  Decoder | Field | Optional Action
    # =============|==================|=================
    Decode_Field_As   escaped    log     try_next
    Decode_Field_As   json       log 

`

@edsiper
Copy link
Member

edsiper commented Aug 31, 2018

@HarishHothi would you please share your full Fluent Bit configuration ? (and..are you running in Kubernetes?)

@HarishHothi
Copy link

Hi @edsiper Below is my full fluentbit configuration. Yes we are running fluentbit in on-premise kubernetes cluster.
https://github.com/HarishHothi/SpringTestRepoHarish/blob/master/fluentbit-configmap.yaml

@HarishHothi
Copy link

hi @edsiper is there any update?

@ese
Copy link
Contributor

ese commented Sep 16, 2018

I did a PR and build 0.14.2 with cherry-picked fix. Could you test if this work for you.
quay.io/sergioballesteros/fluentbit:0.14.2-pr769

@HarishHothi
Copy link

HarishHothi commented Sep 18, 2018

Hi @ese Still see the same problem. My sample log {"Message":"Hi Does double quotes \" work\"","severity":"info"} is still not indexable in kibana. I am using the same fluent bit configuration in on-premise kube cluster.
https://raw.githubusercontent.com/HarishHothi/SpringTestRepoHarish/master/fluentbit-configmap.yaml
I also forwarded the more details on your slack account.

@ese
Copy link
Contributor

ese commented Sep 18, 2018

@HarishHothi This is the config I am using:

  fluent-bit.conf: |
    [SERVICE]
        Flush        1
        Log_Level    info
        Daemon        off
        Parsers_File  parsers.conf
        HTTP_Server   On
        HTTP_Listen   0.0.0.0
        HTTP_Port     2020

    [INPUT]
        Name          tail
        Path          /var/log/containers/*.log
        Parser        docker
        Refresh_Interval 5
        ignore_older  6h
        Tag           kube.*
        Mem_Buf_Limit 10MB
        Skip_Long_Lines On

    [FILTER]
        Name   kubernetes
        Match  kube.*
        K8S-Logging.Parser On
        K8S-Logging.Exclude On
        Merge_Log On

    [OUTPUT]
        Name  es
        Match kube.*
        Host  ${FLUENT_ELASTICSEARCH_HOST}
        Port  ${FLUENT_ELASTICSEARCH_PORT}
        Logstash_Format On
        Logstash_Prefix containers

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

@meggarr
Copy link
Contributor

meggarr commented Sep 18, 2018

@HarishHothi The quote must be double back-slash escaped in the logs, otherwise, it will be treated as JSON tokens which is wrong,

E.g.

{
  "_index": "logs-2018.09.18",
  "_type": "flb_type",
  "_id": "ppHI62UBcPJcRNEQT6uo",
  "_version": 1,
  "_score": null,
  "_source": {
    "@timestamp": "2018-09-18T08:24:56.777Z",
    "message": "ABC Request >GET /xyz/123, data >{\"paramOne\":\"123456\"}",
    "log": "{\"timeMillis\":1537259096777,\"thread\":\"thread-1\",\"level\":\"DEBUG\",\"loggerName\":\"com.xyz.XyzHelper\",\"message\":\"ABC Request >GET /xyz/123, data >{\\\"paramOne\\\":\\\"123456\\\"}\",\"endOfBatch\":false,\"loggerFqcn\":\"io.vertx.core.logging.Logger\",\"contextMap\":{},\"threadId\":83,\"threadPriority\":5}\r",
    "stream": "stdout",
    "timeMillis": 1537259096777,
    "thread": "thread-1",
    "level": "DEBUG",
  ...
}

@gajus
Copy link

gajus commented Jan 7, 2019

Is this a related issue helm/charts#10424 ?

@Pluies
Copy link

Pluies commented Mar 19, 2019

For what it's worth, we ran into the same issue in our Kubernetes set up with the fluent-bit Helm chart using fluentbit 1.0.4 and ended up solving it with the following:

  • Create a new parser, basically as a copy of the docker parser
  • Change the parser to use:
    Decode_Field_As escaped_utf8 log
  • Delete the current index in Elasticsearch

@kiich
Copy link

kiich commented Apr 9, 2019

Just comment here as well as we were also facing same issue where " in the value field of our json formatted logs were not being parsed/correctly understood in our case by Splunk.
Our app log after it has been decoded by fluent-bit docker parser+decoder:

{"log":"{\"logName\":\"app-third_party\",\"timestamp\":\"1554804600355\",\"level\":\"INFO\",\"thread\":\"http-nio-8080-exec-5\",\"req.requestURI\":\"/xxx.do\",\"request_method\":\"GET\",\"message\":\"target=\\\"dsc-command-chx_datas
tax-readSession\\\" duration=42 result=SUCCESS \",\"context\":\"default\"}\n","stream":"stdout","time":"2019-04-09T14:25:00.103780996Z"}

When gone through the docker parser/decoder of fluent-bit with the following config:

[PARSER]
    Name        docker
    Format      json
    Time_Key    time
    Time_Format %Y-%m-%dT%H:%M:%S.%L
    Time_Keep   Off
    # Command      |  Decoder | Field | Optional Action
    # =============|==================|=================
    Decode_Field_As   escaped    log    do_next
    Decode_Field      json       log

Was not showing up as valid JSON on Splunk hence it could not extract these lovely JSON fields.

Once we changed the decoder to use escaped_utf8 instead of escaped, it all magically started to work and Splunk was able to extract and index all the JSON fields so a big thank you to @Pluies for the pointer!

@TarekAS
Copy link

TarekAS commented May 20, 2019

@Pluies we are having the same issues with fluent-bit on Helm (escaping "). Can you show us how you did it in values.yaml?
This is what I'm doing right now:

...
parsers:
  enabled: true
  json:
    - name: docker
      extraEntries: |-
        Time_Key    time
        Time_Format %Y-%m-%dT%H:%M:%S.%L
        Time_Keep   Off
        Decode_Field_As escaped_utf8 log do_next
        Decode_Field_As json log

@TarekAS
Copy link

TarekAS commented May 21, 2019

For those using Helm, I found this to be a working configuration in values.yaml:

input:
  tail:
    parser: dockerCustom

parsers:
  enabled: true
  json:
    - name: dockerCustom
      extraEntries: |-
       Time_Key    time
       Time_Format %Y-%m-%dT%H:%M:%S.%L
       Time_Keep   On
       Decode_Field_As escaped_utf8 log do_next
       Decode_Field_As json log

@kiich
Copy link

kiich commented May 30, 2019

I appreciate this is already closed issue and I have previously commented with workaround I used of using Decode_Field_As escaped_utf8 log do_next - BUT i have found this to then break other things in my log, mainly the multiline stack traces.

When using escaped_utf8, the new line \n in the log line seems to get decoded to \\n and hence just appears as that in Splunk, causing it NOT to display as multiline stack trace.

Anyone else seen this? Will raise a new issue anyways.

@edsiper
Copy link
Member

edsiper commented Jun 6, 2019

FYI: Please check the following comment on #1278 :

#1278 (comment)

@edsiper
Copy link
Member

edsiper commented Jun 14, 2019

Issue already fixed, ref: #1278 (comment)

arianvp added a commit to wireapp/wire-server-deploy that referenced this issue Sep 9, 2019
arianvp added a commit to wireapp/wire-server-deploy that referenced this issue Sep 23, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging a pull request may close this issue.