日志追踪系统实现
通过扩展 dubbo Filter, 拦截 RPC 请求的方式, 将在请求 API 时通过 SnowFlake 算法生成的全局唯一 traceId 存入到 RpcContext 中, 传递给下一个服务.
业务日志
通过 Load Time wearing 技术自动埋点, 在进入方法时, 通过 MDC 获取 traceId
接入追踪系统
- dubbo 追踪接入
<!-- fkh-service pom.xml 引入 日志追踪插件 -->
<dependency>
<groupId>com.fkhwl</groupId>
<artifactId>fkh-trace-client</artifactId>
<version>0.2</version>
</dependency>
2
3
4
5
6
- 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>
2
3
4
5
6
7
8
9
- 方法日志自动埋点
<!-- 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>
2
3
4
5
6
7
8
9
10
11
12
13
14
实现原理
自动埋点
自动埋点使用 代码织入(AOP)
代码织入实现方式
- 静态代理
- AspectJ 织入器weaver)
- compile-time weaving 使用aspectj 编译器进行编译源码
- post-compile weaving 对class 文件进行织入
- load-time weaving(LTW) 当class loader 加载类的时候, 进行织入
- AspectJ 织入器weaver)
- 动态代理
- JDK 动态代理(接口)
- 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;
}
}
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>
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>
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"/>
VM 参数
开发时, idea 设置
tomcat7
-javaagent:/path/to/spring-instrument-4.3.3.RELEASE.jar
-javaagent:/path/to/aspectjweaver-1.8.9.jar
2
tomcat8
-javaagent:/path/to/aspectjweaver-1.8.9.jar
tomcat 设置 javaagent
catalina.sh 最前面添加
JAVA_OPTS="-javaagent:/path/to/spring-instrument-4.3.3.RELEASE.jar -javaagent:/path/to/aspectjweaver-1.8.9.jar"
调用链日志
扩展 Filter
@Activate 是一个 Duboo 框架提供的注解. 在 Dubbo 官方文档上有记载: 对于集合类扩展点, 比如: Filter, InvokerListener, ExportListener, TelnetHandler, StatusChecker等, 可以同时加载多个实现. 主要用处是标注在插件接口实现类上, 用来配置该扩展实现类激活条件. 在Dubbo框架里面的Filter的各种实现类都通过Activate标注, 用来描述该Filter什么时候生效.
用 @Activate 来实现一些 Filter , 可以具体如下:
- 无条件自动激活, 直接使用默认的注解即可
import com.alibaba.dubbo.common.extension.Activate;
import com.alibaba.dubbo.rpc.Filter;
@Activate
// 无条件自动激活
public class XxxFilter implements Filter {
// ...
}
2
3
4
5
6
7
- 配置 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 {
// ...
}
2
3
4
5
6
- 只对提供方激活, 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 {
// ...
}
2
3
4
5
6
7
在 resourves/META-INF/dubbo/com.alibaba.dubbo.prc.Filter
文件中添加自定义 Filter 全类名
tracingFilter=com.fkhwl.trace.client.dubbo.TracingFilter
自定义参数在 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);
}
}
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);
}
}
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();
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();
}
}
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) {
}
}
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());
}
}
}
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
- applicationName1
root 节点下, 根据 应用名 区分不同应用 集群部署时, 相同应用名根据 host 和 port 区分, 修改某个节点, 不会影响其他节点.
其他模块接入
pom.xml 配置
添加 name
标签, 用于统一标识应用名, 使用 ${project.name}
获取 name
值
<name>应用名</name>
比如在 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>
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>
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>
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>
2
3
4
5
最后在 applicationContext.xml 引入 fkh-config.xml
<import resource="classpath:fkh-config.xml"/>
日志节点监控和修改日志接口
监控
接口
- 获取所有应用列表
- 应用的当前日志级别 (root, com.fkhwl)
- 修改某个应用的日志 (root, com.fkhwl)
- 修改全部应用的日志 (root, com.fkhwl)
- 重置全部日志级别
日志类型
日志类型 | 说明 |
---|---|
normal | 正常入库日志 |
invoke_interface | api调用日志 |
middleware_opt | 中间件操作日志(目前仅支持hbase和mongo) |
job_execute | job执行日志 |
rpc_trace | rpc trace跟踪日志 |
custom_log | 自定义埋点日志 |
thirdparty_call | 第三方系统调用日志 |
正常日志
LOGGER.info("我是测试日志打印")
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());
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());
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());
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());
2
3
4
5