Repository navigation
Log reason for service stop - #1245
ela-kotulska-frequenz wants to merge 1 commit into
Conversation
Sorry, something went wrong.
There was a problem hiding this comment.
Pull Request Overview
This PR adds logging of cancellation reasons for both the background service and actor components.
- Adds a module-level logger and debug log in _background_service.py
- Adds an info-level log in _actor.py when an actor is cancelled
Reviewed Changes
Copilot reviewed 2 out of 2 changed files in this pull request and generated no comments.
| File | Description |
|---|---|
| src/frequenz/sdk/actor/_background_service.py | Imported logging, initialized _logger, and added a debug log call in cancel() |
| src/frequenz/sdk/actor/_actor.py | Added an info log call in cancel(), but missing logger import/definition |
src/frequenz/sdk/actor/_background_service.py:174
- This new debug logging for cancellation isn't covered by existing tests. Consider adding unit tests to verify that the cancellation reason is logged correctly.
_logger.debug("Service %s cancelled, reason: %s", self.name, msg)
src/frequenz/sdk/actor/_actor.py:147
- Add tests to ensure the actor's cancellation reason is logged at info level, matching the new behavior introduced here.
_logger.info("Actor %s cancelled, reason: %s", self.name, msg)
src/frequenz/sdk/actor/_actor.py:147
- The _logger is used here but not defined or imported. Please add import logging and initialize _logger = logging.getLogger(__name__) at the top of this file.
_logger.info("Actor %s cancelled, reason: %s", self.name, msg)
Sorry, something went wrong.
| Args: | ||
| msg: The message to be passed to the tasks being cancelled. | ||
| """ | ||
| if msg is not None: |
There was a problem hiding this comment.
Isn't this calling the super method and then its logged twice?
Sorry, something went wrong.
There was a problem hiding this comment.
In Actor has info log.
In Backgroud has debug log.
Having info log in BackgroundService will create lots of unnecessary logs (that we probably don't need).
Do you have different idea?
Sorry, something went wrong.
There was a problem hiding this comment.
Ah, well in this case it seems fine then. Didn't notice the different levels
Sorry, something went wrong.
There was a problem hiding this comment.
Cancel sounds like a rare event, and it's useful to know. INFO doesn't trigger any alerts. It wouldn't be too bad if we just had INFO in the background service.
Sorry, something went wrong.
There was a problem hiding this comment.
Oh, I didn't see this comment. For me this still sounds like a debug, because I guess it is only useful when debugging, when things are working you should see an INFO for the actor stopping, and that should be enough. That said, I'm OK to merge if there is enough consensus.
Sorry, something went wrong.
llucax
left a comment
There was a problem hiding this comment.
I'm not sure if this should be info or debug also, it seems like it might be too fine grained detail for a normal run, as we are already logging when it actually stops, so cancel would only be interesting if there is a bug and the cancel is not resulting in a stop.
Sorry, something went wrong.
| Args: | ||
| msg: The message to be passed to the tasks being cancelled. | ||
| """ | ||
| _logger.info("Service %s cancelled, reason: %s", self.name, msg) |
There was a problem hiding this comment.
Maybe it would be a bit easier to the eyes like this?
| _logger.info("Service %s cancelled, reason: %s", self.name, msg) | |
| _logger.info("Service %s cancelled%s", self.name, msg, f": {msg}" if msg is not None else "") |
Sorry, something went wrong.
Log `msg` argument to simplify debugging. Signed-off-by: Elzbieta Kotulska <elzbieta.kotulska@frequenz.com>
| msg: The message to be passed to the tasks being cancelled. | ||
| """ | ||
| if msg is not None: | ||
| _logger.info("Actor %s cancelled, reason: %s", self, msg) |
There was a problem hiding this comment.
looks like this came back somehow.
Sorry, something went wrong.
There was a problem hiding this comment.
Actor has info log because this log is important to see workflow. Log is printed only if msg is not None, to avoid log duplication (actor prints that it is cancelled in run method - and this log was useful many times.)
Background service has debug log, because info would log many misleading logs during normal runtime, which might be confusing. And those logs are only useful during debugging.
Sorry, something went wrong.
There was a problem hiding this comment.
I wouldn't put the if, I think it might be more confusing, as one might expect seeing a log entry for all cancelled operations once you saw one in the logs, you would have to be very involved in the code to know it is only logged if there is a message.
I feel pretty strongly about this one as I think it could do real harm, so for me it is either always or never.
Then again, I would prefer not to have a special case in actor with info, but I can live with that one.
Sorry, something went wrong.
|
Actor has info log because this log is important to see workflow. Log is printed only if msg is not None, to avoid log duplication (actor prints that it is cancelled in run method - and this log was useful many times.) Background service has debug log, because info would log many misleading logs during normal runtime, which might be confusing. And those logs are only useful during debugging. |
Sorry, something went wrong.
Can you give some examples? I'm still very doubtful of adding a conditional log (only logging if there is a message) as it could be misleading, specially during a stressful debugging session. Is it really a pattern we use that we cancel without a message when we want stop something but use a message when something else happens? I can hardly remember any case where we use a cancellation message (unless it is passed automatically by stop() for example). |
Sorry, something went wrong.
Actor has info log because this log is important to see workflow. Log is printed only if msg is not None, to avoid log duplication (actor prints that it is cancelled in run method - and this log was useful many times.)
Background service has debug log, because info would log many misleading logs during normal runtime, which might be confusing. And those logs are only useful during debugging.