Closed rfk closed 12 years ago
I get a clean test run with nose, but python setup.py test
gives me 57 passes and a stacktrace inside of multiprocessing.
Ran 57 tests in 0.268s
OK Error in atexit._run_exitfuncs: Traceback (most recent call last): File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/atexit.py", line 24, in _run_exitfuncs func(_targs, _kargs) File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/multiprocessing/util.py", line 258, in _exit_function info('process shutting down') TypeError: 'NoneType' object is not callable Error in sys.exitfunc: Traceback (most recent call last): File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/atexit.py", line 24, in _run_exitfuncs func(_targs, _kargs) File "/System/Library/Frameworks/Python.framework/Versions/2.6/lib/python2.6/multiprocessing/util.py", line 258, in _exit_function info('process shutting down') TypeError: 'NoneType' object is not callable
@crankycoder any chance this is pulling in some unpublished metlog stuff? I just tried from a fresh mozservices checkout and a fresh virtualenv, and I still get 4 failing tests with python setup.py test
.
Here's the output I get using a fresh virtualenv:
(moz)rfk@rambutan:mozservices$ python setup.py test
/usr/lib/python2.7/distutils/dist.py:267: UserWarning: Unknown distribution option: 'paster_plugins'
warnings.warn(msg)
running test
running egg_info
writing requirements to mozsvc.egg-info/requires.txt
writing mozsvc.egg-info/PKG-INFO
writing top-level names to mozsvc.egg-info/top_level.txt
writing dependency_links to mozsvc.egg-info/dependency_links.txt
reading manifest file 'mozsvc.egg-info/SOURCES.txt'
reading manifest template 'MANIFEST.in'
writing manifest file 'mozsvc.egg-info/SOURCES.txt'
running build_ext
test_that_backend_errors_are_captured (mozsvc.tests.test_tweens.TestTweens) ... No handlers could be found for logger "mozsvc"
ok
test_that_backend_errors_can_set_retry_after (mozsvc.tests.test_tweens.TestTweens) ... ok
test_that_retry_after_doesnt_get_set_to_zero (mozsvc.tests.test_tweens.TestTweens) ... ok
test_maybe_resolve_name (mozsvc.tests.test_util.TestUtil) ... ok
test_resolve_name (mozsvc.tests.test_util.TestUtil) ... ok
test_round_time (mozsvc.tests.test_util.TestUtil) ... ok
test_get_url (mozsvc.tests.test_http_helpers.TestHttp) ... ok
test_proxy (mozsvc.tests.test_http_helpers.TestHttp) ... ok
test_auth_backend_is_loaded (mozsvc.tests.test_user.UserTestCase) ... ok
test_authenticate (mozsvc.tests.test_user.UserTestCase) ... ok
test_authenticate_with_bad_password (mozsvc.tests.test_user.UserTestCase) ... ok
test_authenticate_with_no_backend (mozsvc.tests.test_user.UserTestCase) ... ok
test_authenticate_with_no_username (mozsvc.tests.test_user.UserTestCase) ... ok
test_authenticate_with_normal_request_object (mozsvc.tests.test_user.UserTestCase) ... ok
test_authenticate_with_repozewho_style_credentials (mozsvc.tests.test_user.UserTestCase) ... ok
test_authenticate_with_unicode_password (mozsvc.tests.test_user.UserTestCase) ... ok
test_authenticate_with_unknown_username (mozsvc.tests.test_user.UserTestCase) ... ok
test_includeme_with_bad_backend (mozsvc.tests.test_user.UserTestCase) ... ok
test_registry_is_stored_in_environment (mozsvc.tests.test_user.UserTestCase) ... ok
test_req_user_bad_password (mozsvc.tests.test_user.UserTestCase) ... ok
test_req_user_exposes_repoze_who_identity (mozsvc.tests.test_user.UserTestCase) ... ok
test_req_user_no_password (mozsvc.tests.test_user.UserTestCase) ... ok
test_req_user_no_username (mozsvc.tests.test_user.UserTestCase) ... ok
test_req_user_success (mozsvc.tests.test_user.UserTestCase) ... ok
test_graceful_handling_of_bad_auth_policy (mozsvc.tests.test_user.UserWhoAuthTestCase) ... ok
test_graceful_handling_of_other_request_objects (mozsvc.tests.test_user.UserWhoAuthTestCase) ... ok
test_that_basic_auth_is_not_used_when_theres_no_backend (mozsvc.tests.test_user.UserWhoAuthTestCase) ... ok
test_that_basic_auth_is_used_by_default (mozsvc.tests.test_user.UserWhoAuthTestCase) ... ok
test_that_explicit_settings_are_not_overridden (mozsvc.tests.test_user.UserWhoAuthTestCase) ... ok
test_that_macauth_can_use_per_node_hostname_secrets (mozsvc.tests.test_user.UserWhoAuthTestCase) ... ok
test_that_macauth_cant_use_both_secret_and_secrets_file (mozsvc.tests.test_user.UserWhoAuthTestCase) ... ok
test_that_macauth_is_used_by_default (mozsvc.tests.test_user.UserWhoAuthTestCase) ... ok
test_loading_from_config (mozsvc.tests.test_plugin.TestPluginLoading) ... ok
test_loading_from_settings (mozsvc.tests.test_plugin.TestPluginLoading) ... ok
test_loading_several_plugins (mozsvc.tests.test_plugin.TestPluginLoading) ... ok
test_loading_with_conflict_detection (mozsvc.tests.test_plugin.TestPluginLoading) ... ok
test_loading_with_conflict_resolution (mozsvc.tests.test_plugin.TestPluginLoading) ... ok
test_get_configurator (mozsvc.tests.test_config.ConfigTestCase) ... ok
test_get_configurator_nofile (mozsvc.tests.test_config.ConfigTestCase) ... ok
test_load_into_settings (mozsvc.tests.test_config.ConfigTestCase) ... ok
test_nofile (mozsvc.tests.test_config.ConfigTestCase) ... ok
test_reader (mozsvc.tests.test_config.ConfigTestCase) ... ok
test_settings_dict_copy (mozsvc.tests.test_config.ConfigTestCase) ... ok
test_settings_dict_getsection (mozsvc.tests.test_config.ConfigTestCase) ... ok
test_settings_dict_setdefaults (mozsvc.tests.test_config.ConfigTestCase) ... ok
test_decorated_view_fn (mozsvc.tests.test_service_definition.TestServiceDefinition) ... ok
test_stacked_decorated_view (mozsvc.tests.test_service_definition.TestServiceDefinition) ... ERROR
test_multiple_files (mozsvc.tests.test_secrets.TestSecrets) ... ok
test_read_write (mozsvc.tests.test_secrets.TestSecrets) ... ok
test_only_some_decorators (mozsvc.tests.test_partial_disable_metrics.TestDisabledTimers) ... ok
test_apache_logger (mozsvc.tests.test_metrics.TestCannedDecorators) ... ok
test_decorator_ordering (mozsvc.tests.test_metrics.TestCannedDecorators) ... FAIL
test_loading_from_config (mozsvc.tests.test_metrics.TestConfigurationLoading) ... FAIL
test_loading_from_config (mozsvc.tests.test_metrics.TestMetrics) ... ok
test_decorate_at_constructor (mozsvc.tests.test_metrics.TestMetricsService) ... FAIL
test_decorator_override (mozsvc.tests.test_metrics.TestMetricsService) ... ok
test_metrics_service (mozsvc.tests.test_metrics.TestMetricsService) ... FAIL
======================================================================
ERROR: test_stacked_decorated_view (mozsvc.tests.test_service_definition.TestServiceDefinition)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/rfk/TEMP/mozservices/mozsvc/tests/test_service_definition.py", line 75, in test_stacked_decorated_view
resp = self.app.get("/service5")
File "/home/rfk/TEMP/mozservices/WebTest-1.3.4-py2.7.egg/webtest/app.py", line 749, in get
expect_errors=expect_errors)
File "/home/rfk/TEMP/mozservices/WebTest-1.3.4-py2.7.egg/webtest/app.py", line 1043, in do_request
res = req.get_response(app, catch_exc_info=True)
File "build/bdist.linux-x86_64/egg/webob/request.py", line 1249, in get_response
application, catch_exc_info=True)
File "build/bdist.linux-x86_64/egg/webob/request.py", line 1222, in call_application
app_iter = application(self.environ, start_response)
File "/home/rfk/TEMP/mozservices/WebTest-1.3.4-py2.7.egg/webtest/lint.py", line 174, in lint_app
iterator = application(environ, start_response_wrapper)
File "build/bdist.linux-x86_64/egg/webob/dec.py", line 130, in __call__
resp = self.call_func(req, *args, **self.kwargs)
File "build/bdist.linux-x86_64/egg/webob/dec.py", line 195, in call_func
return self.func(req, *args, **kwargs)
File "/home/rfk/TEMP/mozservices/cornice-0.8-py2.7.egg/cornice/tests/__init__.py", line 18, in __call__
return request.get_response(self.app)
File "build/bdist.linux-x86_64/egg/webob/request.py", line 1253, in get_response
application, catch_exc_info=False)
File "build/bdist.linux-x86_64/egg/webob/request.py", line 1222, in call_application
app_iter = application(self.environ, start_response)
File "/home/rfk/TEMP/mozservices/pyramid-1.3-py2.7.egg/pyramid/router.py", line 187, in __call__
response = self.handle_request(request)
File "/home/rfk/TEMP/mozservices/cornice-0.8-py2.7.egg/cornice/__init__.py", line 45, in cornice_tween
response = handler(request)
File "/home/rfk/TEMP/mozservices/pyramid-1.3-py2.7.egg/pyramid/tweens.py", line 20, in excview_tween
response = handler(request)
File "/home/rfk/TEMP/mozservices/pyramid-1.3-py2.7.egg/pyramid/router.py", line 164, in handle_request
response = view_callable(context, request)
File "/home/rfk/TEMP/mozservices/pyramid-1.3-py2.7.egg/pyramid/config/views.py", line 609, in __call__
return view(context, request)
File "/home/rfk/TEMP/mozservices/pyramid-1.3-py2.7.egg/pyramid/config/views.py", line 307, in attr_view
return view(context, request)
File "/home/rfk/TEMP/mozservices/pyramid-1.3-py2.7.egg/pyramid/config/views.py", line 280, in predicate_wrapper
return view(context, request)
File "/home/rfk/TEMP/mozservices/pyramid-1.3-py2.7.egg/pyramid/config/views.py", line 333, in rendered_view
result = view(context, request)
File "/home/rfk/TEMP/mozservices/cornice-0.8-py2.7.egg/cornice/service.py", line 34, in call_service
response = func(request)
File "/home/rfk/TEMP/mozservices/metlog_py-0.8.5-py2.7.egg/metlog/decorators/base.py", line 149, in __call__
return replacement(*args, **kwargs)
File "/home/rfk/TEMP/mozservices/mozsvc/metrics.py", line 120, in metlog_call
return self._fn(*args, **kwargs)
File "/home/rfk/TEMP/mozservices/metlog_py-0.8.5-py2.7.egg/metlog/decorators/base.py", line 149, in __call__
return replacement(*args, **kwargs)
File "/home/rfk/TEMP/mozservices/metlog_py-0.8.5-py2.7.egg/metlog/decorators/stats.py", line 51, in metlog_call
self.client.incr(*self.args, **self.kwargs)
AttributeError: 'NoneType' object has no attribute 'incr'
======================================================================
FAIL: test_decorator_ordering (mozsvc.tests.test_metrics.TestCannedDecorators)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/rfk/TEMP/mozservices/mozsvc/tests/test_metrics.py", line 140, in test_decorator_ordering
self.assertEqual(len(msgs), 2)
AssertionError: 1 != 2
======================================================================
FAIL: test_loading_from_config (mozsvc.tests.test_metrics.TestConfigurationLoading)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/rfk/TEMP/mozservices/mozsvc/tests/test_metrics.py", line 78, in test_loading_from_config
self.assertEqual(len(plugin.client.sender.msgs), 1)
AssertionError: 0 != 1
======================================================================
FAIL: test_decorate_at_constructor (mozsvc.tests.test_metrics.TestMetricsService)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/rfk/TEMP/mozservices/mozsvc/tests/test_metrics.py", line 255, in test_decorate_at_constructor
self.assertEqual(len(msgs), 3)
AssertionError: 2 != 3
======================================================================
FAIL: test_metrics_service (mozsvc.tests.test_metrics.TestMetricsService)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/rfk/TEMP/mozservices/mozsvc/tests/test_metrics.py", line 240, in test_metrics_service
self.assertEqual(len(msgs), 2)
AssertionError: 1 != 2
----------------------------------------------------------------------
Ran 57 tests in 0.188s
FAILED (failures=4, errors=1)
Error in atexit._run_exitfuncs:
Traceback (most recent call last):
File "/usr/lib/python2.7/atexit.py", line 24, in _run_exitfuncs
func(*targs, **kargs)
File "/usr/lib/python2.7/multiprocessing/util.py", line 284, in _exit_function
info('process shutting down')
TypeError: 'NoneType' object is not callable
Error in sys.exitfunc:
Traceback (most recent call last):
File "/usr/lib/python2.7/atexit.py", line 24, in _run_exitfuncs
func(*targs, **kargs)
File "/usr/lib/python2.7/multiprocessing/util.py", line 284, in _exit_function
info('process shutting down')
TypeError: 'NoneType' object is not
Taking just this failure as an example:
======================================================================
FAIL: test_metrics_service (mozsvc.tests.test_metrics.TestMetricsService)
----------------------------------------------------------------------
Traceback (most recent call last):
File "/home/rfk/TEMP/mozservices/mozsvc/tests/test_metrics.py", line 240, in test_metrics_service
self.assertEqual(len(msgs), 2)
AssertionError: 1 != 2
----------------------------------------------------------------------
The problem seems to be some sort of global configuration conflict. On one of my machines, the "timeit" decorator someone finds itself in the list of disabled decorators, is not executed and hence we are missing one of the expected log messages. On another machine, it is not in the disabled list and the tests run fine.
I suspect that the configuration from this unrelated test is somehow leaking over into the other tests, but I'm not sure how or why: https://github.com/mozilla-services/mozservices/blob/master/mozsvc/tests/test_partial_disable_metrics.py#L36
Yep, throwing in some print statements shows that this is an ordering issue between test_metrics.py and test_partial_disable_metrics.py. nosetests
runs test_metrics first, and everything works fine. python setup.py test
runs test_partial_disable_metrics.py first, and the list of disabled decorators persists into subsequent test runs to cause the errors shown above.
If I rename "test_partial_disable_metrics.py" to "test_aaaaa.py" so that nose will run it first, I get the same errors using both nosetests
and python setup.py test
.
Thanks for the debugging! Once I renamed the partial disable test file to test_aaaaa.py I was also able to reproduce. I think I've fixed it in c09088c874f0bfe67f09e7ea7018dc140ec28430. You wanna test it out and close if it fixes it for you too?
Great, thanks! I still get one failing test, due to a similar ordering issue with test_service_definition.py. It is the same AttributeError: 'NoneType' object has no attribute 'incr'
error from the tracebacks in my previous comment.
I tried applying your fix to this file as well bug it didn't seem to help.
Ah, this was a different one, that would only happen if test_service_definition was run before test_metrics. I was able to reproduce and have pushed a fix.
Confirming that all tests now pass for me as well. Thanks!
For me at least, running the tests via
nosetests
reports 57 test and 0 failures. Running withpython setup.py test
reports 57 tests, 4 failures, 1 error. All seem to be related to metlog.Can anyone else confirm this, is it something funny about my machine? Does it indicate some corner-case where metlog doesn't get set up properly?