From 43fb6e648c5141ebaa48adfcd77926a5f14b1861 Mon Sep 17 00:00:00 2001 From: Robin Jarry Date: Thu, 17 Sep 2026 17:52:36 +0200 Subject: [PATCH] smoke: wait until grcli events has subscribed The event stream is started in the background and races with interface creation. If the subscription lands after an interface is created, its add event is missed and grcli prints the interface by its numeric id, which breaks wait_event pattern matching. This happens regularly on slow CI runners and never locally. Redirect the grout logs to files and tail them, so the harness can watch them. When starting the event stream, temporarily raise the grout.api log level to debug and block until the daemon logs the successful GR_EVENT_SUBSCRIBE before returning. Interfaces are then only created once the stream is guaranteed to receive their events. Signed-off-by: Robin Jarry --- smoke/_init.sh | 140 +++++++++++++++++++++++++++++++++---------------- 1 file changed, 95 insertions(+), 45 deletions(-) diff --git a/smoke/_init.sh b/smoke/_init.sh index 8893ec35a..f2319452b 100644 --- a/smoke/_init.sh +++ b/smoke/_init.sh @@ -142,6 +142,9 @@ stop_grout() { tmux kill-window -t gdb fi + kill -9 "$grout_log_pid" "$grout_err_pid" \ + "$grcli_events_pid" "$grcli_events_log_pid" 2>/dev/null || true + if [ "$ret" -ne 0 ]; then status="$ret" if [ "$ret" -gt 128 ]; then @@ -376,8 +379,44 @@ fi echo "INTERACTIVE=${INTERACTIVE:-false} GDB=${GDB:-false} PAUSE_ON_FAILURE=${PAUSE_ON_FAILURE:-false}" +grout_pid= +grout_log_pid= +grout_err_pid= +grcli_events_pid= +grcli_events_log_pid= + set -x +_start_grout() { + $local_grout_cmd >$tmp/grout.log 2>$tmp/grout.err & + grout_pid=$! + + if [ -t 1 ]; then + # print grout logs in blue (stderr in bold red) + tail -f $tmp/grout.log > >(awk '{print "\033[34m" $0 "\033[0m"}') & + grout_log_pid=$! + tail -f $tmp/grout.err > >(awk '{print "\033[1;31m" $0 "\033[0m"}') >&2 & + grout_err_pid=$! + else + tail -f $tmp/grout.log & + grout_log_pid=$! + tail -f $tmp/grout.err >&2 & + grout_err_pid=$! + fi +} + +_wait_grout_started() { + SECONDS=0 + while ! socat FILE:/dev/null UNIX-CONNECT:$GROUT_SOCK_PATH 2>/dev/null; do + if [ "$SECONDS" -gt 30 ]; then + gdb -p "$grout_pid" -batch -ex 'thread apply all bt' grout + fail "grout took more than 30s to start" + fi + kill -0 "$grout_pid" + sleep 1 + done +} + if [ "$run_grout" = true ]; then smoke_setenv ASAN_OPTIONS disable_coredump=0 if [ "$use_hardware_ports" = false ]; then @@ -409,15 +448,8 @@ if [ "$run_grout" = true ]; then tmux new-window -d -n gdb gdb \ -ex 'handle SIGTERM nostop print pass' \ --args $local_grout_cmd - elif [ -t 1 ]; then - # print grout logs in blue (stderr in bold red) - $local_grout_cmd \ - > >(awk '{print "\033[34m" $0 "\033[0m"}') \ - 2> >(awk '{print "\033[1;31m" $0 "\033[0m"}' >&2) & - grout_pid=$! else - $local_grout_cmd & - grout_pid=$! + _start_grout fi fi if [ "${GDB:-false}" = true ]; then @@ -426,15 +458,7 @@ if [ "${GDB:-false}" = true ]; then gdb_pid=$(tmux list-windows -F '#{window_name} #{pane_pid}' | awk '/gdb/{print $2}') grout_pid=$(pgrep -P $gdb_pid | head -n1) else - SECONDS=0 - while ! socat FILE:/dev/null UNIX-CONNECT:$GROUT_SOCK_PATH 2>/dev/null; do - if [ "$SECONDS" -gt 30 ]; then - gdb -p "$grout_pid" -batch -ex 'thread apply all bt' grout - fail "grout took more than 30s to start" - fi - kill -0 "$grout_pid" - sleep 1 - done + _wait_grout_started fi smoke_setenv GROUT_PAGER "" @@ -458,23 +482,56 @@ fi # Truncates events.log and resets __event_mark so wait_event reads # from the new line 1 onwards. _start_events_stream() { - case "${follow_events:-true}" in - hide) - grcli events > $tmp/events.log & - ;; - false) - touch $tmp/events.log - ;; - *) - if [ -t 1 ]; then - # print events in yellow - grcli events | tee $tmp/events.log | awk '{print "\033[33m" $0 "\033[0m"}' & - else - grcli events | tee $tmp/events.log & - fi - ;; - esac __event_mark=0 + + if [ "${follow_events:-true}" = false ]; then + touch $tmp/events.log + return + fi + + local end level wait_subscribe=false + + # Only the daemon we spawned ourselves writes to $tmp/grout.log. When + # connecting to an already running daemon (run_grout=false) or running + # under gdb, the file does not exist and subscription readiness cannot be + # detected from it. + if [ -f "$tmp/grout.log" ]; then + wait_subscribe=true + end=$(wc -l < $tmp/grout.log) + level=$(grcli -j log level show | jq -re '.[] | select(.name == "grout.api") .level') + + # Enable api debug logs so we can detect when grcli has subscribed. + # The stream is started in the background and racing with interface + # creation: if we returned before the subscription is active, the + # first iface add events would be missed and never resolved. + grcli log level set grout.api:debug + fi + + grcli events > $tmp/events.log & + grcli_events_pid=$! + + if [ "${follow_events:-true}" = true ]; then + if [ -t 1 ]; then + # print events in yellow + tail -f $tmp/events.log > >(awk '{print "\033[33m" $0 "\033[0m"}') & + grcli_events_log_pid=$! + else + tail -f $tmp/events.log & + grcli_events_log_pid=$! + fi + fi + + if [ "$wait_subscribe" = false ]; then + return + fi + + # Wait until the daemon logs our own subscription before returning so + # that no interface event is missed. + { tail -f -n +$((end + 1)) $tmp/grout.log || : ; } | + timeout 10 grep -qE "pid=$grcli_events_pid\>.*GR_EVENT_SUBSCRIBE.*Success" || + fail "timeout after 10s waiting for grcli events" + + grcli log level set grout.api:$level } _start_events_stream @@ -484,25 +541,18 @@ _start_events_stream # with grout). The events log is truncated and the mark is reset by # _start_events_stream, so the caller can directly use wait_event after. restart_grout() { - kill -9 "$grout_pid" || true + kill -9 "$grout_pid" \ + "$grout_log_pid" "$grout_err_pid" \ + "$grcli_events_pid" "$grcli_events_log_pid" || true SECONDS=0 while kill -0 "$grout_pid" 2>/dev/null; do [ "$SECONDS" -gt 5 ] && fail "grout still alive after SIGKILL" sleep 0.1 done - kill %?grcli 2>/dev/null || true - wait %?grcli 2>/dev/null || true + _start_grout - $local_grout_cmd & - grout_pid=$! - - SECONDS=0 - while ! socat FILE:/dev/null UNIX-CONNECT:$GROUT_SOCK_PATH 2>/dev/null; do - [ "$SECONDS" -gt 30 ] && fail "respawned grout did not open its socket" - kill -0 "$grout_pid" || fail "respawned grout died" - sleep 0.2 - done + _wait_grout_started _start_events_stream }