diff --git a/src/firebase_functions/logger.py b/src/firebase_functions/logger.py index 0e22fc5..1caebe1 100644 --- a/src/firebase_functions/logger.py +++ b/src/firebase_functions/logger.py @@ -5,6 +5,7 @@ import enum as _enum import json as _json import sys as _sys +import traceback as _traceback import typing as _typing import typing_extensions as _typing_extensions @@ -43,6 +44,7 @@ class LogEntry(_typing.TypedDict): severity: _typing_extensions.Required[LogSeverity] message: _typing_extensions.NotRequired[str] + stack_trace: _typing_extensions.NotRequired[str] def _entry_from_args(severity: LogSeverity, *args, **kwargs) -> LogEntry: @@ -54,24 +56,134 @@ def _entry_from_args(severity: LogSeverity, *args, **kwargs) -> LogEntry: [ value if isinstance(value, str) - else _json.dumps(_remove_circular(value), ensure_ascii=False) + else _json.dumps(_coerce_json_safe(_remove_circular(value)), ensure_ascii=False) for value in args ] ) other: dict[str, _typing.Any] = { - key: value if isinstance(value, str) else _remove_circular(value) + key: value if isinstance(value, str) else _coerce_json_safe(_remove_circular(value)) for key, value in kwargs.items() } entry: dict[str, _typing.Any] = {"severity": severity, **other} if message: entry["message"] = message + if severity == LogSeverity.ERROR: + stack_trace = _stack_trace_from_args(args, kwargs) + if stack_trace is not None: + entry["stack_trace"] = stack_trace return _typing.cast(LogEntry, entry) -def _remove_circular(obj: _typing.Any, refs: set[_typing.Any] | None = None): +def _stack_trace_from_exception(exception: BaseException) -> str | None: + """ + Returns a formatted stack trace for an exception when available. + """ + + if exception.__traceback__ is not None: + try: + return "".join( + _traceback.format_exception(exception.__class__, exception, exception.__traceback__) + ) + except Exception: + stack_trace = "".join(_traceback.format_tb(exception.__traceback__)) + stack_trace += f"{exception.__class__.__name__}: {_safe_exception_string(exception)}\n" + return stack_trace + return None + + +def _stack_trace_from_exception_type(exception_type: type[BaseException]) -> str | None: + """ + Returns the active stack trace when the given type matches the current exception. + """ + + exc_type, exc_value, exc_traceback = _sys.exc_info() + if exc_type is exception_type and exc_value is not None: + if exc_traceback is not None: + return "".join(_traceback.format_exception(exc_type, exc_value, exc_traceback)) + return None + + +def _stack_trace_from_args( + args: tuple[_typing.Any, ...], kwargs: dict[str, _typing.Any] +) -> str | None: + """ + Returns the first available stack trace from logger arguments or active exception state. + """ + + for value in (*args, *kwargs.values()): + if isinstance(value, BaseException): + stack_trace = _stack_trace_from_exception(value) + if stack_trace is not None: + return stack_trace + elif isinstance(value, type) and issubclass(value, BaseException): + stack_trace = _stack_trace_from_exception_type(value) + if stack_trace is not None: + return stack_trace + + exc_type, exc_value, exc_traceback = _sys.exc_info() + if exc_type is not None and exc_value is not None and exc_traceback is not None: + return "".join(_traceback.format_exception(exc_type, exc_value, exc_traceback)) + + return None + + +def _safe_exception_string(exception: BaseException) -> str: + """ + Returns a string representation of an exception without propagating repr/str errors. + """ + + try: + return str(exception) + except Exception: + return exception.__class__.__name__ + + +def _coerce_json_safe(obj: _typing.Any): + """ + Converts values that survive circular-reference removal into JSON-safe values. + """ + + if isinstance(obj, str | int | float | bool | type(None)): + return obj + if isinstance(obj, dict): + return { + _coerce_json_safe_dict_key(key): _coerce_json_safe(value) for key, value in obj.items() + } + if isinstance(obj, list): + return [_coerce_json_safe(item) for item in obj] + if isinstance(obj, tuple): + return tuple(_coerce_json_safe(item) for item in obj) + return _safe_repr(obj) + + +def _coerce_json_safe_dict_key(obj: _typing.Any): + """ + Converts dictionary keys into values accepted by JSON object encoding. + """ + + if isinstance(obj, str | int | float | bool | type(None)): + return obj + coerced = _coerce_json_safe(obj) + if isinstance(coerced, str | int | float | bool | type(None)): + return coerced + return _safe_repr(coerced) + + +def _safe_repr(obj: _typing.Any) -> str: + """ + Returns a repr without propagating repr errors. + """ + + try: + return repr(obj) + except Exception: + return obj.__class__.__name__ + + +def _remove_circular(obj: _typing.Any, refs: set[int] | None = None): """ Removes circular references from the given object and replaces them with "[CIRCULAR]". """ diff --git a/tests/test_logger.py b/tests/test_logger.py index 8f6aaee..6936ea2 100644 --- a/tests/test_logger.py +++ b/tests/test_logger.py @@ -4,6 +4,7 @@ """ import json +import sys import pytest @@ -59,6 +60,143 @@ def test_severity_should_be_error(self, capsys: pytest.CaptureFixture[str]): log_output = json.loads(raw_log_output) assert log_output["severity"] == "ERROR" + def test_error_should_accept_exception(self, capsys: pytest.CaptureFixture[str]): + try: + raise ValueError("boom") + except ValueError as exception: + logger.error("failed", error=exception) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert isinstance(log_output["error"], str) + assert "ValueError" in log_output["error"] + assert "boom" in log_output["error"] + assert "stack_trace" in log_output + assert "ValueError: boom" in log_output["stack_trace"] + + def test_error_should_accept_exception_type(self, capsys: pytest.CaptureFixture[str]): + try: + raise TypeError("boom") + except TypeError: + logger.error("failed", error=sys.exc_info()[0]) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert isinstance(log_output["error"], str) + assert "TypeError" in log_output["error"] + assert "stack_trace" in log_output + assert "TypeError: boom" in log_output["stack_trace"] + + def test_error_should_accept_self_referential_exception( + self, capsys: pytest.CaptureFixture[str] + ): + class SelfArgError(Exception): + pass + + exception = SelfArgError("boom") + exception.args = (exception,) + + logger.error("failed", error=exception) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert isinstance(log_output["error"], str) + assert "SelfArgError" in log_output["error"] + + def test_error_should_accept_exception_with_cyclic_payload( + self, capsys: pytest.CaptureFixture[str] + ): + payload = {} + payload["self"] = payload + exception = ValueError(payload) + + logger.error("failed", error=exception) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert isinstance(log_output["error"], str) + assert "ValueError" in log_output["error"] + assert "stack_trace" not in log_output + + def test_error_should_accept_exception_with_non_json_serializable_args( + self, capsys: pytest.CaptureFixture[str] + ): + payload = object() + exception = ValueError(payload) + + logger.error("failed", error=exception) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert isinstance(log_output["error"], str) + assert "ValueError" in log_output["error"] + + def test_error_should_accept_exception_with_repr_raising_arg( + self, capsys: pytest.CaptureFixture[str] + ): + class BadRepr: + def __repr__(self): + raise RuntimeError("boom") + + exception = ValueError(BadRepr()) + + logger.error("failed", error=exception) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert isinstance(log_output["error"], str) + assert "ValueError" in log_output["error"] + + def test_error_should_accept_exception_with_non_json_serializable_dict_key( + self, capsys: pytest.CaptureFixture[str] + ): + payload = {object(): "value"} + exception = ValueError(payload) + + logger.error("failed", error=exception) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert isinstance(log_output["error"], str) + assert "ValueError" in log_output["error"] + + def test_error_should_accept_exception_with_tuple_dict_key( + self, capsys: pytest.CaptureFixture[str] + ): + payload = {(1, "two"): "value"} + exception = ValueError(payload) + + logger.error("failed", error=exception) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert isinstance(log_output["error"], str) + assert "ValueError" in log_output["error"] + def test_log_should_have_message(self, capsys: pytest.CaptureFixture[str]): logger.log("bar") raw_log_output = capsys.readouterr().out @@ -78,6 +216,73 @@ def test_message_should_be_space_separated(self, capsys: pytest.CaptureFixture[s log_output = json.loads(raw_log_output) assert log_output["message"] == expected_message + def test_error_should_include_active_stack_trace(self, capsys: pytest.CaptureFixture[str]): + try: + raise ValueError("boom") + except ValueError: + logger.error("failed") + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert "stack_trace" in log_output + assert "ValueError: boom" in log_output["stack_trace"] + + def test_error_should_surface_top_level_stack_trace_for_exception_error( + self, capsys: pytest.CaptureFixture[str] + ): + try: + raise ValueError("boom") + except ValueError as exception: + logger.error("failed", error=exception) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert "stack_trace" in log_output + assert "ValueError: boom" in log_output["stack_trace"] + assert isinstance(log_output["error"], str) + assert "ValueError" in log_output["error"] + + def test_error_should_surface_top_level_stack_trace_for_exception_type_error( + self, capsys: pytest.CaptureFixture[str] + ): + try: + raise TypeError("boom") + except TypeError: + logger.error("failed", error=sys.exc_info()[0]) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert "stack_trace" in log_output + assert "TypeError: boom" in log_output["stack_trace"] + assert isinstance(log_output["error"], str) + assert "TypeError" in log_output["error"] + + def test_error_should_not_add_nested_trace_to_error_dict( + self, capsys: pytest.CaptureFixture[str] + ): + try: + raise ValueError("boom") + except ValueError: + logger.error("failed", error={"stack_trace": "custom traceback"}) + + raw_log_output = capsys.readouterr().err + log_output = json.loads(raw_log_output) + + assert log_output["severity"] == "ERROR" + assert log_output["message"] == "failed" + assert log_output["error"] == {"stack_trace": "custom traceback"} + assert "stack_trace" in log_output + assert "ValueError: boom" in log_output["stack_trace"] + def test_remove_circular_references(self, capsys: pytest.CaptureFixture[str]): # Create an object with a circular reference. circ = {"b": "foo"}