Use JavaAgent to implement code invasion-free enhanced LogBack

• preface
• Strengthen the logback
• Web interceptor configuration
• Write javaAgent program
• Making javaagent package
• test
• conclusion

preface

Program running log is very important for troubleshooting system problems, business monitoring, etc. Java logging is mostly realized by logback, Log4J and other frameworks. I packaged a log plug-in package according to the company’s log specification before, and the system needs to integrate toolkit and print logs according to the log printing specification. The operation and maintenance system uses FileBeat to collect logs to ES, and develops ELK (ES, LogSTah, Kibana) to view logs. But some of the very old and big system is not integrated logging toolkit, and for some reason has not, this leads to some problems, for example, on the query log data processing failure is very difficult, because there is no process in the log traceId context, this means that the printing of all is broken, There’s no way to do a link trace. Every troubleshooting problem is simply not too painful; In addition, for some interfaces, it is not possible to visualize the interface execution time in the log. Arthas can be used to record the interface execution time, but it is not appropriate to use Arthas every time you want to check the interface execution time. Is there a way to add traceId and time to the system log without reinventing the system to zero intrusion into the business code? Of course, this article will introduce the implementation of business system code without intrusion enhanced log through JavaAgent technology + bytecode enhanced Logback (logback, LOG4J can also be enhanced) Logger.

Strengthen the logback

First, we define the storage of traceId to realize the ability to add traceId to the log content. We define a class. I named TraceContext and defined it as the context of the link. TraceContext: ThreadLocal is used to store traceids. ThreadLocal is used to store traceids, but ThreadLocal is used for thread isolation.

/ * * *@author liupenghui
 * @date 2021/10/8 5:30 下午
 */
public class TraceContext {

    /** * Store thread traceId */
    private static final ThreadLocal<String> TRANSMITTABLE_THREAD_LOCAL = new ThreadLocal<>();

    /** * if a ThreadLocal has a traceId, then a new * is generated@return traceId
     */
    public static String getTraceId(a) {
        String traceId = TRANSMITTABLE_THREAD_LOCAL.get();
        if (StringUtils.isNotBlank(traceId)) {
            return traceId;
        } else {
            // Simple use of UUID, you can use the snowflake algorithm, I am here to simplify, roughly demonstrate the meaning, not industrial applications
            traceId = UUID.randomUUID().toString();
            TRANSMITTABLE_THREAD_LOCAL.set(traceId);
            returntraceId; }}/** * Delete traceId from ThreadLocal
    public static void remove(a) { TRANSMITTABLE_THREAD_LOCAL.remove(); }}Copy the code

Then enhance the Logger of logback. Here I use the open source tool TLog to enhance bytecode using Javassit. The code is as follows:

public class AspectLogEnhance {

    public static void enhance(a) {
        try {
            CtClass cc = null;
            try {
                ClassPool pool = ClassPool.getDefault();
                // Import the custom logback enhancement class LogbackBytesEnhance
                pool.importPackage("org.agent.enhance.bytes.logback.LogbackBytesEnhance");
                / / enhancement class, ch. Qos. Logback. Classic. The Logger
                cc = pool.get("ch.qos.logback.classic.Logger");
                if(cc ! =null) {
                    // The method of enhancement
                    CtMethod ctMethod = cc.getDeclaredMethod("buildLoggingEventAndAppend");
                    / / method body, enhanced LogbackBytesEnhance. Enhance their implementation
                    ctMethod.setBody("{return LogbackBytesEnhance.enhance($1, $2, $3, $4, $5, $6, this); }");
                    cc.toClass();
                    System.out.println("Locakback log enhancement succeeded"); }}catch (Exception e) {
                e.printStackTrace();
                System.out.println("Locakback log enhancement failed"); }}catch(Throwable t) { t.printStackTrace(); }}}Copy the code

Org. Agent. Enhance the bytes. Logback. LogbackBytesEnhance code is as follows:

public class LogbackBytesEnhance {


    / * * * to enhance ch. Qos. Logback. Classic. Logger buildLoggingEventAndAppend method *@param fqcn
     * @param marker
     * @param level
     * @param msg
     * @param params
     * @param t
     * @param logger
     */
    public static void enhance(final String fqcn, final Marker marker, final Level level, final String msg, final Object[] params,
                               final Throwable t, Logger logger) {
        // Log content
        String resultLog;
        / / generated traceId
        if (StringUtils.isNotBlank(TraceContext.getTraceId())) {
            // Concatenate the traceId with the log content. This is the key point. This is where the trceId is generated and concatenated to the log content
            resultLog = StrUtil.format("{} {}", TraceContext.getTraceId(), msg);
        } else {
            resultLog = msg;
        }
        / / enhance buildLoggingEventAndAppend
        LoggingEvent loggingEvent = newLoggingEvent(fqcn, logger, level, resultLog, t, params); loggingEvent.setMarker(marker); logger.callAppenders(loggingEvent); }}Copy the code

Web interceptor configuration

My program is based on SpringMVC, so I need to configure the interceptor for Http requests. If the interface is Dubbo, SpringCloud and other RPC frameworks can also use the Filter or interceptor provided by them. I will implement the interceptor configuration of SpringMVC first. The interceptor configuration code is as follows:

SpringWebInterceptorConfiguration

/ * * *@author liupenghui
 * @date2021/10/9 5:45pm */
@Configuration
// This configuration is loaded only with WebMvcConfigurer
@ConditionalOnClass(name = {"org.springframework.web.servlet.config.annotation.WebMvcConfigurer"})
public class SpringWebInterceptorConfiguration {

    private static final Logger log = LoggerFactory.getLogger(SpringWebInterceptorConfiguration.class);

    @Bean
    public WebMvcConfiguration addWebInterceptor(a) {
        log.info("Define Web interceptors");
        return newWebMvcConfiguration(); }}Copy the code

WebMvcConfiguration adds interceptors

The following code implements the WebMvcConfigurer interface and overwrites the addInterceptors method to addInterceptors. Here, two interceptors are added, one to clean up the traceId in TraceContext and the other to record the execution time of the interface.

/ * * *@author liupenghui
 * @date 2021/10/11 9:43 上午
 */
public class WebMvcConfiguration implements WebMvcConfigurer {

    private static final Logger log = LoggerFactory.getLogger(WebMvcConfiguration.class);

    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        InterceptorRegistration interceptorRegistration;
        log.info("Add interceptor");
        // Intercepted request path
        interceptorRegistration = registry.addInterceptor(new WebInterceptor()).addPathPatterns("/ *");
        Springboot 1.5.X does not have an order method
        try{
            Method method = ReflectUtil.getMethod(InterceptorRegistration.class, "order", Integer.class);
            if(ObjectUtil.isNotNull(method)){ method.invoke(interceptorRegistration, Ordered.HIGHEST_PRECEDENCE); }}catch (Exception e){
            e.printStackTrace();
            log.info("TraceId interceptor load failed");
        }
        interceptorRegistration = registry.addInterceptor(new TimeInterceptor()).addPathPatterns("/ *");
        Springboot 1.5.X does not have an order method
        try{
            Method method = ReflectUtil.getMethod(InterceptorRegistration.class, "order", Integer.class);
            if(ObjectUtil.isNotNull(method)){ method.invoke(interceptorRegistration, Ordered.HIGHEST_PRECEDENCE); }}catch (Exception e){
            e.printStackTrace();
            log.info("Time-consuming interceptor load failed"); }}}Copy the code

Configure the Springboot autowler and create the spring.factories under the resource/ meta-INF directory as follows:

org.springframework.boot.autoconfigure.EnableAutoConfiguration=\
  org.agent.config.SpringWebInterceptorConfiguration
Copy the code

TraceId Clears interceptors

/ * * *@author liupenghui
 * @date 2021/10/9 6:29 下午
 */
public class WebInterceptor implements HandlerInterceptor {

    private static final Logger log = LoggerFactory.getLogger(WebInterceptor.class);

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        log.info("Intercept the request");
        response.addHeader("traceId", TraceContext.getTraceId());
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        HandlerInterceptor.super.postHandle(request, response, handler, modelAndView);
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        log.info("Clean up the traceId"); TraceContext.remove(); }}Copy the code

Interface time interceptor

/ * * *@author liupenghui
 * @date 2021/10/8 1:34 下午
 */
public class TimeInterceptor implements HandlerInterceptor {

    private static final Logger log = LoggerFactory.getLogger(TimeInterceptor.class);

    private static final ThreadLocal<StopWatch> STOP_WATCH_THREAD_LOCAL = new ThreadLocal<>();

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {
        String url = request.getRequestURI();
        String parameters = JSON.toJSONString(request.getParameterMap());
        log.info("Start request URL[{}] with: {}", url, parameters);
        StopWatch stopWatch = new StopWatch();
        STOP_WATCH_THREAD_LOCAL.set(stopWatch);
        stopWatch.start();
        return true;
    }

    @Override
    public void postHandle(HttpServletRequest request, HttpServletResponse response, Object handler, ModelAndView modelAndView) throws Exception {
        HandlerInterceptor.super.postHandle(request, response, handler, modelAndView);
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {
        StopWatch stopWatch = STOP_WATCH_THREAD_LOCAL.get();
        stopWatch.stop();
        log.info("End the call to URL[{}] in {} ms", request.getRequestURI(), stopWatch.getTime()); STOP_WATCH_THREAD_LOCAL.remove(); }}Copy the code

Write javaAgent program

Logback enhancements and HTTP interface interception capabilities are already in place, so all you need to do is write the JavaAgent, which is as simple as aspectLogenance.enhance () in the premain method; The code is as follows:

/ * * *@author liupenghui
 * @date 2021/10/8 11:21 上午
 */
public class PreAgent {

    public static void premain(String args, Instrumentation inst) { AspectLogEnhance.enhance(); }}Copy the code

The details of JavaAgent technology are not introduced here, but you can refer to the javaAgent usage guide in the article I reprinted

Making javaagent package

The program is packaged using Maven, and the plug-in package is as follows

<build>
        <finalName>java-agent</finalName>
        <plugins>
            <plugin>
                <artifactId>maven-deploy-plugin</artifactId>
                <configuration>
                    <skip>true</skip>
                </configuration>
            </plugin>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-shade-plugin</artifactId>
                <version>1.4</version>
                <executions>
                    <execution>
                        <phase>package</phase>
                        <goals>
                            <goal>shade</goal>
                        </goals>
                        <configuration>
                            <keepDependenciesWithProvidedScope>true</keepDependenciesWithProvidedScope>
                            <promoteTransitiveDependencies>false</promoteTransitiveDependencies>
                            <createDependencyReducedPom>true</createDependencyReducedPom>
                            <minimizeJar>false</minimizeJar>
                            <createSourcesJar>true</createSourcesJar>

                            <transformers>
                                <transformer
                                        implementation="org.apache.maven.plugins.shade.resource.ManifestResourceTransformer">
                                    <manifestEntries>
                                        <Premain-Class>org.agent.PreAgent</Premain-Class>
                                    </manifestEntries>
                                </transformer>
                            </transformers>
                        </configuration>
                    </execution>
                </executions>
            </plugin>
        </plugins>
    </build>
Copy the code

test

Write test program

/ * * *@author liupenghui
 * @date 2021/10/8 4:34 下午
 */
@SpringBootApplication
@RestController
public class Application {

    private static final Logger log = LoggerFactory.getLogger(Application.class);

    public static void main(String[] args) throws Exception {
        new SpringApplication(Application.class).run(args);
    }

    @GetMapping("/hello")
    public String hello(a) {
        log.info("Test Log 1");
        log.info("Test Log 2");
        log.info("Test Log 3");
        log.info("Test Log 4");
        return "11 + hello"; }}Copy the code

The test results

No logging enhanced by JavaAgent

The test result without log enhancement is shown in the figure below. I called the interface four times, and the log printed by the interface did not contain traceId. As you can imagine, it would be very difficult to find the problem in the business system log.

Enhanced logging effects through JavaAgent

• Program start parameter adds JavaAgent

Method one:

Direct IDEA setup program startup parameters, as shown below:

Method 2:

Java-javaagent: Your path /java-agent.jar -jar Your path /java-agent-test.jar

I adopted method 1 here, and the test results are shown as follows:

As you can see in the red box, a random string is added to the log content. This is the traceId we added, and the interceptor does its job, recording the interface execution time, and clearing the traceId of the current thread after the interface execution.

conclusion

Javaagent and bytecode enhancement techniques have been used to implement invastion-free logging, but there are some limitations to this. The problem I have encountered is that there is no way to implement asynchronous logging, for example, how to do link tracing of asynchronous logs. Because I realize before logging toolkit by com. Alibaba. TTL. TransmittableThreadLocal rewrite MDCAdapter and modify the way a thread pool is can realize asynchronous log, but I now this way is not support for the MDC.