mask_password doesn't handle non-ASCII characters

[James Carey]

When the message passed to mask_password() contains non-ASCII characters the line:

      message = six.text_type(message)

fails with:

      UnicodeDecodeError: 'ascii' codec can't decode byte 0xe9 in position 128: ordinal not in range(128)

[James Carey (jecarey)]

We could modify the use of six.text_type to specify an encoding and then to only call it if it needs to be done:

     if not isinstance(message, six.text_type):
         message = six.text_type(message, 'utf8')

Does that imply that we may need to do this anywhere that six.text_type is used?

Another option would be to set the default encoding to 'utf8' if we are running in Python 2.x, but I see a lot of debate about whether that's a good idea or not.

[Doug Hellmann (doug-hellmann)]

Forcing the default encoding is definitely not a good idea. The function to do that is removed from Python's sys module on startup to prevent doing that.

Specifying an encoding inside mask_password() is no good either, since we don't actually know right encoding to use.

Where are we seeing byte strings containing non-ASCII characters? Those callers should probably be updated to use unicode strings themselves, and on up the stack.

We can also look at whether mask_password actually requires us to be doing the unicode conversion. Would the function work (or at least not throw an error) if we skipped that?

[James Carey (jecarey)]

I'll follow up on where the non-ASCII characters are coming from. I think is is due to translation, which makes me wonder why it wasn't unicode already.

It seems like it would be appropriate to remove it. I suspect that the thinking when adding it was that you could get a i18n._Message object passed in, but that would actually be an incorrect usage, since the mask_password should be called on the message after it has been translated and the replacement text applied.

[Doug Hellmann (doug-hellmann)]

I'll bet you're right about the use with Message objects.

[James Carey (jecarey)]

Looking at it their are two cases where mask_password is being called:
    (checked: Nova, Neutron, Cinder, Keystone)

   (1) on a message being logged:
            msg = _("Action: '%(action)s', body: "
                    "%(body)s") % {'action': action,
                                   'body': unicode(body, 'utf-8')}
            LOG.debug(logging.mask_password(msg))

   (2) on stdout and stderr (processutils.py):
                (stdout, stderr) = result
                sanitized_stdout = strutils.mask_password(stdout)
                sanitized_stderr = strutils.mask_password(stderr)

    We're seeing this problem in case #2. This includes a bug opened against cinder: https://bugs.launchpad.net/cinder/+bug/1368527

     I looked at simply removing the call to six.text_type and the concern is the case where an i18n._Message is being used in case (1) due to lazy translation being enabled. The i18n._Message contains two versions of the message. One that is the message with the replacement text applied and the other is the original message with the replacement not applied, but saved for application after translation. If the six.text_type coercion isn't done I believe the mask_password code will run and will modify the message with the replacement text applied, but not to the other. This means that if the returned i18n._Message object is translated it would return an unmasked version of the message.

    So it seems like the safest solution would be to modify mask_password() to only coerce to a six.text_type if the message is an instance of the i18n._Message object, but this exposes an internal object of oslo.i18n. This is a big change and since I don't see any cases where it isn't sent to logging, I don't think this is an issue at this time.

    So my inclination is to remove the coercion to six.text_type, but I am still concerned because there are places in the code where we call six.text_type on exceptions. We've removed the use of str() when logging them, but when string operators are called on them we replaced str() with six.text_type(). So are we assuming that our exceptions contain unicode? If so, then we should have processutils.py doing the decode on stdout and strerr before it is used to create the exception, which would mean it could be done before calling mask_password, which would also fix this failure.

[James Carey (jecarey)]

Discussion i n #openstack-oslo (http://eavesdrop.openstack.org/irclogs/%23openstack-oslo/%23openstack-oslo.2014-09-15.log) starting at 2014-09-15T15:25:56.

For Juno going to modify mask_password() to ignore the decode error when coercing. For Kilo going to look at modifying processutils to decode the messages.

[Doug Hellmann (doug-hellmann)]

Where a _Message() is logged, the caller should invoke mask_password() on the value that is passed into the _Message (body, in the example given).

Where we're logging the output of commands (or the commands themselves), processutils should ensure that it passes a unicode string to mask_password().

It would be interesting to see what happened if we raised an error if mask_password is given a byte string instead of a unicode object. I suspect that would expose a lot of places where we are not properly decoding byte strings.

[Doug Hellmann (doug-hellmann)]

For now we are going to make mask_password ignore the decoding error and work on the byte string, but in kilo we need to think about that and fix the callers.

[Doug Hellmann (doug-hellmann)]

Related bug https://bugs.launchpad.net/cinder/+bug/1368527

[Doug Hellmann (doug-hellmann)]

Fix in incubator: https://review.openstack.org/121632

[Doug Hellmann (doug-hellmann)]

oslo.utils fix: https://review.openstack.org/121657

[Sergey Gotliv (sgotliv)]

In Trove due to this issue installation of database on Fedora image doesn't work.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/131279
Committed: https://git.openstack.org/cgit/openstack/ceilometer/commit/?id=470ba0a26a8a15211639331d040812b47d745106
Submitter: Jenkins
Branch: stable/juno

commit 470ba0a26a8a15211639331d040812b47d745106
Author: James Carey <email address hidden>
Date: Mon Oct 27 14:38:25 2014 -0700

    Sync strutils from oslo-incubator for mask_password fix

    This sync pulls in:
       1131b56 Enable mask_password to handle byte code strings

    This is needed because Ceilometer commands are hitting the same
    problem Cinder was hitting in bug 1368527 which was fixed
    by this strutils update in bug 1366189.

    This is not needed in kilo because in kilo Ceilometer has moved
    to using the oslo.utils library, which has this fix in it.

    Closes-bug: #1366189
    Change-Id: I4aacbe8d44f0ae2a649294652a388fbd5e15b4c9

[Amrith Kumar (amrith)]

For trove, see https://review.openstack.org/#/c/141880/

[Amrith Kumar (amrith)]

The commit that will get us the fix (I believe) is https://review.openstack.org/#/c/141081/ which is part of the 141880 chain of fixes.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/141880
Committed: https://git.openstack.org/cgit/openstack/trove/commit/?id=6ea94c4bf73993535625cb6a440919aabcfbb7c6
Submitter: Jenkins
Branch: master

commit 6ea94c4bf73993535625cb6a440919aabcfbb7c6
Author: Amrith Kumar <email address hidden>
Date: Mon Dec 15 13:59:10 2014 -0500

    resync oslo-incubator code

    This commit syncs the following oslo incubator modules used by Trove
    and all dependent changes.

    __init__.py

    6b048e79 Let oslotest manage the six.move setting for mox

    context.py

    411ba356 Simplify is_user_context method
    9b73877b Add a RequestContext.from_dict method
    85d1ce6e Python 3: enable tests/unit/middleware/test_request_id.py
    c0d357bb Add model_query() to db.sqlalchemy.utils module

    eventlet_backdoor.py

    a3220c51 add list_opts to all modules with configuration options
    5d40e143 Remove code that moved to oslo.i18n
    90ae24bf Remove redundant default=None for config options
    fcf517d7 Update oslo log messages with translation domains
    ad17a697 Fix filter() usage due to python 3 compability
    8b2b0b74 Use hacking import_exceptions for gettextutils._
    12bcdb71 Remove vim header

    log.py

    943cb94a Merge "Make use_syslog=True log to syslog via /dev/log"
    8345204c Merge "add list_opts to all modules with configuration options"
    ac4330dd Make use_syslog=True log to syslog via /dev/log
    df774ff4 Import PublishErrorsHandler from oslo.messaging
    a3220c51 add list_opts to all modules with configuration options
    6c706c5c Delete graduated serialization files
    5d40e143 Remove code that moved to oslo.i18n
    6ff6b4b4 Switch oslo-incubator to use oslo.utils and remove old modules
    aa744115 log: add missing space in error message
    037dee00 Set stevedore log level to WARN by default
    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

    loopingcall.py

    5d40e143 Remove code that moved to oslo.i18n
    e3773930 Changes calcuation of variable delay
    ab5d5f1c Use timestamp in loopingcall
    bc48099a Log the function name of looping call
    fb4e863c Remove deprecated LoopingCall
    fcf517d7 Update oslo log messages with translation domains
    8b2b0b74 Use hacking import_exceptions for gettextutils._
    12bcdb71 Remove vim header

    service.py

    5d40e143 Remove code that moved to oslo.i18n
    6ede600f rpc, notifier: remove deprecated modules

    threadgroup.py

    1523f000 threadgroup: don't log GreenletExit
    5a1a0166 Make stop_timers() method public
    fdc88831 Add graceful stop function to ThreadGroup.stop
    5f8ace05 Merge "threadgroup: use threading rather than greenthread"
    2d06d6ca Simple typo correction
    4d18b57a threadgroup: use threading rather than greenthread
    25ff65e9 Make wait & stop methods work on all threads
    12bcdb71 Remove vim header
    9d3c34b5 Add a link method to Thread
    ...