perpetuo icon indicating copy to clipboard operation
perpetuo copied to clipboard
verified publisher icon njsmith

Add json logging to perpetuo

Open rohitmittapalli opened this issue 1 year ago • 1 comments

Did not change any of the message statements. Added json logging for GKE compatibility and jq parsing.

  1. pip uninstall perpetuo
  2. pip install /Users/rohit/code/perpetuo
  3. python example.py
  4. sudo perpetuo watch 44262 & sudo perpetuo --json-mode watch 95271

rohitmittapalli avatar Aug 21 '24 02:08 rohitmittapalli

Before changes

Attempting to monitor pid 93708...
Successfully monitoring pid 93708
Trio run loop (thread 0x1_ead2_cf40) stall detected in process 93708 for at least 214.87875ms
command line: ["python3", "example.py"]
This thread is probably responsible:

    Thread 1ead2cf40 (active)
        <module> (/Users/rohit/code/perpetuo/example.py:43)
        run (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_run.py:2295)
            async_fn = <function at 0x104ea1120>
            clock = None
            instruments = ()
            restrict_keyboard_interrupt_to_checkpoints = False
            strict_exception_groups = True
            args = ()
            __tracebackhide__ = True
            runner = <Runner at 0x1049c2340>
            prev_library = None
            gen = <generator at 0x104968ee0>
            next_send = []
            timeout = 0.9998109580192249
        unrolled_run (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_run.py:2621)
            runner = <Runner at 0x1049c2340>
            async_fn = <function at 0x104ea1120>
            args = ()
            host_uses_signal_set_wakeup_fd = False
            __tracebackhide__ = True
            timeout = 0.9998109580192249
            deadline = 148750.44608390727
            idle_primed = None
            events = []
            now = 148751.45236453228
            task = <Task at 0x104ea1bc0>
            batch = []
            next_send_fn = <builtin_function_or_method at 0x104eae570>
            next_send = <Error at 0x104eba000>
            final_outcome = None
        main (/Users/rohit/code/perpetuo/example.py:40)
            some_local = {"a": 1}
            another_local = 3
            thread = <_MainThread at 0x103415250>
            nursery = <Nursery at 0x104eb8c90>
        foo (/Users/rohit/code/perpetuo/example.py:18)
        naughty (/Users/rohit/code/perpetuo/example.py:14)

Other threads (probably not responsible):

    Thread 16e7d3000 (active)
        _bootstrap (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py:1002)
            self = <Thread at 0x104eb98d0>
        _bootstrap_inner (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py:1045)
            self = <Thread at 0x104eb98d0>
        run (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py:982)
            self = <Thread at 0x104eb98d0>
        _work (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_thread_cache.py:186)
            self = <WorkerThread at 0x104eb96d0>
        _handle_job (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_thread_cache.py:163)
            self = <WorkerThread at 0x104eb96d0>
            fn = <function at 0x104ea2980>
            deliver = <function at 0x104ea2a20>
            name = "gil_naughty from trio.to_thread.run_sync"
        capture (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/outcome/_impl.py:67)
            sync_fn = <function at 0x104ea2980>
            args = ()
            kwargs = {}
        worker_fn (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_threads.py:382)
        gil_naughty (/Users/rohit/code/perpetuo/example.py:24)
            test_local = "hello"

Trio run loop (thread 0x1_ead2_cf40) stall detected in process 93708 for at least 276.428208ms
  (no traceback due to rate-limiting)
Trio run loop (thread 0x1_ead2_cf40) stall detected in process 93708 for at least 331.517792ms
  (no traceback due to rate-limiting)
Trio run loop (thread 0x1_ead2_cf40) stall detected in process 93708 for at least 386.689625ms
  (no traceback due to rate-limiting)
Trio run loop (thread 0x1_ead2_cf40) stall detected in process 93708 for at least 441.8685ms
  (no traceback due to rate-limiting)
Trio run loop (thread 0x1_ead2_cf40) stall detected in process 93708 for at least 495.887167ms
  (no traceback due to rate-limiting)

After changes, json_mode = False

[Info] Attempting to monitor pid 96303...
  pid: 96303
[Info] Successfully monitoring pid 96303
  pid: 96303
[Warning] Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 215.920167ms
  name: Trio run loop (thread 0x1_ead2_cf40)
  duration: 215.920167ms
  pid: 96303
[Info] command line: ["python3", "example.py"]
[Warning] This thread is probably responsible:
  name: Trio run loop (thread 0x1_ead2_cf40)
  duration: 215.920167ms
  pid: 96303
[Info] Thread 1ead2cf40
  owns_gil: false
  thread_id: 1ead2cf40
  status: active
Traceback:
        <module> (/Users/rohit/code/perpetuo/example.py:43)
        run (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_run.py:2295)
            async_fn = <function at 0x105c85120>
            clock = None
            instruments = ()
            restrict_keyboard_interrupt_to_checkpoints = False
            strict_exception_groups = True
            args = ()
            __tracebackhide__ = True
            runner = <Runner at 0x104f62340>
            prev_library = None
            gen = <generator at 0x104f08ee0>
            next_send = []
            timeout = 0.9997402910084929
        unrolled_run (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_run.py:2621)
            runner = <Runner at 0x104f62340>
            async_fn = <function at 0x105c85120>
            args = ()
            host_uses_signal_set_wakeup_fd = False
            __tracebackhide__ = True
            timeout = 0.9997402910084929
            deadline = 182906.67389334284
            idle_primed = None
            events = []
            now = 182906.67501138482
            task = <Task at 0x105c85bc0>
            batch = []
            next_send_fn = <builtin_function_or_method at 0x105c926b0>
            next_send = <Error at 0x105c9e280>
            final_outcome = None
        main (/Users/rohit/code/perpetuo/example.py:40)
            some_local = {"a": 1}
            another_local = 3
            thread = <_MainThread at 0x104a15290>
            nursery = <Nursery at 0x105c9d010>
        foo (/Users/rohit/code/perpetuo/example.py:18)
        naughty (/Users/rohit/code/perpetuo/example.py:14)
[Info] Other threads (probably not responsible):
  name: Trio run loop (thread 0x1_ead2_cf40)
  duration: 215.920167ms
  pid: 96303
[Info] Thread 16e333000
  thread_id: 16e333000
  status: active+gil
  owns_gil: true
Traceback:
        _bootstrap (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py:1002)
            self = <Thread at 0x105c9d990>
        _bootstrap_inner (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py:1045)
            self = <Thread at 0x105c9d990>
        run (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py:982)
            self = <Thread at 0x105c9d990>
        _work (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_thread_cache.py:186)
            self = <WorkerThread at 0x105c9d850>
        _handle_job (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_thread_cache.py:163)
            self = <WorkerThread at 0x105c9d850>
            fn = <function at 0x105c86980>
            deliver = <function at 0x105c86a20>
            name = "gil_naughty from trio.to_thread.run_sync"
        capture (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/outcome/_impl.py:67)
            sync_fn = <function at 0x105c86980>
            args = ()
            kwargs = {}
        worker_fn (/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_threads.py:382)
        gil_naughty (/Users/rohit/code/perpetuo/example.py:25)
            test_local = "hello"
[Warning] Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 279.114125ms
  name: Trio run loop (thread 0x1_ead2_cf40)
  pid: 96303
  duration: 279.114125ms
[Warning] No traceback due to rate-limiting for pid 96303
  name: Trio run loop (thread 0x1_ead2_cf40)
  pid: 96303
  duration: 279.114125ms

After changes, json_mode = True

{"severity":"INFO","message":"Attempting to monitor pid 96303...","additional_info":{"pid":"96303"}}
{"severity":"INFO","message":"Successfully monitoring pid 96303","additional_info":{"pid":"96303"}}
{"severity":"WARNING","message":"Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 218.035792ms","additional_info":{"duration":"218.035792ms","name":"Trio run loop (thread 0x1_ead2_cf40)","pid":"96303"}}
{"severity":"INFO","message":"command line: [\"python3\", \"example.py\"]"}
{"severity":"WARNING","message":"This thread is probably responsible:","additional_info":{"duration":"218.035792ms","name":"Trio run loop (thread 0x1_ead2_cf40)","pid":"96303"}}
{"severity":"INFO","message":"Thread 1ead2cf40","additional_info":{"status":"active","thread_id":"1ead2cf40","owns_gil":"false"},"traceback":[{"name":"<module>","filename":"/Users/rohit/code/perpetuo/example.py","line":43,"locals":[]},{"name":"run","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_run.py","line":2295,"locals":[{"name":"async_fn","value":"<function at 0x105c85120>"},{"name":"clock","value":"None"},{"name":"instruments","value":"()"},{"name":"restrict_keyboard_interrupt_to_checkpoints","value":"False"},{"name":"strict_exception_groups","value":"True"},{"name":"args","value":"()"},{"name":"__tracebackhide__","value":"True"},{"name":"runner","value":"<Runner at 0x104f62340>"},{"name":"prev_library","value":"None"},{"name":"gen","value":"<generator at 0x104f08ee0>"},{"name":"next_send","value":"[]"},{"name":"timeout","value":"0.9999342919909395"}]},{"name":"unrolled_run","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_run.py","line":2621,"locals":[{"name":"runner","value":"<Runner at 0x104f62340>"},{"name":"async_fn","value":"<function at 0x105c85120>"},{"name":"args","value":"()"},{"name":"host_uses_signal_set_wakeup_fd","value":"False"},{"name":"__tracebackhide__","value":"True"},{"name":"timeout","value":"0.9999342919909395"},{"name":"deadline","value":"182980.95061792684"},{"name":"idle_primed","value":"None"},{"name":"events","value":"[]"},{"name":"now","value":"182980.9517225098"},{"name":"task","value":"<Task at 0x105c85bc0>"},{"name":"batch","value":"[]"},{"name":"next_send_fn","value":"<builtin_function_or_method at 0x105c926b0>"},{"name":"next_send","value":"<Error at 0x105c9eec0>"},{"name":"final_outcome","value":"None"}]},{"name":"main","filename":"/Users/rohit/code/perpetuo/example.py","line":40,"locals":[{"name":"some_local","value":"{\"a\": 1}"},{"name":"another_local","value":"3"},{"name":"thread","value":"<_MainThread at 0x104a15290>"},{"name":"nursery","value":"<Nursery at 0x105c9d010>"}]},{"name":"foo","filename":"/Users/rohit/code/perpetuo/example.py","line":18,"locals":[]},{"name":"naughty","filename":"/Users/rohit/code/perpetuo/example.py","line":14,"locals":[]}]}
{"severity":"INFO","message":"Other threads (probably not responsible):","additional_info":{"duration":"218.035792ms","name":"Trio run loop (thread 0x1_ead2_cf40)","pid":"96303"}}
{"severity":"INFO","message":"Thread 16e333000","additional_info":{"thread_id":"16e333000","status":"active+gil","owns_gil":"true"},"traceback":[{"name":"_bootstrap","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py","line":1002,"locals":[{"name":"self","value":"<Thread at 0x105c9d990>"}]},{"name":"_bootstrap_inner","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py","line":1045,"locals":[{"name":"self","value":"<Thread at 0x105c9d990>"}]},{"name":"run","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/threading.py","line":982,"locals":[{"name":"self","value":"<Thread at 0x105c9d990>"}]},{"name":"_work","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_thread_cache.py","line":186,"locals":[{"name":"self","value":"<WorkerThread at 0x105c9d850>"}]},{"name":"_handle_job","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_core/_thread_cache.py","line":163,"locals":[{"name":"self","value":"<WorkerThread at 0x105c9d850>"},{"name":"fn","value":"<function at 0x105c86980>"},{"name":"deliver","value":"<function at 0x105c86a20>"},{"name":"name","value":"\"gil_naughty from trio.to_thread.run_sync\""}]},{"name":"capture","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/outcome/_impl.py","line":67,"locals":[{"name":"sync_fn","value":"<function at 0x105c86980>"},{"name":"args","value":"()"},{"name":"kwargs","value":"{}"}]},{"name":"worker_fn","filename":"/opt/homebrew/Caskroom/miniforge/base/envs/py311/lib/python3.11/site-packages/trio/_threads.py","line":382,"locals":[]},{"name":"gil_naughty","filename":"/Users/rohit/code/perpetuo/example.py","line":25,"locals":[{"name":"test_local","value":"\"hello\""}]}]}
{"severity":"WARNING","message":"Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 275.823667ms","additional_info":{"duration":"275.823667ms","pid":"96303","name":"Trio run loop (thread 0x1_ead2_cf40)"}}
{"severity":"WARNING","message":"No traceback due to rate-limiting for pid 96303","additional_info":{"duration":"275.823667ms","pid":"96303","name":"Trio run loop (thread 0x1_ead2_cf40)"}}
{"severity":"WARNING","message":"Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 327.691292ms","additional_info":{"pid":"96303","duration":"327.691292ms","name":"Trio run loop (thread 0x1_ead2_cf40)"}}
{"severity":"WARNING","message":"No traceback due to rate-limiting for pid 96303","additional_info":{"pid":"96303","duration":"327.691292ms","name":"Trio run loop (thread 0x1_ead2_cf40)"}}
{"severity":"WARNING","message":"Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 379.769584ms","additional_info":{"duration":"379.769584ms","name":"Trio run loop (thread 0x1_ead2_cf40)","pid":"96303"}}
{"severity":"WARNING","message":"No traceback due to rate-limiting for pid 96303","additional_info":{"duration":"379.769584ms","name":"Trio run loop (thread 0x1_ead2_cf40)","pid":"96303"}}
{"severity":"WARNING","message":"Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 434.412584ms","additional_info":{"name":"Trio run loop (thread 0x1_ead2_cf40)","duration":"434.412584ms","pid":"96303"}}
{"severity":"WARNING","message":"No traceback due to rate-limiting for pid 96303","additional_info":{"name":"Trio run loop (thread 0x1_ead2_cf40)","duration":"434.412584ms","pid":"96303"}}
{"severity":"WARNING","message":"Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 488.097292ms","additional_info":{"name":"Trio run loop (thread 0x1_ead2_cf40)","pid":"96303","duration":"488.097292ms"}}
{"severity":"WARNING","message":"No traceback due to rate-limiting for pid 96303","additional_info":{"name":"Trio run loop (thread 0x1_ead2_cf40)","pid":"96303","duration":"488.097292ms"}}
{"severity":"WARNING","message":"Trio run loop (thread 0x1_ead2_cf40) stall detected in process 96303 for at least 543.162167ms","additional_info":{"pid":"96303","duration":"543.162167ms","name":"Trio run loop (thread 0x1_ead2_cf40)"}}

JSON view of a line w/traceback: image

rohitmittapalli avatar Sep 24 '24 21:09 rohitmittapalli

CI failure is spurious and fixed by b2983aa191eb089b0f23bb813784c7efd0133cdb

njsmith avatar Oct 17 '24 03:10 njsmith