Deadlock when attempting to log to stdout

Development
1

Obviously this is a bad design that needs to be changed, nevertheless I thought its useful to report: If there is an attempt to do fputs(stdout, ....) on the audio thread, this might result in a deadlock, the only escape is to remove the instrument.

EDIT: It doesn’t seem to matter which thread is logging, any thread that logs might hit a deadlock sooner or later.

(gdb) bt
#0  __GI___libc_write (nbytes=51, buf=0x55562b4b8c60, fd=1) at ../sysdeps/unix/sysv/linux/write.c:26
#1  __GI___libc_write (fd=1, buf=buf@entry=0x55562b4b8c60, nbytes=nbytes@entry=51) at ../sysdeps/unix/sysv/linux/write.c:24
#2  0x00007fff45b967fc in _IO_new_file_write (f=0x7fff45cc15c0 <_IO_2_1_stdout_>, data=0x55562b4b8c60, n=51) at ./libio/fileops.c:1180
#3  0x00007fff45b95c0c in new_do_write
    (fp=0x7fff45cc15c0 <_IO_2_1_stdout_>, data=0x55562b4b8c60 "append@141: Received sysex: f0002033011071405f23f7\n, MHz: 128.9325 (113.8459 avg)\n\ned preset\n, mf=000082, pd=00000c, df=000001 => cycles per sample=462, predefined samplerate=144000\n\n", to_do=to_do@entry=51)
    at ./libio/libioP.h:947
#4  0x00007fff45b97840 in _IO_new_do_write (fp=<optimized out>, data=<optimized out>, to_do=51) at ./libio/fileops.c:425
#5  0x00007fff45b96e68 in _IO_new_file_xsputn (n=51, data=<optimized out>, f=0x7fff45cc15c0 <_IO_2_1_stdout_>) at ./libio/libioP.h:947
#6  _IO_new_file_xsputn (f=0x7fff45cc15c0 <_IO_2_1_stdout_>, data=<optimized out>, n=51) at ./libio/fileops.c:1196
#7  0x00007fff45b8b0d4 in __GI__IO_fputs (str=0x7ffeb011d5c0 "append@141: Received sysex: f0002033011071405f23f7\n", fp=0x7fff45cc15c0 <_IO_2_1_stdout_>) at ./libio/libioP.h:947
#8  0x00007fff40ebec8c in Logging::g_logToConsole(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) () at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#9  0x00007fff40e7d2c0 in virusLib::Hdi08TxParser::append(unsigned int) () at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#10 0x00007fff40e73bb8 in virusLib::Microcontroller::processHdi08Tx(std::vector<synthLib::SMidiEvent, std::allocator<synthLib::SMidiEvent> >&) () at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#11 0x00007fff40e740d4 in virusLib::Microcontroller::readMidiOut(std::vector<synthLib::SMidiEvent, std::allocator<synthLib::SMidiEvent> >&) () at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#12 0x00007fff40e554bc in virusLib::Device::process(std::array<float const*, 4ul> const&, std::array<float*, 12ul> const&, unsigned long, std::vector<synthLib::SMidiEvent, std::allocator<synthLib::SMidiEvent> > const&, std::vector<synthLib::SMidiEvent, std::allocator<synthLib::SMidiEvent> >&) () at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#13 0x00007fff40e89514 in synthLib::ResamplerInOut::process(std::array<float const*, 4ul> const&, std::array<float*, 12ul>&, std::vector<synthLib::SMidiEvent, std::allocator<synthLib::SMidiEvent> > const&, std::vector<synthLib::SMidiEvent, std::allocator<synthLib::SMidiEvent> >&, unsigned int, std::function<void (std::array<float const*, 4ul> const&, std::array<float*, 12ul> const&, unsigned long, std::vector<synthLib::SMidiEvent, std::allocator<synthLib::SMidiEvent> > const&, std::vector<synthLib::SMidiEvent, std::allocator<synthLib::SMidiEvent> >&)> const&) ()
    at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#14 0x00007fff40e86c40 in synthLib::Plugin::process(std::array<float const*, 4ul> const&, std::array<float*, 12ul> const&, unsigned long, float, float, bool) () at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#15 0x00007fff40de5694 in pluginLib::Processor::processBlock(juce::AudioBuffer<float>&, juce::MidiBuffer&) () at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#16 0x00007fff40d242d0 in juce::lv2_client::LV2PluginInstance::run(unsigned int) () at /usr/local/lib/lv2/OsTIrus.lv2/libOsTIrus.so
#17 0x000055560f39c51c in jalv_run ()
#18 0x000055560f398800 in jack_process_cb ()
#19 0x00007fff46a44138 in  () at /lib/aarch64-linux-gnu/libjack.so.0
#20 0x00007fff46a43df8 in  () at /lib/aarch64-linux-gnu/libjack.so.0
#21 0x00007fff46a62294 in  () at /lib/aarch64-linux-gnu/libjack.so.0
#22 0x00007fff45b9ee30 in start_thread (arg=0x7fffd8ed9f07) at ./nptl/pthread_create.c:442
#23 0x00007fff45c07adc in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:79
2 Likes
2

Yes! It’s a known “limitation”. There is a reason. We use “jalv” as plugin host and the zynthian UI comunicates with it using commands thru the tty, so if the hosted plugin writes to the tty (stdout), it will break the communication between the UI and the LV2 host. Until now, almost all plugins we have in the zynthian collection are totally silent in the stdout, so we rarely have found issues with this. Perhaps one or two times.

Anyway, it’s a limitation and we should work to improve it. Please, open an issue in our tracking system so this is not forgotten. We have to do some work with jalv integration in the next weeks/months, so we could take a look to this too. It should be workable.

Thanks for reporting.

1 Like
3

thanks, perfect explanation of what’s going on. Will do builds without any logging then.

Reported it here

2 Likes