Discussion:
bufferevent_openssl_filter_new and event_base_free
Topher LaFata
2014-09-17 19:19:18 UTC
Permalink
Hello,

I am running into a problem where I am unable to properly free the
event_base when using the bufferevent_openssl_filter.
I have a use case where I need to connect and immediately disconnect from a
remote server.

This is the error I am seeing.

[debug] event_add: event: 0x7fd99ac1e490 (fd 6), EV_READ call 0x10811b8f0

[debug] event_callback_finalize_many_: 3 events finalizing

[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x1081175c0

[debug] event_del: 0x7fd99ad00b80 (fd -1), callback 0x108117620

[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x1081175c0

[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0

[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x108116c70

[debug] event_callback_finalize_many_: 3 events finalizing

[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0

[debug] event_del: 0x7fd99ac1e510 (fd 6), callback 0x10811bb30

[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0

[debug] event_base_free_: 1 events were still set in base

[err] event.c:840: Assertion TAILQ_EMPTY(&base->activequeues[i]) failed in
event_base_free_Abort trap: 6


I attached a small test program demonstrating the problem. You will have to
change the LIBEVENT_BASE_DIR variable in the included Makefile.

I am able to get around the problem by not freeing the underlying
bufferevent or by using event_base_free_nofinalize but then we are leaking
memory according to valgrind.

It is not clear to me that I am even setting up this stuff properly even
though it is working well. Any insight would be greatly appreciated!

Thanks for your time!

Topher
Azat Khuzhin
2014-09-22 05:38:15 UTC
Permalink
Post by Topher LaFata
Hello,
I am running into a problem where I am unable to properly free the
event_base when using the bufferevent_openssl_filter.
I have a use case where I need to connect and immediately disconnect from a
remote server.
This is the error I am seeing.
[debug] event_add: event: 0x7fd99ac1e490 (fd 6), EV_READ call 0x10811b8f0
[debug] event_callback_finalize_many_: 3 events finalizing
[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x1081175c0
[debug] event_del: 0x7fd99ad00b80 (fd -1), callback 0x108117620
[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x1081175c0
[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0
[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x108116c70
[debug] event_callback_finalize_many_: 3 events finalizing
[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0
[debug] event_del: 0x7fd99ac1e510 (fd 6), callback 0x10811bb30
[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0
[debug] event_base_free_: 1 events were still set in base
[err] event.c:840: Assertion TAILQ_EMPTY(&base->activequeues[i]) failed in
event_base_free_Abort trap: 6
I attached a small test program demonstrating the problem. You will have to
change the LIBEVENT_BASE_DIR variable in the included Makefile.
I am able to get around the problem by not freeing the underlying
bufferevent or by using event_base_free_nofinalize but then we are leaking
memory according to valgrind.
It is not clear to me that I am even setting up this stuff properly even
though it is working well. Any insight would be greatly appreciated!
Hi Topher,

That is because bufferevent_finalize_cb_() -> ...
bufferevent_decref_and_unlock_() ... -> event_queue_insert_active().
IOW bufferevent finalize add events into active queue, during cleaning this
active queue in event_base_free_():
...
for (i = 0; i < base->nactivequeues; ++i) {
struct event_callback *evcb, *next;
for (evcb = TAILQ_FIRST(&base->activequeues[i]); evcb; ) {
next = TAILQ_NEXT(evcb, evcb_active_next);
/* Here TAILQ_REMOVE() called, and TAILQ_INSERT_*() too
* from bufferevent_decref_and_unlock_() -> ... ->
* event_queue_insert_active() */
n_deleted += event_base_cancel_single_callback_(base, evcb, run_finalizers);
evcb = next;
}
}
...
for (i = 0; i < base->nactivequeues; ++i)
EVUTIL_ASSERT(TAILQ_EMPTY(&base->activequeues[i]));


Watchpoint 3: -location base->activequeues[0]

Old value = {
tqh_first = 0x0,
tqh_last = 0x61fdf0
}
New value = {
tqh_first = 0x621d00,
tqh_last = 0x61fdf0
}
0x00007ffff7ba2a91 in event_queue_insert_active (base=0x61f9c0, evcb=0x621d00) at event.c:3269
3269 TAILQ_INSERT_TAIL(&base->activequeues[evcb->evcb_pri],
(gdb) bt
#0 0x00007ffff7ba2a91 in event_queue_insert_active (base=0x61f9c0, evcb=0x621d00) at event.c:3269
#1 0x00007ffff7ba1948 in event_callback_activate_nolock_ (base=0x61f9c0, evcb=0x621d00) at event.c:2903
#2 0x00007ffff7b9f115 in event_callback_finalize_nolock_ (base=0x61f9c0, flags=0, evcb=0x621d00, cb=0x7ffff7b93239 <bufferevent_finalize_cb_>) at event.c:2181
#3 0x00007ffff7b9f2e3 in event_callback_finalize_many_ (base=0x61f9c0, n_cbs=3, evcbs=0x7fffffffdbb0, cb=0x7ffff7b93239 <bufferevent_finalize_cb_>) at event.c:2223
#4 0x00007ffff7b931f7 in bufferevent_decref_and_unlock_ (bufev=0x621cf0) at bufferevent.c:717
#5 0x00007ffff7b93453 in bufferevent_decref_ (bufev=0x621cf0) at bufferevent.c:783
#6 0x00007ffff7b93401 in bufferevent_finalize_cb_ (evcb=0x622240, arg_=0x622230) at bufferevent.c:776
#7 0x00007ffff7b9b622 in event_base_cancel_single_callback_ (base=0x61f9c0, evcb=0x622240, run_finalizers=1) at event.c:741
#8 0x00007ffff7b9b867 in event_base_free_ (base=0x61f9c0, run_finalizers=1) at event.c:814
#9 0x00007ffff7b9bb6a in event_base_free (base=0x61f9c0) at event.c:869
#10 0x0000000000401747 in _close ()
#11 0x0000000000401899 in main ()

*But* bufferevent_decref_and_unlock_() called not only from
event_base_free():
(gdb) bt
#0 event_callback_finalize_many_ (base=0x6b40e0, n_cbs=3, evcbs=0x7fffffffd8b0, cb=0x7ffff7b93239 <bufferevent_finalize_cb_>) at event.c:2199
#1 0x00007ffff7b931f7 in bufferevent_decref_and_unlock_ (bufev=0x6b4ea0) at bufferevent.c:717
#2 0x00007ffff7b98cbf in bufferevent_writecb (fd=12, event=4, arg=0x6b4ea0) at bufferevent_sock.c:313
#3 0x00007ffff7b9d147 in event_persist_closure (base=0x6b40e0, ev=0x6b4f30) at event.c:1510
#4 0x00007ffff7b9d430 in event_process_active_single_queue (base=0x6b40e0, activeq=0x6b4530, max_to_process=2147483647, endtime=0x0) at event.c:1569
#5 0x00007ffff7b9da58 in event_process_active (base=0x6b40e0) at event.c:1668
#6 0x00007ffff7b9e1b7 in event_base_loop (base=0x6b40e0, flags=0) at event.c:1891
#7 0x00007ffff7b9dade in event_base_dispatch (event_base=0x6b40e0) at event.c:1702
#8 0x000000000044237a in test_bufferevent_connect (arg=0x6b46b0) at regress_bufferevent.c:576
#9 0x0000000000485d19 in testcase_run_bare_ (testcase=0x6a4af0 <bufferevent_testcases+240>) at tinytest.c:105
#10 0x0000000000485dc6 in testcase_run_forked_ (group=0x6a5fb0 <testgroups+112>, testcase=0x6a4af0 <bufferevent_testcases+240>) at tinytest.c:189
#11 0x0000000000485feb in testcase_run_one (group=0x6a5fb0 <testgroups+112>, testcase=0x6a4af0 <bufferevent_testcases+240>) at tinytest.c:247
#12 0x000000000048693a in tinytest_main (c=2, v=0x7fffffffdef8, groups=0x6a5f40 <testgroups>) at tinytest.c:434
#13 0x000000000047343f in main (argc=2, argv=0x7fffffffdef8) at regress_main.c:459

I'm not sure about the proper patch, maybe some EV_FINALIZE flag for that
events or something like this (and only when it called from event_base_free()).
Nick could you look into this?

Cheers,
Azat.
***********************************************************************
To unsubscribe, send an e-mail to ***@freehaven.net with
unsubscribe libevent-users in the body.
Topher LaFata
2014-09-22 13:03:25 UTC
Permalink
Thank you for the response.

The workaround that I ended up using was to make sure event_base_loopexit was
called before trying to free the event base. Event though I am pumping the
loop myself this had the side effect of allowing me to shutdown the event
base cleanly.
Post by Topher LaFata
Post by Topher LaFata
Hello,
I am running into a problem where I am unable to properly free the
event_base when using the bufferevent_openssl_filter.
I have a use case where I need to connect and immediately disconnect
from a
Post by Topher LaFata
remote server.
This is the error I am seeing.
[debug] event_add: event: 0x7fd99ac1e490 (fd 6), EV_READ call
0x10811b8f0
Post by Topher LaFata
[debug] event_callback_finalize_many_: 3 events finalizing
[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x1081175c0
[debug] event_del: 0x7fd99ad00b80 (fd -1), callback 0x108117620
[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x1081175c0
[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0
[debug] event_del: 0x7fd99ad00b00 (fd -1), callback 0x108116c70
[debug] event_callback_finalize_many_: 3 events finalizing
[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0
[debug] event_del: 0x7fd99ac1e510 (fd 6), callback 0x10811bb30
[debug] event_del: 0x7fd99ac1e490 (fd 6), callback 0x10811b8f0
[debug] event_base_free_: 1 events were still set in base
[err] event.c:840: Assertion TAILQ_EMPTY(&base->activequeues[i]) failed
in
Post by Topher LaFata
event_base_free_Abort trap: 6
I attached a small test program demonstrating the problem. You will have
to
Post by Topher LaFata
change the LIBEVENT_BASE_DIR variable in the included Makefile.
I am able to get around the problem by not freeing the underlying
bufferevent or by using event_base_free_nofinalize but then we are
leaking
Post by Topher LaFata
memory according to valgrind.
It is not clear to me that I am even setting up this stuff properly even
though it is working well. Any insight would be greatly appreciated!
Hi Topher,
That is because bufferevent_finalize_cb_() -> ...
bufferevent_decref_and_unlock_() ... -> event_queue_insert_active().
IOW bufferevent finalize add events into active queue, during cleaning this
...
for (i = 0; i < base->nactivequeues; ++i) {
struct event_callback *evcb, *next;
for (evcb = TAILQ_FIRST(&base->activequeues[i]); evcb; ) {
next = TAILQ_NEXT(evcb, evcb_active_next);
/* Here TAILQ_REMOVE() called, and
TAILQ_INSERT_*() too
* from bufferevent_decref_and_unlock_() -> ... ->
* event_queue_insert_active() */
n_deleted +=
event_base_cancel_single_callback_(base, evcb, run_finalizers);
evcb = next;
}
}
...
for (i = 0; i < base->nactivequeues; ++i)
EVUTIL_ASSERT(TAILQ_EMPTY(&base->activequeues[i]));
Watchpoint 3: -location base->activequeues[0]
Old value = {
tqh_first = 0x0,
tqh_last = 0x61fdf0
}
New value = {
tqh_first = 0x621d00,
tqh_last = 0x61fdf0
}
0x00007ffff7ba2a91 in event_queue_insert_active (base=0x61f9c0,
evcb=0x621d00) at event.c:3269
3269 TAILQ_INSERT_TAIL(&base->activequeues[evcb->evcb_pri],
(gdb) bt
#0 0x00007ffff7ba2a91 in event_queue_insert_active (base=0x61f9c0,
evcb=0x621d00) at event.c:3269
#1 0x00007ffff7ba1948 in event_callback_activate_nolock_ (base=0x61f9c0,
evcb=0x621d00) at event.c:2903
#2 0x00007ffff7b9f115 in event_callback_finalize_nolock_ (base=0x61f9c0,
flags=0, evcb=0x621d00, cb=0x7ffff7b93239 <bufferevent_finalize_cb_>) at
event.c:2181
#3 0x00007ffff7b9f2e3 in event_callback_finalize_many_ (base=0x61f9c0,
n_cbs=3, evcbs=0x7fffffffdbb0, cb=0x7ffff7b93239
<bufferevent_finalize_cb_>) at event.c:2223
#4 0x00007ffff7b931f7 in bufferevent_decref_and_unlock_ (bufev=0x621cf0)
at bufferevent.c:717
#5 0x00007ffff7b93453 in bufferevent_decref_ (bufev=0x621cf0) at bufferevent.c:783
#6 0x00007ffff7b93401 in bufferevent_finalize_cb_ (evcb=0x622240,
arg_=0x622230) at bufferevent.c:776
#7 0x00007ffff7b9b622 in event_base_cancel_single_callback_
(base=0x61f9c0, evcb=0x622240, run_finalizers=1) at event.c:741
#8 0x00007ffff7b9b867 in event_base_free_ (base=0x61f9c0,
run_finalizers=1) at event.c:814
#9 0x00007ffff7b9bb6a in event_base_free (base=0x61f9c0) at event.c:869
#10 0x0000000000401747 in _close ()
#11 0x0000000000401899 in main ()
*But* bufferevent_decref_and_unlock_() called not only from
(gdb) bt
#0 event_callback_finalize_many_ (base=0x6b40e0, n_cbs=3,
evcbs=0x7fffffffd8b0, cb=0x7ffff7b93239 <bufferevent_finalize_cb_>) at
event.c:2199
#1 0x00007ffff7b931f7 in bufferevent_decref_and_unlock_ (bufev=0x6b4ea0)
at bufferevent.c:717
#2 0x00007ffff7b98cbf in bufferevent_writecb (fd=12, event=4,
arg=0x6b4ea0) at bufferevent_sock.c:313
#3 0x00007ffff7b9d147 in event_persist_closure (base=0x6b40e0,
ev=0x6b4f30) at event.c:1510
#4 0x00007ffff7b9d430 in event_process_active_single_queue
(base=0x6b40e0, activeq=0x6b4530, max_to_process=2147483647, endtime=0x0)
at event.c:1569
#5 0x00007ffff7b9da58 in event_process_active (base=0x6b40e0) at event.c:1668
#6 0x00007ffff7b9e1b7 in event_base_loop (base=0x6b40e0, flags=0) at event.c:1891
#7 0x00007ffff7b9dade in event_base_dispatch (event_base=0x6b40e0) at event.c:1702
#8 0x000000000044237a in test_bufferevent_connect (arg=0x6b46b0) at
regress_bufferevent.c:576
#9 0x0000000000485d19 in testcase_run_bare_ (testcase=0x6a4af0
<bufferevent_testcases+240>) at tinytest.c:105
#10 0x0000000000485dc6 in testcase_run_forked_ (group=0x6a5fb0
<testgroups+112>, testcase=0x6a4af0 <bufferevent_testcases+240>) at
tinytest.c:189
#11 0x0000000000485feb in testcase_run_one (group=0x6a5fb0
<testgroups+112>, testcase=0x6a4af0 <bufferevent_testcases+240>) at
tinytest.c:247
#12 0x000000000048693a in tinytest_main (c=2, v=0x7fffffffdef8,
groups=0x6a5f40 <testgroups>) at tinytest.c:434
#13 0x000000000047343f in main (argc=2, argv=0x7fffffffdef8) at regress_main.c:459
I'm not sure about the proper patch, maybe some EV_FINALIZE flag for that
events or something like this (and only when it called from
event_base_free()).
Nick could you look into this?
Cheers,
Azat.
***********************************************************************
unsubscribe libevent-users in the body.
Loading...