yahoo-eng-team team mailing list archive

Thread
Date
[Bug 1347891] [NEW] mis-use of XML canonicalization in keystone tests

To: yahoo-eng-team@xxxxxxxxxxxxxxxxxxx
From: Mike Bayer <mike_mp@xxxxxxxxxxxxxxxx>
Date: Wed, 23 Jul 2014 20:18:12 -0000
Reply-to: Bug 1347891 <1347891@xxxxxxxxxxxxxxxxxx>
Sender: bounces@xxxxxxxxxxxxx
Public bug reported:

running the keystone suite on a new Fedora VM, I get many many failures
of the variety of XML comparison failing, in a non-deterministic way:

[classic@localhost keystone]$ tox -e py27 --  keystone.tests.test_versions.XmlVersionTestCase.test_v3_disabled
py27 develop-inst-noop: /home/classic/dev/redhat/keystone
py27 runtests: PYTHONHASHSEED='2335155056'
py27 runtests: commands[0] | python setup.py testr --slowest --testr-args=keystone.tests.test_versions.XmlVersionTestCase.test_v3_disabled
running testr
running=
OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
OS_LOG_CAPTURE=${OS_LOG_CAPTURE:-1} \
${PYTHON:-python} -m subunit.run discover -t ./ ./keystone/tests --list 
running=
OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
OS_LOG_CAPTURE=${OS_LOG_CAPTURE:-1} \
${PYTHON:-python} -m subunit.run discover -t ./ ./keystone/tests  --load-list /tmp/tmpCKSHDr
======================================================================
FAIL: keystone.tests.test_versions.XmlVersionTestCase.test_v3_disabled
tags: worker-0
----------------------------------------------------------------------
Empty attachments:
  pythonlogging:''-1
  stderr
  stdout

pythonlogging:'': {{{
Adding cache-proxy 'keystone.tests.test_cache.CacheIsolatingProxy' to backend.
Deprecated: keystone.common.kvs.Base is deprecated as of Icehouse in favor of keystone.common.kvs.KeyValueStore and may be removed in Juno.
Registering Dogpile Backend keystone.tests.test_kvs.KVSBackendForcedKeyMangleFixture as openstack.kvs.KVSBackendForcedKeyMangleFixture
Registering Dogpile Backend keystone.tests.test_kvs.KVSBackendFixture as openstack.kvs.KVSBackendFixture
KVS region configuration for token-driver: {'keystone.kvs.arguments.distributed_lock': True, 'keystone.kvs.backend': 'openstack.kvs.Memory', 'keystone.kvs.arguments.lock_timeout': 6}
Using default dogpile sha1_mangle_key as KVS region token-driver key_mangler
It is recommended to only use the base key-value-store implementation for the token driver for testing purposes.  Please use keystone.token.backends.memcache.Token or keystone.token.backends.sql.Token instead.
KVS region configuration for os-revoke-driver: {'keystone.kvs.arguments.distributed_lock': True, 'keystone.kvs.backend': 'openstack.kvs.Memory', 'keystone.kvs.arguments.lock_timeout': 6}
Using default dogpile sha1_mangle_key as KVS region os-revoke-driver key_mangler
Callback: `keystone.contrib.revoke.core.Manager._trust_callback` subscribed to event `identity.OS-TRUST:trust.deleted`.
Callback: `keystone.contrib.revoke.core.Manager._consumer_callback` subscribed to event `identity.OS-OAUTH1:consumer.deleted`.
Callback: `keystone.contrib.revoke.core.Manager._access_token_callback` subscribed to event `identity.OS-OAUTH1:access_token.deleted`.
Callback: `keystone.contrib.revoke.core.Manager._role_callback` subscribed to event `identity.role.deleted`.
Callback: `keystone.contrib.revoke.core.Manager._user_callback` subscribed to event `identity.user.deleted`.
Callback: `keystone.contrib.revoke.core.Manager._user_callback` subscribed to event `identity.user.disabled`.
Callback: `keystone.contrib.revoke.core.Manager._project_callback` subscribed to event `identity.project.deleted`.
Callback: `keystone.contrib.revoke.core.Manager._project_callback` subscribed to event `identity.project.disabled`.
Callback: `keystone.contrib.revoke.core.Manager._domain_callback` subscribed to event `identity.domain.disabled`.
Deprecated: keystone.middleware.core.XmlBodyMiddleware is deprecated as of Icehouse in favor of support for "application/json" only and may be removed in K.
Auth token not in the request header. Will not build auth context.
arg_dict: {}
}}}

Traceback (most recent call last):
  File "/home/classic/dev/redhat/keystone/.tox/py27/lib/python2.7/site-packages/mock.py", line 1201, in patched
    return func(*args, **keywargs)
  File "keystone/tests/test_versions.py", line 460, in test_v3_disabled
    self.assertThat(data, matchers.XMLEquals(expected))
  File "/home/classic/dev/redhat/keystone/.tox/py27/lib/python2.7/site-packages/testtools/testcase.py", line 406, in assertThat
    raise mismatch_error
MismatchError: expected = <version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
  <media-types>
    <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
    <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
  </media-types>
  <links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </links>
  <link href="http://localhost:26739/v2.0/"; rel="self"/>
  <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
</version>

actual = <version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
  <links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </links>
  <media-types>
    <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
    <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
  </media-types>
  <link href="http://localhost:26739/v2.0/"; rel="self"/>
  <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
</version>
======================================================================
FAIL: process-returncode
tags: worker-0
----------------------------------------------------------------------
Binary content:
  traceback (test/plain; charset="utf8")
Ran 2 (-19) tests in 0.155s (-1.192s)
FAILED (id=19, failures=2 (-8))
error: testr failed (1)
ERROR: InvocationError: '/home/classic/dev/redhat/keystone/.tox/py27/bin/python setup.py testr --slowest --testr-args=keystone.tests.test_versions.XmlVersionTestCase.test_v3_disabled'
____________________________________________________________________ summary ____________________________________________________________________
ERROR:   py27: commands failed


the reason for this is straightforward.  In Python, the ordering of dictionaries is non-deterministic, and can be affected by very subtle changes such as the order in which bytecode is imported or invoked.   The XML being produced here is subject to dictionary ordering issues, and above we can see that subsets of nodes, specifically <links> and <media-types> are ordered differently in the assertion case and the expected case.     Running these tests, sometimes I don't get the failure; I don't get the failure if I run under py.test, and in some tox/testr scenarios, I don't get them either.  This is normal behavior for Python dictionary ordering behavior; it is affected very randomly by the Python interpreter's order of events.   If I go into v2_VERSION_DATA and reverse the order of <media-types> and <links>, then the py.test version fails, and the tox version succeeds.

now.  keystone actually knows about this, and to overcome it they use
the function keystone/tests/matchers.py -> XMLEquals to overcome it,
making use of the lxml write_c14n() function to write canonical XML.
Good start, but unfortunately this is not enough for this case.   Below
is a simple test that illustrates that write_c14n() is not sufficient to
reorder nodes:

from lxml import etree
import io

doc1 = """
<version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
  <media-types>
    <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
    <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
  </media-types>
  <links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </links>
  <link href="http://localhost:26739/v2.0/"; rel="self"/>
  <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
</version>
"""

doc2 = """
<version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
  <links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </links>
  <media-types>
    <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
    <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
  </media-types>
  <link href="http://localhost:26739/v2.0/"; rel="self"/>
  <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
</version>
"""


def go(doc):
    parser = etree.XMLParser(remove_blank_text=True)


    doc = doc.strip()

    fp = io.BytesIO()
    dom = etree.fromstring(doc, parser)
    dom.getroottree().write_c14n(fp)
    s = fp.getvalue()

    dom = etree.fromstring(s, parser)
    return etree.tostring(dom, pretty_print=True).decode('utf-8')

dom1 = go(doc1)
dom2 = go(doc2)

print dom1

print dom2

print dom1 == dom2

output:

$ python test.py
<version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
  <media-types>
    <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
    <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
  </media-types>
  <links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </links>
  <link href="http://localhost:26739/v2.0/"; rel="self"/>
  <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
</version>

<version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
  <links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </links>
  <media-types>
    <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
    <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
  </media-types>
  <link href="http://localhost:26739/v2.0/"; rel="self"/>
  <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
</version>

False


for a solution here, the test must either be modified to check for
specific paths (e.g. such iteration through xpaths to do a tree-
comparison), or the XML output from the web service needs to ensure
ordering.

** Affects: keystone
     Importance: Undecided
         Status: New

-- 
You received this bug notification because you are a member of Yahoo!
Engineering Team, which is subscribed to Keystone.
https://bugs.launchpad.net/bugs/1347891

Title:
  mis-use of XML canonicalization in keystone tests

Status in OpenStack Identity (Keystone):
  New

Bug description:
  running the keystone suite on a new Fedora VM, I get many many
  failures of the variety of XML comparison failing, in a non-
  deterministic way:

  [classic@localhost keystone]$ tox -e py27 --  keystone.tests.test_versions.XmlVersionTestCase.test_v3_disabled
  py27 develop-inst-noop: /home/classic/dev/redhat/keystone
  py27 runtests: PYTHONHASHSEED='2335155056'
  py27 runtests: commands[0] | python setup.py testr --slowest --testr-args=keystone.tests.test_versions.XmlVersionTestCase.test_v3_disabled
  running testr
  running=
  OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
  OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
  OS_LOG_CAPTURE=${OS_LOG_CAPTURE:-1} \
  ${PYTHON:-python} -m subunit.run discover -t ./ ./keystone/tests --list 
  running=
  OS_STDOUT_CAPTURE=${OS_STDOUT_CAPTURE:-1} \
  OS_STDERR_CAPTURE=${OS_STDERR_CAPTURE:-1} \
  OS_LOG_CAPTURE=${OS_LOG_CAPTURE:-1} \
  ${PYTHON:-python} -m subunit.run discover -t ./ ./keystone/tests  --load-list /tmp/tmpCKSHDr
  ======================================================================
  FAIL: keystone.tests.test_versions.XmlVersionTestCase.test_v3_disabled
  tags: worker-0
  ----------------------------------------------------------------------
  Empty attachments:
    pythonlogging:''-1
    stderr
    stdout

  pythonlogging:'': {{{
  Adding cache-proxy 'keystone.tests.test_cache.CacheIsolatingProxy' to backend.
  Deprecated: keystone.common.kvs.Base is deprecated as of Icehouse in favor of keystone.common.kvs.KeyValueStore and may be removed in Juno.
  Registering Dogpile Backend keystone.tests.test_kvs.KVSBackendForcedKeyMangleFixture as openstack.kvs.KVSBackendForcedKeyMangleFixture
  Registering Dogpile Backend keystone.tests.test_kvs.KVSBackendFixture as openstack.kvs.KVSBackendFixture
  KVS region configuration for token-driver: {'keystone.kvs.arguments.distributed_lock': True, 'keystone.kvs.backend': 'openstack.kvs.Memory', 'keystone.kvs.arguments.lock_timeout': 6}
  Using default dogpile sha1_mangle_key as KVS region token-driver key_mangler
  It is recommended to only use the base key-value-store implementation for the token driver for testing purposes.  Please use keystone.token.backends.memcache.Token or keystone.token.backends.sql.Token instead.
  KVS region configuration for os-revoke-driver: {'keystone.kvs.arguments.distributed_lock': True, 'keystone.kvs.backend': 'openstack.kvs.Memory', 'keystone.kvs.arguments.lock_timeout': 6}
  Using default dogpile sha1_mangle_key as KVS region os-revoke-driver key_mangler
  Callback: `keystone.contrib.revoke.core.Manager._trust_callback` subscribed to event `identity.OS-TRUST:trust.deleted`.
  Callback: `keystone.contrib.revoke.core.Manager._consumer_callback` subscribed to event `identity.OS-OAUTH1:consumer.deleted`.
  Callback: `keystone.contrib.revoke.core.Manager._access_token_callback` subscribed to event `identity.OS-OAUTH1:access_token.deleted`.
  Callback: `keystone.contrib.revoke.core.Manager._role_callback` subscribed to event `identity.role.deleted`.
  Callback: `keystone.contrib.revoke.core.Manager._user_callback` subscribed to event `identity.user.deleted`.
  Callback: `keystone.contrib.revoke.core.Manager._user_callback` subscribed to event `identity.user.disabled`.
  Callback: `keystone.contrib.revoke.core.Manager._project_callback` subscribed to event `identity.project.deleted`.
  Callback: `keystone.contrib.revoke.core.Manager._project_callback` subscribed to event `identity.project.disabled`.
  Callback: `keystone.contrib.revoke.core.Manager._domain_callback` subscribed to event `identity.domain.disabled`.
  Deprecated: keystone.middleware.core.XmlBodyMiddleware is deprecated as of Icehouse in favor of support for "application/json" only and may be removed in K.
  Auth token not in the request header. Will not build auth context.
  arg_dict: {}
  }}}

  Traceback (most recent call last):
    File "/home/classic/dev/redhat/keystone/.tox/py27/lib/python2.7/site-packages/mock.py", line 1201, in patched
      return func(*args, **keywargs)
    File "keystone/tests/test_versions.py", line 460, in test_v3_disabled
      self.assertThat(data, matchers.XMLEquals(expected))
    File "/home/classic/dev/redhat/keystone/.tox/py27/lib/python2.7/site-packages/testtools/testcase.py", line 406, in assertThat
      raise mismatch_error
  MismatchError: expected = <version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
    <media-types>
      <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
      <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
    </media-types>
    <links>
      <link href="http://localhost:26739/v2.0/"; rel="self"/>
      <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
    </links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </version>

  actual = <version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
    <links>
      <link href="http://localhost:26739/v2.0/"; rel="self"/>
      <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
    </links>
    <media-types>
      <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
      <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
    </media-types>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </version>
  ======================================================================
  FAIL: process-returncode
  tags: worker-0
  ----------------------------------------------------------------------
  Binary content:
    traceback (test/plain; charset="utf8")
  Ran 2 (-19) tests in 0.155s (-1.192s)
  FAILED (id=19, failures=2 (-8))
  error: testr failed (1)
  ERROR: InvocationError: '/home/classic/dev/redhat/keystone/.tox/py27/bin/python setup.py testr --slowest --testr-args=keystone.tests.test_versions.XmlVersionTestCase.test_v3_disabled'
  ____________________________________________________________________ summary ____________________________________________________________________
  ERROR:   py27: commands failed

  
  the reason for this is straightforward.  In Python, the ordering of dictionaries is non-deterministic, and can be affected by very subtle changes such as the order in which bytecode is imported or invoked.   The XML being produced here is subject to dictionary ordering issues, and above we can see that subsets of nodes, specifically <links> and <media-types> are ordered differently in the assertion case and the expected case.     Running these tests, sometimes I don't get the failure; I don't get the failure if I run under py.test, and in some tox/testr scenarios, I don't get them either.  This is normal behavior for Python dictionary ordering behavior; it is affected very randomly by the Python interpreter's order of events.   If I go into v2_VERSION_DATA and reverse the order of <media-types> and <links>, then the py.test version fails, and the tox version succeeds.

  now.  keystone actually knows about this, and to overcome it they use
  the function keystone/tests/matchers.py -> XMLEquals to overcome it,
  making use of the lxml write_c14n() function to write canonical XML.
  Good start, but unfortunately this is not enough for this case.
  Below is a simple test that illustrates that write_c14n() is not
  sufficient to reorder nodes:

  from lxml import etree
  import io

  doc1 = """
  <version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
    <media-types>
      <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
      <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
    </media-types>
    <links>
      <link href="http://localhost:26739/v2.0/"; rel="self"/>
      <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
    </links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </version>
  """

  doc2 = """
  <version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
    <links>
      <link href="http://localhost:26739/v2.0/"; rel="self"/>
      <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
    </links>
    <media-types>
      <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
      <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
    </media-types>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </version>
  """

  
  def go(doc):
      parser = etree.XMLParser(remove_blank_text=True)

  
      doc = doc.strip()

      fp = io.BytesIO()
      dom = etree.fromstring(doc, parser)
      dom.getroottree().write_c14n(fp)
      s = fp.getvalue()

      dom = etree.fromstring(s, parser)
      return etree.tostring(dom, pretty_print=True).decode('utf-8')

  dom1 = go(doc1)
  dom2 = go(doc2)

  print dom1

  print dom2

  print dom1 == dom2

  output:

  $ python test.py
  <version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
    <media-types>
      <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
      <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
    </media-types>
    <links>
      <link href="http://localhost:26739/v2.0/"; rel="self"/>
      <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
    </links>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </version>

  <version xmlns="http://docs.openstack.org/identity/api/v2.0"; id="v2.0" status="stable" updated="2014-04-17T00:00:00Z">
    <links>
      <link href="http://localhost:26739/v2.0/"; rel="self"/>
      <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
    </links>
    <media-types>
      <media-type base="application/json" type="application/vnd.openstack.identity-v2.0+json"/>
      <media-type base="application/xml" type="application/vnd.openstack.identity-v2.0+xml"/>
    </media-types>
    <link href="http://localhost:26739/v2.0/"; rel="self"/>
    <link href="http://docs.openstack.org/"; rel="describedby" type="text/html"/>
  </version>

  False


  for a solution here, the test must either be modified to check for
  specific paths (e.g. such iteration through xpaths to do a tree-
  comparison), or the XML output from the web service needs to ensure
  ordering.

To manage notifications about this bug go to:
https://bugs.launchpad.net/keystone/+bug/1347891/+subscriptions
Follow ups

[Bug 1347891] Re: mis-use of XML canonicalization in keystone tests
From: Adam Gandelman, 2014-10-02
[Bug 1347891] Re: mis-use of XML canonicalization in keystone tests
From: Thierry Carrez, 2014-09-04
[Bug 1347891] Re: mis-use of XML canonicalization in keystone tests
From: Dolph Mathews, 2014-08-15
[Bug 1347891] [NEW] mis-use of XML canonicalization in keystone tests
From: Mike Bayer, 2014-07-23
References

[Bug 1347891] [NEW] mis-use of XML canonicalization in keystone tests
From: Mike Bayer, 2014-07-23