manager: unified logging

• when using logging into stdio, supervisord aggregates all logs and tags them, so that it's obvious where they came from
• when logging to syslog, every process logs there directly and we rely on the syslog facility to log times and original process (however, stdio is still forwarded from all processes to the syslog in order not to miss any crucial error messages which could be printed there)
• added a new logging target from-env, which uses $KRES_LOGGING_TARGET environment variable to load the actual configuration value

closes #698 (closed)

Example log after the changes:

syslog:

Oct 12 12:20:32 dingo knot_resolver_manager.log[1238884]: Changing logging level to 'DEBUG'
Oct 12 12:20:32 dingo knot_resolver_manager.kresd_controller[1238884]: Starting service manager auto-selection...
Oct 12 12:20:32 dingo knot_resolver_manager.kresd_controller.supervisord[1238884]: Detection - supervisord controller is available for use
Oct 12 12:20:32 dingo knot_resolver_manager.kresd_controller[1238884]: Available subprocess controllers are ('supervisord',)
Oct 12 12:20:32 dingo knot_resolver_manager.kresd_controller[1238884]: Selected controller 'supervisord'
Oct 12 12:20:32 dingo knot_resolver_manager.kres_manager[1238884]: Starting controller
Oct 12 12:20:32 dingo knot_resolver_manager.kresd_controller.supervisord[1238884]: Supervisord is already running, we will just update its config...
Oct 12 12:20:32 dingo knot_resolver_manager.kres_manager[1238884]: Looking for already running workers
Oct 12 12:20:32 dingo knot_resolver_manager.kres_manager[1238884]: Testing the new config with a canary process
Oct 12 12:20:32 dingo /supervisord[1238815]: spawned: 'kresd0' with pid 1238915
Oct 12 12:20:32 dingo kresd[1238915]: [system] path = /home/vasek/Work/knot-resolver/manager/etc/knot-resolver/runtime/control/0
Oct 12 12:20:32 dingo /supervisord[1238815]: success: kresd0 entered RUNNING state, process sent ready notification via $NOTIFY_SOCKET
Oct 12 12:20:32 dingo knot_resolver_manager.kres_manager[1238884]: Canary process test passed.
Oct 12 12:20:32 dingo knot_resolver_manager.kres_manager[1238884]: Applying config to all workers
Oct 12 12:20:32 dingo knot_resolver_manager.kresd_controller.interface[1238884]: Writing config file for kresd:kresd0
Oct 12 12:20:32 dingo knot_resolver_manager.kresd_controller.interface[1238884]: Restarting kresd:kresd0
Oct 12 12:20:32 dingo /supervisord[1238815]: waiting for kresd0 to stop
Oct 12 12:20:32 dingo /supervisord[1238815]: stopped: kresd0 (exit status 0)
Oct 12 12:20:32 dingo /supervisord[1238815]: spawned: 'kresd0' with pid 1238918
Oct 12 12:20:32 dingo kresd[1238918]: [system] path = /home/vasek/Work/knot-resolver/manager/etc/knot-resolver/runtime/control/0
Oct 12 12:20:32 dingo /supervisord[1238815]: success: kresd0 entered RUNNING state, process sent ready notification via $NOTIFY_SOCKET
Oct 12 12:20:32 dingo knot_resolver_manager.kres_manager[1238884]: Starting cache GC
Oct 12 12:20:32 dingo /supervisord[1238815]: spawned: 'cache-gc' with pid 1238921
Oct 12 12:20:32 dingo /supervisord[1238815]: success: cache-gc entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
Oct 12 12:20:32 dingo knot_resolver_manager.server[1238884]: Initial configuration applied. Process manager initialized...
Oct 12 12:20:32 dingo knot_resolver_manager.server[1238884]: Starting API HTTP server on http://127.0.0.1:5000
Oct 12 12:20:32 dingo knot_resolver_manager.server[1238884]: Manager fully initialized and running in 0.214 seconds
Oct 12 12:20:32 dingo /supervisord[1238815]: success: manager entered RUNNING state, process sent ready notification via $NOTIFY_SOCKET
Oct 12 12:20:32 dingo /supervisord[1238815]: captured stdio output from cache-gc[1238921]: Knot Resolver Cache Garbage Collector, version 5.5.3
Oct 12 12:20:37 dingo /supervisord[1238815]: received SIGINT indicating exit request
Oct 12 12:20:37 dingo /supervisord[1238815]: waiting for cache-gc, kresd0, manager to die
Oct 12 12:20:37 dingo knot_resolver_manager.server[1238884]: Received SIGINT, triggering graceful shutdown
Oct 12 12:20:37 dingo knot_resolver_manager.server[1238884]: Stopping API service...
Oct 12 12:20:37 dingo knot_resolver_manager.server[1238884]: Stopping kresd manager...
Oct 12 12:20:37 dingo /supervisord[1238815]: ignoring unrecognized data on $NOTIFY_SOCKET sent from PID=1238884, data='b'STOPPING=1''
Oct 12 12:20:37 dingo knot_resolver_manager.server[1238884]: The manager run for 5 seconds...
Oct 12 12:20:37 dingo /supervisord[1238815]: stopped: manager (exit status 0)
Oct 12 12:20:37 dingo /supervisord[1238815]: stopped: kresd0 (exit status 0)
Oct 12 12:20:37 dingo /supervisord[1238815]: stopped: cache-gc (exit status 0)

stdout:

2022-10-12 12:21:30,398 manager[1239812]: [WARNING] knot_resolver_manager.log: Changing logging level to 'DEBUG'
2022-10-12 12:21:30,398 manager[1239812]: [INFO] knot_resolver_manager.kresd_controller: Starting service manager auto-selection...
2022-10-12 12:21:30,398 manager[1239812]: [DEBUG] knot_resolver_manager.kresd_controller.supervisord: Detection - supervisord controller is available for use
2022-10-12 12:21:30,398 manager[1239812]: [INFO] knot_resolver_manager.kresd_controller: Available subprocess controllers are ('supervisord',)
2022-10-12 12:21:30,398 manager[1239812]: [INFO] knot_resolver_manager.kresd_controller: Selected controller 'supervisord'
2022-10-12 12:21:30,398 manager[1239812]: [DEBUG] knot_resolver_manager.kres_manager: Starting controller
2022-10-12 12:21:30,399 manager[1239812]: [INFO] knot_resolver_manager.kresd_controller.supervisord: Supervisord is already running, we will just update its config...
2022-10-12 12:21:30,421 manager[1239812]: [DEBUG] knot_resolver_manager.kres_manager: Looking for already running workers
2022-10-12 12:21:30,443 manager[1239812]: [DEBUG] knot_resolver_manager.kres_manager: Testing the new config with a canary process
2022-10-12 12:21:30,600 supervisor[1239739]: [INFO] spawned: 'kresd0' with pid 1239845
2022-10-12 12:21:30,619 kresd0[1239845]: [system] path = /home/vasek/Work/knot-resolver/manager/etc/knot-resolver/runtime/control/0
2022-10-12 12:21:30,620 supervisor[1239739]: [INFO] success: kresd0 entered RUNNING state, process sent ready notification via $NOTIFY_SOCKET
2022-10-12 12:21:30,621 manager[1239812]: [DEBUG] knot_resolver_manager.kres_manager: Canary process test passed.
2022-10-12 12:21:30,622 manager[1239812]: [DEBUG] knot_resolver_manager.kres_manager: Applying config to all workers
2022-10-12 12:21:30,622 manager[1239812]: [DEBUG] knot_resolver_manager.kresd_controller.interface: Writing config file for kresd:kresd0
2022-10-12 12:21:30,623 manager[1239812]: [DEBUG] knot_resolver_manager.kresd_controller.interface: Restarting kresd:kresd0
2022-10-12 12:21:30,624 supervisor[1239739]: [INFO] waiting for kresd0 to stop
2022-10-12 12:21:30,626 supervisor[1239739]: [INFO] stopped: kresd0 (exit status 0)
2022-10-12 12:21:30,629 supervisor[1239739]: [INFO] spawned: 'kresd0' with pid 1239848
2022-10-12 12:21:30,643 kresd0[1239848]: [system] path = /home/vasek/Work/knot-resolver/manager/etc/knot-resolver/runtime/control/0
2022-10-12 12:21:30,643 supervisor[1239739]: [INFO] success: kresd0 entered RUNNING state, process sent ready notification via $NOTIFY_SOCKET
2022-10-12 12:21:30,645 manager[1239812]: [DEBUG] knot_resolver_manager.kres_manager: Starting cache GC
2022-10-12 12:21:30,648 supervisor[1239739]: [INFO] spawned: 'cache-gc' with pid 1239851
2022-10-12 12:21:30,649 supervisor[1239739]: [INFO] success: cache-gc entered RUNNING state, process has stayed up for > than 0 seconds (startsecs)
2022-10-12 12:21:30,650 manager[1239812]: [INFO] knot_resolver_manager.server: Initial configuration applied. Process manager initialized...
2022-10-12 12:21:30,651 manager[1239812]: [INFO] knot_resolver_manager.server: Starting API HTTP server on http://127.0.0.1:5000
2022-10-12 12:21:30,652 supervisor[1239739]: [INFO] success: manager entered RUNNING state, process sent ready notification via $NOTIFY_SOCKET
2022-10-12 12:21:30,652 manager[1239812]: [INFO] knot_resolver_manager.server: Manager fully initialized and running in 0.26 seconds
2022-10-12 12:21:30,655 cache-gc[1239851]: Knot Resolver Cache Garbage Collector, version 5.5.3
^C2022-10-12 12:21:33,659 supervisor[1239739]: [WARN] received SIGINT indicating exit request
2022-10-12 12:21:33,660 supervisor[1239739]: [INFO] waiting for cache-gc, kresd0, manager to die
2022-10-12 12:21:33,660 manager[1239812]: [INFO] knot_resolver_manager.server: Received SIGINT, triggering graceful shutdown
2022-10-12 12:21:33,660 supervisor[1239739]: [WARN] ignoring unrecognized data on $NOTIFY_SOCKET sent from PID=1239812, data='b'STOPPING=1''
2022-10-12 12:21:33,660 manager[1239812]: [INFO] knot_resolver_manager.server: Stopping API service...
2022-10-12 12:21:33,660 manager[1239812]: [INFO] knot_resolver_manager.server: Stopping kresd manager...
2022-10-12 12:21:33,662 manager[1239812]: [INFO] knot_resolver_manager.server: The manager run for 3 seconds...
2022-10-12 12:21:33,712 supervisor[1239739]: [INFO] stopped: manager (exit status 0)
2022-10-12 12:21:33,715 supervisor[1239739]: [INFO] stopped: kresd0 (exit status 0)
2022-10-12 12:21:33,717 supervisor[1239739]: [INFO] stopped: cache-gc (exit status 0)