OK. There are definitely race conditions in the timer handling of libqb
- at least according to helgrind which found 2 rather easily, so I
suspect that is what is happening here.
I'm preparing a patch to fix them at the moment. The patch will go into
the version 2 stream. Depending on which distribution you're using you
might need to ask for a backport of that patch to v1 or, if you're using
sources, ask me very nicely for a backport to upstream ;-)
Chrissie
On 27/01/2021 08:07, Christine Caulfield wrote:
Hi,
I've never seen anything like that before and, as ou say, no real work
ha sbeen don in that are since 1.0.2 so I doubt it's a fixed bug.
Although libqb claims thread-safety I wouldn't rule out a threading bug
with you adding timers from another thread. Looking at the test suite
there is actually very little testing of libqbs thread-safety so that's
where I would start looking for a start.
I'll have a play with it today, but you are able to come up with a
reproducer for us that would be very helpful.
Chrissie
On 25/01/2021 05:29, Miranda, Russel wrote:
Hello ClusterLabs Developers,
I'm a developer working on an application that is using libqb (1.0.2)
for its main event loop, and after running for a few hours, I'm
encountering this assertion failure:
loop_timerlist.c:67: make_job_from_tmo: Assertion `t->state ==
QB_POLL_ENTRY_ACTIVE' failed.
The assertion causes a SIGABRT, and generates a core file. The stack
trace is at the point of the failure is:
#0 0x00007ff3c76dd207 in raise () from /lib64/libc.so.6
#1 0x00007ff3c76de8f8 in abort () from /lib64/libc.so.6
#2 0x00007ff3c76d6026 in __assert_fail_base () from /lib64/libc.so.6
#3 0x00007ff3c76d60d2 in __assert_fail () from /lib64/libc.so.6
#4 0x00007ff3ca1c828d in make_job_from_tmo (data=0x5460250) at
loop_timerlist.c:67
#5 0x00007ff3ca1c815b in timerlist_expire (timerlist=0x5dffe98) at
../include/tlist.h:210
#6 expire_the_timers (s=0x5dffe80, ms_timeout=<optimized out>) at
loop_timerlist.c:78
#7 0x00007ff3ca1c6acc in qb_loop_run (lp=<optimized out>) at
loop.c:175 ...
Going back up to the point of the assertion (make_job_from_tmo), here
is what the "data" parameter looks like:
(gdb) p *((struct qb_loop_timer*)data)
$1 = {item = {list = {next = 0x5460250, prev = 0x5460250}, source =
0x5dffe80, user_data = 0x7ff3c9144f60 <sessions+6240>, type =
QB_LOOP_FD},
dispatch_fn = 0xac8b00 <sessionTimeoutHandler(void*)>, p =
QB_LOOP_MED, timerlist_handle = 0x0, state = QB_POLL_ENTRY_EMPTY,
check = 978999470, install_pos = 11}
Indeed, as the assertion indicates, t->state is QB_POLL_ENTRY_EMPTY
when the assertion fails.
The timer that appears to have expired was added a few seconds earlier
at the point when a message was sent (via socket) to an external
entity. Typically, when that entity responds, the timer is stopped
(via qb_loop_timer_del) to prevent expiration. If timer expiration
occurs before the response is received, the registered dispatch
function is called to handle failure of the external entity to respond.
That this timer would expire and call the dispatch_fn
(sessionTimeoutHandler(void*)) passing in the value of user_data
(0x7ff3c9144f60) at this point in the operation of the program is
entirely plausible / expected, and I have validated that user_data
points to a valid object of the appropriate type as well - so all of
the caller-settable data looks correct to me in the timer entry. While
I cannot completely exclude the possibility that something stepped on
the t->state value, it seems unlikely that it would have affected only
that one object property in the timer entry.
It appears to me that the timer has expired, but the timer list entry
has the wrong state. I'm confused to how that might occur. I've been
searching through the API documentation and online through forums, and
I can't find anyone else reporting this particular assertion failure
within "make_job_from_tmo", or even suggesting what we might be doing
wrong to cause it. Has anyone seen this before?
Some additional notes:
* There is another thread active that can call qb_loop_timer_add to
add a timer to the main event loop (it is not the timer that has
expired here), but it could have been adding a timer at the same time
this timer expired.
My understanding is that (excluding the IPC calls), libqb is
thread-safe, so it should be safe to call the qb_loop_timer_add() API
from another thread. qb_loop_timer_add() is the only libqb API called
from the other thread.
* In some cases we are adding timers that expire immediately (that is,
with a delay as short as 0ns). That is not the case with this
particular timer, it has a delay that is several seconds long.
The qb_loop_timer_add() API doesn't indicate a minimum for the
delay, so I am not aware of this being an incorrect usage - though we
could probably switch to calling the qb_loop_job_add API instead if
that is an incorrect use of the API.
None of the libqb releases since 1.0.2 appear to have any changes
introduced specifically to address a problem like this - though I do
see there were some minor updates made to the loop_timerlist.c code to
silence warnings. If there is a known problem in this area in 1.0.2, I
will try see how hard it is going to be to step up to the newer version.
I'm hoping someone has seen this problem before, or can suggest
something that we might be doing wrong in the use of the API that
could lead to this state.
Sincere thanks for any suggestions,
Russ
_______________________________________________
Manage your subscription:
https://lists.clusterlabs.org/mailman/listinfo/developers
ClusterLabs home: https://www.clusterlabs.org/
_______________________________________________
Manage your subscription:
https://lists.clusterlabs.org/mailman/listinfo/developers
ClusterLabs home: https://www.clusterlabs.org/
_______________________________________________
Manage your subscription:
https://lists.clusterlabs.org/mailman/listinfo/developers
ClusterLabs home: https://www.clusterlabs.org/
