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

Bug #1726043 reported by Dmitrii Shcherbakov
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Charm Helpers
Triaged
Wishlist
Unassigned
OpenStack Ceilometer Charm
Triaged
Wishlist
Unassigned
OpenStack Cinder Charm
Triaged
Wishlist
Unassigned
OpenStack Glance Charm
Triaged
Wishlist
Unassigned
OpenStack Heat Charm
Triaged
Wishlist
Unassigned
OpenStack Keystone Charm
Triaged
Wishlist
Unassigned
OpenStack Neutron API Charm
Triaged
Wishlist
Unassigned
OpenStack Neutron Gateway Charm
Triaged
Wishlist
Unassigned
OpenStack Nova Cloud Controller Charm
Triaged
Wishlist
Unassigned

Bug Description

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

Tags: cpe-onsite
Revision history for this message
Dmitrii Shcherbakov (dmitriis) wrote :
Revision history for this message
James Page (james-page) wrote :

+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.

Changed in charm-helpers:
status: New → Triaged
Changed in charm-ceilometer:
status: New → Triaged
Changed in charm-cinder:
status: New → Triaged
Changed in charm-glance:
status: New → Triaged
Changed in charm-heat:
status: New → Triaged
Changed in charm-keystone:
status: New → Triaged
Changed in charm-neutron-api:
status: New → Triaged
Changed in charm-neutron-gateway:
status: New → Confirmed
status: Confirmed → Triaged
Changed in charm-nova-cloud-controller:
status: New → Triaged
importance: Undecided → Wishlist
Changed in charm-neutron-gateway:
importance: Undecided → Wishlist
Changed in charm-neutron-api:
importance: Undecided → Wishlist
Changed in charm-keystone:
importance: Undecided → Wishlist
Changed in charm-heat:
importance: Undecided → Wishlist
Changed in charm-glance:
importance: Undecided → Wishlist
Changed in charm-cinder:
importance: Undecided → Wishlist
Changed in charm-ceilometer:
importance: Undecided → Wishlist
Changed in charm-helpers:
importance: Undecided → Wishlist
Revision history for this message
James Page (james-page) wrote :

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

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.