search

adameus03 / LabMate

Lab asset management systems prototype
0 stars 0 forks source link

UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY assertion fails #21

Open adameus03 opened 3 days ago

adameus03 commented 3 days ago

This assertion failure occurs sometimes when repeatedly measuring a tag via while true; do echo -n '10000 15' > driver/measure && echo "$(cat read_rate) $(cat rssi)"; done

[DEBUG] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/main.c:937): Write /uhf0/driver/measure: tx_p_val=15.000000
[INFO] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/uhfd.c:552): uhfd_measure_dev requested for devno 0
[DEBUG] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/uhfd.c:589): uhfd_measure_dev: Setting select parameters
[VERBOSE] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:476): Sending frame: 0xAA 0x00 0x0C 0x00 0x13 0x81 0x00 0x00 0x00 0x20 0x60 0x00 0x43 0x43 0x43 0x43 0x43 0x43 0x43 0x43 0x43 0x43 0x43 0x43 0x44 0xDD 
[VERBOSE] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:258): Received prolog: 0xAA 0x01 0x0C 0x00 0x01 
[VERBOSE] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:312): Received param data: 0x00 
[VERBOSE] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:363): Received epilog: 0x0E 0xDD 
[DEBUG] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:377): Received frame: 0xAA 0x01 0x0C 0x00 0x01 0x00 0x0E 0xDD 
[VERBOSE] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:397): Checksum OK
[DEBUG] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/uhfd.c:596): uhfd_measure_dev: Setting query parameters
[DEBUG] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/uhfd.c:603): uhfd_measure_dev: Setting select mode
[DEBUG] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/uhfd.c:610): uhfd_measure_dev: Setting transmit power
[INFO] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/uhfman.c:873): Transmit power level already set to: 15.00 dBm
[VERBOSE] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:476): Sending frame: 0xAA 0x00 0x27 0x00 0x03 0x22 0xFF 0xFF 0x4A 0xDD 
[DEBUG] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:979): Waiting for 0x27 notification frame...
[WARN] 2024-11-28 14:37:36  (/home/mundus/base/sem7/LabMate/rscs/ypdr200.c:230): Error polling for response prolog: poll_rv=0
rscs: /home/mundus/base/sem7/LabMate/rscs/uhfman.c:1197: uhfman_multiple_polling_stop: Assertion `(pCtx->_config.flags & (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY) == (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY' failed.

Thread 3 "rscs" received signal SIGABRT, Aborted.
[Switching to Thread 0x7ffff74326c0 (LWP 1419666)]
__pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, 
    no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
44      ./nptl/pthread_kill.c: No such file or directory.
(gdb) 
(gdb) 
(gdb) bt
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, 
    no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44
#1  0x00007ffff7dc2e9f in __pthread_kill_internal (signo=6, threadid=<optimized out>)
    at ./nptl/pthread_kill.c:78
#2  0x00007ffff7d73fb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x00007ffff7d5e472 in __GI_abort () at ./stdlib/abort.c:79
#4  0x00007ffff7d5e395 in __assert_fail_base (
    fmt=0x7ffff7ed2a90 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", 
    assertion=assertion@entry=0x555555589df0 "(pCtx->_config.flags & (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY) == (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY", 
    file=file@entry=0x555555589580 "/home/mundus/base/sem7/LabMate/rscs/uhfman.c", 
    line=line@entry=1197, 
    function=function@entry=0x55555558a2a0 <__PRETTY_FUNCTION__.2> "uhfman_multiple_polling_stop") at ./assert/assert.c:92
#5  0x00007ffff7d6ceb2 in __GI___assert_fail (
    assertion=0x555555589df0 "(pCtx->_config.flags & (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY) == (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY", 
    file=0x555555589580 "/home/mundus/base/sem7/LabMate/rscs/uhfman.c", line=1197, 
    function=0x55555558a2a0 <__PRETTY_FUNCTION__.2> "uhfman_multiple_polling_stop")
    at ./assert/assert.c:101
#6  0x0000555555563901 in uhfman_multiple_polling_stop (
    pCtx=0x55555559d488 <__main_globals+5960>)
    at /home/mundus/base/sem7/LabMate/rscs/uhfman.c:1197
#7  0x000055555556e8cb in uhfd_measure_dev (pUHFD=0x55555559c0d0 <__main_globals+912>, 
    devno=0, timeout_us=10000, tx_power=15) at /home/mundus/base/sem7/LabMate/rscs/uhfd.c:626
#8  0x000055555555ebf1 in do_write (path=0x7fffe8000c40 "/uhf0/driver/measure", 
    buffer=0x7ffff6b30060 "10000 155343434343434343", size=8, offset=0, fi=0x7ffff7431d70)
    at /home/mundus/base/sem7/LabMate/rscs/main.c:956
#9  0x00007ffff7f55b8b in fuse_fs_write_buf () from /lib/x86_64-linux-gnu/libfuse3.so.3
#10 0x00007ffff7f55cc9 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#11 0x00007ffff7f61334 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#12 0x00007ffff7f5c569 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#13 0x00007ffff7dc1144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#14 0x00007ffff7e417dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81
(gdb) thread apply all bt

Thread 5 (Thread 0x7ffff622c6c0 (LWP 1422331) "rscs"):
#0  __GI___libc_read (nbytes=1052672, buf=0x7ffff592a010, fd=4) at ../sysdeps/unix/sysv/linux/read.c:26                                                                                     
#1  __GI___libc_read (fd=4, buf=0x7ffff592a010, nbytes=1052672) at ../sysdeps/unix/sysv/linux/read.c:24                                                                                     
#2  0x00007ffff7f62458 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#3  0x00007ffff7f5c460 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#4  0x00007ffff7dc1144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#5  0x00007ffff7e417dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 4 (Thread 0x7ffff6b2f6c0 (LWP 1420350) "rscs"):
#0  __GI___libc_read (nbytes=1052672, buf=0x7ffff622d010, fd=4) at ../sysdeps/unix/sysv/linux/read.c:26                                                                                     
#1  __GI___libc_read (fd=4, buf=0x7ffff622d010, nbytes=1052672) at ../sysdeps/unix/sysv/linux/read.c:24                                                                                     
#2  0x00007ffff7f62458 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#3  0x00007ffff7f5c460 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#4  0x00007ffff7dc1144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#5  0x00007ffff7e417dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 3 (Thread 0x7ffff74326c0 (LWP 1419666) "rscs"):
#0  __pthread_kill_implementation (threadid=<optimized out>, signo=signo@entry=6, no_tid=no_tid@entry=0) at ./nptl/pthread_kill.c:44                                                        
#1  0x00007ffff7dc2e9f in __pthread_kill_internal (signo=6, threadid=<optimized out>) at ./nptl/pthread_kill.c:78                                                                           
#2  0x00007ffff7d73fb2 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#3  0x00007ffff7d5e472 in __GI_abort () at ./stdlib/abort.c:79
#4  0x00007ffff7d5e395 in __assert_fail_base (fmt=0x7ffff7ed2a90 "%s%s%s:%u: %s%sAssertion `%s' failed.\n%n", assertion=assertion@entry=0x555555589df0 "(pCtx->_config.flags & (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY) == (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY", file=file@entry=0x555555589580 "/home/mundus/base/sem7/LabMate/rscs/uhfman.c", line=line@entry=1197, function=function@entry=0x55555558a2a0 <__PRETTY_FUNCTION__.2> "uhfman_multiple_polling_stop") at ./assert/assert.c:92
#5  0x00007ffff7d6ceb2 in __GI___assert_fail (assertion=0x555555589df0 "(pCtx->_config.flags & (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY) == (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY", file=0x555555589580 "/home/mundus/base/sem7/LabMate/rscs/uhfman.c", line=1197, function=0x55555558a2a0 <__PRETTY_FUNCTION__.2> "uhfman_multiple_polling_stop") at ./assert/assert.c:101
#6  0x0000555555563901 in uhfman_multiple_polling_stop (pCtx=0x55555559d488 <__main_globals+59--Type <RET> for more, q to quit, c to continue without paging--
60>) at /home/mundus/base/sem7/LabMate/rscs/uhfman.c:1197
#7  0x000055555556e8cb in uhfd_measure_dev (pUHFD=0x55555559c0d0 <__main_globals+912>, devno=0, timeout_us=10000, tx_power=15) at /home/mundus/base/sem7/LabMate/rscs/uhfd.c:626
#8  0x000055555555ebf1 in do_write (path=0x7fffe8000c40 "/uhf0/driver/measure", buffer=0x7ffff6b30060 "10000 155343434343434343", size=8, offset=0, fi=0x7ffff7431d70) at /home/mundus/base/sem7/LabMate/rscs/main.c:956                                                                  
#9  0x00007ffff7f55b8b in fuse_fs_write_buf () from /lib/x86_64-linux-gnu/libfuse3.so.3
#10 0x00007ffff7f55cc9 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#11 0x00007ffff7f61334 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#12 0x00007ffff7f5c569 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#13 0x00007ffff7dc1144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#14 0x00007ffff7e417dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 2 (Thread 0x7ffff7d356c0 (LWP 1419665) "rscs"):
#0  __GI___libc_read (nbytes=1052672, buf=0x7ffff7433010, fd=4) at ../sysdeps/unix/sysv/linux/read.c:26                                                                                     
#1  __GI___libc_read (fd=4, buf=0x7ffff7433010, nbytes=1052672) at ../sysdeps/unix/sysv/linux/read.c:24                                                                                     
#2  0x00007ffff7f62458 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#3  0x00007ffff7f5c460 in ?? () from /lib/x86_64-linux-gnu/libfuse3.so.3
#4  0x00007ffff7dc1144 in start_thread (arg=<optimized out>) at ./nptl/pthread_create.c:442
#5  0x00007ffff7e417dc in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

Thread 1 (Thread 0x7ffff7d36b80 (LWP 1419659) "rscs"):
#0  __futex_abstimed_wait_common64 (private=<optimized out>, cancel=true, abstime=0x0, op=393, expected=0, futex_word=0x7fffffffdbc8) at ./nptl/futex-internal.c:57
#1  __futex_abstimed_wait_common (futex_word=futex_word@entry=0x7fffffffdbc8, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>, cancel=cancel@entry=true) at ./nptl/futex-internal.c:87                                             
#2  0x00007ffff7dbdefb in __GI___futex_abstimed_wait_cancelable64 (futex_word=futex_word@entry=0x7fffffffdbc8, expected=expected@entry=0, clockid=clockid@entry=0, abstime=abstime@entry=0x0, private=<optimized out>) at ./nptl/futex-internal.c:139
#3  0x00007ffff7dc8c4f in do_futex_wait (sem=sem@entry=0x7fffffffdbc8, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:111
#4  0x00007ffff7dc8ce0 in __new_sem_wait_slow64 (sem=0x7fffffffdbc8, abstime=0x0, clockid=0) at ./nptl/sem_waitcommon.c:183
#5  0x00007ffff7f5c818 in fuse_session_loop_mt_312 () from /lib/x86_64-linux-gnu/libfuse3.so.3
#6  0x00007ffff7f5b3ad in fuse_loop_mt_312 () from /lib/x86_64-linux-gnu/libfuse3.so.3
#7  0x00007ffff7f64e1d in fuse_main_real () from /lib/x86_64-linux-gnu/libfuse3.so.3
--Type <RET> for more, q to quit, c to continue without paging--
#8  0x000055555555f34f in main (argc=3, argv=0x7fffffffde38) at /home/mundus/base/sem7/LabMate/rscs/main.c:1045                                                                             
(gdb)
adameus03 commented 3 days ago

After commit https://github.com/adameus03/LabMate/commit/613091ba3cb4c6c7d4eebf3481c79b03aa9c7616 introducing debug log for this issue, we got:

[DEBUG] 2024-11-28 17:15:35  (/home/mundus/base/rscs/uhfman.c:1197): Stopping multiple polling, pCtx->_config.flags: 0x0F
rscs: /home/mundus/base/rscs/uhfman.c:1198: uhfman_multiple_polling_stop: Assertion `(pCtx->_config.flags & (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY) == (uint8_t)UHFMAN_CTX_CONFIG_FLAG_IS_MPOLL_BUSY' failed.