Logging Howto and Best Practices

Logging Functions

The logging macros are defined in the project libebee_common in the file log/log.h .

macros:

Logging Macro Description
LOG_<log severity>_FN log formatted message with the severity, source file name, line in code, function name
LOG_<log severity> log formatted message with the severity, source file name, line in code
LOG_FN_BEGIN can be used at the beginning of a function, just logs out “<function name()>” in TRACE level
LOG_FN_EXIT can be used at the end of a function, just logs “leaving <function name>()” in TRACE level

User Logs

When creating a diagnostics package there is included a user log file home/charge/user.logs . It is a subset of the regular log file and contains all relevant information for the user.

There are special log macros for generating user log entries

Log Macro Description
USER_INFO used for logging relevat information, e.g. start of charging, CP line state changes, …
USER_WARN used for warnings where the controller can react properly, e.g. disconnect from backend, disconnect from DLM slave, failed firmware update
USER_ERR used when the controller cannot react properly on failures, e.g. contactor cannot be opened, ADC is not responding
USER_INFO_FN same as USER_INFO, logs the the function name additionally
USER_WARN_FN same as USER_WARN, logs the the function name additionally
USER_ERR_FN same as USER_ERR, logs the the function name additionally

Default Logging Level

The default logging level in DEBUG.

Logging Level Description

Log Level Description
ERR identifies error events that may still let the software run, but with restricted capabilities in the impacted routes
WARN raise a “red sign”, less important than errors, should be used when e.g. expected results take longer than expected, file sizes are near their limit, and so on, only use them if the software can handle these events properly without reduction of the functionality
DBG default log level, should contain all the information which help to understand relevant state changes or state details, e.g. charging duration, meter values
VDBG used when want to log additional information which can also be developer related, e.g. message queue length, length of data packets
TRACE can be used as logpoint when it is relevant to find out whether the function was called, can contain information only developer related

Best Practices

  1. In case of malfunctions the logs should help to understand the situation which lead to the issue. So “unknown error” or “exception at …” will not help.
  2. In the logs should be all relevant information which help to understand relevant state changes, e.g. a cable was attached –> show the PP value
  3. Repeated logs should be avoided when they do not help to understand the issue. If there are repeated logs expected they should be suppressed for a specific period, then logged again (one log entry) and then suppressed again.
  4. The log message should contain all the relevant information in a human readable format. E.g. Enumeration values as integer will not help, there should also be the corresponding name of the enum value.
  5. Use English Language, i18n is not needed
  6. Use only ASCII, otherwise messages could be unreadable
  7. The log in the default log level (DEBUG) should last a week due to delayed diagnostic file pulling.
  8. Don’t log sensitive information: no passwords, customers' individual data, …
  9. Don’t log for troubleshooting purposes only: Relevant state changes, user interactions, monitoring is also important.

Setting the log level system wide

You can select a log level via the web interface or by modifying the file '/home/charge/persistency/LogLevel_custom' directly.

Additionally can change the log level at run-time. For this there's a FIFO '/home/charge/ebee_log_level'. Simply writing (echoing) a log level into it with e.g.: 

charge@~$ echo TRACE > ebee_log_level

will change the log level to TRACE level. Just keep in mind that this is only a temporary change until next reboot, it won't modify the persistency file for the log level.

Setting the log level module wide

You can also change the log level of individual components. If you want to switch e.g. only the log level for the RFID subsystem to TRACE, but leave all others at their current level, you can do e.g.: 

charge@~$ echo "RFID=TRACE" > ebee_log_level

Instead of the name of the subsystem you can also its number. If you look into the log file and search for a line coming from the RFID subsystem, you may find a line like an 

Jan  1 00:48:25 cp cp_app[1713]: <15>   auth_rfid.c:923  [01e8d000] (*D) - auth_rfid_init(): init

The number of the subsystem is the number enclosed in '<>'. So the number for the RFID subsystem is 15 and you can thus change its log level using: 

charge@~$ echo "15=VDBG" > ebee_log_level

And you can also set several components in the same command, just separate them by a ';', i.e. 

charge@~$ echo "RFID=VDBG; SOCKETTYPE2=ERR" > ebee_log_level