Issue with java format

[mm3906078]

Hello everyone,
I’m experiencing an issue with the cri plugin. My original configuration is as follows:

<source>
  @type tail
  path /var/log/containers/*.log
  pos_file /var/log/fluentd-es-containers.log.pos
  tag kubernetes.*
  read_from_head true
  <parse>
    @type multi_format
    <pattern>
      format cri
      time_format %Y-%m-%dT%H:%M:%S.%N%Z
      <parse>
        @type json
      </parse>
      <parse>
        @type none
      </parse>
    </pattern>
    <pattern>
      format none
    </pattern>
  </parse>
</source>

My expectation was that logs containing JSON would be parsed accordingly, and all Java logs would be handled by the none parser. However, I noticed that the logs are still being processed using the cri format instead of matching the expected pattern.

For example, here is a log entry after applying this configuration:

2025-03-15T15:35:09.417781166+03:30 stdout F 	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)

Could anyone help me understand why the logs aren’t matching the cri pattern as intended?

Thank you.

[mm3906078]

The output changes when I remove the <parse> @type none </parse> section from the configuration. Here’s the modified configuration:

<source>
  @type tail
  path /var/log/containers/*.log
  pos_file /var/log/fluentd-es-containers.log.pos
  tag kubernetes.*
  read_from_head true
  <parse>
    @type multi_format
    <pattern>
      format cri
      time_format %Y-%m-%dT%H:%M:%S.%N%Z
      <parse>
        @type json
      </parse>
      <parse>
        @type multiline
        format_firstline /\d{4}-\d{1,2}-\d{1,2}/
        format1 /^(?<time>\d{4}-\d{1,2}-\d{1,2} \d{1,2}:\d{1,2}:\d{1,2}) (?<level>[^\s]+) \[(?<thread>.*)\] (?<message>.*)/
      </parse>
      <parse>
        @type none
      </parse>
    </pattern>
    # <pattern>
    #   format none
    # </pattern>
  </parse>
</source>

After this change, I received the following warning messages:

2025-03-15 12:51:34 +0000 [warn]: #0 pattern not matched: "2025-03-15T16:21:28.71299447+03:30 stdout F 2025-03-15 12:51:28 +0000 [warn]: #0 pattern not matched: \"2025-03-15T16:21:24.694313655+03:30 stdout F 2025-03-15 12:51:24 +0000 [warn]: #0 pattern not matched: \\\"2025-03-15T16:21:21.386165861+03:30 stdout F 2025-03-15 12:51:21 +0000 [warn]: #0 pattern not matched: \\\\\\\"2025-03-15T16:21:19.168069196+03:30 stdout F 2025-03-15 12:51:19 +0000 [warn]: #0 pattern not matched: \\\\\\\\\\\\\\\"2025-03-15T16:21:17.000199614+03:30 stdout F 2025-03-15 12:51:17 +0000 [warn]: #0 pattern not matched: \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"2025-03-15T16:21:15.156293556+03:30 stdout F 2025-03-15 12:51:15 +0000 [warn]: #0 pattern not matched: \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"2025-03-15T16:21:13.345343126+03:30 stdout F 2025-03-15 12:51:13 +0000 [warn]: #0 pattern not matched: \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"2025-03-15T16:21:11.510968486+03:30 stdout F 2025-03-15 12:51:11 +0000 [warn]: #0 pattern not matched: \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"2025-03-15T16:21:09.771596945+03:30 stdout F 2025-03-15 12:51:09 +0000 [warn]: #0 pattern not matched: \\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\tat java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\\"

[daipom]

@mm3906078
Could you please share some specific examples?
(Sample logs, their parsing results, and their expected values.)

[mm3906078]

Hi @daipom,

Thanks for your response.

Below is an example output of the logs obtained directly from kubectl. Note that we use log4j for logging in our Java applications.

2025-03-29 11:54:05.983  INFO [REDACTED,REDACTED,REDACTED] 1 --- [org.springframework.amqp.rabbit.RabbitListenerEndpointContainer#0-1] c.d.g.api.msg.event.DomainEventReceiver  : received Registration kyc Billing Event: RegistrationKycBillingEvent(super=AbstractKycBillingEvent(super=BaseBillingEvent(trackingCode=REDACTED, type=REGISTRATION_INFO_INQUIRY, amount=1, billingDate=REDACTED), initiator=REDACTED, businessId=REDACTED, providerName=REDACTED, providerId=REDACTED, fetchedFromCache=false, providerStatus=FAILURE))

Additionally, error logs spanning multiple lines are displayed as follows:

2025-03-29 11:58:33.716 ERROR [REDACTED,REDACTED,REDACTED] 1 --- [http-nio-7098-exec-6] c.d.c.c.CreditResponseExceptionHandler REDACTED:

java.lang.RuntimeException: REDACTED.exception.ActivationValidationException: collateral is eNote but no eNote step found
        at REDACTED.transformer.activation.ActivationAdminBeanMapperImpl.toBusinessActivationInfoModel(ActivationAdminBeanMapperImpl.java:757)
        at REDACTED.service.activation.impl.ActivationAdminServiceImpl.getBusinessActivationInfo(ActivationAdminServiceImpl.java:91)
        at REDACTED.api.web.activation.BusinessActivationResource.getActivationInfo(BusinessActivationResource.java:46)
        at jdk.internal.reflect.GeneratedMethodAccessor333.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:568)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
        at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150)
        at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895)
        at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
        at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
        at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1067)
        at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:963)
        at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
        at org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:898)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:655)
        at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)

Please let me know if you need any additional data or further clarification.

[Watson1978]

I've tried to reproduce. and I got the following logs.

2025-04-16 10:45:33 +0900 [info]: using configuration file: <ROOT>
  <source>
    @type tail
    path "/home/watson/tmp/access*.log"
    tag "kubernetes.*"
    read_from_head true
    <parse>
      @type "multi_format"
      unmatched_lines 
      <pattern>
        format cri
        time_format "%Y-%m-%dT%H:%M:%S.%N%Z"
        <parse>
          @type json
        </parse>
        <parse>
          @type none
        </parse>
      </pattern>
      <pattern>
        format none
      </pattern>
    </parse>
  </source>
  <match kubernetes.**>
    @type stdout
  </match>
</ROOT>
2025-04-16 10:45:33 +0900 [info]: starting fluentd-1.18.0 pid=18939 ruby="3.4.3"
2025-04-16 10:45:33 +0900 [info]: spawn command to main:  cmdline=["/home/watson/.rbenv/versions/3.4.3/bin/ruby", "-Eascii-8bit:ascii-8bit", "bin/fluentd", "-c", "/home/watson/prj/sandbox/fluentd/fluent.conf", "--under-supervisor"]
2025-04-16 10:45:33 +0900 [info]: #0 init worker0 logger path=nil rotate_age=nil rotate_size=nil
2025-04-16 10:45:33 +0900 [info]: adding match pattern="kubernetes.**" type="stdout"
2025-04-16 10:45:33 +0900 [info]: adding source type="tail"
2025-04-16 10:45:33 +0900 [warn]: #0 'pos_file PATH' parameter is not set to a 'tail' source.
2025-04-16 10:45:33 +0900 [warn]: #0 this parameter is highly recommended to save the position to resume tailing.
2025-04-16 10:45:33 +0900 [warn]: section <parse> is not used in <pattern> of cri plugin
2025-04-16 10:45:33 +0900 [info]: #0 starting fluentd worker pid=18971 ppid=18939 worker=0
2025-04-16 10:45:33 +0900 [info]: #0 following tail of /home/watson/tmp/access.log
2025-04-16 10:45:33.545703682 +0900 kubernetes.home.watson.tmp.access.log: {"message":"2025-03-29 11:54:05.983  INFO [REDACTED,REDACTED,REDACTED] 1 --- [org.springframework.amqp.rabbit.RabbitListenerEndpointContainer#0-1] c.d.g.api.msg.event.DomainEventReceiver  : received Registration kyc Billing Event: RegistrationKycBillingEvent(super=AbstractKycBillingEvent(super=BaseBillingEvent(trackingCode=REDACTED, type=REGISTRATION_INFO_INQUIRY, amount=1, billingDate=REDACTED), initiator=REDACTED, businessId=REDACTED, providerName=REDACTED, providerId=REDACTED, fetchedFromCache=false, providerStatus=FAILURE))"}
2025-04-16 10:45:33 +0900 [info]: #0 fluentd worker is now running worker=0

This log is due to the second none setting in fluent-plugin-multi-format-parser, it seems to be the correct behaviour.

[Watson1978]

We think fluent-plugin-parser-cri cannot handle multiple <parse> sections.
Ref.

fluent-plugin-parser-cri/lib/fluent/plugin/parser_cri.rb

Lines 35 to 39 in 4ef06cb

	if parser_config = conf.elements('parse').first
	type = parser_config['@type']
	@sub_parser = Fluent::Plugin.new_parser(type, parent: self.owner)
	@sub_parser.configure(parser_config)
	end