ml: clear last recently used parser to match next parser(#5524) #5564

nokute78 · 2022-06-12T11:26:59Z

Currently, multiline doesn't update a last recently used parser lru_parser.
It causes second+ stream can't be parsed correctly.

This patch is to fix it and add test cases.

Enter [N/A] in the box, if an item is not applicable to your change.

Testing
Before we can approve your change; please submit the following in a comment:

Example configuration file for the change
Debug log output from testing the change

Attached Valgrind output that shows no leaks or memory corruption was found

If this is a change to packaging of containers or native binaries then please confirm it works for all targets.

[N/A] Attached local packaging test output showing all targets (including any new ones) build.

Documentation

[N/A] Documentation required for this feature

Backporting

[N/A] Backport to latest stable release.

Configuration

#5524 (comment)

Debug log

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

[2022/06/12 20:25:09] [ info] [fluent bit] version=1.9.5, commit=b98b935de6, pid=208771
[2022/06/12 20:25:09] [ info] [storage] version=1.2.0, type=memory-only, sync=normal, checksum=disabled, max_chunks_up=128
[2022/06/12 20:25:09] [ info] [cmetrics] version=0.3.1
[2022/06/12 20:25:09] [ info] [filter:multiline:multiline.0] created emitter: emitter_for_multiline.0
[2022/06/12 20:25:09] [ info] [sp] stream processor started
[2022/06/12 20:25:09] [ info] [filter:multiline:multiline.0] created new multiline stream for tail.0_java.1
[2022/06/12 20:25:09] [ info] [filter:multiline:multiline.0] created new multiline stream for tail.1_java.2
[2022/06/12 20:25:09] [ info] [input:tail:tail.0] inotify_fs_add(): inode=525856 watch_fd=1 name=java1.log
[2022/06/12 20:25:09] [ info] [input:tail:tail.1] inotify_fs_add(): inode=529130 watch_fd=1 name=java2.log
[2022/06/12 20:25:09] [ info] [output:stdout:stdout.0] worker #0 started
[0] java.1: [1655033109.152638255, {"log"=>"Exception in thread "main" java.lang.IllegalStateException: ..null property
     at com.example.myproject.Author.getBookIds(xx.java:38)
     at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: java.lang.NullPointerException
     at com.example.myproject.Book.getId(Book.java:22)
     at com.example.myproject.Author.getBookIds(Author.java:35)
     ... 1 more"}]
[1] java.1: [1655033109.152644536, {"log"=>"single line"}]
[0] java.2: [1655033109.152784151, {"log"=>"single line..."}]
[1] java.2: [1655033109.152785663, {"log"=>"Dec 14 06:41:08 Exception in thread "main" java.lang.RuntimeException: Something has gone wrong, aborting!
    at com.myproject.module.MyProject.badMethod(MyProject.java:22)
    at com.myproject.module.MyProject.oneMoreMethod(MyProject.java:18)
    at com.myproject.module.MyProject.anotherMethod(MyProject.java:14)
    at com.myproject.module.MyProject.someMethod(MyProject.java:10)
    at com.myproject.module.MyProject.main(MyProject.java:6)"}]
[2] java.2: [1655033109.152787216, {"log"=>"another line..."}]
^C[2022/06/12 20:25:11] [engine] caught signal (SIGINT)

Valgrind output

$ valgrind --leak-check=full bin/fluent-bit -c a.conf 
==208775== Memcheck, a memory error detector
==208775== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==208775== Using Valgrind-3.15.0 and LibVEX; rerun with -h for copyright info
==208775== Command: bin/fluent-bit -c a.conf
==208775== 
Fluent Bit v1.9.5
* Copyright (C) 2015-2022 The Fluent Bit Authors
* Fluent Bit is a CNCF sub-project under the umbrella of Fluentd
* https://fluentbit.io

[2022/06/12 20:25:39] [ info] [fluent bit] version=1.9.5, commit=b98b935de6, pid=208775
[2022/06/12 20:25:40] [ info] [storage] version=1.2.0, type=memory-only, sync=normal, checksum=disabled, max_chunks_up=128
[2022/06/12 20:25:40] [ info] [cmetrics] version=0.3.1
[2022/06/12 20:25:40] [ info] [filter:multiline:multiline.0] created emitter: emitter_for_multiline.0
[2022/06/12 20:25:40] [ info] [output:stdout:stdout.0] worker #0 started
[2022/06/12 20:25:40] [ info] [sp] stream processor started
[2022/06/12 20:25:40] [ info] [filter:multiline:multiline.0] created new multiline stream for tail.0_java.1
[2022/06/12 20:25:40] [ info] [filter:multiline:multiline.0] created new multiline stream for tail.1_java.2
[2022/06/12 20:25:40] [ info] [input:tail:tail.0] inotify_fs_add(): inode=525856 watch_fd=1 name=java1.log
[2022/06/12 20:25:40] [ info] [input:tail:tail.1] inotify_fs_add(): inode=529130 watch_fd=1 name=java2.log
[0] java.1: [1655033140.167003121, {"log"=>"Exception in thread "main" java.lang.IllegalStateException: ..null property
     at com.example.myproject.Author.getBookIds(xx.java:38)
     at com.example.myproject.Bootstrap.main(Bootstrap.java:14)
Caused by: java.lang.NullPointerException
     at com.example.myproject.Book.getId(Book.java:22)
     at com.example.myproject.Author.getBookIds(Author.java:35)
     ... 1 more"}]
[1] java.1: [1655033140.171368330, {"log"=>"single line"}]
[0] java.2: [1655033140.304598653, {"log"=>"single line..."}]
[1] java.2: [1655033140.304628525, {"log"=>"Dec 14 06:41:08 Exception in thread "main" java.lang.RuntimeException: Something has gone wrong, aborting!
    at com.myproject.module.MyProject.badMethod(MyProject.java:22)
    at com.myproject.module.MyProject.oneMoreMethod(MyProject.java:18)
    at com.myproject.module.MyProject.anotherMethod(MyProject.java:14)
    at com.myproject.module.MyProject.someMethod(MyProject.java:10)
    at com.myproject.module.MyProject.main(MyProject.java:6)"}]
[2] java.2: [1655033140.304684874, {"log"=>"another line..."}]
^C[2022/06/12 20:25:41] [engine] caught signal (SIGINT)
[2022/06/12 20:25:41] [ info] [input] pausing tail.0
[2022/06/12 20:25:41] [ info] [input] pausing tail.1
[2022/06/12 20:25:41] [ warn] [engine] service will shutdown in max 5 seconds
[2022/06/12 20:25:42] [ info] [engine] service has stopped (0 pending tasks)
[2022/06/12 20:25:42] [ info] [input:tail:tail.1] inotify_fs_remove(): inode=529130 watch_fd=1
[2022/06/12 20:25:42] [ info] [input:tail:tail.0] inotify_fs_remove(): inode=525856 watch_fd=1
[2022/06/12 20:25:42] [ info] [output:stdout:stdout.0] thread worker #0 stopping...
[2022/06/12 20:25:42] [ info] [output:stdout:stdout.0] thread worker #0 stopped
==208775== 
==208775== HEAP SUMMARY:
==208775==     in use at exit: 0 bytes in 0 blocks
==208775==   total heap usage: 1,788 allocs, 1,788 frees, 1,941,519 bytes allocated
==208775== 
==208775== All heap blocks were freed -- no leaks are possible
==208775== 
==208775== For lists of detected and suppressed errors, rerun with: -s
==208775== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

$ valgrind --leak-check=full bin/flb-rt-filter_multiline 
==208784== Memcheck, a memory error detector
==208784== Copyright (C) 2002-2017, and GNU GPL'd, by Julian Seward et al.
==208784== Using Valgrind-3.15.0 and LibVEX; rerun with -h for copyright info
==208784== Command: bin/flb-rt-filter_multiline
==208784== 
Test ml_buffered_two_streams...                 [2022/06/12 20:26:05] [ info] [fluent bit] version=1.9.5, commit=b98b935de6, pid=208784
[2022/06/12 20:26:05] [ info] [storage] version=1.2.0, type=memory-only, sync=normal, checksum=disabled, max_chunks_up=128
[2022/06/12 20:26:05] [ info] [cmetrics] version=0.3.1
[2022/06/12 20:26:05] [ info] [filter:multiline:multiline.0] created emitter: emitter_for_multiline.0
[2022/06/12 20:26:05] [ info] [sp] stream processor started
(snip)
[ OK ]
SUCCESS: All unit tests have passed.
==208784== 
==208784== HEAP SUMMARY:
==208784==     in use at exit: 0 bytes in 0 blocks
==208784==   total heap usage: 10,773 allocs, 10,773 frees, 22,830,246 bytes allocated
==208784== 
==208784== All heap blocks were freed -- no leaks are possible
==208784== 
==208784== For lists of detected and suppressed errors, rerun with: -s
==208784== ERROR SUMMARY: 0 errors from 0 contexts (suppressed: 0 from 0)

Fluent Bit is licensed under Apache 2.0, by submitting this pull request I understand that this code will be released under the terms of that license.

nokute78 · 2022-06-12T12:28:16Z

CI is not stable.
This test codes need parameter tuning...

sofsms · 2022-06-14T10:00:57Z

Hello,

When this change will be release ?

edsiper · 2022-06-17T21:44:25Z

Multiline unit test is failing:


The following tests FAILED:
	 25 - flb-rt-filter_multiline (Failed)
Error: Process completed with exit code 8.

Signed-off-by: Takahiro Yamashita <[email protected]>

nokute78 · 2022-06-17T23:16:47Z

src/multiline/flb_ml.c

+            /*
+             * Clear last recently used parser to match new parser.
+             * Do not flush last_stream_id since it should continue to parsing.
+             */
+            lru_parser = NULL;


Note: I removed flb_ml_flush_parser_instance.
Since last_stream_id may be parsing.

nokute78 · 2022-06-17T23:20:00Z

@edsiper CI passed.

I modified below when stream_id is changed.

Clear lru_parser to be parsed new stream_id.
Remove flb_ml_flush_parser_instance to keep parsing last_stream_id.

nokute78 · 2022-07-02T12:37:34Z

@edsiper Ping.
It is ready to review.

edsiper · 2022-07-06T18:01:53Z

thanks!

nokute78 requested review from edsiper, leonardo-albertovich, fujimotos and koleini as code owners June 12, 2022 11:27

github-actions bot added the docs-required label Jun 12, 2022

nokute78 mentioned this pull request Jun 12, 2022

Multiline filters stopped working in 1.9.3 #5524

Closed

nokute78 force-pushed the fix_5524_ml_streams branch 3 times, most recently from 2f01d60 to ee3205a Compare June 12, 2022 12:27

nokute78 marked this pull request as draft June 17, 2022 21:50

nokute78 force-pushed the fix_5524_ml_streams branch from ee3205a to 5b0d37e Compare June 17, 2022 21:53

nokute78 added 2 commits June 18, 2022 07:15

tests: runtime: filter_multiline: add multi stream test(fluent#5524)

d2167ed

Signed-off-by: Takahiro Yamashita <[email protected]>

ml: clear last recently used parser to match next parser(fluent#5524)

a5bfb28

Signed-off-by: Takahiro Yamashita <[email protected]>

nokute78 force-pushed the fix_5524_ml_streams branch from 5b0d37e to a5bfb28 Compare June 17, 2022 22:16

nokute78 marked this pull request as ready for review June 17, 2022 23:15

nokute78 commented Jun 17, 2022

View reviewed changes

davidacb mentioned this pull request Jun 30, 2022

Error when running cmake #5661

Closed

edsiper merged commit 97d50c3 into fluent:master Jul 6, 2022

nokute78 deleted the fix_5524_ml_streams branch July 7, 2022 11:34

drbugfinder-work mentioned this pull request Aug 10, 2022

Multiline filter breaks pipeline #5864

Closed

nokute78 mentioned this pull request Jan 31, 2023

(v1.8.3) Built-in multiline parser (cri) failing to concatenate large logs #3938

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

ml: clear last recently used parser to match next parser(#5524) #5564

ml: clear last recently used parser to match next parser(#5524) #5564

nokute78 commented Jun 12, 2022 •

edited

Loading

nokute78 commented Jun 12, 2022

sofsms commented Jun 14, 2022

edsiper commented Jun 17, 2022

nokute78 Jun 17, 2022

nokute78 commented Jun 17, 2022

nokute78 commented Jul 2, 2022

edsiper commented Jul 6, 2022

ml: clear last recently used parser to match next parser(#5524) #5564

ml: clear last recently used parser to match next parser(#5524) #5564

Conversation

nokute78 commented Jun 12, 2022 • edited Loading

Configuration

Debug log

Valgrind output

nokute78 commented Jun 12, 2022

sofsms commented Jun 14, 2022

edsiper commented Jun 17, 2022

nokute78 Jun 17, 2022

Choose a reason for hiding this comment

nokute78 commented Jun 17, 2022

nokute78 commented Jul 2, 2022

edsiper commented Jul 6, 2022

nokute78 commented Jun 12, 2022 •

edited

Loading