Program gets stuck in reader.stop_reading()

[HanYangZhao]

I'm testing the program by repeating reader.start_reading() and reader.stop_reading(). At some point (few minutes or few hours), reader.stop_reading() will not return resulting in the program getting stuck. I was unable to replicate the problem with a pure C implementation, so, there is something going on with the way python threads is mixed with c threads. Using gdb I was able to confirm that one of the c threads gets stuck

30 Jun 06:45:18 2020 - initializeReader
30 Jun 06:45:18 2020 - stopping current reader
stopping_read
read_callback_null
stats_callback_null
stopping_read_cs
read_callback
^C
Thread 1 "python3" received signal SIGINT, Interrupt.
__libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
46      ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S: No such file or directory.
(gdb) info thread
  Id   Target Id         Frame 
* 1    Thread 0x76fee210 (LWP 3019) "python3" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  2    Thread 0x769b3460 (LWP 3025) "python3" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  3    Thread 0x75fff460 (LWP 3026) "python3" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
  4    Thread 0x757fe460 (LWP 3027) "python3" __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
(gdb) bt 
#0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
#1  0x76ec3072 in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x3f22b4) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#2  __pthread_cond_wait_common (abstime=0x0, mutex=0x3f21e0, cond=0x3f2288) at pthread_cond_wait.c:502
#3  __pthread_cond_wait (cond=0x3f2288, mutex=0x3f21e0) at pthread_cond_wait.c:655
#4  0x76b6757a in TMR_stopReading (reader=0x3f10e0) at tm_reader_async.c:387
#5  0x76b5fab0 in Reader_stop_reading (self=0x3f10d8) at mercury.c:976
#6  0x0009ffb2 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)
(gdb) thread 4
[Switching to thread 4 (Thread 0x757fe460 (LWP 3027))]
#0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
46      in ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S
(gdb) bt
#0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
#1  0x76ec5194 in futex_abstimed_wait_cancelable (private=0, abstime=0x0, expected=1, futex_word=0x3f21a8) at ../sysdeps/unix/sysv/linux/futex-internal.h:205
#2  do_futex_wait (sem=sem@entry=0x3f21a8, abstime=0x0) at sem_waitcommon.c:115
#3  0x76ec5274 in __new_sem_wait_slow (sem=0x3f21a8, abstime=0x0) at sem_waitcommon.c:282
#4  0x76b6839e in process_async_response (reader=0x3f10e0) at tm_reader_async.c:977
#5  0x76b689b2 in do_background_reads (arg=0x3f10e0) at tm_reader_async.c:1218

tm_reader_async.c:1218  -> process_async_response(reader);
tm_reader_async.c:977 -> sem_wait(&reader->queue_slots);

[kmauser]

I'm experiencing a similar situation on Windows; program hangs sometimes when stop_reading() is called. The reader stops, but the program never returns. It's easy to make happen when doing a repeated sequence of start_reading(), delay for a few seconds, and then stop_reading(). I built python-mercury module from source using Mercury API 1.35.

[charlescochran]

I ran into this issue as well. After much work with gdb, I discovered the issue and implemented a fix (see the PR I just opened). Here is my commit message explaining the isse:

As of mercuryapi-1.31.4.35, when tm_reader_async.c's TMR_stopReading()
is called by Reader_stop_reading(), it ultimately ends up waiting for
reader->readState to become TMR_READ_STATE_DONE while holding the GIL.
This happens in tm_reader_async.c's do_background_reads(), but not until
the tag queue is emptied by read callbacks. These are triggered by
invoke_read_callback(), but this function blocks until it can acquire
the GIL. This frequently results in deadlock upon attempting to stop an
asynchronous read.

Previously, this was partially addressed by temporarily setting
self->readCallback (and self->statsCallback) to NULL in
Reader_stop_reading(), but this causes a SEGV in invoke_read_callback()
if it occurs after self->readCallback is verified to not be NULL but
before it is called. Instead of temporarily setting these function
pointers to NULL, release the GIL in Reader_stop_reading(), allowing
invoke_read_callback() to empty the tag queue and thereby avoiding
deadlock. Then, use a mutex to prevent concurrent calls to
TMR_stopReading(), since this was previously prevented by the GIL.

Temporarily setting self->statsCallback to NULL in Reader_stop_reading()
also prevented stats callbacks from occurring in subsequent asynchronous
reads. This functionality is now fixed.

[natcl]

Very nice ! We've been waiting for a fix for this for a long time, will try it out, hope this gets merged !
Thanks !

[gotthardp]

Thanks a lot for your effort, @charlescochran!

@natcl, please let me know whether the fix works for you as well. I will merge it then.

[natcl]

Thanks, it might take a little while before we can test but I'll let you know !

[natcl]

@charlescochran I tried your pull request and I'm still getting a freeze on stopReading after a couple of minutes of calling it in a loop (every 4 seconds)
Were you able to test it over a long period of time on you side ?

[charlescochran]

Hmm. I have been regularly testing it over long periods of time and it has been not freezing.

Perhaps you are encountering a separate bug. Can you run your program using gdb? If so, when the hang happens, please hit Ctrl-C, do a bt, and paste the result here.

[natcl]

Thanks will do !

[natcl]

itp@itp-master:/usr/tpm/bin$ gdb python3
GNU gdb (Ubuntu 8.1.1-0ubuntu1) 8.1.1
Copyright (C) 2018 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "arm-linux-gnueabihf".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<http://www.gnu.org/software/gdb/bugs/>.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from python3...(no debugging symbols found)...done.
(gdb) run uhfReader.py
Starting program: /usr/bin/python3 uhfReader.py
Cannot parse expression `.L1207 4@r4'.
warning: Probes-based dynamic linker interface failed.
Reverting to original interface.

[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/arm-linux-gnueabihf/libthread_db.so.1".
03 Jun 23:47:11 2022 - Starting ThingMagic reader
[New Thread 0x7683c460 (LWP 21173)]
03 Jun 23:47:11 2022 - Heartbeat started
03 Jun 23:47:11 2022 - initializeReader
03 Jun 23:47:11 2022 - stopReading: Reading was already stopped
03 Jun 23:47:11 2022 - Creating new reader on port tmr:///dev/ttymxc0
03 Jun 23:47:11 2022 - {"command": "initializeReader", "antennaPort": 1, "readPower": [[1, 2000], [2, 2000]], "region": "JP", "readerInitialized": true, "fwVersion": "01.0B.04.04-20.20.02.13-BL12.12.13.00", "serialNb": "3618527017600UM+", "readState": "TMR_READ_STATE_IDLE"}
03 Jun 23:47:11 2022 - startReading at 50 50 duty cycle
[New Thread 0x75eff460 (LWP 21181)]
[New Thread 0x756fe460 (LWP 21182)]
03 Jun 23:48:17 2022 - stopReading
^C
Thread 1 "python3" received signal SIGINT, Interrupt.
__libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
46      ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S: No such file or directory.
(gdb) bt
#0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
#1  0x76f770d4 in __libc_recvfrom (fd=4, buf=0x7601b018, len=131072, flags=0, addr=..., addrlen=0x7effee38) at ../sysdeps/unix/sysv/linux/recvfrom.c:27
#2  0x0002d2f2 in ?? ()
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

[natcl]

I think I might have something missing to get the full stack ?

[natcl]

Ah I installed ionotify and it seems better, new log coming soon

[natcl]

That seems better:

04 Jun 00:05:17 2022 - initializeReader
04 Jun 00:05:17 2022 - stopReading: Reading was already stopped
04 Jun 00:05:17 2022 - {"command": "initializeReader", "antennaPort": 1, "readPower": [[1, 2000], [2, 2000]], "region": "JP", "readerInitialized": true, "fwVersion": "01.0B.04.04-20.20.02.13-BL12.12.13.00", "serialNb": "3618527017600UM+", "readState": "TMR_READ_STATE_DONE"}
04 Jun 00:05:17 2022 - startReading at 50 50 duty cycle
04 Jun 00:05:21 2022 - stopReading
04 Jun 00:05:25 2022 - initializeReader
04 Jun 00:05:25 2022 - stopReading: Reading was already stopped
04 Jun 00:05:25 2022 - {"command": "initializeReader", "antennaPort": 1, "readPower": [[1, 2000], [2, 2000]], "region": "JP", "readerInitialized": true, "fwVersion": "01.0B.04.04-20.20.02.13-BL12.12.13.00", "serialNb": "3618527017600UM+", "readState": "TMR_READ_STATE_DONE"}
04 Jun 00:05:25 2022 - startReading at 50 50 duty cycle
04 Jun 00:05:29 2022 - stopReading
04 Jun 00:05:33 2022 - initializeReader
04 Jun 00:05:33 2022 - stopReading: Reading was already stopped
04 Jun 00:05:33 2022 - {"command": "initializeReader", "antennaPort": 1, "readPower": [[1, 2000], [2, 2000]], "region": "JP", "readerInitialized": true, "fwVersion": "01.0B.04.04-20.20.02.13-BL12.12.13.00", "serialNb": "3618527017600UM+", "readState": "TMR_READ_STATE_DONE"}
04 Jun 00:05:33 2022 - startReading at 50 50 duty cycle
^C
Thread 1 "python3" received signal SIGINT, Interrupt.
__libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
46      ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S: No such file or directory.
(gdb) bt
#0  __libc_do_syscall () at ../sysdeps/unix/sysv/linux/arm/libc-do-syscall.S:46
#1  0x76ec308e in futex_wait_cancelable (private=<optimized out>, expected=0, futex_word=0x3a382c) at ../sysdeps/unix/sysv/linux/futex-internal.h:88
#2  __pthread_cond_wait_common (abstime=0x0, mutex=0x3a3758, cond=0x3a3800) at pthread_cond_wait.c:502
#3  __pthread_cond_wait (cond=0x3a3800, mutex=0x3a3758) at pthread_cond_wait.c:655
#4  0x769f8682 in TMR_stopReading () from /usr/lib/python3/dist-packages/mercury.cpython-36m-arm-linux-gnueabihf.so
#5  0x769f371c in ?? () from /usr/lib/python3/dist-packages/mercury.cpython-36m-arm-linux-gnueabihf.so
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

[charlescochran]

Interesting. Please run git log --oneline and paste the result.

[natcl]

Oh you want to verify if I'm running the correct code ?
I'm not actually running this from a Git repo, it's packaged as a Debian file with other things.
Let me check on my side to confirm I'm running your branch.

[charlescochran]

I want to verify that, and also that you have the other latest commits on master. There have been 6 commits since the latest release. I think I remember the latest release having bugs that were fixed by them. My branch is on the latest master rather than the latest release, so as long as you are not cherry-picking it, you should also have those bug fixes as well (assuming you are running my branch, of course).