@log_async_call support for async functions

[jtrakk]

This could be a separate @log_async_call decorator or combined into the same @log_call. Here's an example of the combined version.

# XXX BROKEN Don't use this.
def log_call(
    wrapped_function: Optional[Callable] = None,
    action_type: Optional[str] = None,
    include_args: Optional[Iterable[str]] = None,
    include_result: bool = True,
) -> Callable:
    """Decorator/decorator factory that logs inputs and the return result.
    If used with inputs (i.e. as a decorator factory), it accepts the following
    parameters:
    @param action_type: The action type to use.  If not given the function name
        will be used.
    @param include_args: If given, should be a list of strings, the arguments to log.
    @param include_result: True by default. If False, the return result isn't logged.
    """
    if wrapped_function is None:
        return functools.partial(
            log_call,
            action_type=action_type,
            include_args=include_args,
            include_result=include_result,
        )

    if action_type is None:
        if six.PY3:
            action_type = "{}.{}".format(
                wrapped_function.__module__, wrapped_function.__qualname__
            )
        else:
            action_type = wrapped_function.__name__

    if six.PY3 and include_args is not None:
        from inspect import signature

        sig = signature(wrapped_function)
        if set(include_args) - set(sig.parameters):
            raise ValueError(
                (
                    "include_args ({}) lists arguments not in the " "wrapped function"
                ).format(include_args)
            )

    @functools.wraps(wrapped_function)
    def logging_wrapper(*args, **kwargs):
        bound_args = inspect.signature(wrapped_function).bind(*args, **kwargs)

        # Remove self if it's included:
        if "self" in bound_args.arguments:
            bound_args.arguments.pop("self")

        # Filter arguments to log, if necessary:
        if include_args is not None:
            bound_args.arguments = {k: bound_args.arguments[k] for k in include_args}

        with contextlib.ExitStack() as stack:
            ctx = stack.enter_context(
                eliot.start_action(action_type=action_type, **bound_args.arguments)
            )
            result = wrapped_function(*args, **kwargs)
            if not include_result:
                return result
            if isinstance(result, collections.abc.Coroutine):

                async def wrap_await(stack_dup):
                    with stack_dup:
                        actual_result = await result
                        ctx.add_success_fields(result=actual_result)
                        return actual_result

                return wrap_await(stack.pop_all())

            ctx.add_success_fields(result=result)
            return result

    return logging_wrapper

[itamarst]

Hm. Might want different decorator to reduce performance impact...

Are you actively using Eliot with async code, BTW? Does the coroutine support work well?

[jtrakk]

I've been trying Eliot in a small project with Trio, and they seem to be working quite well together so far.

[itamarst]

Huh. My expectation is that Eliot doesn't (yet) support coroutines in Trio (see #290), though I'm happy to add support when I have time.

[jtrakk]

Right, my log outputs are currently blocking writes.

[itamarst]

The issue isn't blocking writes, it's coroutine interleaving breaking the Eliot context. Possibly the method I use accidently works with Trio, or possibly you haven't hit that edge case yet: it would require a coroutine context switching inside a with start_action(): block to another coroutine.

[jtrakk]

Hmm, what should I notice if it's going wrong?

[itamarst]

Action A is started in coroutine 1. Coroutine 2 logs message M after A was started but before A ends. M is child of A.

Can probably check this by doing:

Coroutine 1: with start_action(): await sleep(30) Coroutine 2: await sleep(10); Message.log()

Presuming a Trio-specific sleep function which I assume it has.

[jtrakk]

Ah sure enough, the message appears as the child of the action.

import json

import eliot
import trio


def json_to_file(x):
    print(json.dumps(x))


async def do_action(x):
    with eliot.start_action(action_type="do_action", x=x):
        await trio.sleep(30)


async def do_message(y):
    await trio.sleep(10)
    eliot.Message.log(message_type="do_message", y=y)


async def async_main():
    async with trio.open_nursery() as nursery:
        nursery.start_soon(do_action, "first-object")
        nursery.start_soon(do_message, "second-object")


def main():
    eliot.add_destinations(json_to_file)
    trio.run(async_main)


if __name__ == "__main__":
    main()


# {"timestamp": 1553481014.7285504, "task_uuid": "5a6c82aa-a9ee-49dd-a3f7-f5ed7b09df0a", "task_level": [1], "x": "first-object", "action_status": "started", "action_type": "do_action"}
# {"timestamp": 1553481014.728725, "task_uuid": "5a6c82aa-a9ee-49dd-a3f7-f5ed7b09df0a", "task_level": [2], "action_status": "succeeded", "action_type": "do_action"}
# {"timestamp": 1553481014.7287977, "task_uuid": "fc5285a2-94b1-4d9f-b70c-d32ad7b2bcae", "task_level": [1], "message_type": "do_message", "y": "second-object"}


# bffdae44-4438-47ae-9f6a-a40d4128ca86
# └── do_action/1 ⇒ started 2019-03-25 02:30:44 ⧖ 30.065s
#     ├── x: first-object
#     ├── do_message/2 2019-03-25 02:30:54
#     │   └── y: second-object
#     └── do_action/3 ⇒ succeeded 2019-03-25 02:31:14

[jtrakk]

The code I posted at the top of this issue is broken and it's too hard to understand. I'm using a separate @log_async_call, which is better.

[itamarst]

In case someone (me?) wants to do this with single API, one can check if callable is async by doing inspect.iscoroutinefunction(o) or inspect.coroutinefunction(o.__call__) (the latter handles classes with async __call__.)