Design and demo of distributed exception log tracing

Posted by DonelleJenae on Fri, 24 Dec 2021 12:30:22 +0100

preface

With the advancement of microservicing, the network interaction between services not only increases the R & D cost, but also makes the log tracking more cumbersome. If the call of a remote interface fails, you may need to query multiple service logs to find the stack information of the service with the actual exception. Although there are some mature solutions in the industry, such as skywalking, Spring Cloud Sleuth, etc., I think the implementation based on java agent is still biased. Can we realize distributed exception log link tracking based on the code level and sacrifice certain code invasiveness to ensure the rapid implementation of functions. The probation assessment of the new company involves the content of distributed log. First try to build your own wheel, and then learn how to build a good wheel.

Design ideas

Where does the log exist?

1. Documents
Different microservices may be on different servers, and the final log file collection will be troublesome, so file storage is not considered here.
2. Database
Based on the configuration of multiple data sources, it is indeed feasible for multiple microservices to write exception information to the same database, but the IO resources of the database are often prone to bottlenecks under high concurrency. Even if asynchronous writing is removed, there will be a loss of IO performance, so it is not the optimal solution.
3.Redis
I think Redis is the most reasonable storage medium. The reasons are as follows: first, the reading and writing are based on the fast memory speed; second, the expiration time can be configured without data accumulation; third, the data type HashMap is perfectly suitable for the storage of distributed logs. The key is the unique identification of the request, and the key value pair is the service name and exception information.

How does the unique identifier of the request come from?

Considering the accessibility of existing projects, it is really unreasonable to require all client requests to bring their own unique ID, so the generation of the unique ID is handed over to the server. Where to intercept and uniformly generate unique identifiers? At first, I wanted to do it in the gateway, but the risk is too great. Since it is to track the calls between micro services, the aspect will be more reasonable and more accessible.

How to quickly access existing projects?

Based on the manual registration of bean s, you can inject the aspect into the project. Service name, log expiration time, exception stack information level, etc. shall be configured.

DEMO

Let's look at the project structure first

common is the specific implementation of the aspect. eureka is selected as the registry. Log service provides the function of viewing distributed exception logs. ServiceA, B and C are micro services that call each other.

com.common.aop.FeignAspect

/**
 * @Author linlx
 * @Date 2021/8/13 8:42
 * @Description feign Interface section to realize the generation of unique identification
 **/
@Aspect
public class FeignAspect {

  private String serverName;

  public FeignAspect(String serverName) {
    this.serverName = serverName;
  }

  // The pointcut is the location of the feignClient package of the project
  @Pointcut("execution(* com.*.client.*.*(..))")
  private void pointcut() {

  }

  @Before(value = "pointcut() && args(apiRequest)")
  public void beforeAdvice(ApiRequest<?> apiRequest) {
  	// Generate a unique ID for the request
    if (StringUtils.isEmpty(apiRequest.getRequestId())) {
      apiRequest.setRequestId(
          "origin-serverName:" + serverName + ":" + UUID.randomUUID().toString().substring(0, 10));
    }
  }
}

com.common.aop.LogAspect

/**
 * @Author linlx
 * @Date 2021/8/12 8:42
 * @Description
 **/
@Aspect
@Slf4j
public class LogAspect {

  private ThreadLocal<ApiRequest> threadLocal = new ThreadLocal<>();

  private ExecutorService executorService;

  // service name
  private String serviceName;

  // Log expiration time
  private Long expireMinutes;

  // Level of exception stack information
  private Integer exceptionLogDepth;

  public LogAspect(String serviceName, Long expireMinutes, Integer exceptionLogDepth) {
    this.serviceName = serviceName;
    this.expireMinutes = expireMinutes;
    this.exceptionLogDepth = exceptionLogDepth;
    this.executorService = Executors.newSingleThreadExecutor(
        new ThreadFactoryBuilder().setNameFormat("LogAspect-" + this.serviceName + "-%d").build());
  }

  @Resource
  private StringRedisTemplate stringRedisTemplate;

  // The tangent point is the entrance of feign interface
  @Pointcut("execution(* com.*.controller.*.*(..))")
  private void pointcut() {

  }

  @Before(value = "pointcut() && args(apiRequest)")
  public void beforeAdvice(ApiRequest<?> apiRequest) {
    // Put request parameters into thread variables
    threadLocal.set(apiRequest);
  }

  @Around("pointcut()")
  public void around(ProceedingJoinPoint joinPoint) throws Throwable {
    String methodName = joinPoint.getSignature().getName();
    Object[] params = joinPoint.getArgs();
    try {
      joinPoint.proceed();
    } catch (Exception e) {
      String feignId = threadLocal.get().getRequestId();
      // Asynchronous log writing
      executorService.execute(() -> {
        LogRedisVO logRedisVO = new LogRedisVO();
        logRedisVO.setParams(params);
        // Exception name
        logRedisVO.setExceptionName(e.toString());
        // Original method with exception
        logRedisVO.setOriginMethodName(methodName);
        logRedisVO.setCreateTime(new Date());

        StackTraceElement[] stackTrace = e.getStackTrace();
        Integer index = Math.min(exceptionLogDepth, stackTrace.length);
        List<LogExceptionVO> logExceptionVOList = new ArrayList<>(index);
        LogExceptionVO logExceptionVO;
        for (int i = 0; i < index; i++) {
          logExceptionVO = new LogExceptionVO();
          // Class with exception
          logExceptionVO.setClassName(stackTrace[i].getClassName());
          // Number of rows with exception
          logExceptionVO.setLineNumber(stackTrace[i].getLineNumber());
          // Method of exception
          logExceptionVO.setExceptionMethodName(stackTrace[i].getMethodName());
          logExceptionVOList.add(logExceptionVO);
        }
        logRedisVO.setLogExceptionVOList(logExceptionVOList);
        // Key is the unique identification of the request. The key value pair is the service name - exception log information
        stringRedisTemplate.opsForHash().put(feignId, serviceName, JSON.toJSONString(logRedisVO));
        stringRedisTemplate.expire(feignId, expireMinutes, TimeUnit.MINUTES);
      });
      throw e;
    }
  }
}

Manually inject the two sections in ServiceA, B and C

  @Value("${spring.application.name}")
  private String serverName;

  @Value("${logAspect.expireMinutes}")
  private Long expireMinutes;

  @Value("${logAspect.exceptionLogDepth}")
  private Integer exceptionLogDepth;

  @Bean
  public LogAspect logAspect() {
    return new LogAspect(serverName, expireMinutes, exceptionLogDepth);
  }

  @Bean
  public FeignAspect feignAspect() {
    return new FeignAspect(serverName);
  }

Go down to test. The calling link is a - > b, and B is abnormal

@RestController
public class ServiceAController {

  @Autowired
  private ServiceBFeign serviceBFeign;

  @PostMapping("/testLog")
  public void testLog(@RequestBody ApiRequest request) {
    serviceBFeign.testLog(request);
  }
}
----------------------------------------------------------

@RestController
public class ServiceBController implements ServiceBFeign {

  @Autowired
  private ServiceCFeign serviceCFeign;

  @Override
  public String testLog(ApiRequest apiRequest) {
    if (1 == 1) {
      throw new RuntimeException();
    }
    return "success";
  }
}

After an exception occurs after a postman request, use the interface provided by log service to view it. The returned exception log is as follows

[
	[{
			"serviceName": "ServiceA",
			"logRedisVO": {
				"exceptionName": "feign.FeignException: status 500 reading ServiceBFeign#testLog(ApiRequest)",
				"originMethodName": "testLog",
				"logExceptionVOList": [{
					"className": "feign.FeignException",
					"lineNumber": 78,
					"exceptionMethodName": "errorStatus"
				}],
				"createTime": "2021-08-14 16:24:54",
				"params": [{
					"requestId": "origin-serverName:ServiceA:481cabc0-a",
					"body": "hello world"
				}]
			}
		},
		{
			"serviceName": "ServiceB",
			"logRedisVO": {
				"exceptionName": "java.lang.RuntimeException",
				"originMethodName": "testLog",
				"logExceptionVOList": [{
						"className": "com.serviceb.controller.ServiceBController",
						"lineNumber": 23,
						"exceptionMethodName": "testLog"
					},
					{
						"className": "com.serviceb.controller.ServiceBController$$FastClassBySpringCGLIB$$bcd3b687",
						"lineNumber": -1,
						"exceptionMethodName": "invoke"
					}
				],
				"createTime": "2021-08-14 16:24:54",
				"params": [{
					"requestId": "origin-serverName:ServiceA:481cabc0-a",
					"body": "hello world"
				}]
			}
		}
	]
]

It can also be seen from the requestId that the entry service of this request is ServiceA. Finally, test the log output of call exceptions between the three services.

[
	[{
			"serviceName": "ServiceC",
			"logRedisVO": {
				"exceptionName": "java.lang.RuntimeException",
				"originMethodName": "testLogThird",
				"logExceptionVOList": [{
						"className": "com.servicec.controller.ServiceCController",
						"lineNumber": 19,
						"exceptionMethodName": "testLogThird"
					},
					{
						"className": "com.servicec.controller.ServiceCController$$FastClassBySpringCGLIB$$66a13189",
						"lineNumber": -1,
						"exceptionMethodName": "invoke"
					},
					{
						"className": "org.springframework.cglib.proxy.MethodProxy",
						"lineNumber": 218,
						"exceptionMethodName": "invoke"
					}
				],
				"createTime": "2021-08-14 16:28:15",
				"params": [{
					"requestId": "origin-serverName:ServiceA:744cfb5c-7",
					"body": "hello world"
				}]
			}
		},
		{
			"serviceName": "ServiceA",
			"logRedisVO": {
				"exceptionName": "feign.FeignException: status 500 reading ServiceBFeign#testLogThird(ApiRequest)",
				"originMethodName": "testLogThird",
				"logExceptionVOList": [{
					"className": "feign.FeignException",
					"lineNumber": 78,
					"exceptionMethodName": "errorStatus"
				}],
				"createTime": "2021-08-14 16:28:15",
				"params": [{
					"requestId": "origin-serverName:ServiceA:744cfb5c-7",
					"body": "hello world"
				}]
			}
		},
		{
			"serviceName": "ServiceB",
			"logRedisVO": {
				"exceptionName": "feign.FeignException: status 500 reading ServiceCFeign#testLogThird(ApiRequest)",
				"originMethodName": "testLogThird",
				"logExceptionVOList": [{
						"className": "feign.FeignException",
						"lineNumber": 78,
						"exceptionMethodName": "errorStatus"
					},
					{
						"className": "feign.codec.ErrorDecoder$Default",
						"lineNumber": 93,
						"exceptionMethodName": "decode"
					}
				],
				"createTime": "2021-08-14 16:28:15",
				"params": [{
					"requestId": "origin-serverName:ServiceA:744cfb5c-7",
					"body": "hello world"
				}]
			}
		}
	]
]

The exception log of each service can output different levels of stack information according to the configuration.

summary

Let's talk about the disadvantages first. For the implementation based on the aspect, the execution expression needs to be adjusted according to the project structure. At present, there is no way to configure it. Second, there is code intrusion. All feign requests need to inherit a parent class containing the unique ID of the request. Third, a whole layer of redis needs to be vacated for log storage to facilitate full log query. Finally, it has the advantages of simple implementation. The two basic aspects and redis complete the link collection and display of distributed logs, which is more suitable for projects from 0 to 1.

Because the company banned github, leave the source code in the email to share.

Topics: Java