1. Background

In this article, a log monitor system is designed for one classic monolithic Spring MVC project, which contains three module layers: Controller, Service, and Repository.

2. Requirement

• All system exceptions should be recorded.
• Pretty log format. Compatible for further scaled and distributed micro service
• Easy to trace the bug must have: when, where, who, what, How long
• Performance measurement for rest request in the Controller layer
• Performance measurement for Business Service layer
• Report problem when database SQL query in the Repository layer takes longer time

When: the time the bug occurs
Where: in which application, which layer, which package, which Class, which line
Who: account which calls the request, if the request is not anonymous. Or IP address
What: what happened? the full stack message or short message
How long: the execution time for each layer

3. About Log

3-1. 1. Log Level:

The log4j has defined the common log level as :

TRACE — The TRACE Level designates finer-grained informational events than the DEBUG
DEBUG — The DEBUG Level designates fine-grained informational events that are most useful to debug an application.
INFO — The INFO level designates informational messages that highlight the progress of the application at coarse-grained level.
WARN — The WARN level designates potentially harmful situations.
ERROR — The ERROR level designates error events that might still allow the application to continue running.
FATAL — The FATAL level designates very severe error events that will presumably lead the application to abort.

This definition is just simple and in practice, which kind of log should be recorded, your team should discuss for it. Here is one discussion in StackOverflow.

1. The log level in a project should be clear and followed by every developer.
2. Log standard is must have. Besides developers, the testing engineers and DevOps engineers can also locate the bug easily
3. About log level:
   FATAL — System level error which should be handled by administrator immediately. When such error occurs, means your service is not available. This level should be used cautiously because this is the most serious log level. It does not make sense if such log level occurs often. As usually, a fatal log should be recorded only once in life circle of a process,  which will be terminated without retrieving. If child service of one service has beyond retrieved exception, this exception could be also recorded as a fatal log.
   ERROR — This level should be handled immediately but has lower priority than fatal level. This level has affected the user’s operation. From this point, error and fatal error has the same affection on users.  Fatal means service is down, and error means cannot provide normal service and keep printing error log. But any error related to users’ incorrect operations, such as wrong parameters, should not be recorded as error level.
   WARN — This level means the system could have problem probably, or not, such as network problem. For those which not yet recognized as errors but will turn to errors if no one has handled, could be recorded as warn level. For example, one SQL query execution time has longer than a threshold, or the storage of one service has almost reached the limit. Such kind of log does not require to be handled immediately although, but still require checking and handling in a schedule.  Warn level logs should not be recorded too often.
   INFO — This level records normal working status, such as service initialization or one request has been processed successfully. Through info logs, the developer can easily locate fatal, error and warn errors. Too many Info logs are inappropriate. Normally, info level logs should less than 10% of trace level logs.
   DEBUG or TRACE — This level should record each step of process exactly, for example, which operation, what parameters. The developer can diagnose and locate the bug with debug messages.

Rule 1: The Team including DevOps should define the log level standard and the corresponding process.

3-2. 2. Log Maintenance

DEBUG or TRACE level log is important to locate the bug so that the log format should be optimized.

1. The team should optimize the log format and standard, and follow it. The team should review the logs periodically.
2. Every team member should abide by the rules
3. Developer try to work as DevOps, locate bug from logs
4. If DevOps find a problem in logs, should report to developers
5. If takes a long time to locate the bug, that means the log is not perfect enough and should be improved.
6. Thinking about error prediction via logs.  For example, OOM error, slow sql query or resource limitation error.

Rule 2: The team should review and optimize the logs periodically.

 

3-3. 3. Log Category

3-3-1. Diagnosed Log

• Request input and output
• Request and response for external service
• Resource operation:  open file
• service exception: database not available
• Background schedule process
• Service start, loading and stop

3-3-2. Statistic Log

• User visit statistic
• Page visit statistic
• Charging or payment log

3-3-3. Audit Log

• Administration operation

Rule 3:  Clarify the purpose of different log and classify them.

3-4. 4. Redundant Log vs Useless Log

some example here….. TODO

Rule 4: DO NOT record useless log to avoid log flood

 

3-5. 5. Log record integrity

For example, a user is editing his blog. It could have the following steps:

• Controller request&response
• Blog Service operation
• Blog Repository database update

Errors could occur in every step. What is recommended to record including:

• The initialization parameters when the system starting or initializing
• Record all exceptions during the system running
• Record all warnings during the system running
• Record value changing before and after database persistence
• Record the communication among modules
• Record the important state changing
• The schedule job working status

What is not recommended to record:

• Function calling
• file content. If it is required, take a piece of it
• “benign” error.  Sometimes there is an error, but there is right process can handle it. For example, find duplicated data before insert data.

Rule 5: Log should be exact and have integrity, bugs can be located  only depends on logs

3-6. 6. Test Log

Unit test,  API test… TODO

 

3-7. 7. APM and Distributed Tracing

What is APM? What is distributed tracing?

A Monolithic application could have many modules or external services. Transforming monolithic application into a microservices-based one is hard to trace the bug. If you have 100 servers and you get the error in one request, image that.

We need a global unique RequestID, which will go through all child service and in each communication. If we collect all logs and we can find one completion tracing records with such RequestID.

3-8. 7. Dynamic Log Recording

DEBUG level log record too many details and could cause flood logs in distributed service.  We need a switch to turn on or shut down the debug level during runtime.

• Add such switch in configuration, property file or yml
• add a switch as a query string parameter in request url, such as “DEBUG=ON”.

The administrator could config the debug level for some modules or some requests at any time.

3-9. 8. Log Isolation and Size Control

In some case, the error log could be recorded into separated files.

The log size should under control. The huge log file is not convenience for monitor or bug tracking. Log slicing by day or hour, it depends on the number of logs. The only principle is that the developer can locate the bug as soon as possible.

To avoid occupying the hard disk by log file, the log files need to be cleaned under schedule. For example, clear logs too months ago after receiving the hard disk limit warning.

 

4. Practice

4-1. 1. Log format

You can define yours own team log format.

Name	Remark
requestID	uuid
timestamp	log record time
level	log level
message	log message
app	application name
module	module name
operation label	custom annotation label or request uri
accountId	account id
accountType	account type
status	response status code
elapsed	the number of milliseconds elapsed for the execution of logging event
error	full error message
thread id
Class name
package.class	Used to output the category of the logging event
line number	Used to output the line number from where the logging request was issued

This is the log pattern layout example in log4j.xml:

 

4-2. 2. Generate RequestID

You can use UUID as RequestID as will. I am using snowflake ID in my project.

Add a filter to add RequestID in the header and transmit it in the request.

in web.xml

In log4j.xml pattern layout:

3. MDC

what is MDC: Mapped Diagnostic Context ?

 

4-3. 3. AOP or Interceptor Implementation

In your config property file define some value for AOP.

 

4-3-1. 3.1 AOP for Repository

Show me the code.

 

4-3-2. 3.2 AOP for Service

Show me the code.

 

4-3-3. 3.3 AOP for Controller

ControllerAspect

4-3-4. 3.4 AOP Controller Problem

But I have this problem: AOP cannot advise on annotated controllers

3.4.1 Previous config:

application-context.xml

spring-mvc-servlet.xml

web.xml

 

4-3-4-1. 3.4.2 Try 1

Ref: spring-aop-is-not-working-in-with-mvc-structure

The aspects and the beans to be applied needs to be in the same ApplicationContext but ApplicationContext is not aware of WebApplicationContext.

application-context.xml

spring-mvc-servlet.xml

This solution works, now ControllerAscpect can intercept controller. But there is a problem, all controllers and methods which protected by Shiro, return 404 not found error!

4-3-4-2. 3.4.3 Try 2

Ref: Spring AOP Advice on Annotated Controllers

web.xml

This solution works, now ControllerAscpect can intercept controller. But same problem 404 not found as Try 1.

Then I tried to remove the Shiro AOP for annotation from spring-mvc-servlet.xml:

Now the Shiro protected controllers work again. BUT all the Shiro annotations stop working!!!!

I have not found an AOP solution for my controllers. TODO

 

4-3-4-3. 3.4.4 Try Interceptor

Other developers mentioned that Interceptor is more suitable for controller:

For MVC controllers the preferred method of accomplishing what you are trying to do is to use interceptors.  General rule is use interceptors when you want to intercept certain web requests. Use Aspects when you want to intercept methods on normal spring beans. Since the question is related to intercepting Controllers (which are mapped to web requests)….

application-context.xml

spring-mvc-servlet.xml

This solution works. And ControllerInterceptor works with ServiceAspect and RepositoryAspect now.

 

5. Test

In the test, a blog edit request was executed, and all related logs were collected here:

Take one line and map the content to the log format table:

Name	Content
requestID	259708060346486784
timestamp	2018-12-03 14:22:47,842
level	INFO
message	[service][/blog/post/edit.do][edit()]|[]
app	mgr
module	service
operation label	/blog/post/edit.do
accountId	1:0
accountType	1:0
status
elapsed	194
error	— available in error
thread id	79671
Class name	ServiceAspect
package.class	— available in error
line number	— available in error

 

 

6. ELK

TODO

 

 

7. Reference:

最佳日志实践

最佳日志实践（v2.0）

[elk]基于elk的业务日志格式设计

Spring 使用笔记之(二) – AOP和Interceptor(拦截器)

Spring Boot: Setting a unique ID per request

自己写分布式链路追踪框架1–TraceId/SpanId/ParentSpanId生成及传递

在SpringBoot项目中添加logback的MDC

[总结]日志格式

NOST-73