debug log messages need to be unicode

Bug #1348244 reported by James Carey on 2014-07-24
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Cinder
High
Jay Bryant
OpenStack Compute (nova)
Undecided
James Carey
oslo-incubator
Undecided
James Carey
cinder (Ubuntu)
Undecided
Liang Chen
Trusty
Undecided
Liang Chen
nova (Ubuntu)
Undecided
Liang Chen

Bug Description

Nova SRU:
[Impact]

 * Nova services fail to start because they cannot connect to rsyslog

[Test Case]

 * Set user_syslog to True in nova.conf, stop rsyslog service and restart nova services.

[Regression Potential]

 * The following patches from 1385295 and 1399088 that address the
   regression introduced in this bug's fix are also included.
   fix-syslog-logging.patch (LP: #1385295)
   move-syslog-instantiation.patch (LP: #1399088)

When nova services log to syslog, they should wait for syslog to start prior to the nova-* services start.

Cinder SRU:
[Impact]

 * Cinder services fail to start because they cannot connect to rsyslog

[Test Case]

 * Set user_syslog to True in cinder.conf, stop rsyslog service and restart cinder services.

[Regression Potential]

 * The following patches from 1385295 and 1399088 that address the
   regression introduced in this bug's fix are also included.
   fix-syslog-logging.patch (LP: #1385295)
   move-syslog-instantiation.patch (LP: #1399088)

When cinder services log to syslog, they should wait for syslog to start prior to the cinder-* services start.

Debug logs should be:

    LOG.debug("message") should be LOG.debug(u"message")

Before the translation of debug log messages was removed, the translation was returning unicode. Now that they are no longer translated they need to be explicitly marked as unicode.

This was confirmed by discussion with dhellman. See 2014-07-23T13:48:23 in this log http://eavesdrop.openstack.org/irclogs/%23openstack-oslo/%23openstack-oslo.2014-07-23.log

The problem was discovered when an exception was used as replacement text in a debug log message:

       LOG.debug("Failed to mount image %(ex)s)", {'ex': e})

In particular it was discovered as part of enabling lazy translation, where the exception message is replaced with an object that does not support str(). Note that this would also fail without lazy enabled, if a translation for the exception message was provided that was unicode.

Example trace:

 Traceback (most recent call last):
  File "nova/tests/virt/disk/test_api.py", line 78, in test_can_resize_need_fs_type_specified
    self.assertFalse(api.is_image_partitionless(imgfile, use_cow=True))
  File "nova/virt/disk/api.py", line 208, in is_image_partitionless
    fs.setup()
  File "nova/virt/disk/vfs/localfs.py", line 80, in setup
    LOG.debug("Failed to mount image %(ex)s)", {'ex': e})
  File "/usr/lib/python2.7/logging/__init__.py", line 1412, in debug
    self.logger.debug(msg, *args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1128, in debug
    self._log(DEBUG, msg, args, **kwargs)
  File "/usr/lib/python2.7/logging/__init__.py", line 1258, in _log
    self.handle(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1268, in handle
    self.callHandlers(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 1308, in callHandlers
    hdlr.handle(record)
  File "nova/test.py", line 212, in handle
    self.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 723, in format
    return fmt.format(record)
  File "/usr/lib/python2.7/logging/__init__.py", line 464, in format
    record.message = record.getMessage()
  File "/usr/lib/python2.7/logging/__init__.py", line 328, in getMessage
    msg = msg % self.args
  File "/opt/stack/nova/.tox/py27/local/lib/python2.7/site-packages/oslo/i18n/_message.py", line 167, in __str__
    raise UnicodeError(msg)
UnicodeError: Message objects do not support str() because they may contain non-ascii characters. Please use unicode() or translate() instead.
======================================================================
FAIL: nova.tests.virt.disk.test_api.APITestCase.test_resize2fs_e2fsck_fails
tags: worker-3

James Carey (jecarey) on 2014-07-24
Changed in nova:
assignee: nobody → James Carey (jecarey)
Jay Bryant (jsbryant) wrote :

A hacking check will also need to be created to go with this to make sure this issue doesn't creep in with future commits.

Changed in cinder:
status: New → Confirmed
importance: Undecided → High
assignee: nobody → Jay Bryant (jsbryant)
milestone: none → juno-3

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

Changed in nova:
status: New → In Progress

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

Changed in cinder:
status: Confirmed → In Progress

Change abandoned by James Carey (<email address hidden>) on branch: master
Review: https://review.openstack.org/110018
Reason: After further investigation, I found the actual bug in oslo log.py and confirmed that fixing it fixes the bug I was seeing in Nova. I will update bug report with details and the Nova part will change to synchronizing the updated log.py from oslo.

Change abandoned by Jay Bryant (<email address hidden>) on branch: master
Review: https://review.openstack.org/110059
Reason: Abandoning this change as we have found where the bug resides further down the stack. Sorry for the fire drill.

James Carey (jecarey) on 2014-07-29
Changed in oslo:
assignee: nobody → James Carey (jecarey)
James Carey (jecarey) wrote :

Before the change to no longer translate debug logs all messages were being converted to unicode by the _() implementation. Now the messages for debug logs are not translated by _() but, when oslo logging is used (log.py) the intention was that as part of the process() method on the ContextAdapter class (which is a LoggerAdapter returned from oslo's getLogger method) it would ensure that the log messages were unicode. In particular the check is:

        if not isinstance(msg, six.string_types):
            msg = six.text_type(msg)

Unfortunately the isinstance() is checking if it is an instance of six.string_types (i.e. checking if it is a str in PY3 or a basestring in PY2). This means that the cast to six.text_type (unicode) is only happening when the message does not need it. Instead the check should be if it is an instance of six.text_type so that when it isn't, the cast is done.:

        if not isinstance(msg, six.text_type):
            msg = six.text_type(msg)

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

Changed in oslo:
status: New → In Progress
Rushi Agrawal (rushiagr) wrote :

Marking as invalid in Cinder.

Changed in cinder:
milestone: juno-3 → none
status: In Progress → Invalid
Jay Bryant (jsbryant) wrote :

Rushi, putting this back to confirmed and targeted. This is still an issue but we are fixing it from a different approach. I want to leave this open to track syncing the fix from Oslo.

Changed in cinder:
milestone: none → juno-3
status: Invalid → Confirmed

Reviewed: https://review.openstack.org/110772
Committed: https://git.openstack.org/cgit/openstack/oslo-incubator/commit/?id=661441359d59cd255042a844cb4921dfc95a34d3
Submitter: Jenkins
Branch: master

commit 661441359d59cd255042a844cb4921dfc95a34d3
Author: James Carey <email address hidden>
Date: Wed Jul 30 20:05:50 2014 +0000

    Correct coercion of logged message to unicode

    Changed to check if logged message is an instance of six.text_type
    and coerce it to unicode if it isn't.

    Change-Id: I26b0d3490f731f6fdb9a429aa9ef59360ddc88ba
    Closes-bug: #1348244

Changed in oslo:
status: In Progress → Fix Committed

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

Changed in cinder:
status: Confirmed → In Progress

Reviewed: https://review.openstack.org/114020
Committed: https://git.openstack.org/cgit/openstack/cinder/commit/?id=ca810742e0062f6964fed55a9e964431cfd14059
Submitter: Jenkins
Branch: master

commit ca810742e0062f6964fed55a9e964431cfd14059
Author: Jay S. Bryant <email address hidden>
Date: Wed Aug 13 12:16:49 2014 -0500

    Sync latest oslo-incubator log for debug fixes

    This patch pulls in the changes in openstack/common/log.py that
    fix the problems that popped up after we removed _() from
    around LOG.debug messages. The change in log ensures that any
    text that is not of six.text_type is converted to six.text_type.

    Current HEAD in OSLO:
    ---------------------
    commit 759bd8791ec6a4b0e89f649a4179d177530e7536
    Merge: 71d072f 631f880
    Author: Jenkins <email address hidden>
    Date: Wed Aug 13 13:37:27 2014 +0000

    Merge "Set keystonemiddleware and routes.middleware to log on WARN level"
    ---------------------

    Additional changes being merged (newest to oldest):
    ---------------------
    759bd879 -
    Merge "Set keystonemiddleware and routes.middleware to log on WARN level
    71d072f1 -
    Merge "Except socket.error if syslog isn't running"
    37c00918 -
    Add unicode coercion of logged messages to ContextFormatter
    66144135 -
    Correct coercion of logged message to unicode
    1188d88a -
    Except socket.error if syslog isn't running
    ac995bec -
    Fix E126 pep8 errors

    Note that this change required an update to config.sample due to change
    759bd879 - Merge "Set keystonemiddleware and routes.middleware to log
    on WARN level"

    Change-Id: I4b849981c65300b327076d68fbf8601d46ec61f0
    Closes-Bug: 1348244

Changed in cinder:
status: In Progress → Fix Committed

Reviewed: https://review.openstack.org/114030
Committed: https://git.openstack.org/cgit/openstack/nova/commit/?id=b29443b7f53bef00f7b96da9d7967f05ac6a1c30
Submitter: Jenkins
Branch: master

commit b29443b7f53bef00f7b96da9d7967f05ac6a1c30
Author: James Carey <email address hidden>
Date: Wed Aug 13 21:05:54 2014 +0000

    Partial oslo-incubator sync -- log.py

    This patch pulls in the changes in openstack/common/log.py that fix
    a problem exposed by the removal of translation from LOG.debug
    messages. This removal causes the messages to no longer be unicode, which
    can cause formatting problems. The changes in log.py ensure that any
    message that is not of six.test_type is coverted to six.text_type.

    Note that this is required to complete blueprint: i18n-enablement.

    Generated with:
    python update.py --base nova --dest-dir /opt/stack/nova --modules log

    log:
     759bd87 Merge "Set keystonemiddleware and routes.middleware to log on WARN l
     71d072f Merge "Except socket.error if syslog isn't running"
     37c0091 Add unicode coercion of logged messages to ContextFormatter
     6614413 Correct coercion of logged message to unicode
     1188d88 Except socket.error if syslog isn't running
     ac995be Fix E126 pep8 errors
     36e5c2d Merge "Adjust oslo logging to provide adapter is enabled for"
     631f880 Set keystonemiddleware and routes.middleware to log on WARN level
     726d00a Adjust oslo logging to provide adapter is enabled for

    Change-Id: I255a68fc60963386e8fefe65c3ffd269795adbf4
    Closes-Bug: 1348244

Changed in nova:
status: In Progress → Fix Committed
Thierry Carrez (ttx) on 2014-09-04
Changed in cinder:
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2014-09-05
Changed in nova:
milestone: none → juno-3
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2014-09-05
Changed in oslo-incubator:
milestone: none → juno-3
status: Fix Committed → Fix Released
Thierry Carrez (ttx) on 2014-10-16
Changed in nova:
milestone: juno-3 → 2014.2
Thierry Carrez (ttx) on 2014-10-16
Changed in cinder:
milestone: juno-3 → 2014.2
Liang Chen (cbjchen) on 2015-06-03
description: updated
description: updated
Liang Chen (cbjchen) on 2015-06-03
Changed in nova (Ubuntu):
status: New → In Progress
assignee: nobody → Liang Chen (cbjchen)

The attachment "trusty debdiff" seems to be a debdiff. The ubuntu-sponsors team has been subscribed to the bug report so that they can review and hopefully sponsor the debdiff. If the attachment isn't a patch, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are member of the ~ubuntu-sponsors, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issue please contact him.]

tags: added: patch
Liang Chen (cbjchen) on 2015-06-08
Changed in cinder (Ubuntu):
assignee: nobody → Liang Chen (cbjchen)
status: New → In Progress
Chris J Arges (arges) on 2015-06-16
Changed in cinder (Ubuntu):
status: In Progress → Fix Released
Changed in nova (Ubuntu):
status: In Progress → Fix Released
Changed in cinder (Ubuntu Trusty):
assignee: nobody → Liang Chen (cbjchen)
Changed in nova (Ubuntu Trusty):
assignee: nobody → Liang Chen (cbjchen)
Chris J Arges (arges) wrote :

A few comments before sponsoring:
Nova/Cinder
  - wait-syslog-on-startup.patch you mentioned was from comments in bug 1459046, can you have somebody else review this like James Page to ensure it makes sense. (Since this isn't upstream)
  - The changelog refers to bugs that aren't SRU/targeted to Ubuntu/nova/trusty, can you either make those bugs proper SRUs or change the changelog. If you use this bug as the master bug, then it should explain why those patches are needed. (Fixing regression)

Liang Chen (cbjchen) wrote :

Hi Chris,

Thanks for looking at the patch. I will contact James Page to review wait-syslog-on-startup.patch, and update the corresponding bugs that are referenced in the changelog.

Thanks,
Liang

description: updated
Liang Chen (cbjchen) on 2015-06-16
description: updated
Leonardo Borda (lborda) wrote :

Hi Guys,

Any news in regards to Liang's patch? Do you think we can have the fix in the Trusty release?

ty
Leo

Liang Chen (cbjchen) wrote :

Nova SRU is removed as it will be fixed at https://bugs.launchpad.net/ubuntu/+source/nova/+bug/1459046

Sebastien Bacher (seb128) wrote :

@Liang, do you mean that the change there shouldn't be reviewed for sponsoring anymore?

Liang Chen (cbjchen) wrote :

@Sebastien, The fix for Nova is merged at LP#1459046. cinder patch is still needed. But the current cinder patch is unnecessarily big, it can be done more easily as LP#1459046 does. I will remove the cinder patch for now, and propose a simpler one later. Thanks.

Michael Terry (mterry) wrote :

OK. Removing trusty's nova task then. And unsubscribing ubuntu-sponsors until a new patch is updated. Thanks, Liang!

no longer affects: nova (Ubuntu Trusty)
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers