Fix bug where ws exceptions not being logged (#2213)

* Fix bug where ws exceptions not being logged

* Fix t\est

sanic/app.py

@@ -893,6 +893,8 @@ class Sanic(BaseSanic, metaclass=TouchUpMeta):
         self.websocket_tasks.add(fut)
         try:
             await fut
+        except Exception as e:
+            self.error_handler.log(request, e)
         except (CancelledError, ConnectionClosed):
             pass
         finally:

sanic/handlers.py

@@ -1,5 +1,3 @@
-from traceback import format_exc
-
 from sanic.errorpages import exception_response
 from sanic.exceptions import (
     ContentRangeError,
@@ -99,7 +97,6 @@ class ErrorHandler:
             if response is None:
                 response = self.default(request, exception)
         except Exception:
-            self.log(format_exc())
             try:
                 url = repr(request.url)
             except AttributeError:
@@ -115,11 +112,6 @@ class ErrorHandler:
                 return text("An error occurred while handling an error", 500)
         return response
 
-    def log(self, message, level="error"):
-        """
-        Deprecated, do not use.
-        """
-
     def default(self, request, exception):
         """
         Provide a default behavior for the objects of :class:`ErrorHandler`.
@@ -135,6 +127,11 @@ class ErrorHandler:
             :class:`Exception`
         :return:
         """
+        self.log(request, exception)
+        return exception_response(request, exception, self.debug)
+
+    @staticmethod
+    def log(request, exception):
         quiet = getattr(exception, "quiet", False)
         if quiet is False:
             try:
@@ -142,13 +139,10 @@ class ErrorHandler:
             except AttributeError:
                 url = "unknown"
 
-            self.log(format_exc())
             error_logger.exception(
                 "Exception occurred while handling uri: %s", url
             )
 
-        return exception_response(request, exception, self.debug)
-
 
 class ContentRangeHandler:
     """

tests/test_asgi.py

@@ -360,6 +360,7 @@ async def test_request_handle_exception(app):
     _, response = await app.asgi_client.get("/error-prone")
     assert response.status_code == 503
 
+
 @pytest.mark.asyncio
 async def test_request_exception_suppressed_by_middleware(app):
     @app.get("/error-prone")
@@ -374,4 +375,4 @@ async def test_request_exception_suppressed_by_middleware(app):
     assert response.status_code == 403
 
     _, response = await app.asgi_client.get("/error-prone")
-    assert response.status_code == 403
+    assert response.status_code == 403

tests/test_exceptions.py

@@ -1,3 +1,4 @@
+import logging
 import warnings
 
 import pytest
@@ -232,3 +233,20 @@ def test_sanic_exception(exception_app):
         request, response = exception_app.test_client.get("/old_abort")
     assert response.status == 500
     assert len(w) == 1 and "deprecated" in w[0].message.args[0]
+
+
+def test_exception_in_ws_logged(caplog):
+    app = Sanic(__file__)
+
+    @app.websocket("/feed")
+    async def feed(request, ws):
+        raise Exception("...")
+
+    with caplog.at_level(logging.INFO):
+        app.test_client.websocket("/feed")
+
+    assert caplog.record_tuples[1][0] == "sanic.error"
+    assert caplog.record_tuples[1][1] == logging.ERROR
+    assert (
+        "Exception occurred while handling uri:" in caplog.record_tuples[1][2]
+    )