ColorHandler not reset color

[Vadim Ponomarev]

I am trying to use ColorHandler from oslo_log.handlers for highlighting output to stdout. I changed my logging configuration file, added:

   [handler_test_handler]
   class = oslo_log.handlers.ColorHandler
   formatter = context
   args = (sys.stdout,)

Also, i added '%(color)s' attribute to logging_context_format_string and logging_default_format_string parametrs. When i run some openstack agent by manual, i see that oslo_log does not reset the color in stdout for each new line (see the image in attachment).

I guess, that to solve the problem need pass a separate attribute to formatter on ColorHandler class, like a '%(color_reset)s' with value "\033[0m".

[Doug Hellmann (doug-hellmann)]

How did devstack handle colors?

[Vadim Ponomarev (velizarx)]

In devstack, configuration include manual reset symbols (^[[00m). For example, see neutron configuration file:

"
logging_exception_prefix = ERROR %(name)s ^[[01;35m%(instance)s^[[00m
logging_default_format_string = %(color)s%(levelname)s %(name)s [^[[00;36m-%(color)s] ^[[01;35m%(instance)s%(color)s%(message)s^[[00m
logging_context_format_string = %(color)s%(levelname)s %(name)s [^[[01;36m%(global_request_id)s %(request_id)s ^[[00;36m%(project_name)s %(user_name)s%(color)s] ^[[01;35m%(instance)s%(color)s%(message)s^[[00m
logging_debug_format_suffix = ^[[00;33m{{(pid=%(process)d) %(funcName)s %(pathname)s:%(lineno)d}}^[[00m
"

Because of this, in devstack not see the problem. In the devstack output (journalctl -f -a --unit devstack@q-*) all ok.

To see the problem, you need to start the service in manual and specifying the logging config file. Like this:

neutron-server --config-file /etc/neutron/neutron.conf --config-file /etc/neutron/plugins/ml2/ml2_conf.ini --log-config-append /etc/neutron/logging.conf

And in the logging.conf file there should be something like:

"
[loggers]
keys = neutron

[handlers]
keys = stdout, test_handler

[formatters]
keys = context, default

[logger_neutron]
level = INFO
handlers = syslog, test_handler
qualname = neutron

[handler_test_handler]
class = oslo_log.handlers.ColorHandler
formatter = context
args = (sys.stdout,)

[handler_syslog]
level = WARNING
class = handlers.SysLogHandler
args = ('/dev/log', handlers.SysLogHandler.LOG_LOCAL0)
formatter = context

[formatter_context]
class = oslo_log.formatters.ContextFormatter

[formatter_default]
format = %(message)s
"

In actual installations openstask often used split logs of individual files. Therefore, a special logging configuration file is used.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/571791

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/571791
Committed: https://git.openstack.org/cgit/openstack/oslo.log/commit/?id=9da1f158b233b7212f010d726cca4f6230bd2e5f
Submitter: Zuul
Branch: master

commit 9da1f158b233b7212f010d726cca4f6230bd2e5f
Author: Ben Nemec <email address hidden>
Date: Fri Jun 1 17:51:53 2018 +0000

    Provide reset_color key on log record

    When logging with color, it is necessary to reset the color at the
    end of each line to avoid the color bleeding into subsequent log
    lines. This change adds a new key to the record called 'reset_color'
    that serves as a shortcut to the escape sequence to reset the color.
    It also provides documentation for the ColorHandler class that
    explains how to use it.

    Change-Id: I68f1c716cbed241f79fa65dae1affe810b8e6e30
    Closes-Bug: 1731477

[OpenStack Infra (hudson-openstack)]

This issue was fixed in the openstack/oslo.log 3.39.0 release.