Invocation context variables

[rwb27]

This pull request introduces two new top-level functions:

• lt.cancellable_sleep(interval) is equivalent to time.sleep but may raise InvocationCancelledError to stop the action.
• lt.get_invocation_logger() supplies a logging.Logger object that captures logs specific to the current invocation.

Together, these two functions remove the need for the InvocationLogger and CancelHook dependencies, completing the third phase of #182 .

import labthings_fastapi as lt

class Counter(lt.Thing):
    """An example counter Thing."""

    index: int = lt.property(default=0)

    @lt.thing_action
    def count(self, n: int, dt: float) -> None:
        "Count slowly and log about it."
        logger = lt.get_invocation_logger()
        for i in range(n):
            lt.cancellable_sleep(dt)  # If the action is cancelled, an exception is raised here to terminate it
            self.index += 1
            logger.info(f"Counted to {self.index}")  # This appears if the action is polled

I have also added lt.ThreadWithInvocationID (name might want to change) which is a subclass of threading.Thread that supplies an invocation ID. This allows an action to be run in a background thread without errors because it's missing an invocation ID context. It also allows the thread to be cancelled.

This is mostly implemented with one new module, invocation_contexts. I've moved CancelEvent from the invocation dependencies module into the new module, and the dependencies now use invocation_contexts so they still work.

The one place where dependencies are still used is in generating invocation IDs for actions that are invoked over HTTP. Because of the way FastAPI's dependency mechanism works, I can't get rid of this without breaking both of the dependencies mentioned above. I intend to leave them in for now to facilitate migration, but the whole module will be deleted before too long.

I have written new, bottom-up unit tests in test_invocation_contexts (with 100% coverage of the new module) and have also migrated test_action_cancellation and test_action_logging to use the new API. The old tests are preserved in a submodule, along with other dependency-related tests.

I've deliberately not exposed all the functions at top-level in the module: I think the two functions and one class I've exposed are the API we want people to use. I should make fake_action_context visible, most likely in a test module, so one could say from labthings_fastapi.testing import fake_action_context. That would be a natural home for create_thing_without_server and maybe a few other things.

[barecheck]

Barecheck - Code coverage report

Total: 94.17%

Your code coverage diff: 0.36% ▴

Uncovered files and lines

File	Lines
src/labthings_fastapi/actions/__init__.py	145-146, 438-439, 567-568, 581, 606-607
src/labthings_fastapi/descriptors/action.py	126, 130, 303-304, 307, 310, 359

[rwb27]

After reading the logging docs I think our current approach of creating a new logger name for every invocation is explicitly discouraged (because loggers don't get garbage collected). I think a good solution would be to use a filter to add context information to the LogRecord and a custom handler to append logs to the right invocation object, if needed.

This would result in a property Thing.logger that returns a logger named for a particular Thing instance, so instead of needing an invocation logger that's specific to one invocation, we'd simply call self.logger.info("message").

A side effect of this approach is that I no longer think it's reasonable to raise an exception if the logger is used without the invocation context variable being set: exceptions in logging code are usually unhelpful. If the logger is used from outside an action, the log message should still be logged, but without the invocation context data.

In the future, it would be nice to think more about how to relay progress to a user/client. I think our current use of a logger for this has some advantages, but also some drawbacks.

[rwb27]

After discussing with @julianstirling and @bprobert97 I think logs should go via Thing.logger as described above, and the jury's out on whether we should make cancellable_sleep be a method of Thing or a module-level method. If it's a module-level method, the conclusion was that it shouldn't raise an error if it was called outside of an invocation thread, so that code can be tested without overriding things.

@julianstirling was also strongly in favour of adding a second function with a descriptive name, rather than cancellable_sleep(None) to check for cancellation without waiting.

[julianstirling]

I think I understand this a bit more than the last two.

I think the upshot of this reviewing is that it is very hard to keep 4 complex PRs that interact in my head. I think it would be good once we have merged the 3 later PRs into the base one, to do a final review of #183

[julianstirling]

I assume this would have meant that invocation loggers the old way wouldn't work? But this is superseded I think by #191

[julianstirling]

This is unhelpful when reading tests.