New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix remaining failing test in 5.2 #2195

Closed
pbauer opened this Issue Oct 27, 2017 · 11 comments

Comments

Projects
None yet
5 participants
@pbauer
Member

pbauer commented Oct 27, 2017

Plone 5.2 - Python 2.7 is finally green but we still have 9 failling tests in http://jenkins.plone.org/job/plone-5.2-python-2.7-at/.
This is a meta-ticket so that people do not work on the same issue at the same time.

Here are these tests and links to issue/pr.

  • Products.ATContentTypes.tests.traversal.txt see below
  • Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional.test_attacker_redirect passes locally. Fixed in plone/Products.CMFFormController#14
  • Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional.test_regression passes locally. Fixed in plone/Products.CMFFormController#14
  • plone.app.blob.tests.test_integration.IntegrationTests.testIconLookupForUnknownMimeType. Issue #2194
  • src.plone.app.blob.tests.replacement-types.txt. Issue #2193
  • Products.Archetypes.tests.traversal.txt PR: zopefoundation/Zope#215
  • plone.app.blob.tests.test_replacements.FileReplacementTests.testCreateFileBlob PR: plone/plone.app.blob#44
  • plone.app.imaging.tests.test_new_scaling.ImagePublisherTests.testPublishFTPScaleViaUID. PR: zopefoundation/Zope#214
  • plone.app.imaging.tests.test_new_scaling.ImagePublisherTests.testPublishWebDavScaleViaUID. PR: zopefoundation/Zope#214
  • Robot.Test Controlpanel Types.Scenario: Allow comments for Link Type Fix: 561bc78
@pbauer

This comment has been minimized.

Show comment
Hide comment
@pbauer

pbauer Oct 27, 2017

Member

I'm working on Products.ATContentTypes.tests.traversal.txt at the moment.

Member

pbauer commented Oct 27, 2017

I'm working on Products.ATContentTypes.tests.traversal.txt at the moment.

@pbauer

This comment has been minimized.

Show comment
Hide comment
@pbauer

pbauer Oct 27, 2017

Member

Products.ATContentTypes.tests.traversal.txt is partly fixed with zopefoundation/Zope#215. But in line 252 there is another issue with PUT:

  >>> print http(r"""
  ... PUT /%s/simple_folder/index_html HTTP/1.1
  ... Authorization: Basic %s:%s
  ... Content-Type: text/plain; charset="utf-8"
  ... Depth: 0
  ...
  ... Simple Folder Index
  ... """ % (portal_name, default_user, default_password), handle_errors=False, foo=True)
  HTTP/1.1 201 Created
  ...

For 5.1 PUT of Zope/webdav/NullResource.py(105)PUT() is used but in 5.2 it is ZServer/webdav/Resource.py(239)PUT(). The question is why?

Details: The (swallowed) error is raise MethodNotAllowed('Method not supported for this resource.') by ZServer.webdav.Resource.Resource.PUT
Stepping up to Zope/src/ZPublisher/WSGIPublisher.py(56)call_object():
obj is <bound method FSPageTemplate.PUT of <FSPageTemplate at /plone/index_html used for /plone/simple_folder>>.

Doing exactly the same in Plone 5.1 in call_object the equivalent object is
<bound method NullResource.PUT of <webdav.NullResource.NullResource object at 0x1156bcc08>>

Member

pbauer commented Oct 27, 2017

Products.ATContentTypes.tests.traversal.txt is partly fixed with zopefoundation/Zope#215. But in line 252 there is another issue with PUT:

  >>> print http(r"""
  ... PUT /%s/simple_folder/index_html HTTP/1.1
  ... Authorization: Basic %s:%s
  ... Content-Type: text/plain; charset="utf-8"
  ... Depth: 0
  ...
  ... Simple Folder Index
  ... """ % (portal_name, default_user, default_password), handle_errors=False, foo=True)
  HTTP/1.1 201 Created
  ...

For 5.1 PUT of Zope/webdav/NullResource.py(105)PUT() is used but in 5.2 it is ZServer/webdav/Resource.py(239)PUT(). The question is why?

Details: The (swallowed) error is raise MethodNotAllowed('Method not supported for this resource.') by ZServer.webdav.Resource.Resource.PUT
Stepping up to Zope/src/ZPublisher/WSGIPublisher.py(56)call_object():
obj is <bound method FSPageTemplate.PUT of <FSPageTemplate at /plone/index_html used for /plone/simple_folder>>.

Doing exactly the same in Plone 5.1 in call_object the equivalent object is
<bound method NullResource.PUT of <webdav.NullResource.NullResource object at 0x1156bcc08>>

@ale-rt

This comment has been minimized.

Show comment
Hide comment
@ale-rt

ale-rt Oct 29, 2017

Member

Just a note: reverting this zopefoundation/Products.CMFCore@05b3968#diff-4e6966d1d7ef0aaed5a8c2322c887fb1
is enough to make the test plone.app.blob.tests.test_integration.IntegrationTests.testIconLookupForUnknownMimeType pass.
If we keep the test like it is now the goal is to have utool.getPortalObject().unrestrictedTraverse(icon) actually resolve the icon.

Member

ale-rt commented Oct 29, 2017

Just a note: reverting this zopefoundation/Products.CMFCore@05b3968#diff-4e6966d1d7ef0aaed5a8c2322c887fb1
is enough to make the test plone.app.blob.tests.test_integration.IntegrationTests.testIconLookupForUnknownMimeType pass.
If we keep the test like it is now the goal is to have utool.getPortalObject().unrestrictedTraverse(icon) actually resolve the icon.

@jensens jensens added this to the Plone 5.2 milestone Nov 1, 2017

@pbauer

This comment has been minimized.

Show comment
Hide comment
@pbauer

pbauer Nov 6, 2017

Member

The two issues that pass locally might be fixed with plone/Products.Marshall@23a7752

Member

pbauer commented Nov 6, 2017

The two issues that pass locally might be fixed with plone/Products.Marshall@23a7752

@pbauer

This comment has been minimized.

Show comment
Hide comment
@pbauer

pbauer Nov 9, 2017

Member

plone/Products.Marshall@23a7752 fixed failures I had when running ./bin/test --layer plone.app.testing.bbb.PloneTestCase -s Products.Marshall -s Products.CMFFormController but sadly not the two KeyError: Application. I will investigate further.

The remaining failure in Products.ATContentTypes.tests.traversal.txt where NullResource was not used in 5.2 was fixed with zopefoundation/Zope#221 but not merged. @davisagli: Any idea when you might have a look at that again?

Member

pbauer commented Nov 9, 2017

plone/Products.Marshall@23a7752 fixed failures I had when running ./bin/test --layer plone.app.testing.bbb.PloneTestCase -s Products.Marshall -s Products.CMFFormController but sadly not the two KeyError: Application. I will investigate further.

The remaining failure in Products.ATContentTypes.tests.traversal.txt where NullResource was not used in 5.2 was fixed with zopefoundation/Zope#221 but not merged. @davisagli: Any idea when you might have a look at that again?

@davisagli

This comment has been minimized.

Show comment
Hide comment
@davisagli

davisagli Nov 9, 2017

Member

@pbauer I've been trying a different approach to that one in plone/plone.app.folder#14 but I haven't gotten it quite right yet.

Member

davisagli commented Nov 9, 2017

@pbauer I've been trying a different approach to that one in plone/plone.app.folder#14 but I haven't gotten it quite right yet.

pbauer added a commit to plone/Products.CMFFormController that referenced this issue Nov 9, 2017

@pbauer

This comment has been minimized.

Show comment
Hide comment
@pbauer

pbauer Nov 9, 2017

Member

So here is small story about the failing tests in Products.CMFFormController. Here is the spoiler: I did not find the issue so I migrated them to proper plone.app.testing and worked around it like this. I probably should have done that first. But I still think the approach I took might be of interest for those who do not regularly have to deal tests due to test-isolation issues.

The two breaking tests test_attacker_redirect and test_regression were passing when the ran in isolation or when all test of Products.CMFFormController ran. So how can I find the issue assuming the traceback is not really helpful? Products.CMFFormController is dead but sadly still used by some of our older ControllerPageTemplates - they need to die!

Here is the relevant part of the log:

#### Running tests for group Archetypes ####
Running Products.Archetypes.tests.attestcase.Archetypes:Functional tests:
  Set up plone.testing.zca.LayerCleanup in 0.000 seconds.
  Set up plone.testing.z2.Startup in 0.152 seconds.
  Set up plone.app.testing.layers.PloneFixture in 14.741 seconds.
  Set up plone.app.testing.bbb.PloneTestCaseFixture in 3.482 seconds.
  Set up Products.Archetypes.tests.attestcase.ATTestCaseFixture in 0.593 seconds.
  Set up Products.Archetypes.tests.attestcase.Archetypes:Functional in 0.000 seconds.
  Ran 476 tests with 0 failures, 0 errors and 0 skipped in 1 minutes 36.839 seconds.
Running Products.PortalTransforms.testing.PortalTransformsLayer:Integration tests:
  Tear down Products.Archetypes.tests.attestcase.Archetypes:Functional in 0.000 seconds.
  Tear down Products.Archetypes.tests.attestcase.ATTestCaseFixture in 0.008 seconds.
  Tear down plone.app.testing.bbb.PloneTestCaseFixture in 0.008 seconds.
  Set up plone.app.event.testing.PAEventLayer in 0.902 seconds.
  Set up plone.app.contenttypes.testing.PloneAppContenttypes in 0.914 seconds.
  Set up Products.PortalTransforms.testing.ProductsPortalTransformsLayer in 0.032 seconds.
  Set up Products.PortalTransforms.testing.PortalTransformsLayer:Integration in 0.000 seconds.
  Ran 94 tests with 0 failures, 0 errors and 0 skipped in 39.797 seconds.
Running Testing.ZopeTestCase.layer.ZopeLite tests:
  Tear down Products.PortalTransforms.testing.PortalTransformsLayer:Integration in 0.000 seconds.
  Tear down Products.PortalTransforms.testing.ProductsPortalTransformsLayer in 0.004 seconds.
  Tear down plone.app.contenttypes.testing.PloneAppContenttypes in 0.469 seconds.
  Tear down plone.app.event.testing.PAEventLayer in 0.022 seconds.
  Tear down plone.app.testing.layers.PloneFixture in 0.077 seconds.
  Tear down plone.testing.z2.Startup in 0.019 seconds.
  Tear down plone.testing.zca.LayerCleanup in 0.001 seconds.
  Set up Testing.ZopeTestCase.layer.ZopeLite in 0.018 seconds.
  Ran 7 tests with 0 failures, 0 errors and 0 skipped in 0.032 seconds.
Running plone.app.testing.bbb.PloneTestCase:Functional tests:
  Tear down Testing.ZopeTestCase.layer.ZopeLite in 0.000 seconds.
  Set up plone.testing.zca.LayerCleanup in 0.000 seconds.
  Set up plone.testing.z2.Startup in 0.101 seconds.
  Set up plone.app.testing.layers.PloneFixture in 9.722 seconds.
  Set up plone.app.testing.bbb.PloneTestCaseFixture in 2.628 seconds.
  Set up plone.app.testing.bbb.PloneTestCase:Functional in 0.000 seconds.


Error in test test_attacker_redirect (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Traceback (most recent call last):
  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Products.CMFFormController/Products/CMFFormController/tests/testRedirectTo.py", line 97, in test_attacker_redirect
    handle_errors=False,
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/functional.py", line 43, in wrapped_func
    return func(*args, **kw)
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/functional.py", line 127, in publish
    wsgi_result = publish(env, start_response)
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/ZPublisher/WSGIPublisher.py", line 254, in publish_module
    with load_app(module_info) as new_mod_info:
  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/sandbox.py", line 73, in load_app
    with ZPublisher.WSGIPublisher.__old_load_app__(module_info) as ret:
  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/ZPublisher/WSGIPublisher.py", line 220, in load_app
    app = app_wrapper()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/App/ZApplication.py", line 78, in __call__
    return connection.root()[self._name]
  File "/home/jenkins/shiningpanda/jobs/2fa08faf/virtualenvs/d41d8cd9/lib/python2.7/UserDict.py", line 40, in __getitem__
    raise KeyError(key)
KeyError: 'Application'



Error in test test_regression (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Traceback (most recent call last):
  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Products.CMFFormController/Products/CMFFormController/tests/testRedirectTo.py", line 71, in test_regression
    handle_errors=False,
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/functional.py", line 43, in wrapped_func
    return func(*args, **kw)
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/functional.py", line 127, in publish
    wsgi_result = publish(env, start_response)
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/ZPublisher/WSGIPublisher.py", line 254, in publish_module
    with load_app(module_info) as new_mod_info:
  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/sandbox.py", line 73, in load_app
    with ZPublisher.WSGIPublisher.__old_load_app__(module_info) as ret:
  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/ZPublisher/WSGIPublisher.py", line 220, in load_app
    app = app_wrapper()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/App/ZApplication.py", line 78, in __call__
    return connection.root()[self._name]
  File "/home/jenkins/shiningpanda/jobs/2fa08faf/virtualenvs/d41d8cd9/lib/python2.7/UserDict.py", line 40, in __getitem__
    raise KeyError(key)
KeyError: 'Application'

  Ran 68 tests with 0 failures, 2 errors and 0 skipped in 1.626 seconds.
Running plone.app.folder.tests.layer.plone.app.folder testing:Integration tests:
  Set up plone.app.folder.tests.layer.IntegrationFixture in 0.027 seconds.
  Set up plone.app.folder.tests.layer.plone.app.folder testing:Integration in 0.000 seconds.
  Ran 27 tests with 0 failures, 0 errors and 0 skipped in 9.033 seconds.
Running plone.app.folder.tests.layer.plone.app.folder testing:Partial ordering integration tests:
  Tear down plone.app.folder.tests.layer.plone.app.folder testing:Integration in 0.000 seconds.
  Tear down plone.app.folder.tests.layer.IntegrationFixture in 0.004 seconds.
  Set up plone.app.folder.tests.layer.PartialOrderingIntegrationFixture in 0.025 seconds.
  Set up plone.app.folder.tests.layer.plone.app.folder testing:Partial ordering integration in 0.000 seconds.
  Ran 3 tests with 0 failures, 0 errors and 0 skipped in 0.584 seconds.
Running plone.app.widgets.testing.PloneAppWidgetsLayer:Integration tests:
  Tear down plone.app.folder.tests.layer.plone.app.folder testing:Partial ordering integration in 0.000 seconds.
  Tear down plone.app.folder.tests.layer.PartialOrderingIntegrationFixture in 0.003 seconds.
  Tear down plone.app.testing.bbb.PloneTestCase:Functional in 0.000 seconds.
  Tear down plone.app.testing.bbb.PloneTestCaseFixture in 0.007 seconds.
  Set up plone.app.widgets.testing.PloneAppWidgetsDXLayer in 1.317 seconds.
  Set up plone.app.widgets.testing.PloneAppWidgetsLayer:Integration in 0.000 seconds.
  Ran 10 tests with 0 failures, 0 errors and 0 skipped in 0.185 seconds.
Running plone.testing.zca.ZCMLDirectives tests:
  Tear down plone.app.widgets.testing.PloneAppWidgetsLayer:Integration in 0.000 seconds.
  Tear down plone.app.widgets.testing.PloneAppWidgetsDXLayer in 0.004 seconds.
  Tear down plone.app.testing.layers.PloneFixture in 0.051 seconds.
  Tear down plone.testing.z2.Startup in 0.005 seconds.
  Set up plone.testing.zca.ZCMLDirectives in 0.006 seconds.
  Ran 4 tests with 0 failures, 0 errors and 0 skipped in 0.018 seconds.
Running zope.testrunner.layer.UnitTests tests:
  Tear down plone.testing.zca.ZCMLDirectives in 0.000 seconds.
  Tear down plone.testing.zca.LayerCleanup in 0.001 seconds.
  Set up zope.testrunner.layer.UnitTests in 0.000 seconds.
<string>:1: (WARNING/2) "raw" directive disabled.
<string>:1: (WARNING/2) "include" directive disabled.
  Ran 44 tests with 0 failures, 0 errors and 0 skipped in 0.074 seconds.
Tearing down left over layers:
  Tear down zope.testrunner.layer.UnitTests in 0.000 seconds.
Total: 733 tests, 0 failures, 2 errors and 0 skipped in 3 minutes 10.739 seconds.
#### Finished tests for group Archetypes ####

What? Why is does connection.root() have no Application. Makes not sense to me and a pdb there did not help me shedding light at all.

First I reproduced the error by testing all packages in the test-group Archetypes (where the error occurs):

./bin/test -s Products.Archetypes -s Products.CMFFormController -s Products.MimetypesRegistry -s Products.PortalTransforms -s Products.statusmessages -s Products.validation -s plone.app.folder

Then I only use the test-layers that are actually set up according to the output:

./bin/test --layer Products.Archetypes.tests.attestcase.Archetypes \
           --layer Products.PortalTransforms.testing.PortalTransformsLayer \
           --layer Testing.ZopeTestCase.layer.ZopeLite \
           --layer plone.app.testing.bbb.PloneTestCase \
           -s Products.Archetypes \
           -s Products.CMFFormController \
           -s Products.MimetypesRegistry \
           -s Products.PortalTransforms \
           -s Products.statusmessages \
           -s Products.validation \
           -s plone.app.folder

That works, I see the error. But I will not try to read 733 tests and wait for more than 3 minutes each time I think I may have fixed something!

Thus I use divide and conquer to figure out which combination producedes the failing tests: remove half of the packages layers and see if it still fails. If they pass try the other half. Do the same with the layers.

Remember to keep --layer plone.app.testing.bbb.PloneTestCase and -s Products.CMFFormController to not skip the test that expose the issue.

It turned out that the following combination exposed the issue:

./bin/test \
    --layer Products.Archetypes.tests.attestcase.Archetypes \
    --layer Testing.ZopeTestCase.layer.ZopeLite \
    --layer plone.app.testing.bbb.PloneTestCase \
    -s Products.Archetypes \
    -s Products.CMFFormController

Still way to many tests to have a look. Most of them in Products.Archetypes. So I removed (I actually move the py-files to some temp folder) all python tests and kept the doctests (and their setup). The only reason is that I hate doctests and consequently it is usually a doctest that creates problems. I was right.

Consequently I kept only one doctest that still kept the issue by commenting out the others in test_doctest.py of Products.Archetypes.

Now I needed to find a combination of three tests from these layers that still expose the issue. To to that I added the option -vv to the testrunner to see the names and python path of all tests I still run.

./bin/test --layer Products.Archetypes.tests.attestcase.Archetypes --layer Testing.ZopeTestCase.layer.ZopeLite --layer plone.app.testing.bbb.PloneTestCase -s Products.Archetypes -s Products.CMFFormController -vv
Running tests at level 1
Running Products.Archetypes.tests.attestcase.Archetypes:Functional tests:
  Set up plone.testing.zca.LayerCleanup in 0.000 seconds.
  Set up plone.testing.z2.Startup in 0.157 seconds.
  Set up plone.app.testing.layers.PloneFixture in 10.252 seconds.
  Set up plone.app.testing.bbb.PloneTestCaseFixture in 1.871 seconds.
  Set up Products.Archetypes.tests.attestcase.ATTestCaseFixture in 0.647 seconds.
  Set up Products.Archetypes.tests.attestcase.Archetypes:Functional in 0.000 seconds.
  Running:
    1/1 (100.0%) /Users/pbauer/workspace/coredev/src/Products.Archetypes/Products/Archetypes/tests/traversal_4981.txt

  Ran 1 tests with 0 failures, 0 errors, 0 skipped in 0.269 seconds.
Running Testing.ZopeTestCase.layer.ZopeLite tests:
  Tear down Products.Archetypes.tests.attestcase.Archetypes:Functional in 0.000 seconds.
  Tear down Products.Archetypes.tests.attestcase.ATTestCaseFixture in 0.010 seconds.
  Tear down plone.app.testing.bbb.PloneTestCaseFixture in 0.009 seconds.
  Tear down plone.app.testing.layers.PloneFixture in 0.065 seconds.
  Tear down plone.testing.z2.Startup in 0.004 seconds.
  Tear down plone.testing.zca.LayerCleanup in 0.001 seconds.
  Set up Testing.ZopeTestCase.layer.ZopeLite in 0.009 seconds.
  Running:
    1/5 (20.0%) test_parseXML_empty (Products.CMFFormController.tests.test_exportimport.CMFFormControllerImportConfiguratorTests)
    2/5 (40.0%) test_parseXML_with_info (Products.CMFFormController.tests.test_exportimport.CMFFormControllerImportConfiguratorTests)
    3/5 (60.0%) test_action_not_unicode (Products.CMFFormController.tests.test_exportimport.Test_importCMFFormController)
    4/5 (80.0%) test_normal (Products.CMFFormController.tests.test_exportimport.Test_importCMFFormController)
    5/5 (100.0%) test_partial (Products.CMFFormController.tests.test_exportimport.Test_importCMFFormController)

  Ran 5 tests with 0 failures, 0 errors, 0 skipped in 0.023 seconds.
Running plone.app.testing.bbb.PloneTestCase:Functional tests:
  Tear down Testing.ZopeTestCase.layer.ZopeLite in 0.000 seconds.
  Set up plone.testing.zca.LayerCleanup in 0.000 seconds.
  Set up plone.testing.z2.Startup in 0.092 seconds.
  Set up plone.app.testing.layers.PloneFixture in 7.227 seconds.
  Set up plone.app.testing.bbb.PloneTestCaseFixture in 2.087 seconds.
  Set up plone.app.testing.bbb.PloneTestCase:Functional in 0.000 seconds.
  Running:
    1/4 (25.0%) testCopy (Products.CMFFormController.tests.testCopyRename.TestCopyRename)
    2/4 (50.0%) testRename (Products.CMFFormController.tests.testCopyRename.TestCopyRename)
    3/4 (75.0%) test_attacker_redirect (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)


Error in test test_attacker_redirect (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/Users/pbauer/workspace/coredev/src/Products.CMFFormController/Products/CMFFormController/tests/testRedirectTo.py", line 97, in test_attacker_redirect
    handle_errors=False,
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/functional.py", line 43, in wrapped_func
    return func(*args, **kw)
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/functional.py", line 127, in publish
    wsgi_result = publish(env, start_response)
  File "/Users/pbauer/workspace/coredev/src/Zope/src/ZPublisher/WSGIPublisher.py", line 254, in publish_module
    with load_app(module_info) as new_mod_info:
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/sandbox.py", line 73, in load_app
    with ZPublisher.WSGIPublisher.__old_load_app__(module_info) as ret:
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/ZPublisher/WSGIPublisher.py", line 220, in load_app
    app = app_wrapper()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/App/ZApplication.py", line 78, in __call__
    return connection.root()[self._name]
  File "/Users/pbauer/workspace/coredev/bin/../lib/python2.7/UserDict.py", line 40, in __getitem__
    raise KeyError(key)
KeyError: 'Application'

    4/4 (100.0%) test_regression (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)


Error in test test_regression (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/Users/pbauer/workspace/coredev/src/Products.CMFFormController/Products/CMFFormController/tests/testRedirectTo.py", line 71, in test_regression
    handle_errors=False,
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/functional.py", line 43, in wrapped_func
    return func(*args, **kw)
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/functional.py", line 127, in publish
    wsgi_result = publish(env, start_response)
  File "/Users/pbauer/workspace/coredev/src/Zope/src/ZPublisher/WSGIPublisher.py", line 254, in publish_module
    with load_app(module_info) as new_mod_info:
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/sandbox.py", line 73, in load_app
    with ZPublisher.WSGIPublisher.__old_load_app__(module_info) as ret:
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/ZPublisher/WSGIPublisher.py", line 220, in load_app
    app = app_wrapper()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/App/ZApplication.py", line 78, in __call__
    return connection.root()[self._name]
  File "/Users/pbauer/workspace/coredev/bin/../lib/python2.7/UserDict.py", line 40, in __getitem__
    raise KeyError(key)
KeyError: 'Application'


  Ran 4 tests with 0 failures, 2 errors, 0 skipped in 0.403 seconds.
Tearing down left over layers:
  Tear down plone.app.testing.bbb.PloneTestCase:Functional in 0.000 seconds.
  Tear down plone.app.testing.bbb.PloneTestCaseFixture in 0.010 seconds.
  Tear down plone.app.testing.layers.PloneFixture in 0.068 seconds.
  Tear down plone.testing.z2.Startup in 0.007 seconds.
  Tear down plone.testing.zca.LayerCleanup in 0.001 seconds.

Tests with errors:
   test_attacker_redirect (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
   test_regression (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Total: 10 tests, 0 failures, 2 errors, 0 skipped in 24.082 seconds.

24 seconds? I can work with that.

Still I remove tests from each layer until I only have three tests remaining and revert my changes to . Products.Archetypes

The result is the following:

./bin/test \
    --layer Products.Archetypes.tests.attestcase.Archetypes \
    --layer Testing.ZopeTestCase.layer.ZopeLite \
    --layer plone.app.testing.bbb.PloneTestCase \
    -s Products.Archetypes \
    -s Products.CMFFormController \
    -t test_parseXML_empty \
    -t traversal_4981 \
    -t test_attacker_redirect \
    -vv

Since more than one test still exposed the issue I kept only very simple ones because I guessed that the issue is actually in the setup or teardown.

So next I change the test test_parseXML_empty to a simple return. The error is still there. Trying the same with traversal_4981 makes it go away.

At this point I can skip constraining the layers since I only run three tests from two packages.

Time to actually read what the remaining tests are doing. I strip down all tests and their setup to the base minimum that still breaks the tests and cannot find anything. I turn CMFFormControllerImportConfiguratorTests into a ZopeTestCase and a PloneTestCase and realize that the error disappears when it is a PloneTestCase. Bad. Migrating the whole test to PloneTestCase or plone.app.testing would be a lot of work since CMFFormControllerImportConfiguratorTests inherits from Products.GenericSetup.tests.common.BaseRegistryTests and does a lot of additional magic.

So the test-layers for the two tests that do not fail or error by themselves but trigger the issue in the failing tests (traversal_4981 and test_parseXML_empty) seem to be out of the scope of what I can do so I taker a closer look at the failing tests themselves. I quickly that I hate them but that what they is actually quite simple. Why do I hate them? Becase they use the method self.publish of ZopeTestCase.Functional. That method (and its evil doctest-cousin Testing.ZopeTestCase.zopedoctest.functional.http) are way too clever helper methods that make things harder, not easier. I prefer to use restrictedTraverse or the testbrowser any time since both are much closer to what actually happens in the application.

This is the moment when I decide to migrate them to proper plone.app.testing tests. It takes me about 1h to create plone/Products.CMFFormController#14 which resolves the issue. The rest of the day was spent on a fruitless attempt to find the issue that must still be lurking somewhere between the three tests and their layers.

I hope that monster will never rear its ugly head again until CMFFormController is finally removed from the coredev. The PLIP #2092 by @esteele an me will remove the last remaining ControllerPageTemplates but there are some left in Archetypes.

I fear it will be quite some time until all ZopeTestCase and PloneTestCase tests are migrated to plone.app.testing. The remaining happy thought is that many will not need to be migrated since they are part of Archetypes and will go awaaaaay with it.

Member

pbauer commented Nov 9, 2017

So here is small story about the failing tests in Products.CMFFormController. Here is the spoiler: I did not find the issue so I migrated them to proper plone.app.testing and worked around it like this. I probably should have done that first. But I still think the approach I took might be of interest for those who do not regularly have to deal tests due to test-isolation issues.

The two breaking tests test_attacker_redirect and test_regression were passing when the ran in isolation or when all test of Products.CMFFormController ran. So how can I find the issue assuming the traceback is not really helpful? Products.CMFFormController is dead but sadly still used by some of our older ControllerPageTemplates - they need to die!

Here is the relevant part of the log:

#### Running tests for group Archetypes ####
Running Products.Archetypes.tests.attestcase.Archetypes:Functional tests:
  Set up plone.testing.zca.LayerCleanup in 0.000 seconds.
  Set up plone.testing.z2.Startup in 0.152 seconds.
  Set up plone.app.testing.layers.PloneFixture in 14.741 seconds.
  Set up plone.app.testing.bbb.PloneTestCaseFixture in 3.482 seconds.
  Set up Products.Archetypes.tests.attestcase.ATTestCaseFixture in 0.593 seconds.
  Set up Products.Archetypes.tests.attestcase.Archetypes:Functional in 0.000 seconds.
  Ran 476 tests with 0 failures, 0 errors and 0 skipped in 1 minutes 36.839 seconds.
Running Products.PortalTransforms.testing.PortalTransformsLayer:Integration tests:
  Tear down Products.Archetypes.tests.attestcase.Archetypes:Functional in 0.000 seconds.
  Tear down Products.Archetypes.tests.attestcase.ATTestCaseFixture in 0.008 seconds.
  Tear down plone.app.testing.bbb.PloneTestCaseFixture in 0.008 seconds.
  Set up plone.app.event.testing.PAEventLayer in 0.902 seconds.
  Set up plone.app.contenttypes.testing.PloneAppContenttypes in 0.914 seconds.
  Set up Products.PortalTransforms.testing.ProductsPortalTransformsLayer in 0.032 seconds.
  Set up Products.PortalTransforms.testing.PortalTransformsLayer:Integration in 0.000 seconds.
  Ran 94 tests with 0 failures, 0 errors and 0 skipped in 39.797 seconds.
Running Testing.ZopeTestCase.layer.ZopeLite tests:
  Tear down Products.PortalTransforms.testing.PortalTransformsLayer:Integration in 0.000 seconds.
  Tear down Products.PortalTransforms.testing.ProductsPortalTransformsLayer in 0.004 seconds.
  Tear down plone.app.contenttypes.testing.PloneAppContenttypes in 0.469 seconds.
  Tear down plone.app.event.testing.PAEventLayer in 0.022 seconds.
  Tear down plone.app.testing.layers.PloneFixture in 0.077 seconds.
  Tear down plone.testing.z2.Startup in 0.019 seconds.
  Tear down plone.testing.zca.LayerCleanup in 0.001 seconds.
  Set up Testing.ZopeTestCase.layer.ZopeLite in 0.018 seconds.
  Ran 7 tests with 0 failures, 0 errors and 0 skipped in 0.032 seconds.
Running plone.app.testing.bbb.PloneTestCase:Functional tests:
  Tear down Testing.ZopeTestCase.layer.ZopeLite in 0.000 seconds.
  Set up plone.testing.zca.LayerCleanup in 0.000 seconds.
  Set up plone.testing.z2.Startup in 0.101 seconds.
  Set up plone.app.testing.layers.PloneFixture in 9.722 seconds.
  Set up plone.app.testing.bbb.PloneTestCaseFixture in 2.628 seconds.
  Set up plone.app.testing.bbb.PloneTestCase:Functional in 0.000 seconds.


Error in test test_attacker_redirect (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Traceback (most recent call last):
  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Products.CMFFormController/Products/CMFFormController/tests/testRedirectTo.py", line 97, in test_attacker_redirect
    handle_errors=False,
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/functional.py", line 43, in wrapped_func
    return func(*args, **kw)
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/functional.py", line 127, in publish
    wsgi_result = publish(env, start_response)
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/ZPublisher/WSGIPublisher.py", line 254, in publish_module
    with load_app(module_info) as new_mod_info:
  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/sandbox.py", line 73, in load_app
    with ZPublisher.WSGIPublisher.__old_load_app__(module_info) as ret:
  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/ZPublisher/WSGIPublisher.py", line 220, in load_app
    app = app_wrapper()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/App/ZApplication.py", line 78, in __call__
    return connection.root()[self._name]
  File "/home/jenkins/shiningpanda/jobs/2fa08faf/virtualenvs/d41d8cd9/lib/python2.7/UserDict.py", line 40, in __getitem__
    raise KeyError(key)
KeyError: 'Application'



Error in test test_regression (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Traceback (most recent call last):
  File "/usr/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Products.CMFFormController/Products/CMFFormController/tests/testRedirectTo.py", line 71, in test_regression
    handle_errors=False,
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/functional.py", line 43, in wrapped_func
    return func(*args, **kw)
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/functional.py", line 127, in publish
    wsgi_result = publish(env, start_response)
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/ZPublisher/WSGIPublisher.py", line 254, in publish_module
    with load_app(module_info) as new_mod_info:
  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/Testing/ZopeTestCase/sandbox.py", line 73, in load_app
    with ZPublisher.WSGIPublisher.__old_load_app__(module_info) as ret:
  File "/usr/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/ZPublisher/WSGIPublisher.py", line 220, in load_app
    app = app_wrapper()
  File "/home/jenkins/workspace/plone-5.2-python-2.7-at/src/Zope/src/App/ZApplication.py", line 78, in __call__
    return connection.root()[self._name]
  File "/home/jenkins/shiningpanda/jobs/2fa08faf/virtualenvs/d41d8cd9/lib/python2.7/UserDict.py", line 40, in __getitem__
    raise KeyError(key)
KeyError: 'Application'

  Ran 68 tests with 0 failures, 2 errors and 0 skipped in 1.626 seconds.
Running plone.app.folder.tests.layer.plone.app.folder testing:Integration tests:
  Set up plone.app.folder.tests.layer.IntegrationFixture in 0.027 seconds.
  Set up plone.app.folder.tests.layer.plone.app.folder testing:Integration in 0.000 seconds.
  Ran 27 tests with 0 failures, 0 errors and 0 skipped in 9.033 seconds.
Running plone.app.folder.tests.layer.plone.app.folder testing:Partial ordering integration tests:
  Tear down plone.app.folder.tests.layer.plone.app.folder testing:Integration in 0.000 seconds.
  Tear down plone.app.folder.tests.layer.IntegrationFixture in 0.004 seconds.
  Set up plone.app.folder.tests.layer.PartialOrderingIntegrationFixture in 0.025 seconds.
  Set up plone.app.folder.tests.layer.plone.app.folder testing:Partial ordering integration in 0.000 seconds.
  Ran 3 tests with 0 failures, 0 errors and 0 skipped in 0.584 seconds.
Running plone.app.widgets.testing.PloneAppWidgetsLayer:Integration tests:
  Tear down plone.app.folder.tests.layer.plone.app.folder testing:Partial ordering integration in 0.000 seconds.
  Tear down plone.app.folder.tests.layer.PartialOrderingIntegrationFixture in 0.003 seconds.
  Tear down plone.app.testing.bbb.PloneTestCase:Functional in 0.000 seconds.
  Tear down plone.app.testing.bbb.PloneTestCaseFixture in 0.007 seconds.
  Set up plone.app.widgets.testing.PloneAppWidgetsDXLayer in 1.317 seconds.
  Set up plone.app.widgets.testing.PloneAppWidgetsLayer:Integration in 0.000 seconds.
  Ran 10 tests with 0 failures, 0 errors and 0 skipped in 0.185 seconds.
Running plone.testing.zca.ZCMLDirectives tests:
  Tear down plone.app.widgets.testing.PloneAppWidgetsLayer:Integration in 0.000 seconds.
  Tear down plone.app.widgets.testing.PloneAppWidgetsDXLayer in 0.004 seconds.
  Tear down plone.app.testing.layers.PloneFixture in 0.051 seconds.
  Tear down plone.testing.z2.Startup in 0.005 seconds.
  Set up plone.testing.zca.ZCMLDirectives in 0.006 seconds.
  Ran 4 tests with 0 failures, 0 errors and 0 skipped in 0.018 seconds.
Running zope.testrunner.layer.UnitTests tests:
  Tear down plone.testing.zca.ZCMLDirectives in 0.000 seconds.
  Tear down plone.testing.zca.LayerCleanup in 0.001 seconds.
  Set up zope.testrunner.layer.UnitTests in 0.000 seconds.
<string>:1: (WARNING/2) "raw" directive disabled.
<string>:1: (WARNING/2) "include" directive disabled.
  Ran 44 tests with 0 failures, 0 errors and 0 skipped in 0.074 seconds.
Tearing down left over layers:
  Tear down zope.testrunner.layer.UnitTests in 0.000 seconds.
Total: 733 tests, 0 failures, 2 errors and 0 skipped in 3 minutes 10.739 seconds.
#### Finished tests for group Archetypes ####

What? Why is does connection.root() have no Application. Makes not sense to me and a pdb there did not help me shedding light at all.

First I reproduced the error by testing all packages in the test-group Archetypes (where the error occurs):

./bin/test -s Products.Archetypes -s Products.CMFFormController -s Products.MimetypesRegistry -s Products.PortalTransforms -s Products.statusmessages -s Products.validation -s plone.app.folder

Then I only use the test-layers that are actually set up according to the output:

./bin/test --layer Products.Archetypes.tests.attestcase.Archetypes \
           --layer Products.PortalTransforms.testing.PortalTransformsLayer \
           --layer Testing.ZopeTestCase.layer.ZopeLite \
           --layer plone.app.testing.bbb.PloneTestCase \
           -s Products.Archetypes \
           -s Products.CMFFormController \
           -s Products.MimetypesRegistry \
           -s Products.PortalTransforms \
           -s Products.statusmessages \
           -s Products.validation \
           -s plone.app.folder

That works, I see the error. But I will not try to read 733 tests and wait for more than 3 minutes each time I think I may have fixed something!

Thus I use divide and conquer to figure out which combination producedes the failing tests: remove half of the packages layers and see if it still fails. If they pass try the other half. Do the same with the layers.

Remember to keep --layer plone.app.testing.bbb.PloneTestCase and -s Products.CMFFormController to not skip the test that expose the issue.

It turned out that the following combination exposed the issue:

./bin/test \
    --layer Products.Archetypes.tests.attestcase.Archetypes \
    --layer Testing.ZopeTestCase.layer.ZopeLite \
    --layer plone.app.testing.bbb.PloneTestCase \
    -s Products.Archetypes \
    -s Products.CMFFormController

Still way to many tests to have a look. Most of them in Products.Archetypes. So I removed (I actually move the py-files to some temp folder) all python tests and kept the doctests (and their setup). The only reason is that I hate doctests and consequently it is usually a doctest that creates problems. I was right.

Consequently I kept only one doctest that still kept the issue by commenting out the others in test_doctest.py of Products.Archetypes.

Now I needed to find a combination of three tests from these layers that still expose the issue. To to that I added the option -vv to the testrunner to see the names and python path of all tests I still run.

./bin/test --layer Products.Archetypes.tests.attestcase.Archetypes --layer Testing.ZopeTestCase.layer.ZopeLite --layer plone.app.testing.bbb.PloneTestCase -s Products.Archetypes -s Products.CMFFormController -vv
Running tests at level 1
Running Products.Archetypes.tests.attestcase.Archetypes:Functional tests:
  Set up plone.testing.zca.LayerCleanup in 0.000 seconds.
  Set up plone.testing.z2.Startup in 0.157 seconds.
  Set up plone.app.testing.layers.PloneFixture in 10.252 seconds.
  Set up plone.app.testing.bbb.PloneTestCaseFixture in 1.871 seconds.
  Set up Products.Archetypes.tests.attestcase.ATTestCaseFixture in 0.647 seconds.
  Set up Products.Archetypes.tests.attestcase.Archetypes:Functional in 0.000 seconds.
  Running:
    1/1 (100.0%) /Users/pbauer/workspace/coredev/src/Products.Archetypes/Products/Archetypes/tests/traversal_4981.txt

  Ran 1 tests with 0 failures, 0 errors, 0 skipped in 0.269 seconds.
Running Testing.ZopeTestCase.layer.ZopeLite tests:
  Tear down Products.Archetypes.tests.attestcase.Archetypes:Functional in 0.000 seconds.
  Tear down Products.Archetypes.tests.attestcase.ATTestCaseFixture in 0.010 seconds.
  Tear down plone.app.testing.bbb.PloneTestCaseFixture in 0.009 seconds.
  Tear down plone.app.testing.layers.PloneFixture in 0.065 seconds.
  Tear down plone.testing.z2.Startup in 0.004 seconds.
  Tear down plone.testing.zca.LayerCleanup in 0.001 seconds.
  Set up Testing.ZopeTestCase.layer.ZopeLite in 0.009 seconds.
  Running:
    1/5 (20.0%) test_parseXML_empty (Products.CMFFormController.tests.test_exportimport.CMFFormControllerImportConfiguratorTests)
    2/5 (40.0%) test_parseXML_with_info (Products.CMFFormController.tests.test_exportimport.CMFFormControllerImportConfiguratorTests)
    3/5 (60.0%) test_action_not_unicode (Products.CMFFormController.tests.test_exportimport.Test_importCMFFormController)
    4/5 (80.0%) test_normal (Products.CMFFormController.tests.test_exportimport.Test_importCMFFormController)
    5/5 (100.0%) test_partial (Products.CMFFormController.tests.test_exportimport.Test_importCMFFormController)

  Ran 5 tests with 0 failures, 0 errors, 0 skipped in 0.023 seconds.
Running plone.app.testing.bbb.PloneTestCase:Functional tests:
  Tear down Testing.ZopeTestCase.layer.ZopeLite in 0.000 seconds.
  Set up plone.testing.zca.LayerCleanup in 0.000 seconds.
  Set up plone.testing.z2.Startup in 0.092 seconds.
  Set up plone.app.testing.layers.PloneFixture in 7.227 seconds.
  Set up plone.app.testing.bbb.PloneTestCaseFixture in 2.087 seconds.
  Set up plone.app.testing.bbb.PloneTestCase:Functional in 0.000 seconds.
  Running:
    1/4 (25.0%) testCopy (Products.CMFFormController.tests.testCopyRename.TestCopyRename)
    2/4 (50.0%) testRename (Products.CMFFormController.tests.testCopyRename.TestCopyRename)
    3/4 (75.0%) test_attacker_redirect (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)


Error in test test_attacker_redirect (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/Users/pbauer/workspace/coredev/src/Products.CMFFormController/Products/CMFFormController/tests/testRedirectTo.py", line 97, in test_attacker_redirect
    handle_errors=False,
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/functional.py", line 43, in wrapped_func
    return func(*args, **kw)
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/functional.py", line 127, in publish
    wsgi_result = publish(env, start_response)
  File "/Users/pbauer/workspace/coredev/src/Zope/src/ZPublisher/WSGIPublisher.py", line 254, in publish_module
    with load_app(module_info) as new_mod_info:
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/sandbox.py", line 73, in load_app
    with ZPublisher.WSGIPublisher.__old_load_app__(module_info) as ret:
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/ZPublisher/WSGIPublisher.py", line 220, in load_app
    app = app_wrapper()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/App/ZApplication.py", line 78, in __call__
    return connection.root()[self._name]
  File "/Users/pbauer/workspace/coredev/bin/../lib/python2.7/UserDict.py", line 40, in __getitem__
    raise KeyError(key)
KeyError: 'Application'

    4/4 (100.0%) test_regression (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)


Error in test test_regression (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Traceback (most recent call last):
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/unittest/case.py", line 329, in run
    testMethod()
  File "/Users/pbauer/workspace/coredev/src/Products.CMFFormController/Products/CMFFormController/tests/testRedirectTo.py", line 71, in test_regression
    handle_errors=False,
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/functional.py", line 43, in wrapped_func
    return func(*args, **kw)
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/functional.py", line 127, in publish
    wsgi_result = publish(env, start_response)
  File "/Users/pbauer/workspace/coredev/src/Zope/src/ZPublisher/WSGIPublisher.py", line 254, in publish_module
    with load_app(module_info) as new_mod_info:
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/Testing/ZopeTestCase/sandbox.py", line 73, in load_app
    with ZPublisher.WSGIPublisher.__old_load_app__(module_info) as ret:
  File "/usr/local/Cellar/python/2.7.13_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/contextlib.py", line 17, in __enter__
    return self.gen.next()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/ZPublisher/WSGIPublisher.py", line 220, in load_app
    app = app_wrapper()
  File "/Users/pbauer/workspace/coredev/src/Zope/src/App/ZApplication.py", line 78, in __call__
    return connection.root()[self._name]
  File "/Users/pbauer/workspace/coredev/bin/../lib/python2.7/UserDict.py", line 40, in __getitem__
    raise KeyError(key)
KeyError: 'Application'


  Ran 4 tests with 0 failures, 2 errors, 0 skipped in 0.403 seconds.
Tearing down left over layers:
  Tear down plone.app.testing.bbb.PloneTestCase:Functional in 0.000 seconds.
  Tear down plone.app.testing.bbb.PloneTestCaseFixture in 0.010 seconds.
  Tear down plone.app.testing.layers.PloneFixture in 0.068 seconds.
  Tear down plone.testing.z2.Startup in 0.007 seconds.
  Tear down plone.testing.zca.LayerCleanup in 0.001 seconds.

Tests with errors:
   test_attacker_redirect (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
   test_regression (Products.CMFFormController.tests.testRedirectTo.TestRedirectToFunctional)
Total: 10 tests, 0 failures, 2 errors, 0 skipped in 24.082 seconds.

24 seconds? I can work with that.

Still I remove tests from each layer until I only have three tests remaining and revert my changes to . Products.Archetypes

The result is the following:

./bin/test \
    --layer Products.Archetypes.tests.attestcase.Archetypes \
    --layer Testing.ZopeTestCase.layer.ZopeLite \
    --layer plone.app.testing.bbb.PloneTestCase \
    -s Products.Archetypes \
    -s Products.CMFFormController \
    -t test_parseXML_empty \
    -t traversal_4981 \
    -t test_attacker_redirect \
    -vv

Since more than one test still exposed the issue I kept only very simple ones because I guessed that the issue is actually in the setup or teardown.

So next I change the test test_parseXML_empty to a simple return. The error is still there. Trying the same with traversal_4981 makes it go away.

At this point I can skip constraining the layers since I only run three tests from two packages.

Time to actually read what the remaining tests are doing. I strip down all tests and their setup to the base minimum that still breaks the tests and cannot find anything. I turn CMFFormControllerImportConfiguratorTests into a ZopeTestCase and a PloneTestCase and realize that the error disappears when it is a PloneTestCase. Bad. Migrating the whole test to PloneTestCase or plone.app.testing would be a lot of work since CMFFormControllerImportConfiguratorTests inherits from Products.GenericSetup.tests.common.BaseRegistryTests and does a lot of additional magic.

So the test-layers for the two tests that do not fail or error by themselves but trigger the issue in the failing tests (traversal_4981 and test_parseXML_empty) seem to be out of the scope of what I can do so I taker a closer look at the failing tests themselves. I quickly that I hate them but that what they is actually quite simple. Why do I hate them? Becase they use the method self.publish of ZopeTestCase.Functional. That method (and its evil doctest-cousin Testing.ZopeTestCase.zopedoctest.functional.http) are way too clever helper methods that make things harder, not easier. I prefer to use restrictedTraverse or the testbrowser any time since both are much closer to what actually happens in the application.

This is the moment when I decide to migrate them to proper plone.app.testing tests. It takes me about 1h to create plone/Products.CMFFormController#14 which resolves the issue. The rest of the day was spent on a fruitless attempt to find the issue that must still be lurking somewhere between the three tests and their layers.

I hope that monster will never rear its ugly head again until CMFFormController is finally removed from the coredev. The PLIP #2092 by @esteele an me will remove the last remaining ControllerPageTemplates but there are some left in Archetypes.

I fear it will be quite some time until all ZopeTestCase and PloneTestCase tests are migrated to plone.app.testing. The remaining happy thought is that many will not need to be migrated since they are part of Archetypes and will go awaaaaay with it.

mister-roboto pushed a commit to plone/buildout.coredev that referenced this issue Nov 9, 2017

[fc] Repository: Products.CMFFormController
Branch: refs/heads/master
Date: 2017-11-09T17:18:47+01:00
Author: Philip Bauer (pbauer) <bauer@starzel.de>
Commit: plone/Products.CMFFormController@b51fb48

Migrate breaking tests to plone.app.testing. See plone/Products.CMFPlone#2195.

Files changed:
M CHANGES.rst
M Products/CMFFormController/tests/testRedirectTo.py
M setup.py
Repository: Products.CMFFormController

Branch: refs/heads/master
Date: 2017-11-09T21:37:49+01:00
Author: Philip Bauer (pbauer) <bauer@starzel.de>
Commit: plone/Products.CMFFormController@c1109e5

Merge pull request #14 from plone/migrate_breakting_tests

Migrate breaking tests to plone.app.testing

Files changed:
M CHANGES.rst
M Products/CMFFormController/tests/testRedirectTo.py
M setup.py
@gforcada

This comment has been minimized.

Show comment
Hide comment
@gforcada

gforcada Nov 9, 2017

Contributor

@pbauer you should turn that into a blog post!

According to http://jenkins.plone.org/py3/deps-reverse/Products.CMFFormController.svg only archetypes, ATCT and CMFPlone use CMFFormController, and on CMFPlone is almost gone, is still that much work to do?

Lastly, regarding migration to p.a.testing, sadly is the way to go, we need to have all tests over it to avoid isolation tests.

Contributor

gforcada commented Nov 9, 2017

@pbauer you should turn that into a blog post!

According to http://jenkins.plone.org/py3/deps-reverse/Products.CMFFormController.svg only archetypes, ATCT and CMFPlone use CMFFormController, and on CMFPlone is almost gone, is still that much work to do?

Lastly, regarding migration to p.a.testing, sadly is the way to go, we need to have all tests over it to avoid isolation tests.

@pbauer

This comment has been minimized.

Show comment
Hide comment
Member

pbauer commented Nov 10, 2017

@pbauer

This comment has been minimized.

Show comment
Hide comment
@pbauer

pbauer Nov 16, 2017

Member

The final issue was fixed with plone/plone.app.folder#14 by @davisagli. Many thanks!
With this the build of 5.2 is finally green. As it happens today is also the day when the last blocker was removed from https://github.com/plone/Products.CMFPlone/projects/6, so we could release 5.1 and 5.2 on the same day 😉

Member

pbauer commented Nov 16, 2017

The final issue was fixed with plone/plone.app.folder#14 by @davisagli. Many thanks!
With this the build of 5.2 is finally green. As it happens today is also the day when the last blocker was removed from https://github.com/plone/Products.CMFPlone/projects/6, so we could release 5.1 and 5.2 on the same day 😉

@pbauer

This comment has been minimized.

Show comment
Hide comment
@pbauer

pbauer Nov 16, 2017

Member

With this closed we can start merging the open pull-requests that fix imports with Python 3. Tada!

Member

pbauer commented Nov 16, 2017

With this closed we can start merging the open pull-requests that fix imports with Python 3. Tada!

@pbauer pbauer closed this Nov 16, 2017

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment