Output to "log_file" gets rotated, but this is not documented or tunable, and rotated files don't follow usual naming conventions

[dardhal]

Bug Report

What happened

Not a bug report as such, rather, a RFE (Request For Enhancement).

Today, while doing some random log checking in the Linux server where zigbee2mqtt is running, noticed the configured log file (as set in the "log_file" directive) had rotated:

# ls -lrt zigbee2mqtt*.log
-rw-r--r-- 1 root root 10000425 Apr  3 04:41 zigbee2mqtt1.log
-rw-r--r-- 1 root root   160803 Apr  3 19:29 zigbee2mqtt.log

Checked the documentation for the configuration file (https://www.zigbee2mqtt.io/information/configuration.html) and didn't see anything related to log rotation defaults or tuning.

Took the time to dig deeper the last part of the old log file and the first part of the new one, and didn't see anything out of the ordinary happening (such as a service restart).

As expected, it is the "zigbee2mqtt.log" the one being currently open and appended to by the service. Of course, I have "log_file: zigbee2mqtt.log" under "advanced:" in the yaml configuration file.

What did you expect to happen

If assuming letting the application generating the logs to be the one in charge or rotating them is a good thing (which I don't think it is the case, there being dedicated solutions for log rotation, such as the good old "logrotate"), at least I would have expected:

• That this built-in log rotation is documented somewhere (can't tell this is not the case 100% sure, but if this is documented, I failed to find it when searching, so not immediate for the vast majority of users to know up-front)
• That the rotated log file to follow the usual "logrotate" naming convention for preserved log files. So that "zigbee2mqtt.log.1" to have been created, instead of the one created and named "zigbee2mqtt1.log"

That zigbee2mqtt behaves in this way, makes it the exception regarding log management among the myriad of other services, processes and applications running on a regular Linux server, which is probably added code to this software, and makes log management for zigbee2mqtt unnecessarily specific and time consuming.

How to reproduce it (minimal and precise)

It looks like the rotation was triggered when the active log file was over 10,000,000 bytes big. This is confirmed by looking into the source code (cloned the repository today and saw this):

lib/util/logger.js

// Add file logger when enabled
// NOTE: the initiation of the logger, even when not added as transport tries to create the logging directory
if (output.includes('file')) {
    transportsToUse.push(new winston.transports.File({
	filename: path.join(directory, logFilename),
	json: false,
	level,
	tailable: true,
	maxFiles: 3, // Keep last 3 files
	maxsize: 10000000, // 10MB
	format: winston.format.combine(
	    winston.format.timestamp({format: timestampFormat}),
	    winston.format.printf(/* istanbul ignore next */(info) => {
	        const {timestamp, level, message} = info;
	        return `${levelWithCompensatedLength[level]} ${timestamp.split('.')[0]}: ${message}`;
	    }),
	),
    }));
}

So if my limited (aka non-existent) understanding of the JS source code is correct, we have a hardcoded log rotation policy by which we will keep at most 3 log files with up to 10 MB each, and filenames which are not following usual naming standards.

Of course, as an end user / administrator I couldn't care less about the ins and out of the code (and resorting to external libraries to simplify code seems to be right), but not if at the expense of making "zigbee2mqtt" a bad neighbour and an special use case when dealing with logs.

It is my opinion zigbee2mqtt should :

• Have it documented that there is internal log rotation in place, and the defaults being used
• A configuration option in the .yalm file so that log rotation is disabled, option which defaults to current behavior (internal log rotation enabled)

This way, 95% of users may continue to use zigbee2mqtt the way they do (as they don't care about logs except for the last few lines when debugging), but the remainder 5% can have the software logs under control and managed the same way many others in the system are.

Debug Info

zigbee2mqtt version: HEAD as of April 4 2020
CC253X firmware version: N/A

[Koenkk]

When removing

	tailable: true,
	maxFiles: 3, // Keep last 3 files
	maxsize: 10000000, // 10MB

does it work as expected?

[dardhal]

Hi, did the following testing:

• Stopped zigbee2mqtt
• Log files after stopping the service were as follows:
  -rw-r--r-- 1 root root 341167 Apr 4 11:42 zigbee2mqtt.log
  -rw-r--r-- 1 root root 10000425 Apr 3 04:41 zigbee2mqtt1.log
• Filled the "active" log file with text data, so that it ended up being this large (bigger than 10 MB):
  -rw-r--r-- 1 root root 10341592 Apr 4 11:44 zigbee2mqtt.log
• Edited the installed zigbee2mqtt version 1.10.0 file "lib/util/logger.js" and removed the lines requested
• Started the zigbee2mqtt service again
• Log file was not rotated. Triggered some further Zigbee events (for the Hue) to have logs added normally to the log file, and it still did not rotate
• Stopped the service once again, left the active log file as this:
  -rw-r--r-- 1 root root 10357896 Apr 4 11:46 zigbee2mqtt.log
• Reverted the changes to the "lib/util/logger.js" file and started the service once again
• Before I had the chance to check the logs, log files had been further rotated:
  -rw-r--r-- 1 root root 10000425 Apr 3 04:41 zigbee2mqtt2.log
  -rw-r--r-- 1 root root 10358179 Apr 4 11:46 zigbee2mqtt1.log
  -rw-r--r-- 1 root root 760 Apr 4 11:46 zigbee2mqtt.log

Theefore, it is confirmed that by removing the specified lines in the code, zigbee2mqtt works, regarding log rotation, as "expected"; in the sense that it does not rotate the log files and hence this task can be done by (for example) logrotate.

Having a flag in the code to turn log rotation off for those few of us inclined to do so, would be super.

Thank you.

[Koenkk]

Implemented, can be set via

advanced:
  log_rotation: false