How to record call logs with low intrusion

Preface

A few days ago, his friend’s boss asked him to implement such a function, which is to record the interface request response log every time with a low intrusion, and then count the success and failure times of each request call, and the response time. At that time, my friend’s realization idea was in every request. Add a custom annotation to the method of the controller of a business, and then write an aop to record the log with this custom annotation as a pointcut.

This kind of AOP+ annotations to achieve log records should be a very common implementation. However, when my friends landed, they found that the project had too many places to add custom annotations. I'll tell him later, then don't write a comment, just use the form as follows

execution(* com.github.lybgeek.logaop.service..*.*(..))

Isn't this okay? He said that his boss wanted to use this function for each project team. Like my method above, it might not work. I asked him why it didn’t work. He said that the package name of each project is different. Thinking, he said that poincut must not be written like this in the code

execution(* com.github.lybgeek.a.service..*.*(..) 
|| * com.github.lybgeek.b.service..*.*(..) || * com.github.lybgeek.c.service..*.*(..) )

So every time you add a new log record, you have to change the aspect code, it's better to use custom annotations. After listening to his explanation, I got a black question mark face. So I took advantage of the 5.1 holiday period to write a demo to achieve the above requirements

Business scene

Low intrusive recording interface request response log for each request, and then count the success, failure times and response time of each request call

This business needs should be very simple and difficult to achieve is that minimally invasive , minimally invasive mentioned, my first thought is without the user having to write code, or simply write a small amount of code, or just a simple configuration, it is best to do No perception of business.

Means of realization

I provide 2 ideas here

• javaagent + byte-buddy
• springboot automatic assembly + AOP

javaagent

1. What is javaagent

Javaagent is a simple and elegant java agent. It can intercept or enhance the class by using java's own instrument feature + javassist/byte-buddy bytecode.

javaAgent is an interceptor that runs before the main method. Its default method is called premain, which means that the premain method is executed first and then the main method is executed.

2. How to implement a javaagent

• a. The premain method must be implemented

Example:

public class AgentDemo {

    public static void premain(String agentArgs, Instrumentation inst) {
        System.out.println("agentArgs : " + agentArgs);
        inst.addTransformer(new DefineTransformer(),true);
    }

    static class DefineTransformer implements ClassFileTransformer {

        @Override
        public byte[] transform(ClassLoader loader, String className, Class<?> classBeingRedefined, ProtectionDomain protectionDomain, byte[] classfileBuffer) throws IllegalClassFormatException {
            System.out.println("premain load Class:" + className);
            return classfileBuffer;
        }
    }
}

• b. Add the MANIFEST.MF file in the META-INF directory, the content is as follows

Manifest-Version: 1.0
Implementation-Version: 0.0.1-SNAPSHOT
Premain-Class: com.github.lybgeek.agent.ServiceLogAgent
Can-Redefine-Classes: true

Among them, Premain-Class is a required option. MANIFEST.MF can be generated using the maven plug-in, the plug-in is as follows

 <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-jar-plugin</artifactId>
                <version>3.2.0</version>
                <configuration>
                    <archive>
                        <manifest>
                            <addClasspath>true</addClasspath>
                        </manifest>
                        <manifestEntries>
                            <Premain-Class>com.github.lybgeek.agent.ServiceLogAgent</Premain-Class>
                            <Agent-Class>com.github.lybgeek.agent.ServiceLogAgent</Agent-Class>
                            <Can-Redefine-Classes>true</Can-Redefine-Classes>
                            <Can-Retransform-Classes>true</Can-Retransform-Classes>
                        </manifestEntries>
                    </archive>
                </configuration>
            </plugin>

3. How to use javagent for business code

java -javaagent:agentjar文件的位置 [= 传入 premain的参数 ] -jar 要运行的jar文件

Note : -javaagent must be before -jar, otherwise it will not take effect

byte-buddy

1. What is byte-buddy

Byte Buddy is a JVM runtime code generator, you can use it to create any class, and does not enforce an interface like the JDK dynamic proxy. Byte Buddy also provides a simple API to facilitate manual, through the Java Agent, or modify the bytecode during the build

2. Byte-buddy tutorial

Note: is introduced to use byte-buddy, the length will be longer, so the following 2 byte-buddy learning links are provided, and interested friends can click to view

https://blog.gmem.cc/byte-buddy-study-note

https://notes.diguage.com/byte-buddy-tutorial/

How to use javaagent + byte-buddy to achieve low intrusion logging

1. Write the agent entry class

public class ServiceLogAgent {


    public static String base_package_key = "agent.basePackage";

    public static void premain(String agentArgs, Instrumentation inst) {
        System.out.println("loaded agentArgs ：" + agentArgs);
        Properties properties = PropertiesUtils.getProperties(agentArgs);
        ServiceLogHelperFactory serviceLogHelperFactory = new ServiceLogHelperFactory(properties);
        serviceLogHelperFactory.getServiceLogHelper().initTable();

        AgentBuilder.Transformer transformer = (builder, typeDescription, classLoader, javaModule) -> {
            return builder
                    .method(ElementMatchers.<MethodDescription>any()) // 拦截任意方法
                    .intercept(MethodDelegation.to(new ServiceLogInterceptor(serviceLogHelperFactory))); // 委托
        };

        AgentBuilder.Listener listener = new AgentBuilder.Listener() {
            private Log log = LogFactory.getLog(AgentBuilder.Listener.class);

            @Override
            public void onDiscovery(String s, ClassLoader classLoader, JavaModule javaModule, boolean b) {
            }

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

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

            @Override
            public void onError(String s, ClassLoader classLoader, JavaModule javaModule, boolean b, Throwable throwable) {
                log.error(throwable.getMessage(),throwable);
            }

            @Override
            public void onComplete(String s, ClassLoader classLoader, JavaModule javaModule, boolean b) {
            }

        };

        new AgentBuilder
                .Default()
                // 指定需要拦截的类
                .type(ElementMatchers.nameStartsWith(properties.getProperty(base_package_key)))
                .and(ElementMatchers.isAnnotatedWith(Service.class))
                .transform(transformer)
                .with(listener)
                .installOn(inst);
    }


}

2. Write an interceptor

public class ServiceLogInterceptor {
    private Log log = LogFactory.getLog(ServiceLogInterceptor.class);


    private ServiceLogHelperFactory serviceLogHelperFactory;

    public ServiceLogInterceptor(ServiceLogHelperFactory serviceLogHelperFactory) {
        this.serviceLogHelperFactory = serviceLogHelperFactory;
    }

    @RuntimeType
    public Object intercept(@AllArguments Object[] args, @Origin Method method, @SuperCall Callable<?> callable) {
        long start = System.currentTimeMillis();
        long costTime = 0L;
        String status = ServiceLog.SUCEESS;
        Object result = null;
        String respResult = null;
        try {
            // 原有函数执行
            result = callable.call();
            respResult = JsonUtils.object2json(result);
        } catch (Exception e){
            log.error(e.getMessage(),e);
            status = ServiceLog.FAIL;
            respResult = e.getMessage();
        } finally{
            costTime = System.currentTimeMillis() - start;
            saveLog(args, method, costTime, status, respResult);
        }
        return result;
    }

    private void saveLog(Object[] args, Method method, long costTime, String status, String respResult) {
        if(!isSkipLog(method)){
            ServiceLog serviceLog = serviceLogHelperFactory.createServiceLog(args,method);
            serviceLog.setCostTime(costTime);
            serviceLog.setRespResult(respResult);
            serviceLog.setStatus(status);
            ServiceLogHelper serviceLogHelper = serviceLogHelperFactory.getServiceLogHelper();
            serviceLogHelper.saveLog(serviceLog);
        }
    }


    private boolean isSkipLog(Method method){
        ServiceLogProperties serviceLogProperties = serviceLogHelperFactory.getServiceLogProperties();
        List<String> skipLogServiceNameList = serviceLogProperties.getSkipLogServiceNameList();
        if(!CollectionUtils.isEmpty(skipLogServiceNameList)){
            String currentServiceName = method.getDeclaringClass().getName() + ServiceLogProperties.CLASS_METHOD_SPITE + method.getName();
            return skipLogServiceNameList.contains(currentServiceName);
        }
        return false;
    }



}

3. Package the agent into jar through maven

4. Effect demonstration

First, idea adds the following content in the vm parameter of the startup class

 -javaagent:F:\springboot-learning\springboot-agent\springboot-javaagent-log\target\agent-log.jar=F:\springboot-learning\springboot-agent\springboot-javaagent-log\target\classes\agent.properties

Effect picture

How to use automatic assembly + AOP to achieve low intrusion logging

Note: In fact, the way of friends is almost fine, just move the poincut out to the configuration file file.

1. Write the aspect

@Slf4j
public class ServiceLogAdvice implements MethodInterceptor {

    private LogService logService;

    public ServiceLogAdvice(LogService logService) {
        this.logService = logService;
    }

    @Override
    public Object invoke(MethodInvocation invocation)  {

        long start = System.currentTimeMillis();
        long costTime = 0L;
        String status = ServiceLog.SUCEESS;
        Object result = null;
        String respResult = null;
        try {
            // 原有函数执行
            result = invocation.proceed();
            respResult = JSON.toJSONString(result);
        } catch (Throwable e){
            log.error(e.getMessage(),e);
            status = ServiceLog.FAIL;
            respResult = e.getMessage();
        } finally{
            costTime = System.currentTimeMillis() - start;
            saveLog(invocation.getArguments(), invocation.getMethod(), costTime, status, respResult);
        }
        return result;

    }

    private void saveLog(Object[] args, Method method, long costTime, String status, String respResult) {
            ServiceLog serviceLog = ServiceLog.builder()
                                    .serviceName(method.getDeclaringClass().getName())
                                    .costTime(costTime)
                                    .methodName(method.getName())
                                    .status(status)
                                    .reqArgs(JSON.toJSONString(args))
                                    .respResult(respResult).build();
           logService.saveLog(serviceLog);
    }
}

2. Inject the aspect bean

 @Bean
    @ConditionalOnMissingBean
    public AspectJExpressionPointcutAdvisor serviceLogAspectJExpressionPointcutAdvisor(AopLogProperties aopLogProperties) {
        AspectJExpressionPointcutAdvisor advisor = new AspectJExpressionPointcutAdvisor();
        advisor.setExpression(aopLogProperties.getPointcut());
        advisor.setAdvice(serviceLogAdvice());
        return advisor;
    }

3. Write automatic assembly class

@Configuration
@EnableConfigurationProperties(AopLogProperties.class)
@ConditionalOnProperty(prefix = "servicelog",name = "enabled",havingValue = "true",matchIfMissing = true)
public class AopLogAutoConfiguration {

    @Autowired
    private JdbcTemplate jdbcTemplate;

    @Bean
    @ConditionalOnMissingBean
    public LogService logService(){
        return new LogServiceImpl(jdbcTemplate);
    }

    @Bean
    @ConditionalOnMissingBean
    public ServiceLogAdvice serviceLogAdvice(){
        return new ServiceLogAdvice(logService());
    }

    @Bean
    @ConditionalOnMissingBean
    public AspectJExpressionPointcutAdvisor serviceLogAspectJExpressionPointcutAdvisor(AopLogProperties aopLogProperties) {
        AspectJExpressionPointcutAdvisor advisor = new AspectJExpressionPointcutAdvisor();
        advisor.setExpression(aopLogProperties.getPointcut());
        advisor.setAdvice(serviceLogAdvice());
        return advisor;
    }


}

4. Write spring.factories

org.springframework.boot.autoconfigure.EnableAutoConfiguration=\
    com.github.lybgeek.logaop.config.AopLogAutoConfiguration

5. Effect demonstration

Do the following configuration in the business code

• 5.1 Introduce starter in pom.xml

  <dependency>
            <groupId>com.github.lybgeek</groupId>
            <artifactId>aoplog-springboot-starter</artifactId>
            <version>0.0.1-SNAPSHOT</version>
        </dependency>

• 5.2 Configure pointcut in the yml file

servicelog:
  pointcut: execution(* com.github.lybgeek.mock.service.client..*.*(..))
  enabled: true

• 5.3 Effect picture

to sum up

The above mainly enumerates two ways to achieve low intrusion logging through javaagent and aop plus automatic assembly 2. In fact, these two implementations are used a lot in some open source solutions. For example, byte-buddy is used in skywalking and arthas. For example, MethodInterceptor is useful in spring transactions. So look at the source code more, when designing the plan, sometimes unexpected sparks will be generated

demo link

https://github.com/lyb-geek/springboot-learning/tree/master/springboot-agent