Provide New Log-File for every Boot

[tb-killa]

It would be better if zigbee2mqtt would provide the logfile seperated on every Start with Timestamp in Filename.
This would be the advantage for getting easier readable logfiles (and shortend too).

On every Start we generate the logfile with Name: logfile_%timenow%.log

[tb-killa]

@Koenkk We should use this: https://github.com/winstonjs/winston-daily-rotate-file
From this official module we could use the included functionality
filename: Filename to be used to log to. This filename can include the %DATE% placeholder which will include the formatted datePattern at that point in the filename. (default: 'winston.log.%DATE%)
What do you think ?

[Koenkk]

Yes that would be great!

[tb-killa]

@Koenkk I´m testing the mentioned winston-daily-rotate-file.
First i edit the package.json file and extend this via "winston-daily-rotate-file": "*", and do an initial npm install which seems to be success.
Finaly i edit my lib\util\logger.js like this:

const winston = require('winston');
require('winston-daily-rotate-file');
const data = require('./data');
const settings = require('./settings');

let logLevel = '';
if (process.env.DEBUG) {
    logLevel = 'debug';
} else if (settings.get().advanced && settings.get().advanced.log_level) {
    logLevel = settings.get().advanced.log_level;
} else {
    logLevel = winston.level.info;
}

const logger = new (winston.Logger)({
    transports: [
        new (winston.transports.DailyRotateFile)({
            filename: data.joinPath('log-%DATE%.txt'),
            datePattern: 'yyyy-MM-dd-HH',
            json: false,
            level: logLevel,
            maxFiles: 3,
            maxsize: 10000000, // 10MB
        }),
        new (winston.transports.Console)({
            timestamp: () => new Date().toLocaleString(),
            formatter: function(options) {
                return options.timestamp() + ' ' +
                        winston.config.colorize(options.level, options.level.toUpperCase()) + ' ' +
                        (options.message ? options.message : '') +
                        (options.meta && Object.keys(options.meta).length ? '\n\t'+ JSON.stringify(options.meta) : '' );
            },
        }),
    ],
});

logger.transports.console.level = logLevel;

module.exports = logger;

Now i´m getting this type of logfile-format: log-yyyy-08-Su-17.txt
Do you maybe know why this happened ?

Btw: Do you´v got an idea how to change path via configuration.yaml file ? We couldn´t do include
const settings = require('./settings'); in data.js because it is interdependent!
Hope we could work together to close this issue and finaly #207 :)

[tb-killa]

Edit: Okay i think this isn´t really what we need because if i use the datePattern with Minutes we get rotation every minute. What we need is some Sort of Datepattern in FileName.
I have to look deeper for this.
But for the other point i need your help ;)

[Koenkk]

I think the easiest solution would be only changing filename: data.joinPath(log-${Date.now()}.txt),.

Then we should do a automatic cleanup (e.g. only keep the 10 newest files).

For the log directory I would put something in configuration.yaml like:

advanced:
  log_directory: /var/log

In logger.js we could then do:

const path = settings.get().advanced && settings.get().advanced.log_directory ? settings.get().advanced.log_directory : data


            filename: path.joinPath(`log-${Date.now()}.txt`),

[tb-killa]

I´m use moment for formation and build some testcode like this:
const formatefilename = 'log-' + moment(new Date()).format('YYYY-MM-DD-HH-mm-ss') + '.txt';
and got this as logfilename: log-2018-08-05-18-01-16.txt

With moment we could use the same format: http://momentjs.com/docs/#/displaying/format/

[tb-killa]

@Koenkk What do you think about this ??? :

const path = settings.get().advanced && settings.get().advanced.log_directory ? settings.get().advanced.log_directory : data
const filename = settings.get().advanced && settings.get().advanced.log_filename ? settings.get().advanced.log_filename : 'log-'
const filedatepattern = settings.get().advanced && settings.get().advanced.log_filedatepattern ? settings.get().advanced.log_filedatepattern : 'YYYY-MM-DD-HH'

filename: path.joinPath(filename+moment(new Date()).format(filedatepattern)+'.txt'),

[tb-killa]

Hmm .. there is something wrong with your path sample :(

TypeError: path.joinPath is not a function
    at Object.<anonymous> (/opt/zigbee2mqtt/lib/util/logger.js:22:28)
    at Module._compile (module.js:652:30)
    at Object.Module._extensions..js (module.js:663:10)
    at Module.load (module.js:565:32)
    at tryModuleLoad (module.js:505:12)
    at Function.Module._load (module.js:497:3)
    at Module.require (module.js:596:17)
    at require (internal/module.js:11:18)
    at Object.<anonymous> (/opt/zigbee2mqtt/lib/mqtt.js:2:16)
    at Module._compile (module.js:652:30)

[Koenkk]

I've implemented #207.

The date pattern looks good! 😄

We should keep in mind that we also need to do a cleanup (as winston wont do that anymore becuase the log file names change).

[tb-killa]

Cool thanks.
Hope that the Pattern could also be implemented ?

What about implemented rudimental fs.unlink function themselve or maybe use some functionality from winston-files like this ? https://github.com/winstonjs/winston/blob/master/lib/winston/transports/file.js#L563

I´v do some tests.. sadly with our solution of dynamic filename the filesize and filecount doesn´t work anymore.

[tb-killa]

I´v do some more tests.
inside files.js from winston transport i´v search for the maxfiles and found that we need dirname to get them working. sadly this filecount work on direct names like log.txt and not if we got some dynamic into it like we do with timestamp. To get this working we need some patching of the functions to search for files with wildcards like filename*. This could work because we give the acutally filename via variable over.

[Koenkk]

I think that its easier to just keep the 10 latest logs (removing older ones once creating the logger).

[tb-killa]

Do you mean manually remove of files?

[Koenkk]

@tb-killa yes

[tb-killa]

Okay sounds great. Some sort of periodic triggered function (maybe with our ping function??) who checks for the files inside our definded path and remove them via fs.unlink. This also seems that we doesnt could use any more the Winston internal functions for filesize and maxfiles.
But i think our own implementation would also be good :)

[Koenkk]

Yes, I think it should be on: https://github.com/Koenkk/zigbee2mqtt/blob/master/lib/util/logger.js#L34 (only on startup). As we won't have more than 12 anyway (max 3 logs of current run, and max 9 old logs)

[tb-killa]

@Koenkk Should we delete if files older than xx Days or xx Hours ?
I´m actually working on build some sort of remove function.

[Koenkk]

I think keeping the last 10 files (and removing other ones) is good enough for now.

[tb-killa]

@Koenkk Please Check my Changes on: https://github.com/tb-killa/zigbee2mqtt/tree/logfile-extended
I´v implemented dynamic logfilename and cleanup-function.
For LogfileName you could use
configuration.yaml
with options like this

advanced:
   log_filename: '[log-]%filenamedateformat%' 
   log_filename_date_format: 'YYYY-MM-DD.HH.mm.ss'

for log_filename_date_format you could use anything like http://momentjs.com/docs/#/displaying/format/ is available.
for log_filename you could build own name, it has to contain %filenamedateformat% and other letters has to be escape by [ ] .
Note: i have given the file extension (txt)!

cleanup-function is implemented by using our logDirectory and everything else .. read comments in function ;)

I am very busy in the next few weeks, so I can only look at the project from time to time, if at all.
If you like the changes, you are welcome to provide a PR or modify and merge accordingly :)

[tb-killa]

@Koenkk nice and thanks for your work on getting it finished.
Do you need my github permission actually?
We doesnt work with Dynamic file Name?

[Koenkk]

Yes I needed your permission in order to push to your branch.

The dynamic file name causes confusion.

First file looks like:

log-2018-04-03-19:30:20.txt

Second:
log-2018-04-03-19:30:201.txt

Third:
log-2018-04-03-19:30:202.txt

So I thought it would be better to just have a separate directory per run.

Can this be closed?

[tb-killa]

Okay.
Yes close it.

[Koenkk]

Ok, great, thanks for the effort you put into it!

[tb-killa]

Thank you, the honour is yours ;)