feat: add tenant id to log output

[amanji]

This PR modifies the Tenant plugin with a tenant-specific log formatter that will inject the Tenant ID into log records (replacing the default Wallet ID in the ACA-Py multitenant setup).

Tenant ID is dependent on the Wallet ID which itself is dependent on the auth token present in request headers. As a result, only tenant-authorized methods and routes will log the Tenant ID.

[github-actions[bot]]

Deployment	Resource	Location
Traction
	Tenant UI	https://pr-1065-traction-tenant-ui-dev.apps.silver.devops.gov.bc.ca
	Innkeeper UI	https://pr-1065-traction-tenant-ui-dev.apps.silver.devops.gov.bc.ca/innkeeper
Aca-Py
	Admin Swagger	https://pr-1065-traction-acapy-admin-dev.apps.silver.devops.gov.bc.ca/api/doc
	Tenant Proxy Swagger	https://pr-1065-traction-tenant-proxy-dev.apps.silver.devops.gov.bc.ca/api/doc

Deployment URLs ready for review.

[loneil]

@amanji should the setup on this PR be outputting tenant identifiers on the logs to standard out?

Was poking around and I don't see them in the pod for example some snippits of creating a schema

[amanji]

The IDs only show up when using the API. It's injected as route middleware.

[loneil]

The IDs only show up when using the API. It's injected as route middleware.

All those calls do go through the API. The Tenant UI calls the API with the token same as any Tenant LOB would.

Same type of thing if I go through admin swagger

or curl

[amanji]

Not sure why the IDs are not displaying. At minimum the Wallet ID should show up in the logs.

[esune]

FYI this is rebased to aca-py 0.12.1 now. Still not seeing wallet or tenant id in standard out logs on it.

@amanji can you please take a look?

[amanji]

Resolves: #1037

[amanji]

Good catch. I'm only setting the tenant_id if one is found. I should be resetting it.

[loneil]

@amanji Things were working away but I saw the pod crashing out a couple times (thought it might be a resource thing and OCP was being suspiciously slow) but then digging I've seen a couple pods end with

Traceback (most recent call last):
File "/home/aries/.venv/bin/aca-py", line 8, in <module>
sys.exit(script_main())
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/__main__.py", line 69, in script_main
main(sys.argv)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/__main__.py", line 75, in main
run(args)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/__main__.py", line 64, in run
run_command(command, args)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/commands/__init__.py", line 38, in run_command
module.execute(argv)
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/commands/start.py", line 63, in execute
run_loop(start_app(conductor), shutdown_app(conductor))
File "/home/aries/.venv/lib/python3.9/site-packages/aries_cloudagent/commands/start.py", line 101, in run_loop
loop.run_forever()
File "/home/aries/.venv/lib/python3.9/site-packages/nest_asyncio.py", line 82, in run_forever
self._run_once()
File "/home/aries/.venv/lib/python3.9/site-packages/nest_asyncio.py", line 129, in _run_once
handle._run()
File "/usr/local/lib/python3.9/asyncio/events.py", line 94, in _run
self._loop.call_exception_handler(context)
File "/usr/local/lib/python3.9/asyncio/base_events.py", line 1786, in call_exception_handler
logger.error('Exception in default exception handler',
File "/usr/local/lib/python3.9/logging/__init__.py", line 1475, in error
self._log(ERROR, msg, args, **kwargs)
File "/usr/local/lib/python3.9/logging/__init__.py", line 1587, in _log
record = self.makeRecord(self.name, level, fn, lno, msg, args,
File "/usr/local/lib/python3.9/logging/__init__.py", line 1556, in makeRecord
rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func,
File "/home/aries/traction_plugins/traction_innkeeper/v1_0/tenant/__init__.py", line 53, in new_log_record_factory
record = prev_log_record_factory(*args, **kwargs)
File "/home/aries/traction_plugins/traction_innkeeper/v1_0/tenant/__init__.py", line 53, in new_log_record_factory
record = prev_log_record_factory(*args, **kwargs)
File "/home/aries/traction_plugins/traction_innkeeper/v1_0/tenant/__init__.py", line 53, in new_log_record_factory
record = prev_log_record_factory(*args, **kwargs)
[Previous line repeated 983 more times]
RecursionError: maximum recursion depth exceeded

Can't reproduce so far but prev_log_record_factory is something added here right? Any thoughts?

[jamshale]

I'm a bit unsure where this is at? I'll approve it though if you think it's good @amanji ?

[esune]

I'm a bit unsure where this is at? I'll approve it though if you think it's good @amanji ?

I think we need some more tweaks - see review comments. I'll run through the deployed PR later to check the output (haven't checked that yet), but the repeated instantiation of a log factory class is what I am not liking too much currently.

[amanji]

I've referenced the documentation on how the logging factory works

https://docs.python.org/3/howto/logging-cookbook.html#customizing-logrecord

I will also take another stab at filtering:

https://docs.python.org/3/library/logging.html#filter-objects

[esune]

I've referenced the documentation on how the logging factory works

https://docs.python.org/3/howto/logging-cookbook.html#customizing-logrecord

I will also take another stab at filtering:

https://docs.python.org/3/library/logging.html#filter-objects

Thanks! I think the overall approach is correct, although I am wondering what would happen if the innkeeper plugin wasn't installed/run last in the plugin stack. This is something we can ignore though, since we are in control of how things are setup for Traction and can specify the plugin to be the last one to be loaded in the startup parameters (I believe).

My main concern is mostly with creating/setting a new log factory for every request, based on its creation being part of the middleware: ideally, this would be something that is set up front by the plugin and used from there on without having to re-create the factory class again.