Logback日志异步打印接入指南，输出自定义业务数据

背景

随着应用的请求量上升，日志输出量也会成线性比例的上升，给磁盘IO带来压力与性能瓶颈。应用也遇到了线程池满，是因为大量线程卡在输出日志。为了缓解日志同步打印，会采取异步打印日志。这样会引起日志中的追踪id丢失，不能基于追踪id查询相关日志，给问题解决带来新的挑战。

目标

• 业务数据传递
  • 在日志输出中，业务可以传递用户自定义数据并输出到日志中，并自动构建字段索引，便于快速查询。(包含同步输出)
• 轻量级接入

技术方案

基于SLF4J日志事件LoggingEvent和映射诊断上下文MDC

• 在Logback日志事件LoggingEvent implements ILoggingEvent进入日志异步追加器AsyncAppender extends AsyncAppenderBase<ILoggingEvent>的队列blockingQueue之前，把数据状态临时存储到MDC适配器LogbackMDCAdapter的mdcPropertyMap线程本地变量副本中。
• 在组装日志数据前从其取出这些临时的内存数据状态，并组装到最终的日志文本数据中。

具体实现

XxxJsonLayout

package com.xxx.logback;import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.contrib.json.classic.JsonLayout;
import java.time.Instant;
import java.time.ZoneId;
import java.time.ZoneOffset;
import java.time.format.DateTimeFormatter;
import java.util.Map;import org.apache.skywalking.apm.toolkit.trace.TraceContext;/*** JSON格式布局输出*/
public class XxxJsonLayout extends JsonLayout {/*** 零时区 UTC 0* 协调世界时（UTC）*/private static final ZoneId ZONE_ID_0 = ZoneId.ofOffset("UTC", ZoneOffset.UTC);/*** 东八区 UTC+8*/private static final ZoneId ZONE_ID_8 = ZoneId.of("Asia/Shanghai");private static final String AT_TIMESTAMP_ATTR_NAME = "@timestamp";@Overrideprotected void addCustomDataToJsonMap(Map<String, Object> map, ILoggingEvent event) {String timestampFormat = Instant.ofEpochMilli(event.getTimeStamp()).atZone(ZONE_ID_8).format(DateTimeFormatter.ISO_LOCAL_DATE_TIME);map.put(TIMESTAMP_ATTR_NAME, timestampFormat);String atTimestampFormat = Instant.ofEpochMilli(event.getTimeStamp()).atZone(ZONE_ID_0).format(DateTimeFormatter.ISO_LOCAL_DATE_TIME);// ES record create timestampmap.put(AT_TIMESTAMP_ATTR_NAME, atTimestampFormat);// log async appender print, app data pass by MDC// 日志异步打印，应用日志数据从MDC传递if (this.isIncludeMDC()) {Map<String, String> mdcPropertyMap = event.getMDCPropertyMap();map.putAll(MdcUtil.applyAsMap(mdcPropertyMap));}String traceId = TraceContext.traceId();// 日志异步打印时，追踪id为空，需要从MDC传递if (!isEmptyTraceId(traceId)) {map.put(MdcUtil.TRACE_ID_KEY, traceId);}}/*** 空的追踪身份*/private static final String EMPTY_TRACE_CONTEXT_ID = "N/A";/*** 忽略的追踪*/private static final String IGNORE_TRACE = "Ignored_Trace";private static boolean isEmptyTraceId(String traceId) {return traceId == null || traceId.isEmpty()|| EMPTY_TRACE_CONTEXT_ID.equals(traceId);}
}

MdcUtil

package com.xxx.logback;import java.util.HashMap;
import java.util.Map;
import java.util.Set;import com.google.common.collect.Sets;
import lombok.extern.slf4j.Slf4j;
import org.apache.skywalking.apm.toolkit.trace.TraceContext;
import org.slf4j.MDC;/*** Proxy of {@link MDC}.** @since 2024/4/13*/
@Slf4j
public final class MdcUtil {/*** 追踪身份*/static final String TRACE_ID_KEY = "traceId";public static void setTraceId() {MDC.put(TRACE_ID_KEY, TraceContext.traceId());}public static void setTraceId(String traceId) {MDC.put(TRACE_ID_KEY, traceId);}// 业务过程数据private static final String USER_ID = "userId";private static final String COACH_ID = "coachId";private static final String ADMIN_ID = "adminId";private static final String RESPONSE_TIME = "rt";private static final String RESPONSE_CODE = "code";private static final String API = "api";private static final String REMOTE_APP = "remoteApp";public static void setUserId(Long userId) {MDC.put(USER_ID, "" + userId);}public static void setCoachId(Long coachId) {MDC.put(COACH_ID, "" + coachId);}public static void setAdminId(Long adminId) {MDC.put(ADMIN_ID, "" + adminId);}public static void setResponseTime(long responseTime) {MDC.put(RESPONSE_TIME, Long.toString(responseTime));}public static void setResponseTime(int responseTime) {MDC.put(RESPONSE_TIME, Integer.toString(responseTime));}public static void setResponseCode(int responseCode) {MDC.put(RESPONSE_CODE, Integer.toString(responseCode));}public static void setResponseCode(String responseCode) {MDC.put(RESPONSE_CODE, responseCode);}public static void setApi(String api) {MDC.put(API, api);}public static void setRemoteApp(String remoteApp) {MDC.put(REMOTE_APP, remoteApp);}public static void clear() {MDC.clear();}/*** ES long data type*/private static final Set<String> LONG_DATA_KEY_SET = Sets.newHashSet(USER_ID, COACH_ID, ADMIN_ID, RESPONSE_TIME);public static Map<String, Object> applyAsMap(Map<String, String> mdcPropertyMap) {Map<String, Object> result = new HashMap<>(mdcPropertyMap.size());mdcPropertyMap.forEach((key, value) -> {if (LONG_DATA_KEY_SET.contains(key)) {result.put(key, toLong(value, Long.MIN_VALUE));} else {result.put(key, value);}});return result;}private static long toLong(String str, long defaultValue) {if (str == null) {return defaultValue;} else {try {return Long.parseLong(str, 10);} catch (NumberFormatException e) {log.warn("parse string to long error, str={}", str);return defaultValue;}}}
}

XxxJsonLayoutEncoder

package com.xxx.logback;import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.contrib.jackson.JacksonJsonFormatter;
import ch.qos.logback.core.encoder.LayoutWrappingEncoder;import java.nio.charset.StandardCharsets;public class XxxJsonLayoutEncoder extends LayoutWrappingEncoder<ILoggingEvent> {@Overridepublic void start() {XxxJsonLayout jsonLayout = new XxxJsonLayout();jsonLayout.setContext(context);jsonLayout.setIncludeContextName(false);jsonLayout.setAppendLineSeparator(true);jsonLayout.setJsonFormatter(new JacksonJsonFormatter());jsonLayout.start();super.setCharset(StandardCharsets.UTF_8);super.setLayout(jsonLayout);super.start();}
}

应用如何接入

xxx-spring-boot-starter升级依赖版本

xxx-spring-boot-starter版本是2.7.18

<properties><xxx-spring-boot.version>2.7.18</xxx-spring-boot.version>
</properties><dependencyManagement><dependencies><dependency><groupId>com.spring.boot</groupId><artifactId>xxx-spring-boot-starter</artifactId><version>${xxx-spring-boot.version}</version></dependency></dependencies>
</dependencyManagement>

Logback日志配置

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration><springProperty scope="context" name="appName" source="spring.application.name"/><include resource="org/springframework/boot/logging/logback/defaults.xml"/><property name="STDOUT_PATTERN" value="%d [%t] %5p %c - %m%n"/><property name="log.name" value="${appName}"/><property name="log.path" value="/home/admin/logs"/><springProperty scope="context" name="appName" source="spring.application.name"/><appender class="ch.qos.logback.core.rolling.RollingFileAppender" name="BIZ_LOG"><encoder class="com.xxx.logback.XxxJsonLayoutEncoder"/><file>${log.path}/${log.name}.log</file><rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy"><fileNamePattern>${log.path}/${log.name}_%i.log</fileNamePattern><maxIndex>1</maxIndex></rollingPolicy><triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy"><maxFileSize>100MB</maxFileSize></triggeringPolicy></appender><!-- report日志异步打印appender --><appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender"><!-- 不丢失日志（默认discardingThreshold=queueSize/5，如果队列的80%已满,则会丢弃TRACT、DEBUG、INFO级别的日志 --><discardingThreshold>0</discardingThreshold><!-- 默认队列深度,该值会影响性能.默认值256 --><queueSize>256</queueSize><!-- 当队列满了之后，后面阻塞的线程想要打印的日志就直接被丢弃，从而线程不会阻塞，但有可能会丢失日志--><neverBlock>true</neverBlock><appender-ref ref="BIZ_LOG"/></appender><logger name="report" level="info" additivity="false"><appender-ref ref="ASYNC"/></logger><root level="INFO"><appender-ref ref="ASYNC"/></root></configuration>

传递业务自定义数据到日志

使用MdcUtil传递用户id、教练id、优惠券id、商品id、交易订单id、支付订单id、物流订单id、api、responseTime、responseCode、追踪id等，从用户、教练、营销、商品、交易、物流等维度观测用户的实操路径。

以Dubbo Filter举例

@Activate(group = CommonConstants.PROVIDER, order = 1)
public class DubboAccessLogFilter implements Filter {private static final Logger REPORT_LOG = LoggerFactory.getLogger("report");@Overridepublic Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {JSONObject logInfo = new JSONObject();// ...try {// 在日志输出前设置过程数据到MDC// 异步输出日志时，才需要设置MdcUtil.setTraceId();// 可选-同步/异步MdcUtil.setUserId(userId);MdcUtil.setCoachId(coachId);MdcUtil.setApi(api);MdcUtil.setResponseTime(responseTime);MdcUtil.setResponseCode(responseCode);// ...Result result = invoker.invoke(invocation);// ...return result;} finally {REPORT_LOG.info(logInfo.toJSONString());// 资源清理，需要放在日志打印后面MdcUtil.clear();}}
}

使用案例

xxx-class日志异步打印

按追踪维度查询操作日志

xxx-user日志同步打印

按api维度查询统计数据

api:"com.xxx.user.client.UserTokenApi/decodeTokenForCoach" and code:"00000"

按用户维度查询实操路径