日志追踪系统实现


12/13/2017 dubbo

通过扩展 dubbo Filter, 拦截 RPC 请求的方式, 将在请求 API 时通过 SnowFlake 算法生成的全局唯一 traceId 存入到 RpcContext 中, 传递给下一个服务.

业务日志

通过 Load Time wearing 技术自动埋点, 在进入方法时, 通过 MDC 获取 traceId

接入追踪系统

  1. dubbo 追踪接入
<!-- fkh-service pom.xml 引入 日志追踪插件 -->
<dependency>
        <groupId>com.fkhwl</groupId>
        <artifactId>fkh-trace-client</artifactId>
        <version>0.2</version>
</dependency>
1
2
3
4
5
6
  1. http 追踪接入
<!-- web.xml 添加 -->
<filter>
        <filter-name>controllerFilter</filter-name>
        <filter-class>com.fkhwl.trace.client.rest.LoggerFilter</filter-class>
</filter>
<filter-mapping>
        <filter-name>controllerFilter</filter-name>
        <url-pattern>/*</url-pattern>
</filter-mapping>
1
2
3
4
5
6
7
8
9
  1. 方法日志自动埋点
<!-- META-INFO/aop.xml-->
<?xml version="1.0" encoding="UTF-8"?>
<aspectj>
    <weaver>
        <!-- only weave classes in your application-specific packages -->
        <include within="com.fkhwl.fkhserver.rest.resource.impl.*"/>
    </weaver>
    <aspects>
        <!-- weave in just these aspects -->
        <!--<aspect name="com.fkhwl.trace.client.aspect.ProfilingAspect"/>-->
        <aspect name="com.fkhwl.fkhserver.rest.aspect.ProfilingAspect"/>
        <aspect name="com.fkhwl.fkhserver.rest.aspect.TraceAspect"/>
    </aspects>
</aspectj>
1
2
3
4
5
6
7
8
9
10
11
12
13
14

实现原理

自动埋点

自动埋点使用 代码织入(AOP)

代码织入实现方式

  1. 静态代理
    1. AspectJ 织入器weaver)
      1. compile-time weaving 使用aspectj 编译器进行编译源码
      2. post-compile weaving 对class 文件进行织入
      3. load-time weaving(LTW) 当class loader 加载类的时候, 进行织入
  2. 动态代理
    1. JDK 动态代理(接口)
    2. CGlib(类)

这里使用 Load Time wearing 实现, 这种方式在类加载器织入代码. 编译器织入, 会造成编译速度变慢, 而且必须使用 ajc 编译器 动态代理会生成大量代理类, 加速内存消耗 使用类加载期织入相对于其他两种方式,更加轻便.

具体实现

定义切面
@Aspect
public class TraceAspect {
    private static final Logger log = LoggerFactory.getLogger(TraceAspect.class);
    @Pointcut("execution(* com.fkhwl.fkhserver.rest.resource.impl..*.*(..))")
    public void profileMethod() {

    }
    @Around("profileMethod()")
    public Object profile(ProceedingJoinPoint jp) {
        Object result = "";
        String methodName = jp.getSignature().getName();
        log.error("前置通知");
        //执行目标方法
        try {
            //前置通知
            log.error("The method " + methodName + " begins with " + Arrays.asList(jp.getArgs()));
            result = jp.proceed();
            //返回通知
            log.error("The method " + methodName + " ends with " + Arrays.asList(jp.getArgs()));
        } catch (Throwable e) {
            //异常通知
            log.error("The method " + methodName + " occurs expection : " + e);
            throw new RuntimeException(e);
        }
        log.error("get MDC {}", MDC.get(Span.TRACE_ID));
        return result;
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
准备 aop.xml

这个文件要求放在META-INF/aop.xml路径下, 以告知AspectJ Weaver我们需要把ProfilingAspect织入到应用的哪些类中

<?xml version="1.0" encoding="UTF-8"?>
<aspectj>
    <weaver>
        <!-- only weave classes in your application-specific packages -->
        <include within="com.fkhwl.fkhserver.rest.resource.impl.*"/>
        <!-- 必须包含切面的路径 -->
        <include within="com.fkhwl.trace.client.aspect.*"/>
    </weaver>
    <aspects>
        <!-- weave in just these aspects -->
        <aspect name="com.fkhwl.trace.client.aspect.TraceAspect"/>
    </aspects>
</aspectj>
1
2
3
4
5
6
7
8
9
10
11
12
13
maven 依赖
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjweaver</artifactId>
    <version>1.8.9</version>
</dependency>
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-aop</artifactId>
    <version>${spring-version}</version>
</dependency>
1
2
3
4
5
6
7
8
9
10
配置 applicationContext.xml

aspectj-weaving = on / off / auto-detect 如果设置为 auto-detect(默认), spring 将会在 classpath 中查找 aspejct 需要的 META-INF/aop.xml, 如果找到则开启 aspectj weaving

<context:load-time-weaver aspectj-weaving="autodetect"/>
1
VM 参数

开发时, idea 设置

tomcat7

-javaagent:/path/to/spring-instrument-4.3.3.RELEASE.jar 
-javaagent:/path/to/aspectjweaver-1.8.9.jar
1
2

tomcat8

-javaagent:/path/to/aspectjweaver-1.8.9.jar
1
tomcat 设置 javaagent

catalina.sh 最前面添加

JAVA_OPTS="-javaagent:/path/to/spring-instrument-4.3.3.RELEASE.jar -javaagent:/path/to/aspectjweaver-1.8.9.jar" 
1

调用链日志

扩展 Filter

@Activate 是一个 Duboo 框架提供的注解. 在 Dubbo 官方文档上有记载: 对于集合类扩展点, 比如: Filter, InvokerListener, ExportListener, TelnetHandler, StatusChecker等, 可以同时加载多个实现. 主要用处是标注在插件接口实现类上, 用来配置该扩展实现类激活条件. 在Dubbo框架里面的Filter的各种实现类都通过Activate标注, 用来描述该Filter什么时候生效.

用 @Activate 来实现一些 Filter , 可以具体如下:

  1. 无条件自动激活, 直接使用默认的注解即可
import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.Filter;
@Activate 
// 无条件自动激活
public class XxxFilter implements Filter {
    // ...
}
1
2
3
4
5
6
7
  1. 配置 xxx 参数, 并且参数为有效值时激活, 比如配了cache=”lru”, 自动激活 CacheFilter
import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.Filter;
@Activate("xxx") // 当配置了xxx参数, 并且参数为有效值时激活, 比如配了cache="lru", 自动激活CacheFilter. 
public class XxxFilter implements Filter {
    // ...
}
1
2
3
4
5
6
  1. 只对提供方激活, group 可选 provider 或 consumer
import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.Filter;
@Activate(group = {Constants.PROVIDER, Constants.CONSUMER})
// 只对提供方激活, group可选"provider"或"consumer"
public class XxxFilter implements Filter {
    // ...
}
1
2
3
4
5
6
7

resourves/META-INF/dubbo/com.alibaba.dubbo.prc.Filter 文件中添加自定义 Filter 全类名

tracingFilter=com.fkhwl.trace.client.dubbo.TracingFilter
1

自定义参数在 RPC 请求的传递

使用 aop, 在 调用 dubbo 服务之前, 通过 RpcContext.getContext().setAttachments 保存自定义参数 在服务端使用 RpcContext.getContext().getAttachment 获取自定义参数

RpcContext 是一个 ThreadLocal 的临时状态记录器, 当接收到 RPC 请求, 或发起 RPC 请求 时, RpcContext 的状态都会变化. 比如: A 调 B, B 再调 C, 则 B 机器上, 在 B 调 C 之 前, RpcContext 记录的是 A 调 B 的信息, 在 B 调 C 之后, RpcContext 记录的是 B 调 C 的 信息.

/** 
 * 在调用service的接口之前, 加入一些dubbo的隐式参数 
 * 2017-12-13 17:34 dong4j 
 */  
@Aspect  
@Component  
public class DubboServiceContextAop {  
  
    @Pointcut("execution(* com.xxx.xxx.service.*.*(..))")  
    public void serviceApi() {  
    }  
  
    @Before("serviceApi()")  
    public void dubboContext(JoinPoint jp) {  
        Map<String, String> context = new HashMap<>();  
        // todo you want do  
        RpcContext.getContext().setAttachments(context);  
    }   
} 

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
public class DubboContextFilter implements Filter {  
    @Override  
    public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {  
        String var= RpcContext.getContext().getAttachment(Aop中放入的);  
        //todo 其他相关处理  
        return invoker.invoke(invocation);  
    }  
} 

1
2
3
4
5
6
7
8
9

RpcContext 相关 API

// 远程调用
xxxService.xxx();
// 本端是否为消费端, 这里会返回true
boolean isConsumerSide = RpcContext.getContext().isConsumerSide();
// 获取最后一次调用的提供方IP地址
String serverIP = RpcContext.getContext().getRemoteHost();
// 获取当前服务配置信息, 所有配置信息都将转换为URL的参数
String application = RpcContext.getContext().getUrl().getParameter("application");
// 注意: 每发起RPC调用, 上下文状态会变化
yyyService.yyy();
1
2
3
4
5
6
7
8
9
10
public class XxxServiceImpl implements XxxService {
public void xxx() {
    // 本端是否为提供端, 这里会返回true
    boolean isProviderSide = RpcContext.getContext().isProviderSide();
    // 获取调用方IP地址
    String clientIP = RpcContext.getContext().getRemoteHost();
    // 获取当前服务配置信息, 所有配置信息都将转换为URL的参数
    String application = RpcContext.getContext().getUrl().getParameter("applicatio
    n");
    // 注意: 每发起RPC调用, 上下文状态会变化
    yyyService.yyy();
    // 此时本端变成消费端, 这里会返回false
    boolean isProviderSide = RpcContext.getContext().isProviderSide();
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15

traceId 的传递过程

生成 traceId

在处理前端请求之前, 使用 LoggerFilter 拦截请求, 通过 SnowFlake 生成 traceId, 并存入 MDC 中

@Slf4j
public class LoggerFilter extends AbstractRequestLoggingFilter {
    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
                                    final FilterChain filterChain)
        throws ServletException, IOException {
        final String traceId = "" + new SnowflakeId(0).generate();
        MDC.put(Span.TRACE_ID, traceId);
    
        ...
        super.doFilterInternal(request, response, filterChain);
        ...
        log.error(ApiLog.buildApiLog(EventType.invoke_interface, request.getRequestURI(), request.getHeader("token"), response.getStatus(), EventLog.MONITOR_STATUS_SUCCESS, "我是mock api成功日志").toString());
        // 请求处理完成后清理 MDC 中的值
        MDC.remove(Span.TRACE_ID);
    }
    @Override
    protected void beforeRequest(HttpServletRequest request, String message) {
    }
    
    @Override
    protected void afterRequest(HttpServletRequest request, String message) {
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
服务间传递 traceId

存放在 MDC 中的值只有在同一个线程中才能共享, 当发起 Rpc 调用后, 肯定不是同一个线程, 因此使用 RpcContext 来传递 Rpc traceId

服务调用之前, 消费者端

通过 RpcContext.getContext().setAttachments("traceId",MDC.get("traceId")) 将 traceId 存入 RpcContext

服务调用之后, 提供者端

通过 RpcContext.rpcContext.getAttachment("traceId") 从 RpcContext 中获取 traceId, 并使用 MDC.put("traceId", traceId) 将 traceId 存入当前线程中, 便于业务日志打印

删除 traceId

请求完成后, dubbo 服务线程自动销毁, 只需要在 LoggerFilter 中调用 MDC.clear() 清除 MDC

传输日志

kafka

http://blog.csdn.net/honglei915/article/details/37563647

动态修改日志级别

这里选择使用 JMX 来实现日志级别动态修改.

具体实现

监听容器启动

当容器启动时, 获取应用名, 然后创建 zookeeper 临时节点

以前使用 ServerListener 实现, 但是这种方式需要修改 web.xml, 添加一个自定义 ServerListener 监听器.

这里重构下, 将监听容器启动然后创建 zookeeper 节点的逻辑迁入到 fkh-trace 模块中

@Component
@Slf4j
public class ApplicationEventHandle implements ApplicationListener, ApplicationContextAware {
    @Autowired
    private TraceConfig traceConfig;
    // 注入 ServletContext
    @Autowired
    private ServletContext servletContext;


    /**
     * Sets application context.
     * 获取应用上下文, 从而获取 speing 管理的 bean
     * @param applicationContext the application context
     * @throws BeansException the beans exception
     */
    @Override
    public void setApplicationContext(ApplicationContext applicationContext) throws BeansException {    }
    
    /**
     * On application event.
     * 监听应用启动事件
     * @param applicationEvent the application event
     */
    @Override
    public void onApplicationEvent(ApplicationEvent applicationEvent) {
        if (applicationEvent instanceof ContextRefreshedEvent) {
            ContextRefreshedEvent contextRefreshedEvent = (ContextRefreshedEvent) applicationEvent;
            //root application context 没有parent, 他就是老大.
            if (contextRefreshedEvent.getApplicationContext().getParent() == null) {
                //需要执行的逻辑代码, 当spring容器初始化完成后就会执行该方法. 
                log.error("spring 容器初始化完成: {}", applicationEvent.getClass());
    
                // 获取 ServletContext 容器未初始化完成, 使用这种方式会报空指针
                // WebApplicationContext webApplicationContext = ContextLoader.getCurrentWebApplicationContext();
                // ServletContext servletContext = webApplicationContext.getServletContext();
                DynamicChangeLogLevel.initZookeeperNode(traceConfig.getZookeeperHost(), servletContext
                    .getServletContextName());
            }
        } // 应用启动, 需要在代码动态添加监听器才可捕获
        else if (applicationEvent instanceof ContextStartedEvent) {
            log.error("应用启动事件: {}", applicationEvent.getClass());
        }
        // 应用停止(context.stop();)
        else if (applicationEvent instanceof ContextStoppedEvent) {
            log.error("应用停止事件: {}", applicationEvent.getClass());
            // 防止动态修改日志级别时内存溢出
            LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
            loggerContext.stop();
        }
        // 应用关闭(强制 stop)
        else if (applicationEvent instanceof ContextClosedEvent) {
            log.error("应用关闭事件: {}", applicationEvent.getClass());
        } else {
            log.error("其他事件: {}", applicationEvent.getClass());
        }
    }
}
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58

zk 节点组成

  • loglevel
    • applicationName1
      • serviceHost1:servicePort1 --> data = defaultLogLevel
      • serviceHost2:servicePort2 --> data = defaultLogLevel
    • applicationName2
      • serviceHost1:servicePort1 --> data = defaultLogLevel

root 节点下, 根据 应用名 区分不同应用 集群部署时, 相同应用名根据 host 和 port 区分, 修改某个节点, 不会影响其他节点.

其他模块接入

pom.xml 配置

添加 name 标签, 用于统一标识应用名, 使用 ${project.name} 获取 name

<name>应用名</name>
1

比如在 logback.xml 中, 向 JMX 注册 MBean, 需要标识当前应用名 logback.xml 配置

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <!-- 设置别名 必须在 <jmxConfigurator/> 之前设置 -->
    <contextName>${project.name}</contextName>
    <!--JMX监控-->
    <jmxConfigurator/>
    <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener"/>
    <!-- MDC 处理 -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}] [%thread] %-5level %logger{5} - %X{traceId} - %X{platformType} - %X{clientVersion} - %msg%n
            </pattern>
            <charset>UTF-8</charset>
        </encoder>
    </appender>
    <root level="DEBUG">
        <appender-ref ref="STDOUT"/>
        <!--<appender-ref ref="FILE" />-->
    </root>
    <logger name="com.fkhwl" level="DEBUG"/>
</configuration>
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21

只需要在 web.xml 添加以下配置, 用于标识当前应用

<display-name>应用名</display-name>
<context-param>
    <param-name>webAppRootKey</param-name>
    <param-value>应用名</param-value>
</context-param>
1
2
3
4
5

为了便于管理应用名, 这里使用 pom.xml 中的 name 标签来设置 web.xml 中的设置

在 pom.xml 中添加 maven-war-plugin 插件

<plugin>
    <groupId>org.apache.maven.plugins</groupId>
    <artifactId>maven-war-plugin</artifactId>
    <version>2.6</version>
    <configuration>
        <webResources>
            <resource>
                <directory>src/main/webapp</directory>
                <filtering>true</filtering>
            </resource>
        </webResources>
    </configuration>
</plugin>
1
2
3
4
5
6
7
8
9
10
11
12
13

然后 web.xml 的配置就可以修改为

<display-name>${project.name}</display-name>
<context-param>
    <param-name>webAppRootKey</param-name>
    <param-value>${project.name}</param-value>
</context-param>
1
2
3
4
5

最后在 applicationContext.xml 引入 fkh-config.xml

<import resource="classpath:fkh-config.xml"/>
1

日志节点监控和修改日志接口

监控

接口

  1. 获取所有应用列表
  2. 应用的当前日志级别 (root, com.fkhwl)
  3. 修改某个应用的日志 (root, com.fkhwl)
  4. 修改全部应用的日志 (root, com.fkhwl)
  5. 重置全部日志级别

日志类型

日志类型 说明
normal 正常入库日志
invoke_interface api调用日志
middleware_opt 中间件操作日志(目前仅支持hbase和mongo)
job_execute job执行日志
rpc_trace rpc trace跟踪日志
custom_log 自定义埋点日志
thirdparty_call 第三方系统调用日志

正常日志

LOGGER.info("我是测试日志打印")
1

api日志

// 参数依次为EventType(事件类型)、api、账号、请求耗时、成功还是失败、具体自定义的日志内容
LOGGER.info(ApiLog.buildApiLog(EventType.invoke_interface, "/app/status", "800001", 100, EventLog.MONITOR_STATUS_SUCCESS, "我是mock api成功日志").toString());
LOGGER.info(ApiLog.buildApiLog(EventType.invoke_interface, "/app/status", "800001", 10, EventLog.MONITOR_STATUS_FAILED, "我是mock api失败日志").toString());
1
2
3

中间件日志

// 参数依次为EventType(事件类型)、MiddleWare(中间件名称)、操作耗时、成功还是失败、具体自定义的日志内容
LOGGER.info(EventLog.buildEventLog(EventType.middleware_opt, MiddleWare.HBASE.symbol(), 100, EventLog.MONITOR_STATUS_SUCCESS, "我是mock middle ware成功日志").toString());
LOGGER.info(EventLog.buildEventLog(EventType.middleware_opt, MiddleWare.MONGO.symbol(), 10, EventLog.MONITOR_STATUS_FAILED, "我是mock middle ware失败日志").toString());
1
2
3

job执行日志

// job执行仅仅处理失败的日志(成功的不做处理, 所以只需要构造失败的日志), 参数依次为EventType(事件类型)、job 的id号、操作耗时、失败、具体自定义的日志内容
LOGGER.info(EventLog.buildEventLog(EventType.job_execute, "application_1477705439920_0544", 10, EventLog.MONITOR_STATUS_FAILED, "我是mock job exec失败日志").toString());
1
2

第三方请求日志

// 参数依次为EventType(事件类型)、第三方名称、操作耗时、成功还是失败、具体自定义的日志内容
LOGGER.info(EventLog.buildEventLog(EventType.thirdparty_call, "xx1", 100, EventLog.MONITOR_STATUS_FAILED, "我是mock third 失败日志").toString());
LOGGER.info(EventLog.buildEventLog(EventType.thirdparty_call, "xx1", 100, EventLog.MONITOR_STATUS_SUCCESS, "我是mock third 成功日志").toString());
LOGGER.info(EventLog.buildEventLog(EventType.thirdparty_call, "xx2", 100, EventLog.MONITOR_STATUS_SUCCESS, "我是mock third 成功日志").toString());
LOGGER.info(EventLog.buildEventLog(EventType.thirdparty_call, "xx2", 100, EventLog.MONITOR_STATUS_FAILED, "我是mock third 失败日志").toString());
1
2
3
4
5
Last Updated: 7/3/2019, 6:22:52 PM