Back to blog

Stockfish said readyok twice and my app read it once

When Stockfish refused a setting, my app reported it and left the ready reply behind it unread. The next check took that old reply as its own and passed.

• 5 min read •
rust stockfish uci testing

For about two weeks in September, if Stockfish refused two settings in a row, my chess app reported the first and let the second pass as fine. The check on the second setting had read an answer that belonged to the first. The app is a desktop chess GUI and terminal CLI in Rust that plays and analyses with Stockfish. The bug was one early return, and I had added it on purpose.

Stockfish has no window of its own, so my app starts it as a separate program. The app writes commands to Stockfish's standard input, or stdin, and reads the answers from its standard output, stdout. Each direction is a pipe, a one-way channel the operating system gives two programs to pass bytes along. What goes over it is UCI, the Universal Chess Interface, one command or answer per line.

Two commands matter here. setoption name X value Y changes a setting, which UCI calls an option, and the protocol defines no reply to it. isready asks Stockfish whether it has finished with everything sent so far. The UCI description says it must always be answered with readyok. So after a setting, my app sends isready and waits for readyok. That reply is one bare word and doesn't say which isready it answers, so order is the only link.

The UCI description asks an engine to ignore anything it doesn't understand. Stockfish is more helpful. Give it a setting it doesn't have and it prints a line saying so, then answers the next isready as normal. This is what Stockfish 18 prints today, with the start-up lines cut:

$ printf 'uci\nsetoption name Bogus value 1\nisready\nsetoption name Other value 1\nisready\nquit\n' | stockfish
uciok
No such option: Bogus
readyok
No such option: Other
readyok

The cause was a change I made on 12 September. Before it, the wait skipped every line that wasn't readyok, so a refused setting vanished without a word. That commit made the wait fail the moment it saw a refusal, which let the app show it. Here is the loop just before the fix:

while let Some(line) = self.next_line().await {
    if line == "readyok" {
        return Ok(());
    }
    if is_refusal(&line) {
        return Err(anyhow::anyhow!("{line}"));
    }
}

That return Err looks like the careful thing to do, and it is the whole bug. My own comment above is_refusal, the function that spots these lines, says Stockfish still sends readyok afterwards. The comment knew, but the loop didn't act on it.

Take two refused settings in a row, Bogus and then Other:

app sends                 Stockfish prints       old wait returns
setoption Bogus, isready  No such option: Bogus  error for Bogus
                          readyok, left unread
setoption Other, isready  No such option: Other  ready, wrongly
                          readyok
isready                   readyok                error for Other, late

The first wait reads the refusal and rightly returns an error, but the readyok behind it stays unread. The second wait sends its own isready, and the first line it reads is that old readyok. So it reports ready without waiting for the answer to its own question. The refusal of Other sits in the pipe and comes out as the next wait's error, one question late. It happens whenever two waits in a row each meet a refusal.

Nothing in the pipe tells the two readyok lines apart. A pipe is a stream of bytes, and its manual page says there is "no concept of message boundaries". Only the count of lines pairs an answer with its question, and the early return broke the count. Every question gets exactly one answer, and if you walk away before it comes, it waits and answers your next question instead.

The fix on 27 September keeps the refusal and reads on to readyok:

let mut refusal = None;
while let Some(line) = self.next_line().await {
    if line == "readyok" {
        return refusal.map_or(Ok(()), |line| Err(anyhow::anyhow!("{line}")));
    }
    if is_refusal(&line) {
        refusal.get_or_insert(line);
    }
}

A turn now ends at readyok, never at the first interesting line. A refusal seen on the way becomes the error at that point, and get_or_insert keeps only the first one. The function's comment now explains why it reads on, for whoever next feels like adding an early return. That could well be me.

The tests don't start the real Stockfish. They start sh, the Unix shell, running a tiny loop that reads a command and answers the way an engine would. Each test slots in extra answers where {arms} sits:

let mut command = Command::new("sh");
command.arg("-c").arg(format!(
    "while read cmd; do case $cmd in \
     uci) echo uciok;; isready) echo readyok;; {arms} \
     esac; done"
));

For this bug the test passes in setoption*) echo 'No such option: x';;, so every setting is refused. It sends two settings and expects both to fail. Then one plain wait must come back clean, which shows no refusal was left waiting. On the old code the second setting comes back fine, so the test fails there. I think a fake like this is worth copying for any code that drives another program, because a few lines of shell let you script the other side exactly.

You don't need chess to hit this. Whenever replies carry no id, every way out of a wait has to read to the line that ends the turn. The error path is the easy one to miss, because returning early on an error feels careful. So look at every return inside a read loop and ask what is still in the pipe when it leaves. Then write a test that sends two failing requests in a row, since one failure on its own looks fine.

Sources and further reading: