异步文件日志输出问号的解决方案

现象

日志输出使用 AsyncAppender 时，输出的文件行号信息是 ?:? 例如日志配置

<!-- Simple file output --> < appender name = "FILE" class = "ch.qos.logback.core.rolling.RollingFileAppender" > <!-- encoder defaults to ch.qos.logback.classic.encoder.PatternLayoutEncoder --> < encoder > < pattern >framework-server-demo %date %level [%thread] %logger{10} [%file:%line] - %msg%n</ pattern > < charset >UTF-8</ charset > </ encoder > < rollingPolicy class = "ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy" > < fileNamePattern >log/info-%d{yyyy-MM-dd}.%i.log</ fileNamePattern > < maxFileSize >50MB</ maxFileSize > </ rollingPolicy > < filter class = "ch.qos.logback.classic.filter.ThresholdFilter" > < level >INFO</ level > </ filter > <!-- Safely log to the same file from multiple JVMs. Degrades performance! --> < prudent >true</ prudent > </ appender > < appender name = "FILE_ASYNC" class =  "ch.qos.logback.classic.AsyncAppender" > < discardingThreshold >0</ discardingThreshold > < queueSize >512</ queueSize > < appender-ref ref = "FILE" /> </ appender > < root level = "INFO" > < appender-ref ref = "FILE_ASYNC" /> </ root >

输出的日志是：

framework-server-demo 2017-07-17 14:15:11,876 INFO [main] o.s.j.e.a.AnnotationMBeanExporter [?:?] - Located managed bean 'refreshScope': registering with JMX server as MBean [org.springframework.cloud.context.scope.refresh:name=refreshScope,type=RefreshScope]
framework-server-demo 2017-07-17 14:15:11,881 INFO [main] o.s.j.e.a.AnnotationMBeanExporter [?:?] - Located managed bean 'configurationPropertiesRebinder': registering with JMX server as MBean [org.springframework.cloud.context.properties:name=configurationPropertiesRebinder,context=43f2f92d,type=ConfigurationPropertiesRebinder]
framework-server-demo 2017-07-17 14:15:11,887 INFO [main] o.s.j.e.a.AnnotationMBeanExporter [?:?] - Located managed bean 'refreshEndpoint': registering with JMX server as MBean [org.springframework.cloud.endpoint:name=refreshEndpoint,type=RefreshEndpoint]
framework-server-demo 2017-07-17 14:15:11,888 INFO [main] o.s.b.a.e.j.EndpointMBeanExporter [?:?] - Registering beans for JMX exposure on startup
framework-server-demo 2017-07-17 14:15:12,709 INFO [main] application [?:?] - jolokia: No access restrictor found, access to any MBean is allowed
framework-server-demo 2017-07-17 14:15:12,714 INFO [main] application [?:?] - jolokia: jolokia:type=Config is already registered. Adding it with jolokia:type=Config,uuid=43140813-0dc0-413d-96c0-5de1799eadd3, but you should revise your setup in order to either use a qualifier or ensure, that only a single agent gets registered (otherwise history functionality might not work)
framework-server-demo 2017-07-17 14:15:12,714 INFO [main] application [?:?] - jolokia: Cannot register (legacy) MBean handler for config store with name jmx4perl:type=Config since it already exists. This is the case if another agent has been already started within the same JVM. The registration is skipped.
framework-server-demo 2017-07-17 14:15:12,715 INFO [main] application [?:?] - jolokia: Jolokia Discovery MBean registration is skipped because there is already one registered.
           

原因分析

输出文件以及行号信息需要 stacktrace 获取 callerdata，因为性能原因 logback 的 AsyncAppender 默认是不记录该信息。

官方文档 https://logback.qos.ch/manual/appenders.html#AsyncAppender:

includeCallerData

boolean

Extracting caller data can be rather expensive. To improve performance, by default, caller data associated with an event is not extracted when the event added to the event queue. By default, only "cheap" data like the thread name and the MDC are copied. You can direct this appender to include caller data by setting the includeCallerData property to true.

解决方案

就如文档说明，只需要在 logback 配置文件里 AsyncAppender 中添加

< appender name = "FILE_ASYNC" class =  "ch.qos.logback.classic.AsyncAppender" > < discardingThreshold >0</ discardingThreshold > < queueSize >512</ queueSize > < includeCallerData >true</ includeCallerData >  <!-- Copy caller data to event --> < appender-ref ref = "FILE" /> </ appender >

开启记录信息即可。

结果：

framework-server-demo 2017-07-17 14:14:29,250 INFO [main] o.s.w.s.DispatcherServlet [FrameworkServlet.java:487] - FrameworkServlet 'dispatcherServlet': initialization started
framework-server-demo 2017-07-17 14:14:29,275 INFO [main] o.s.w.s.DispatcherServlet [FrameworkServlet.java:506] - FrameworkServlet 'dispatcherServlet': initialization completed in 25 ms
framework-server-demo 2017-07-17 14:14:29,308 INFO [main] o.e.j.s.ServerConnector [AbstractConnector.java:266] - Started [email protected]{HTTP/1.1}{0.0.0.0:8081}
framework-server-demo 2017-07-17 14:14:29,312 INFO [main] o.s.b.c.e.j.JettyEmbeddedServletContainer [JettyEmbeddedServletContainer.java:121] - Jetty started on port(s) 8081 (http/1.1)
framework-server-demo 2017-07-17 14:14:29,316 INFO [main] c.o.f.s.d.s.ServerApplication [StartupInfoLogger.java:57] - Started ServerApplication in 12.99 seconds (JVM running for 18.795)