Introducing rewrite_tag breaks multiline in 1.8.9 #4325

starteleport · 2021-11-15T15:05:54Z

Bug Report

Describe the bug
I have a pipeline: tail -> kubernetes -> multiline -> (omitted for brevity) -> es. I want to introduce rewrite_tag so that I have: tail -> kubernetes -> rewrite_tag -> multiline -> (omitted for brevity) -> es. However, this change breaks multiline parsing. The records are not concatenated AND Kubernetes tags are only left on lines that correspond to start_state.

To Reproduce

Download and extract gist: https://gist.github.com/starteleport/ed66f30b7161f185658e711a7a95a2a2
Compare outputs of fluent-bit -c fluent-bit-repro-norewrite.conf and fluent-bit -c fluent-bit-repro-rewrite.conf.

Expected behavior
Both configs produce the same set of multiline records with Kubernetes tags being correctly set.

Screenshots
Not applicable

Your Environment

Version used: reproduced on 1.8.9
Configuration: please see gist above
Environment name and version (e.g. Kubernetes? What version?): local
Server type and version:
Operating System and version: macOS Monterey
Filters and plugins: rewrite_tag, multiline, multiline_parser

Additional context
This works on 1.8.6.

The text was updated successfully, but these errors were encountered:

nokute78 · 2021-11-19T23:59:51Z

Could you share output of out_stdout plugin ? (ok case and broken case)
Could you try using multiline filter before rewrite_tag filter if you can ?
tail -> kubernetes -> multiline -> rewrite_tag -> ...

We discuss re-design for multiline filter #4309
Since current multiline filter doesn't work and that issue is depended on input plugin. #4173
rewrite_tag emits record using in_emitter plugin and I think in_emitter also cause the issue.

starteleport · 2021-11-20T11:28:29Z

Thanks for the information! Stdout for ok case: https://github.com/fluent/fluent-bit/files/7574459/norewrite.txt Stdout for broken case: https://github.com/fluent/fluent-bit/files/7574460/rewrite.txt Although using multiline before rewrite_tag does work in this case, it is useless for my whole use-case. I use rewrite_tag to split logs coming from different logging systems in order to have only .NET logs pass through multiline filter, not HAProxy logs, for example.

…

20 нояб. 2021 г., в 03:00, Takahiro Yamashita ***@***.***> написал(а): Could you share output of out_stdout plugin ? (ok case and broken case) Could you try using multiline filter before rewrite_tag filter if you can ? tail -> kubernetes -> multiline -> rewrite_tag -> ... We discuss re-design for multiline filter #4309 <#4309> Since current multiline filter doesn't work and that issue is depended on input plugin. #4173 <#4173> rewrite_tag emits record using in_emitter plugin and I think in_emitter also cause the issue. — You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub <#4325 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAW6EINDWOABIM2QMFNHY2TUM3QIDANCNFSM5IB5HHXA>. Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

nokute78 · 2021-11-21T00:20:31Z

Thank you.

I tested below config to simplify the issue.
I think #4128 causes this issue and it is merged from v1.8.9.

[SERVICE]
    Daemon Off
    Flush 1
    Log_Level debug
    Parsers_File custom_parsers-repro.conf
    HTTP_Server Off
    HTTP_Listen 0.0.0.0
    HTTP_Port 2020
    Health_Check Off

[INPUT]
    Name tail
    Path ./repro-external-api-745f757c59-ndgg8_staging_repro-external-api-4303caf1c98782551d123e21f7ea93b56f87b3c59c27e1d325cb126abf6eda6d.log
    multiline.parser docker, cri
    Tag kube.*
    Mem_Buf_Limit 5MB
    Skip_Long_Lines On
    Refresh_Interval 5
    Read_from_Head true

[FILTER]
    Name record_modifier
    Match kube.*
    Record kubernetes staging

[FILTER]
    Name          rewrite_tag
    Match         kube.*
    Rule          kubernetes ^(staging|production)$ apps false
    Emitter_Name  apps_tag_rewriter

[FILTER]
    name                  multiline
    match                 apps
    multiline.key_content log
    multiline.parser      multiline_dotnet_console

[OUTPUT]
    Name stdout
    Match *

in_emitter writes records to msgpack buffer directly from v1.8.9. It is to avoid exausting memory on high load. However it causes an issue when using mutiline parser. fluent#4325 This patch is to be selectable sync/async mode. in_emitter supports 'async_emit' property to select it. Default is 'false'. If it is 'true', in_emitter tries to buffer records like v1.8.8. Signed-off-by: Takahiro Yamashita <nokute78@gmail.com>

starteleport · 2021-11-23T09:01:17Z

I'm not sure how the above PR is supposed to fix this, could you elaborate, please? As it seems to me, there is new flag Emitter_async_emit that switches the behavior to one of 1.8.8 or 1.8.9. But I am able to reproduce the issue on both versions.

nokute78 · 2021-11-23T11:12:18Z

Hmm.
Could you add debug_flush true for filter_multiline ?
Could you share full log on v1.8.6 and v1.8.7 using broken case configuration?

filter_rewrite_tag was modified v1.8.4 and v1.8.9. It was not changed on v1.8.7...
https://fluentbit.io/announcements/v1.8.4/
https://fluentbit.io/announcements/v1.8.9/

starteleport · 2021-11-23T13:35:56Z

Yes, you are right, it's only 1.8.9. I've tried many times with different versions and got it mixed up. It's not even working with rewrite_tag on 1.8.7 and 1.8.8: I've got no records output in case rewrite_tag is present.

ozzy-ext · 2021-11-25T16:26:58Z

The same issue on 1.8.10

nokute78 · 2021-11-30T13:03:15Z

@starteleport Thank you for comment.
So #4357 may not fix this issue, right ?

Hmm the below config is working correctly using #4357.
#4325 (comment)

starteleport · 2021-11-30T13:08:26Z

@nokute78, I have not checked with #4357, but I trust you when you say it works 😄. As I understand, your fix is for 1.8.9+. My initial claim that it does not work for 1.8.8 is true, but the underlying reason seems to be some other than for 1.8.9. So I think #4357 will fix the issue.

nokute78 · 2021-11-30T13:30:39Z

@starteleport Thank you.
v1.8.8 buffers records at in_emitter and v1.8.9 doesn't.
It changes a number of records which are received filter_multiline at one time.
I think it is root cause.

@ozzy-ext Does it work correctly on v1.8.8 ?

ozzy-ext · 2021-12-16T09:56:22Z

@ozzy-ext Does it work correctly on v1.8.8 ?

Yes, it does! But v1.8.9 has issue. It suits me! Good!

nokute78 · 2021-12-22T03:32:46Z

@ozzy-ext Thank you.

So I think #4128 causes this issue.

drbugfinder-work · 2022-02-21T15:09:41Z

We are also using the multiline parser in combination with rewrite_tag. ( tail -> rewrite_tag -> multiline -> lua -> ... -> forward ) For now we are stuck at version 1.8.8 where this pipeline is working.
We did some tests and tried to undo the changes made to the multiline and rewrite_tag filters to see what causes the issue.

The following list shows what changes are necessary in the different versions to get back to a working state:

1.8.9, 1.8.10:
git revert 191f7fb a54334f f8727e9 30e8a66

1.8.11:
git revert 1a6c096
git revert 191f7fb a54334f f8727e9 30e8a66

1.8.12:
git revert 1a6c096
git revert 191f7fb a54334f f8727e9 30e8a66
git revert --no-commit e09a7bb..592d1b0

@nokute78 @edsiper @PettitWesley Will this be fixed in the near future or will this plugin combination stay in this broken state? Thank you!

drbugfinder-work · 2022-04-07T09:53:01Z

@nokute78 @edsiper @PettitWesley Still not working in v1.9.1

PettitWesley · 2022-04-08T00:25:21Z

@drbugfinder-work @ozzy-ext I think part of whats going on here is that you discovered that the multiline filter didn't/doesn't work... I fixed this when I added the new buffer mode (defaults to true) which was released in 1.8.12. That's the first version where the multiline filter works as you expect. However, then we made a mistake in the 1.9 release... we accidentally forgot to merge the buffer mode commits into it, and so 1.9.0 and 1.9.1 were actually released without the feature. We apologize for this and it will be fixed for 1.9.2

#4173

drbugfinder-work · 2022-04-08T07:22:24Z

@PettitWesley @ozzy-ext @nokute78
Actually 1.8.8 is the last working version. All later versions, including 1.8.12 and 1.9.x, only work with the above reverts.

Since the above reverts are related to in_emitter, we think that the emitter change caused the issue.

nokute78 · 2022-04-08T22:07:32Z

@drbugfinder-work I sent a patch #4357 (has not been merged yet)
Above patch is to add an option to select v1.8.8 behavior (or current behavior).

I have no good ideas to date to answer below review comment ....
#4357 (comment)

drbugfinder-work · 2022-04-12T07:10:18Z

@nokute78
I've just built v1.9.1 with your patch and it works as expected. Thank you for this.

drbugfinder-work · 2022-05-16T10:25:45Z

@nokute78 Unfortunately functionality is broken again in v1.9.3 (with your patch applied).

Must be related to the changes: 57ecb32
(cc @PettitWesley)

nokute78 · 2022-05-22T00:32:33Z

I noted current status #4357 (comment) .
I can't reproduce this issue on v1.9.3 (without my patch).

custom_parsers-repro.conf and log are #4357 (comment) .

$ ~/git/WORKTREE/v1.9.3/build/bin/fluent-bit -c bug2.conf 
Fluent Bit v1.9.3
* Copyright (C) 2015-2022 The Fluent Bit Authors
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

[2022/05/22 09:31:30] [ info] [fluent bit] version=1.9.3, commit=9eb4996b7d, pid=6286
[2022/05/22 09:31:30] [ info] [storage] version=1.2.0, type=memory-only, sync=normal, checksum=disabled, max_chunks_up=128
[2022/05/22 09:31:30] [ info] [cmetrics] version=0.3.1
[2022/05/22 09:31:30] [ info] [input:tail:tail.0] multiline core started
[2022/05/22 09:31:30] [ info] [filter:multiline:multiline.2] created emitter: emitter_for_multiline.2
[2022/05/22 09:31:30] [ info] [sp] stream processor started
[2022/05/22 09:31:30] [ info] [filter:multiline:multiline.2] created new multiline stream for emitter.1_apps
[2022/05/22 09:31:30] [ info] [input:tail:tail.0] inotify_fs_add(): inode=1453674 watch_fd=1 name=./repro-external-api-745f757c59-ndgg8_staging_repro-external-api-4303caf1c98782551d123e21f7ea93b56f87b3c59c27e1d325cb126abf6eda6d.log
[2022/05/22 09:31:30] [ info] [output:stdout:stdout.0] worker #0 started
[0] apps: [1636558774.790353236, {"log"=>"info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      => SpanId:01505dc18911774c, TraceId:b86129629f6999479b90a26bae122e46, ParentId:0000000000000000 => ConnectionId:0HMD3I6TBKKDA => RequestPath:/ RequestId:0HMD3I6TBKKDA:00000002
      Request finished HTTP/1.1 GET http://10.0.2.125:80/ - - - 200 - text/plain;+charset=utf-8 0.1316ms
", "stream"=>"stdout", "time"=>"2021-11-10T15:39:34.790353236Z", "kubernetes"=>"staging"}]
[1] apps: [1636558784.788911426, {"log"=>"info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      => SpanId:0418144220ef6845, TraceId:cfe54fe94ecaaa44ab09457f7f868752, ParentId:0000000000000000 => ConnectionId:0HMD3I6TBKKDC => RequestPath:/ RequestId:0HMD3I6TBKKDC:00000002
      Request starting HTTP/1.1 GET http://10.0.2.125:80/ - -
", "stream"=>"stdout", "time"=>"2021-11-10T15:39:44.788911426Z", "kubernetes"=>"staging"}]
[2] apps: [1636558784.789629801, {"log"=>"info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      => SpanId:0418144220ef6845, TraceId:cfe54fe94ecaaa44ab09457f7f868752, ParentId:0000000000000000 => ConnectionId:0HMD3I6TBKKDC => RequestPath:/ RequestId:0HMD3I6TBKKDC:00000002
      Request finished HTTP/1.1 GET http://10.0.2.125:80/ - - - 200 - text/plain;+charset=utf-8 0.1946ms
", "stream"=>"stdout", "time"=>"2021-11-10T15:39:44.789629801Z", "kubernetes"=>"staging"}]
[3] apps: [1636558784.789656241, {"log"=>"info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      => SpanId:5018968b4ab3f342, TraceId:94b3b5b666fba84ca420f0a336559e7b, ParentId:0000000000000000 => ConnectionId:0HMD3I6TBKKDD => RequestPath:/ RequestId:0HMD3I6TBKKDD:00000002
      Request starting HTTP/1.1 GET http://10.0.2.125:80/ - -
", "stream"=>"stdout", "time"=>"2021-11-10T15:39:44.789656241Z", "kubernetes"=>"staging"}]
[0] apps: [1636558784.789667968, {"log"=>"info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      => SpanId:5018968b4ab3f342, TraceId:94b3b5b666fba84ca420f0a336559e7b, ParentId:0000000000000000 => ConnectionId:0HMD3I6TBKKDD => RequestPath:/ RequestId:0HMD3I6TBKKDD:00000002
      Request finished HTTP/1.1 GET http://10.0.2.125:80/ - - - 200 - text/plain;+charset=utf-8 0.1048ms
", "stream"=>"stdout", "time"=>"2021-11-10T15:39:44.789667968Z", "kubernetes"=>"staging"}]

bug2.conf:

[SERVICE]
    Daemon Off
    Flush 1
    Parsers_File custom_parsers-repro.conf
    HTTP_Server Off
    HTTP_Listen 0.0.0.0
    HTTP_Port 2020
    Health_Check Off

[INPUT]
    Name tail
    Path ./repro-external-api-745f757c59-ndgg8_staging_repro-external-api-4303caf1c98782551d123e21f7ea93b56f87b3c59c27e1d325cb126abf6eda6d.log
    multiline.parser docker, cri
    Tag kube.*
    Mem_Buf_Limit 5MB
    Skip_Long_Lines On
    Refresh_Interval 5
    Read_from_Head true

[FILTER]
    Name record_modifier
    Match kube.*
    Record kubernetes staging

[FILTER]
    Name          rewrite_tag
    Match         kube.*
    Rule          kubernetes ^(staging|production)$ apps false
    Emitter_Name  apps_tag_rewriter

[FILTER]
    name                  multiline
    match                 apps
    multiline.key_content log
    multiline.parser      multiline_dotnet_console

[OUTPUT]
    Name stdout
    Match *

drbugfinder-work · 2022-06-01T15:57:13Z

@nokute78 @PettitWesley
We did a lot of testing and found out, that multiline processing is broken - WITHOUT the usage of rewrite_tag in combination

A configuration that we use is like:

[FILTER]
    name                    multiline
    match                   kube.*
    multiline.parser        multiline_msg
    multiline.key_content   log

We found out, that if multiple streams are getting matched by this ONE multiline filter, only the first processed stream is handled correctly. All subsequent streams will not getting converted into multiline.

If we split the multiline into multiple filters where only one stream will be the source for the multiline processing, then everything works fine again:

[FILTER]
    name                    multiline
    match                   kube.staging
    multiline.parser        multiline_msg
    multiline.key_content   log
[FILTER]
    name                    multiline
    match                   kube.production
    multiline.parser        multiline_msg
    multiline.key_content   log

This behaviour occurred with v1.9.3, as I wrote in #4325 (comment). Before that change a wildcard could be used to process records from multiple sources and all our tests were fine.

This new behaviour is definitely a regression, as you no longer can handle multiple tag streams with the same multiline filter. (You can however use the wildcard in the match pattern, as long as only one stream matches it)

drbugfinder-work · 2022-06-01T15:57:52Z

Please also see: #5524 (comment)

nokute78 · 2022-06-04T23:47:45Z

@drbugfinder-work Thank you for reporting.
I think your reporting new issue #4325 (comment) is different from the original issue.
The new issue will be followed as #5524 .

github-actions · 2022-09-03T02:19:27Z

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 · 2022-09-08T02:21:43Z

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

nokute78 mentioned this issue Nov 21, 2021

in_emitter: support async mode(#4325) #4357

Draft

4 tasks

starteleport changed the title ~~Introducing rewrite_tag breaks multiline in 1.8.7+~~ Introducing rewrite_tag breaks multiline in 1.8.9 Nov 24, 2021

shenningz mentioned this issue Jun 1, 2022

Multiline filters stopped working in 1.9.3 #5524

Closed

drbugfinder-work mentioned this issue Aug 10, 2022

Multiline filter breaks pipeline #5864

Closed

github-actions bot added the Stale label Sep 3, 2022

github-actions bot closed this as completed Sep 8, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Introducing rewrite_tag breaks multiline in 1.8.9 #4325

Introducing rewrite_tag breaks multiline in 1.8.9 #4325

starteleport commented Nov 15, 2021 •

edited

Loading

nokute78 commented Nov 19, 2021

starteleport commented Nov 20, 2021 via email •

edited

Loading

nokute78 commented Nov 21, 2021

starteleport commented Nov 23, 2021

nokute78 commented Nov 23, 2021

starteleport commented Nov 23, 2021

ozzy-ext commented Nov 25, 2021

nokute78 commented Nov 30, 2021

starteleport commented Nov 30, 2021

nokute78 commented Nov 30, 2021

ozzy-ext commented Dec 16, 2021

nokute78 commented Dec 22, 2021

drbugfinder-work commented Feb 21, 2022 •

edited

Loading

drbugfinder-work commented Apr 7, 2022

PettitWesley commented Apr 8, 2022

drbugfinder-work commented Apr 8, 2022

nokute78 commented Apr 8, 2022 •

edited

Loading

drbugfinder-work commented Apr 12, 2022

drbugfinder-work commented May 16, 2022 •

edited

Loading

nokute78 commented May 22, 2022

drbugfinder-work commented Jun 1, 2022

drbugfinder-work commented Jun 1, 2022

nokute78 commented Jun 4, 2022

github-actions bot commented Sep 3, 2022

github-actions bot commented Sep 8, 2022

Introducing rewrite_tag breaks multiline in 1.8.9 #4325

Introducing rewrite_tag breaks multiline in 1.8.9 #4325

Comments

starteleport commented Nov 15, 2021 • edited Loading

Bug Report

nokute78 commented Nov 19, 2021

starteleport commented Nov 20, 2021 via email • edited Loading

nokute78 commented Nov 21, 2021

starteleport commented Nov 23, 2021

nokute78 commented Nov 23, 2021

starteleport commented Nov 23, 2021

ozzy-ext commented Nov 25, 2021

nokute78 commented Nov 30, 2021

starteleport commented Nov 30, 2021

nokute78 commented Nov 30, 2021

ozzy-ext commented Dec 16, 2021

nokute78 commented Dec 22, 2021

drbugfinder-work commented Feb 21, 2022 • edited Loading

drbugfinder-work commented Apr 7, 2022

PettitWesley commented Apr 8, 2022

drbugfinder-work commented Apr 8, 2022

nokute78 commented Apr 8, 2022 • edited Loading

drbugfinder-work commented Apr 12, 2022

drbugfinder-work commented May 16, 2022 • edited Loading

nokute78 commented May 22, 2022

drbugfinder-work commented Jun 1, 2022

drbugfinder-work commented Jun 1, 2022

nokute78 commented Jun 4, 2022

github-actions bot commented Sep 3, 2022

github-actions bot commented Sep 8, 2022

starteleport commented Nov 15, 2021 •

edited

Loading

starteleport commented Nov 20, 2021 via email •

edited

Loading

drbugfinder-work commented Feb 21, 2022 •

edited

Loading

nokute78 commented Apr 8, 2022 •

edited

Loading

drbugfinder-work commented May 16, 2022 •

edited

Loading