Nested JSON Message in Kubernetes Logs to Elasticsearch

[marvin...@ecclesia-gruppe.de]

Hey, 

I am sorry, that this question appears again, but the recently asked questions regarding this topic are just not enough to make it work.

We are running our applications in a kubernetes cluster, in the near future, the applications should log using the logstash logback encoder, which just acts as a tcp json sender. 

Normal logging is already working, using the follow configuration:

input-kubernetes.conf: |

    [INPUT]

        Name              tail

        Tag               kube.*

        Path              /var/log/containers/*application-log*.log

        Parser            ecc_parser

        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.cluster.local:443

        Merge_Log           On

        K8S-Logging.Parser  On

    [FILTER]

        Name record_modifier

        Match *

        Remove_key @timestamp

  output-elasticsearch.conf: |

    [OUTPUT]

        Name            es

        Match           *

        Host            ${FLUENT_ELASTICSEARCH_HOST}

        Port            ${FLUENT_ELASTICSEARCH_PORT}

        Logstash_Format On

        Logstash_Prefix fluentbit

        Retry_Limit     False

  parsers.conf: |

    [PARSER]

        Name        ecc_parser

        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_utf8   log    do_next

        Decode_Field_As   json       message

There are some special log events, which wont get parsed. This means, they will be shown in Kibana (meaning elasticesearch), but the fields eg message wont be filled. They are just empty, all the information are contained in the field "log".

The first problem I was facing appeared, when there is a json message in the field "message". I solved this by using Decode_Field_As as above. Now the json message in the message field is not parsed, but instead simply used as the messages value. 

That is okay, I think. Splitting those messages into many fields is propably not the best appraoch considering the fact, that merely 1% of the current messages has those fields.

One problem remains: Some message wont get parsed into the message field, although the dont contain any json:

Output of the application:

{"@timestamp":"2019-02-14T11:09:02.405+01:00","@version":"1","message":"parseNext s=START HeapByteBuffer@41176749[p=0,l=0,c=8192,r=0]={<<<>>>HTTP/1.1 200 OK\\r\\n...\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00}","logger_name":"org.eclipse.jetty.http.HttpParser","thread_name":"qtp1005996827-387","level":"DEBUG","level_value":10000}

Output of the kubernetes log file:

{"log":"{\"@timestamp\":\"2019-02-14T11:09:02.405+01:00\",\"@version\":\"1\",\"m
essage\":\"parseNext s=START HeapByteBuffer@41176749[p=0,l=0,c=8192,r=0]={\u003c
\u003c\u003c\u003e\u003e\u003eHTTP/1.1 200 OK\\\\r\\\\n...\\\\x00\\\\x00\\\\x00\
\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\
x00}\",\"logger_name\":\"org.eclipse.jetty.http.HttpParser\",\"thread_name\":\"q
tp1005996827-387\",\"level\":\"DEBUG\",\"level_value\":10000}\n","stream":"stdou
t","time":"2019-02-14T10:09:02.40695597Z"}

In this case, only the log field is shown in Kibana, the content of the log is not getting parsed. Why is that?

I would be fine, if the content of the message field is not parsed at all. Meaning no matter the content, There will always be X Fields per Content, while X wont ever change. 

Is there a way to configure fluent bit to not parse the content of the message field?

Thank you in advance.

[Don Bowman]

maybe you can post the raw text of a few lines of the output of your app showing both cases? I would do this from 'kubectl logs ...' so I can see what the input to fluent-bit would be (or even better, a few lines from the  /var/log/containers/*application-log*.log

generally your tools are:

'grep' filter if you want to do somthing to include/exclude lines matching

'nest'/'modify' to add/move/change json fields

'parser' (json, regex) to extract from the single field to make multiple fields

if you log is json already, this is the simplest, normally you just use an json parser w/o the Decode_Field_As.

--
You received this message because you are subscribed to the Google Groups "Fluent-Bit" group.
To unsubscribe from this group and stop receiving emails from it, send an email to fluent-bit+...@googlegroups.com.
To post to this group, send email to fluen...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/fluent-bit/58b77554-a21d-47b4-9fbb-f36517b41bfd%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Marvin Berger]

Oh my, I never tried to just delete the Decode_Field_As property completly. Now every event is parsed correctly. Thank you so much.

Just in case there is any demand in the future, to parse json fields, although merely a few out of 100 events contain those, this is a typical log entry:

{"log":"{\"@timestamp\":\"2019-02-14T12:55:45.068+01:00\",\"@version\":\"1\",\"message\":\"{\\\"id\\\":7397,\\\"kontaktdaten\\\":{\\\"telefon\\\":\\\"+49 (0) \\\",\\\"fax\\\":\\\"+49 (0) \\\",\\\"mobil\\\":null,\\\"email\\\":\\\"te...@test.de\\\"},\\\"kostenstelle\\\":\\\"21100\\\",\\\"avatar\\\":{\\\"href\\\":\\\"/sys/v1/mitarbeiter/id/7397/avatar\\\"},\\\"vertreterregeln\\\":{\\\"href\\\":\\\"/sys/v1/vertreterr?97\\\"},\\\"funktionen\\\":{\\\"href\\\":\\\"/sys/v1/funktion/mitarbeiterId?mitarbeiterId=7397\\\"},\\\"abteilungen\\\":{\\\"href\\\":\\\"97\\\"},\\\"rollen\\\":{\\\"href\\\":\\\"397\\\"},\\\"gruppen\\\":{\\\"href\\\":\\\"erId?mitarbeiterId=7397\\\"},\\\"unterschriften\\\":{\\\"href\\\":\\\"/sys/v17\\\"},\\\"profil\\\":\\\"muster97\\\",\\\"pknr\\\":\\\"r97\\\",\\\"personalNummer\\\":70,\\\"auszubildender\\\":false,\\\"technisch\\\":false,\\\"anrede\\\":\\\"Herr\\\",\\\"titel\\\":null,\\\"vorname\\\":\\\"Max\\\",\\\"nachname\\\":\\\"Mustermann\\\",\\\"name\\\":\\\"Max Mustermann\\\",\\\"nachnameVorname\\\":\\\"Max, Mustermann\\\",\\\"nameMitAnrede\\\":\\\"\\\",\\\"nachnameMitAnrede\\\":\\\"\\\",\\\"geschlecht\\\":\\\"MAENNLICH\\\",\\\"firma\\\":{\\\"href\\\":\\\"/sys/v1/firma\\\"},\\\"lohnFirma\\\":\\\"040\\\",\\\"niederlassung\\\":{\\\"href\\\":\\\"/sys/v1/mitarbeiter\\\"},\\\"abteilung\\\":{\\\"href\\\":\\\"/sys\\\"},\\\"strasse\\\":\\\"Chausse 4\\\",\\\"plz\\\":\\\"1123134\\\",\\\"ort\\\":\\\"Berlin\\\",\\\"land\\\":null,\\\"geburtsdatum\\\":\\\"1994-05-24\\\",\\\"gueltigVon\\\":\\\"2018-12-31T23:00:00Z\\\",\\\"gueltigBis\\\":null,\\\"gueltig\\\":true,\\\"geloescht\\\":false}\",\"logger_name\":\"de.firma.api.client.internal.InternalClient\",\"thread_name\":\"qtp1638332837-16\",\"level\":\"DEBUG\",\"level_value\":10000}\n","stream":"stdout","time":"2019-02-14T11:55:45.070216985Z"}

{"log":"{\"@timestamp\":\"2019-02-14T12:55:45.068+01:00\",\"@version\":\"1\",\"message\":\"\u003c-- END HTTP (1380-byte body)\",\"logger_name\":\"de.firma.api.client.internal.InternalClient\",\"thread_name\":\"qtp1638332837-16\",\"level\":\"DEBUG\",\"level_value\":10000}\n","stream":"stdout","time":"2019-02-14T11:55:45.070234119Z"}

{"log":"{\"@timestamp\":\"2019-02-14T12:55:45.330+01:00\",\"@version\":\"1\",\"message\":\"--\u003e GET https://api.ads.firma/sys/v1/rolle/mitarbeiterId?mitarbeiterId=7397\u0026limit=2147483647 http/1.1\",\"logger_name\":\"de.firma.api.client.internal.InternalClient\",\"thread_name\":\"qtp1638332837-16\",\"level\":\"INFO\",\"level_value\":20000}\n","stream":"stdout","time":"2019-02-14T11:55:45.330328663Z"}

{"log":"{\"@timestamp\":\"2019-02-14T12:55:45.330+01:00\",\"@version\":\"1\",\"message\":\"Authorization: Bearer eyJraWQiOiJiJ2aXMiLCJpYXQiOjE1NTAxNDUzNTcsImV4cCI6MTU1MDIzMTc1Nywic2NvcGUiOiJzZWFyY2ggc2VydmljZS1idnMgc2VydmljZS1zeXMiLCJzdWIiOiJiZXJnZXc1OSIsIm5ld19zdWIiOiI3Mzk3IiwibmV3X25ld19zdWIiOiJtaXRhcmJlaXRlclxcNzM5NyJ9.l_UNIyK-UbjZQpWyA10Yj8gJav-VQ7b3wCH5VqXrr6GnRziNaPYTGebzQMUlQfkxdqsyIzN5xOdJ5_VXcg6vNw\",\"logger_name\":\"de.firma.api.client.internal.InternalClient\",\"thread_name\":\"qtp1638332837-16\",\"level\":\"INFO\",\"level_value\":20000}\n","stream":"stdout","time":"2019-02-14T11:55:45.331083475Z"}

{"log":"{\"@timestamp\":\"2019-02-14T12:55:45.331+01:00\",\"@version\":\"1\",\"message\":\"--\u003e END GET\",\"logger_name\":\"de.firma.api.client.internal.InternalClient\",\"thread_name\":\"qtp1638332837-16\",\"level\":\"INFO\",\"level_value\":20000}\n","stream":"stdout","time":"2019-02-14T11:55:45.331338815Z"}

{"log":"{\"@timestamp\":\"2019-02-14T12:55:45.343+01:00\",\"@version\":\"1\",\"message\":\"\u003c-- 200 OK https://api.ads.firma/sys/v1/rolle/mitarbeiterId?mitarbeiterId=7397\u0026limit=2147483647 (took 12 ms )\",\"logger_name\":\"de.firma.api.client.internal.InternalClient\",\"thread_name\":\"qtp1638332837-16\",\"level\":\"INFO\",\"level_value\":20000}\n","stream":"stdout","time":"2019-02-14T11:55:45.344714025Z"}

{"log":"{\"@timestamp\":\"2019-02-14T12:55:45.344+01:00\",\"@version\":\"1\",\"message\":\"Date: Thu, 14 Feb 2019 11:55:58 GMT\",\"logger_name\":\"de.firma.api.client.internal.InternalClient\",\"thread_name\":\"qtp1638332837-16\",\"level\":\"INFO\",\"level_value\":20000}\n","stream":"stdout","time":"2019-02-14T11:55:45.344744896Z"}

{"log":"{\"@timestamp\":\"2019-02-14T12:55:45.839+01:00\",\"@version\":\"1\",\"message\":\"parseNext s=START HeapByteBuffer@64b71412[p=0,l=0,c=8192,r=0]={\u003c\u003c\u003c\u003e\u003e\u003eGET /vis/ HTTP/1....\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00\\\\x00}\",\"logger_name\":\"org.eclipse.jetty.http.HttpParser\",\"thread_name\":\"qtp1638332837-17\",\"level\":\"DEBUG\",\"level_value\":10000}\n","stream":"stdout","time":"2019-02-14T11:55:45.843998532Z"}