背景

随着应用的请求量上升，日志输出量也会成线性比例的上升，给磁盘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;

/**
 * @author hadesy
 */
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";

    @Override
    protected 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 timestamp
        map.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()
                || "N/A".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> {
    @Override
    public 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");

    @Override
    public 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"

按用户维度查询实操路径