Winboard 4.4.1 : a bug in NPS mode ?

[Francois]

Hi,

I am trying to play games in NPS mode (using -firstNPS and -secondNPS).
Most of the time it works OK, but for a given starting position and set of opponents, winboard (?) seems to go nuts.
The game is between my engine (BugChess2 1.6.4) and the last Twisted Logic version. I am using the custom Polyglot version HGM built for me for Twisted, and winboard 4.4.1. Both engines play at 40/10sec with NPS=900000 from a certain starting pos. After the first move we can see in the winboard debug file that the sent time and otim comand drop from 1000 to 1 centisec, and it seems the reason why twisted gets stuck at the end (with only 1 centisec left to think) - and then back from 1 to 1000 whereas it should decrease regularly.
Any idea of what could go wrong ?

Thanks !

François

my winboard debug file :

recognized 'normal' (-1) as variant normal
WinBoard 4.4.1 + BugChess2_V1_6_4.exe
Reset(1, 0) from gameMode 0
recognized 'normal' (-1) as variant normal
GameEnds(0, (null), 2)
shuffleOpenings = 0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
StartChildProcess (dir="C:\TempFK\DistributedFPKWBTM\BugChess2_V1_6_4") BugChess2_V1_6_4.exe -winboard
516 >first : xboard
protover 2
516 <first : feature done=0
516 >first : accepted done
781 <first : feature ping=1 setboard=1 playother=1 san=1 time=1 draw=0 sigint=0 sigterm=0 analyze=1 myname="BugChess2 V1.6.4" variants="normal" colors=0 name=1 nps=1 done=1
781 >first : accepted ping
781 >first : accepted setboard
781 >first : accepted playother
781 >first : accepted san
781 >first : accepted time
781 >first : accepted draw
781 >first : accepted sigint
781 >first : accepted sigterm
781 >first : accepted analyze
781 >first : accepted myname
781 >first : accepted variants
781 >first : accepted colors
781 >first : accepted name
781 >first : accepted nps
781 >first : accepted done
797 >first : new
random
797 >first : level 40 0:10 0
797 >first : nps 900000
797 >first : post
797 >first : hard
797 >first : easy
797 >first : ping 1
FEN castling rights: -1 -1 -1 7 0 4
797 >first : force
write FEN 50-move: 0 0 0
e0. p=-4
797 >first : setboard rq2kb1r/1b1n1ppp/pp2pn2/2p5/3P4/2NBPN2/PP2QPPP/R1BR2K1 w kq - 0 1
-1 -1 -1 7 0 4
-1 -1 -1 -1 -1 -1
7 0 4 7 0 4
Load Position
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
StartChildProcess (dir="C:\TempFK\DistributedFPKWBTM\Polyglot") polyglot.exe TwistedLogic_20090922.ini
1297 >second: xboard
protover 2
1297 <second: PolyGlot 1.4.38x by Fabien Letouzey.
1297 <first : pong 1
1297 <second: feature done=0
1297 >second: accepted done
1297 <second: feature analyze=1
1297 >second: accepted analyze
1297 <second: feature colors=0
1297 >second: accepted colors
1297 <second: feature draw=1
1297 >second: accepted draw
1297 <second: feature ics=1
1297 >second: accepted ics
1297 <second: feature myname="Twisted Logic 20090922"
1297 >second: accepted myname
1297 <second: feature name=1
1297 >second: accepted name
1297 <second: feature pause=0
1297 >second: accepted pause
1297 <second: feature ping=1
1297 >second: accepted ping
1297 <second: feature playother=1
1297 >second: accepted playother
1297 <second: feature reuse=1
1297 >second: accepted reuse
1297 <second: feature san=0
1297 >second: accepted san
1297 <second: feature setboard=1
1297 >second: accepted setboard
1297 <second: feature sigint=0
1297 >second: accepted sigint
1297 <second: feature sigterm=0
1297 >second: accepted sigterm
1297 <second: feature time=1
1297 >second: accepted time
1297 <second: feature usermove=1
1297 >second: accepted usermove
1297 <second: feature nps=1
1297 >second: accepted nps
1297 <second: feature memory=1
1297 >second: accepted memory
1297 <second: feature smp=0
1297 >second: accepted smp
1297 <second: feature egt=""
1297 >second: accepted egt
1297 <second: feature variants="normal"
1297 >second: accepted variants
1297 <second: feature option="Pawn Hash -spin 16 1 32"
1297 >second: accepted option
1297 <second: feature option="OwnBook -check 1"
1297 >second: accepted option
1313 <second: feature option="Book File -file twistedbook.bin"
1313 >second: accepted option
1313 <second: feature option="Book Move Limit -spin 128 1 256"
1313 >second: accepted option
1313 <second: feature option="Display Book Moves -check 0"
1313 >second: accepted option
1313 <second: feature option="Time Buffer -spin 1000 0 10000"
1313 >second: accepted option
1313 <second: feature option="Transposition Table -check 1"
1313 >second: accepted option
1313 <second: feature option="Null Move Pruning -check 1"
1313 >second: accepted option
1313 <second: feature option="Null Move Verification -check 1"
1313 >second: accepted option
1313 <second: feature option="Null Move Fail High -check 1"
1313 >second: accepted option
1313 <second: feature option="Null Threat -check 1"
1313 >second: accepted option
1313 <second: feature option="Zero Recapture Extension -check 0"
1313 >second: accepted option
1313 <second: feature option="Internal Iterative Deepening -check 1"
1313 >second: accepted option
1313 <second: feature option="Internal Iterative Deepening Solid -check 1"
1313 >second: accepted option
1313 <second: feature option="Internal Iterative Deepening Depth -spin 5 1 15"
1313 >second: accepted option
1313 <second: feature option="Delta Pruning -check 1"
1313 >second: accepted option
1313 <second: feature option="Delta Pruning Solid -check 1"
1313 >second: accepted option
1313 <second: feature option="Delta Pruning Threshold -spin 50 0 500"
1313 >second: accepted option
1313 <second: feature option="Quiescence Check Depth -spin 5 1 15"
1313 >second: accepted option
1313 <second: feature option="Selectivity -check 0"
1313 >second: accepted option
1313 <second: feature option="Selectivity Base -spin 3 1 15"
1313 >second: accepted option
1313 <second: feature option="Selectivity Threshold -spin 125 0 500"
1313 >second: accepted option
1313 <second: feature option="Selectivity Cutoff -spin 125 0 500"
1313 >second: accepted option
1313 <second: feature option="Zero Pruning -check 1"
1313 >second: accepted option
1313 <second: feature option="Zero Pruning Base -spin 9 1 15"
1313 >second: accepted option
1313 <second: feature option="Zero Pruning Threshold -spin 100 0 500"
1313 >second: accepted option
1313 <second: feature option="Zero Pruning Multiplier -spin 50 0 500"
1313 >second: accepted option
1313 <second: feature option="Speculation Aggressive -check 0"
1313 >second: accepted option
1313 <second: feature option="Speculation PV -check 1"
1313 >second: accepted option
1313 <second: feature option="Speculation PV Level -spin 12 0 30"
1313 >second: accepted option
1313 <second: feature option="Extended Speculation PV -check 0"
1313 >second: accepted option
1313 <second: feature option="Extended Speculation PV Level -spin 12 0 30"
1313 >second: accepted option
1313 <second: feature option="Speculation -check 1"
1313 >second: accepted option
1313 <second: feature option="Speculation Base -spin 3 2 15"
1313 >second: accepted option
1313 <second: feature option="Speculation Level -spin 4 2 30"
1313 >second: accepted option
1313 <second: feature option="Extended Speculation -check 1"
1313 >second: accepted option
1313 <second: feature option="Extended Speculation Base -spin 4 3 15"
1313 >second: accepted option
1313 <second: feature option="Extended Speculation Level -spin 4 2 30"
1313 >second: accepted option
1313 <second: feature option="Eval Grain Size -spin 0 0 4"
1313 >second: accepted option
1313 <second: feature option="Fill Hash With PV -check 1"
1313 >second: accepted option
1313 <second: feature option="King Attacks Aggression Level -spin 4 0 20"
1313 >second: accepted option
1313 <second: feature option="UCI_ShowCurrLine -check 0"
1328 >second: accepted option
1328 <second: feature option="UCI_EngineAbout -file Twisted Logic by Edsel Apostol"
1328 >second: accepted option
1328 <second: feature option="Polyglot Polyglot Version -combo 1.4.38x"
1328 >second: accepted option
1328 <second: feature option="Polyglot Log -check 1"
1328 >second: accepted option
1328 <second: feature option="Polyglot LogFile -file TwistedLogic_20090922.log"
1328 >second: accepted option
1328 <second: feature option="Polyglot OptionFile -file TwistedLogic_20090922.ini"
1328 >second: accepted option
1328 <second: feature option="Polyglot Book -check 0"
1328 >second: accepted option
1328 <second: feature option="Polyglot BookFile -file book.bin"
1328 >second: accepted option
1328 <second: feature option="Polyglot BookRandom -check 1"
1328 >second: accepted option
1328 <second: feature option="Polyglot BookDepth -spin 256 0 256"
1328 >second: accepted option
1328 <second: feature option="Polyglot BookLearn -check 0"
1328 >second: accepted option
1328 <second: feature option="Polyglot BookTreshold -spin 5 0 1000"
1328 >second: accepted option
1328 <second: feature option="Polyglot Resign -check 0"
1328 >second: accepted option
1328 <second: feature option="Polyglot ResignMoves -spin 3 0 10000"
1328 >second: accepted option
1328 <second: feature option="Polyglot ResignScore -spin 800 0 10000"
1328 >second: accepted option
1328 <second: feature option="Polyglot MateScore -spin 10000 0 100000"
1328 >second: accepted option
1328 <second: feature option="Polyglot ShowPonder -check 0"
1328 >second: accepted option
1328 <second: feature option="Polyglot UCIVersion -spin 2 1 2"
1328 >second: accepted option
1328 <second: feature option="Polyglot RepeatPV -check 1"
1328 >second: accepted option
1328 <second: feature option="Polyglot SyncStop -check 0"
1328 >second: accepted option
1328 <second: feature option="Polyglot CanPonder -check 0"
1328 >second: accepted option
1328 <second: feature option="Polyglot PromoteWorkAround -check 0"
1328 >second: accepted option
1328 <second: feature option="Save polyglot.ini -save"
1328 >second: accepted option
1328 <second: feature done=1
1328 >second: accepted done
1344 >second: memory 68
1344 >second: new
random
1344 >second: ics -
1344 >second: level 40 0:10 0
1344 >second: nps 900000
1344 >second: post
1344 >second: hard
1344 >second: easy
1344 >second: ping 1
1344 >second: force
write FEN 50-move: 0 0 0
e0. p=-4
1344 >second: setboard rq2kb1r/1b1n1ppp/pp2pn2/2p5/3P4/2NBPN2/PP2QPPP/R1BR2K1 w kq - 0 1
Two Machines
1344 >first : computer
1344 >first : name Twisted Logic 20090922
1344 >second: computer
1344 >second: name BugChess2 V1.6.4
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
time odds: 1 1
1344 >first : time 1000
1344 >first : otim 1000
book hit = (NULL)
1344 >first : go
nps: w=900000, b=900000
1344 <second: pong 1
1703 <first : 8 -19 34 155802 d4xc5 d7xc5 d3-c2 f8-d6 e3-e4 e8-g8 c1-g5 f8-d8
1703 <first : move dxc5
machine move 0, castling = -1 -1 -1 7 0 4
move to parse: dxc5
7 0 4 7 0 4 Legality test? d4c5
-1 -1 -1 7 0 4 Legality test? d4c5
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=0 (3,3)-(2,4) -
7 0 4 7 0 4 Legality test? d4c5
movetype=33, promochar=0=-
MateTest: K=1, my=14, his=15
move: d4c5
, parse: dxc5 (
)
MateTest: K=1, my=14, his=15
repeat test fmm=1 bmm=0 ep=-4, reps=4
1 ep=-3
0 ep=-4
time odds: 1 1
1719 >second: time 1000
1719 >second: otim 1
book hit = (NULL)
1719 >second: usermove 1719 >second: d4c5
1719 >second: go
silence
1844 <second: 8 -42 12 87477 Bxc5 Na4 O-O e4 Bd6 Bg5 h6 Bd2 Rc8
2031 <second: 8 -42 31 225000 Bxc5 Na4 O-O e4 Bd6 Bg5 h6 Bd2 Rc8
2031 <second: move f8c5
machine move 1, castling = -1 -1 -1 7 0 4
move to parse: f8c5
7 0 4 7 0 4 Legality test? f8c5
-1 -1 -1 7 0 4 Legality test? f8c5
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=24 (5,7)-(2,4) -
MateTest: K=1, my=14, his=14
move: f8c5
, parse: Bxc5 (
)
MateTest: K=1, my=14, his=14
repeat test fmm=2 bmm=0 ep=-4, reps=4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2031 >first : time 1
2031 >first : otim 1
book hit = (NULL)
2031 >first : Bxc5
silence
2047 <first : 3 -13 0 2934 d3-c2 e8-g8 a2-a4
2047 <first : move Bc2
machine move 2, castling = -1 -1 -1 7 0 4
move to parse: Bc2
Parser Qa1: yyleng=3, 2(-1,-1)-(2,1) = 0 ( )
Disambiguate in: 2(-1,-1)-(2,1) = 0 (-)
Disambiguate out: 2(3,2)-(2,1) = 0 (-)
-1 -1 -1 7 0 4 Legality test? d3c2
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=2 (3,2)-(2,1) -
MateTest: K=1, my=14, his=14
move: d3c2
, parse: Bc2 (
)
MateTest: K=1, my=14, his=14
repeat test fmm=3 bmm=0 ep=-4, reps=4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2047 >second: time 1
2047 >second: otim 1000
book hit = (NULL)
2047 >second: usermove 2047 >second: d3c2
silence
2047 <second: move e8g8
machine move 3, castling = -1 -1 -1 7 0 4
move to parse: e8g8
7 0 4 7 0 4 Legality test? e8g8
-1 -1 -1 7 0 4 Legality test? e8g8
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=43 (4,7)-(6,7) -
7 0 4 7 0 4 Legality test? e8g8
MateTest: K=1, my=14, his=14
move: e8g8
, parse: O-O (
)
MateTest: K=1, my=14, his=14
repeat test fmm=4 bmm=0 ep=-4, reps=4
4 ep=-4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2047 >first : time 1000
2047 >first : otim 1
book hit = (NULL)
2047 >first : O-O
silence
2313 <first : 8 -26 25 161309 e3-e4 f8-d8 c1-g5 h7-h6 g5-h4 c5-d6 a1-c1 d8-c8
2313 <first : move e4
machine move 4, castling = -1 -1 -1 7 0 -1
move to parse: e4
Disambiguate in: 0(4,-1)-(4,3) = 0 (-)
Disambiguate out: 0(4,2)-(4,3) = 0 (-)
-1 -1 -1 7 0 -1 Legality test? e3e4
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=0 (4,2)-(4,3) -
7 0 4 7 0 4 Legality test? e3e4
movetype=33, promochar=0=-
MateTest: K=1, my=14, his=14
move: e3e4
, parse: e4 (
)
MateTest: K=1, my=14, his=14
repeat test fmm=5 bmm=0 ep=-4, reps=4
5 ep=-3
4 ep=-4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2313 >second: time 1
2313 >second: otim 1
book hit = (NULL)
2313 >second: usermove 2313 >second: e3e4
silence
2313 <second: move d7e5
machine move 5, castling = -1 -1 -1 7 0 -1
move to parse: d7e5
7 0 4 7 0 4 Legality test? d7e5
-1 -1 -1 7 0 -1 Legality test? d7e5
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=23 (3,6)-(4,4) -
MateTest: K=1, my=14, his=14
move: d7e5
, parse: Ne5 (
)
MateTest: K=1, my=14, his=14
repeat test fmm=6 bmm=0 ep=-4, reps=4
6 ep=-4
5 ep=-3
4 ep=-4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2313 >first : time 1
2313 >first : otim 1
book hit = (NULL)
2313 >first : Ne5
silence
2328 <first : 3 4 0 10191 f3xe5 b8xe5 c1-e3
2328 <first : move Nxe5
machine move 6, castling = -1 -1 -1 7 0 -1
move to parse: Nxe5
Parser Qa1: yyleng=4, 1(-1,-1)-(4,4) = 0 ( )
Disambiguate in: 1(-1,-1)-(4,4) = 0 (-)
Disambiguate out: 1(5,2)-(4,4) = 0 (-)
-1 -1 -1 7 0 -1 Legality test? f3e5
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=1 (5,2)-(4,4) -
MateTest: K=1, my=13, his=14
move: f3e5
, parse: Nxe5 (
)
MateTest: K=1, my=13, his=14
repeat test fmm=7 bmm=0 ep=-4, reps=4
7 ep=-2
6 ep=-4
5 ep=-3
4 ep=-4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2344 >second: time 1
2344 >second: otim 1000
book hit = (NULL)
2344 >second: usermove 2344 >second: f3e5
silence
2344 <second: move b8e5
machine move 7, castling = -1 -1 -1 7 0 -1
move to parse: b8e5
7 0 4 7 0 4 Legality test? b8e5
-1 -1 -1 7 0 -1 Legality test? b8e5
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=26 (1,7)-(4,4) -
MateTest: K=1, my=13, his=13
move: b8e5
, parse: Qxe5 (
)
MateTest: K=1, my=13, his=13
repeat test fmm=8 bmm=0 ep=-4, reps=4
8 ep=-2
7 ep=-2
6 ep=-4
5 ep=-3
4 ep=-4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2344 >first : time 1000
2344 >first : otim 1
book hit = (NULL)
2344 >first : Qxe5
silence
2953 <first : 9 -8 60 330996 g2-g3 e5-c7 c1-f4 e6-e5 f4-g5 f8-d8 g5xf6 g7xf6 c3-d5
2953 <first : move g3
machine move 8, castling = -1 -1 -1 7 0 -1
move to parse: g3
Disambiguate in: 0(6,-1)-(6,2) = 0 (-)
Disambiguate out: 0(6,1)-(6,2) = 0 (-)
-1 -1 -1 7 0 -1 Legality test? g2g3
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=0 (6,1)-(6,2) -
7 0 4 7 0 4 Legality test? g2g3
movetype=33, promochar=0=-
MateTest: K=1, my=13, his=13
move: g2g3
, parse: g3 (
)
MateTest: K=1, my=13, his=13
repeat test fmm=9 bmm=0 ep=-4, reps=4
9 ep=-3
8 ep=-2
7 ep=-2
6 ep=-4
5 ep=-3
4 ep=-4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2969 >second: time 1
2969 >second: otim 1
book hit = (NULL)
2969 >second: usermove 2969 >second: g2g3
silence
2969 <second: move a8d8
machine move 9, castling = -1 -1 -1 7 0 -1
move to parse: a8d8
7 0 4 7 0 4 Legality test? a8d8
-1 -1 -1 7 0 -1 Legality test? a8d8
(-1,0) (-1,0) (-1,0) (7,7) (0,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=25 (0,7)-(3,7) -
MateTest: K=1, my=13, his=13
move: a8d8
, parse: Rad8 (
)
MateTest: K=1, my=13, his=13
repeat test fmm=10 bmm=0 ep=-4, reps=4
10 ep=-4
9 ep=-3
8 ep=-2
7 ep=-2
6 ep=-4
5 ep=-3
4 ep=-4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2969 >first : time 1
2969 >first : otim 1
book hit = (NULL)
2969 >first : Rad8
silence
2984 <first : 3 -7 1 16001 c1-f4 e5-h5 e2xh5
2984 <first : move Bf4
machine move 10, castling = -1 -1 -1 7 -1 -1
move to parse: Bf4
Parser Qa1: yyleng=3, 2(-1,-1)-(5,3) = 0 ( )
Disambiguate in: 2(-1,-1)-(5,3) = 0 (-)
Disambiguate out: 2(2,0)-(5,3) = 0 (-)
-1 -1 -1 7 -1 -1 Legality test? c1f4
(-1,0) (-1,0) (-1,0) (7,7) (-1,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=2 (2,0)-(5,3) -
MateTest: K=1, my=13, his=13
move: c1f4
, parse: Bf4 (
)
MateTest: K=1, my=13, his=13
repeat test fmm=11 bmm=0 ep=-4, reps=4
11 ep=-4
10 ep=-4
9 ep=-3
8 ep=-2
7 ep=-2
6 ep=-4
5 ep=-3
4 ep=-4
3 ep=-4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
3000 >second: time 1
3000 >second: otim 1000
book hit = (NULL)
3000 >second: usermove 3000 >second: c1f4
silence
3000 <second: 1 +0 0 0 No legal move found. Start a new game.

[H.G.Muller]

Yes, sorry I could not react sooner; my laptop on which I develop WinBoard fell off the table, and although it was only a 40-cm drop it landed on the power plug. As a result the plug was smashed in, fragmenting the bottom of the female part, tearing the central contact plus a nearby component off the circuit board. Although I first thought the laptop had survived the fall, after half an hour I had drained the battery, and discovered I could no longer charge it. So I had to spend all day to take apart the laptop in a desperate attempt to raise it from the dead. As the damage was under the CPU cooler I had to take that off to glue the plug fragments together, and solder the components back onto the PCB. And as I had no thermal paste to remount it, I had to go shopping for that first. It is really a miracle that I am back up now on the resurrected laptop.

What you report sounds pretty bad too, because it sounds like memory pollution. The NPS code in itself is quite simple, and seems OK, from the fact that most of the time it works. So there must be a bug elsewhere that somehow erroneously overwrites this correct code, or the data it uses. But that means the problem can be everywhere...

Do I understand correctly that this problem occurs only when you use this particular position? (That would make me suspect the FEN reader.) Is it reproducible, or do you have to run many games before it occurs?

[Francois]

Yes, sorry I could not react sooner; my laptop on which I develop WinBoard fell off the table, and although it was only a 40-cm drop it landed on the power plug. As a result the plug was smashed in, fragmenting the bottom of the female part, tearing the central contact plus a nearby component off the circuit board. Although I first thought the laptop had survived the fall, after half an hour I had drained the battery, and discovered I could no longer charge it. So I had to spend all day to take apart the laptop in a desperate attempt to raise it from the dead. As the damage was under the CPU cooler I had to take that off to glue the plug fragments together, and solder the components back onto the PCB. And as I had no thermal paste to remount it, I had to go shopping for that first. It is really a miracle that I am back up now on the resurrected laptop.

What you report sounds pretty bad too, because it sounds like memory pollution. The NPS code in itself is quite simple, and seems OK, from the fact that most of the time it works. So there must be a bug elsewhere that somehow erroneously overwrites this correct code, or the data it uses. But that means the problem can be everywhere...

Do I understand correctly that this problem occurs only when you use this particular position? (That would make me suspect the FEN reader.) Is it reproducible, or do you have to run many games before it occurs?

Well, i am happy that your laptop be saved after all
Yes the winboard bug seems nasty. But at least it is easily reproducible : given the same starting position and opponents, everything happens in the same way, so there is hope to catch it.
However i have no idea if this happened with other starting positions and other opponents - i was able to detect it here because winboard did not return and blocked my tournament manager.
I tried to compile winboard here with a few more debug lines to check the variables used to decrease time in NPS mode, but my exe seems to have something wrong : games now end with "Fatal Error: Bad game file" which did not happen with the released exe

[Francois]

Weirder and weirder...
My home-made version of winboard (official 4.4.1 sources with some additional fprintf to the debug file when computing the new remaining time in NPS mode, compiled in release mode with visual 2005 Professional SP2) does not behave as the downloaded 4.4.1 exe :
In the same conditions my exe says "Bad game file", which is normal as the first argument in my command line is the full winboard exe path in my CreateProcess call (as advised in visual help) which WinBoard considers to be the game file name. I removed the winboard path from the command line and everything seemed to work again, with my previous bug having disappeared in these conditions.
Of course given the king of bug we expect, this might mean it will reappear later in other conditions as the Exe change might have changed the memory conditions needed for the problem to show. I'll keep you posted if it reappears.
Still, i am wondering why the release exe and my compiled exe behave so differently...Different Compilers ?

Thanks,
François

[H.G.Muller]

The release version is made by gcc under Cygwin.

Problem is that I also cannot reproduce the exact version. (I might have updated the compiler or libraries in the mean time). The exe file has a size that is a little different. But at least it should be more similar. I tried to reproduce the error (with other engines), but so far not succeeded. Errors like this tend to be very volatile, and could depend on anything. Even the exact path-name of the engine directories, or the contents of your .ini file.

So I hope that you can help me debug this. I have posted a version of 4.4.1 with two debug prints added: one to print the remaining times immediately after any input from an engine is received, and another after decrementing the clocks based on thinking output. It is at:

http://hgm.nubati.net/winbug.zip

Can you check if, under the same conditions, this reproduces the error. And if it does, send me the debug file?

[Francois]

I just replaced my executable by yours and relaunched my tournament.
I will keep you posted.

[Francois]

Guess what ? It happened again with your exe, with the same opponent but another starting pos. We are "lucky"

Here is the debug file :

recognized 'normal' (-1) as variant normal
WinBoard 4.4.1 + BugChess2_V1_6_4.exe
Reset(1, 0) from gameMode 0
recognized 'normal' (-1) as variant normal
GameEnds(0, (null), 2)
shuffleOpenings = 0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
StartChildProcess (dir="C:\TempFK\DistributedFPKWBTM\BugChess2_V1_6_4") BugChess2_V1_6_4.exe -winboard
515 >first : xboard
protover 2
515 <first : feature done=0
machine move: nps=900000, W:10000 B:10000
515 >first : accepted done
530 <first : feature ping=1 setboard=1 playother=1 san=1 time=1 draw=0 sigint=0 sigterm=0 analyze=1 myname="BugChess2 V1.6.4" variants="normal" colors=0 name=1 nps=1 done=1
machine move: nps=900000, W:10000 B:10000
530 >first : accepted ping
530 >first : accepted setboard
530 >first : accepted playother
530 >first : accepted san
530 >first : accepted time
530 >first : accepted draw
530 >first : accepted sigint
530 >first : accepted sigterm
530 >first : accepted analyze
530 >first : accepted myname
530 >first : accepted variants
530 >first : accepted colors
530 >first : accepted name
530 >first : accepted nps
530 >first : accepted done
546 >first : new
random
546 >first : level 40 0:10 0
546 >first : nps 900000
546 >first : post
546 >first : hard
546 >first : easy
546 >first : ping 1
FEN castling rights: -1 -1 -1 -1 -1 -1
546 >first : force
write FEN 50-move: 0 0 0
e0. p=-4
546 >first : setboard rn1q1rk1/1pp1bppp/pn1pp3/4P2b/2PP4/2N1BN1P/PP2BPP1/R2Q1RK1 w - - 0 1
-1 -1 -1 -1 -1 -1
-1 -1 -1 -1 -1 -1
7 0 4 7 0 4
Load Position
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
StartChildProcess (dir="C:\TempFK\DistributedFPKWBTM\Polyglot") polyglot.exe TwistedLogic_20090922.ini
1044 >second: xboard
protover 2
1044 <second: PolyGlot 1.4.38x by Fabien Letouzey.
machine move: nps=900000, W:10000 B:10000
1044 <first : pong 1
machine move: nps=900000, W:10000 B:10000
1044 <second: feature done=0
machine move: nps=900000, W:10000 B:10000
1044 >second: accepted done
1044 <second: feature analyze=1
machine move: nps=900000, W:10000 B:10000
1044 >second: accepted analyze
1044 <second: feature colors=0
machine move: nps=900000, W:10000 B:10000
1044 >second: accepted colors
1044 <second: feature draw=1
machine move: nps=900000, W:10000 B:10000
1044 >second: accepted draw
1044 <second: feature ics=1
machine move: nps=900000, W:10000 B:10000
1044 >second: accepted ics
1044 <second: feature myname="Twisted Logic 20090922"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted myname
1060 <second: feature name=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted name
1060 <second: feature pause=0
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted pause
1060 <second: feature ping=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted ping
1060 <second: feature playother=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted playother
1060 <second: feature reuse=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted reuse
1060 <second: feature san=0
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted san
1060 <second: feature setboard=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted setboard
1060 <second: feature sigint=0
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted sigint
1060 <second: feature sigterm=0
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted sigterm
1060 <second: feature time=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted time
1060 <second: feature usermove=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted usermove
1060 <second: feature nps=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted nps
1060 <second: feature memory=1
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted memory
1060 <second: feature smp=0
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted smp
1060 <second: feature egt=""
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted egt
1060 <second: feature variants="normal"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted variants
1060 <second: feature option="Pawn Hash -spin 16 1 32"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="OwnBook -check 1"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Book File -file twistedbook.bin"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Book Move Limit -spin 128 1 256"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Display Book Moves -check 0"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Time Buffer -spin 1000 0 10000"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Transposition Table -check 1"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Null Move Pruning -check 1"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Null Move Verification -check 1"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Null Move Fail High -check 1"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Null Threat -check 1"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Zero Recapture Extension -check 0"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Internal Iterative Deepening -check 1"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Internal Iterative Deepening Solid -check 1"
machine move: nps=900000, W:10000 B:10000
1060 >second: accepted option
1060 <second: feature option="Internal Iterative Deepening Depth -spin 5 1 15"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Delta Pruning -check 1"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Delta Pruning Solid -check 1"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Delta Pruning Threshold -spin 50 0 500"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Quiescence Check Depth -spin 5 1 15"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Selectivity -check 0"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Selectivity Base -spin 3 1 15"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Selectivity Threshold -spin 125 0 500"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Selectivity Cutoff -spin 125 0 500"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Zero Pruning -check 1"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Zero Pruning Base -spin 9 1 15"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Zero Pruning Threshold -spin 100 0 500"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Zero Pruning Multiplier -spin 50 0 500"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Speculation Aggressive -check 0"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Speculation PV -check 1"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Speculation PV Level -spin 12 0 30"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Extended Speculation PV -check 0"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Extended Speculation PV Level -spin 12 0 30"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Speculation -check 1"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Speculation Base -spin 3 2 15"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Speculation Level -spin 4 2 30"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Extended Speculation -check 1"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Extended Speculation Base -spin 4 3 15"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Extended Speculation Level -spin 4 2 30"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Eval Grain Size -spin 0 0 4"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="Fill Hash With PV -check 1"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="King Attacks Aggression Level -spin 4 0 20"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1076 <second: feature option="UCI_ShowCurrLine -check 0"
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted option
1091 <second: feature option="UCI_EngineAbout -file Twisted Logic by Edsel Apostol"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot Polyglot Version -combo 1.4.38x"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot Log -check 1"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot LogFile -file TwistedLogic_20090922.log"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot OptionFile -file TwistedLogic_20090922.ini"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot Book -check 0"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot BookFile -file book.bin"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot BookRandom -check 1"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot BookDepth -spin 256 0 256"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot BookLearn -check 0"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot BookTreshold -spin 5 0 1000"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot Resign -check 0"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot ResignMoves -spin 3 0 10000"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot ResignScore -spin 800 0 10000"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot MateScore -spin 10000 0 100000"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot ShowPonder -check 0"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot UCIVersion -spin 2 1 2"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot RepeatPV -check 1"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot SyncStop -check 0"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot CanPonder -check 0"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Polyglot PromoteWorkAround -check 0"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature option="Save polyglot.ini -save"
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted option
1091 <second: feature done=1
machine move: nps=900000, W:10000 B:10000
1091 >second: accepted done
1107 >second: memory 68
1107 >second: new
random
1107 >second: ics -
1107 >second: level 40 0:10 0
1107 >second: nps 900000
1107 >second: post
1107 >second: hard
1107 >second: easy
1107 >second: ping 1
1107 >second: force
write FEN 50-move: 0 0 0
e0. p=-4
1107 >second: setboard rn1q1rk1/1pp1bppp/pn1pp3/4P2b/2PP4/2N1BN1P/PP2BPP1/R2Q1RK1 w - - 0 1
Two Machines
1107 >first : computer
1107 >first : name Twisted Logic 20090922
1107 >second: computer
1107 >second: name BugChess2 V1.6.4
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
time odds: 1 1
1107 >first : time 1000
1107 >first : otim 1000
book hit = (NULL)
1107 >first : go
nps: w=900000, b=900000
1107 <second: pong 1
machine move: nps=900000, W:10000 B:10000
1590 <first : 9 26 45 254208 d1-b3 b8-d7 a1-d1 d8-c8 f1-e1 h5-g6 e3-f4 f7-f6 c4-c5
machine move: nps=900000, W:10000 B:10000
after decrement nps=900000, W:-2147473648 B:10000 tick=-2147483648
1590 <first : move Qb3
machine move: nps=900000, W:-2147473648 B:10000
machine move 0, castling = -1 -1 -1 -1 -1 -1
move to parse: Qb3
Parser Qa1: yyleng=3, 4(-1,-1)-(1,2) = 0 ( )
Disambiguate in: 4(-1,-1)-(1,2) = 0 (-)
Disambiguate out: 4(3,0)-(1,2) = 0 (-)
-1 -1 -1 -1 -1 -1 Legality test? d1b3
(-1,0) (-1,0) (-1,0) (-1,7) (-1,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=4 (3,0)-(1,2) -
MateTest: K=1, my=16, his=16
move: d1b3
, parse: Qb3 (
)
MateTest: K=1, my=16, his=16
repeat test fmm=1 bmm=0 ep=-4, reps=4
1 ep=-4
0 ep=-4
time odds: 1 1
1590 >second: time 1000
1590 >second: otim 1
book hit = (NULL)
1590 >second: usermove 1590 >second: d1b3
1590 >second: go
silence
1699 <second: 8 -95 11 80643 Nc6 exd6 Bxd6 c5 Na5 Qc2 Bg6 Ne4
machine move: nps=900000, W:-2147473648 B:10000
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
1715 <second: 9 -247 12 104164 Nc6 exd6 Bxd6 c5 Na5 Qc2 Bg6 Qc1 Nac4 cxd6 Nxe3 fxe3 Qxd6
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
1793 <second: 9 -114 20 156533 dxe5 dxe5 Nc6 Rad1 Qc8 Bxb6 cxb6 g4 Bg6 Qxb6 Rd8 Rxd8+ Bxd8
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
1870 <second: 9 -114 28 225000 dxe5 dxe5 Nc6 Rad1 Qc8 Bxb6 cxb6 g4 Bg6 Qxb6 Rd8 Rxd8+ Bxd8
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
1870 <second: move d6e5
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 1, castling = -1 -1 -1 -1 -1 -1
move to parse: d6e5
7 0 4 7 0 4 Legality test? d6e5
-1 -1 -1 -1 -1 -1 Legality test? d6e5
(-1,0) (-1,0) (-1,0) (-1,7) (-1,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=22 (3,5)-(4,4) -
7 0 4 7 0 4 Legality test? d6e5
movetype=33, promochar=0=-
MateTest: K=1, my=15, his=16
move: d6e5
, parse: dxe5 (
)
MateTest: K=1, my=15, his=16
repeat test fmm=2 bmm=0 ep=-4, reps=4
2 ep=-3
1 ep=-4
0 ep=-4
time odds: 1 1
1870 >first : time 1
1870 >first : otim 1
book hit = (NULL)
1870 >first : dxe5
silence
1886 <first : 3 26 0 6167 d4xe5 b8-c6 a1-d1
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:10000 B:-2147473648 tick=-2147483648
1886 <first : move dxe5
machine move: nps=900000, W:10000 B:-2147473648
machine move 2, castling = -1 -1 -1 -1 -1 -1
move to parse: dxe5
7 0 4 7 0 4 Legality test? d4e5
-1 -1 -1 -1 -1 -1 Legality test? d4e5
(-1,0) (-1,0) (-1,0) (-1,7) (-1,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=0 (3,3)-(4,4) -
7 0 4 7 0 4 Legality test? d4e5
movetype=33, promochar=0=-
MateTest: K=1, my=15, his=15
move: d4e5
, parse: dxe5 (
)
MateTest: K=1, my=15, his=15
repeat test fmm=3 bmm=0 ep=-4, reps=4
3 ep=-3
2 ep=-3
1 ep=-4
0 ep=-4
time odds: 1 1
1886 >second: time 1
1886 >second: otim 1000
book hit = (NULL)
1886 >second: usermove 1886 >second: d4e5
silence
1902 <second: move b8c6
machine move: nps=900000, W:10000 B:-2147473648
machine move 3, castling = -1 -1 -1 -1 -1 -1
move to parse: b8c6
7 0 4 7 0 4 Legality test? b8c6
-1 -1 -1 -1 -1 -1 Legality test? b8c6
(-1,0) (-1,0) (-1,0) (-1,7) (-1,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=23 (1,7)-(2,5) -
MateTest: K=1, my=15, his=15
move: b8c6
, parse: Nc6 (
)
MateTest: K=1, my=15, his=15
repeat test fmm=4 bmm=0 ep=-4, reps=4
4 ep=-4
3 ep=-3
2 ep=-3
1 ep=-4
0 ep=-4
time odds: 1 1
1902 >first : time 1000
1902 >first : otim 1
book hit = (NULL)
1902 >first : Nc6
silence
2058 <first : 9 42 15 110464 a1-d1 d8-c8 e3xb6 c7xb6 b3xb6 h5xf3 e2xf3 c6xe5 f3xb7
machine move: nps=900000, W:10000 B:-2147473648
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
2058 <first : move Rad1
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 4, castling = -1 -1 -1 -1 -1 -1
move to parse: Rad1
Disambiguate in: 3(0,-1)-(3,0) = 0 (-)
Disambiguate out: 3(0,0)-(3,0) = 0 (-)
-1 -1 -1 -1 -1 -1 Legality test? a1d1
(-1,0) (-1,0) (-1,0) (-1,7) (-1,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=3 (0,0)-(3,0) -
MateTest: K=1, my=15, his=15
move: a1d1
, parse: Rad1 (
)
MateTest: K=1, my=15, his=15
repeat test fmm=5 bmm=0 ep=-4, reps=4
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-3
1 ep=-4
0 ep=-4
time odds: 1 1
2058 >second: time 1
2058 >second: otim 1
book hit = (NULL)
2058 >second: usermove 2058 >second: a1d1
silence
2073 <second: move d8e8
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 5, castling = -1 -1 -1 -1 -1 -1
move to parse: d8e8
7 0 4 7 0 4 Legality test? d8e8
-1 -1 -1 -1 -1 -1 Legality test? d8e8
(-1,0) (-1,0) (-1,0) (-1,7) (-1,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=26 (3,7)-(4,7) -
MateTest: K=1, my=15, his=15
move: d8e8
, parse: Qe8 (
)
MateTest: K=1, my=15, his=15
repeat test fmm=6 bmm=0 ep=-4, reps=4
6 ep=-4
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-3
1 ep=-4
0 ep=-4
time odds: 1 1
2073 >first : time 1
2073 >first : otim 1
book hit = (NULL)
2073 >first : Qe8
silence
2089 <first : 3 71 1 6064 e3xb6 c7xb6 b3xb6
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:10000 B:-2147473648 tick=-2147483648
2089 <first : move Bxb6
machine move: nps=900000, W:10000 B:-2147473648
machine move 6, castling = -1 -1 -1 -1 -1 -1
move to parse: Bxb6
Parser Qa1: yyleng=4, 2(-1,-1)-(1,5) = 0 ( )
Disambiguate in: 2(-1,-1)-(1,5) = 0 (-)
Disambiguate out: 2(4,2)-(1,5) = 0 (-)
-1 -1 -1 -1 -1 -1 Legality test? e3b6
(-1,0) (-1,0) (-1,0) (-1,7) (-1,7) (-1,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=2 (4,2)-(1,5) -
MateTest: K=1, my=14, his=15
move: e3b6
, parse: Bxb6 (
)
MateTest: K=1, my=14, his=15
repeat test fmm=7 bmm=0 ep=-4, reps=4
7 ep=-2
6 ep=-4
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-3
1 ep=-4
0 ep=-4
time odds: 1 1
2089 >second: time 1
2089 >second: otim 1000
book hit = (NULL)
2089 >second: usermove 2089 >second: e3b6
silence
2089 <second: 1 +0 0 0 No legal move found. Start a new game.
machine move: nps=900000, W:10000 B:-2147473648
after decrement nps=900000, W:10000 B:10000 tick=-2147483648

[H.G.Muller]

Great! Obviously this is where it goes wrong:

1590 <first : 9 26 45 254208 d1-b3 b8-d7 a1-d1 d8-c8 f1-e1 h5-g6 e3-f4 f7-f6 c4-c5
machine move: nps=900000, W:10000 B:10000
after decrement nps=900000, W:-2147473648 B:10000 tick=-2147483648

When HandleMachineMove is called because there was input from the engine the white and black times are still OK. After the decrement, the white time is cr*p, but that seems the fault of the tickLength that was subtracted from it. So the tickLength is improperly calculated from the node count. (While the nps value is still undamaged at 900000.)

I will look if I see an obvious place where the node count is messed up between reading it and the calculation. If not, I will make a winboard.exe with a few more print statements along the path followed by the node count.

The value the tickLength has here is -0x50000000 in hexadecimal, which is in itself very suspect...

I'll be back!

[H.G.Muller]

Hmm, it seems that my Linux calculator has been lying to me? The printed value of the ticklen actually corresponds to 0x80000000 (i.e. only the sign bit is set). I see nothing that could explain the printing of this strange and obviously wrong value in the code below. The node count is a u64 variable 'nodes' there. The ticklen variable gets a value immediately before it is used and printed, and the expression that assigns the value (ticklen = (1000. * u64ToDouble(nodes)) / cps->nps;) is very unlikely to produce this special value because of 'nodes' having a corrupted value. (Unless it is some overflow code.)

To shed some more light on this, I made a new winboard.exe, (same link) which now also prints nodes, u64ToDouble(nodes) and the original thinking output from which 'nodes' was just derived in addition to what it already printed. I hope that I changed so little now, that the error persists with these same engines and position.

Code: Select all

   if (!ignore) {
       buf1[0] = NULLCHAR;
       if (sscanf(message, "%d%c %d %d " u64Display " %[^\n]\n",
             &plylev, &plyext, &curscore, &time, &nodes, buf1) >= 5) {

      if (plyext != ' ' && plyext != '\t') {
          time *= 100;
      }

                /* [AS] Negate score if machine is playing black and reporting absolute scores */
                if( cps->scoreIsAbsolute &&
                    ((gameMode == MachinePlaysBlack) || (gameMode == TwoMachinesPlay && cps->twoMachinesColor[0] == 'b')) )
                {
                    curscore = -curscore;
                }


      programStats.depth = plylev;
      programStats.nodes = nodes;
      programStats.time = time;
      programStats.score = curscore;
      programStats.got_only_move = 0;

      if(cps->nps >= 0) { /* [HGM] nps: use engine nodes or time to decrement clock */
         int ticklen;
         if(cps->nps == 0) ticklen = 10*time;                    // use engine reported time
         else ticklen = (1000. * u64ToDouble(nodes)) / cps->nps; // convert node count to time
         if(WhiteOnMove(forwardMostMove) && (gameMode == MachinePlaysWhite ||
                  gameMode == TwoMachinesPlay && cps->twoMachinesColor[0] == 'w'))
              whiteTimeRemaining = timeRemaining[0][forwardMostMove] - ticklen;
         if(!WhiteOnMove(forwardMostMove) && (gameMode == MachinePlaysBlack ||
                  gameMode == TwoMachinesPlay && cps->twoMachinesColor[0] == 'b'))
              blackTimeRemaining = timeRemaining[1][forwardMostMove] - ticklen;
if(appData.debugMode) fprintf(debugFP, "after decrement nps=%d, W:%ld B:%ld tick=%d nodes=" u64Display "=%f '%s'\n",
               cps->nps, whiteTimeRemaining, blackTimeRemaining, ticklen, nodes, u64ToDouble(nodes), message);
      }


[Francois]

I updated my exe this morning. So far, no news of the bug. I'll keep you posted.

[Francois]

It happened again, here is the new debug file.
It seems your new debug info did not show
I just checked that i did use the last executable at your link, which i did. Could something be wrong with your exe ?

recognized 'normal' (-1) as variant normal
WinBoard 4.4.1 + polyglot.exe
Reset(1, 0) from gameMode 0
recognized 'normal' (-1) as variant normal
GameEnds(0, (null), 2)
shuffleOpenings = 0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
StartChildProcess (dir="C:\TempFK\DistributedFPKWBTM\Polyglot") polyglot.exe TwistedLogic_20090922.ini
515 >first : xboard
protover 2
546 <first : PolyGlot 1.4.38x by Fabien Letouzey.
machine move: nps=900000, W:10000 B:10000
546 <first : feature done=0
machine move: nps=900000, W:10000 B:10000
546 >first : accepted done
546 <first : feature analyze=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted analyze
546 <first : feature colors=0
machine move: nps=900000, W:10000 B:10000
546 >first : accepted colors
546 <first : feature draw=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted draw
546 <first : feature ics=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted ics
546 <first : feature myname="Twisted Logic 20090922"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted myname
546 <first : feature name=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted name
546 <first : feature pause=0
machine move: nps=900000, W:10000 B:10000
546 >first : accepted pause
546 <first : feature ping=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted ping
546 <first : feature playother=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted playother
546 <first : feature reuse=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted reuse
546 <first : feature san=0
machine move: nps=900000, W:10000 B:10000
546 >first : accepted san
546 <first : feature setboard=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted setboard
546 <first : feature sigint=0
machine move: nps=900000, W:10000 B:10000
546 >first : accepted sigint
546 <first : feature sigterm=0
machine move: nps=900000, W:10000 B:10000
546 >first : accepted sigterm
546 <first : feature time=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted time
546 <first : feature usermove=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted usermove
546 <first : feature nps=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted nps
546 <first : feature memory=1
machine move: nps=900000, W:10000 B:10000
546 >first : accepted memory
546 <first : feature smp=0
machine move: nps=900000, W:10000 B:10000
546 >first : accepted smp
546 <first : feature egt=""
machine move: nps=900000, W:10000 B:10000
546 >first : accepted egt
546 <first : feature variants="normal"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted variants
546 <first : feature option="Pawn Hash -spin 16 1 32"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="OwnBook -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Book File -file twistedbook.bin"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Book Move Limit -spin 128 1 256"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Display Book Moves -check 0"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Time Buffer -spin 1000 0 10000"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Transposition Table -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Null Move Pruning -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Null Move Verification -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Null Move Fail High -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Null Threat -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Zero Recapture Extension -check 0"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Internal Iterative Deepening -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Internal Iterative Deepening Solid -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Internal Iterative Deepening Depth -spin 5 1 15"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Delta Pruning -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Delta Pruning Solid -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Delta Pruning Threshold -spin 50 0 500"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Quiescence Check Depth -spin 5 1 15"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Selectivity -check 0"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Selectivity Base -spin 3 1 15"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Selectivity Threshold -spin 125 0 500"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Selectivity Cutoff -spin 125 0 500"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Zero Pruning -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Zero Pruning Base -spin 9 1 15"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Zero Pruning Threshold -spin 100 0 500"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Zero Pruning Multiplier -spin 50 0 500"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Speculation Aggressive -check 0"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Speculation PV -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Speculation PV Level -spin 12 0 30"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Extended Speculation PV -check 0"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Extended Speculation PV Level -spin 12 0 30"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
546 <first : feature option="Speculation -check 1"
machine move: nps=900000, W:10000 B:10000
546 >first : accepted option
561 <first : feature option="Speculation Base -spin 3 2 15"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Speculation Level -spin 4 2 30"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Extended Speculation -check 1"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Extended Speculation Base -spin 4 3 15"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Extended Speculation Level -spin 4 2 30"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Eval Grain Size -spin 0 0 4"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Fill Hash With PV -check 1"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="King Attacks Aggression Level -spin 4 0 20"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="UCI_ShowCurrLine -check 0"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="UCI_EngineAbout -file Twisted Logic by Edsel Apostol"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot Polyglot Version -combo 1.4.38x"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot Log -check 1"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot LogFile -file TwistedLogic_20090922.log"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot OptionFile -file TwistedLogic_20090922.ini"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot Book -check 0"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot BookFile -file book.bin"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot BookRandom -check 1"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot BookDepth -spin 256 0 256"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot BookLearn -check 0"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot BookTreshold -spin 5 0 1000"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot Resign -check 0"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot ResignMoves -spin 3 0 10000"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot ResignScore -spin 800 0 10000"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot MateScore -spin 10000 0 100000"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot ShowPonder -check 0"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot UCIVersion -spin 2 1 2"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot RepeatPV -check 1"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot SyncStop -check 0"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot CanPonder -check 0"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Polyglot PromoteWorkAround -check 0"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature option="Save polyglot.ini -save"
machine move: nps=900000, W:10000 B:10000
561 >first : accepted option
561 <first : feature done=1
machine move: nps=900000, W:10000 B:10000
561 >first : accepted done
577 >first : memory 68
577 >first : new
random
577 >first : ics -
577 >first : level 40 0:10 0
577 >first : nps 900000
577 >first : post
577 >first : hard
577 >first : easy
577 >first : ping 1
FEN castling rights: 7 0 4 7 0 4
577 >first : force
write FEN 50-move: 0 0 0
e0. p=-4
577 >first : setboard rn1qk2r/pp2p1bp/3pp1p1/2p3N1/2bP1PQ1/2N5/PPP3PP/R1B1K2R w KQkq - 0 1
7 0 4 7 0 4
-1 -1 -1 -1 -1 -1
7 0 4 7 0 4
Load Position
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
StartChildProcess (dir="C:\TempFK\DistributedFPKWBTM\BugChess2_V1_6_4") BugChess2_V1_6_4.exe -winboard
1076 >second: xboard
protover 2
1076 <second: feature done=0
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted done
1076 <first : pong 1
machine move: nps=900000, W:10000 B:10000
1076 <second: feature ping=1 setboard=1 playother=1 san=1 time=1 draw=0 sigint=0 sigterm=0 analyze=1 myname="BugChess2 V1.6.4" variants="normal" colors=0 name=1 nps=1 done=1
machine move: nps=900000, W:10000 B:10000
1076 >second: accepted ping
1076 >second: accepted setboard
1076 >second: accepted playother
1076 >second: accepted san
1076 >second: accepted time
1076 >second: accepted draw
1076 >second: accepted sigint
1076 >second: accepted sigterm
1076 >second: accepted analyze
1076 >second: accepted myname
1076 >second: accepted variants
1076 >second: accepted colors
1076 >second: accepted name
1076 >second: accepted nps
1076 >second: accepted done
1091 >second: new
random
1091 >second: level 40 0:10 0
1091 >second: nps 900000
1091 >second: post
1091 >second: hard
1091 >second: easy
1091 >second: ping 1
1091 >second: force
write FEN 50-move: 0 0 0
e0. p=-4
1091 >second: setboard rn1qk2r/pp2p1bp/3pp1p1/2p3N1/2bP1PQ1/2N5/PPP3PP/R1B1K2R w KQkq - 0 1
Two Machines
1091 >first : computer
1091 >first : name BugChess2 V1.6.4
1091 >second: computer
1091 >second: name Twisted Logic 20090922
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
time odds: 1 1
1091 >first : time 1000
1091 >first : otim 1000
book hit = (NULL)
1091 >first : go
nps: w=900000, b=900000
1200 <second: pong 1
machine move: nps=900000, W:10000 B:10000
1216 <first : 8 -23 12 87285 dxc5 dxc5 Be3 O-O Bxc5 h5 Qf3 Nc6
machine move: nps=900000, W:10000 B:10000
after decrement nps=900000, W:-2147473648 B:10000 tick=-2147483648
1341 <first : 9 -3 25 178343 dxc5 dxc5 Be3 O-O Bxc5 Qa5 Ne4 e5 O-O-O Rxf4
machine move: nps=900000, W:-2147473648 B:10000
after decrement nps=900000, W:-2147473648 B:10000 tick=-2147483648
1403 <first : 9 -3 31 225000 dxc5 dxc5 Be3 O-O Bxc5 Qa5 Ne4 e5 O-O-O Rxf4
machine move: nps=900000, W:-2147473648 B:10000
after decrement nps=900000, W:-2147473648 B:10000 tick=-2147483648
1403 <first : move d4c5
machine move: nps=900000, W:-2147473648 B:10000
machine move 0, castling = 7 0 4 7 0 4
move to parse: d4c5
7 0 4 7 0 4 Legality test? d4c5
7 0 4 7 0 4 Legality test? d4c5
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=0 (3,3)-(2,4) -
7 0 4 7 0 4 Legality test? d4c5
movetype=33, promochar=0=-
MateTest: K=1, my=14, his=14
move: d4c5
, parse: dxc5 (
)
MateTest: K=1, my=14, his=14
repeat test fmm=1 bmm=0 ep=-4, reps=4
1 ep=-3
0 ep=-4
time odds: 1 1
1403 >second: time 1000
1403 >second: otim 1
book hit = (NULL)
1403 >second: dxc5
1403 >second: go
silence
1481 <second: 6 115 6 31627 g7xc3 b2xc3 d6xc5 e1-f2 h7-h5 g4-f3 d8-d5
machine move: nps=900000, W:-2147473648 B:10000
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
1481 <second: move Bxc3
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 1, castling = 7 0 4 7 0 4
move to parse: Bxc3
Parser Qa1: yyleng=4, 24(-1,-1)-(2,2) = 0 ( )
Disambiguate in: 24(-1,-1)-(2,2) = 0 (-)
Disambiguate out: 24(6,6)-(2,2) = 0 (-)
7 0 4 7 0 4 Legality test? g7c3
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=24 (6,6)-(2,2) -
MateTest: K=1, my=13, his=14
move: g7c3
, parse: Bxc3+ (
)
MateTest: K=1, my=13, his=14
repeat test fmm=2 bmm=0 ep=-4, reps=4
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1481 >first : time 1
1481 >first : otim 1
book hit = (NULL)
1481 >first : usermove 1481 >first : g7c3
silence
1496 <first : move b2c3
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 2, castling = 7 0 4 7 0 4
move to parse: b2c3
7 0 4 7 0 4 Legality test? b2c3
7 0 4 7 0 4 Legality test? b2c3
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=0 (1,1)-(2,2) -
7 0 4 7 0 4 Legality test? b2c3
movetype=33, promochar=0=-
MateTest: K=1, my=13, his=13
move: b2c3
, parse: bxc3 (
)
MateTest: K=1, my=13, his=13
repeat test fmm=3 bmm=0 ep=-4, reps=4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1496 >second: time 1
1496 >second: otim 1
book hit = (NULL)
1496 >second: bxc3
silence
1496 <second: 3 127 0 1636 d8-a5 g4-h3 d6xc5
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:-2147473648 B:10000 tick=-2147483648
1512 <second: move Qa5
machine move: nps=900000, W:-2147473648 B:10000
machine move 3, castling = 7 0 4 7 0 4
move to parse: Qa5
Parser Qa1: yyleng=3, 26(-1,-1)-(0,4) = 0 ( )
Disambiguate in: 26(-1,-1)-(0,4) = 0 (-)
Disambiguate out: 26(3,7)-(0,4) = 0 (-)
7 0 4 7 0 4 Legality test? d8a5
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=26 (3,7)-(0,4) -
MateTest: K=1, my=13, his=13
move: d8a5
, parse: Qa5 (
)
MateTest: K=1, my=13, his=13
repeat test fmm=4 bmm=0 ep=-4, reps=4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1512 >first : time 1
1512 >first : otim 1000
book hit = (NULL)
1512 >first : usermove 1512 >first : d8a5
silence
1512 <first : move c1d2
machine move: nps=900000, W:-2147473648 B:10000
machine move 4, castling = 7 0 4 7 0 4
move to parse: c1d2
7 0 4 7 0 4 Legality test? c1d2
7 0 4 7 0 4 Legality test? c1d2
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=2 (2,0)-(3,1) -
MateTest: K=1, my=13, his=13
move: c1d2
, parse: Bd2 (
)
MateTest: K=1, my=13, his=13
repeat test fmm=5 bmm=0 ep=-4, reps=4
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1512 >second: time 1000
1512 >second: otim 1
book hit = (NULL)
1512 >second: Bd2
silence
1793 <second: 9 86 28 140159 a5xc5 g5xe6 c5-c8 f4-f5 c4xe6 f5xe6 h8-f8 h1-f1 f8xf1 e1xf1
machine move: nps=900000, W:-2147473648 B:10000
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
1793 <second: move Qxc5
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 5, castling = 7 0 4 7 0 4
move to parse: Qxc5
Parser Qa1: yyleng=4, 26(-1,-1)-(2,4) = 0 ( )
Disambiguate in: 26(-1,-1)-(2,4) = 0 (-)
Disambiguate out: 26(0,4)-(2,4) = 0 (-)
7 0 4 7 0 4 Legality test? a5c5
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=26 (0,4)-(2,4) -
MateTest: K=1, my=12, his=13
move: a5c5
, parse: Qxc5 (
)
MateTest: K=1, my=12, his=13
repeat test fmm=6 bmm=0 ep=-4, reps=4
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1793 >first : time 1
1793 >first : otim 1
book hit = (NULL)
1793 >first : usermove 1808 >first : a5c5
silence
1808 <first : move g5e6
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 6, castling = 7 0 4 7 0 4
move to parse: g5e6
7 0 4 7 0 4 Legality test? g5e6
7 0 4 7 0 4 Legality test? g5e6
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=1 (6,4)-(4,5) -
MateTest: K=1, my=12, his=12
move: g5e6
, parse: Nxe6 (
)
MateTest: K=1, my=12, his=12
repeat test fmm=7 bmm=0 ep=-4, reps=4
7 ep=-2
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1808 >second: time 1
1808 >second: otim 1
book hit = (NULL)
1808 >second: Nxe6
silence
1808 <second: 3 87 0 1176 c4xe6 g4xe6 b8-d7
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:-2147473648 B:10000 tick=-2147483648
1808 <second: move Bxe6
machine move: nps=900000, W:-2147473648 B:10000
machine move 7, castling = 7 0 4 7 0 4
move to parse: Bxe6
Parser Qa1: yyleng=4, 24(-1,-1)-(4,5) = 0 ( )
Disambiguate in: 24(-1,-1)-(4,5) = 0 (-)
Disambiguate out: 24(2,3)-(4,5) = 0 (-)
7 0 4 7 0 4 Legality test? c4e6
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=24 (2,3)-(4,5) -
MateTest: K=1, my=11, his=12
move: c4e6
, parse: Bxe6 (
)
MateTest: K=1, my=11, his=12
repeat test fmm=8 bmm=0 ep=-4, reps=4
8 ep=-2
7 ep=-2
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1824 >first : time 1
1824 >first : otim 1000
book hit = (NULL)
1824 >first : usermove 1824 >first : c4e6
silence
1824 <first : move g4e6
machine move: nps=900000, W:-2147473648 B:10000
machine move 8, castling = 7 0 4 7 0 4
move to parse: g4e6
7 0 4 7 0 4 Legality test? g4e6
7 0 4 7 0 4 Legality test? g4e6
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=4 (6,3)-(4,5) -
MateTest: K=1, my=11, his=11
move: g4e6
, parse: Qxe6 (
)
MateTest: K=1, my=11, his=11
repeat test fmm=9 bmm=0 ep=-4, reps=4
9 ep=-2
8 ep=-2
7 ep=-2
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1824 >second: time 1000
1824 >second: otim 1
book hit = (NULL)
1824 >second: Qxe6
silence
1964 <second: 7 68 14 63560 b8-d7 a2-a4 b7-b6 e6-e3 c5xe3 d2xe3 a8-c8 e1-d2
machine move: nps=900000, W:-2147473648 B:10000
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
1964 <second: move Nd7
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 9, castling = 7 0 4 7 0 4
move to parse: Nd7
Parser Qa1: yyleng=3, 23(-1,-1)-(3,6) = 0 ( )
Disambiguate in: 23(-1,-1)-(3,6) = 0 (-)
Disambiguate out: 23(1,7)-(3,6) = 0 (-)
7 0 4 7 0 4 Legality test? b8d7
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=23 (1,7)-(3,6) -
MateTest: K=1, my=11, his=11
move: b8d7
, parse: Nd7 (
)
MateTest: K=1, my=11, his=11
repeat test fmm=10 bmm=0 ep=-4, reps=4
10 ep=-4
9 ep=-2
8 ep=-2
7 ep=-2
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1964 >first : time 1
1964 >first : otim 1
book hit = (NULL)
1964 >first : usermove 1964 >first : b8d7
silence
1964 <first : move a1b1
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 10, castling = 7 0 4 7 0 4
move to parse: a1b1
7 0 4 7 0 4 Legality test? a1b1
7 0 4 7 0 4 Legality test? a1b1
(7,0) (0,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=3 (0,0)-(1,0) -
MateTest: K=1, my=11, his=11
move: a1b1
, parse: Rb1 (
)
MateTest: K=1, my=11, his=11
repeat test fmm=11 bmm=0 ep=-4, reps=4
11 ep=-4
10 ep=-4
9 ep=-2
8 ep=-2
7 ep=-2
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1964 >second: time 1
1964 >second: otim 1
book hit = (NULL)
1964 >second: Rb1
silence
1980 <second: 3 87 0 1038 b7-b6 h1-f1 h8-f8
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:-2147473648 B:10000 tick=-2147483648
1980 <second: move b6
machine move: nps=900000, W:-2147473648 B:10000
machine move 11, castling = 7 -1 4 7 0 4
move to parse: b6
Disambiguate in: 22(1,-1)-(1,5) = 0 (-)
Disambiguate out: 22(1,6)-(1,5) = 0 (-)
7 -1 4 7 0 4 Legality test? b7b6
(7,0) (-1,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=22 (1,6)-(1,5) -
7 0 4 7 0 4 Legality test? b7b6
movetype=33, promochar=0=-
MateTest: K=1, my=11, his=11
move: b7b6
, parse: b6 (
)
MateTest: K=1, my=11, his=11
repeat test fmm=12 bmm=0 ep=-4, reps=4
12 ep=-3
11 ep=-4
10 ep=-4
9 ep=-2
8 ep=-2
7 ep=-2
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1980 >first : time 1
1980 >first : otim 1000
book hit = (NULL)
1980 >first : usermove 1980 >first : b7b6
silence
1980 <first : move e1e2
machine move: nps=900000, W:-2147473648 B:10000
machine move 12, castling = 7 -1 4 7 0 4
move to parse: e1e2
7 0 4 7 0 4 Legality test? e1e2
7 -1 4 7 0 4 Legality test? e1e2
(7,0) (-1,0) (4,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=21 (4,0)-(4,1) -
MateTest: K=1, my=11, his=11
move: e1e2
, parse: Ke2 (
)
MateTest: K=1, my=11, his=11
repeat test fmm=13 bmm=0 ep=-4, reps=4
13 ep=-4
12 ep=-3
11 ep=-4
10 ep=-4
9 ep=-2
8 ep=-2
7 ep=-2
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
1980 >second: time 1000
1980 >second: otim 1
book hit = (NULL)
1980 >second: Ke2
silence
2229 <second: 9 111 23 138515 c5-c6 h1-e1 d7-c5 e6-h3 c6-d5 d2-e3 d5xa2 e3xc5 a2xc2 e2-f1
machine move: nps=900000, W:-2147473648 B:10000
after decrement nps=900000, W:-2147473648 B:-2147473648 tick=-2147483648
2229 <second: move Qc6
machine move: nps=900000, W:-2147473648 B:-2147473648
machine move 13, castling = 7 -1 -1 7 0 4
move to parse: Qc6
Parser Qa1: yyleng=3, 26(-1,-1)-(2,5) = 0 ( )
Disambiguate in: 26(-1,-1)-(2,5) = 0 (-)
Disambiguate out: 26(2,4)-(2,5) = 0 (-)
7 -1 -1 7 0 4 Legality test? c5c6
(7,0) (-1,0) (-1,0) (7,7) (0,7) (4,7) castling rights
TC string = '+40/0:10'
mps=40 tc=10000 inc=0
CoordsToAlgebraic, piece=26 (2,4)-(2,5) -
MateTest: K=1, my=11, his=11
move: c5c6
, parse: Qc6 (
)
MateTest: K=1, my=11, his=11
repeat test fmm=14 bmm=0 ep=-4, reps=4
14 ep=-4
13 ep=-4
12 ep=-3
11 ep=-4
10 ep=-4
9 ep=-2
8 ep=-2
7 ep=-2
6 ep=-2
5 ep=-4
4 ep=-4
3 ep=-3
2 ep=-2
1 ep=-3
0 ep=-4
time odds: 1 1
2229 >first : time 1
2229 >first : otim 1
book hit = (NULL)
2229 >first : usermove 2229 >first : c5c6
silence
2229 <first : 1 +0 0 0 No legal move found. Start a new game.
machine move: nps=900000, W:-2147473648 B:-2147473648
after decrement nps=900000, W:10000 B:-2147473648 tick=-2147483648

[H.G.Muller]

This is weird. I checked things on my end, and the backend.c file that prints the extra info has date 29/1 18:31, just like the winboard.exe in the winboard folder and in the zip file (which has 18:34 as time). When I try 'make', it says there is nothing to do, so that means the .exe is already derived from the backend.c, despite the equal time. The size of the zip is 477,964 bytes. This is the same as the winboard.zip on my website. This has a time of 17:37, though, which is an anomaly. (Perhaps that server uses GMT?) The size of the winboard.exe is 1,224,192 bytes.

What is the size of the .exe you have? Could it be that your computer is caching an old winboard.zip?

What is worse: I tried to run the version I have, and it crashes immediately! From the debug file it seems to crash while printing the extra output, in particular the message. Yet I don't see anything wrong there:

Code: Select all

if(appData.debugMode) fprintf(debugFP, "after decrement nps=%d, W:%ld B:%ld tick=%d nodes=" u64Display "=%f '%s'\n",
               cps->nps, whiteTimeRemaining, blackTimeRemaining, ticklen, nodes, u64ToDouble(nodes), message);


The debug file ends in:

Code: Select all

6429 <first :  1     18        0          3 d7d5
machine move: nps=900, W:300000 B:300000
after decrement nps=900, W:300000 B:299997 tick=3 nodes=3=0.000000 '


So it seems to croak while writing the message (which should be the line of Thinking Output the engine sent it).

Nodes = 3 seems to be correct, 'nodes' is a variabe declared as u64, and filled just before by an sscanf using format u64Display (which should be #defined to something like %llu for gcc). However, the following %f format, which should print the node count as a double, prints 0.00000, while it should have printed 3.000000. It is almost like the printf is somehow out of phase here (not understanding the u64Display format properly), and thus gets a garbage double followed by a garbage pointer to the message. The u64Display seems to work in all other print statements, though. It could also be that the type of u64ToDouble is not understood by the compiler. That would explain why ticklen can end up as garbage, as it calls this function in the context of an expression. If the compiler takes the 'result' from a wrong register (%eax in stead of a foating-point register) it will get garbage (and out of phase in the printf, as it will push 32 bits on the stack where the format expects a 64-bit double). The declaration of u64ToDouble is unsuspect, though:

Code: Select all

/* Some compiler can't cast u64 to double
 * This function do the job for us:

 * We use the highest bit for cast, this only
 * works if the highest bit is not
 * in use (This should not happen)
 *
 * We used this for all compiler
 */
double
u64ToDouble(u64 value)
{
  double r;
  u64 tmp = value & u64Const(0x7fffffffffffffff);
  r = (double)(s64)tmp;
  if (value & u64Const(0x8000000000000000))
       r +=  9.2233720368547758080e18; /* 2^63 */
 return r;
}


Hmm, this code does use the constant 0x80000000, which mysteriously ends up as ticklen...

[H.G.Muller]

Arggh! My mistake!

I uploaded the file which printed the extra debug info to home.hccnet.nl/winboard.zip in stead of hgm.nubati.net/winbug.zip...

Nevertheless, it seems we have serendipitously traced the bug:

The version of gcc I am using now does not understand the %llu format in printf, and only takes a 4-byte quantity from the stack. I guess most of WB gets away with this, because the node count is the last of the 4 numbers on a thinking-output line, and is not printed in an sprintf together with the PV that follows: this is strcat'd later to it. It is never used in a printf with anything behind it.

But if it does not understand it in printf, it stands to reason that it also will not understand it in scanf. Which means that after reading the node count from the thinking-output message, it will only only store the lowest 4 bytes into the u64 variable. As this is a local variable, the 32 high-order bits will remain uninitialized data, and can contain anything. Apparently we are so lucky (or unlucky, depending how you look at it), that this almost always happens to contain zero. But on the rare occasion when it doesn't the (1000.*u64ToDouble(nodes))/cps->nps expression can easily overflow the 32-bit int ticklen to which it is assigned, which apparently results in an overflow code 0x80000000 there.

So the bug fixing should consist of figuring out what format string this compiler needs to print a u64 variable...

[H.G.Muller]

The strange thing is that in the following test program, compied with the same compiler, everything works as it should:

Code: Select all

#include <stdio.h>
main()
{
 unsigned long long int t;
 t = ~0;
 printf("low word = %08x, high word = %08x\n", t);
 printf("%llu %d %d %d\n", t, 1, 2, 3);
 sscanf("23", "%llu", &t);
 printf("low word = %08x, high word = %08x\n", t);
 printf("%llu %d %d %d\n", t, 1, 2, 3);
}


Output:

Code: Select all

$ ./a
low word = ffffffff, high word = ffffffff
18446744073709551615 1 2 3
low word = 00000017, high word = 00000000
23 1 2 3


[H.G.Muller]

Aha!

Code: Select all

$ gcc -mno-cygwin test.o -o test.exe

hgm@CHESS_LAPTOP /home/fboard/xboard-4.4.1/winboard
$ ./test
low word = ffffffff, high word = ffffffff
4294967295 -1 1 2
low word = 00000017, high word = ffffffff
23 -1 1 2

hgm@CHESS_LAPTOP /home/fboard/xboard-4.4.1/winboard
$ gcc test.o -o test.exe

hgm@CHESS_LAPTOP /home/fboard/xboard-4.4.1/winboard
$ ./test
low word = ffffffff, high word = ffffffff
18446744073709551615 1 2 3
low word = 00000017, high word = 00000000
23 1 2 3


The problem occurs as soon as I link with -mno-cygwin. Apparently it uses different libraries then, and these libraries have printf and scanf implementations that do not understand the %llu format....

Nasty!

[Michel]

This is a well known problem. Polyglot uses something like this.

#if defined(_MSC_VER) || defined(__MINGW32__) || defined(__MINGW64__)
# define S64_FORMAT "%I64d"
# define U64_FORMAT "%016I64X"
#else
# define S64_FORMAT "%lld"
# define U64_FORMAT "%016llX"
#endif

[Francois]

Great !
This explains why my Visual made exe seemed to work fine.
I will use it while waiting for the official fix.

Thanks

François

[H.G.Muller]

This is a well known problem. Polyglot uses something like this.

#if defined(_MSC_VER) || defined(__MINGW32__) || defined(__MINGW64__)
# define S64_FORMAT "%I64d"
# define U64_FORMAT "%016I64X"
#else
# define S64_FORMAT "%lld"
# define U64_FORMAT "%016llX"
#endif

But this prints the unsigneds as hexadecimal, not? That is no good.

[Michel]

But this prints the unsigneds as hexadecimal, not? That is no good.

Hey yes! I never noticed that. I guess Fabien Letouzey thought unsigned long long's
would only be used as hash codes...

I guess that should be

#define U64_FORMAT "%I64u"

[H.G.Muller]

OK, I tried %I64u, and that seems to work in the test program. When I use the same settings as MSVC for my compiler, I get error messages on the constant suffixes. When I only use the %I64 format, I get warnings for the format not matching the variable.

Is the proper procedure to just ignore these warnings?