Trio's nursery lifetime interacts badly with start_action

[itamarst]

(Based on discussion in https://trio.discourse.group/t/eliot-the-causal-logging-library-now-supports-trio/167)

Consider:

from eliot import start_action, to_file
import trio

to_file(open("trio.log", "w"))


async def say(message, delay):
    with start_action(action_type="say", message=message):
        await trio.sleep(delay)

async def main():
    async with trio.open_nursery() as nursery:
        with start_action(action_type="main"):
            nursery.start_soon(say, "hello", 1)
            nursery.start_soon(say, "world", 2)

trio.run(main)

The result:

0ed1a1c3-050c-4fb9-9426-a7e72d0acfc7
└── main/1 ⇒ started 2019-04-26 13:01:13 ⧖ 0.000s
    └── main/2 ⇒ succeeded 2019-04-26 13:01:13

0ed1a1c3-050c-4fb9-9426-a7e72d0acfc7
└── <unnamed>
    ├── say/3/1 ⇒ started 2019-04-26 13:01:13 ⧖ 2.002s
    │   ├── message: world
    │   └── say/3/2 ⇒ succeeded 2019-04-26 13:01:15
    └── say/4/1 ⇒ started 2019-04-26 13:01:13 ⧖ 1.001s
        ├── message: hello
        └── say/4/2 ⇒ succeeded 2019-04-26 13:01:14

What happens is that the start_action finishes before the nursery schedules the say() calls, so they get logged after the action is finished. Putting the start_action outside the nursery lifetime fixes this.

Depending how you look at this this is either:

1. A problem with Trio integration.
2. A design flaw in the parser (notice that all those messages are actually the same tree, the parser just decides the tree is finished too early).
3. A general problem with async context managers/contextvars/how actions finish.

[itamarst]

The discussion above has some suggestions for solutions.

[itamarst]

Still think there should be some Trio-specific support, but adding a 10-second delay to the parser before it finishes up an action would probably catch most cases.