CAF::FileWriter does not log file changes

[ned21]

Follow up from discussion in #98.

With --verbose we display the diff and log that the file was updated (which also gets echo'd to screen). Without --verbose we display nothing. Do we log anything? It would appear not because stdout is just an out of the logger, and verbose defaults to false. This seems suboptimal to me: whether a file has been changed or not should always be logged, even if not shown on stdout. Making the diff optional seems OK, especially since we don't want to log sensitive information.

A simple fix would be to log the result of the Check::File at info level. Given that until #98 this was being printed to stdout it would not be a net increase in the amount of lines shown on stdout during an interactive run.

[stdweird]

@ned21 i'd prefer not raise the default to info. i'll have a look to split up the loglevel for logtofile/syslog and stdout (or something like that).

[ned21]

Logging verbose message to the file by default but not to stdout is fine with me. We always try to be generous with what we log to a file and conservative with what we log to stdout.

[stdweird]

@ned21 @jrha i've changed my mind a bit how to handle this. i still tend to implement the splitted loglevels, but i'm afraid im'm going to reinvent Log4Perl or something like that.
would it be nicer if quattor/ncm-ncd#14 worked? well, i tried to get some part resurrected by #117. I'll try to implement the relevant part in ncm-ncd such that ncm-ncd generates an overview of the modified files. would that suffice?

[stdweird]

@ned21 this is now stdout with #117, #98 and quattor/ncm-ncd#51

2015/10/12-12:09:53 -----------------------------------------------------------
2015/10/12-12:09:54 [INFO] configure on component metaconfig executed, 0 errors, 0 warnings
2015/10/12-12:09:54 [INFO] EVENT: metaconfig modified file /etc/accountpage_db.conf

so no more updated polution, and each component logs a nice line (ofcourse, that specific format is just a proposal)

[piojo-zz]

but i'm afraid im'm going to reinvent Log4Perl or something like that.

So, why not replace CAF::Log with Log::Log4perl (or make CAF::Log use Log::Log4perl instead of LC::Log)?

[stdweird]

@Piojo instead of LC::Log? it's not like it uses it atm 😄
but 👍 on replacing it with Log4Perl

[ned21]

@stdweird [INFO] EVENT: is a ugly since now you have 12 characters of metadata before you get the real message. I haven't had time to read #117 yet but can we keep the log file optimised for humans and make a separate log that is intended to be parsed elsewhere?

[stdweird]

@ned21 the format is whatever we agree on. i guess there will be more remarks on the PRs, this is just something that could be done. the info is logged in https://github.com/quattor/ncm-ncd/pull/51/files#diff-160e27257dcc0fd21f34efa66afec9bbR344, but nothing should prevent to do something different.

"a separate log that can be parsed" sounds like part of actual solution of quattor/ncm-ncd#14.

[jouvin]

I completely missed this discussion... I tend to agree that having this kind of logging done by CAF would be a useful addition but we need to take into account that several/many components already do some logging based on CAF close() return value. The duplication is probably less a problem that the current absence of logging in some components...We may just clean it up at some point. Or do we want to make this logging by CAF potentially optional? I can imagine some use case where you would like to disable logging by CAF to have a customized message.

[stdweird]

@jouvin to be clear, this is about reducing the loglevels in CAF, it should indeed be left to the component or in e.g. ncm-ncd. see the example output in
#100 (comment)

the component does not log a single thing, it is ncm-ncd that gives an overview of any important events.

[jouvin]

May be my wording was not clear, I wanted to say that I would not like to see unconditionnally some messages logged by CAF at info level without a way for a component to disable it. I understand that the exact amount of information really displayed is controled by ncm-ncd. Your example show something logged by CAF (if I understood properly) with the message built by CAF rather than by the component. I think this is good in most cases but I can imagine some where it is not.

[stdweird]

the example reports the events after the component finished to run, so it done only by ncm-ncd. CAF does not report anything with loglevel info.
i think that the run of any component should report with info level any important changes to the system (like file updated, service restarted,..) but this code shows that this can be done also without modifying any component to insert the same messages (unless they report something more relevant/specific than 'file X changed'). i don't think it is that relevant that the messages are reported when changes happen, but rather that they are reported.

[jouvin]

I missed that. I agree that if this is a summary added by ncm-ncd after the run of each component it can be useful to have a common format for all components making easier to look for these changes.

[stdweird]

pushing this to 16.6. i'll add some functionality to report certain events when they are called, not at the end

[ned21]

At workshop we decided to change ncm-ncd so that verbose messages are always logged to the file, regardless of whether --verbose is passed on the command line. This will mean that the current log file will always reflect what files were changed and the diff. This cannot leak information provided the log files have the same permissions as the profile directory.

Using CAF::History to generate machine parseable history will be covered by separate issues.

[stdweird]

@ned21 i only now see the "provided the log files have the same permissions as the profile directory" remark.
this is currently not the case. should be easy to add however

[stdweird]

Should be fully covered in code, but the defaults are not what agreed upon to allow a migration form legacy behaviour. 2 issues are opened to change the defaults to always log with verbose_logfile quattor/ncm-ncd#94 and to make the logdir not world_readable quattor/ncm-ncd#93
quattor/configuration-modules-core#948 allows you to already change them to whatever you want, irrespective of the defaults

@ned21 @jrha imho this can be closed