Open jtrakk opened 5 years ago
Hm. Might want different decorator to reduce performance impact...
Are you actively using Eliot with async code, BTW? Does the coroutine support work well?
I've been trying Eliot in a small project with Trio, and they seem to be working quite well together so far.
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.
Right, my log outputs are currently blocking writes.
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.
Hmm, what should I notice if it's going wrong?
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.
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
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.
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__
.)
This could be a separate
@log_async_call
decorator or combined into the same@log_call
. Here's an example of the combined version.