how parse springboot multiline log #5430

suinxinliulang · 2022-05-07T08:00:02Z

suinxinliulang
May 7, 2022

I want use fluent-bit collect multiline log, but my test result not like demo in offical manual.

my log file content:

022-05-07 15:51:57.423  INFO 71618 --- [scheduling-1] m.d.s.controller.TestController          : userInfo:UserInfo(id=null, name=test, nickName=null, gender=null, birthday=2022-03-09, phone=null, email=2819239@131.com, createTime=2022-05-07T15:51:57.423384, updateTime=null)
2022-05-07 15:52:02.422  INFO 71618 --- [scheduling-1] m.d.s.controller.TestController          : userInfo:UserInfo(id=null, name=test, nickName=null, gender=null, birthday=2022-03-09, phone=null, email=2819239@131.com, createTime=2022-05-07T15:52:02.422751, updateTime=null)
2022-05-07 15:52:07.422  INFO 71618 --- [scheduling-1] m.d.s.controller.TestController          : userInfo:UserInfo(id=null, name=test, nickName=null, gender=null, birthday=2022-03-09, phone=null, email=2819239@131.com, createTime=2022-05-07T15:52:07.422789, updateTime=null)
2022-05-07 15:52:12.423  INFO 71618 --- [scheduling-1] m.d.s.controller.TestController          : userInfo:UserInfo(id=null, name=test, nickName=null, gender=null, birthday=2022-03-09, phone=null, email=2819239@131.com, createTime=2022-05-07T15:52:12.423109, updateTime=null)
2022-05-07 15:52:15.702 ERROR 71618 --- [http-nio-8084-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.ArithmeticException: / by zero] with root cause

java.lang.ArithmeticException: / by zero
	at my.demo.springboot.controller.TestController.errorCase(TestController.java:56) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]

fluent-bit.conf and parse.conf

# fluent-bit.conf
[SERVICE]
    parsers_file parser.conf
[INPUT]
    name tail
    path /app/log/spring.log
    multiline.parser multiline_parser
[OUTPUT]
    name stdout
    match *

# parse.conf
[MULTILINE_PARSER]
    name multiline_parser
    type regex
    flush_timeout 1000
    # 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
    # ------|---------------|--------------------------------------------
    rule "start_state" "/(?<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d*)[\s]*(?<level>\S*)[\s]*(?<thread>\d* --- \[\s*\S*\][\s]*\S*)\s*:(?<message>.*)/" "empty_row"
    rule "empty_row" "/^\n+\S* \S+/m" "cont"
    rule "cont" "/\s+[at]+.*/" "cont"

[PARSER]
    name single_line_parser
    format regex
    regex ^(?<time>\d{4}-\d{2}-\d{2}\s\d{2}:\d{2}:\d{2}.\d*)[\s]*(?<level>\S*)[\s]*(?<thread>\d* --- \[\s*\S*\][\s]*\S*)\s*:(?<message>.*)$
    time_key time
    time_format %Y-%m-%d %H:%M:%S.%L

fluent bit print result

[0] tail.0: [1651910223.126153291, {"log"=>"2022-05-07 15:57:03.125  INFO 72735 --- [scheduling-1] m.d.s.controller.TestController          : userInfo:UserInfo(id=null, name=test, nickName=null, gender=null, birthday=2022-03-09, phone=null, email=2819239@131.com, createTime=2022-05-07T15:57:03.125770, updateTime=null)
"}]
[0] tail.0: [1651910226.590900290, {"log"=>"2022-05-07 15:57:06.590 ERROR 72735 --- [http-nio-8084-exec-1] o.a.c.c.C.[.[.[/].[dispatcherServlet]    : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.ArithmeticException: / by zero] with root cause
"}]
[1] tail.0: [1651910226.590900290, {"log"=>"java.lang.ArithmeticException: / by zero
"}]
[2] tail.0: [1651910226.590900290, {"log"=>"    at my.demo.springboot.controller.TestController.errorCase(TestController.java:56) ~[classes/:na]
"}]
[3] tail.0: [1651910226.590900290, {"log"=>"    at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
"}]

lecaros · 2022-05-19T21:07:36Z

lecaros
May 19, 2022
Maintainer

Hi @suinxinliulang
Have you used the built-in java parser?

[INPUT]
    name                  tail
    path                  sample.log
    multiline.parser      java

0 replies

RaJiska · 2022-05-26T15:34:29Z

RaJiska
May 26, 2022

Hi @suinxinliulang ,

This is a tough one I just solved after working on it for the past few days. So far it seems to always work with Springboot logs, here are my set of rules:

    # rules |   state name    | regex pattern                             | next state
    # ------|-----------------|--------------------------------------------------------
    rule      "start_state"      "/^(\d+-\d+-\d+ \d+:\d+:\d+\.\d+)(.*)$/"  "empty_row"
    rule      "empty_row"        "/^$/"                                    "error_row"
    rule      "error_row"        "/^.*$/"                                  "stacktrace"
    rule      "stacktrace"       "/^\s*at .*$/"                            "stacktrace"

I haven't tested my list of rules thoroughly, please let me know if there is any unexpected behavior. There is a minor issue which is that the last empty line won't be captured. I am not sure how this could be achieved without some sort of final_state rule.

In addition to the above, an issue I am having from this is that the last line always seems to be buffered and does not get flushed. If anybody has a solution for that I am taking.

@lecaros
Using the built-in Java parser is not good enough as it will just group the raw stacktrace together, being:

java.lang.ArithmeticException: / by zero
	at my.demo.springboot.controller.TestController.errorCase(TestController.java:56) ~[classes/:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]

The goal should be to group this stacktrace, with the empty line above, as well as with the properly standardised log entry ensuring that the stacktrace belongs to an entry with parsable values.

0 replies

lecaros · 2022-05-26T20:12:37Z

lecaros
May 26, 2022
Maintainer

What implementation of logger are you using? That extra empty line seems odd to me.
Are all your exceptions printed like that?

3 replies

RaJiska May 26, 2022

We are using Springboot with Slf4j. We log exception the following way:

logger.error("Exception message", exception);

Which will be print exactly the same way as OP formatted it (except I believe OP got an exception handled by Springboot internal), which is:

<time> <level> <...> : Exception message
<Empty line>
<Stacktrace>
<Empty line>

lecaros May 27, 2022
Maintainer

I see. Slf4j is just the facade; perhaps the underlying implementation (logback, log4j, etc.) is doing something odd there. Can you provide a small repro?
If that's standard, we should add it to the built-in parser; otherwise, just come up with a working rule.

RaJiska May 30, 2022

By standard I meant having a consistent way of handling logging, rather than a standard within the Java language itself. I believe each library may display entries differently, and some I believe are highly customizable in terms of displayed fields (I believe it's the case of slf4j), therefore I am not sure if it'd be possible to add directly into the built-in parser.

As requested I made a small repo for you to be able to test for yourself. The following are the commands I use to run it:

# Start Fluentd
cd fluentd
docker build --no-cache -t tmp . && docker run --rm -it -p24224:24224 tmp
# Start Springboot
cd sample-java-app
./mvnw package
docker run --name springboot-test --log-driver=fluentd --log-opt fluentd-address=localhost:24224 --log-opt tag=app.java-slf4j.testapp --net=host -v $(pwd)/sample-java-app:/app --workdir /app --rm openjdk:16-alpine3.13 java -jar target/sample-0.0.1-SNAPSHOT.jar

The above should generate Springboot starting logs. To generate some extra logs, you can achieve it with the following commands:

# Generate Stacktrace
docker exec springboot-test sh -c 'apk update && apk add curl && curl localhost:8080/foo'
# Generate a single log entry
docker exec springboot-test sh -c 'apk update && apk add curl && curl localhost:8080/bar'

lecaros · 2022-06-06T21:10:31Z

lecaros
Jun 6, 2022
Maintainer

Hi for the repro @RaJiska.
I've found a couple of users asking about this empty line generated by logback. (this, for example).
For reference to @suinxinliulang,
this is the config:

[SERVICE]
    Parsers_File parsers_test.conf
    Log_Level info
    Flush       1

[INPUT]
    name                  tail
    path                  sample.log
    read_from_head        true

[FILTER]
    Name multiline
    Match *
    multiline.key_content log
    multiline.parser supertest

[FILTER]
    Name     parser
    Match    *
    Key_Name log
    Parser   java-slf4j
    Preserve_Key true
    Reserve_Data true

[OUTPUT]
    Name stdout
    Match **

parsers:

[PARSER]
    Name        java-slf4j
    Format      regex
    Regex       ^(?<TIME>\d+-\d+-\d+ \d+:\d+:\d+\.\d+)\s+(?<LEVEL>\S+) \d+ --- \[\s*(?<THREAD>[^\]]+)\] (?<CONTEXT>\S+)\s+: (?<MESSAGE>.*)$
    Time_Key    TIME
    Time_Format %Y-%m-%d %H:%M:%S.%L

[MULTILINE_PARSER]
    name          supertest
    type          regex
    flush_timeout 500
    #
    # 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
    # ------|-----------------|--------------------------------------------------------
    rule      "start_state"      "/^(\d+-\d+-\d+ \d+:\d+:\d+\.\d+)(.*)$/"  "empty_row"
    rule      "empty_row"        "/^$/"                                    "error_row"
    rule      "error_row"        "/^.*$/"                                  "stacktrace"
    rule      "stacktrace"       "/^(\s*at .*|)$/"                            "stacktrace"

sample.log

2022-05-27 02:50:17.990  INFO 1 --- [nio-8080-exec-4] i.b.example.sample.FooBarController      : Hello World
2022-05-27 02:50:17.992 ERROR 1 --- [nio-8080-exec-4] i.b.example.sample.FooBarController      : Real Exception Bro

java.lang.Exception: Exception just occured bro
	at io.buildpacks.example.sample.FooBarController.Foo(FooBarController.java:17) ~[classes!/:0.0.1-SNAPSHOT]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
	at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:78) ~[na:na]
	at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
	at java.base/java.lang.reflect.Method.invoke(Method.java:567) ~[na:na]
	at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:189) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:138) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:102) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:800) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1038) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:942) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1005) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:897) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:634) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:882) ~[spring-webmvc-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:741) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53) ~[tomcat-embed-websocket-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:92) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:93) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.1.5.RELEASE.jar!/:5.1.5.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:200) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:490) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:139) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:74) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:408) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:834) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1415) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1130) ~[na:na]
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:630) ~[na:na]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.16.jar!/:9.0.16]
	at java.base/java.lang.Thread.run(Thread.java:831) ~[na:na]

2022-05-27 02:50:17.992  INFO 1 --- [nio-8080-exec-4] i.b.example.sample.FooBarController      : DONE

Still need to figure out if this should be added to the built-in java parser.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

how parse springboot multiline log #5430

{{title}}

Replies: 4 comments 3 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

Select a reply

how parse springboot multiline log #5430

suinxinliulang May 7, 2022

Replies: 4 comments · 3 replies

lecaros May 19, 2022 Maintainer

RaJiska May 26, 2022

lecaros May 26, 2022 Maintainer

RaJiska May 26, 2022

lecaros May 27, 2022 Maintainer

RaJiska May 30, 2022

lecaros Jun 6, 2022 Maintainer

suinxinliulang
May 7, 2022

Replies: 4 comments 3 replies

lecaros
May 19, 2022
Maintainer

RaJiska
May 26, 2022

lecaros
May 26, 2022
Maintainer

lecaros May 27, 2022
Maintainer

lecaros
Jun 6, 2022
Maintainer