glib errors (CRITICAL: Source ID 16 was not found when attempting to remove it)

[stepnem]

With current master (commit a8b2650) as well as latest release
(Arch Linux package 1.9.2-1), I get error messages like the one in
subject (only the number changes) for each notification after the
first one since dunst started, as long as no other notification is
being displayed. (IOW, the error does not seem to occur when a
notification reuses another notification's window on screen.)

No config involved (started as dunst -conf - </dev/null), but happens with
my usual configuration as well.

No desktop environment (startx with XMonad window manager).

glib2 version 2.76.4-1 (Arch Linux package)

I've stopped the log spam (with no ill effects) with the following patch:

diff --git a/src/dunst.c b/src/dunst.c
index 11e4d98d9056..93f047975f00 100644
--- a/src/dunst.c
+++ b/src/dunst.c
@@ -104,7 +104,10 @@ static gboolean run(void *data)
 
                 if (sleep >= 0) {
                         if (reason == 0 || next_timeout < now || timeout_at < next_timeout) {
-                                if (next_timeout != 0) {
+                                if (next_timeout != 0 &&
+                                    g_main_context_find_source_by_id(
+                                            g_main_loop_get_context(mainloop),
+                                            next_timeout_id) != NULL) {
                                         g_source_remove(next_timeout_id);
                                 }
                                 next_timeout_id = g_timeout_add(sleep/1000, run, NULL);

But that's most likely not the solution, just stopping the symptom.
Quoting https://docs.gtk.org/glib/type_func.Source.remove.html:

It is a programmer error to attempt to remove a non-existent source.

Dunst seems to be doing just that. Unfortunately I'm not familiar with dunst
code base or GLib and am unlikely to be of much further help any time soon.

Here's a GDB backtrace at time of writing the error message:

#0  __GI___libc_write (fd=2, buf=0x555555609b20, nbytes=66) at ../sysdeps/unix/sysv/linux/write.c:25
#1  0x00007ffff7484d4d in _IO_new_file_write (f=0x7ffff763f4e0 <_IO_2_1_stderr_>, data=0x555555609b20, n=66) at fileops.c:1181
        count = <optimized out>
        to_do = 66
#2  0x00007ffff7483014 in new_do_write
    (fp=fp@entry=0x7ffff763f4e0 <_IO_2_1_stderr_>, data=data@entry=0x555555609b20 "CRITICAL: Source ID 16 was not found when attempting to remove it\n", to_do=to_do@entry=66) at /usr/src/debug/glibc/glibc/libio/libioP.h:1030
        count = <optimized out>
#3  0x00007ffff7484f41 in _IO_new_file_xsputn (n=66, data=<optimized out>, f=0x7ffff763f4e0 <_IO_2_1_stderr_>) at fileops.c:1255
        block_size = <optimized out>
        do_write = <optimized out>
        s = <optimized out>
        to_do = <optimized out>
        must_flush = <optimized out>
        count = <optimized out>
        s = <optimized out>
        to_do = 66
#4  _IO_new_file_xsputn (f=0x7ffff763f4e0 <_IO_2_1_stderr_>, data=<optimized out>, n=66) at fileops.c:1197
        s = <optimized out>
        to_do = 66
#5  0x00007ffff74783fb in __GI__IO_fputs
    (str=str@entry=0x555555609b20 "CRITICAL: Source ID 16 was not found when attempting to remove it\n", fp=fp@entry=0x7ffff763f4e0 <_IO_2_1_stderr_>)
    at /usr/src/debug/glibc/glibc/libio/libioP.h:1030
        _IO_acquire_lock_file = 0x7ffff763f4e0 <_IO_2_1_stderr_>
        len = 66
        result = -1
#6  0x00007ffff7719c67 in print_string (stream=0x7ffff763f4e0 <_IO_2_1_stderr_>, string=0x555555609b20 "CRITICAL: Source ID 16 was not found when attempting to remove it\n")
    at ../glib/glib/gmessages.c:3327
        charset = 0x55555560bcf0 "UTF-8"
        ret = <optimized out>
#7  0x00007ffff771d637 in g_printerr (format=<optimized out>) at ../glib/glib/gmessages.c:3476
        args = {{gp_offset = 24, fp_offset = 48, overflow_arg_area = 0x7fffffffccc0, reg_save_area = 0x7fffffffcbf0}}
        string = 0x555555609b20 "CRITICAL: Source ID 16 was not found when attempting to remove it\n"
        free_me = 0x555555609b20 "CRITICAL: Source ID 16 was not found when attempting to remove it\n"
        local_glib_printerr_func = <optimized out>
        __func__ = "g_printerr"
#8  0x00007ffff77181c5 in g_logv (log_domain=0x7ffff77710be "GLib", log_level=G_LOG_LEVEL_CRITICAL, format=<optimized out>, args=args@entry=0x7fffffffcd90)
    at ../glib/glib/gmessages.c:1391
        domain = 0x0
        data = 0x0
        depth = <optimized out>
        log_func = 0x5555555681cd <dunst_log_handler>
        domain_fatal_mask = <optimized out>
        masquerade_fatal = 0
        test_level = G_LOG_LEVEL_CRITICAL
        was_fatal = 0
        was_recursion = 0
        msg_alloc = 0x5555555d2ad0 "Source ID 16 was not found when attempting to remove it"
        msg = 0x5555555d2ad0 "Source ID 16 was not found when attempting to remove it"
        i = 3
#9  0x00007ffff7718494 in g_log (log_domain=<optimized out>, log_level=<optimized out>, format=<optimized out>) at ../glib/glib/gmessages.c:1460
        args = {{gp_offset = 32, fp_offset = 48, overflow_arg_area = 0x7fffffffce70, reg_save_area = 0x7fffffffcdb0}}
#10 0x00007ffff770fb95 in g_source_remove (tag=16) at ../glib/glib/gmain.c:2622
        source = 0x0
        __func__ = "g_source_remove"
#11 0x00005555555662d5 in run (data=0x1) at src/dunst.c:108
        sleep = 9992292
        next_timeout = 97512827481
        next_timeout_id = 16
        reason = 1
        __func__ = "run"
        now = 97516570604
        timeout_at = 97526562896
#12 0x00007ffff79644c8 in call_in_idle_cb (user_data=0x7fffe0005710) at ../glib/gio/gdbusconnection.c:5002
        invocation = 0x7fffe0005710
        vtable = <optimized out>
        registration_id = <optimized out>
        subtree_registration_id = <optimized out>
        ei = 0x555555611900
        es = 0x0
        __func__ = "call_in_idle_cb"
#13 0x00007ffff7710a31 in g_main_dispatch (context=0x55555559a390) at ../glib/glib/gmain.c:3460
        dispatch = 0x7ffff770ca10 <g_idle_dispatch>
        prev_source = 0x0
        begin_time_nsec = 65882494585902
        was_in_call = 0
        user_data = 0x7fffe0005710
        callback = 0x7ffff79643a0 <call_in_idle_cb>
        cb_funcs = 0x7ffff77ff380 <g_source_callback_funcs>
        cb_data = 0x7fffe0005890
        need_destroy = <optimized out>
        source = 0x7fffe0005820
        current = 0x5555555a46a0
        i = 0
#14 g_main_context_dispatch (context=0x55555559a390) at ../glib/glib/gmain.c:4200
#15 0x00007ffff776dcc9 in g_main_context_iterate.isra.0 (context=0x55555559a390, block=block@entry=1, dispatch=dispatch@entry=1, self=<optimized out>)
    at ../glib/glib/gmain.c:4276
        max_priority = 2147483647
        timeout = -1
        some_ready = 1
        nfds = 2
        allocated_nfds = <optimized out>
        fds = <optimized out>
        begin_time_nsec = 65882492244627
#16 0x00007ffff770ffef in g_main_loop_run (loop=0x5555555a4fd0) at ../glib/glib/gmain.c:4479
        __func__ = "g_main_loop_run"
#17 0x00005555555666c5 in dunst_main (argc=1, argv=0x7fffffffd218) at src/dunst.c:227
        verbosity = <optimized out>
        cmdline_config_path = <optimized out>
        dbus_owner_id = 1
        pause_src = 3
        unpause_src = 4
        term_src = 5
        int_src = 6
#18 0x00007ffff7427cd0 in __libc_start_call_main (main=main@entry=0x5555555625d0 <main>, argc=argc@entry=1, argv=argv@entry=0x7fffffffd218)
    at ../sysdeps/nptl/libc_start_call_main.h:58
        self = <optimized out>
        result = <optimized out>
        unwind_buf = {cancel_jmp_buf = {{jmp_buf = {140737488343576, 2591314373424465312, 0, 140737488343592, 140737354125312, 93824992399864, -2591314372001905248, -2591297988229970528}, mask_was_saved = 0}}, priv = {pad = {0x0, 0x0, 0x7fffffffd218, 0x1}, data = {prev = 0x0, cleanup = 0x0, canceltype = -11752}}}
        not_first_call = <optimized out>
#19 0x00007ffff7427d8a in __libc_start_main_impl
    (main=0x5555555625d0 <main>, argc=1, argv=0x7fffffffd218, init=<optimized out>, fini=<optimized out>, rtld_fini=<optimized out>, stack_end=0x7fffffffd208)
    at ../csu/libc-start.c:360
#20 0x0000555555562605 in _start ()

[kaarelen]

I have same issue. (writing here just to get notifications)

[fwsmit]

I have same issue. (writing here just to get notifications)

You can click subscribe to receive notifications. No need to add a comment for that

[fwsmit]

@tobast What do you think of this and the proposed solution?

[tobast]

Whoops, I think I indeed introduced that. Basically, whenever the timer calls run(), if there is no need to set a new timer, the previous timer ID was not cleared — and a subsequent run() would later try to remove it, although it is now expired. See MR above.

[tobast]

@fwsmit hang on, now that I look at it a bit more, I don't understand how it passed my tests. There are more issues here, I need to think about it. Can you reopen this issue?

[fwsmit]

Okay, I'll reopen it :)

[fwsmit]

Maybe it's better to set the timeout id to zero when it's removed

[bynect]

Is this still happening?

[tobast]

Yes, it is not solved yet. Sorry, I did not find the time to focus on this recently, I'll try to do this soon.