Allow to override the log level while logging exceptions (#79)

While logging information during an exception `except` block, instead of
overwriting the log level with `CRITICAL`, the log level used by the
caller will be set instead.

This allows the caller to use:

```python
try:
    raise ValueError()
except Exception as exc:
    logger.info(f"I was expecting this error: {exc}")
```

The log message will be logged as `INFO` level, whereas it was logged as
`CRITICAL` before.

If an `exception` attribute is still passed to the logger, as in
`logger.info("something", exception=exc)`, the log level will be `INFO`
as expected but the error will also still be correctly reported (in
Error Reporting + the bubble in Cloud Logging)

Author: multani

README.md

@@ -58,6 +58,11 @@ except:
 
 if not converted:
     logger.critical("This is not supposed to happen", converted=converted)
+
+try:
+    1 / 0
+except ZeroDivisionError as exc:
+    logger.info("This was known to happen! {exc}")
 ```
 
 The `structlog_gcp.build_processors()` function constructs structlog processors to:
@@ -70,12 +75,66 @@ For more advanced usage, see [Advanced Configuration](#advanced-configuration)
 
 ### Errors
 
-Errors are automatically reported to the [Google Error Reporting service](https://cloud.google.com/error-reporting/).
+
+Errors are automatically reported to the [Google Error Reporting service](https://cloud.google.com/error-reporting/), most of the time.
+
+#### Using `logger.exception`
+
+Using:
+
+```python
+try:
+    1 / 0
+except:
+    logger.exception("oh no")
+```
+
+Will give you:
+
+* The current exception can automatically added into the log event
+* The log level will be `ERROR`
+* The exception will be reported in Error Reporting
+
+##### Using `logger.$LEVEL(..., exception=exc)`
+
+Using:
+
+```python
+try:
+    1 / 0
+except Exception as exc
+    logger.info("oh no", exception=exc)
+```
+Will give you:
+
+* The specified exception will be part of the log event
+* The log level will be `INFO`, or whichever log level you used
+* The exception will be reported in Error Reporting
+
+
+##### Using `logger.$LEVEL(...)`
+
+Not passing any `exception` argument to the logger, as in:
+
+```python
+try:
+    1 / 0
+except Exception as exc
+    logger.warning(f"oh no: {exc}")
+```
+
+Will give you:
+
+* The exception will **not** be part of the log event.
+* The log level will be `WARNING` (or whichever log level you used)
+* AND the exception will **not** be reported in Error Reporting
+
+### Configuration
 
 You can configure the service name and the version used during the report with 2 different ways:
 
-* By default, the library assumes to run with Cloud Function environment
-  variables configured, in particular [the `K_SERVICE` and `K_REVISION` variables](https://cloud.google.com/functions/docs/configuring/env-var#runtime_environment_variables_set_automatically).
+* By default, the library assumes to run with Cloud Run environment
+  variables configured, in particular [the `K_SERVICE` and `K_REVISION` variables](https://cloud.google.com/run/docs/configuring/services/overview-environment-variables#reserved_environment_variables_for_functions).
 * You can also pass the service name and revision at configuration time with:
 
   ```python

structlog_gcp/base.py

@@ -54,7 +54,7 @@ def build_gcp_processors(
     procs.append(structlog.processors.TimeStamper(fmt="iso"))
     procs.append(processors.init_cloud_logging)
 
-    procs.extend(processors.setup_log_severity())
+    procs.append(processors.LogSeverity())
     procs.extend(processors.setup_code_location())
 
     # Errors: log exceptions

structlog_gcp/constants.py

@@ -0,0 +1,22 @@
+ERROR_EVENT_TYPE = (
+    "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent"
+)
+
+SOURCE_LOCATION_KEY = "logging.googleapis.com/sourceLocation"
+
+CLOUD_LOGGING_KEY = "cloud-logging"
+
+# From Python's logging level to Google level
+# https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry#LogSeverity
+SEVERITY_MAPPING = {
+    "notset": "DEFAULT",  # The log entry has no assigned severity level.
+    "debug": "DEBUG",  # Debug or trace information.
+    "info": "INFO",  # Routine information, such as ongoing status or performance.
+    # "notice": "NOTICE", # Normal but significant events, such as start up, shut down, or a configuration change.
+    "warn": "WARNING",  # Warning events might cause problems.
+    "warning": "WARNING",  # Warning events might cause problems.
+    "error": "ERROR",  # Error events are likely to cause problems.
+    "critical": "CRITICAL",  # Critical events cause more severe problems or outages.
+    # "alert": "ALERT", # A person must take an action immediately.
+    # "emergency": "EMERGENCY", #	One or more systems are unusable.
+}

structlog_gcp/error_reporting.py

@@ -3,11 +3,11 @@
 import structlog.processors
 from structlog.typing import EventDict, Processor, WrappedLogger
 
-from .types import CLOUD_LOGGING_KEY, ERROR_EVENT_TYPE, SOURCE_LOCATION_KEY
+from .constants import CLOUD_LOGGING_KEY, ERROR_EVENT_TYPE, SOURCE_LOCATION_KEY
 
 
-def setup_exceptions(log_level: str = "CRITICAL") -> list[Processor]:
-    return [structlog.processors.format_exc_info, ReportException(log_level)]
+def setup_exceptions() -> list[Processor]:
+    return [structlog.processors.format_exc_info, ReportException()]
 
 
 class ReportException:
@@ -16,8 +16,8 @@ class ReportException:
     # https://cloud.google.com/error-reporting/reference/rest/v1beta1/projects.events/report
     # https://cloud.google.com/error-reporting/docs/formatting-error-messages#log-entry-examples
 
-    def __init__(self, log_level: str = "CRITICAL") -> None:
-        self.log_level = log_level
+    def __init__(self) -> None:
+        pass
 
     def __call__(
         self, logger: WrappedLogger, method_name: str, event_dict: EventDict
@@ -27,7 +27,6 @@ def __call__(
             return event_dict
 
         event_dict[CLOUD_LOGGING_KEY]["@type"] = ERROR_EVENT_TYPE
-        event_dict[CLOUD_LOGGING_KEY]["severity"] = self.log_level
 
         # https://cloud.google.com/error-reporting/docs/formatting-error-messages
         message = event_dict[CLOUD_LOGGING_KEY]["message"]
@@ -53,8 +52,9 @@ def __call__(
         self, logger: WrappedLogger, method_name: str, event_dict: EventDict
     ) -> EventDict:
         severity = event_dict[CLOUD_LOGGING_KEY]["severity"]
+        has_strack_trace = "stack_trace" in event_dict[CLOUD_LOGGING_KEY]
 
-        if severity not in self.severities:
+        if severity not in self.severities and not has_strack_trace:
             return event_dict
 
         # https://cloud.google.com/error-reporting/reference/rest/v1beta1/ErrorContext

structlog_gcp/processors.py

@@ -6,11 +6,7 @@
 import structlog.processors
 from structlog.typing import EventDict, Processor, WrappedLogger
 
-from .types import CLOUD_LOGGING_KEY, SOURCE_LOCATION_KEY
-
-
-def setup_log_severity() -> list[Processor]:
-    return [structlog.processors.add_log_level, LogSeverity()]
+from .constants import CLOUD_LOGGING_KEY, SEVERITY_MAPPING, SOURCE_LOCATION_KEY
 
 
 def setup_code_location() -> list[Processor]:
@@ -77,27 +73,14 @@ class LogSeverity:
 
     def __init__(self) -> None:
         self.default = "notset"
-
-        # From Python's logging level to Google level
-        self.mapping = {
-            "notset": "DEFAULT",  # The log entry has no assigned severity level.
-            "debug": "DEBUG",  # Debug or trace information.
-            "info": "INFO",  # Routine information, such as ongoing status or performance.
-            # "notice": "NOTICE", # Normal but significant events, such as start up, shut down, or a configuration change.
-            "warn": "WARNING",  # Warning events might cause problems.
-            "warning": "WARNING",  # Warning events might cause problems.
-            "error": "ERROR",  # Error events are likely to cause problems.
-            "critical": "CRITICAL",  # Critical events cause more severe problems or outages.
-            # "alert": "ALERT", # A person must take an action immediately.
-            # "emergency": "EMERGENCY", #	One or more systems are unusable.
-        }
+        self.mapping = SEVERITY_MAPPING.copy()
 
     def __call__(
         self, logger: WrappedLogger, method_name: str, event_dict: EventDict
     ) -> EventDict:
         """Format a Python log level value as a GCP log severity."""
 
-        log_level = event_dict.pop("level")
+        log_level = method_name
         severity = self.mapping.get(log_level, self.default)
 
         event_dict[CLOUD_LOGGING_KEY]["severity"] = severity

structlog_gcp/types.py

@@ -31,10 +31,12 @@ def logger(mock_logger_env: None) -> Generator[WrappedLogger, None, None]:
     """Setup a logger for testing and return it"""
 
     structlog.reset_defaults()
+    structlog.contextvars.clear_contextvars()
 
     processors = structlog_gcp.build_processors()
     structlog.configure(processors=processors)
     logger = structlog.get_logger()
+
     yield logger
 
     structlog.reset_defaults()

tests/conftest.py

@@ -29,7 +29,7 @@ def test_normal(stdout: T_stdout, logger: WrappedLogger) -> None:
     assert msg == expected
 
 
-def test_error(stdout: T_stdout, logger: WrappedLogger) -> None:
+def test_exception(stdout: T_stdout, logger: WrappedLogger) -> None:
     try:
         1 / 0
     except ZeroDivisionError:
@@ -56,7 +56,7 @@ def test_error(stdout: T_stdout, logger: WrappedLogger) -> None:
             "version": "unknown version",
         },
         "foo": "bar",
-        "severity": "CRITICAL",
+        "severity": "ERROR",
         "message": "oh noes",
         "stack_trace": "oh noes\nTraceback blabla",
         "time": "2023-04-01T08:00:00.000000Z",
@@ -190,4 +190,59 @@ def test_core_processors_only(stdout: T_stdout, mock_logger_env: None) -> None:
     # No JSON formmating, no contextvars
     expected = "message='test' time='2023-04-01T08:00:00.000000Z' severity='INFO' logging.googleapis.com/sourceLocation={'file': '/app/test.py', 'line': '42', 'function': 'test:test123'}"
 
+    assert expected == msg
+
+
+def test_exception_different_level(stdout: T_stdout, logger: WrappedLogger) -> None:
+    try:
+        1 / 0
+    except ZeroDivisionError as exc:
+        logger.warning("oh no; anyways", exception=exc)
+
+    msg = json.loads(stdout())
+
+    expected = {
+        "@type": "type.googleapis.com/google.devtools.clouderrorreporting.v1beta1.ReportedErrorEvent",
+        "context": {
+            "reportLocation": {
+                "file": "/app/test.py",
+                "function": "test:test123",
+                "line": "42",
+            },
+        },
+        "logging.googleapis.com/sourceLocation": {
+            "file": "/app/test.py",
+            "function": "test:test123",
+            "line": "42",
+        },
+        "serviceContext": {
+            "service": "unknown service",
+            "version": "unknown version",
+        },
+        "severity": "WARNING",
+        "message": "oh no; anyways",
+        "stack_trace": "oh no; anyways\ndivision by zero",
+        "time": "2023-04-01T08:00:00.000000Z",
+    }
+    assert msg == expected
+
+
+def test_exception_handled(stdout: T_stdout, logger: WrappedLogger) -> None:
+    try:
+        1 / 0
+    except ZeroDivisionError as exc:
+        logger.info(f"I was expecting that error: {exc}")
+
+    msg = json.loads(stdout())
+
+    expected = {
+        "logging.googleapis.com/sourceLocation": {
+            "file": "/app/test.py",
+            "function": "test:test123",
+            "line": "42",
+        },
+        "severity": "INFO",
+        "message": "I was expecting that error: division by zero",
+        "time": "2023-04-01T08:00:00.000000Z",
+    }
     assert msg == expected