Per Tenant Logging - Complete Implementation

[shaangill025]

resolve #2359

[dbluhm]

I'm not terribly fond of this approach. In order to keep it going, we have to remember to get a logger instance with a profile which adds overhead to a task that should incur as little overhead as possible -- if not at execution time, it at least adds overhead in code. This means more lines of code that maintainers need to scan through to find issues.

So here's my suggestion: can we use context variables and a custom log formatter that reads a wallet_id context var to retrieve the wallet id (or any other subwallet specific values) when it's available?

[shaangill025]

@dbluhm Based on your feedback, I have reworked the logging mechanism.

I added configure_per_tenant function to LoggingConfigurator which will be called during startup once here. Also added get_adapted_logger_inst utility function in aries_cloudagent/config/logging.py to improve code readability and reduce duplication, this will be called upon from different classes to get an adapted logger instance [formatted with wallet_id], if applicable.

[WadeBarnes]

What throws me off with this implementation is there is now a "special" way the get a "special" logger, rather than one consistent way to get a logger. A developer needs to be conscious of which logger they are using in a given context in order to have the desired behavior.

It would be better if the implementation was more compatible with the built in logging functionality so it would be completely transparent to the developer. So the implementation may consist of a custom log handler and a custom log formatter. I believe this is inline with @dbluhm's suggestion of a custom log formatter.

[shaangill025]

What throws me off with this implementation is there is now a "special" way the get a "special" logger, rather than one consistent way to get a logger. A developer needs to be conscious of which logger they are using in a given context in order to have the desired behavior.

@WadeBarnes The reworked implementation adds a conditional to the existing app configuration to configure logger here:

• If --log-file is passed then configure_per_tenant is called. The log handlers will then be added [i.e configuration applied] to all loggers across that agent instance. There are no special loggers in case log.file setting is involved as this will be the only type of logger.

It would be better if the implementation was more compatible with the built in logging functionality so it would be completely transparent to the developer. So the implementation may consist of a custom log handler and a custom log formatter. I believe this is inline with @dbluhm's suggestion of a custom log formatter

• Re implementation may consist of a custom log handler and a custom log formatter, that is implemented in configure_per_tenant. This function is called once during startup to apply the configuration to all loggers. But the thing is that each Logger instance declared on different files also needs to be adapted with a contextual wallet_id identifier from profile settings. And this is done by calling get_adapted_logger_inst, you will see calls to this function across most files in this PR.

Re A developer needs to be conscious of which logger they are using in a given context in order to have the desired behavior, If the file where a logger is to be declared involves just access by the root_profile then LOGGER = logging.getLogger(__name__) declaration will be sufficient [just like before]. Each wallet_id entry in log file will be set as null in this case. But if the file is expected to be accessed by tenant profiles then a call to get_adapted_logger_inst is required which update logger with wallet_id identifier.

Does this address your concerns?

[WadeBarnes]

It's the calls to get_adapted_logger_inst that are really throwing me off, this implies "special" logger processing, and requires the developer to be aware of whether or not to use the modified logging behavior. I'm wondering whether this can be implemented in a custom log handler that looks up the wallet_id identifier automatically and then the whole process becomes completely transparent; no need to call get_adapted_logger_inst to change the logging behavior.

From the compatibility standpoint I was thinking an implementation that was more compatible with the logging.config.dictConfig(), where the logging configuration could be "defined" rather than "coded". This would help clean up aries_cloudagent/config/util.py and allow the per-tenant logging configuration to be defined in a log config file.

[WadeBarnes]

I'm not super familiar with extending logging in python, but per-tenant logging, on the surface, to me, feels like an extension to the built in file log handler (or RotatingFileHandler) that collects the additional context and writes to individual files (one for each tenant), or a custom log formatter that collects and writes the additional context. In the case of the custom log formatter, it would be configured on a file log handler which is configured to write to a dynamic set of files (one for each tenant).

[shaangill025]

I'm wondering whether this can be implemented in a custom log handler that looks up the wallet_id identifier automatically and then the whole process becomes completely transparent; no need to call get_adapted_logger_inst to change the logging behavior.

For example, in aries_cloudagent/connections/base_manager.py, the wallet_id will only be known once BaseConnectionManager is being initialized. In BaseConnectionManager.__init__ Instead of calling get_adapted_logger_inst I can have the same logic [as included in the function] in there. My rationale behind get_adapted_logger_inst was to extract common code out in a utility function.

[shaangill025]

@WadeBarnes @esune This is ready for review, all changes requested should be incorporated now [incl DictConfig support]. The Logging.md has been updated and can be of help in testing this out.

[swcurran]

Let’s get this reviewed and merged in the next few days. Causing grief in debugging in multi-tenant worlds.

Thanks!

[WadeBarnes]

@esune, @loneil, @shaangill025, @swcurran, I've created a ore release image for this PR if you'd like to test it out with a traction instance; https://github.com/hyperledger/aries-cloudagent-python/pkgs/container/aries-cloudagent-python/134985613?tag=py3.9-0.11.0-pr2425-pre0

[esune]

This is looking a lot better than the first pass 🙂
I added a couple comments/questions, but other than that it looks good to me. If @dbluhm and/or @usingtechnology want to give it a look as they are more frequently involved in code changes for ACA-Py it would be great.

[esune]

This looks like the same pattern/variable that is held in default_per_tenant_logging_config.ini - any reason to have the setting it repeated here?

[shaangill025]

It is used in the following conditional code, where --log-file is provided and --multitenant enabled but no file handler is specified in a custom config (different from default):
https://github.com/hyperledger/aries-cloudagent-python/blob/1fd858763897039b39815a110e4417ce67f48763/aries_cloudagent/config/logging.py#L136

[sonarqubecloud]

Kudos, SonarCloud Quality Gate passed!   

0 Bugs
0 Vulnerabilities
0 Security Hotspots
0 Code Smells

No Coverage information
No Duplication information

[WadeBarnes]

@esune, @loneil, @shaangill025, @swcurran, A new pre release image for this PR has been created; https://github.com/hyperledger/aries-cloudagent-python/pkgs/container/aries-cloudagent-python/137906897?tag=py3.9-0.11.0-pr2425-pre1

[WadeBarnes]

Pre image was rebuilt; https://github.com/hyperledger/aries-cloudagent-python/pkgs/container/aries-cloudagent-python/137970106?tag=py3.9-0.11.0-pr2425-pre2

[shaangill025]

Closing this PR and opening #2550 due to an issue with legacy (removed) code being in the pre-release images.