Specification of Logs

[guowei-su]

This idea comes from OSPP2022. The current DS log output is not standardized enough, which can bring difficulties in locating system problems through logs. Therefore I have an idea and would like to discuss it.

Currently DS uses the Logback framework and uses four levels of log printing - DEBUG, WARN, INFO, ERROR. Let me first describe the meaning of these four log levels.

• DEBUG: This level is used in the development and testing process to output debugging information. As far as possible, the developer prints the parameter information, process details, and result information during debugging with this level of logging, which is convenient for locating and analyzing problems during the development and testing stages.
• WARN: This level is used to warn about the problems that will occur during the runtime, where the problems are predictable. For example, scenarios such as method parameter determination, method deprecation, etc. The warning information output by the developer should be more complete to facilitate the analysis.
• INFO: This level is used to record information during system operation, such as master, worker initialization configuration, business status, process, and other information. The information output by the developer using this level should reflect the running process of the system and the execution information of the business.
• ERROR: This level is used to output some unpredictable errors and exceptions, which can affect the system process. For example, node start/stop, task scheduling exceptions, etc. The developer should output the information of this level including the error description, method parameters, products of the execution process and the stack information of exceptions, etc.

Based on the meaning of the above logging levels, I think the following specification should be made.

1. Log level usage specification.

   Different levels of logs play different roles in business processes, and failure to use reasonable log levels for printing can cause great difficulties for system operation and maintenance.

   When printing logs, it is necessary to clarify the role played by the current logs and choose a reasonable level according to its role. For example, for the key steps in the master module and worker module, you need to use the INFO level to print; for the details of the key steps, you can use the DEBUG level to print; for the problems that do not affect the normal process of the system, you can use the WARN level to print; for the problems that cause the system process to fail, you can use the ERROR level for printing.

2. Log content specification.

   Whether the log content is standardized determines whether the log can serve its intended purpose.

   The INFO level log is used to describe the status information or operation information of the current program call, which serves to describe the system operation process. Therefore, INFO level logs need to appear in every part of the application's operation, and their content should include the description of the program, program parameters, and other information. For example, in the buildFlowDag of master module's WorkflowExecuteRunnable, the description information of entering and exiting the program needs to be output, and the description information of exiting needs to be divided into two cases, one is normal exit, printing the description information of normal exit and program product; the other is abnormal exit, printing the description of abnormal exit.

   The WARN level log is used to describe the tolerable errors that occur in the current program call, i.e., errors that do not require human intervention. the WARN level log needs to print exception description information, field parameters, etc. For example, the log prints when the parameter checksum fails in the api module.

   The ERROR level log is used to describe the current intolerable errors that occur in program calls and affect the operation of the application. ERROR level log generally appears in the program part or program product verification wrapped by the try catch of the application program, and its content should include detailed error description, program description and site information to ensure that the problem can be quickly located according to the log. For example, in the buildFlowDag of master module's WorkflowExecuteRunnable, when the product verification of generateFlowDag fails, the ERROR level log content to be output includes error description, current program description, program parameters; in the catch block, we need to save the site context and exception stack information, and unified use of Logback for exception handling, the content format is as follows.

   logger.error("error is {}", e.getMessage(), e);

   The DEBUG level logging is used to help in the development, debugging phase. DEBUG level logs are not allowed to be used in the production environment, but they are usually found at critical programs that need to be debugged, and need to record detailed site information, parameters, products, etc.

3. Log format and organization specification.

   The current log format and organization is sufficient

4. Caution.

   • Do not use standard output to print logs. Standard output can greatly affect system performance.

   • Function printStackTrace() is prohibited for exception handling. This method prints the exception stack information to the standard error output, which violates Caution 1. It also loses the information of the log format. Exceptions should be handled using the following format.

     logger.error("error is {}", e.getMessage(), e);

   • Prohibit printing the log in separate lines. The contents of the logs need to be associated with the relevant information in the log format. Printing the logs in separate lines will cause the contents of the logs to not match the time and other information, and will cause the logs to be mixed in a large number of log environments, which will make the logs more difficult to retrieve.

   • Prohibit the use of the "+" operator to splice log content. Use placeholders for log formatting and printing to improve memory usage efficiency.

   • Make sure to override the toString() method to prevent printing meaningless hashcode, when the log content includes object instances,

Welcome to add!

[ruanwenjun]

If you already print the exception stack, you don't need to print the message again, unless you want to add more messages.

And it's better to add a specific message about which step occurs exception rather than error is {}.
e.g. log.error("Handle state event error, the state event is {}", event, e) is better than the error is {}.

[guowei-su]

U're right. The exception log also needs to clearly describe the scene, parameters, and exception stack information, so we can do something like this: log.error("description of current scene, parameters", {}..., e). Thx!