module logging project

We were talking on irc yesterday about logging and how to make it
better for everyone.

- logging right now takes a separate exec_command per-module which
slows everything down and it causes problem if you don't want the
things you're running sent to syslog.

However, we do think encouraging local logging is a good idea - if only
b/c it means the admin can see what ansible did on the machine by
looking at normal logs.

So if we move logging to be a decision the modules make on their own
then it helps us make more intelligent logging decisions.

Each module should:

1. support logging directly (a subprocess call to logger or python
syslog module call). the tag should be 'ansible' and just send it to
auth.info or daemon.info

2. for modules which note 'changed' have them only log events on
changed (and in that case WHAT changed)

3. for modules which do not note changed - just log what is being
called and what arguments are passed in

3. if the argument '#NO_LOG' is included then do not log anything (this
is valuable for password changes, etc)

This is a potential project for someone to get started working on
ansible and help everyone out.

if no one gets to this I'll work on it but it's a great place to get
involved.

-sv

A few thoughts:

1) I was thinking that a module template would be nice. I've been
using the user module for this purpose, but there could be an official
one. That would encourage modules to be written in a standard way,
could include logger functions, etc.

2) In relation to logging, personally I'd like to see the modules pass
more info back to the overlord when state changes. If standard
functions were used, the same logging function could do both.

3) I've actually commented out the exec_command that does the logging,
as it was causing my system to hang. Haven't had time to figure out
why.

4) Could we perhaps pass an optional #DEBUG parameter to modules, that
would cause debug level logging, both locally and bubbling back to the
overlord.

-mgw

I'm going to work on these ideas with the apt module and see what
everyone thinks.

A few thoughts:

  1. I was thinking that a module template would be nice. I’ve been
    using the user module for this purpose, but there could be an official
    one. That would encourage modules to be written in a standard way,
    could include logger functions, etc.

+1.

Modules outside of core don’t have to be written in Python, but we might
as well have one.

We should keep this in the core repo in the docs/ dir, most likely
and can maintain it as our preferences change.

We can also link this through the docs project.

This would encourage usage of state, failures if states don’t match, etc.

EXCELLENT idea.

  1. In relation to logging, personally I’d like to see the modules pass
    more info back to the overlord when state changes. If standard
    functions were used, the same logging function could do both.

So we already have stderr bubbling up to the overlord, for debugging purposes.

I want to maintain the changed True/False logic, but there is nothing saying
we can’t have a standard of an “events” return which contains a series
of log-like messages and include that in the normal JSON, if the module
would like to explain itself in a more standard way. This could be something
that --verbose decides to show, for instance, and I think that’s a great idea

It is important for debugging reasons (such as module failure) that we not
require a structure for stderr.

result = {
changed: True
events: [ ‘updated the foo’, ‘updated the splat’, ‘…’ ]
}

This would of course be totally optional so old modules wouldn’t cause any
problems with it.

  1. I’ve actually commented out the exec_command that does the logging,
    as it was causing my system to hang. Haven’t had time to figure out
    why.

Strange. If you find out why, let us know. Maybe some issue with the
logger program on Debian? Seems unlikely to me, but I’m all for removing
the explicit extra calls to logger regardless.

  1. Could we perhaps pass an optional #DEBUG parameter to modules, that
    would cause debug level logging, both locally and bubbling back to the
    overlord.

I don’t like the calling convention.

Thinking about this further, I also dislike the convention of having most modules recognize commented out
magic params, just because it increases the amount of boilerplate
they need to handle. This basically makes all the module source code start
to look like a giant hack. So I’m going to make the call that we not do this.

For the no log, that’s basically would have been:

log = True
if args.find(“#NO_LOG”):
log=False
args=args.replace(“#NO_LOG”,“”)

Since we already have the argsfile convention, perhaps it is better to extend the module
calling convention to be more like this:

module-name path-to-json-args-file 1/0

where that last 1/0 is the log/don’t log bit.

That’s much more standardized and easier for people writing modules to parse.

Special care must be taken when making sure this also works with async wrapper, which would
encourage us to not do this often. As a reminder, the async wrapper takes more options, so it would
also take that 1/0 log bit on the end and pass it along to what it wrapped.

Modules that didn’t understand the last parameter also wouldn’t have to change, which would
avoid breaking existing modules.

One thing I’m also going to require is if we decide to make any broad based changes for the log thing, or the events
thing, that in order to accept the patch we must update all existing modules to follow that convention. We have a
bit of a lag in some of the modules not using the json functions now and over time it will become more difficult to tell
which is a “proper” module to use as a starting point for coding style and so forth.

Sound ok?

–Michael

About the debugging part, let’s just establish a convention of really using stderr for now. If someone wants to rename the “-D” to be the verbose option, that is fine with me, and we can cleanup the way
that information is printed.

It would simply things greatly.

(I still think log/nolog should probably be a command line argument to the module script itself, not something in the args string to parse out or ignore)

a command line argument to the module script itself? Where would we be
passing this in, then, for example, from a playbook?

- action: mymodule arg1 arg2 arg3 ???

where?

-sv

I think it would be cleanest (and most auditable) if we did:

  • name: do stuff and don’t log it
    action: module
    remote_log: False

with the default log state being True

in Runner, this maps to the command line argument to the module implementation.

If we accidentally typo’d #NO_LOG as #NOLOG or something, it would actually log, and you’d have no way to know.

However, we can (as mgw and I’ve discussed) add checking to playbook to ensure that only valid options are included and they
are all of the correct types.

How do I pass this same info in from the cli?

ansible all -m mymodule -a "stuff"

where does remote_log: false go?

-sv

--no-remote-log (-R?) seems reasonable.

Remote is quite ambiguous in this case. Is it remote to where it is initiated, or remote from where it is running.

If we get a specific nomenclature for this, we can make it clearer ?

–no-remote-log (-R?) seems reasonable.

Remote is quite ambiguous in this case. Is it remote to where it is
initiated, or remote from where it is running.

If we get a specific nomenclature for this, we can make it clearer ?

I think the opt parse argument explanation can explain this.

The frame of reference for the user should be where the (ansible) program is being used.