Skip to content

Change default "extra" contents of activity/workflow logs #490

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 4 commits into from
Apr 2, 2024
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
23 changes: 19 additions & 4 deletions temporalio/activity.py
Original file line number Diff line number Diff line change
Expand Up @@ -427,9 +427,14 @@ class LoggerAdapter(logging.LoggerAdapter):
activity_info_on_message: Boolean for whether a string representation of
a dict of some activity info will be appended to each message.
Default is True.
activity_info_on_extra: Boolean for whether an ``activity_info`` value
will be added to the ``extra`` dictionary, making it present on the
``LogRecord.__dict__`` for use by others.
activity_info_on_extra: Boolean for whether a ``temporal_activity``
dictionary value will be added to the ``extra`` dictionary with some
activity info, making it present on the ``LogRecord.__dict__`` for
use by others. Default is True.
full_activity_info_on_extra: Boolean for whether an ``activity_info``
value will be added to the ``extra`` dictionary with the entire
activity info, making it present on the ``LogRecord.__dict__`` for
use by others. Default is False.
Comment on lines +434 to +437
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think the term full is really clear. Maybe activity_info_data_class_on_extra and clarify this may not be the best option for indexing? I'd also consider deprecating this eventually, no need to have both versions long term, this is just for a transition period.

Copy link
Member Author

@cretz cretz Apr 2, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think the term full is really clear. Maybe activity_info_data_class_on_extra and clarify this may not be the best option for indexing

I considered removing "full" but it clashed with the other. "full activity info" literally refers to activity.Info, that it's a dataclass shouldn't matter.

I'd also consider deprecating this eventually, no need to have both versions long term, this is just for a transition period.

Considered this, but it's off by default and harmless for the most part, so no reason not to leave it.

"""

def __init__(
Expand All @@ -439,17 +444,27 @@ def __init__(
super().__init__(logger, extra or {})
self.activity_info_on_message = True
self.activity_info_on_extra = True
self.full_activity_info_on_extra = False

def process(
self, msg: Any, kwargs: MutableMapping[str, Any]
) -> Tuple[Any, MutableMapping[str, Any]]:
"""Override to add activity details."""
if self.activity_info_on_message or self.activity_info_on_extra:
if (
self.activity_info_on_message
or self.activity_info_on_extra
or self.full_activity_info_on_extra
):
context = _current_context.get(None)
if context:
if self.activity_info_on_message:
msg = f"{msg} ({context.logger_details})"
if self.activity_info_on_extra:
# Extra can be absent or None, this handles both
extra = kwargs.get("extra", None) or {}
extra["temporal_activity"] = context._logger_details
kwargs["extra"] = extra
if self.full_activity_info_on_extra:
# Extra can be absent or None, this handles both
extra = kwargs.get("extra", None) or {}
extra["activity_info"] = context.info()
Expand Down
23 changes: 19 additions & 4 deletions temporalio/workflow.py
Original file line number Diff line number Diff line change
Expand Up @@ -1085,9 +1085,14 @@ class LoggerAdapter(logging.LoggerAdapter):
workflow_info_on_message: Boolean for whether a string representation of
a dict of some workflow info will be appended to each message.
Default is True.
workflow_info_on_extra: Boolean for whether a ``workflow_info`` value
will be added to the ``extra`` dictionary, making it present on the
``LogRecord.__dict__`` for use by others.
workflow_info_on_extra: Boolean for whether a ``temporal_workflow``
dictionary value will be added to the ``extra`` dictionary with some
workflow info, making it present on the ``LogRecord.__dict__`` for
use by others. Default is True.
full_workflow_info_on_extra: Boolean for whether a ``workflow_info``
value will be added to the ``extra`` dictionary with the entire
workflow info, making it present on the ``LogRecord.__dict__`` for
use by others. Default is False.
log_during_replay: Boolean for whether logs should occur during replay.
Default is False.
"""
Expand All @@ -1099,18 +1104,28 @@ def __init__(
super().__init__(logger, extra or {})
self.workflow_info_on_message = True
self.workflow_info_on_extra = True
self.full_workflow_info_on_extra = False
self.log_during_replay = False

def process(
self, msg: Any, kwargs: MutableMapping[str, Any]
) -> Tuple[Any, MutableMapping[str, Any]]:
"""Override to add workflow details."""
if self.workflow_info_on_message or self.workflow_info_on_extra:
if (
self.workflow_info_on_message
or self.workflow_info_on_extra
or self.full_workflow_info_on_extra
):
runtime = _Runtime.maybe_current()
if runtime:
if self.workflow_info_on_message:
msg = f"{msg} ({runtime.logger_details})"
if self.workflow_info_on_extra:
# Extra can be absent or None, this handles both
extra = kwargs.get("extra", None) or {}
extra["temporal_workflow"] = runtime.logger_details
kwargs["extra"] = extra
if self.full_workflow_info_on_extra:
# Extra can be absent or None, this handles both
extra = kwargs.get("extra", None) or {}
extra["workflow_info"] = runtime.workflow_info()
Expand Down
2 changes: 1 addition & 1 deletion tests/worker/test_activity.py
Original file line number Diff line number Diff line change
Expand Up @@ -814,7 +814,7 @@ async def say_hello(name: str) -> str:
assert records[-1].message.startswith(
"Called with arg: Temporal ({'activity_id': '"
)
assert records[-1].__dict__["activity_info"].activity_type == "say_hello"
assert records[-1].__dict__["temporal_activity"]["activity_type"] == "say_hello"


async def test_activity_worker_shutdown(client: Client, worker: ExternalWorker):
Expand Down
6 changes: 5 additions & 1 deletion tests/worker/test_workflow.py
Original file line number Diff line number Diff line change
Expand Up @@ -1883,6 +1883,7 @@ async def test_workflow_logging(client: Client, env: WorkflowEnvironment):
workflow.logger.base_logger.addHandler(handler)
prev_level = workflow.logger.base_logger.level
workflow.logger.base_logger.setLevel(logging.INFO)
workflow.logger.full_workflow_info_on_extra = True

def find_log(starts_with: str) -> Optional[logging.LogRecord]:
for record in cast(List[logging.LogRecord], log_queue.queue):
Expand Down Expand Up @@ -1915,9 +1916,12 @@ def find_log(starts_with: str) -> Optional[logging.LogRecord]:
record = find_log("Signal: signal 1")
assert (
record
and record.__dict__["workflow_info"].workflow_type == "LoggingWorkflow"
and record.__dict__["temporal_workflow"]["workflow_type"]
== "LoggingWorkflow"
and record.funcName == "my_signal"
)
# Since we enabled full info, make sure it's there
assert isinstance(record.__dict__["workflow_info"], workflow.Info)

# Clear queue and start a new one with more signals
log_queue.queue.clear()
Expand Down