rec / recs

🎬 recs: the Universal Recorder 🎬
MIT License
2 stars 1 forks source link

Intermittent C/C++ crashes when a Python exception is thrown in audio code #30

Closed rec closed 1 year ago

rec commented 1 year ago

I can't reproduce at this time but it happened while I was writing the end-to-end unit test

rec commented 1 year ago

Here's a traceback

-*- mode: compilation; default-directory: "/code/recs/" -*-
Compilation started at Mon Oct 16 16:20:52

NO_COLOR=1 d pytest -k end_to_end -s --log-cli-level=DEBUG
========================================== test session starts ===========================================
platform darwin -- Python 3.11.6, pytest-7.4.2, pluggy-1.3.0
rootdir: /Users/tom/synthetic/code/recs
collected 29 items / 28 deselected / 1 selected                                                          

test/test_end_to_end.py::test_end_to_end 
--------------------------------------------- live log call ----------------------------------------------
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: start: before
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: run: before
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: pre_run: before
DEBUG    root:thread.py:50 (HasThread)Thread-Ext: start: before
DEBUG    root:thread.py:50 (HasThread)Thread-Ext: run: before
DEBUG    root:thread.py:50 (HasThread)Thread-Mic: start: before
DEBUG    root:thread.py:50 (HasThread)Thread-Ext: pre_run: before
DEBUG    root:thread.py:50 (HasThread)Thread-Mic: run: before
DEBUG    root:thread.py:50 (HasThread)Thread-Mic: pre_run: before
DEBUG    root:thread.py:50 (HasThread)Thread-Ext: stop: before
DEBUG    root:thread.py:54 (HasThread)Thread-Ext: run: after
DEBUG    root:thread.py:50 (HasThread)Thread-Mic: stop: before
DEBUG    root:thread.py:54 (HasThread)Thread-Mic: run: after
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Ext: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Mic: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Mic: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Mic: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Ext: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Ext: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: stop: before
DEBUG    root:thread.py:50 (HasThread)Thread-Flower 8: stop: before
Fatal Python error: Segmentation fault

Current thread 0x000000016ce8b000 (most recent call first):
  File DEBUG    root:thread.py:50 (HasThread)Thread-Ext: stop: before
"/Users/tom/synthetic/code/recs/.direnv/python-3.11/lib/python3.11/site-packages/soundfile.py", line 1186 in close
  File "/Users/tom/synthetic/code/recs/recs/audio/channel_writer.py", line 68 in close
  File "/Users/tom/synthetic/code/recs/recs/ui/channel_recorder.py", line 41 in stop
  File "/Users/tom/synthetic/code/recs/recs/ui/device_recorder.py", line 110 in stop
  File "/Users/tom/synthetic/code/recs/recs/ui/device_recorder.py", line 95 in callback
  File "/Users/tom/synthetic/code/recs/recs/audio/device.py", line 51 in cb
  File "/Users/tom/synthetic/code/recs/test/conftest.py", line 95 in __callback
  File "/Users/tom/synthetic/code/recs/.direnv/python-3.11/lib/python3.11/site-packages/threa/thread.py", line 113 in run
  File "/Users/tom/synthetic/code/recs/.direnv/python-3.11/lib/python3.11/site-packages/threa/thread.py", line 51 in wrapped
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/threading.pyDEBUG    root:thread.py:50 (HasThread)Thread-Mic: stop: before
", line 982 in run
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/threading.py", line 1045 in _bootstrap_inner
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/threading.py", line 1002 in _bootstrap

Thread 0x0000000104a68580 (most recent call first):
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/contextlib.py", line 146 in __exit__
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.py", line 1230 in filter
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.py", line 978 in handle
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.py", line 1706 in callHandlers
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.py", line 1644 in handle
  File "/Library/Frameworks/Python.framework/Versions/3.11/lib/python3.11/logging/__init__.pyFAILED", line 851549824 in _log
  File time: command terminated abnormally
        0.98 real         0.68 user         1.73 sys

Compilation segmentation fault: 11 at Mon Oct 16 16:20:53
rec commented 1 year ago

I have managed to trigger this and other, different crashes, some more abrupt, dozens of times since I wrote this.

All of these new ones have been within soundfile which is only used in a comparatively small area of the code. The code above appears to happen with sounddevice, which I don't use in tests because it relies on hardware to exist, but I'm thinking now I should, for "integration tests", which might reveal this.

All of the soundfile crashs have been associated with shutdown of one type or another.

Occasionally, there's some sort of fault in normal shutdown, but most of the time, these happen when there's some other sort of exception thrown, which includes both unit test failures, and "expected" exceptions, where the code raises to report to the user that something is actually wrong (and gets caught at the top level and reported nicely).

My theory is that soundfile takes a chunk of memory to write to a file, but does not create a python reference for that chunk of memory, so in some cases it gets garbage collected while soundfile is writing, and it segfaults.

rec commented 1 year ago

The lock is a bit heavy-handed for my taste, but I don't believe it will have any visible ramifications, and it might prevent these crashes in the future. Unfortunately I was unable to come up with a way to reproduce these crashes to see if there's an effect, but I left a switch in the code for later experimentation.

rec commented 1 year ago

This has yet to reoccur since I put that change in.

Running the program and interrupting it a lot has not caused either of the two crashes to occur.

I'm going to close it for now, but my theory is that we'll see this again once the program gets out into the wild, if it ever does.