springboot打印接口及方法出入参及实现方法级链路跟踪解决aop失效(插桩方式)

皮特猫.

已于 2023-07-03 20:09:38 修改

阅读量2.6k

点赞数

文章标签： spring boot 后端 java

于 2023-07-03 15:10:41 首次发布

本文链接：https://blog.csdn.net/qq_41214487/article/details/131515105

版权

常规aop实现打印日志出入参耗时方式

定义注解

controller日志打印注解（controller类上使用）

@Retention(RetentionPolicy.RUNTIME)
@Target(value = {ElementType.TYPE})
public @interface LogForAdaptor {
    /**是否打印参数*/
    boolean argsNeed() default true;
    /**是否打印结果*/
    boolean resultNeed() default true;
    /**是否打印耗时*/
    boolean millisecondNeed() default true;
}

method上使用

@Retention(RetentionPolicy.RUNTIME)
@Target(value = {ElementType.METHOD})
public @interface LogForMethod {
    @AliasFor("description")
    String value() default "";
    /**超过定义的耗时会打印日志,作为慢日志输出*/
    long maxSlowTime() default 0L;
    /**描述*/
    @AliasFor("value")
    String description() default "";
    /**是否打印结果*/
    boolean resultNeed() default true;
}

切面处理(支持接口上使用注解)

定义切点

1、类注解打印controller接口出入参耗时切点

public class LogForAdaptorPointcut extends StaticMethodMatcherPointcutAdvisor {
    @Override
    public boolean matches(Method method, Class<?> aClass) {
        LogForAdaptor annotation = AnnotationUtils.findAnnotation(method.getDeclaringClass(), LogForAdaptor.class);
        return Objects.nonNull(annotation);
    }
}

2、方法注解，打印方法出入参耗时切点

public class LogForMethodPointcut extends StaticMethodMatcherPointcutAdvisor {
    @Override
    public boolean matches(Method method, Class<?> aClass) {
        return AnnotatedElementUtils.hasAnnotation(method, LogForMethod.class);
    }
}

切面处理逻辑

1、controller类注解处理逻辑

@Slf4j
public class LogForAdaptorPointcutAdvice implements MethodInterceptor {
    @Override
    public Object invoke(MethodInvocation methodInvocation) throws Throwable {
        Method method = methodInvocation.getMethod();
        Class<?> clazz = method.getDeclaringClass();
        if (clazz.getDeclaredAnnotation(RestController.class) != null || clazz.getDeclaredAnnotation(Controller.class) != null) {
            LogForAdaptor logs = clazz.getDeclaredAnnotation(LogForAdaptor.class);
            boolean argsNeed = logs.argsNeed();
            boolean resultNeed = logs.resultNeed();
            boolean millisecondNeed = logs.millisecondNeed();
            //获取request
            RequestAttributes requestAttributes = RequestContextHolder.getRequestAttributes();
            //http请求的方法
            ServletRequestAttributes ra = (ServletRequestAttributes) requestAttributes;
            HttpServletRequest request;
            //请求路径
            request = ra.getRequest();
            String servletPath = request.getServletPath();
            if (argsNeed) {
                log.info("path:{},入参:{}", servletPath, Arrays.toString(methodInvocation.getArguments()));
            }
            long start = System.currentTimeMillis();
            Object result = methodInvocation.proceed();
            if (millisecondNeed) {
                long end = System.currentTimeMillis();
                log.info("path:{},处理总耗时:{}ms", servletPath, end - start);
            }
            if (resultNeed) {
                log.info("path:{},出参:{}", servletPath, JSON.toJSONString(result));
            }
            return result;
        }
        return null;
    }
}

2、方法注解处理逻辑

public class LogForMethodPointcutAdvice implements MethodInterceptor {
    @Override
    public Object invoke(MethodInvocation methodInvocation) throws Throwable {
        long start = System.currentTimeMillis();
        Method method = methodInvocation.getMethod();
        Logger logger = LoggerFactory.getLogger(method.getDeclaringClass());
        String args = Arrays.toString(methodInvocation.getArguments());
        LogForMethod logForTimeConsumer = AnnotationUtils.findAnnotation(method, LogForMethod.class);
        long milliseconds = this.getMillisecond(logForTimeConsumer);
        String description = this.getDescription(logForTimeConsumer);
        boolean resultNeed = this.getResultNeed(logForTimeConsumer);
        logger.info(description + ",method:{},方法入参:{}", method.getName(), args);
        Object result = methodInvocation.proceed();
        long end = System.currentTimeMillis();
        if (end - start > milliseconds && milliseconds != 0L) {
            logger.warn(description + ",slow.method:{},方法耗时:{}ms", method.getName(), end - start);
            if (resultNeed) {
                logger.warn(description + ",slow.method:{},方法出参:{}", method.getName(), JSON.toJSONString(result));
            }
        } else {
            logger.info(description + ", method:{},方法耗时:{}ms", method.getName(), end - start);
            if (resultNeed) {
                logger.info(description + ", method:{},方法出参:{}", method.getName(), JSON.toJSONString(result));
            }
        }
        return result;
    }

    private String getDescription(LogForMethod logForTimeConsumer) {
        return logForTimeConsumer.description();
    }

    private long getMillisecond(LogForMethod logForTimeConsumer) {
        return logForTimeConsumer.maxSlowTime();
    }

    private boolean getResultNeed(LogForMethod logForTimeConsumer) {
        return logForTimeConsumer.resultNeed();
    }
}

aop工厂注册

1、类注解

@Configuration
public class LogForAdaptorPointcutAdvisor extends AbstractBeanFactoryPointcutAdvisor {

    @Override
    public Pointcut getPointcut() {
        return new LogForAdaptorPointcut();
    }

    @Override
    public Advice getAdvice() {
        return new LogForAdaptorPointcutAdvice();
    }
}

2、方法注解

@Configuration
public class LogForMethodPointcutAdvisor extends AbstractBeanFactoryPointcutAdvisor {

    @Override
    public Pointcut getPointcut() {
        return new LogForMethodPointcut();
    }

    @Override
    public Advice getAdvice() {
        return new LogForMethodPointcutAdvice();
    }
}

常规实现方式存在的问题

由于采用spring aop的方式，可能会导致spring aop失效的场景，均会导致日志打印失效。
同类调用，这可能是常见的书写代码的方式，例如同类中方法a调用this.b(),则会导致b方法打印日志失效。

解决aop失效

常见解决方案

取巧：自身注入自己，然后拿实例调用方法，但这会造成循环依赖
启动类添加@EnableAspectJAutoProxy(exposeProxy = true)，使用AopContext.currentProxy()获取代理类，但日常开发中，为了打印个日志，还要特意注意aop失效的场景，很难受。

行之有效的解决方案

jvm动态字节码插桩实现代理(bytebuddy实现)

1、引入依赖

        <dependency>
            <groupId>net.bytebuddy</groupId>
            <artifactId>byte-buddy</artifactId>
            <version>1.11.22</version>
        </dependency>

2、定义log探针

public class LogAgent {
    private static final LogAgent INSTANCE = new LogAgent();
    private volatile AtomicBoolean isInit = new AtomicBoolean(false);

    private LogAgent() {
    }

    public static LogAgent getInstance() {
        return INSTANCE;
    }

    public void install() {
        if (!isInit.compareAndSet(false, true)) {
            TraceLog.info(LogAgent.class, ">>>>>>>>>> log agent install success >>>>>>>>>>");
            return;
        }
        synchronized (LogAgent.class) {
            ByteBuddyAgent.install();
            new AgentBuilder.Default()
                    .type(nameStartsWith("com.xxx")
                            .and(not(isAbstract())))
                    .transform((builder, typeDescription, classLoader, javaModule) ->
                            builder.method(isAnnotatedWith(LogForMethod.class)
                                            .and(not(isConstructor())))
                                    .intercept(MethodDelegation.withDefaultConfiguration().to(LogForMethodAgentAdvice.class)))
                    .type(isAnnotatedWith(LogForAdaptor.class)
                            .and(isAnnotatedWith(RestController.class)
                                    .or(isAnnotatedWith(Controller.class)))
                            .and(not(isAbstract())))
                    .transform((builder, typeDescription, classLoader, javaModule) ->
                            builder.method(
                                            not(isConstructor())
                                                    .and(not(isAnnotatedWith(LogForMethod.class))))
                                    .intercept(MethodDelegation.withDefaultConfiguration().to(LogForAdaptorAgentAdvice.class)))
                    .with(new AgentBuilder.Listener() {
                        @Override
                        public void onDiscovery(String s, ClassLoader classLoader, JavaModule javaModule, boolean b) {
                        }

                        @Override
                        public void onTransformation(TypeDescription typeDescription, ClassLoader classLoader, JavaModule module, boolean loaded, DynamicType dynamicType) {
                        }

                        @Override
                        public void onIgnored(TypeDescription typeDescription, ClassLoader classLoader, JavaModule module, boolean loaded) {
                        }

                        @Override
                        public void onError(String typeName, ClassLoader classLoader, JavaModule module, boolean loaded, Throwable throwable) {
                            TraceLog.error(LogAgent.class, "logMethod agent discovery some error typeName:{} stack errorInfo:{}", typeName, throwable);
                        }

                        @Override
                        public void onComplete(String typeName, ClassLoader classLoader, JavaModule module, boolean loaded) {
                        }
                    })
                    .installOnByteBuddyAgent();
        }
    }
}

上述代码使用cas操作是为了防止spring容器重复加载导致log探针重复定义导致生成多个代理类，最终导致重复输出日志的问题

3、自定义日志输出类解决探针内日志输出总是agent类

/**
 * @classDesc: 功能描述:(解决探针内日志输出总是agent类)
 * @date: 2022/11/21 15:30
 */
public class TraceLog {

    private static Logger logger = LoggerFactory.getLogger(TraceLog.class);

    public static boolean isDebugEnabled() {
        return logger.isDebugEnabled();
    }

    public static boolean isInfoEnabled() {
        return logger.isInfoEnabled();
    }

    public static boolean isErrorEnabled() {
        return logger.isErrorEnabled();
    }

    public static void debug(Class clazz, String msg, Object... args) {
        if (clazz != null) {
            logger = LoggerFactory.getLogger(clazz);
        }
        logger.debug(msg, args);
    }

    public static void info(Class clazz, String msg, Object... args) {
        if (clazz != null) {
            logger = LoggerFactory.getLogger(clazz);
        }
        logger.info(msg, args);
    }

    public static void warn(Class clazz, String msg, Object... args) {
        if (clazz != null) {
            logger = LoggerFactory.getLogger(clazz);
        }
        logger.warn(msg, args);
    }

    public static void error(Class clazz, String msg, Object... args) {
        if (clazz != null) {
            logger = LoggerFactory.getLogger(clazz);
        }
        logger.error(msg, args);
    }
}

4、controller探针增强

/**
 * @classDesc: 功能描述:(controller日志打印拦截器)
 * @date: 2022/11/21 15:30
 */
public class LogForAdaptorAgentAdvice {

    @RuntimeType
    @Trace
    public static Object invoke(@SuperCall Callable<?> callable,
                                @AllArguments Object args[],
                                @Origin Method method) throws Exception {

        Class<?> clazz = method.getDeclaringClass();
        LogForAdaptor logs = clazz.getDeclaredAnnotation(LogForAdaptor.class);
        boolean argsNeed = logs.argsNeed();
        boolean resultNeed = logs.resultNeed();
        boolean millisecondNeed = logs.millisecondNeed();

        //获取request
        RequestAttributes requestAttributes = RequestContextHolder.getRequestAttributes();
        //http请求的方法
        ServletRequestAttributes ra = (ServletRequestAttributes) requestAttributes;
        HttpServletRequest request;
        //请求路径
        request = ra.getRequest();
        String servletPath = request.getServletPath();
        ActiveSpan.setOperationName(String.format("服务:%s=>接口:%s", LogAgentInitProcessor.applicationName, servletPath));

        StringBuilder logArgs = new StringBuilder().append("\n");
        if (argsNeed) {
            logArgs.append(String.format("接口粒度:%s,入参:%s", servletPath, Arrays.toString(args)));
        }
        long start = System.currentTimeMillis();
        Object result = null;
        try {
            result = callable.call();
            return result;
        } finally {
            if (millisecondNeed) {
                long end = System.currentTimeMillis();
                logArgs.append("\n")
                        .append(String.format("接口粒度:%s,处理总耗时:%s ms", servletPath, end - start));
            }
            if (resultNeed) {
                logArgs.append("\n")
                        .append(String.format("接口粒度:%s,出参:%s", servletPath, JSON.toJSONString(result)));
            }

            ActiveSpan.info(logArgs.toString());
            TraceLog.info(clazz, logArgs.toString());
        }

    }
}

5、方法探针增强

/**
 * @classDesc: 功能描述:(方法级日志打印)
 * @date: 2022/11/21 15:30
 */
public class LogForMethodAgentAdvice {
    @RuntimeType
    @Trace
    public static Object invoke(@SuperCall Callable<?> callable,
                                @AllArguments Object args[],
                                @Origin Method method) throws Throwable {

        long start = System.currentTimeMillis();

        Class<?> aClass = method.getDeclaringClass();

        LogForMethod logForTimeConsumer = method.getAnnotation(LogForMethod.class);
        long milliseconds = logForTimeConsumer.maxSlowTime();
        String value = logForTimeConsumer.value();
        String description = logForTimeConsumer.value();
        String outputDes = StringUtils.isBlank(value) ? description : value;
        boolean resultNeed = logForTimeConsumer.resultNeed();
        String methodName = StringUtils.isBlank(outputDes) ? method.getName() : outputDes;

        ActiveSpan.setOperationName(String.format("服务:%s=>method:%s", LogAgentInitProcessor.applicationName, methodName));
        StringBuilder logArgs = new StringBuilder().append("\n");
        logArgs.append(String.format("method:%s,方法入参:%s", methodName, Arrays.toString(args)));
        Object result = null;
        try {
            result = callable.call();
            return result;
        } finally {
            long end = System.currentTimeMillis();

            if (end - start > milliseconds && milliseconds != 0L) {
                logArgs.append("\n")
                        .append(String.format("slow.method:%s,方法耗时:%sms", methodName, end - start));
                if (resultNeed) {
                    logArgs.append("\n")
                            .append(String.format("slow.method:%s,方法出参:%s", methodName, JSON.toJSONString(result)));
                }
            } else {
                logArgs.append("\n")
                        .append(String.format("method:%s,方法耗时:%sms", methodName, end - start));
                if (resultNeed) {
                    logArgs.append("\n")
                            .append(String.format("method:%s,方法出参:%s", methodName, JSON.toJSONString(result)));
                }
            }

            TraceLog.info(aClass, logArgs.toString());
            ActiveSpan.info(logArgs.toString());
        }

    }

}

6、log探针注入

/**
 * @classDesc: 功能描述:(log探针注入)
 * @date: 2022/11/21 15:30
 */
public class LogAgentInitProcessor implements ApplicationListener<ApplicationEnvironmentPreparedEvent> {
    public static String applicationName;

    @Override
    public void onApplicationEvent(ApplicationEnvironmentPreparedEvent event) {
        ConfigurableEnvironment environment = event.getEnvironment();
        LogAgentInitProcessor.applicationName = environment.getProperty("spring.application.name", "未识别");
        LogAgent.getInstance().install();
    }
}

7、springboot启动配置

resource下新建META-INF文件夹,在其下新建spring.factories文件，新增以下代码

org.springframework.context.ApplicationListener=\
com.xxx.LogAgentInitProcessor

至此，使用以上定义的LogForAdaptor和LogForMethod注解即可实现方法日志打印，并且可以代理static方法，解决aop失效的问题。

将带有注解的方法加入skywalking链路中实现方法级trace

上述log探针方式的实现中，@Trace注解结合ActiveSpan的方法即可实现skywalking方法级链路的追踪，同时在skywalking的链路中展示出方法的出入参，方便定位问题
skywalking需要apm-customize-enhance-plugin.jar添加到plugins中

动态插桩后的部署问题

本地jar启动时出现报错时，java -jar 修改为jdkpath/java.exe -jar 启动
容器环境中启动时报错,docker run修改为docker run --init 或者使用脚本启动
k8s 启动时报错使用脚本启动

报错原因：jvm动态插桩采用的是动态attach的方式，需要启动的pid不能为1,容器环境下，启动系统默认pid都是1，因此需要使用脚本启动或者docker --init启动守护线程以保证程序启动时不会使用pid为1

篇幅问题，不在赘述太多关于java动态字节码插桩和skywalking的知识了。