Skip to content

smoke: wait until grcli events has subscribed #753

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
christophefontaine merged 1 commit into from
Sep 18, 2026
Merged

smoke: wait until grcli events has subscribed #753

Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
140 changes: 95 additions & 45 deletions smoke/_init.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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 ""
Expand All @@ -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"
Comment on lines +530 to +532

@qodo-free-for-open-source-projects qodo-free-for-open-source-projects Bot Sep 17, 2026

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Action required

2. Event startup can hang indefinitely 🐞 Bug ☼ Reliability

The readiness pipeline waits for the tail -f producer after grep -q exits, while the shell's
ignored pipe signal means the producer only notices the closed reader on a later write. If the
subscription message is the final log record, the function never reaches the level restoration, and
the stated ten-second timeout does not bound the whole pipeline.
Agent Prompt 
## Issue description
The timeout covers only `grep`, while the shell still waits for the persistent `tail -f` process after a successful match.

## Fix Focus Areas
- smoke/_init.sh[512-516]

## Recommended Fix
Run the log follower under explicit lifecycle management: capture its PID, wait for the bounded matcher, and terminate and reap the follower immediately on either success or timeout. Preserve the matcher status before cleanup so timeout still calls `fail`.

ⓘ Copy this prompt and use it to remediate the issue with your preferred AI generation tools

Comment on lines +530 to +532

@qodo-free-for-open-source-projects qodo-free-for-open-source-projects Bot Sep 17, 2026

Copy link
Copy Markdown

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Action required

3. Another subscriber can bypass the wait 🐞 Bug ≡ Correctness

The readiness check accepts any successful GR_EVENT_SUBSCRIBE log record without verifying the
logged client PID belongs to the newly launched event command. During daemon restart, the surviving
routing process reconnects and issues the same request, so its subscription can satisfy the check
while the event command is still racing with subsequent interface creation.
Agent Prompt 
## Issue description
The readiness expression cannot distinguish the smoke event client from other processes subscribing concurrently, particularly the routing process reconnecting after restart.

## Fix Focus Areas
- smoke/_init.sh[498-514]
- main/api.c[335-345]

## Recommended Fix
Launch `grcli events` so its actual process PID is captured, then require both that PID and the successful subscription request in the daemon log. Ensure pipelines or process substitutions do not replace the captured PID with that of `tee` or `awk`.

ⓘ Copy this prompt and use it to remediate the issue with your preferred AI generation tools


grcli log level set grout.api:$level
}

_start_events_stream
Expand All @@ -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
}
Expand Down