Adding plaintext and JSON logging formatters

[Alsheh]

This PR adds two configurable logging formatters: plaintext and JSON. The formatter will format the supervisord logs as well as the logs of its child processes.

The logging parameters that can be added under any section in the supervisor config file to control how each process renders its logs are as follows:

• loglevel : can be one of critical, error, warn, info, debug, trace, or blather.
• logformat: this parameter dictates how to convert some of the fields available in the LogRecord into text. NOTE: using the % operator will conflict with the environment variables expansion syntax so use the python string format style { .
• logformatter: can be one of plaintext or json.

JSON Log Formatter:
In order to configure the supervisord to emit logs in a JSON format, the following configuration can be used:

[supervisord]
...
loglevel=info
logformat={asctime} {levelname} {message}
logformatter=json

Output:

{"asctime": "2021-04-20 01:09:04,439", "levelname": "CRIT", "message": "Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message."}
{"asctime": "2021-04-20 01:09:04,455", "levelname": "INFO", "message": "supervisord started with pid 1"}
{"asctime": "2021-04-20 01:09:05,463", "levelname": "INFO", "message": "spawned: 'app' with pid 9"}
...
{"asctime": "2021-04-20 01:09:07,061", "levelname": "INFO", "message": "success: app entered RUNNING state, process has stayed up for > than 1 seconds (startsecs)"}

PLAINTEXT Log Formatter:
Reversing the above log format and putting levelname and asctime in square brackets with the plaintext formatter:

[supervisord]
...
loglevel=info
logformat={message} [{levelname}] [{asctime}]
logformatter=plaintext

Output (note the app uses the default log format which can be configured under the app section):

Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message. [CRIT] [2021-04-20 01:44:13,291]
supervisord started with pid 1 [INFO] [2021-04-20 01:44:13,302]
spawned: 'app' with pid 9 [INFO] [2021-04-20 01:44:14,306]
...
success: app entered RUNNING state, process has stayed up for > than 1 seconds (startsecs) [INFO] [2021-04-20 01:44:15,845]

Using default values in the log format:
Any field is specified in the log format but not defined in the log record can default to some value in this form: {<field>:<default-value>}. You can also make the field default to an environment variable using the Supervisor environment variables expansion syntax {<field>:%(ENV_X)s}!

Example config for a log format that uses the process_name field which will default to supervisord since process_name is undefined in the log record:

[supervisord]
...
loglevel=info
logformat=[{process_name:supervisord}] {asctime} {levelname} {message}
logformatter=plaintext

Output:

[supervisord] 2021-04-21 02:47:17,223 CRIT Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.
[supervisord] 2021-04-21 02:47:17,233 INFO supervisord started with pid 1
[supervisord] 2021-04-21 02:47:18,240 INFO spawned: 'app' with pid 10

Advanced Log Format Example
This example combines the following:

• Uses the JSON formatter for supervisord.
• Uses the plaintext formatter to output logs in the key=value form for Nginx.
• The field process_name used in both log formats which will default to the defined process name in log format.
• Log formats used in both supervisord and Nginx includes the python version in the logs from an environment variable ({python_version:%(ENV_PYTHON_VERSION)s}) which leverages the fact that supervisor expands environment variables in the config file in this form %(ENV_*).

[supervisord]
...
loglevel=info
logformat={asctime} {levelname} {message} {process_name:supervisord} {python_version:%(ENV_PYTHON_VERSION)s}
logformatter=json

[program:nginx]
...
loglevel=info
logformat=process_name={process_name:nginx} timestamp={asctime} level={levelname} python_version={python_version:%(ENV_PYTHON_VERSION)s} message={message}
logformatter=plaintext

Output (note the mixed log formats):

{"asctime": "2021-04-21 03:25:08,062", "levelname": "CRIT", "message": "Supervisor is running as root.  Privileges were not dropped because no user is specified in the config file.  If you intend to run as root, you can set user=root in the config file to avoid this message.", "process_name": "supervisord", "python_version": "3.7.9"}
{"asctime": "2021-04-21 03:25:08,072", "levelname": "INFO", "message": "supervisord started with pid 1", "process_name": "supervisord", "python_version": "3.7.9"}
{"asctime": "2021-04-21 03:25:09,053", "levelname": "INFO", "message": "spawned: 'nginx' with pid 11", "process_name": "supervisord", "python_version": "3.7.9"}
process_name=nginx timestamp=2021-04-21 03:25:09,121 level=INFO python_version=3.7.9 message=Restarting nginx: nginx
...
process_name=nginx timestamp=2021-04-21 03:25:58,054 level=INFO python_version=3.7.9 message=172.17.0.1 - - [21/Apr/2021:03:25:58 +0000] "GET / HTTP/1.1" 200 8 "-" "curl/7.64.1"

Resolves: #553 #1337 #1002

[ion-f3]

Hi. I'm quite interested in this PR and willing to contribute if needed. What are the next steps here? Looks like it needs some tests for the new functionality?

[Alsheh]

hey @ion-f3 - thanks for expressing interest in this PR and your contribution is welcome! Next steps:

• Adding tests for new functionality.
• Making the PR Python 2 backward compatible to pass CI tests (only if this is a hard requirement by Supervisor).
• Investigating an issue where, sometimes, multiple lines are combined into one log message when the JSON formatter is used (e.g. {"message": "first line output\nsecond line output"}). The logger just emits whatever is given to it so my guess is that the dispatcher is combining these multiline messages; the issue is not obvious until the JSON formatter is turned on and the \n the character is included in between the combined log messages in the message field.

[wvdschel-f3]

@mnaberez @mcdonc would you guys be open to merging this into the main branch at some point?