Expected data missing from child process stdout stream

Sorry for the bad title, I couldn't come up with anything more descriptive. I have a function like this:

pub fn evaluate(&mut self, position: &str, depth: u8) -> LicheszterResult<()> {
        let mut child = Command::new("./Stockfish/src/stockfish").stdin(Stdio::piped()).stdout(Stdio::piped()).spawn()?;
        let mut stdin = child.stdin.take().unwrap();
        let buffer = format!("go position {} depth {}\n", &position, &depth.to_string().as_str());
        println!("{}", stdin.write(buffer.as_bytes())?);
        let mut stdout = child.stdout.take().unwrap();
        println!("{}", stdout.read_to_string(&mut String::new())?);
        Ok(())
    }

This function (or a rather awful prototype of one) should be used to write to Stockfish chess engine standard input and then get the standard output in return (it should produce output when given input). However, when I run this function I get this output:

30

That is the usize of the bytes written to the standard input, and it is completely correct. However, it never prints out the output and I have no clue why. Am I doing the stdout part somehow wrong? I'm relatively new to Rust.

That is the usize of the bytes written to the standard input, and it is completely correct. However, it never prints out the output and I have no clue why.

Look at the documentation of read_to_string:

fn read_to_string(&mut self, buf: &mut String) -> Result<usize>

Read all bytes until EOF in this source, appending them to buf.

You are handing it &mut String::new(), so the string is a temporary, thrown away after read_to_string() returns. You need to actually use it, which means assigning it to a variable so you can read into it and then print it.

        let mut output = String::new();
        stdout.read_to_string(&mut output)?;
        println!("{}", output);

(The numeric return value can be ignored since it's always the same as output.len() in this case where output starts empty.)

Two more things:

  • Your write() is also incorrect, because write() is allowed to write less than all the data it was given (because the system call that usually underlies it also works that way). You should use write_all() instead, which is guaranteed to write all of the data or return an error.
  • This is probably not applicable to your program (I assume you are planning to interpret the string, eventually), but if you intend to just display the output, you should not use Stdio::piped() but Stdio::inherit() to let the program's stdout use your stdout. This is more efficient (less copying), allows the output to be viewed as it is produced rather than only after the child process exits, and avoids full-buffer deadlocking if you are writing lots more data than you are here.

I changed the output to be stored in a variable as you suggested, but the end result remains the same: no output is printed. I also tried to use Stdio::inherit() but it gives me this error:

thread 'main' panicked at 'called `Option::unwrap()` on a `None` value', src/engine.rs:79:44
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace

To me, this looks like the ChildStdin doesn't exist because the Option returns None. Any suggestions?

I changed the output to be stored in a variable as you suggested, but the end result remains the same: no output is printed.

Strange, because previously we established there are 30 bytes. Try this:

    println!("{:?}", output);

That way it will be printed with quotes and escapes, so you can see exactly what characters are in the string — even if it is empty you will see "".


I also tried to use Stdio::inherit() but it gives me this error … this looks like the ChildStdin doesn't exist because the Option returns None.

Yes; the point of inherit is that it doesn't redirect the output. So, if you use it, there is no stdout pipe available to take. If you use inherit then you can't read the output, but you also don't need to if you only want it printed.

That's why I said it probably isn't what you want, because I assume you plan to parse the output of the program. I mentioned it because "capture the output and immediately print it" is an antipattern; it is worse in several ways than simply inheriting. But if you do intend for your program to do something with the output, piped() is appropriate and inherit() is not.

The problem is that read_to_string reads all the bytes from a Read implementor, and for a ChildStdout that means it must wait until the child process has exited, so your program must wait for stockfish to exit.

But stockfish is not exiting, presumably because after writing the output of your first command, it waits for your program to give it another command. Both processes are waiting for the other to do something - you have a deadlock.

You probably just need to close (by dropping) the stdin after writing to it it:

pub fn evaluate(&mut self, position: &str, depth: u8) -> LicheszterResult<()> {
        let mut child = Command::new("./Stockfish/src/stockfish").stdin(Stdio::piped()).stdout(Stdio::piped()).spawn()?;
        let mut stdin = child.stdin.take().unwrap();
        let buffer = format!("go position {} depth {}\n", &position, &depth.to_string().as_str());
        println!("{}", stdin.write(buffer.as_bytes())?);
        drop(stdin);
        let mut stdout = child.stdout.take().unwrap();
        println!("{}", stdout.read_to_string(&mut String::new())?);
        Ok(())
    }

Dropping stdin indeed gives me output, but it still looks like something is off. The given output is:

Stockfish 200622 by the Stockfish developers (see AUTHORS file)
info string NNUE evaluation using nn-3c0aa92af1da.nnue enabled
bestmove a2a3

However, the output should look like this (tested with a manual run):

Stockfish 200622 by the Stockfish developers (see AUTHORS file)
info string NNUE evaluation using nn-3c0aa92af1da.nnue enabled
info depth 1 seldepth 1 multipv 1 score cp 46 nodes 20 nps 20000 tbhits 0 time 1 pv d2d4
info depth 2 seldepth 2 multipv 1 score cp 71 nodes 67 nps 33500 tbhits 0 time 2 pv e2e4
info depth 3 seldepth 2 multipv 1 score cp 71 nodes 169 nps 84500 tbhits 0 time 2 pv e2e4
info depth 4 seldepth 3 multipv 1 score cp 75 nodes 288 nps 96000 tbhits 0 time 3 pv g2g3 a7a6 d2d4
info depth 5 seldepth 4 multipv 1 score cp 71 nodes 448 nps 112000 tbhits 0 time 4 pv e2e4
info depth 6 seldepth 3 multipv 1 score cp 96 nodes 679 nps 113166 tbhits 0 time 6 pv e2e4 d7d5
info depth 7 seldepth 7 multipv 1 score cp 58 nodes 2728 nps 136400 tbhits 0 time 20 pv c2c4 c7c5 g1f3 g7g6
info depth 8 seldepth 8 multipv 1 score cp 49 nodes 5616 nps 140400 tbhits 0 time 40 pv e2e4 e7e6 c2c4 d7d5 c4d5 e6d5 e4d5
info depth 9 seldepth 9 multipv 1 score cp 46 nodes 10005 nps 185277 tbhits 0 time 54 pv e2e4 e7e5 g1f3 b8c6 d2d4 e5d4 f3d4
info depth 10 seldepth 11 multipv 1 score cp 58 nodes 22188 nps 288155 tbhits 0 time 77 pv e2e4 e7e5 g1f3 g8f6 d2d4 e5d4 e4e5 f6g4
bestmove e2e4 ponder e7e5

As you can see, in my program Stockfish gives an incorrect best move. What could cause this? It looks like the process exits too early or something.

EDIT: it seems like the same output occurs no matter the analysed position. So something is definitely off here.

You could try use the shell instead of your program to do what should be the same thing:

echo 'go position X depth Y' | ./Stockfish/src/stockfish | cat

(The ending | cat is to ensure that stockfish sees a pipe, not a tty, as its stdout.)

Then see if it does the same thing, and try variations on the commands. In principle you can do the same thing with Rust code but this might be a faster way to experiment. Let me emphasize that — you need to experiment. In order to find out why something's different, you need to figure out what you're doing differently. Try runs of the command that are in-between what your program is currently doing and what your "manual run" was.

1 Like