search

fluent / fluent-bit

Fast and Lightweight Logs and Metrics processor for Linux, BSD, OSX and Windows
https://fluentbit.io
Apache License 2.0
5.86k stars 1.59k forks source link

Fluent Bit Multiline Java Parsing is Not Working as Expected for WebSphere Java Logs #9407

Open wanlonghenry opened 1 month ago

wanlonghenry commented 1 month ago

Bug Report

Describe the bug The Fluent Bit multiline Java parser is not stitching together logs as expected for WebSphere Java logs. It appears that some line in the WebSphere logs is treated as a new log entry, despite the configuration for multiline logging.

To Reproduce

fluent-bit tailing log in collecting pods:

2024-09-16T15:03:44.848991124Z stdout F 2024-09-16 11:03:44,844 [Default Executor-thread-512] ERROR ca.on.gov.edu.common.web.util.FatalErrorHelper - (FatalErrorLogger.java:37) - [c:10.204.72.117:N/A] 2bf9a39a-3a13-44f4-8b76-c41ce29eeb82 - Exception thrown for - anonymousUser 2024-09-16T15:03:44.849019487Z stdout F javax.faces.application.ViewExpiredException: /public/login.xhtml - No saved view state could be found for the view identifier: /public/login.xhtml 2024-09-16T15:03:44.849026651Z stdout F at org.apache.myfaces.lifecycle.RestoreViewExecutor.execute(RestoreViewExecutor.java:183) 2024-09-16T15:03:44.849032472Z stdout F at org.apache.myfaces.lifecycle.LifecycleImpl.executePhase(LifecycleImpl.java:196) 2024-09-16T15:03:44.849038613Z stdout F at org.apache.myfaces.lifecycle.LifecycleImpl.execute(LifecycleImpl.java:143) 2024-09-16T15:03:44.849044875Z stdout F at javax.faces.webapp.FacesServlet.service(FacesServlet.java:198) 2024-09-16T15:03:44.849051136Z stdout F at com.ibm.ws.webcontainer.servlet.ServletWrapper.service(ServletWrapper.java:1266) 2024-09-16T15:03:44.849057118Z stdout F at [internal classes] 2024-09-16T15:03:44.849063359Z stdout F at org.apache.myfaces.webapp.filter.ExtensionsFilter.doFilter(ExtensionsFilter.java:357) 2024-09-16T15:03:44.849069821Z stdout F at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203) 2024-09-16T15:03:44.849075842Z stdout F at [internal classes] 2024-09-16T15:03:44.849081383Z stdout F at ca.on.gov.edu.sorl.filter.CacheFilter.doFilter(CacheFilter.java:25) 2024-09-16T15:03:44.849086943Z stdout F at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203) 2024-09-16T15:03:44.849092453Z stdout F at [internal classes] 2024-09-16T15:03:44.849097984Z stdout F at ca.on.gov.edu.sorl.filter.CrossScriptingFilter.doFilter(CrossScriptingFilter.java:26) 2024-09-16T15:03:44.849103444Z stdout F at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203) 2024-09-16T15:03:44.849108884Z stdout F at [internal classes] 2024-09-16T15:03:44.849114525Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:327) 2024-09-16T15:03:44.849120225Z stdout F at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:115) 2024-09-16T15:03:44.849125716Z stdout F at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:81) 2024-09-16T15:03:44.849131206Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.849136737Z stdout F at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:122) 2024-09-16T15:03:44.849142176Z stdout F at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:116) 2024-09-16T15:03:44.849147657Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.849153107Z stdout F at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:126) 2024-09-16T15:03:44.849158758Z stdout F at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:81) 2024-09-16T15:03:44.849176481Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.849182322Z stdout F at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:109) 2024-09-16T15:03:44.849187792Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.849193252Z stdout F at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:149) 2024-09-16T15:03:44.849198662Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.849204072Z stdout F at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63) 2024-09-16T15:03:44.849209642Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.849215032Z stdout F at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:103) 2024-09-16T15:03:44.849220433Z stdout F at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:89) 2024-09-16T15:03:44.849225813Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.849231183Z stdout F at org.springframework.security.web.header.HeaderWriterFilter.doHeadersAfter(HeaderWriterFilter.java:90) 2024-09-16T15:03:44.849236843Z stdout F at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:75) 2024-09-16T15:03:44.849242253Z stdout F at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) 2024-09-16T15:03:44.849247684Z stdout F at org.spri 2024-09-16T15:03:44.851242439Z stdout F ngframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.851273046Z stdout F at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:55) 2024-09-16T15:03:44.85128034Z stdout F at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) 2024-09-16T15:03:44.851286862Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.851293885Z stdout F at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:112) 2024-09-16T15:03:44.851300588Z stdout F at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:82) 2024-09-16T15:03:44.851306609Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.85131238Z stdout F at org.springframework.security.web.access.channel.ChannelProcessingFilter.doFilter(ChannelProcessingFilter.java:133) 2024-09-16T15:03:44.85131809Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.851323721Z stdout F at org.springframework.security.web.session.DisableEncodeUrlFilter.doFilterInternal(DisableEncodeUrlFilter.java:42) 2024-09-16T15:03:44.851329261Z stdout F at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:117) 2024-09-16T15:03:44.851335012Z stdout F at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:336) 2024-09-16T15:03:44.851340613Z stdout F at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:211) 2024-09-16T15:03:44.851357093Z stdout F at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:183) 2024-09-16T15:03:44.851362694Z stdout F at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:354) 2024-09-16T15:03:44.851370198Z stdout F at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:267) 2024-09-16T15:03:44.851378774Z stdout F at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203) 2024-09-16T15:03:44.851387891Z stdout F at [internal classes] 2024-09-16T15:03:44.851396517Z stdout F at ca.on.gov.edu.common.web.MdcLogfilter.doFilter(MdcLogfilter.java:91) 2024-09-16T15:03:44.851405013Z stdout F at com.ibm.ws.webcontainer.filter.FilterInstanceWrapper.doFilter(FilterInstanceWrapper.java:203) 2024-09-16T15:03:44.85141417Z stdout F at [internal classes] 2024-09-16T15:03:44.851422596Z stdout F at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) 2024-09-16T15:03:44.85143056Z stdout F at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) 2024-09-16T15:03:44.851439056Z stdout F at java.base/java.lang.Thread.run(Unknown Source) 2024-09-16T15:03:44.865336937Z stdout F 2024-09-16 11:03:44,865 [Default Executor-thread-512] INFO ca.on.gov.edu.common.web.util.exception.ViewExpiredLoggingHandle - (ViewExpiredLoggingHandle.java:49) - [c:10.204.72.117:N/A] detect ViewExpiredException - [2bf9a39a-3a13-44f4-8b76-c41ce29eeb82] - 10.204.72.117 - [rSRlB6/h72eiViQ6xgTMOXLgO2riJzSHwthE/Cbm4hiicRlO5LZcts4Bh7BjADgA9zWPKdZTZxT3jOqyg/BaqtG8NZ8=] 2024-09-16T15:03:44.865497087Z stdout F 2024-09-16 11:03:44,865 [Default Executor-thread-512] INFO ca.on.gov.edu.common.web.util.exception.ViewExpiredLoggingHandle - (ViewExpiredLoggingHandle.java:50) - [c:10.204.72.117:N/A] JSESSIONID for [2bf9a39a-3a13-44f4-8b76-c41ce29eeb82] = 2024-09-16T15:03:44.866001347Z stdout F 2024-09-16 11:03:44,865 [Default Executor-thread-512] INFO ca.on.gov.edu.common.web.MdcLogfilter - (MdcLogfilter.java:109) - [c:10.204.72.117:N/A] Elapsed time:POST:/SORRL/public/login.xhtml:25 2024-09-16T15:03:44.883523036Z stdout F 2024-09-16 11:03:44,881 [Default Executor-thread-624] DEBUG ca.on.gov.edu.sorl.managedbean.ErrorBean - (ErrorBean.java:31) - [c:10.204.72.117:N/A] cleaning session ... 2024-09-16T15:03:44.892558076Z stdout F 2024-09-16 11:03:44,892 [Default Executor-thread-624] INFO ca.on.gov.edu.common.web.MdcLogfilter - (MdcLogfilter.java:109) - [c:10.204.72.117:N/A] Elapsed time:GET:/SORRL/public/error.xhtml:15


- Steps to reproduce the problem:
  Set up Fluent Bit with the default Java multiline parser.
  Generate logs from a WebSphere Java application where each log spans multiple lines.
  Observe that some lines are treated as a separate log entry rather than being stitched together.

**Expected behavior**
Logs are stitched together without breaking wording

**Screenshots**
![image](https://github.com/user-attachments/assets/edeca407-696b-4a64-af57-5b83a75829d5)
![image](https://github.com/user-attachments/assets/54731d48-8982-4057-affa-0f2ea566d89a)

**Your Environment**
* Version used: 2.2.3
* Configuration: 

[SERVICE]
    #Default service flush interval is 15 seconds
    Flush         15
    HTTP_Server   Off
    Daemon        Off
    storage.path  /var/opt/microsoft/docker-cimprov/state/flbstore/
    storage.sync  normal
    storage.checksum off
    storage.backlog.mem_limit 10M
    Log_Level     info
    Parsers_File  /etc/opt/microsoft/docker-cimprov/azm-containers-parser.conf
    Log_File      /var/opt/microsoft/docker-cimprov/log/fluent-bit.log
    plugins_file  /etc/opt/microsoft/docker-cimprov/azm-containers-input-plugins.conf

@INCLUDE fluent-bit-input.conf

[INPUT]
    Name tail
    Alias oms_tail
    Tag oms.container.log.la.*
    Path ${AZMON_LOG_TAIL_PATH}
    Read_from_Head true
    DB /var/log/omsagent-fblogs.db
    DB.Sync Off
    Parser cri
    Mem_Buf_Limit 10m
    Buffer_Chunk_Size 1m
    Buffer_Max_Size 1m
    Rotate_Wait 20
    Refresh_Interval 30
    Path_Key filepath
    Skip_Long_Lines On
    Exclude_Path ${AZMON_CLUSTER_LOG_TAIL_EXCLUDE_PATH}

[FILTER]
    Name multiline
    Match oms.container.log.la.*
    multiline.key_content log
    multiline.parser "java"

[FILTER]
    Name grep
    Alias oms_filter
    Match oms.container.log.la.*
    Exclude stream ${AZMON_LOG_EXCLUSION_REGEX_PATTERN}

@INCLUDE fluent-bit-common.conf
@INCLUDE fluent-bit-internal-metrics.conf

* Environment name and version (e.g. Kubernetes? What version?) AKS (Kubernetes 1.28.11)
* Server type and version: WebSphere Liberty 24.0.0.8
* Operating System and version: RHEL 9.4 (OS version in container)
* Filters and plugins: N/A

**Additional context**
The issue was discovered during log collection from WebSphere. Despite setting up multiline parsing in Fluent Bit, logs are still being split into separate records for some lines. The issue may be related to how WebSphere generates the logs (starting a new entry for each line) or a bug in the default Java multiline parser.

We have identified the following log entries that are split across multiple records in the ContainerLogV2 table:
ContainerLogV2
| where ContainerName contains 'sorl'
and TimeGenerated between (datetime('2024-09-10T15:20:57') .. datetime('2024-09-10T15:21:00') )
and LogMessage !contains 'readiness'
| order by TimeGenerated desc
![image](https://github.com/user-attachments/assets/44e04584-c77a-4b92-a7a2-e748a5e3c9eb)

<!--- How has this issue affected you? What are you trying to accomplish? -->
<!--- Providing context helps us come up with a solution that is most useful in the real world -->
patrick-stephens commented 1 month ago

Please provide the full details in the template including things like the target, whether you're using K8S, etc.

Please provide your full configuration, i.e. are you using the recommended multiline parsers for docker or cri prior to attempting multiline parsing? e.g. https://docs.fluentbit.io/manual/pipeline/inputs/tail#multiline-and-containers-v1.8 if you are on K8S which it looks like you are.

Are the failing lines partial ones from the kubelet? Identified by P vs F in CRI format - which I think is what you have.

Please update to the latest version as well to pick up any fixes there and retest.

wanlonghenry commented 1 month ago

Hi @patrick-stephens thanks for checking this. I have updated the description with • Version used: 2.2.3 • Configuration: check full in description • Environment name and version (e.g. Kubernetes? What version?): AKS (Kubernetes 1.28.11) • Server type and version: WebSphere Liberty 24.0.0.8 • Operating System and version: RHEL 9.4 (OS version in container) • Filters and plugins: N/A

We are using java multiline build in parser. Please let us know if you need other information to investigate.

patrick-stephens commented 1 month ago

2.2 series is old now, can you step up as it may already be resolved?