Support custom log formatters across openstack charms (especially JSONFormatter) to improve parsing by log collection tools

[Dmitrii Shcherbakov]

Currently our logging.conf files look as follows across different charms:

https://github.com/openstack/charm-keystone/blob/master/templates/ocata/logging.conf

This may be fine for single-line messages like that:

(keystone.auth.core): 2017-10-22 05:08:30,817 WARNING Deprecated: Direct import of auth plugin 'keystone.auth.plugins.oauth1.OAuth' is deprecated as of Liberty in favor of its entrypoint from 'keystone.auth.oauth1' and may be removed in N.

But not for multi-line tracebacks:

(keystone): 2017-10-22 05:00:02,293 CRITICAL DBNonExistentTable: (sqlite3.OperationalError) no such table: token [SQL: u'DELETE FROM token WHERE token.expires <= ?'] [parameters: ('2017-10-20 05:00:02.2921
25',)]
Traceback (most recent call last):
  File "/usr/bin/keystone-manage", line 10, in <module>
    sys.exit(main())
... <MANY LINES HERE>
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/sql/elements.py", line 323, in _execute_on_connection
... <EVEN MORE LINES>
  File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 450, in do_execute
    cursor.execute(statement, parameters)
DBNonExistentTable: (sqlite3.OperationalError) no such table: token [SQL: u'DELETE FROM token WHERE token.expires <= ?'] [parameters: ('2017-10-20 05:00:02.292125',)]

http://paste.ubuntu.com/25794059/ (full traceback)

For example, without additional configuration, FileBeat will collect each line in a traceback as a separate message (see the screenshot attached).

Multi-line processing in tools such as FileBeat or logstash could be used to properly parse traceback and send it for storage as a single data point but this is an additional burden.

Instead, custom formatters like JSONFormatter or FluentFormatter could be used to present structured output.

JSONFormatter specifically seems to pre-process a traceback and put it into a single value in a json message:
https://git.io/vdNxc
https://git.io/vdNxB

It would be useful to have a generic mechanism to render a custom logging.conf file or just allow passing your own jinja2 template.

https://github.com/openstack/oslo.log/blob/master/doc/source/admin/nova_sample.conf
https://github.com/openstack/keystone/blob/master/etc/logging.conf.sample

[loggers]
keys=<comma-separated-values>

[handlers]
keys=<comma-separated-values>

[formatters]
keys=<comma-separated-values>

[logger_<logger-name>]
level = <level-string>
handlers = <handler-string>
qualname = <qualname-string>

[handler_<handler-name>]
class = <handler-class-name>
args = <handler-tuple>
formatter = <formatter-name> # e.g. <class-formatter> or <format-formatter>

[formatter_<class-formatter>]
class = <formatter-class-name>
# e.g class = oslo_log.formatters.JSONFormatter

[formatter_<format-formatter>]
format = <format-spec-string>

An accompanying unit test can be used as a reference for validation & supported keys reference to a certain extent.
https://git.io/vdNpZ

=====

Ideas:

* allow specifying a map of handlers to be enabled at any given moment (e.g. /var/log/keystone.log handler would be disabled in production and only enabled during debugging while /var/log/keystone.json.log would be always enabled for generic log debugging)
* allow overriding default loggers and handlers: one might want to disable a default handler but also to override it

[James Page (james-page)]

+1 on making this automatic if the openstack charms are deployed with log monitoring tools that want this feature - this would require updating the log config if filebeat or suchlike is related to the charm.

That makes this foolproof, rather than plugging in via configuration options which is never nice IMHO.

[James Page (james-page)]

(plus I'd like to see a spec for this work as it could do with discussion and peer review before implementation).