Using log files for program authentication

[sje]

The idea of using log files for program authentication has been around for some years. However, the execution has at times left much to be desired. For example, the Deep Blue logs were poorly formatted, omitted some kinds of data, and were not available in real time. My suggestion is that authors should agree on minimum requirements for chess program log file output with respect to content and availability. There are a number of benefits resulting from producing comprehensive log output, not the least of which is a defense against false allegations of presenting unoriginal or unauthorized work (i.e., cloning).

Here are what I propose as minimum requirements:

1) A log file should be composed of ASCII text lines with each line being labeled as to what kind of output is presented for that line. Examples: input from the command interface (or GUI), output to the same, moves as they are played, results as they are established, current state of the move selection process, current state of the position, and the current value of the chess clock (if any).

2) Each line should begin with a timestamp with reasonable resolution. Symbolic uses YYYY.MM.DD HH:MM:SS.mmm and could be tweaked to give microsecond resolution (or tweaked to provide only second resolution). It may be a good idea to present the time values as UTC rather than local time for events with remote participants or observers.

3) There should be some mechanism for spooling the log file to a networked web server in real time. This is needed both to serve spectators and to provide support for third party archival assurance purposes.

4) It could be the case that some contents will be dependent on the GUI is use. This shouldn't be a real problem as long as the move selection is clearly shown to be that of the engine (or of the GUI when such is allowed).

5) Sample log files from all of the participants in an event should be publicly posted well before the event. Log files produced during an event should be sent to the event director (preferably in real time) asd also be publicly posted after each round.

Here's a sample log file excerpt from the new Symbolic core running under Xboard:

Code: Select all

2009.04.11 03:20:00.647 < time 259654
2009.04.11 03:20:00.649 < otim 255159
2009.04.11 03:20:00.651 < usermove Qb5
2009.04.11 03:20:00.652 Playing: 11 Qb5
2009.04.11 03:20:00.652 FEN: r2q3r/1pp2ppp/2nbkn2/pQ1pNp2/3P1P2/2N1P3/PPP3PP/R1B2RK1 b - - 3 11
2009.04.11 03:20:00.652 CC: [000:00:42:31.587 B 000:00:43:16.539]
2009.04.11 03:20:00.662 > 0 0 0 0 11... Nxe5
2009.04.11 03:20:00.662 > 1 6 0 13 11... Nxe5 12 fxe5
2009.04.11 03:20:00.662 > 1 12 0 30 11... Bxe5 12 fxe5
2009.04.11 03:20:00.662 > 2 12 0 236 11... Bxe5 12 fxe5
2009.04.11 03:20:00.665 > 3 -83 0 2531 11... Bxe5 12 fxe5 Ne4 13 Qxb7
2009.04.11 03:20:00.667 > 3 -77 0 3646 11... Qe7 12 Nxc6 bxc6 13 Qxc6
2009.04.11 03:20:00.684 > 3 6 2 17696 11... Nb4 12 Qxb7 Bxe5 13 fxe5 Nxc2
2009.04.11 03:20:00.699 > 4 5 3 29540 11... Nb4 12 Rf2 b6 13 Nf3
2009.04.11 03:20:00.811 > 5 12 14 131897 11... Nb4 12 Rb1 Nxc2 13 Qxb7 Qe7
2009.04.11 03:20:01.596 > 6 11 93 876550 11... Nb4 12 Qe2 Qe7 13 a3 Bxe5 14 axb4
2009.04.11 03:20:06.133 > 7 15 546 5267690 11... Nb4 12 Qxb7 Bxe5 13 fxe5 Rb8 14 Qa7 Nxc2
2009.04.11 03:20:37.937 > 8 8 3725 37146359 11... Nb4 12 Qe2 Qe7 13 a3 Nc6 14 Nxc6 bxc6 15 Bd2
2009.04.11 03:21:44.577 Analysis: [+0.081/37,146,359] 11... Nb4 12 Qe2 Qe7 13 a3 Nc6 14 Nxc6 bxc6 15 Bd2
2009.04.11 03:21:44.577 Playing: 11... Nb4
2009.04.11 03:21:44.577 FEN: r2q3r/1pp2ppp/3bkn2/pQ1pNp2/1n1P1P2/2N1P3/PPP3PP/R1B2RK1 w - - 4 12
2009.04.11 03:21:44.577 CC: [000:00:42:31.587 W 000:00:41:32.614]
2009.04.11 03:21:44.577 > move Nb4

[sje]

Here's an example of the start of a log file from Symbolic that shows the details of program and game initialization:

Code: Select all

2009.04.11 02:45:47.428 Symbolic 2009.04.10   Started Sat Apr 11 02:45:47 2009
2009.04.11 02:45:47.428 Environment: 
2009.04.11 02:45:47.428   Host: gail
2009.04.11 02:45:47.428   Processor core count: 4
2009.04.11 02:45:47.428   Symbols: HostOsApple HostIsUnixLike HostCpuX86 HostArchBits64 UseInline UseInlineX86B64
2009.04.11 02:45:47.428 Command line options: 
2009.04.11 02:45:47.428   Option -b argument: Symbolic.book
2009.04.11 02:45:47.428   Option -c argument: xboard
2009.04.11 02:45:47.428   Option -g argument: Symbolic.pgn
2009.04.11 02:45:47.428   Option -l argument: xboard.log
2009.04.11 02:45:47.428   Option -t argument: TB
2009.04.11 02:45:47.471 IntervalTimer periodic interrupt timekeeper subsystem ready
2009.04.11 02:45:47.471 SignalHandlers signal catching subsystem ready
2009.04.11 02:45:47.471 Chess classes initialization started
2009.04.11 02:45:47.474 Chess classes initialization done
2009.04.11 02:45:47.474 Self testing of chess data processing started
2009.04.11 02:45:47.800 Self testing passed
2009.04.11 02:45:47.800 Self testing done
2009.04.11 02:45:47.800 Opening book cache object created
2009.04.11 02:45:47.908 Opening book image loaded   2,423,160 bytes   100,965 moves
2009.04.11 02:45:47.908 Endgame tablebase cache object created
2009.04.11 02:45:47.908 Tablebase directory: TB
2009.04.11 02:45:47.908 Command stream input stack initializing
2009.04.11 02:45:47.908 WatchTask text I/O and signal relay subsystem starting
2009.04.11 02:45:47.908 WatchTask ready
2009.04.11 02:45:47.911 Selected command processor initializing
2009.04.11 02:45:47.912 Command processor base class instance starting
2009.04.11 02:45:47.912 Command input is not interactive
2009.04.11 02:45:47.912 MetaSearch mulithreaded move selection subsystem starting
2009.04.11 02:45:48.783 MetaSearch ready
2009.04.11 02:45:48.783 CpXboardTask Xboard GUI link command processor starting
2009.04.11 02:45:48.783 CpXboardTask ready
2009.04.11 02:45:48.784 DriverTask ready
2009.04.11 02:45:48.784 < xboard
2009.04.11 02:45:48.785 > tellicsnoalias set 1 Symbolic 2009.04.10 by S. J. Edwards
2009.04.11 02:45:48.785 < protover 2
2009.04.11 02:45:48.786 > feature done=0
2009.04.11 02:45:48.786 > feature analyze=1
2009.04.11 02:45:48.786 > feature colors=0
2009.04.11 02:45:48.786 > feature debug=0
2009.04.11 02:45:48.786 > feature draw=1
2009.04.11 02:45:48.786 > feature ics=1
2009.04.11 02:45:48.786 > feature memory=0
2009.04.11 02:45:48.786 > feature myname="Symbolic 2009.04.10"
2009.04.11 02:45:48.786 > feature name=1
2009.04.11 02:45:48.786 > feature nps=0
2009.04.11 02:45:48.786 > feature pause=0
2009.04.11 02:45:48.786 > feature ping=1
2009.04.11 02:45:48.786 > feature playother=1
2009.04.11 02:45:48.786 > feature reuse=1
2009.04.11 02:45:48.786 > feature san=1
2009.04.11 02:45:48.786 > feature setboard=1
2009.04.11 02:45:48.786 > feature sigint=0
2009.04.11 02:45:48.786 > feature sigterm=0
2009.04.11 02:45:48.787 > feature smp=0
2009.04.11 02:45:48.787 > feature time=1
2009.04.11 02:45:48.787 > feature usermove=1
2009.04.11 02:45:48.787 > feature variants="normal"
2009.04.11 02:45:48.787 > feature done=1
2009.04.11 02:45:48.787 < accepted done
2009.04.11 02:45:48.788 < accepted analyze
2009.04.11 02:45:48.789 < accepted colors
2009.04.11 02:45:48.790 < accepted debug
2009.04.11 02:45:48.791 < accepted draw
2009.04.11 02:45:48.792 < accepted ics
2009.04.11 02:45:48.794 < accepted memory
2009.04.11 02:45:48.795 < accepted myname
2009.04.11 02:45:48.796 < accepted name
2009.04.11 02:45:48.797 < accepted nps
2009.04.11 02:45:48.798 < accepted pause
2009.04.11 02:45:48.799 < accepted ping
2009.04.11 02:45:48.800 < accepted playother
2009.04.11 02:45:48.802 < accepted reuse
2009.04.11 02:45:48.803 < accepted san
2009.04.11 02:45:48.804 < accepted setboard
2009.04.11 02:45:48.805 < accepted sigint
2009.04.11 02:45:48.806 < accepted sigterm
2009.04.11 02:45:48.807 < accepted smp
2009.04.11 02:45:48.808 < accepted time
2009.04.11 02:45:48.809 < accepted usermove
2009.04.11 02:45:48.811 < accepted variants
2009.04.11 02:45:48.812 < accepted done
2009.04.11 02:45:48.813 < new
2009.04.11 02:45:48.814 Initializing for a new game
2009.04.11 02:45:48.814 FEN: rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
2009.04.11 02:45:48.814 CC: [000:00:05:00.000   000:00:05:00.000]
2009.04.11 02:45:48.814 New game: Round 1
2009.04.11 02:45:48.814 < random
2009.04.11 02:45:48.815 Random equi-optimal candidate selection is enabled.
2009.04.11 02:45:48.815 < ics -
2009.04.11 02:45:48.816 Internet Chess Server: -
2009.04.11 02:45:48.816 < level 0 60 0
2009.04.11 02:45:48.817 < post
2009.04.11 02:45:48.818 Status update posting is enabled.
2009.04.11 02:45:48.818 < hard
2009.04.11 02:45:48.819 Ponder searching is enabled.
2009.04.11 02:45:48.820 < easy
2009.04.11 02:45:48.820 Ponder searching is disabled.
2009.04.11 02:45:48.821 < ping 1
2009.04.11 02:45:48.822 > pong 1
2009.04.11 02:45:48.822 < force
2009.04.11 02:45:48.823 < computer
2009.04.11 02:45:48.823 The opponent is a computer program.
2009.04.11 02:45:48.824 < name Symbolic v2008.05.25
2009.04.11 02:45:48.824 Opponent name: Symbolic v2008.05.25
2009.04.11 02:45:48.825 < time 360000
2009.04.11 02:45:48.826 < otim 359999
2009.04.11 02:45:48.827 < usermove Nc3
2009.04.11 02:45:48.827 Playing: 1 Nc3
2009.04.11 02:45:48.828 FEN: rnbqkbnr/pppppppp/8/8/8/2N5/PPPPPPPP/R1BQKBNR b KQkq - 1 1
2009.04.11 02:45:48.828 CC: [000:00:05:00.000 B 000:00:04:59.999]
2009.04.11 02:45:48.828 < go

[henkf]

Here's an example of the start of a log file from Symbolic that shows the details of program and game initialization:

I recently started working on a new engine. As you can see from the log file it creates, ( almost ) nothing is working yet, but it seems I've got your approval for the logging feature itself.

Code: Select all

2009-04-11 08:26:10:682 -------------------------------------------------------
2009-04-11 08:26:10:683 +PROGRAM  ************** PROGRAM STARTUP **************
2009-04-11 08:26:10:683 +INIT     Initialization started
2009-04-11 08:26:10:683 -INIT     Initialization finished
2009-04-11 08:26:10:683 +SANITY   Sanity check started
2009-04-11 08:26:10:683 +COLORS   Colors check started
2009-04-11 08:26:10:683 -COLORS   Colors check succeeded
2009-04-11 08:26:10:683 +DIRECT   Directions check started
2009-04-11 08:26:10:683 -DIRECT   Directions check succeeded
2009-04-11 08:26:10:683 +SQUARES  Squares check started
2009-04-11 08:26:10:683 -SQUARES  Squares check succeeded
2009-04-11 08:26:10:683 +MEN      Men check started
2009-04-11 08:26:10:683 -MEN      Men check succeeded
2009-04-11 08:26:10:683 +TIME     Time check started
2009-04-11 08:26:10:683 -TIME     Time check succeeded
2009-04-11 08:26:10:683 +MOVE     Move check started
2009-04-11 08:26:10:683 -MOVE     Move check succeeded
2009-04-11 08:26:10:683 +UNDO     Undo check started
2009-04-11 08:26:10:683 -UNDO     Undo check succeeded
2009-04-11 08:26:10:683 +PIECE    Piece check started
2009-04-11 08:26:10:684 -PIECE    Piece check succeeded
2009-04-11 08:26:10:684 +BOARD    Board check started
2009-04-11 08:26:10:684 <FEN      rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq -
2009-04-11 08:26:10:684 >FEN      rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq -
2009-04-11 08:26:10:684 -BOARD    Board check succeeded
2009-04-11 08:26:10:684 +GENERATE Generate check started
2009-04-11 08:26:10:684 <FEN      rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq -
2009-04-11 08:26:10:684 -GENERATE Generate check succeeded
2009-04-11 08:26:10:684 +ATTACK   Attack check started
2009-04-11 08:26:10:684 +ATTACK   Attack check succeeded
2009-04-11 08:26:10:684 +MAKE     Make check started
2009-04-11 08:26:10:684 <FEN      rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq -
2009-04-11 08:26:10:684 >FEN      rnbqkbnr/pppppppp/8/8/4P3/8/PPPP1PPP/RNBQKBNR b KQkq e3
2009-04-11 08:26:10:684 >FEN      rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq -
2009-04-11 08:26:10:684 -MAKE     Make check succeeded
2009-04-11 08:26:10:684 +PERFT    Perft check started
2009-04-11 08:26:10:684 <FEN      rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq -
2009-04-11 08:26:10:691 >FEN      rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq -
2009-04-11 08:26:10:691 -PERFT    Perft check succeeded
2009-04-11 08:26:10:691 -SANITY   Sanity check finished. 291 tests succeeded
2009-04-11 08:26:10:691 +IO       IO loop started
2009-04-11 08:26:10:947 <IO       xboard
2009-04-11 08:26:10:947 <IO       protover 2
2009-04-11 08:26:20:968 <IO       new
2009-04-11 08:26:20:969 <IO       random
2009-04-11 08:26:20:969 <IO       level 0 20 20
2009-04-11 08:26:20:969 <IO       post
2009-04-11 08:26:20:969 <IO       hard
2009-04-11 08:26:20:976 <IO       force
2009-04-11 08:26:21:755 <IO       computer
2009-04-11 08:26:21:756 <IO       black
2009-04-11 08:26:21:756 <IO       time 120000
2009-04-11 08:26:21:756 <IO       otim 120000
2009-04-11 08:26:21:757 <IO       white
2009-04-11 08:26:21:757 <IO       go
2009-04-11 08:26:31:159 <IO       force
2009-04-11 08:26:33:452 <IO       quit
2009-04-11 08:26:33:452 -IO       IO loop ended
2009-04-11 08:26:33:452 -PROGRAM  ************** PROGRAM SHUTDOWN *************

[sje]

Looks like a good start. Do you use UTC values for your timestamps? I've switched to UTC for logging to avoid timezone chauvinism. Also, the US government screws around with dates for Daylight Saving (European "Summer Time") every few years and I can't expect those outside the country to keep up with the changes.

Timebase drift can be a concern. Some machines have drift in excess of thirty seconds per day, poorer than an inexpensive mechanical wristwatch. It might be worthwhile to have a chess program force a re-synchronization of the system clock with a reliable timeserver at the start of each session.

[henkf]

Looks like a good start. Do you use UTC values for your timestamps? I've switched to UTC for logging to avoid timezone chauvinism. Also, the US government screws around with dates for Daylight Saving (European "Summer Time") every few years and I can't expect those outside the country to keep up with the changes.

Indeed I do. I'm using the windows api call GetSystemTime. I wouldn't mind that all local times would be set to UTC. For me it's close enough to be comfortable. Actually I guess in this case about 80% of the world population could sleep a bit longer in the morning

Timebase drift can be a concern. Some machines have drift in excess of thirty seconds per day, poorer than an inexpensive mechanical wristwatch. It might be worthwhile to have a chess program force a re-synchronization of the system clock with a reliable timeserver at the start of each session.

Allthough I have, like you seem to have, a tendency to be concerned about these details, I'm not too worried about this timedrift with regards to logging. I think it would be easy enough to calibrate two log files with each other.

[sje]

Timebase drift can be a concern. Some machines have drift in excess of thirty seconds per day, poorer than an inexpensive mechanical wristwatch. It might be worthwhile to have a chess program force a re-synchronization of the system clock with a reliable timeserver at the start of each session.

Allthough I have, like you seem to have, a tendency to be concerned about these details, I'm not too worried about this timedrift with regards to logging. I think it would be easy enough to calibrate two log files with each other.

Drift can be corrected in two ways: by a counter drift, or by an immediate setting of the correct time value. It's the latter that can disrupt timestamps noticeably, including jumping back in time.