Skip to content

Commit b7b1cce

Browse files
authored
examples: Poll for expected server logs in test (#8871)
Fixes: #8046 ## Problem The test is flaky due to a race condition in the driver script. Currently, the script waits for the client to exit and immediately validates the server output: https://github.com/grpc/grpc-go/blob/49e224f832c21df2cd3fe833189c8a50244f0eee/examples/examples_test.sh#L195-L219 In the graceful shutdown example, the expected log is written only after the shutdown is complete: https://github.com/grpc/grpc-go/blob/49e224f832c21df2cd3fe833189c8a50244f0eee/examples/features/gracefulstop/server/main.go#L99 If the test driver validates the server output after the client stream closes but before the server logs the expected message, the test fails. ## Fix This PR updates the test driver to poll for the expected log in the server output, instead of checking it only once. Additionally, the shutdown of the test server is blocked until either the server logs a failure or a success message. ## Validation To reproduce the failure, I added a 1s sleep just before the line `log.Println("Server stopped gracefully.")` in the server code. I verified that the test no longer fails with this fix, even with the artificial delay. RELEASE NOTES: N/A
1 parent 2abe1f0 commit b7b1cce

File tree

2 files changed

+24
-1
lines changed

2 files changed

+24
-1
lines changed

examples/examples_test.sh

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -206,7 +206,18 @@ for example in ${EXAMPLES[@]}; do
206206
# Check server log for expected output if expecting an
207207
# output
208208
if [ -n "${EXPECTED_SERVER_OUTPUT[$example]}" ]; then
209-
if ! grep -q "${EXPECTED_SERVER_OUTPUT[$example]}" $SERVER_LOG; then
209+
found=false
210+
211+
# Poll for up to 10 seconds.
212+
for i in {1..10}; do
213+
if grep -q "${EXPECTED_SERVER_OUTPUT[$example]}" "$SERVER_LOG"; then
214+
found=true
215+
break
216+
fi
217+
sleep 1
218+
done
219+
220+
if [ "$found" = "false" ]; then
210221
fail "server log missing output: ${EXPECTED_SERVER_OUTPUT[$example]}
211222
got server log:
212223
$(cat $SERVER_LOG)

examples/features/gracefulstop/server/main.go

Lines changed: 12 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -85,6 +85,7 @@ func main() {
8585
s := grpc.NewServer()
8686
ss := &server{streamStart: make(chan struct{})}
8787
pb.RegisterEchoServer(s, ss)
88+
serverStopped := make(chan struct{}, 1)
8889

8990
go func() {
9091
<-ss.streamStart // wait until server streaming starts
@@ -93,13 +94,24 @@ func main() {
9394
timer := time.AfterFunc(10*time.Second, func() {
9495
log.Println("Server couldn't stop gracefully in time. Doing force stop.")
9596
s.Stop()
97+
// Unblock the main function.
98+
select {
99+
case serverStopped <- struct{}{}:
100+
default:
101+
}
96102
})
97103
defer timer.Stop()
98104
s.GracefulStop() // gracefully stop server after in-flight server streaming rpc finishes
99105
log.Println("Server stopped gracefully.")
106+
// Unblock the main function.
107+
select {
108+
case serverStopped <- struct{}{}:
109+
default:
110+
}
100111
}()
101112

102113
if err := s.Serve(lis); err != nil {
103114
log.Fatalf("failed to serve: %v", err)
104115
}
116+
<-serverStopped
105117
}

0 commit comments

Comments
 (0)