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.

Sign up for GitHub

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

Jump to bottom

Unable to parse multiline logs for containerd #4234

Closed
sumo-drosiek opened this issue Oct 26, 2021 · 8 comments
Closed

Unable to parse multiline logs for containerd #4234

sumo-drosiek opened this issue Oct 26, 2021 · 8 comments
Labels
Stale

Comments

@sumo-drosiek
Copy link
Contributor

Bug Report

Describe the bug
I tried several configurations, but I'm unable to parse multiline logs from containerd using only tail plugin

To Reproduce
logs.txt

2021-09-21T18:03:44.312144359Z stdout P 2021-09-21 This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 7
2021-09-21T18:03:44.312144359Z stdout P   This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 8
2021-09-21T18:03:44.312144359Z stdout P   This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 9
2021-09-21T18:03:44.312144359Z stdout P 2021-09-21 This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 10
2021-09-21T18:03:44.312144359Z stdout P   This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 11

custom_parsers.conf

[MULTILINE_PARSER]
    name          multiline_cri
    type          regex
    flush_timeout 10000
    key_content log
    parser      cri
    # Regex rules for multiline parsing
    # ---------------------------------
    #
    # configuration hints:
    #
    #  - first state always has the name: start_state
    #  - every field in the rule must be inside double quotes
    #
    # rules   |   state name   | regex pattern                   | next state name
    # --------|----------------|--------------------------------------------------
    rule         "start_state"   "^\S+"                           "cont"
    rule        "cont"          "^\s+"                            "cont"

What I want to achieve:

[0] containers.logs.a.txt: [1632247424.312144359, {"time"=>"2021-09-21T18:03:44.312144359Z", "stream"=>"stdout", "_p"=>"P", "log"=>"2021-09-21 This is Partial 7
  This is Partial 8
  This is Partial 9"}]
[1] containers.logs.a.txt: [1632247424.312144359, {"time"=>"2021-09-21T18:03:44.312144359Z", "stream"=>"stdout", "_p"=>"P", "log"=>"2021-09-21 This is Partial 10
  This is Partial 11"}]

fluent-bit.conf

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

[INPUT]
    Name             tail
    Path             logs/*
    multiline.parser multiline_cri
    Tag              containers.*
    Read_from_Head   true
    Refresh_Interval 1
    Rotate_Wait      60
    Mem_Buf_Limit    5MB
    Skip_Long_Lines  On
    DB               tail-db/tail-containers-state.db
    DB.Sync          Normal

[OUTPUT]
    Name          stdout
    Match         *

output

0] containers.logs.a.txt: [1635264620.413247409, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P 2021-09-21 This "}]
[1] containers.logs.a.txt: [1635264620.413252254, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P is "}]
[2] containers.logs.a.txt: [1635264620.413262263, {"log"=>"2021-09-21T18:03:44.312144359Z stdout F Partial 7"}]
[3] containers.logs.a.txt: [1635264620.413264730, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P   This "}]
[4] containers.logs.a.txt: [1635264620.413266818, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P is "}]
[5] containers.logs.a.txt: [1635264620.413269308, {"log"=>"2021-09-21T18:03:44.312144359Z stdout F Partial 8"}]
[6] containers.logs.a.txt: [1635264620.413271802, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P   This "}]
[7] containers.logs.a.txt: [1635264620.413274649, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P is "}]
[8] containers.logs.a.txt: [1635264620.413277489, {"log"=>"2021-09-21T18:03:44.312144359Z stdout F Partial 9"}]
[9] containers.logs.a.txt: [1635264620.413279457, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P 2021-09-21 This "}]
[10] containers.logs.a.txt: [1635264620.413281413, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P is "}]
[11] containers.logs.a.txt: [1635264620.413283069, {"log"=>"2021-09-21T18:03:44.312144359Z stdout F Partial 10"}]
[12] containers.logs.a.txt: [1635264620.413284846, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P   This "}]
[13] containers.logs.a.txt: [1635264620.413287361, {"log"=>"2021-09-21T18:03:44.312144359Z stdout P is "}]

I want to parse multiline on top of the cri "log" output, so I assume the regex_pattern should match it.

In opposite to this I used multiline filter, which works correctly using the same parser:

fluent-bit.conf

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

[INPUT]
    Name             tail
    Path             logs/*
    multiline.parser cri
    Tag              containers.*
    Read_from_Head   true
    Refresh_Interval 1
    Rotate_Wait      60
    Mem_Buf_Limit    5MB
    Skip_Long_Lines  On
    DB               tail-db/tail-containers-state.db
    DB.Sync          Normal

[FILTER]
    Name                  multiline
    Match                 *
    Multiline.key_content log
    Multiline.parser      multiline_cri

[OUTPUT]
    Name          stdout
    Match         *

output

[0] containers.logs.a.txt: [1632247424.312144359, {"time"=>"2021-09-21T18:03:44.312144359Z", "stream"=>"stdout", "_p"=>"P", "log"=>"2021-09-21 This is Partial 7
  This is Partial 8
  This is Partial 9"}]
[1] containers.logs.a.txt: [1632247424.312144359, {"time"=>"2021-09-21T18:03:44.312144359Z", "stream"=>"stdout", "_p"=>"P", "log"=>"2021-09-21 This is Partial 10
  This is Partial 11"}]

This would be fine, but as documentation says:

This filter does not perform buffering that persists across different Chunks. This filter process one Chunk at a time and is not suitable for sources that might send multiline messages in separated chunks

and it doesn't work for longer multiline logs

Expected behavior
Ability to parse mulitline on the top of the cri parser

Screenshots
N/A

Your Environment

  • Version used: 1.8.6

Additional context
N/A
@stevehipwell
Copy link

@sumo-drosiek you might want to search the issues for "multiline" as I'm pretty sure this issue has been reported multiple times, specifically in this case #4033.

@pmalek-sumo
Copy link

I've been looking at this issue and it seems that it more or less is related to receiving multiple IN_MODIFY events for a particular file in the same time range.

One can observe in the below attached log that whenever there's more events than 1 then we receive that may log entries on the stdout plugin (used for debugging purposes)

Probably there's a proper (better) solution but could looking up if there's already a IN_MODIFY event for a particular file and using only the most recent make sense? Or perhaps we don't have enough context at this stage (tail_fs_event()) to make that decision?

fluent-bit/plugins/in_tail/tail_fs_inotify.c

Lines 158 to 159 in 516fb40

static int tail_fs_event(struct flb_input_instance *ins,
struct flb_config *config, void *in_context) 

[2021/11/24 13:39:09] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:39:09] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'
[2021/11/24 13:39:09] [debug] [out coro] cb_destroy coro_id=122
[2021/11/24 13:39:09] [debug] [out coro] cb_destroy coro_id=122
[2021/11/24 13:39:09] [debug] [task] destroy task=0x7ffaf7e37960 (task_id=0)
[2021/11/24 13:39:10] [debug] [input:tail:tail.0] scanning path /var/log/containers/logger*.log
[2021/11/24 13:39:10] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:39:10] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'
[2021/11/24 13:39:10] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:39:11] [debug] [task] created task=0x7ffaf7e37960 id=0 OK
[2021/11/24 13:39:11] [debug] [output:forward:forward.0] request 167 bytes to flush
[0] containers.var.log.containers.logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log: [1637760900.031305703, {"log"=>"[08:07:52.931] level=DEBUG, loggingId=, logger=abc.def, message=this is multiline 1
  this is multiline 2
  this is multiline 3
  this is multiline 4"}]
[2021/11/24 13:39:11] [debug] [input:tail:tail.0] scanning path /var/log/containers/logger*.log
[2021/11/24 13:39:11] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:39:11] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'
[2021/11/24 13:39:11] [debug] [out coro] cb_destroy coro_id=123
[2021/11/24 13:39:11] [debug] [out coro] cb_destroy coro_id=123
[2021/11/24 13:39:11] [debug] [task] destroy task=0x7ffaf7e37960 (task_id=0)
[2021/11/24 13:39:12] [debug] [input:tail:tail.0] scanning path /var/log/containers/logger*.log
[2021/11/24 13:39:12] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:39:12] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'
[2021/11/24 13:39:12] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:39:12] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:39:12] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:39:13] [debug] [task] created task=0x7ffaf7e37960 id=0 OK
[2021/11/24 13:39:13] [debug] [output:forward:forward.0] request 184 bytes to flush
[0] containers.var.log.containers.logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log: [1637760900.031305703, {"log"=>"[08:07:52.931] level=DEBUG, loggingId=, logger=abc.def, message=this is multiline 1"}]
[1] containers.var.log.containers.logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log: [1637760900.031305703, {"log"=>"  this is multiline 2
  this is multiline 3
[2021/11/24 13:39:13] [debug] [input:tail:tail.0] scanning path /var/log/containers/logger*.log
[2021/11/24 13:39:13] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:39:13] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'
[2021/11/24 13:39:13] [debug] [out coro] cb_destroy coro_id=124
  this is multiline 4"}]
[2021/11/24 13:39:13] [debug] [out coro] cb_destroy coro_id=124
[2021/11/24 13:39:13] [debug] [task] destroy task=0x7ffaf7e37960 (task_id=0)
[2021/11/24 13:39:14] [debug] [input:tail:tail.0] scanning path /var/log/containers/logger*.log
[2021/11/24 13:39:14] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:39:14] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'
[2021/11/24 13:39:14] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:39:15] [debug] [task] created task=0x7ffaf7e37960 id=0 OK
[2021/11/24 13:39:15] [debug] [output:forward:forward.0] request 167 bytes to flush
[0] containers.var.log.containers.logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log: [1637760900.031305703, {"log"=>"[08:07:52.931] level=DEBUG, loggingId=, logger=abc.def, message=this is multiline 1
  this is multiline 2
  this is multiline 3
  this is multiline 4"}]
  ...
[2021/11/24 13:41:26] [debug] [input:tail:tail.0] scanning path /var/log/containers/logger*.log
[2021/11/24 13:41:26] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:41:26] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'
[2021/11/24 13:41:26] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:41:26] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:41:26] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:41:26] [debug] [input:tail:tail.0] inode=2308700 events: IN_MODIFY
[2021/11/24 13:41:27] [debug] [input:tail:tail.0] scanning path /var/log/containers/logger*.log
[2021/11/24 13:41:27] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:41:27] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'
[2021/11/24 13:41:27] [debug] [task] created task=0x7ffaf7e37960 id=0 OK
[2021/11/24 13:41:27] [debug] [output:forward:forward.0] request 215 bytes to flush
[2021/11/24 13:41:27] [debug] [out coro] cb_destroy coro_id=191
[0] containers.var.log.containers.logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log: [1637760900.031305703, {"log"=>"[08:07:52.931] level=DEBUG, loggingId=, logger=abc.def, message=this is multiline 1"}]
[1] containers.var.log.containers.logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log: [1637760900.031305703, {"log"=>"  this is multiline 2"}]
[2] containers.var.log.containers.logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log: [1637760900.031305703, {"log"=>"  this is multiline 3"}]
[3] containers.var.log.containers.logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log: [1637760900.031305703, {"log"=>"  this is multiline 4"}]
[2021/11/24 13:41:27] [debug] [out coro] cb_destroy coro_id=191
[2021/11/24 13:41:27] [debug] [task] destroy task=0x7ffaf7e37960 (task_id=0)
[2021/11/24 13:41:28] [debug] [input:tail:tail.0] scanning path /var/log/containers/logger*.log
[2021/11/24 13:41:28] [debug] [input:tail:tail.0] scan_blog add(): dismissed: /var/log/containers/logger_sumologic_alpine-0514a3e3312234ee2002c204f7b9e4fce2d653bc430364ae0c6c68ecc35156da.log, inode 2308700
[2021/11/24 13:41:28] [debug] [input:tail:tail.0] 0 new files found on path '/var/log/containers/logger*.log'

@kasia-kujawa
Copy link

kasia-kujawa commented Dec 15, 2021 •
edited
Loading

I prepared configuration which copes with the case described by @sumo-drosiek, it is combination of default multiline parser for cri logs with custom parser used in multiline filter.

Tested scenario:
/test/logs.txt:

2021-09-21T18:03:44.312144359Z stdout P 2021-09-21 This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 7
2021-09-21T18:03:44.312144359Z stdout P   This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 8
2021-09-21T18:03:44.312144359Z stdout P   This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 9
2021-09-21T18:03:44.312144359Z stdout P 2021-09-21 This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 10
2021-09-21T18:03:44.312144359Z stdout P   This 
2021-09-21T18:03:44.312144359Z stdout P is 
2021-09-21T18:03:44.312144359Z stdout F Partial 11

/test/fluentbit.conf:

[SERVICE]
    Flush        1
    Daemon       Off
    Log_Level    trace
    Parsers_File /test/custom_parsers.conf
    HTTP_Server  On
    HTTP_Listen  0.0.0.0
    HTTP_Port    2020

[INPUT]
    Name             tail
    Path             /test/logs.txt
    multiline.parser cri
    Tag              containers.*
    Read_from_Head   true
    Refresh_Interval 1
    Rotate_Wait      60
    Mem_Buf_Limit    5MB
    Skip_Long_Lines  On
    DB               /test/tail-containers-state.db
    DB.Sync          Normal

[FILTER]
    name                  multiline
    match                 *
    multiline.key_content log
    multiline.parser      multiline_cri

[OUTPUT]
    Name          stdout
    Match         *

/test/custom_parsers.conf

[MULTILINE_PARSER]
    name          multiline_cri
    type          regex
    flush_timeout 10000
    key_content log
    parser      cri
    # Regex rules for multiline parsing
    # ---------------------------------
    #
    # configuration hints:
    #
    #  - first state always has the name: start_state
    #  - every field in the rule must be inside double quotes
    #
    # rules   |   state name   | regex pattern                   | next state name
    # --------|----------------|--------------------------------------------------
    rule         "start_state"   "^\S+"                           "cont"
    rule        "cont"          "^\s+"                            "cont"

and as result I got logs in this form:

[0] containers.test.logs.txt: [1632247424.312144359, {"time"=>"2021-09-21T18:03:44.312144359Z", "stream"=>"stdout", "_p"=>"P", "log"=>"2021-09-21 This is Partial 7
  This is Partial 8
  This is Partial 9"}]
[1] containers.test.logs.txt: [1632247424.312144359, {"time"=>"2021-09-21T18:03:44.312144359Z", "stream"=>"stdout", "_p"=>"P", "log"=>"2021-09-21 This is Partial 10
  This is Partial 11"}]

@kasia-kujawa
Copy link

I missed the fact that:

This filter does not perform buffering that persists across different Chunks. This filter process one Chunk at a time and is not suitable for sources that might send multiline messages in separated chunks

so the configuration provided in #4234 (comment) does not resolve the issue

@github-actions
Copy link
Contributor

This issue is stale because it has been open 90 days with no activity. Remove stale label or comment or this will be closed in 5 days. Maintainers can add the exempt-stale label.

@github-actions github-actions bot added the Stale label Mar 23, 2022
@github-actions
Copy link
Contributor

This issue was closed because it has been stalled for 5 days with no activity.

@sumo-drosiek
Copy link
Contributor Author

It still doesn't work

@sumo-drosiek
Copy link
Contributor Author

please reopen

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
Stale
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@stevehipwell @sumo-drosiek @pmalek-sumo @kasia-kujawa