Add minimal fixes to get logging working

[pvandyken]

There was previously no central initializing of handlers for logging, so only WARNING and higher was getting logged and without a modicum of formatting.

This adds a centralized _logging module to initialize the base logger. This gets called at the two app entrypoints: snakebids.admin:main and upon initialization of SnakebidsApp

I've never implemented logging before, so I wasn't sure of the "correct" way to do it; if anyone has suggestions, let me know. Obviously the system could get more sophisticated, especially with colors, etc, but this gets the basics working.

[tkkuehn]

Thanks for making this PR, I think this is worth implementing and was a good motivation to read about Python logging more specifically.

This all seems pretty much in line with the best practices, but there are a couple of changes that would line up better with my gut preference (I'm open to reasons that the current way is preferable, though):

• Set up the top-level logger in __init__.py (with logging.getLogger(__name__)) to make its existence explicit to anyone who looks there.
• Don't set up a formatter for the top-level logger when SnakeBidsApp is instantiated (best practice seems to be to leave the default config in place in a library and let the caller add formatters etc. if they want).
• Set up the formatter for the admin CLI in admin.py and remove _logging (as of now I don't think there are any plans to add another module that would need _logging.setup_logger).
• Add an example of logger setup (could be the same as what's in _logging now) in the template run.py so people can see how to edit the config in their generated apps if they want.

[pvandyken]

• Set up the top-level logger in __init__.py (with logging.getLogger(__name__)) to make its existence explicit to anyone who looks there.

I'm not familiar enough with the details of python importing: would that code be rerun every single time snakebids or a submodule thereof is imported? If so, is that a problem?

• Don't set up a formatter for the top-level logger when SnakeBidsApp is instantiated (best practice seems to be to leave the default config in place in a library and let the caller add formatters etc. if they want).

I am aware of this, although for clarity, I believe the issue lies more with adding a handler, rather than just the formatting of the handler.

I should have explained my rationale better here, but I forgot. The idea was that since snakebids is sort of supposed to be batteries-included, and since setting up logging is probably not at the forefront a snakebids devs mind, I wanted to have something working out of the box. This is why I made the snakebids root logger available as a property of SnakebidsApp for easier modification.

Even given the above rationalization, a simpler means to disable this built-in logging could be provided (something very doable, but we could add simple method or something)

• Set up the formatter for the admin CLI in admin.py and remove _logging (as of now I don't think there are any plans to add another module that would need _logging.setup_logger).

• Add an example of logger setup (could be the same as what's in _logging now) in the template run.py so people can see how to edit the config in their generated apps if they want.

Response to these follows from above.

[tkkuehn]

would that code be rerun every single time snakebids or a submodule thereof is imported? If so, is that a problem?

The key thing here I think is that "Multiple calls to getLogger() with the same name will always return a reference to the same Logger object." So whether snakebids.logger gets reassigned in the __init__.py shouldn't make a difference as far as I can tell.

This is why I made the snakebids root logger available as a property of SnakebidsApp for easier modification.

I guess the fundamental question here is what the easiest way is for app developers to edit the logging config. logger.getLogger("snakebids") is available anywhere, but they need to know that's the name of our top-level logger. SnakeBidsApp.logger also works and will have the benefit of showing up in the API docs, but my (potentially incorrect) sense is that most app developers will only be operating on a SnakeBidsApp in run.py, so my sense is we may as well put our preferred default logger config in the run.py template so it's obvious how to change it.

[pvandyken]

logger.getLogger("snakebids") is available anywhere, but they need to know that's the name of our top-level logger.

I've definitely seen this type of thing in libraries before (just documenting the name of the logger), but I can't remember where. The reason I had a property had more to do with timing... With refactoring the property can disappear.

One other thing that occurs to me, and that the PR in it's current state doesn't achieve, is that if just generate_inputs is used (e.g. just snakemake without the snakebids app), the logs should still be printed out. Albeit the most relevant ones are errors and warnings and they should print regardless.

But I think this drives at my basic point and concern: in the absence of any special actions, snakebids needs to be able to print out its logs. For anything less severe than warning, this means adding a handler somewhere.

we may as well put our preferred default logger config in the run.py template so it's obvious how to change it.

But would this not clutter up the run.py? For the, I think, very small minority of people who will want to roll out custom logging. If anything, I would start going the route of django, sphinx, etc, and having some sort of settings.py where we can put default logging config. But we don't have anything else that needs configuring, so it's not much of a settings file. Unless we also move CLI configuration into this settings.py...

[tkkuehn]

in the absence of any special actions, snakebids needs to be able to print out its logs. For anything less severe than warning, this means adding a handler somewhere.

Ah I guess my thinking here was that our desired default behaviour is just to print warnings, errors, and any non-log output via print (and then invoke snakemake with its default logging). My inclination is for generally somewhat more terse output (i.e. I think INFO-level logging shouldn't need to be printed in normal operation of a library but may need to be activated for debugging or monitoring). My main concern about the implementation in this PR is that it seems harder for a Snakebids app developer to remove a handler that we instantiate in the library than to add one that does (only) what they want.

That said I think (without much thought about its practicality) adding default CLI args for increased/decreased verbosity would be a reasonable approach (i.e. -q to only log errors, -v to log info and above, and -vv to log debug and above if we add any DEBUG statements).

if just generate_inputs is used (e.g. just snakemake without the snakebids app), the logs should still be printed out. Albeit the most relevant ones are errors and warnings and they should print regardless.

I think it's largely fine to just print out errors and warnings here, but agree that it would be hard for beginners to know how to get more fine-grained logs in this situation. If we anticipate a lot of beginners using generate_inputs outside the context of a SnakeBidsApp maybe it would be worth adding a verbose argument that adds a handler, but I don't really love that either. This was a good point, I think there are trade-offs to any way of handling it.

[pvandyken]

Ah I guess my thinking here was that our desired default behaviour is just to print warnings, errors, and any non-log output via print (and then invoke snakemake with its default logging)

print() should not be used for progress and incidental outputs because it can interfere with important runtime outputs, especially when those outputs are piped to another process. Logs can easily be disabled, and by default are output to stderr.

My inclination is for generally somewhat more terse output (i.e. I think INFO-level logging shouldn't need to be printed in normal operation of a library but may need to be activated for debugging or monitoring).

Searching the current repository for info level logs, all the results are logs that I think should be printed out by default. Now, they were perhaps written without an overriding philosophy on log levels (although @akhanf might want to weigh in here) and the log levels can be changed. There's plenty of precedent for using warning and higher as default output, including the very logging module's default behaviour, and I've no issue with keeping it that way. But then we should probably audit the existing logs and agree on sensible levels.

That said I think (without much thought about its practicality) adding default CLI args for increased/decreased verbosity would be a reasonable approach (i.e. -q to only log errors, -v to log info and above, and -vv to log debug and above if we add any DEBUG statements).

This gets into the very heart of complications involved in wrapping another app. Snakemake obviously has its own logging and cli switches, including a somewhat complicated keyword version of --quiet. If we rolled anything out here it would need to play nicely with snakemake. That's not to say we should avoid this: I think in general it would be nice for bidsapp consumers if they didn't need to know anything about snakemake, which currently is not the case (they need to know at minimum how to dry run, unlock a snakemake process, probably how to clear metadata, etc). This conversation is probably best left to a new issue, but I'd be interested in learning more about the hippunfold experience with this.

[tkkuehn]

Ah I guess my thinking here was that our desired default behaviour is just to print warnings, errors, and any non-log output via print (and then invoke snakemake with its default logging)

print() should not be used for progress and incidental outputs because it can interfere with important runtime outputs, especially when those outputs are piped to another process. Logs can easily be disabled, and by default are output to stderr

I did not write this clearly -- I meant that important runtime (i.e. non-log) outputs should be be output with print, in addition to logs being handled by the logging mechanism. I think we're on the same page here.

Searching the current repository for info level logs, all the results are logs that I think should be printed out by default.

Agreed on this and the rest of what you said in this paragraph about settling on a consistent log level approach. I think in particular all the info-level logs I found in the repo currently could justifiably be warnings.

This gets into the very heart of complications involved in wrapping another app. Snakemake obviously has its own logging and cli switches, including a somewhat complicated keyword version of --quiet. If we rolled anything out here it would need to play nicely with snakemake. That's not to say we should avoid this: I think in general it would be nice for bidsapp consumers if they didn't need to know anything about snakemake, which currently is not the case (they need to know at minimum how to dry run, unlock a snakemake process, probably how to clear metadata, etc). This conversation is probably best left to a new issue, but I'd be interested in learning more about the hippunfold experience with this.

This all makes sense to me! Having two verbosity handling mechanisms side by side and clearly delineating them would certainly introduce another instance of this class of problem.

[pvandyken]

Okay, then for this PR, there were a few issues and inconsistencies that need to be dealt with, but I'll remove the handlers and marking everything that should be logged as at least warning. That'll get everything to a "better-than-nothing" functional state, which was the original intent of this PR.

[pvandyken]

I will continue to keep the handler for the administrative tasks, however.