CRI parser outputs empty log lines

Ahmad-Faizan commented 1 year ago

Bug Report

Describe the bug

We are running Fluent bit on k8s and using the tail input plugin to stream CRI formatted logs to Graylog. While parsing stack trace on some pods, Fluent bit is also picking up the empty log lines that are a part of the stack trace.

To Reproduce

Example log message if applicable:

2023-01-17T16:55:48.241172896Z stderr F TCP/IP connections on port 5432?
2023-01-17T16:55:48.241176242Z stderr F 
2023-01-17T16:55:48.241179528Z stderr F The above exception was the direct cause of the following exception:

Steps to reproduce the problem: Run the above log lines through cri parser and output on stdout. Fluent-bit will output the empty lines too.

Expected behavior

The empty line should be discarded automatically by the cri parser as the Skip_Empty_Lines is enabled for tail input plugin.

Your Environment

Version used: Fluent bit v2.0.8

Configuration:


[SERVICE]
    Daemon Off
    Flush 1
    Log_Level info
    Parsers_File parsers.conf
    Parsers_File custom_parsers.conf
    HTTP_Server On
    HTTP_Listen 0.0.0.0
    HTTP_Port 2020
    Health_Check On

[INPUT]
    Name                      tail
    Tag                       kube.*
    Path                      /var/log/containers/*.log
    multiline.parser          cri
    DB                        /var/log/fluentbit.db
    DB.Sync                   Normal
    Rotate_Wait               30
    Mem_Buf_Limit             30MB
    Skip_Empty_Lines          On
    Refresh_Interval          10

[FILTER]
    Name                      kubernetes
    Match                     kube.*
    Kube_URL                  https://kubernetes.default.svc.cluster.local:443
    Merge_Log                 Off
    K8S-Logging.Parser        On
    K8S-Logging.Exclude       On
    Labels                    Off
    Annotations               Off

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

[FILTER]
    Name                      modify
    Match                     kube.*
    Add                       k8s_environment    prod

[OUTPUT]
    Name                      gelf
    Match                     kube.*
    Host                      graylog-input.mydomain.com
    Port                      5555
    Mode                      tcp
    Gelf_Short_Message_Key    log


* Environment name and version (e.g. Kubernetes? What version?): Kubernetes v1.24.6
* Server type and version:
* Operating System and version: Linux, Ubuntu 18.04.6 LTS
* OS Kernel version: 5.4.0-1094-azure
* Container Runtime version: containerd://1.6.4+azure-4
* Filters and plugins: Tail input plugin, Kubernetes filter, Nest filter, Modify filter, Gelf Output plugin

**Additional context**
How has this issue affected you? What are you trying to accomplish?
We are trying to stream pod logs generated on kubernetes clusters to graylog. We have deployed fluent-bit as a daemonset to read the logs from the tail input plugin.
We suspect that issue #4284 is still active on v2.0.8 of fluent bit
<!--- Providing context helps us come up with a solution that is most useful in the real world -->

Ahmad-Faizan commented 1 year ago

I figured out how to solve this.

 [FILTER]
    Name                        modify
    Match                       *
    Condition Key_value_equals log 
    Set log blank_line

Adding this converts the short_message: "" to short_message: "blank_line". This stops Graylog from complaining with this error

java.lang.IllegalArgumentException: GELF message <cb1a8e64-9687-11ed-8322-dedfe62fb78b> (received from <10.226.0.13:49243>) has empty mandatory "short_message" field.

cesium147 commented 10 months ago

Last version 2.2.0 still have this bug

Config:

[Input]
    Name                  tail
    Path                  /test/test.log
    Tag                   kube.*
    multiline.parser      cri

[FILTER]
    name                  multiline
    match                 kube.*
    multiline.key_content log
    multiline.parser      cri, go, python, java, ruby

[OUTPUT]
    name                  stdout
    match                 *

Source:

2023-11-16T14:09:16.533247217+03:00 stderr F Picked up _JAVA_OPTIONS: -Dsun.misc.URLClassPath.disableJarChecking=true -Dfile.encoding=utf-8 -Djavax.net.ssl.trustStore=/app/cacerts
2023-11-16T14:09:20.808806147+03:00 stdout F
2023-11-16T14:09:20.808897216+03:00 stdout F   .   ____          _            __ _ _
2023-11-16T14:09:20.808904689+03:00 stdout F  /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
2023-11-16T14:09:20.80891196+03:00 stdout F ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
2023-11-16T14:09:20.808914891+03:00 stdout F  \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
2023-11-16T14:09:20.808917373+03:00 stdout F   '  |____| .__|_| |_|_| |_\__, | / / / /
2023-11-16T14:09:20.80891976+03:00 stdout F  =========|_|==============|___/=/_/_/_/
2023-11-16T14:09:20.810208508+03:00 stdout F  :: Spring Boot ::               (v2.7.10)
2023-11-16T14:09:20.81022331+03:00 stdout F
2023-11-16T14:09:21.088298029+03:00 stdout F 2023-11-16T14:09:21.080[INFO][background-preinit][][][][o.h.v.internal.util.Version]: HV000001: Hibernate Validator 6.2.5.Final

Output:

Fluent Bit v2.2.0                                                                                                                                                                                     
* Copyright (C) 2015-2023 The Fluent Bit Authors                                                                                                                                                      
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd                                                                                                                                      
* https://fluentbit.io                                                                                                                                                                                

[2023/11/20 15:49:09] [ info] [fluent bit] version=2.2.0, commit=db8487d123, pid=1
[2023/11/20 15:49:09] [ info] [storage] ver=1.5.1, type=memory, sync=normal, checksum=off, max_chunks_up=128
[2023/11/20 15:49:09] [ info] [cmetrics] version=0.6.4
[2023/11/20 15:49:09] [ info] [ctraces ] version=0.3.1
[2023/11/20 15:49:09] [ info] [input:tail:tail.0] initializing
[2023/11/20 15:49:09] [ info] [input:tail:tail.0] storage_strategy='memory' (memory only) 
[2023/11/20 15:49:09] [ info] [input:tail:tail.0] multiline core started
[2023/11/20 15:49:09] [ info] [filter:multiline:multiline.0] created emitter: emitter_for_multiline.0 
[2023/11/20 15:49:09] [ info] [input:emitter:emitter_for_multiline.0] initializing
[2023/11/20 15:49:09] [ info] [input:emitter:emitter_for_multiline.0] storage_strategy='memory' (memory only) 
[2023/11/20 15:49:09] [ info] [sp] stream processor started 
[2023/11/20 15:49:09] [ info] [output:stdout:stdout.0] worker #0 started
[2023/11/20 15:49:09] [ info] [filter:multiline:multiline.0] created new multiline stream for tail.0_kube.test.test.log
[2023/11/20 15:49:09] [ info] [input:tail:tail.0] inotify_fs_add(): inode=1062495 watch_fd=1 name=/test/test.log 
[0] kube.test.test.log: [[1700132956.533247217, {}], {"time"=>"2023-11-16T14:09:16.533247217+03:00", "stream"=>"stderr", "_p"=>"F", "log"=>"Picked up _JAVA_OPTIONS: -Dsun.misc.URLClassPath.disableJarChecking=true -Dfile.encoding=utf-8 -Djavax.net.ssl.trustStore=/app/cacerts"}]
[1] kube.test.test.log: [[1700495349.528238622, {}], {"log"=>"2023-11-16T14:09:20.808806147+03:00 stdout F"}]
[2] kube.test.test.log: [[1700132960.808897216, {}], {"time"=>"2023-11-16T14:09:20.808897216+03:00", "stream"=>"stdout", "_p"=>"F", "log"=>". _______ _ _"}] 
[3] kube.test.test.log: [[1700132960.808904689, {}], {"time"=>"2023-11-16T14:09:20.808904689+03:00", "stream"=>"stdout", "_p"=>"F", "log"=>" /\\ / ___'_ __ _ _(_)_ ____ _ \ \ \ \"}]
[4] kube.test.test.log: [[1700132960.808911960, {}], {"time"=>"2023-11-16T14:09:20.80891196+03:00", "stream"=>"stdout", "_p"=>"F", "log"=>"( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \"}]
[5] kube.test.test.log: [[1700132960.808914891, {}], {"time"=>"2023-11-16T14:09:20.808914891+03:00", "stream"=>"stdout", "_p"=>"F", "log"=>" \\/___)| |_)| | | | | || (_| |) ) ) )"}]
[6] kube.test.test.log: [[1700132960.808917373, {}], {"time"=>"2023-11-16T14:09:20.808917373+03:00", "stream"=>"stdout", "_p"=>"F", "log"=>"'|____| .__|_| |_|_| |_\__, | / / / /"}] 
[7] kube.test.test.log: [[1700132960.808919760, {}], {"time"=>"2023-11-16T14:09:20.80891976+03:00", "stream"=>"stdout", "_p"=>"F", "log"=>" =========|_|==============|___/=/_/_/_/"}] 
[8] kube.test.test.log: [[1700132960.810208508, {}], {"time"=>"2023-11-16T14:09:20.810208508+03:00", "stream"=>"stdout", "_p"=>"F", "log"=>" :: Spring Boot :: (v2.7.10)"}]
[9] kube.test.test.log: [[1700495349.528324943, {}], {"log"=>"2023-11-16T14:09:20.81022331+03:00 stdout F"}] 
[10] kube.test.test.log: [[1700132961.088298029, {}], {"time"=>"2023-11-16T14:09:21.088298029+03:00", "stream"=>"stdout", "_p"=>"F", "log"=>"2023-11-16T14:09:21.080[INFO][background-preinit][][][][o.h.v.internal.util.Version]: HV000001: Hibernate Validator 6.2.5.Final"}]

Result line 1 and 9 is incorrect parsed.

fluent / fluent-bit

CRI parser outputs empty log lines #6703

Bug Report