Bug in xboard 4.5.2a

[sje]

Bug in xboard 4.5.2a (freshly built and run on Mac OS/X 10.6.7):

While on ICC, in three games in a row late in each game xboard dies with:

Code: Select all

*** error for object 0x1007b7df0: incorrect checksum for freed object - object was probably modified after being freed.
*** set a breakpoint in malloc_error_break to debug

My program then receives an EOF and exits; the game in progress is forfeited.

Note that I may not have the optimal option settings in effect as the last time I used xboard was almost two years ago. I have made an effort to turn off all the stuff I don't need but probably missed something.

Also, I suggest that the sound options be turned off by default, at least for those platforms where the "aplay" program is not present.

[sje]

I switched back to version 4.4.4 and the problem seems to have gone away.

[hgm]

Can you give me the exact option settings yo were using, plus the moves of the game(s) that were played?

It sounds strange to me that XBoard would use free() during a game in the first place. Normally this is only used when you change values of string options, and things like that.

Does your engine send only moves while playing, or does it also use commads like tellics, telall, etc.? (I assume yo dd not make a debug file in any of the crashes? It would be very helpful to see if XBoard crashed on engine input or on ICS input, and which inputtheis was...)

[sje]

Can you give me the exact option settings yo were using, plus the moves of the game(s) that were played?

It sounds strange to me that XBoard would use free() during a game in the first place. Normally this is only used when you change values of string options, and things like that.

Does your engine send only moves while playing, or does it also use commads like tellics, telall, etc.? (I assume yo dd not make a debug file in any of the crashes? It would be very helpful to see if XBoard crashed on engine input or on ICS input, and which inputtheis was...)

Alas, I had already tossed the log file.

Other than the moves being sent, nothing has changed with respect to my program. The xboard invocation is the same as it was two years ago. Everything works fine after going back to 4.4.4 (freshly compiled). This has been tested on two different machines.

Symbolic's transmissions to xboard are unremarkable. The crashes all occurred with no manual input.

Here is a sample log from 4.4.4 that gives sample I/O (see "<" and ">" lines):

Code: Select all

2011.05.10 01:10:00.247 < time 86800
2011.05.10 01:10:00.248 < otim 76300
2011.05.10 01:10:00.250 < usermove Bb2
2011.05.10 01:10:00.250 Playing: 17 Bb2
2011.05.10 01:10:00.250 C/F: [000:00:12:42.998 B 000:00:14:27.999] r2q1rk1/3p2pp/1p2pn2/1Nb5/2Pp4/1P3Q2/PB3PPP/R4RK1 b - - 4 17
2011.05.10 01:10:00.250 Nominal direct search time: 36.166
2011.05.10 01:10:00.250 The move prediction was incorrect.
2011.05.10 01:10:00.288 > 1 33 0 13 17... e5
2011.05.10 01:10:00.288 > 2 30 0 136 17... e5 18 Qd3
2011.05.10 01:10:00.290 > 3 39 0 1077 17... e5 18 Qf5 Qe7
2011.05.10 01:10:00.299 > 4 41 1 5493 17... e5 18 Qg3 Qe7 19 a4
2011.05.10 01:10:00.325 > 5 29 4 21229 17... e5 18 Qf5 d6 19 a4 Qd7
2011.05.10 01:10:00.433 > 6 28 15 97172 17... e5 18 Qf5 d6 19 Rfd1 Qd7 20 Qd3
2011.05.10 01:10:00.776 > 7 38 49 324321 17... e5 18 Qf5 d6 19 f3 Qe7 20 Qd3 d5
2011.05.10 01:10:02.252 > 8 39 197 1363262 17... e5 18 Qf5 d6 19 f3 Qd7 20 Qd3 Bb4 21 a4
2011.05.10 01:10:06.639 > 9 26 635 4400608 17... e5 18 Qe2 Re8 19 a4 d5 20 Rad1 dxc4 21 Qxc4+ Qd5 22 Qd3
2011.05.10 01:10:09.372 Sts: EasyMove   Nodes: 6,320,496   Time: 9.075   Freq: 696431   Period: 1.43589e-06
2011.05.10 01:10:09.372 Analysis: [+0.269/9/6.358/4,400,608/0] 17... e5 18 Qe2 Re8 19 a4 d5 20 Rad1 dxc4 21 Qxc4+ Qd5 22 Qd3
2011.05.10 01:10:09.372 Playing: 17... e5
2011.05.10 01:10:09.372 C/F: [000:00:12:42.998 W 000:00:14:18.877] r2q1rk1/3p2pp/1p3n2/1Nb1p3/2Pp4/1P3Q2/PB3PPP/R4RK1 w - - 0 18
2011.05.10 01:10:09.372 Nominal ponder search time: 35.786
2011.05.10 01:10:09.372 Predicted move: 18 Qe2
2011.05.10 01:10:09.373 > tellall [+0.269/9/6.358/4,400,608/0] 17... e5 18 Qe2 Re8 19 a4 d5 20 Rad1 dxc4 21 Qxc4+ Qd5 22 Qd3
2011.05.10 01:10:09.373 > move e5
2011.05.10 01:10:34.666 < time 86200
2011.05.10 01:10:34.667 < otim 74100
2011.05.10 01:10:34.669 < usermove Qf5
2011.05.10 01:10:34.669 Playing: 18 Qf5
2011.05.10 01:10:34.669 C/F: [000:00:12:20.998 B 000:00:14:21.999] r2q1rk1/3p2pp/1p3n2/1Nb1pQ2/2Pp4/1P6/PB3PPP/R4RK1 b - - 1 18
2011.05.10 01:10:34.669 Nominal direct search time: 35.916
2011.05.10 01:10:34.669 The move prediction was incorrect.
2011.05.10 01:10:34.697 > 1 24 0 21 18... Qb8
2011.05.10 01:10:34.697 > 1 39 0 61 18... Qe7
2011.05.10 01:10:34.698 > 2 42 0 194 18... Qe7 19 a4
2011.05.10 01:10:34.700 > 3 -57 1 814 18... Qe7 19 Rfe1 d5 20 cxd5
2011.05.10 01:10:34.702 > 3 12 1 1150 18... Qb8 19 Rfe1 d6
2011.05.10 01:10:34.709 > 4 15 1 4266 18... Qb8 19 Rfe1 d6 20 a4
2011.05.10 01:10:34.720 > 5 12 2 9913 18... Qb8 19 Rfe1 d6 20 a4 Bb4
2011.05.10 01:10:34.751 > 5 13 6 30263 18... Re8 19 Rfe1 g6 20 Qh3 Kg7
2011.05.10 01:10:34.913 > 6 17 22 147335 18... Re8 19 Rfe1 Qb8 20 a3 Kh8 21 Qd3
2011.05.10 01:10:34.936 > 6 17 24 166242 18... Qb8 19 Rfe1 d6 20 a3 Qc8 21 Qd3
2011.05.10 01:10:34.991 > 7 27 30 201028 18... Qb8 19 Rfe1 d6 20 a4 Qc8 21 Qd3 Ng4
2011.05.10 01:10:37.460 > 8 26 277 1914827 18... Qb8 19 Kh1 Ra5 20 a3 g6 21 Qh3 Be7 22 a4
2011.05.10 01:10:44.633 > 9 5 995 6743345 18... Qb8 19 Rfe1 Re8 20 a3 Re6 21 b4 Bd6 22 Nxd6 Qxd6
2011.05.10 01:10:48.256 > 9 22 1358 9140111 18... Re8 19 Rfe1 g6 20 Qg5 d6 21 a3 Nh5 22 Qh6 Rf8
2011.05.10 01:11:00.667 > 10 18 2601 17637902 18... Re8 19 Rfe1 g6 20 Qg5 d6 21 a3 Kg7 22 Rad1 Qd7 23 a4
2011.05.10 01:11:05.496 Sts: LimitCheckIter   Nodes: 20,958,065   Time: 30.845   Freq: 679443   Period: 1.47179e-06
2011.05.10 01:11:05.496 Analysis: [+0.189/10/26.014/17,637,902/0] 18... Re8 19 Rfe1 g6 20 Qg5 d6 21 a3 Kg7 22 Rad1 Qd7 23 a4
2011.05.10 01:11:05.642 Playing: 18... Re8
2011.05.10 01:11:05.642 C/F: [000:00:12:20.998 W 000:00:13:51.027] r2qr1k1/3p2pp/1p3n2/1Nb1pQ2/2Pp4/1P6/PB3PPP/R4RK1 w - - 2 19
2011.05.10 01:11:05.642 Nominal ponder search time: 34.626
2011.05.10 01:11:05.642 Predicted move: 19 Rfe1
2011.05.10 01:11:05.642 > tellall [+0.189/10/26.014/17,637,902/0] 18... Re8 19 Rfe1 g6 20 Qg5 d6 21 a3 Kg7 22 Rad1 Qd7 23 a4
2011.05.10 01:11:05.642 > move Re8

Sample start-up log:

Code: Select all

2011.05.10 01:05:11.095 < xboard
2011.05.10 01:05:11.096 > tellicsnoalias set 1 Symbolic 2011.05.09 by S. J. Edwards
2011.05.10 01:05:11.096 < protover 2
2011.05.10 01:05:11.097 > feature done=0
2011.05.10 01:05:11.097 > feature analyze=1
2011.05.10 01:05:11.097 > feature colors=0
2011.05.10 01:05:11.097 > feature debug=0
2011.05.10 01:05:11.097 > feature draw=1
2011.05.10 01:05:11.097 > feature ics=1
2011.05.10 01:05:11.097 > feature memory=0
2011.05.10 01:05:11.097 > feature myname="Symbolic 2011.05.09"
2011.05.10 01:05:11.097 > feature name=1
2011.05.10 01:05:11.097 > feature nps=0
2011.05.10 01:05:11.097 > feature pause=0
2011.05.10 01:05:11.097 > feature ping=1
2011.05.10 01:05:11.097 > feature playother=1
2011.05.10 01:05:11.097 > feature reuse=1
2011.05.10 01:05:11.097 > feature san=1
2011.05.10 01:05:11.097 > feature setboard=1
2011.05.10 01:05:11.097 > feature sigint=0
2011.05.10 01:05:11.097 > feature sigterm=0
2011.05.10 01:05:11.097 > feature smp=0
2011.05.10 01:05:11.097 > feature time=1
2011.05.10 01:05:11.097 > feature usermove=1
2011.05.10 01:05:11.097 > feature variants="normal"
2011.05.10 01:05:11.097 > feature done=1
2011.05.10 01:05:11.098 < accepted done
2011.05.10 01:05:11.099 < accepted analyze
2011.05.10 01:05:11.100 < accepted colors
2011.05.10 01:05:11.101 < accepted debug
2011.05.10 01:05:11.103 < accepted draw
2011.05.10 01:05:11.104 < accepted ics
2011.05.10 01:05:11.105 < accepted memory
2011.05.10 01:05:11.109 < accepted myname
2011.05.10 01:05:11.111 < accepted name
2011.05.10 01:05:11.113 < accepted nps
2011.05.10 01:05:11.114 < accepted pause
2011.05.10 01:05:11.115 < accepted ping
2011.05.10 01:05:11.116 < accepted playother
2011.05.10 01:05:11.120 < accepted reuse
2011.05.10 01:05:11.121 < accepted san
2011.05.10 01:05:11.122 < accepted setboard
2011.05.10 01:05:11.124 < accepted sigint
2011.05.10 01:05:11.127 < accepted sigterm
2011.05.10 01:05:11.129 < accepted smp
2011.05.10 01:05:11.131 < accepted time
2011.05.10 01:05:11.132 < accepted usermove
2011.05.10 01:05:11.134 < accepted variants
2011.05.10 01:05:11.135 < accepted done
2011.05.10 01:05:11.136 < new
2011.05.10 01:05:11.136 Initializing for a new game
2011.05.10 01:05:11.137 > tellicsnoalias set 1 Symbolic 2011.05.09 by S. J. Edwards
2011.05.10 01:05:14.756 C/F: [000:00:05:00.000   000:00:05:00.000] rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
2011.05.10 01:05:14.756 New game: Round 1
2011.05.10 01:05:14.756 < random
2011.05.10 01:05:14.757 Random equi-optimal candidate selection is enabled.
2011.05.10 01:05:14.757 < ics chessclub.com
2011.05.10 01:05:14.758 Internet Chess Server: chessclub.com
2011.05.10 01:05:14.758 < post
2011.05.10 01:05:14.759 Status update posting is enabled.
2011.05.10 01:05:14.759 < hard
2011.05.10 01:05:14.760 Ponder searching is enabled.
2011.05.10 01:05:14.761 < ping 1
2011.05.10 01:05:14.762 > pong 1
2011.05.10 01:05:30.464 < level 0 15 3
2011.05.10 01:05:30.465 Note: level command not currently processed
2011.05.10 01:05:30.466 < computer
2011.05.10 01:05:30.466 The opponent is a computer program.
2011.05.10 01:05:30.467 < name ArasanX
2011.05.10 01:05:30.467 Opponent name: ArasanX
2011.05.10 01:05:30.468 > tellopponent Greetings from Symbolic 2011.05.09 by S. J. Edwards
2011.05.10 01:05:30.468 > tellopponent Hello ArasanX, I hope you enjoy this game.
2011.05.10 01:05:30.468 < rating 2356 2255
2011.05.10 01:05:30.468 My rating: 2356   Opponent rating: 2255

xboard invocation:

Code: Select all

/usr/local/bin/xboard \
        -autocomm \
        -autoflag \
        -fcp "./Symbolic -c xboard" \
        -fd $HOME/Arena/Symbolic \
        -hideThinkingFromHuman false \
        -ics \
        -icshost chessclub.com \
        -icshelper $HOME/Arena/Symbolic/tx \
        -icslogon $HOME/Arena/Symbolic/icclogon \
        -sgf $HOME/Arena/Symbolic/icc.pgn \
        -size Medium \
        -thinking \
        -xalarm \
        -xanimate \
        -xbuttons \
        -xrm "*zippyGameEnd: seek 5\nseek 15\n" \
        -xzab \
        -xzadj \
        -zippyMaxGames 2 \
        -zp

[hgm]

OK, thanks. I see you use -autocomm, and this is a potential suspect, as comments are stored in malloc'ed memory. The error message suggest there has been some sort of buffer overrun in the heap, a message overflowing one malloc'ed memory buffer overwriting the start of another one, which then leads to trouble when the latter is free'd.

Were you playing another engine that did excessive kibitzing at the time this happened?

Is there any chance you could reproduce it while running xboard with the extra option -debug (ad send me the xboard.debug file afterwards)?

[sje]

Were you playing another engine that did excessive kibitzing at the time this happened?

No; Arasan doesn't say too much.

If it's of any help, I recall that each of the crashes happened well into a game, 20 to 30 moves.

Is there any chance you could reproduce it while running xboard with the extra option -debug (ad send me the xboard.debug file afterwards)?

I could, but I'd have to dump 4.4.4, re-install 4.5.2a, and then revert to get back to where it is now.

And I'm not sure that a debug log would say much more than what appeared on the console: a trap echoing the command line call followed by the diagnostic I posted earlier. Does xboard log an output line for each malloc/free?

[hgm]

Does xboard log an output line for each malloc/free?

No, it doesn't. But the crucial information I need to have a chance to debug this is what triggered it. Was XBoard processing input from the ICS or from the engine, and what was that input? (E.g. shouts, says, tells or kibitzes from the ICS, a move list it requested, a board with the opponent move thining output, a move or tellopponent command from the engine, etc.) That would enable me to determine what XBoard was likely attempting to do when it crashed, and then I could scrutinize the code for doing it for frees and mallocs. And all that engine and ICS communication is logged in the xboard.debug file.

Without that I can only make blind guesses. I don't think there is any use of malloc and free in the code that relays moves between ICS and engine, and move lists are normally not requested during a game (unless you are observing other games tthe same time). On the other hand, ICS usually sent an enormous amount of chatter, and in -autocomm mode, part of that chatter triggers actions in XBoard. I know that comments to moves are stored in malloc'ed memory, which involves free'ing previously hold comments for that move, and in -autocomm mode some of the say/kibitz/tell commands are captured by XBoard and added to the move.

[sje]

Does xboard log an output line for each malloc/free?

No, it doesn't. But the crucial information I need to have a chance to debug this is what triggered it. Was XBoard processing input from the ICS or from the engine, and what was that input? (E.g. shouts, says, tells or kibitzes from the ICS, a move list it requested, a board with the opponent move thining output, a move or tellopponent command from the engine, etc.) That would enable me to determine what XBoard was likely attempting to do when it crashed, and then I could scrutinize the code for doing it for frees and mallocs. And all that engine and ICS communication is logged in the xboard.debug file.

Without that I can only make blind guesses. I don't think there is any use of malloc and free in the code that relays moves between ICS and engine, and move lists are normally not requested during a game (unless you are observing other games tthe same time). On the other hand, ICS usually sent an enormous amount of chatter, and in -autocomm mode, part of that chatter triggers actions in XBoard. I know that comments to moves are stored in malloc'ed memory, which involves free'ing previously hold comments for that move, and in -autocomm mode some of the say/kibitz/tell commands are captured by XBoard and added to the move.

I understand. Some of Symbolic's analysis outputs via "tellall/tellopponent" can be long, sometimes very long. But these seemed to have worked in the past and under 4.4.4 xboard.

I do recall an xboard bug with long analyses showing in the GUI analysis line display.

Perhaps there are malloc/free bugs that go unnoticed under Windows or Linux but are detected under Mac OS/X?

Maybe I'll give it a try. What options does 4.5.2a need to activate debugging? What and where is the output debug file?

[hgm]

Just "-debug" will do it, and causes the creation of a file 'xboard.debug' in the current directory. You can change the location with the option "-debugFile OTHERNAME" if that is not convenient. (Note that each XBoard session opens the debug file for writing, not appending.)

[sje]

Just "-debug" will do it, and causes the creation of a file 'xboard.debug' in the current directory. You can change the location with the option "-debugFile OTHERNAME" if that is not convenient. (Note that each XBoard session opens the debug file for writing, not appending.)

Okay, I'll give this a try later. Fortunately the problem has been easy to reproduce.