The log collection timestamp is earlier than the source log write time

ibizdevops · July 17, 2023, 2:26am

Hello, we have encountered a problem that the time of the collection log and the source log are inconsistent (see the screenshot below).
Our promtail is deployed in the business Pod through sidecarset. When grafana queries the loki log, it is found that the time is about 20 minutes different from the source log. We checked the running logs of promtail and loki, and there was no abnormality. Also checked the pod and loki server time, also correct. So far, we have not found this problem in other logs. Could you please guide us how to find the cause of this issue?
The following is the configuration of promtail, and the configuration of loki can also be provided if needed. thank you very much for your help!

The versions we use are:
loki: 2.7.5
promtail: 2.7.5
grafana: 9.3.16

promtail.yaml

server:
  http_listen_port: 3101
  grpc_listen_port: 9095
  http_server_read_timeout: 60s
  http_server_write_timeout: 60s
  http_server_idle_timeout: 120s
  enable_runtime_reload: true
  log_level: info

client:
  url: http://loki-service.monitoring:3100/loki/api/v1/push
  tenant_id: xxxxxx
  backoff_config:
    min_period: 100ms
    max_period: 10s
    max_retries: 10
  timeout: 10s

positions:
  filename: /logs/positions.yaml
  sync_period: 3s

scrape_configs:
  - job_name: kubernetes-backend
    static_configs:
    - labels:
        __path__: /logs/*/catalina.out

    pipeline_stages:
    - multiline:
        firstline: '^\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}'
        max_wait_time: 3s
        max_lines: 256

    - regex:
        expression: '^(?P<time>\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}\.\d{3})\s+?(?P<message>((?P<level>\S+)\s+?\[\S+,(?P<traceid>\S*),(?P<spanid>\S*)\].*))$'

    - replace:
        expression: '^(\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}\.\d{3}\s+?)?\S+'
        replace: ''

    - timestamp:
        source: time
        location: Asia/Shanghai
        format: 2006-01-02 15:04:05.000
        fallback_formats:
          - 2006-01-02 15:04:05

    - output:
        source: message

    - labeldrop:
        - job
        - pod
        - container
        - filename

screenshot

source log：

loki log：

tonyswumac · July 17, 2023, 4:27pm

The logs from your second screenshot does not have the trailing 3 digit that the first screen shot does. Is that just from your logs not coming in in the same format? Without that 3 digit your regex won’t fit the log, and the timestamp is therefore not set to the log’s timestamp, rather than the time of collection from promtail.

ibizdevops · July 18, 2023, 12:57am

thank you for your reply!
The first line of our log always has a trailing 3 digits. We queried the next 2 lines of the log. After promtail collected it, we queried the log from loki, and the timestamp was correct.
But found a problem. Since this service is not a request-intensive service, the last log line before 18:39:09.136 is 18:15:33.202, we checked the timestamp of this log, it is the same as the error timestamp of 1689502533202.

The original time of the log: 2023-07-16 18:39:09.136
The wrong one becomes: 2023-07-16 18:15:33.202
(1689503949136 → 1689502533202)
1689502533202 is the timestamp of the last collected log.

Based on this discovery, we tried to query some logs with similar time intervals, but none of them found the problem.

the log after the problem log

source log：

loki log：

the log before the problem log

source log:

loki log:

tonyswumac · July 18, 2023, 4:19pm

Apologies, I am still not quite sure if I actually understand your problem. Please correct me if I am wrong.

Essentially you have three log lines:

2023-07-16 18:15:33.202
2023-07-16 18:39:09.136
2023-07-16 18:42:13.511

And for some reason, the timestamp for the log line 2023-07-16 18:39:09.136 is set to the previous log line, is that correct?

If so that is indeed rather strange. I’d suggest you to see if you can reproduce it. copy those three lines specifically, put them in an isolated instance, install promtail, and run in debug mode (see Troubleshooting | Grafana Loki documentation). If you can reproduce it, great, paste those three lines and I can poke at it as well. If not then the problem may be elsewhere.

ibizdevops · July 19, 2023, 6:46am

Yes, you are correct. Thanks a lot for your guidance. Through debugging, we successfully reproduced this problem. Now the problem is narrowed down, but something is still unclear.

Through debug mode, we discovered that for multiline logs, this seems to be an inevitable issue. It appears that the multiline stage is causing the regex stage to be ignored (I’m not sure if that’s the case). From the screenshot of the debugging process below, it can be seen that the second line of the log does not seem to be matched and processed by the regex stage. However, when we tested the regular expression on the website regex101: build, test, and debug regex, it worked fine (see the screenshot below).

Therefore, we hope that you can guide us once again in fix the configuration. Thank you for your help!

debug screenshot

debug log

Here, the replace stage configured in promtail.yaml above is deleted to make debugging more concise.

[inspect: regex stage]:
{stages.Entry}.Extracted["level"]:
    +: WARN
{stages.Entry}.Extracted["message"]:
    +: WARN [customActivityService,83f4b54eb219483d,030723f5ca1261a4] 9 --- [http-nio-8080-exec-2] o.c.s.i.ActivityPublicServiceServiceImpl : [sadsadsadsadsdsdsadsadsa]sdsads，dsds[dsdsasa21312321]
{stages.Entry}.Extracted["spanid"]:
    +: 030723f5ca1261a4
{stages.Entry}.Extracted["time"]:
    +: 2023-07-16 18:15:33.202
{stages.Entry}.Extracted["traceid"]:
    +: 83f4b54eb219483d
[inspect: timestamp stage]:
{stages.Entry}.Entry.Entry.Timestamp:
    -: 2023-07-19 12:15:12.407455051 +0800 CST
    +: 2023-07-16 18:15:33.202 +0800 CST
[inspect: output stage]:
{stages.Entry}.Entry.Entry.Line:
    -: 2023-07-16 18:15:33.202  WARN [customActivityService,83f4b54eb219483d,030723f5ca1261a4] 9 --- [http-nio-8080-exec-2] o.c.s.i.ActivityPublicServiceServiceImpl : [sadsadsadsadsdsdsadsadsa]sdsads，dsds[dsdsasa21312321]
    +: WARN [customActivityService,83f4b54eb219483d,030723f5ca1261a4] 9 --- [http-nio-8080-exec-2] o.c.s.i.ActivityPublicServiceServiceImpl : [sadsadsadsadsdsdsadsadsa]sdsads，dsds[dsdsasa21312321]
[inspect: labeldrop stage]: none
2023-07-16T18:15:33.202+0800    {__path__="/tmp/logs/catalina.out"} WARN [customActivityService,83f4b54eb219483d,030723f5ca1261a4] 9 --- [http-nio-8080-exec-2] o.c.s.i.ActivityPublicServiceServiceImpl : [sadsadsadsadsdsdsadsadsa]sdsads，dsds[dsdsasa21312321]
[inspect: regex stage]: none
[inspect: regex stage]:
{stages.Entry}.Extracted["level"]:
    +: INFO
{stages.Entry}.Extracted["message"]:
    +: INFO [customActivityService,471338c0bf32b4e8,89db8d229388c79c] 9 --- [http-nio-8080-exec-7] sdk.biz.info                             : Summary^_^10000^_^null^_^ProtocalMustParams:=&charset=UTF-8&=&method=app.messagetemplate.subscribe.query&timestamp=2023-07-16 18:42:13^_^&format=json^_^ApplicationParams:biz_content={"template_id_list":["","",""],"user_id":""}^_^2ms,22ms,1ms^_^trace_id:21909bb516895041334394597ea618
{stages.Entry}.Extracted["spanid"]:
    +: 89db8d229388c79c
{stages.Entry}.Extracted["time"]:
    +: 2023-07-16 18:42:13.511
{stages.Entry}.Extracted["traceid"]:
    +: 471338c0bf32b4e8
[inspect: timestamp stage]:
{stages.Entry}.Entry.Entry.Timestamp:
    -: 2023-07-19 12:15:12.407457515 +0800 CST
    +: 2023-07-16 18:15:33.202000001 +0800 CST
[inspect: timestamp stage]:
{stages.Entry}.Entry.Entry.Timestamp:
    -: 2023-07-19 12:15:12.408975882 +0800 CST
    +: 2023-07-16 18:42:13.511 +0800 CST
[inspect: output stage]: none
[inspect: output stage]:
{stages.Entry}.Entry.Entry.Line:
    -: 2023-07-16 18:42:13.511  INFO [customActivityService,471338c0bf32b4e8,89db8d229388c79c] 9 --- [http-nio-8080-exec-7] sdk.biz.info                             : Summary^_^10000^_^null^_^ProtocalMustParams:=&charset=UTF-8&=&method=app.messagetemplate.subscribe.query&timestamp=2023-07-16 18:42:13^_^&format=json^_^ApplicationParams:biz_content={"template_id_list":["","",""],"user_id":""}^_^2ms,22ms,1ms^_^trace_id:21909bb516895041334394597ea618
    +: INFO [customActivityService,471338c0bf32b4e8,89db8d229388c79c] 9 --- [http-nio-8080-exec-7] sdk.biz.info                             : Summary^_^10000^_^null^_^ProtocalMustParams:=&charset=UTF-8&=&method=app.messagetemplate.subscribe.query&timestamp=2023-07-16 18:42:13^_^&format=json^_^ApplicationParams:biz_content={"template_id_list":["","",""],"user_id":""}^_^2ms,22ms,1ms^_^trace_id:21909bb516895041334394597ea618
[inspect: labeldrop stage]: none
2023-07-16T18:15:33.202000001+0800  {__path__="/tmp/logs/catalina.out"} 2023-07-16 18:39:09.136 ERROR [customActivityService,891efb1888700110,0ebfe9a6361e5711] 9 --- [http-nio-8080-exec-9] c.o.ms.handler.GlobalExceptionHandler    :
java.lang.NullPointerException: null
        at cn.oola.custom.service.impl.FreeActivityServiceImpl.isTodayRegist(FreeActivityServiceImpl.java:436)
        at cn.oola.custom.service.impl.FreeActivityServiceImpl.isEnoughParticipate(FreeActivityServiceImpl.java:442)
        at cn.oola.custom.service.impl.FreeActivityServiceImpl.userJoinActivityInfo(FreeActivityServiceImpl.java:422)
        at cn.oola.custom.service.impl.FreeActivityServiceImpl$$FastClassBySpringCGLIB$$cb5b36ec.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698)
        at cn.oola.custom.service.impl.FreeActivityServiceImpl$$EnhancerBySpringCGLIB$$6550589b.userJoinActivityInfo(<generated>)
        at cn.oola.custom.controller.wx.WebFreeActivityController.userJoinActivityInfo(WebFreeActivityController.java:73)
        at jdk.internal.reflect.GeneratedMethodAccessor489.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)[inspect: labeldrop stage]: none

        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)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.cloud.sleuth.instrument.web.servlet.TracingFilter.doFilter(TracingFilter.java:68)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.cloud.sleuth.instrument.web.servlet.TracingFilter.doFilter(TracingFilter.java:89)
        at org.springframework.cloud.sleuth.autoconfig.instrument.web.LazyTracingFilter.doFilter(TraceWebServletConfiguration.java:121)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:97)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:769)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1722)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base/java.lang.Thread.run(Thread.java:829)
2023-07-16T18:42:13.511+0800    {__path__="/tmp/logs/catalina.out"} INFO [customActivityService,471338c0bf32b4e8,89db8d229388c79c] 9 --- [http-nio-8080-exec-7] sdk.biz.info                             : Summary^_^10000^_^null^_^ProtocalMustParams:=&charset=UTF-8&=&method=app.messagetemplate.subscribe.query&timestamp=2023-07-16 18:42:13^_^&format=json^_^ApplicationParams:biz_content={"template_id_list":["","",""],"user_id":""}^_^2ms,22ms,1ms^_^trace_id:21909bb516895041334394597ea618

sample log

2023-07-16 18:15:33.202  WARN [customActivityService,83f4b54eb219483d,030723f5ca1261a4] 9 --- [http-nio-8080-exec-2] o.c.s.i.ActivityPublicServiceServiceImpl : [sadsadsadsadsdsdsadsadsa]sdsads，dsds[dsdsasa21312321]
2023-07-16 18:39:09.136 ERROR [customActivityService,891efb1888700110,0ebfe9a6361e5711] 9 --- [http-nio-8080-exec-9] c.o.ms.handler.GlobalExceptionHandler    :

java.lang.NullPointerException: null
        at cn.oola.custom.service.impl.FreeActivityServiceImpl.isTodayRegist(FreeActivityServiceImpl.java:436)
        at cn.oola.custom.service.impl.FreeActivityServiceImpl.isEnoughParticipate(FreeActivityServiceImpl.java:442)
        at cn.oola.custom.service.impl.FreeActivityServiceImpl.userJoinActivityInfo(FreeActivityServiceImpl.java:422)
        at cn.oola.custom.service.impl.FreeActivityServiceImpl$$FastClassBySpringCGLIB$$cb5b36ec.invoke(<generated>)
        at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:218)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:783)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
        at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:97)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186)
        at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.proceed(CglibAopProxy.java:753)
        at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:698)
        at cn.oola.custom.service.impl.FreeActivityServiceImpl$$EnhancerBySpringCGLIB$$6550589b.userJoinActivityInfo(<generated>)
        at cn.oola.custom.controller.wx.WebFreeActivityController.userJoinActivityInfo(WebFreeActivityController.java:73)
        at jdk.internal.reflect.GeneratedMethodAccessor489.invoke(Unknown Source)
        at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.base/java.lang.reflect.Method.invoke(Method.java:566)
        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)
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:764)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:227)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.cloud.sleuth.instrument.web.servlet.TracingFilter.doFilter(TracingFilter.java:68)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.cloud.sleuth.instrument.web.servlet.TracingFilter.doFilter(TracingFilter.java:89)
        at org.springframework.cloud.sleuth.autoconfig.instrument.web.LazyTracingFilter.doFilter(TraceWebServletConfiguration.java:121)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:97)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
        at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:189)
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:162)
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:197)
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
        at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:540)
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:135)
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
        at org.apache.catalina.valves.RemoteIpValve.invoke(RemoteIpValve.java:769)
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:357)
        at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:382)
        at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
        at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:895)
        at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1722)
        at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1191)
        at org.apache.tomcat.util.threads.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:659)
        at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
        at java.base/java.lang.Thread.run(Thread.java:829)

2023-07-16 18:42:13.511  INFO [customActivityService,471338c0bf32b4e8,89db8d229388c79c] 9 --- [http-nio-8080-exec-7] sdk.biz.info                             : Summary^_^10000^_^null^_^ProtocalMustParams:=&charset=UTF-8&=&method=app.messagetemplate.subscribe.query&timestamp=2023-07-16 18:42:13^_^&format=json^_^ApplicationParams:biz_content={"template_id_list":["","",""],"user_id":""}^_^2ms,22ms,1ms^_^trace_id:21909bb516895041334394597ea618

tonyswumac · July 19, 2023, 4:43pm

Your problem is because of this:

- regex:
        expression: '^(?P<time>\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}\.\d{3})\s+?(?P<message>((?P<level>\S+)\s+?\[\S+,(?P<traceid>\S*),(?P<spanid>\S*)\].*))$'

Notice the $ at the end, because of the end of line symbol this will not match your multiline logs. Removing it, however, leads to another issue, because you have:

- output:
        source: message

And because of that your multi-line log won’t actually have any of the stack trace output because the message is being replaced by the regex capture now that it actually matches.

I would recommend removing the output part, and just send everything to Loki, and parse on Loki using LogQL. If it’s not desirable, then you’ll have to figure out a way to distinguish between logs with one line or multiple lines, not to mention the logs will actually have mismatched formation in Loki.

This is my test config:

positions:
  filename: /tmp/test/positions.yaml

scrape_configs:
  - job_name: kubernetes-backend
    static_configs:
    - labels:
        __path__: /tmp/test/log.log

    pipeline_stages:
    - multiline:
        firstline: '^\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}'
        max_wait_time: 3s
        max_lines: 256

    - regex:
        expression: '^(?P<time>\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}\.\d{3})\s+?(?P<message>((?P<level>\S+)\s+?\[\S+,(?P<traceid>\S*),(?P<spanid>\S*)\].*))'

    - replace:
        expression: '^(\d{4}-\d{2}-\d{2} \d{1,2}:\d{2}:\d{2}\.\d{3}\s+?)?\S+'
        replace: ''

    - timestamp:
        source: time
        format: 2006-01-02 15:04:05.000
        fallback_formats:
          - 2006-01-02 15:04:05

    - labeldrop:
        - job
        - pod
        - container
        - filename

BTW, what is the regex replace part for? Getting rid of empty logs?

ibizdevops · July 20, 2023, 2:06am

Using your method, we removed the $ and output stage. After debugging, it achieved the desired effect. It’s really great, and we fixed a long-standing configuration error. Thank you so much!

Additionally, the regex replace part aims to remove the dates and times from the source log since they have already been extracted into the timestamp and are displayed in a more user-friendly way in Grafana. If we don’t remove the dates and times from the source log, they would be duplicated in Grafana queries. Therefore, we used regex replace. I’m not sure if this approach is correct. Do you have any good suggestions?

tonyswumac · July 20, 2023, 3:08pm

I think if that’s the intent then it’s a fine solution. I generally prefer to have the logs be as intact as possible, including the duplicated timestamp. One could argue it’s wasted space, but it does give me the peace of mind knowing that the logs i am looking at is as close to how it was produced as possible. I guess one could say it’s just a personal preference.

system · July 19, 2024, 3:09pm

This topic was automatically closed 365 days after the last reply. New replies are no longer allowed.