Help identifying possible stdin issue?

[JVMerlino]

Ok, I need some help from people who are more familiar with this than me. All of a sudden, pondering on Myrddin is no longer working because it is failing to process commands in a timely manner while pondering. I've been working on the eval only, and none of the relevant command handler code has changed in more than ten years.
However, when I upgraded to VS2019, this line in the function to check if input is available from stdin no longer compiled:

Code: Select all

if (stdin->_cnt > 0)

The error is "_cnt is not a member of _iobuf".

After some Googling, it seemed that replacing it with this would be correct:

Code: Select all

if (_filelength(_fileno(stdin)))

Before I tear the rest of my hair out trying to figure out what's going on (I've already spent several hours on it), can somebody at least confirm for me that those two lines are definitely equivalent?

[JVMerlino]

A little more info has been determined via careful debugging. Hopefully HG can help me here, since he's the expert on this stuff.

I have confirmed, by looking at the GUI logs, that both Winboard and my other testing GUI send these commands to Myrddin in quick succession when an opponent moves:
time
otim
...followed by the opponent move.

When Myrddin is not pondering it handles these properly as it is just waiting for the opponent move before starting to think, so it can process all three commands sequentially before the engine starts thinking.

However, when pondering, the time command comes in and is processed. But then Myrddin never receives the otim command and just keeps pondering. Below is Myrddin's log. It starts pondering, receives and processes the time command (the "YES!" confirms that input is available), and then each of those "no 2/0" is the result of an attempt to check if there's input (the "2/0" confirms that the engine is in normal pondering mode). So, the result is that, even though the GUI has sent "otim", Myrddin sees no input...until I type "resign" in Winboard. Then it gets the otim, the move, and the resign all in one go, again because it has stopped thinking and is just waiting for input.

And finally, I went back to the source for my last release (in 2015) and compiled it with VS2019 and it exhibits the same broken behavior (which obviously wasn't there in the release). So I'm 99% sure it's the compiler. But why??? Are there some default compiler settings that could have caused this?

My brain hurts....

Code: Select all

Pondering on c3e4
think start, setting to ENGINE_THINKING
think start, setting to ENGINE_PONDERING
 1     39      0            2 (c3e4) b8c6 
 1     43      0            8 (c3e4) g8f6 
 2     32      0           71 (c3e4) g8f6 d2d3 f6e4 d3e4 
 3     47      0          243 (c3e4) g8f6 d2d3 b8c6 d3e4 
 4     43      0          587 (c3e4) g8f6 d2d3 b8c6 g1f3 
 5     43      0          967 (c3e4) g8f6 d2d3 b8c6 g1f3 
 6     43      0         1349 (c3e4) g8f6 d2d3 b8c6 g1f3 
 7     43      0         2498 (c3e4) g8f6 d2d3 b8c6 g1f3 
 8     43      0         4062 (c3e4) g8f6 d2d3 b8c6 g1f3 
 9     43      0         6485 (c3e4) g8f6 d2d3 b8c6 g1f3 
10     43      0        10468 (c3e4) g8f6 d2d3 b8c6 g1f3 
11     43      0        16079 (c3e4) g8f6 d2d3 b8c6 g1f3 
12     43      1        28846 (c3e4) g8f6 d2d3 b8c6 g1f3 
no 2/0no 2/0no 2/0no 2/0no 2/013     43     17       293401 (c3e4) g8f6 d2d3 b8c6 g1f3 

YES! 20
> Received time 23000
Handling Command time
< Finished time -- nThinkTime = 5700, nGameMove = 5
no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0

14     59    337      5604609 (c3e4) g8f6! 

no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0

14     57    381      6345927 (c3e4) g8f6 e4f6 e7f6 e2e3 d4e3 g1f3 e3d2 c1d2 d8e7 d1e2 b8c6 f3d4 b8c6 e2e7 

no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0
 
15     55    820     13662402 (c3e4) g8f6 e4f6 e7f6 e2e3 d4e3 g1f3 e3d2 c1d2 b8c6 f1b5 d8e7 d1e2 e7e2 e1e2 c8e6 f3d4 e6c4 e2e1 c4b5 d4b5 

no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0 no 2/0
 YES! 20
> Received otim 24000
Handling Command otim
< otim not supported
YES! 20
> Received c3e4
Handling Command c3e4
In move handling with c3e4
We just got a move -- nSideToMove = 1, nEngineMode == 2, nEngineCommand = 0
Backing out the pondering move
< move accepted: c3e4, nFifty=1
Ponder hit!
YES! 10
> Received result 1-0 {MyrddinComp resigns}

[Ras]

Are there some default compiler settings that could have caused this?

Do you switch off I/O-buffering? Here's what I have during engine startup:

Code: Select all

(void) setvbuf(stdin,  NULL, _IONBF, 0);
(void) setvbuf(stdout, NULL, _IONBF, 0);

[hgm]

I didn't answer before, because I do not use the VS compiler, and I don't know what the _filelength and _fileno functions are supposed to do. I had severe doubts that they would do what you wanted, though.

I suppose that you are testing for input from the search thread through PeekNamedPipe(). The problem is that this tells you how many bytes are waiting in the pipe, but not how many unread bytes there stil are in the stream's input buffer. It appears that streams are commonly implemented by reading as many characters as available, as soon as you try to read from them when the input buffer is empty, and then only deliver the characters the call asked for, and buffer the others. Since WinBoard sends time + otim + usermove in immediate succession, reading the 'time' in the CECP command parser leaves the otim and usermove in the input buffer, and nothing in the pipe. So that the engine will never notice the arrival of otim + usermove through PeekNamedPipe(), and will keep pondering forever.

You solved this by using stdin->_cnt to also check if there is anything in the stream buffer. I was not even aware that this was possible. But apparently it is an undocumented, implementation-dependent trick. Which no longer works in a newer implementation of the stream library functions.

In my engines I solved the problem in a flaky way, relying on the fact that the GUI will always send another command immediately after time or otim, so that there is no harm in doing a blocking read for the next line/command. So these commands immediately loop back to reading the next command, rather than the usual control flow, which would decide what the engine should do after the command is processed (and which would have resumes the pondering in that case). This solves the time/otim problem, but would not be resistant to another rapid succession of commands (such as 'move now' immediately after 'go'). Hence 'flaky', but at reasonable TC it never caused any problems.

It seems PeekNamedPipe() returns the number of characters that are waiting in the pipe. I never used that, but it could be used to fundamentally solve this problem: let the input routine that reads the next line always count how many characters there are in that line, and subtract it from a _cnt variable that you maintain yourself. If it is non-zero you can read without any risk of blocking. If it is zero, use PeakNamedPipe(), and add what it returns to _cnt, and decide then if there is something to read.

[JVMerlino]

Are there some default compiler settings that could have caused this?

Do you switch off I/O-buffering? Here's what I have during engine startup:

Code: Select all

(void) setvbuf(stdin,  NULL, _IONBF, 0);
(void) setvbuf(stdout, NULL, _IONBF, 0);

I had turned it off for stdout, but not stdin. And that worked!!! Thank you so much!

No idea why it wasn't a problem before, though.

[JVMerlino]

I didn't answer before, because I do not use the VS compiler, and I don't know what the _filelength and _fileno functions are supposed to do. I had severe doubts that they would do what you wanted, though.

In my engines I solved the problem in a flaky way, relying on the fact that the GUI will always send another command immediately after time or otim, so that there is no harm in doing a blocking read for the next line/command. So these commands immediately loop back to reading the next command, rather than the usual control flow, which would decide what the engine should do after the command is processed (and which would have resumes the pondering in that case). This solves the time/otim problem, but would not be resistant to another rapid succession of commands (such as 'move now' immediately after 'go'). Hence 'flaky', but at reasonable TC it never caused any problems.

It turns out that I didn't need the stdin->_cnt or the _filelength(_fileno() code at all. Commenting it out made no difference. I/O is annoying.

I had considered doing that "flaky" solution, and even tried changing:

Code: Select all

if (CheckForInput(FALSE))
  HandleCommand();

to

Code: Select all

while (CheckForInput(FALSE))
  HandleCommand();

...but that didn't work. The parameter to CheckForInput() tells it to wait for input or not. Apparently Rasmus had the right idea.