Merge pull request #547 from iky/log-errors-as-errors

Log unhandled worker exceptions at ERROR level

nameko/containers.py

@@ -390,8 +390,13 @@ def _run_worker(self, worker_ctx, handle_result):
                 with _log_time('ran handler for %s', worker_ctx):
                     result = method(*worker_ctx.args, **worker_ctx.kwargs)
             except Exception as exc:
-                _log.info('error handling worker %s: %s', worker_ctx, exc,
-                          exc_info=True)
+                if isinstance(exc, worker_ctx.entrypoint.expected_exceptions):
+                    _log.warning(
+                        '(expected) error handling worker %s: %s',
+                        worker_ctx, exc, exc_info=True)
+                else:
+                    _log.exception(
+                        'error handling worker %s: %s', worker_ctx, exc)
                 exc_info = sys.exc_info()
 
             if handle_result is not None:
@@ -475,7 +480,7 @@ def _handle_thread_exited(self, gt):
             _log.debug('%s thread killed by container', self)
 
         except Exception:
-            _log.error('%s thread exited with error', self, exc_info=True)
+            _log.critical('%s thread exited with error', self, exc_info=True)
             # any uncaught error in a thread is unexpected behavior
             # and probably a bug in the extension or container.
             # to be safe we call self.kill() to kill our dependencies and

test/test_container.py

@@ -56,6 +56,7 @@ def kill(self, exc=None):
 
 class CallCollectingEntrypoint(CallCollectorMixin, Entrypoint):
     instances = set()
+    expected_exceptions = ()
 
 
 class CallCollectingDependencyProvider(CallCollectorMixin, DependencyProvider):

test/test_errors.py

@@ -1,7 +1,7 @@
 # start a runner with a service that errors. does it hang? or stop?
 # how do we get an individual servicecontainer to blow up?
 import pytest
-from mock import patch
+from mock import ANY, call, patch
 
 from nameko.events import EventDispatcher
 from nameko.exceptions import RemoteError
@@ -29,6 +29,10 @@ def task(self):
     def broken(self):
         raise ExampleError("broken")
 
+    @rpc(expected_exceptions=ExampleError)
+    def bad(self):
+        raise ExampleError("bad")
+
     @rpc
     def proxy(self, method, *args):
         """ Proxies RPC calls to ``method`` on itself, so we can test handling
@@ -50,11 +54,30 @@ def test_error_in_worker(container_factory, rabbit_config):
     container = container_factory(ExampleService, rabbit_config)
     container.start()
 
-    with entrypoint_hook(container, "broken") as broken:
-        with pytest.raises(ExampleError):
-            broken()
+    with patch('nameko.containers._log') as logger:
+        with entrypoint_hook(container, "broken") as broken:
+            with pytest.raises(ExampleError):
+                broken()
+    assert not container._died.ready()
+
+    assert logger.exception.call_args == call(
+        'error handling worker %s: %s', ANY, ANY)
+
+
+def test_expected_error_in_worker(container_factory, rabbit_config):
+
+    container = container_factory(ExampleService, rabbit_config)
+    container.start()
+
+    with patch('nameko.containers._log') as logger:
+        with entrypoint_hook(container, "bad") as bad:
+            with pytest.raises(ExampleError):
+                bad()
     assert not container._died.ready()
 
+    assert logger.warning.call_args == call(
+        '(expected) error handling worker %s: %s', ANY, ANY, exc_info=True)
+
 
 def test_error_in_remote_worker(container_factory, rabbit_config):