Additional logging options, verbosity and level.

[SalomonSmeke]

Note: This issue is intended to be a superset of: https://github.com/ionelmc/python-redis-lock/issues/60

Background

python-redis-lock locks various actions:

1. Getting a lock.
2. Failing to get a lock.
3. Succeeding in getting a lock.
4. Entering a lock refresher.
5. Exiting a lock refresher.
6. Starting a lock refresher.
7. Attempting to stop a lock refresher.
8. Acking a stopped lock refresher.
9. Releasing lock.

These by default log always, and always at a "debug" level.

Problem

Twofold! Firstly, one might want to add additional logging points (like in issue 60) but since these log indiscriminately, the cost of adding a log is ergonomically high. Secondly, the constant debug output might be undesirable in certain environments.

Solutions

I have a couple of ideas about how to solve this. Would love some input, after which I am happy to implement and submit a PR. The proposals come in two parts, "how to solve at runtime" and "how to configure".

Proposal A

Runtime

Categorize logs by task. "Locking, Unlocking, Refreshing." and use a Enum to determine logging levels, represented here as a dict.

{
   "locking": "debug",
   "unlocking": "debug",
   "refreshing": None
}

Configuring

A config file or stateful component to the library would be best here I think. Open to suggestions. passing such a complex map to each operation, even optionally as a kwarg is unwieldy.

Proposal B

Runtime

Categorize logs by importance. "Info, Warning." and use a verbosity argument to determine logging levels.

fn(verbosity=0) # dont log
fn(verbosity=1) # log warning as debug
fn(verbosity=2) # log warning as info
fn(verbosity=3) # log warning as warning
fn(verbosity=4) # log warning as warning, log info as debug
fn(verbosirty=5) # log warning as warning, log info as info

Given the above mapping I would default to 4 which most closely matches current behavior.

Configuring

Verbosity could be added to every external facing call. But threading that through would be quite messy. Possibly worth decorating class members to intercept the verbosity argument and set the level at the Lock instance scope, which we would read from subsequently. Alternatively it could be threaded through. Finally: could do it as a config file or stateful component, but seems too heavy handed for what is essentially an integer.

Others

Of course any other way you see fit for this works for me! To be 100% clear: consider this me formally volunteering to take this on once we select an approach.

[SalomonSmeke]

Personal use-case: id use verbosity=3. My preference is proposal B.

[ionelmc]

TBH I would like to have this completely configurable via logging. No enums, no flags, no special configuration api in the redis-lock library - the logging system is already configurable enough - why reinvent it?

We can have suffixed loggers for your particular usecase where you'd like to filter certain events. Eg:

redis_lock.acquire:DEBUG:               Getting a lock.
redis_lock.acquire:WARN:                Failing to get a lock.
redis_lock.acquire:INFO:                Succeeding in getting a lock.
redis_lock.refresh.thread.start:DEBUG:  Entering a lock refresher.
redis_lock.refresh.thread.exit:DEBUG:   Exiting a lock refresher.
redis_lock.refresh.start:DEBUG:         Starting a lock refresher.
redis_lock.refresh.shutdown:DEBUG:      Attempting to stop a lock refresher.
redis_lock.refresh.exit:DEBUG:          Acking a stopped lock refresher.
redis_lock.release:DEBUG:               Releasing lock.

[SalomonSmeke]

Makes sense to me! How would you like these to be configurable?

IE: how does someone using a library specify that they dont want output from one of these loggers.

Is the expectation that the user calls redis_lock.logger["acquire"].disabled = True ?

[ionelmc]

Something along the lines of:

logging.getLogger('redis_lock.acquire').disabled = True
logging.getLogger('redis_lock.refresh.thread.start').disabled = True
etc 

Or dict configs like:

{
    'version': 1,
    'disable_existing_loggers': False,
    'loggers': {
        'redis_lock.acquire': {'handlers': [], 'propagate': False},
        'redis_lock.refresh.thread.start': {'handlers': [], 'propagate': False},
    },
    ...
}

[SalomonSmeke]

Works for me!

Plan is to:

a) replace this with a dict containing the various loggers. b) replace .debug with the appropriate logging levels per the OP.

you good if I write/submit a PR along those lines?

[ionelmc]

Sure, please do.

[SalomonSmeke]

@ionelmc done btw!

[SalomonSmeke]

Merged!