<div dir="ltr"><div dir="ltr">On Wed, May 15, 2024 at 2:59 PM Michal Sekletar <<a href="mailto:msekleta@redhat.com">msekleta@redhat.com</a>> wrote:<br></div><div class="gmail_quote"><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr">Hi everyone,<br><br>I am currently struggling to understand why I am running into D-Bus related timeout on PID 1 API bus, which in turn causes systemd to transition the bus to BUS_CLOSING state and stop all Type=dbus services. Here is a reproducer that was put together by Frantisek.<br><br>#/bin/bash<br>set -eux<br>set -o pipefail<br><br>NMOUNTS=800<br>MPOINT="$(findmnt --mountpoint / --noheading -o SOURCE)"<br>TS="$(date +"%s.%N")"<br><br>systemctl mask --now --runtime systemd-oomd.{socket,service}<br>id testuser || useradd testuser<br>systemctl stop "tmp-mnt*.mount" || :<br>systemctl log-level debug<br><br>for i in {0..100}; do<br>        echo "=== $i ==="<br>        for i in $(seq 0 $NMOUNTS); do<br>                mkdir -p "/tmp/mnt$i"<br>                systemd-mount "$MPOINT" "/tmp/mnt$i" &<br>        done<br>        wait<br>        for i in $(seq 0 $NMOUNTS); do<br>                systemd-umount "/tmp/mnt$i" &<br>        done<br>        wait<br><br>        busctl status --user --machine=testuser@ --no-pager<br>        systemctl stop user@4711.service<br>        (! journalctl --since="@$TS" --grep "Connection terminated")<br>done<br><br>The timeout is detected in process_timeout() in sd-bus, however, the reply_callback which timed out has a message with matching reply_cookie already in the bus read queue (for a long time). How is it possible it wasn't processed in the previous event loop iteration? Clearly in reproducer we force systemd to do a bunch of work, i.e. even loop is getting dispatched all the time? Btw, in order to verify that reply is already sitting in the queue I've compiled systemd with the following patch.<br></div></blockquote><div><br></div><div>Great, my mailer screwed up the patch so if anyone would want to apply it, please take it from Github instead.</div><div><br></div><div><a href="https://github.com/msekletar/systemd/commit/a636dcd44996891b0c841e037cd36eb46c15b681.patch">https://github.com/msekletar/systemd/commit/a636dcd44996891b0c841e037cd36eb46c15b681.patch</a></div><div> <br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left-width:1px;border-left-style:solid;border-left-color:rgb(204,204,204);padding-left:1ex"><div dir="ltr"><br>diff --git a/src/libsystemd/sd-bus/bus-message.h b/src/libsystemd/sd-bus/bus-message.h<br>index 76f0d853d3..16d25e11a7 100644<br>--- a/src/libsystemd/sd-bus/bus-message.h<br>+++ b/src/libsystemd/sd-bus/bus-message.h<br>@@ -119,6 +119,8 @@ struct sd_bus_message {<br>         unsigned n_header_offsets;<br> <br>         uint64_t read_counter;<br>+<br>+        time_t rq_in;<br> };<br> <br> static inline bool BUS_MESSAGE_NEED_BSWAP(sd_bus_message *m) {<br>diff --git a/src/libsystemd/sd-bus/bus-socket.c b/src/libsystemd/sd-bus/bus-socket.c<br>index 07179e0705..6c1bc3e13b 100644<br>--- a/src/libsystemd/sd-bus/bus-socket.c<br>+++ b/src/libsystemd/sd-bus/bus-socket.c<br>@@ -1337,6 +1337,7 @@ static int bus_socket_make_message(sd_bus *bus, size_t size) {<br>         if (t) {<br>                 t->read_counter = ++bus->read_counter;<br>                 bus->rqueue[bus->rqueue_size++] = bus_message_ref_queued(t, bus);<br>+                t->rq_in = time(NULL);<br>                 sd_bus_message_unref(t);<br>         }<br> <br>diff --git a/src/libsystemd/sd-bus/sd-bus.c b/src/libsystemd/sd-bus/sd-bus.c<br>index 22784e8f66..9cc7ce212f 100644<br>--- a/src/libsystemd/sd-bus/sd-bus.c<br>+++ b/src/libsystemd/sd-bus/sd-bus.c<br>@@ -511,6 +511,7 @@ static int synthesize_connected_signal(sd_bus *bus) {<br>         memmove(bus->rqueue + 1, bus->rqueue, sizeof(sd_bus_message*) * bus->rqueue_size);<br>         bus->rqueue[0] = bus_message_ref_queued(m, bus);<br>         bus->rqueue_size++;<br>+        m->rq_in = time(NULL);<br> <br>         return 0;<br> }<br>@@ -2681,6 +2682,7 @@ static int process_timeout(sd_bus *bus) {<br>         struct reply_callback *c;<br>         sd_bus_slot *slot;<br>         bool is_hello;<br>+        unsigned i;<br>         usec_t n;<br>         int r;<br> <br>@@ -2695,6 +2697,15 @@ static int process_timeout(sd_bus *bus) {<br>         if (c->timeout_usec > n)<br>                 return 0;<br> <br>+        for (i = 0; i < bus->rqueue_size; i++) {<br>+                sd_bus_message *q = bus->rqueue[i];<br>+<br>+                if (c->cookie == q->reply_cookie) {<br>+                        log_error("Message was put to read queue %" PRIiMAX " seconds ago.", time(NULL) - q->rq_in);<br>+                        assert_not_reached();<br>+                }<br>+        }<br>+<br>         r = bus_message_new_synthetic_error(<br>                         bus,<br>                         c->cookie,<br>@@ -4464,5 +4475,6 @@ _public_ int sd_bus_enqueue_for_read(sd_bus *bus, sd_bus_message *m) {<br>                 return r;<br> <br>         bus->rqueue[bus->rqueue_size++] = bus_message_ref_queued(m, bus);<br>+        m->rq_in = time(NULL);<br>         return 0;<br> }<div><br></div><div>Once compiled with above patch and running reproducer for some time I am hitting assert_not_reached() and log says that matching reply was in read queue for more than 82 seconds! Any ideas or debugging tips would be highly appreciated.</div><div><br></div><div>Cheers,</div><div>Michal</div><div><br><div><br></div></div></div>
</blockquote></div></div>