Unintended traceback omittion #735
Description
After PR #394 was merged, tracebacks are no longer duplicated after structured log messages.
However, the effect of that change is not limited to StructuredLogHandler.
When you try to use StructuredLogHandler in conjunction with some other log handlers as follows, you will encounter an unintended problem.
Specifically, any log handlers will be called later than the StructuredLogHandler will never output traceback because they can not detect record.exc_info and record.exc_text. Both are set to None.
This behaviour is caused by the record object has changed directly in StructuredLogHander.
Code example
import logging
from google.cloud.logging.handlers import StructuredLogHandler
class SampleHandler(logging.StreamHandler): ...
logger = logging.getLogger()
logger.handlers.clear()
logger.addHandler(StructuredLogHandler())
logger.addHandler(SampleHandler())
try:
raise Exception("Test")
except Exception:
logger.exception("Failed")
print("----------")Output
$ python run1.py
{"logging.googleapis.com/diagnostic": {"instrumentation_source": [{"name": "python", "version": "3.5.0"}]},"severity": "INFO", "logging.googleapis.com/labels": {"python_logger": "google.cloud.logging_v2.handlers.structured_log"}, "logging.googleapis.com/trace": "", "logging.googleapis.com/spanId": "", "logging.googleapis.com/trace_sampled": false, "logging.googleapis.com/sourceLocation": {"line": 137, "file": "/Users/shoji.kumagai/work/temp/logging_test/google-cloud-logging/.venv/lib/python3.11/site-packages/google/cloud/logging_v2/handlers/structured_log.py", "function": "emit_instrumentation_info"}, "httpRequest": {} }
{"logging.googleapis.com/diagnostic": {"instrumentation_source": [{"name": "python", "version": "3.5.0"}]},"severity": "INFO", "logging.googleapis.com/labels": {"python_logger": "google.cloud.logging_v2.handlers.structured_log"}, "logging.googleapis.com/trace": "", "logging.googleapis.com/spanId": "", "logging.googleapis.com/trace_sampled": false, "logging.googleapis.com/sourceLocation": {"line": 137, "file": "/Users/shoji.kumagai/work/temp/logging_test/google-cloud-logging/.venv/lib/python3.11/site-packages/google/cloud/logging_v2/handlers/structured_log.py", "function": "emit_instrumentation_info"}, "httpRequest": {} }
{'logging.googleapis.com/diagnostic': {'instrumentation_source': [{'name': 'python', 'version': '3.5.0'}]}}
{"message": "Failed\nTraceback (most recent call last):\n File \"/Users/shoji.kumagai/work/temp/logging_test/google-cloud-logging/run1.py\", line 16, in <module>\n raise Exception(\"Test\")\nException: Test","severity": "ERROR", "logging.googleapis.com/labels": {"python_logger": "root"}, "logging.googleapis.com/trace": "", "logging.googleapis.com/spanId": "", "logging.googleapis.com/trace_sampled": false, "logging.googleapis.com/sourceLocation": {"line": 18, "file": "/Users/shoji.kumagai/work/temp/logging_test/google-cloud-logging/run1.py", "function": "<module>"}, "httpRequest": {} }
Failed
----------
As you can see above, the structured log message is output without traceback intendedly.
On the other hand, the log message of SampleHandler is also output without traceback though it's not intended.
Suggestion
- Never use the original record object in the StructuredLogHander, but use its copied one
- Use the custom Formatter which overridden format() method to omit any traceback