Metadata proxy process errors with binary user_data

[James Page]

Boot instances with binary user data content (rather than simple text) is not happy right now:

2015-10-01 13:19:39.109 10854 DEBUG neutron.agent.metadata.namespace_proxy [-] {'date': 'Thu, 01 Oct 2015 13:19:39 GMT', 'status': '200', 'content-length': '979', 'content-type': 'text/plain; charset=UTF-8', 'content-location': u'http://169.254.169.254/openstack/2013-10-17/user_data'} _proxy_request /usr/lib/python2.7/dist-packages/neutron/agent/metadata/namespace_proxy.py:90
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy [-] Unexpected error.
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy Traceback (most recent call last):
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy File "/usr/lib/python2.7/dist-packages/neutron/agent/metadata/namespace_proxy.py", line 55, in __call__
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy req.body)
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy File "/usr/lib/python2.7/dist-packages/neutron/agent/metadata/namespace_proxy.py", line 91, in _proxy_request
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy LOG.debug(content)
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy File "/usr/lib/python2.7/logging/__init__.py", line 1437, in debug
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy msg, kwargs = self.process(msg, kwargs)
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy File "/usr/lib/python2.7/dist-packages/oslo_log/log.py", line 139, in process
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy msg = _ensure_unicode(msg)
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy File "/usr/lib/python2.7/dist-packages/oslo_log/log.py", line 113, in _ensure_unicode
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy errors='xmlcharrefreplace',
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy File "/usr/lib/python2.7/dist-packages/oslo_utils/encodeutils.py", line 43, in safe_decode
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy return text.decode(incoming, errors)
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy File "/usr/lib/python2.7/encodings/utf_8.py", line 16, in decode
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy return codecs.utf_8_decode(input, errors, True)
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy TypeError: don't know how to handle UnicodeDecodeError in error callback
2015-10-01 13:19:39.109 10854 ERROR neutron.agent.metadata.namespace_proxy
2015-10-01 13:19:39.112 10854 INFO neutron.wsgi [-] 192.168.21.15 - - [01/Oct/2015 13:19:39] "GET /openstack/2013-10-17/user_data HTTP/1.1" 500 343 0.014536

This is thrown be the log call just prior to it being served back to the instance.

ProblemType: Bug
DistroRelease: Ubuntu 15.10
Package: neutron-metadata-agent 2:7.0.0~b3-0ubuntu3
ProcVersionSignature: Ubuntu 4.2.0-11.13-generic 4.2.1
Uname: Linux 4.2.0-11-generic x86_64
ApportVersion: 2.19-0ubuntu1
Architecture: amd64
Date: Thu Oct 1 13:38:21 2015
Ec2AMI: ami-000005ce
Ec2AMIManifest: FIXME
Ec2AvailabilityZone: nova
Ec2InstanceType: m1.small.osci
Ec2Kernel: None
Ec2Ramdisk: None
JournalErrors: -- No entries --
PackageArchitecture: all
SourcePackage: neutron
UpgradeStatus: No upgrade log present (probably fresh install)
mtime.conffile..etc.neutron.metadata.agent.ini: 2015-10-01T13:18:25.075633

[James Page (james-page)]

I'm just re-deploying the environment where I saw this issue - some other bug reports for this error code would indicate that maybe the unicode package is not installed.

[Ihar Hrachyshka (ihar-hrachyshka)]

I have a test case to reproduce it.

[James Page (james-page)]

Installing random unicode packages did not help.

[OpenStack Infra (hudson-openstack)]

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

[Kyle Mestery (mestery)]

James, any chance you can try the patch here [1] to see if it fixes the issue? Thanks to Ihar for the quick turnaround!

[1] https://review.openstack.org/#/c/229958/

[James Page (james-page)]

Kyle

Patch works OK for me.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/229958
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=80e3d9be4923ecad17377b1d15c8392b8a43dac6
Submitter: Jenkins
Branch: master

commit 80e3d9be4923ecad17377b1d15c8392b8a43dac6
Author: Ihar Hrachyshka <email address hidden>
Date: Thu Oct 1 17:13:25 2015 +0200

    metadata: don't crash proxy on non-unicode user data

    We attempt to log every successful metadata response with LOG.debug. But
    as per oslo.log docs [1], we should make sure that what we pass into the
    library is unicode.

    Http.request returns a tuple of Response object and a string, which is
    bytes in Python 2.x [2].

    That's why we need to convert the response content to unicode before
    passing it into oslo.log.

    To achieve it, we utilize encodeutils.safe_decode with 'replace' errors
    handling strategy, so that we don't get exceptions on input that does
    not conform unicode.

    For the unit test case, we pass a string that is not expected to convert
    to unicode with errors='strict' strategy or similar, and check that we
    still don't crash.

    While at it, we remove a check for the number of log calls being
    triggered, because it's something that we should avoid validating in
    test cases, and it cannot trigger a real bug. The mock that was used to
    count the number would also hide the bug that we try to reproduce.

    Note that the bug does not require debug to be set because the crash
    occurs before oslo.log machinery decides it should not log the message.

    [1]: http://docs.openstack.org/developer/oslo.log/usage.html#no-more-implicit-conversion-to-unicode-str
    [2]: http://bitworking.org/projects/httplib2/doc/html/libhttplib2.html#httplib2.Http.request

    Closes-Bug: #1501772
    Change-Id: I6a32c40ff117fae43913386134c8981539697ce8

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/liberty
Review: https://review.openstack.org/230513

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/230513
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=13b6d76da361178ea0b84baf4831a4c7f53e29c7
Submitter: Jenkins
Branch: stable/liberty

commit 13b6d76da361178ea0b84baf4831a4c7f53e29c7
Author: Ihar Hrachyshka <email address hidden>
Date: Thu Oct 1 17:13:25 2015 +0200

    metadata: don't crash proxy on non-unicode user data

    We attempt to log every successful metadata response with LOG.debug. But
    as per oslo.log docs [1], we should make sure that what we pass into the
    library is unicode.

    Http.request returns a tuple of Response object and a string, which is
    bytes in Python 2.x [2].

    That's why we need to convert the response content to unicode before
    passing it into oslo.log.

    To achieve it, we utilize encodeutils.safe_decode with 'replace' errors
    handling strategy, so that we don't get exceptions on input that does
    not conform unicode.

    For the unit test case, we pass a string that is not expected to convert
    to unicode with errors='strict' strategy or similar, and check that we
    still don't crash.

    While at it, we remove a check for the number of log calls being
    triggered, because it's something that we should avoid validating in
    test cases, and it cannot trigger a real bug. The mock that was used to
    count the number would also hide the bug that we try to reproduce.

    Note that the bug does not require debug to be set because the crash
    occurs before oslo.log machinery decides it should not log the message.

    [1]: http://docs.openstack.org/developer/oslo.log/usage.html#no-more-implicit-conversion-to-unicode-str
    [2]: http://bitworking.org/projects/httplib2/doc/html/libhttplib2.html#httplib2.Http.request

    Closes-Bug: #1501772
    Change-Id: I6a32c40ff117fae43913386134c8981539697ce8
    (cherry picked from commit 80e3d9be4923ecad17377b1d15c8392b8a43dac6)

[Launchpad Janitor (janitor)]

This bug was fixed in the package neutron - 2:7.0.0~rc1-0ubuntu4

---------------
neutron (2:7.0.0~rc1-0ubuntu4) wily; urgency=medium

  * Drop hard requirement on python-ryu for this cycle as it supports
    a new alternative agent implementation for Open vSwitch and is not
    the default, avoiding inclusion of ryu in main for Wily.
    - d/control: Drop (Build-)Depends on ryu, add Suggests.
    - d/p/drop-ryu-dep.patch: Patch out hard requirement on ryu.

 -- James Page <email address hidden> Fri, 02 Oct 2015 18:10:49 +0100

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/kilo
Review: https://review.openstack.org/233136

[Ihar Hrachyshka (ihar-hrachyshka)]

oslo.log was not used in Juno, so not affected.

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/233136
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=118a76fd651c19ad098cdee9d0a122a00ddc4e3b
Submitter: Jenkins
Branch: stable/kilo

commit 118a76fd651c19ad098cdee9d0a122a00ddc4e3b
Author: Ihar Hrachyshka <email address hidden>
Date: Thu Oct 1 17:13:25 2015 +0200

    metadata: don't crash proxy on non-unicode user data

    We attempt to log every successful metadata response with LOG.debug. But
    as per oslo.log docs [1], we should make sure that what we pass into the
    library is unicode.

    Http.request returns a tuple of Response object and a string, which is
    bytes in Python 2.x [2].

    That's why we need to convert the response content to unicode before
    passing it into oslo.log.

    To achieve it, we utilize encodeutils.safe_decode with 'replace' errors
    handling strategy, so that we don't get exceptions on input that does
    not conform unicode.

    For the unit test case, we pass a string that is not expected to convert
    to unicode with errors='strict' strategy or similar, and check that we
    still don't crash.

    While at it, we remove a check for the number of log calls being
    triggered, because it's something that we should avoid validating in
    test cases, and it cannot trigger a real bug. The mock that was used to
    count the number would also hide the bug that we try to reproduce.

    Note that the bug does not require debug to be set because the crash
    occurs before oslo.log machinery decides it should not log the message.

    [1]: http://docs.openstack.org/developer/oslo.log/usage.html#no-more-implicit-conversion-to-unicode-str
    [2]: http://bitworking.org/projects/httplib2/doc/html/libhttplib2.html#httplib2.Http.request

    Conflicts:
     neutron/agent/metadata/namespace_proxy.py
     neutron/tests/unit/agent/metadata/test_namespace_proxy.py

    Closes-Bug: #1501772
    Change-Id: I6a32c40ff117fae43913386134c8981539697ce8
    (cherry picked from commit 80e3d9be4923ecad17377b1d15c8392b8a43dac6)

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: stable/juno
Review: https://review.openstack.org/233546

[OpenStack Infra (hudson-openstack)]

Change abandoned by Ihar Hrachyshka (<email address hidden>) on branch: stable/juno
Review: https://review.openstack.org/233546
Reason: Actually, we don't use oslo.log, neither py34 in Juno, so no need for the change.

[OpenStack Infra (hudson-openstack)]

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

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/235300
Committed: https://git.openstack.org/cgit/openstack/neutron/commit/?id=140ccc36d172bead2605968b3d61b36cca8a0040
Submitter: Jenkins
Branch: master

commit 6dcfe3a9362ae5fcf18e5cfb59663e43446cd59c
Author: Kevin Benton <email address hidden>
Date: Tue Oct 6 19:28:47 2015 -0700

    Mock oslo policy HTTPCheck instead of urllib

    We were mocking internal behavior of oslo policy by
    patching urllib. This will break with the upcoming oslo
    release that switches to requests.

    This patch changes the mock to the HTTPCheck level and we
    can leave implementation details testing up to oslo_policy.

    Change-Id: I07957f01307e25f1547197c720eea6e3e7f0ef5a
    Closes-Bug: #1503890
    (cherry picked from commit a0f1d9d6de1560be91d3001c8ac9f880a7a5a7e0)

    Add testresources used by oslo.db fixture

    If we use oslo.db fixtures, we'll need the package or
    the next version of oslo.db release will break us.

    Closes-Bug: #1503501
    Change-Id: I7dfbf240333095d91a414ba15a439bdc4804eb25
    (cherry picked from commit 86ad967e40c2c6752ec0fb46cfd3098ede0c7178)

    Fix functional test_server tests

    Now oslo.service 0.10.0 no longer sends SIGHUP to parent and
    children services.

    This was a chance introduced by 286a6ea, and since it invalidated
    the very logic under test, this must be revised.

    (cherry picked from commit 090fe713592c2b6398d999bfa03b80cbb2054609)

    Change-Id: I18a11283925369bc918002477774f196010a1bc3
    Closes-bug: #1505438
    (cherry picked from commit 090fe713592c2b6398d999bfa03b80cbb2054609)

    Make test_server work with older versions of oslo.service

    Change I18a11283925369bc918002477774f196010a1bc3 fixed the test for
    oslo.service >= 0.10.0, but it also broke it for older versions of
    oslo.service. Since the library has minimal version of >= 0.7.0 in
    requirements.txt, test should pass for those versions too.

    Now, instead of validating that either reset() or restart() of workers
    are triggered on SIGHUP, just validate that .start() is triggered the
    expected number of times (either way, no matter how oslo.service decide
    to clean up the children, they exit and then are respawned).

    Change-Id: I41f9d3af780b3178b075bc1e7084f417a2bd1378
    Closes-Bug: #1505645
    (cherry picked from commit 7bb40921660cf29beb68e338e205499efd6ffa36)

    Fixed multiple py34 gate issues

    1. Scope mock of 'open' to module

    By mocking 'open' at the module level, we can avoid affecting
    'open' calls from other modules.

    2. Stop using LOG.exception in contexts with no sys.exc_info set

    Python 3.4 logger fills in record.exc_info with sys.exc_info() result
    [1], and then it uses it to determine the current exception [2] to
    append to the log message. Since there is no exception, exc_info[1] is
    None, and we get AttributeError inside traceback module.

    It's actually a bug in Python interpreter that it attempt to access the
    attribute when there is no exception. It turns out that it's fixed in
    latest master of cPython [3] (...

[Thierry Carrez (ttx)]

This issue was fixed in the openstack/neutron 8.0.0.0b1 development milestone.