Bug 14860 - libtevent: crash in tevent_common_insert_timer()
Summary: libtevent: crash in tevent_common_insert_timer()
Status: ASSIGNED
Alias: None
Product: Samba 4.1 and newer
Classification: Unclassified
Component: Other (show other bugs)
Version: unspecified
Hardware: All All
: P5 normal (vote)
Target Milestone: ---
Assignee: Stefan Metzmacher
QA Contact: Samba QA Contact
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2021-10-11 10:58 UTC by Alexey
Modified: 2022-02-03 10:02 UTC (History)
2 users (show)

See Also:


Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description Alexey 2021-10-11 10:58:39 UTC
Crash in `libtevent` (used in SSSD project):

#0  0x000003ff8538c97a in tevent_common_insert_timer (ev=0x2aa2526e7d0, te=0x2aa252bd540, optimize_zero=<optimized out>) at ../../tevent_timed.c:219
#1  0x000003ff8538cade in tevent_common_add_timer_internal (ev=0x2aa2526e7d0, mem_ctx=<optimized out>, next_event=..., handler=<optimized out>, 
    private_data=private_data@entry=0x2aa252bab30, handler_name=0x3ff854ae962 "sbus_dispatch", 
    location=0x3ff854ae938 "src/sbus/connection/sbus_dispatcher.c:119", optimize_zero=true) at ../../tevent_timed.c:254
#2  0x000003ff8538ccc8 in tevent_common_add_timer_v2 (ev=<optimized out>, mem_ctx=<optimized out>, 
    next_event=<error reading variable: value has been optimized out>, handler=<optimized out>, private_data=0x2aa252bab30, 
    handler_name=0x3ff854ae962 "sbus_dispatch", location=0x3ff854ae938 "src/sbus/connection/sbus_dispatcher.c:119") at ../../tevent_timed.c:296
#3  0x000003ff85386b32 in _tevent_add_timer (ev=<optimized out>, mem_ctx=mem_ctx@entry=0x2aa252bab30, 
    next_event=<error reading variable: value has been optimized out>, handler=handler@entry=0x3ff85496ff0 <sbus_dispatch>, 
    private_data=private_data@entry=0x2aa252bab30, handler_name=0x3ff854ae962 "sbus_dispatch", 
    location=0x3ff854ae938 "src/sbus/connection/sbus_dispatcher.c:119") at ../../tevent.c:639
#4  0x000003ff85496f64 in sbus_dispatch_schedule (conn=0x2aa252bab30, usecs=<optimized out>) at src/sbus/connection/sbus_dispatcher.c:119
#5  0x000003ff85298cca in _dbus_connection_send_and_unlock () from /lib64/libdbus-1.so.3
#6  0x000003ff85497d10 in sbus_reply (reply=0x2aa25350cf0, conn=<optimized out>) at src/sbus/connection/sbus_send.c:216
#7  sbus_reply (conn=<optimized out>, reply=0x2aa25350cf0) at src/sbus/connection/sbus_send.c:208
...

(gdb) frame
#0  0x000003ff8538c97a in tevent_common_insert_timer (ev=0x2aa2526e7d0, te=0x2aa252bd540, optimize_zero=<optimized out>) at ../../tevent_timed.c:219
219		DLIST_ADD_AFTER(ev->timer_events, te, prev_te);

(gdb) p te
$11 = (struct tevent_timer *) 0x2aa252bd540

(gdb) p te->next
$10 = (struct tevent_timer *) 0x800002aa252e8850

(gdb) p *(te->next)
Cannot access memory at address 0x800002aa252e8850

FWIW, this value - 0x800002aa252e8850 - looks like a "legit" 0x2aa252e8850 (close to other valid pointers) + 0x8000000000000000.


(Initially reported as RHBZ https://bugzilla.redhat.com/show_bug.cgi?id=1930538)
Comment 1 Stefan Metzmacher 2021-10-11 12:13:45 UTC
I guess the content of 'ev' is also relevant here.

https://bugzilla.redhat.com/show_bug.cgi?id=1930538#c1 has a few
more stack frames, I think we need the full backtrace to up to main().

You could also print the global 'tevent_contexts' list...
Comment 2 Alexey 2021-10-11 18:14:18 UTC
(In reply to Stefan Metzmacher from comment #1)

> I guess the content of 'ev' is also relevant here.
(gdb) frame 0
#0  0x000003ff8538c97a in tevent_common_insert_timer (ev=0x2aa2526e7d0, te=0x2aa252bd540, optimize_zero=<optimized out>) at ../../tevent_timed.c:219
219		DLIST_ADD_AFTER(ev->timer_events, te, prev_te);

(gdb) p *ev
$1 = {ops = 0x2aa2526e9a0, signal_events = 0x2aa252b1120, threaded_contexts = 0x0, immediate_events = 0x2aa252bc0f0, fd_events = 0x2aa252a9b50, 
  timer_events = 0x2aa2531a370, scheduled_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, 
      __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}, scheduled_immediates = 0x0, additional_data = 0x2aa2526ea60, 
  wakeup_fde = 0x2aa2526eb70, wakeup_fd = 3, wakeup_read_fd = 0, debug_ops = {debug = 0x0, context = 0x0}, nesting = {allowed = false, level = 1, 
    hook_fn = 0x0, hook_private = 0x0}, tracing = {callback = 0x0, private_data = 0x0}, wrapper = {list = 0x0, glue = 0x0}, last_zero_timer = 0x0, 
  prev = 0x2aa2526fe30, next = 0x0}

(gdb) p *ev->signal_events 
$4 = {prev = 0x2aa2526f780, next = 0x2aa252b0f50, event_ctx = 0x2aa2526e7d0, wrapper = 0x0, busy = false, destroyed = false, signum = 12, sa_flags = 0, 
  handler = 0x2aa0228a098 <signal_be_reset_offline>, private_data = 0x2aa252822a0, handler_name = 0x2aa022a6228 "signal_be_reset_offline", 
  location = 0x2aa022a6202 "src/providers/data_provider_be.c:649", additional_data = 0x2aa252b11e0}

(gdb) p *ev->immediate_events
$6 = {prev = 0x2aa252bc0f0, next = 0x0, event_ctx = 0x2aa2526e7d0, wrapper = 0x0, busy = false, destroyed = false, 
  handler = 0x3ff85497ec0 <free_sbus_watch>, private_data = 0x2aa252bbd70, handler_name = 0x3ff854af0b6 "free_sbus_watch", 
  create_location = 0x3ff854af0fe "src/sbus/connection/sbus_watch.c:181", schedule_location = 0x3ff854af0c6 "src/sbus/connection/sbus_watch.c:308", 
  cancel_fn = 0x0, additional_data = 0x0}

(gdb) p *ev->fd_events 
$7 = {prev = 0x2aa2526eb70, next = 0x2aa252ad9a0, event_ctx = 0x2aa2526e7d0, wrapper = 0x0, busy = false, destroyed = false, fd = 23, flags = 1, 
  handler = 0x3ff85498230 <sbus_watch_handler>, close_fn = 0x0, private_data = 0x2aa25314dd0, handler_name = 0x3ff854af180 "sbus_watch_handler", 
  location = 0x3ff854af15a "src/sbus/connection/sbus_watch.c:246", additional_flags = 3, additional_data = 0x0}

(gdb) p *ev->timer_events
$8 = {prev = 0x2aa252e8850, next = 0x2aa253007e0, event_ctx = 0x2aa2526e7d0, wrapper = 0x0, busy = false, destroyed = false, next_event = {
    tv_sec = 1611866061, tv_usec = 462700}, handler = 0x3ff85496ff0 <sbus_dispatch>, private_data = 0x2aa252bab30, 
  handler_name = 0x3ff854ae962 "sbus_dispatch", location = 0x3ff854ae938 "src/sbus/connection/sbus_dispatcher.c:119", additional_data = 0x0}

(gdb) p *ev->prev
$9 = {ops = 0x2aa25270000, signal_events = 0x0, threaded_contexts = 0x0, immediate_events = 0x0, fd_events = 0x0, timer_events = 0x0, scheduled_mutex = {
    __data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
    __size = '\000' <repeats 39 times>, __align = 0}, scheduled_immediates = 0x0, additional_data = 0x2aa252700c0, wakeup_fde = 0x0, wakeup_fd = 0, 
  wakeup_read_fd = 0, debug_ops = {debug = 0x0, context = 0x0}, nesting = {allowed = false, level = 0, hook_fn = 0x0, hook_private = 0x0}, tracing = {
    callback = 0x0, private_data = 0x0}, wrapper = {list = 0x0, glue = 0x0}, last_zero_timer = 0x0, prev = 0x2aa2527eb20, next = 0x2aa2526e7d0}


> https://bugzilla.redhat.com/show_bug.cgi?id=1930538#c1 has a few
> more stack frames, I think we need the full backtrace to up to main().
#0  0x000003ff8538c97a in tevent_common_insert_timer (ev=0x2aa2526e7d0, te=0x2aa252bd540, optimize_zero=<optimized out>) at ../../tevent_timed.c:219
#1  0x000003ff8538cade in tevent_common_add_timer_internal (ev=0x2aa2526e7d0, mem_ctx=<optimized out>, next_event=..., handler=<optimized out>, 
    private_data=private_data@entry=0x2aa252bab30, handler_name=0x3ff854ae962 "sbus_dispatch", 
    location=0x3ff854ae938 "src/sbus/connection/sbus_dispatcher.c:119", optimize_zero=true) at ../../tevent_timed.c:254
#2  0x000003ff8538ccc8 in tevent_common_add_timer_v2 (ev=<optimized out>, mem_ctx=<optimized out>, 
    next_event=<error reading variable: value has been optimized out>, handler=<optimized out>, private_data=0x2aa252bab30, 
    handler_name=0x3ff854ae962 "sbus_dispatch", location=0x3ff854ae938 "src/sbus/connection/sbus_dispatcher.c:119") at ../../tevent_timed.c:296
#3  0x000003ff85386b32 in _tevent_add_timer (ev=<optimized out>, mem_ctx=mem_ctx@entry=0x2aa252bab30, 
    next_event=<error reading variable: value has been optimized out>, handler=handler@entry=0x3ff85496ff0 <sbus_dispatch>, 
    private_data=private_data@entry=0x2aa252bab30, handler_name=0x3ff854ae962 "sbus_dispatch", 
    location=0x3ff854ae938 "src/sbus/connection/sbus_dispatcher.c:119") at ../../tevent.c:639
#4  0x000003ff85496f64 in sbus_dispatch_schedule (conn=0x2aa252bab30, usecs=<optimized out>) at src/sbus/connection/sbus_dispatcher.c:119
#5  0x000003ff85298cca in _dbus_connection_send_and_unlock () from /lib64/libdbus-1.so.3
#6  0x000003ff85497d10 in sbus_reply (reply=0x2aa25350cf0, conn=<optimized out>) at src/sbus/connection/sbus_send.c:216
#7  sbus_reply (conn=<optimized out>, reply=0x2aa25350cf0) at src/sbus/connection/sbus_send.c:208
#8  0x000003ff854a70b8 in sbus_issue_request_done (subreq=0x0) at src/sbus/router/sbus_router_handler.c:150
#9  0x000003ff854a3ce4 in sbus_request_notify_success (table=<optimized out>, key=<optimized out>, req=req@entry=0x2aa25336a30, 
    messages_fn=messages_fn@entry=0x3ff854a3800 <sbus_request_messages>, reply=reply@entry=0x2aa25350cf0) at src/sbus/request/sbus_request.c:284
#10 0x000003ff854a3d8a in sbus_incoming_request_done (subreq=0x0) at src/sbus/request/sbus_request.c:539
#11 0x000003ff8538cf34 in tevent_common_invoke_timer_handler (te=te@entry=0x2aa25312da0, current_time=..., removed=removed@entry=0x0)
    at ../../tevent_timed.c:370
#12 0x000003ff8538d0ee in tevent_common_loop_timer_delay (ev=ev@entry=0x2aa2526e7d0) at ../../tevent_timed.c:442
#13 0x000003ff8538e594 in epoll_event_loop_once (ev=0x2aa2526e7d0, location=<optimized out>) at ../../tevent_epoll.c:922
#14 0x000003ff8538c34c in std_event_loop_once (ev=0x2aa2526e7d0, location=0x3ff86176eb4 "src/util/server.c:730") at ../../tevent_standard.c:110
#15 0x000003ff85386d2c in _tevent_loop_once (ev=ev@entry=0x2aa2526e7d0, location=location@entry=0x3ff86176eb4 "src/util/server.c:730") at ../../tevent.c:772
#16 0x000003ff85386fde in tevent_common_loop_wait (ev=0x2aa2526e7d0, location=0x3ff86176eb4 "src/util/server.c:730") at ../../tevent.c:893
#17 0x000003ff8538c2cc in std_event_loop_wait (ev=0x2aa2526e7d0, location=0x3ff86176eb4 "src/util/server.c:730") at ../../tevent_standard.c:141
#18 0x000003ff86153cea in server_loop (main_ctx=0x2aa2526eaf0) at src/util/server.c:730
#19 0x000002aa02289610 in main (argc=<optimized out>, argv=<optimized out>) at src/providers/data_provider_be.c:772


> You could also print the global 'tevent_contexts' list...

(gdb) p tevent_contexts
$10 = (struct tevent_context *) 0x2aa25284530

(gdb) p *tevent_contexts
$11 = {ops = 0x2aa25281d60, signal_events = 0x0, threaded_contexts = 0x0, immediate_events = 0x0, fd_events = 0x0, timer_events = 0x0, scheduled_mutex = {
    __data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
    __size = '\000' <repeats 39 times>, __align = 0}, scheduled_immediates = 0x0, additional_data = 0x2aa25282b60, wakeup_fde = 0x0, wakeup_fd = 0, 
  wakeup_read_fd = 0, debug_ops = {debug = 0x3ff85fa4a70 <ldb_tevent_debug>, context = 0x2aa25297a80}, nesting = {allowed = true, level = 0, hook_fn = 0x0, 
    hook_private = 0x0}, tracing = {callback = 0x0, private_data = 0x0}, wrapper = {list = 0x0, glue = 0x0}, last_zero_timer = 0x0, prev = 0x2aa2526e7d0, 
  next = 0x2aa2527eb20}

(gdb) p *tevent_contexts->ops
$13 = {context_init = 0x3ff8538c388 <std_event_context_init>, add_fd = 0x3ff8538e208 <epoll_event_add_fd>, 
  set_fd_close_fn = 0x3ff85387610 <tevent_common_fd_set_close_fn>, get_fd_flags = 0x3ff853875f0 <tevent_common_fd_get_flags>, 
  set_fd_flags = 0x3ff8538e150 <epoll_event_set_fd_flags>, add_timer = 0x3ff8538cc88 <tevent_common_add_timer_v2>, 
  schedule_immediate = 0x3ff853878f0 <tevent_common_schedule_immediate>, add_signal = 0x3ff8538b958 <tevent_common_add_signal>, 
  loop_once = 0x3ff8538c300 <std_event_loop_once>, loop_wait = 0x3ff8538c280 <std_event_loop_wait>}

(gdb) p *tevent_contexts->prev
$15 = {ops = 0x2aa2526e9a0, signal_events = 0x2aa252b1120, threaded_contexts = 0x0, immediate_events = 0x2aa252bc0f0, fd_events = 0x2aa252a9b50, 
  timer_events = 0x2aa2531a370, scheduled_mutex = {__data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, 
      __list = {__prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, __align = 0}, scheduled_immediates = 0x0, additional_data = 0x2aa2526ea60, 
  wakeup_fde = 0x2aa2526eb70, wakeup_fd = 3, wakeup_read_fd = 0, debug_ops = {debug = 0x0, context = 0x0}, nesting = {allowed = false, level = 1, 
    hook_fn = 0x0, hook_private = 0x0}, tracing = {callback = 0x0, private_data = 0x0}, wrapper = {list = 0x0, glue = 0x0}, last_zero_timer = 0x0, 
  prev = 0x2aa2526fe30, next = 0x0}
  --  tevent_contexts->prev->next == 0x0 ..?

(gdb) p *tevent_contexts->next 
$14 = {ops = 0x2aa252789f0, signal_events = 0x0, threaded_contexts = 0x0, immediate_events = 0x0, fd_events = 0x0, timer_events = 0x0, scheduled_mutex = {
    __data = {__lock = 0, __count = 0, __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {__prev = 0x0, __next = 0x0}}, 
    __size = '\000' <repeats 39 times>, __align = 0}, scheduled_immediates = 0x0, additional_data = 0x2aa252784a0, wakeup_fde = 0x0, wakeup_fd = 0, 
  wakeup_read_fd = 0, debug_ops = {debug = 0x3ff85fa4a70 <ldb_tevent_debug>, context = 0x2aa25284030}, nesting = {allowed = true, level = 0, hook_fn = 0x0, 
    hook_private = 0x0}, tracing = {callback = 0x0, private_data = 0x0}, wrapper = {list = 0x0, glue = 0x0}, last_zero_timer = 0x0, prev = 0x2aa25284530, 
  next = 0x2aa2526fe30}


Please let me know if I missed anything.
Comment 3 Andreas Schneider 2022-02-02 10:05:39 UTC
metze: Do you need more information?
Comment 4 Volker Lendecke 2022-02-02 10:55:22 UTC
Just a general remark: Can you reproduce that under valgrind?
Comment 5 Alexey 2022-02-02 11:01:59 UTC
(In reply to Volker Lendecke from comment #4)

No, unfortunately we don't have a clear reproducer.
Comment 6 Stefan Metzmacher 2022-02-03 10:02:00 UTC
(In reply to Andreas Schneider from comment #3)

I have no idea what the problem could be, it might be a dangling
ev->last_zero_timer, but I'm not sure, sorry