Slf4j 控制台日志丢失问题调查

2024.10.30 2024.10.30 99 1 min

今天本地调试项目发现长日志始终打不出来，然后 debug 发现, flush 之后，原来打出来一半的日志就会消失

1
2
3
4
5
6


protected void directEncodeEvent(final LogEvent event) {
    getLayout().encode(event, manager);
    if (this.immediateFlush || event.isEndOfBatch()) {
        manager.flush();
    }
}

然后我发现超过 2048 之后，会分批输出，奇怪的事为啥输出一半，后一半继续输出之后，就消失了呢。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14


static void encodeText(final CharsetEncoder charsetEncoder, final CharBuffer charBuf, final ByteBuffer byteBuf,
        final StringBuilder text, final ByteBufferDestination destination)
        throws CharacterCodingException {
    charsetEncoder.reset();
    if (text.length() > charBuf.capacity()) {
        encodeChunkedText(charsetEncoder, charBuf, byteBuf, text, destination);
        return;
    }
    charBuf.clear();
    text.getChars(0, text.length(), charBuf.array(), charBuf.arrayOffset());
    charBuf.limit(text.length());
    final CoderResult result = charsetEncoder.encode(charBuf, byteBuf, true);
    writeEncodedText(charsetEncoder, charBuf, byteBuf, destination, result);
}

最后发现这里有个折叠标志，原来超过之后 idea 自动折叠了。。哈哈一个小乌龙

Pinpoint_error

2024.9.27 2024.10.9 2979 14 mins

背景

最近升级了公司框架，然后发现错误日志一直在刷。

09-29 09:14:01.001 [o-32622-exec-64] WARN  .p.p.t.d.i.CoyoteOutputStreamInterceptor -- before. Caused:null
java.lang.ArrayIndexOutOfBoundsException: null
	at com.navercorp.pinpoint.profiler.context.DefaultDigiwinHttpBodyDataHolder.logResponseValue(DefaultDigiwinHttpBodyDataHolder.java:155) ~[pinpoint-profiler-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.profiler.context.DefaultDigiwinHttpBodyContext.logResponseValue(DefaultDigiwinHttpBodyContext.java:66) ~[pinpoint-profiler-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.plugin.tomcat.digiwin.interceptor.CoyoteOutputStreamInterceptor.before(CoyoteOutputStreamInterceptor.java:38) ~[pinpoint-tomcat-plugin-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.bootstrap.interceptor.ExceptionHandleAroundInterceptor.before(ExceptionHandleAroundInterceptor.java:35) ~[?:2.5.1-p1]
	at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.springframework.util.FastByteArrayOutputStream.writeTo(FastByteArrayOutputStream.java:248) ~[spring-core-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at org.springframework.web.util.ContentCachingResponseWrapper.copyBodyToResponse(ContentCachingResponseWrapper.java:228) ~[spring-web-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at org.springframework.web.util.ContentCachingResponseWrapper.copyBodyToResponse(ContentCachingResponseWrapper.java:212) ~[spring-web-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at com.digiwin.gateway.filter.StandardHeaderFilter.doFilter(StandardHeaderFilter.java:66) ~[dwapiplatform-filter-5.2.0.1117.jar:5.2.0.1117]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) ~[spring-web-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:544) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:364) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1629) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_372]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_372]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_372]
09-29 09:14:01.001 [o-32622-exec-64] WARN  .p.p.t.d.i.CoyoteOutputStreamInterceptor -- before. Caused:null
java.lang.ArrayIndexOutOfBoundsException: null
	at com.navercorp.pinpoint.profiler.context.DefaultDigiwinHttpBodyDataHolder.logResponseValue(DefaultDigiwinHttpBodyDataHolder.java:155) ~[pinpoint-profiler-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.profiler.context.DefaultDigiwinHttpBodyContext.logResponseValue(DefaultDigiwinHttpBodyContext.java:66) ~[pinpoint-profiler-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.plugin.tomcat.digiwin.interceptor.CoyoteOutputStreamInterceptor.before(CoyoteOutputStreamInterceptor.java:38) ~[pinpoint-tomcat-plugin-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.bootstrap.interceptor.ExceptionHandleAroundInterceptor.before(ExceptionHandleAroundInterceptor.java:35) ~[?:2.5.1-p1]
	at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.springframework.util.FastByteArrayOutputStream.writeTo(FastByteArrayOutputStream.java:251) ~[spring-core-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at org.springframework.web.util.ContentCachingResponseWrapper.copyBodyToResponse(ContentCachingResponseWrapper.java:228) ~[spring-web-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at org.springframework.web.util.ContentCachingResponseWrapper.copyBodyToResponse(ContentCachingResponseWrapper.java:212) ~[spring-web-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at com.digiwin.gateway.filter.StandardHeaderFilter.doFilter(StandardHeaderFilter.java:66) ~[dwapiplatform-filter-5.2.0.1117.jar:5.2.0.1117]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200) ~[spring-web-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107) ~[spring-web-5.0.5.RELEASE.jar:5.0.5.RELEASE]
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:199) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:544) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:364) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1629) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_372]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_372]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_372]

09-29 09:12:55.055 [o-32622-exec-32] ERROR n.p.p.c.DefaultDigiwinHttpBodyDataHolder -- exact  body error code  exception:
com.google.gson.JsonSyntaxException: com.google.gson.stream.MalformedJsonException: Use JsonReader.setLenient(true) to accept malformed JSON at line 1 column 241 path $
	at com.google.gson.Gson.assertFullConsumption(Gson.java:1148) ~[gson-2.10.1.jar:?]
	at com.google.gson.Gson.fromJson(Gson.java:1138) ~[gson-2.10.1.jar:?]
	at com.google.gson.Gson.fromJson(Gson.java:1047) ~[gson-2.10.1.jar:?]
	at com.google.gson.Gson.fromJson(Gson.java:982) ~[gson-2.10.1.jar:?]
	at com.navercorp.pinpoint.profiler.context.DefaultDigiwinHttpBodyDataHolder.close(DefaultDigiwinHttpBodyDataHolder.java:177) ~[pinpoint-profiler-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.profiler.context.DefaultDigiwinHttpBodyContext.close(DefaultDigiwinHttpBodyContext.java:48) ~[pinpoint-profiler-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.bootstrap.plugin.request.ServletRequestListener.destroyed(ServletRequestListener.java:192) ~[?:2.5.1-p1]
	at com.navercorp.pinpoint.plugin.tomcat.javax.interceptor.StandardHostValveInvokeInterceptor.after(StandardHostValveInvokeInterceptor.java:152) ~[pinpoint-tomcat-plugin-2.5.1-p1.jar:2.5.1-p1]
	at com.navercorp.pinpoint.bootstrap.interceptor.ExceptionHandleAroundInterceptor.after(ExceptionHandleAroundInterceptor.java:44) ~[?:2.5.1-p1]
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:196) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:364) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:616) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:831) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1629) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[?:1.8.0_372]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[?:1.8.0_372]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-8.5.64.jar:8.5.64]
	at java.lang.Thread.run(Thread.java:750) ~[?:1.8.0_372]
Caused by: com.google.gson.stream.MalformedJsonException: Use JsonReader.setLenient(true) to accept malformed JSON at line 1 column 241 path $
	at com.google.gson.stream.JsonReader.syntaxError(JsonReader.java:1659) ~[gson-2.10.1.jar:?]
	at com.google.gson.stream.JsonReader.checkLenient(JsonReader.java:1465) ~[gson-2.10.1.jar:?]
	at com.google.gson.stream.JsonReader.doPeek(JsonReader.java:551) ~[gson-2.10.1.jar:?]
	at com.google.gson.stream.JsonReader.peek(JsonReader.java:433) ~[gson-2.10.1.jar:?]
	at com.google.gson.Gson.assertFullConsumption(Gson.java:1144) ~[gson-2.10.1.jar:?]
	... 21 more

调查过程

因为 pinpoint jar 包只放在了容器里，所以本地复现麻烦些，所以准备用 arthas 定位下原因。

代码未生效问题调查

2024.9.24 2024.10.9 5320 25 mins

背景

多语言的设置在测试环境可以正常展示，但是在生产环境却无法展示。

确认代码版本

分支 hotfix/132424 5.2.0:2.2.22.1082

测试： 5.2.0:2.2.22.1082 5.2.0:2.2.22.1082

2.2.22.1050

生产： 5.2.0:2.2.22.1082 5.2.0:2.2.22.1082 5.2.0:2.2.22.1082

2.2.22.1050 2.2.22.1050

生产和测试区镜像一致

确认数据是否一致

测试区

{
                "_id": "66f170b450c88226a84db263",
                "mechanismCode": "ud_m_e9cb9bde2d4e423093b900a6912040d2",
                "mechanismVersion": "2.0",
                "mechanismTheoryCode": "ud_p_6f474b61aeaf4609b29f61bcfdd1216d",
                "status": 1,
                "createDate": "2024/09/23 21:43:19",
                "from": "",
                "createdByDevPlatform": true,
                "deletedByDevPlatform": false,
                "tenantId": "SYSTEM",
                "application": "purchase99",
                "athena_namespace": "purchase99",
                "priority": 0,
                "score": 0,
                "code": "ud_c_792142a1511544e7a0fa6c2e8a1a14b0",
                "version": "1.0",
                "name": "测试能力1",
                "description": "测试能力描述",
                "datamap": "2.0",
                "lang": {
                    "name": {
                        "zh_TW": "測試能力1",
                        "en_US": "test1",
                        "zh_CN": "测试能力1"
                    },
                    "description": {
                        "zh_TW": "測試能力描述",
                        "en_US": "test1desc",
                        "zh_CN": "测试能力描述"
                    }
                }
            }

生产区

数据不一致问题调查

2024.8.22 2024.8.23 55 1 min

背景

还是老问题，线上接口多次请求数据不一致。

过程

通过本地程序并发测试，本地无法复现。

并发测试线上接口，可以复现。

查看日志，发现日志打印不全。不要使用 log.error(“xxxx:{}”, e.getMessage())

修改日志, 打出异常堆栈。

1

log.error("xxxx", e)

发现在并发中，调用会报空指针异常。

1

HttpServletRequest request = ((ServletRequestAttributes) RequestContextHolder.getRequestAttributes()).getRequest();

当前线程是没有设置的，但是代码里会调用继承的, 这里本地并发测试无法复现，但是线上会出现。

1
2
3
4
5
6
7
8


	@Nullable
	public static RequestAttributes getRequestAttributes() {
		RequestAttributes attributes = requestAttributesHolder.get();
		if (attributes == null) {
			attributes = inheritableRequestAttributesHolder.get();
		}
		return attributes;
	}

这个内部的原因暂时还未知，需要了解下继承 threadLoacal 和内部线程流转。

HttpServletRequest.setAttribute 不支持并发问题调查

2024.8.16 2024.8.16 156 1 min

背景

最近发现一个 bug, 有时返回数据，有时返回null。

过程

初步调查发现，应该是报错，但是异常被吞了，导致返回 null。本地调用无法复现，推测可能是并发场景下的报错。

于是通过 postman 来并发调用接口，果然复现了异常。

Request.notifyAttributeAssigned 时由于 context 对象为 null 因此异常。

java.lang.NullPointerException
	at org.apache.catalina.connector.Request.notifyAttributeAssigned(Request.java:1555)
	at org.apache.catalina.connector.Request.setAttribute(Request.java:1541)
	at org.apache.catalina.connector.RequestFacade.setAttribute(RequestFacade.java:540)
	at javax.servlet.ServletRequestWrapper.setAttribute(ServletRequestWrapper.java:293)
	at javax.servlet.ServletRequestWrapper.setAttribute(ServletRequestWrapper.java:293)
	at com.digiwin.athena.knowledgegraph.configuration.KgCacheAspect.around(KgCacheAspect.java:48)
	at sun.reflect.GeneratedMethodAccessor183.invoke(Unknown Source)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:498)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:644)
	at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:633)
	at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:174)
	at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)
	at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:689)
	at com.digiwin.athena.knowledgegraph.service.impl.TaskService$$EnhancerBySpringCGLIB$$73d3828b.postActivityDefinition(<generated>)
	at com.digiwin.athena.knowledgegraph.service.impl.TaskService.lambda$null$98(TaskService.java:3799)
	at java.util.concurrent.CompletableFuture$AsyncRun.run$$$capture(CompletableFuture.java:1640)
	at java.util.concurrent.CompletableFuture$AsyncRun.run(CompletableFuture.java)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:750)

那说明有线程 clear context