Symbolic: I/O handling and sample logfile

[sje]

In Symbolic, all writes to the standard output are gated to a single statement in a single routine which uses a mutex. Each output produces a single line of text, guaranteed not to have jumbled characters from multiple simultaneous accesses. The only exception to this output handling is when the program detects a user error; it then emits a beep by outputting the BEL (0x07) character.

If Symbolic detects that the command input stream is regular file and is not a terminal, it will skip issuing a command prompt.

Each line of output other than the command prompt "[] " is also written to a logfile. Each line in the logfile has a UTC timestamp wilth millisecond resolution. All writing activity has a forced buffer flush at the end of each line.

When the program detects an internal error, it reports the error to the standard error file output and also it a one line external file named CauseOfDeath.

All input is handled with a single call to read(), getting one character at a time. The call is made only when the select() routine detects pending input; therefore the read() call will not block. Note that it is important not to mix C++ I/O routine calls like getline() when accessing a stream with old style C calls like read(), write(), and select(). The program correctly handles an end of file, either from an input command file or by the user typing a contral-D character.

Sample logfile:

Code: Select all

[2013.08.14 15:55:39.710] Symbolic 2013.08.14   Log begun at local time 2013.08.14 11:55:39
[2013.08.14 15:55:39.710] 
[2013.08.14 15:55:39.710] Environment:
[2013.08.14 15:55:39.710]   Host: gail
[2013.08.14 15:55:39.710]   O/S: Apple
[2013.08.14 15:55:39.710] 
[2013.08.14 15:55:39.710] Hardware:
[2013.08.14 15:55:39.710]   Processor: Intel/AMD
[2013.08.14 15:55:39.710]   Word size (bits): 64
[2013.08.14 15:55:39.710]   Cores: 4
[2013.08.14 15:55:39.710]   RAM (MB): 24,576
[2013.08.14 15:55:39.710] 
[2013.08.14 15:55:39.710] Argument count: 1
[2013.08.14 15:55:39.710]   argv[0]: ./Symbolic
[2013.08.14 15:55:39.710] 
[2013.08.14 15:55:39.710] Constant values initialization begun
[2013.08.14 15:55:39.711] Constant values initialization ended
[2013.08.14 15:55:39.711] Class initialization begun
[2013.08.14 15:55:39.736] Class initialization ended
[2013.08.14 15:55:39.736] Argument scan begun
[2013.08.14 15:55:39.736]   Option -b: Book
[2013.08.14 15:55:39.736]   Option -c: I
[2013.08.14 15:55:39.736]   Option -t: TB
[2013.08.14 15:55:39.736] Argument scan ended
[2013.08.14 15:55:39.736] Watcher created
[2013.08.14 15:55:39.736] Watcher::RunLoop begun
[2013.08.14 15:55:39.736] Watcher::RunLoop waiting for gate
[2013.08.14 15:55:39.736] CoPro created
[2013.08.14 15:55:39.736] Transposition table set allocation begun
[2013.08.14 15:55:39.736] Allocating full position transposition table
[2013.08.14 15:55:40.587]   Full position table entry count: 33,554,432
[2013.08.14 15:55:40.587]   Full position table memory size: 805,306,368
[2013.08.14 15:55:40.587] Allocating material balance transposition table
[2013.08.14 15:55:40.692]   Material balance table entry count: 4,194,304
[2013.08.14 15:55:40.692]   Material balance table memory size: 100,663,296
[2013.08.14 15:55:40.692] Allocating pawn structure transposition table
[2013.08.14 15:55:40.963]   Pawn structure table entry count: 4,194,304
[2013.08.14 15:55:40.963]   Pawn structure table memory size: 268,435,456
[2013.08.14 15:55:40.963] Allocating tablebase score transposition table
[2013.08.14 15:55:41.067]   Tablebase score table entry count: 4,194,304
[2013.08.14 15:55:41.067]   Tablebase score table memory size: 100,663,296
[2013.08.14 15:55:41.067] Transposition table set allocation ended
[2013.08.14 15:55:41.067] Loading opening book file: Book
[2013.08.14 15:55:41.453]   Opening book entry count: 226,912
[2013.08.14 15:55:41.453]   Opening book memory size: 7,261,184
[2013.08.14 15:55:41.453] New game
[2013.08.14 15:55:41.453] FEN: rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
[2013.08.14 15:55:41.453] IntCoPro created
[2013.08.14 15:55:41.453] > Symbolic 2013.08.14 by S. J. Edwards
[2013.08.14 15:55:41.453] > Symbolic ready
[2013.08.14 15:55:41.453] > 
[2013.08.14 15:55:41.454] IntCoPro::RunLoop begun
[2013.08.14 15:55:41.454] Watcher::RunLoop gate open
[2013.08.14 15:56:01.009] < help
[2013.08.14 15:56:01.019] >      db  Display board
[2013.08.14 15:56:01.019] > dbcolor  Display board (color)
[2013.08.14 15:56:01.019] >  dbmono  Display board (mono)
[2013.08.14 15:56:01.019] >     dcc  Display chess clock
[2013.08.14 15:56:01.019] >      df  Display FEN
[2013.08.14 15:56:01.019] >      dg  Display game (PGN)
[2013.08.14 15:56:01.019] >     dhm  Display history moves
[2013.08.14 15:56:01.019] >     did  Display program identification
[2013.08.14 15:56:01.019] >     dif  Display initial FEN
[2013.08.14 15:56:01.019] >      dm  Display moves
[2013.08.14 15:56:01.019] >    dobm  Display opening book moves
[2013.08.14 15:56:01.019] >    dpgn  Display PGN game
[2013.08.14 15:56:01.019] >      ds  Display status
[2013.08.14 15:56:01.019] >    exit  Flip the position
[2013.08.14 15:56:01.019] >    flip  Exit program
[2013.08.14 15:56:01.019] >    help  Show help strings
[2013.08.14 15:56:01.019] > loadfen  Load FEN from file
[2013.08.14 15:56:01.019] > loadpgn  Load PGN from file
[2013.08.14 15:56:01.019] >     new  New game
[2013.08.14 15:56:01.019] >    noop  No operation
[2013.08.14 15:56:01.019] >  pcbulk  Path count (bulk mode)
[2013.08.14 15:56:01.019] >  pcfull  Path count (full mode)
[2013.08.14 15:56:01.019] >  pctran  Path count (tran mode)
[2013.08.14 15:56:01.019] >      rg  Random game generation
[2013.08.14 15:56:01.019] >      rm  Retract move
[2013.08.14 15:56:01.019] >    rmts  Retract moves to start
[2013.08.14 15:56:01.019] > savefen  Save FEN to file
[2013.08.14 15:56:01.019] > savepgn  Save PGN to file
[2013.08.14 15:56:01.019] >      sf  Set FEN
[2013.08.14 15:56:01.019] >    test  Test
[2013.08.14 15:56:01.019] >      uc  Unique position generation
[2013.08.14 15:56:01.019] > xpcpass  External path count pass
[2013.08.14 15:56:01.019] >  xpcsum  External path count sum
[2013.08.14 15:56:16.897] < df
[2013.08.14 15:56:16.907] > rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
[2013.08.14 15:56:31.919] < did
[2013.08.14 15:56:31.930] > Symbolic 2013.08.14
[2013.08.14 15:56:47.674] < pcfull 6
[2013.08.14 15:56:47.677] PCTask::RunLoop begun
[2013.08.14 15:56:47.677] PCTask::RunLoop begun
[2013.08.14 15:56:47.677] PCTask::RunLoop begun
[2013.08.14 15:56:47.677] PCTask::RunLoop begun
[2013.08.14 15:56:56.487] PCTask::RunLoop ended
[2013.08.14 15:56:56.498] PCTask::RunLoop ended
[2013.08.14 15:56:56.505] PCTask::RunLoop ended
[2013.08.14 15:56:56.511] PCTask::RunLoop ended
[2013.08.14 15:56:56.511] > PathFull(6): 119,060,324   Pt: 34.118   Wt: 8.834   F/P: 1.34771e+07/7.41997e-08
[2013.08.14 15:57:02.076] < exit
[2013.08.14 15:57:02.087] IntCoPro::Dispatch exit commanded
[2013.08.14 15:57:02.087] IntCoPro::RunLoop ended
[2013.08.14 15:57:02.088] > 
[2013.08.14 15:57:02.088] > Symbolic done
[2013.08.14 15:57:02.088] IntCoPro destroyed
[2013.08.14 15:57:02.088] Unloading opening book
[2013.08.14 15:57:02.088] Transposition table set deallocation begun
[2013.08.14 15:57:02.088] Deallocating tablebase score transposition table
[2013.08.14 15:57:02.103] Deallocating pawn structure transposition table
[2013.08.14 15:57:02.132] Deallocating material balance transposition table
[2013.08.14 15:57:02.149] Deallocating full position transposition table
[2013.08.14 15:57:02.243] Transposition table set deallocation ended
[2013.08.14 15:57:02.243] CoPro Proc time: 34.903
[2013.08.14 15:57:02.243] CoPro Wall time: 1:22.506
[2013.08.14 15:57:02.243] CoPro destroyed
[2013.08.14 15:57:02.252] Watcher::RunLoop ended
[2013.08.14 15:57:02.253] Watcher destroyed
[2013.08.14 15:57:02.253] Class termination begun
[2013.08.14 15:57:02.253] Class termination ended
[2013.08.14 15:57:02.253] Symbolic 2013.08.14   Log ended at local time 2013.08.14 11:57:02

[michiguel]

In Symbolic, all writes to the standard output are gated to a single statement in a single routine which uses a mutex. Each output produces a single line of text, guaranteed not to have jumbled characters from multiple simultaneous accesses. The only exception to this output handling is when the program detects a user error; it then emits a beep by outputting the BEL (0x07) character.

If Symbolic detects that the command input stream is regular file and is not a terminal, it will skip issuing a command prompt.

Each line of output other than the command prompt "[] " is also written to a logfile. Each line in the logfile has a UTC timestamp wilth millisecond resolution. All writing activity has a forced buffer flush at the end of each line.

When the program detects an internal error, it reports the error to the standard error file output and also it a one line external file named CauseOfDeath.

All input is handled with a single call to read(), getting one character at a time. The call is made only when the select() routine detects pending input; therefore the read() call will not block. Note that it is important not to mix C++ I/O routine calls like getline() when accessing a stream with old style C calls like read(), write(), and select(). The program correctly handles an end of file, either from an input command file or by the user typing a contral-D character.

Sample logfile:

Code: Select all

[2013.08.14 15:55:39.710] Symbolic 2013.08.14   Log begun at local time 2013.08.14 11:55:39
[2013.08.14 15:55:39.710] 
[2013.08.14 15:55:39.710] Environment:
[2013.08.14 15:55:39.710]   Host: gail
[2013.08.14 15:55:39.710]   O/S: Apple
[2013.08.14 15:55:39.710] 
[2013.08.14 15:55:39.710] Hardware:
[2013.08.14 15:55:39.710]   Processor: Intel/AMD
[2013.08.14 15:55:39.710]   Word size (bits): 64
[2013.08.14 15:55:39.710]   Cores: 4
[2013.08.14 15:55:39.710]   RAM (MB): 24,576
[2013.08.14 15:55:39.710] 
[2013.08.14 15:55:39.710] Argument count: 1
[2013.08.14 15:55:39.710]   argv[0]: ./Symbolic
[2013.08.14 15:55:39.710] 
[2013.08.14 15:55:39.710] Constant values initialization begun
[2013.08.14 15:55:39.711] Constant values initialization ended
[2013.08.14 15:55:39.711] Class initialization begun
[2013.08.14 15:55:39.736] Class initialization ended
[2013.08.14 15:55:39.736] Argument scan begun
[2013.08.14 15:55:39.736]   Option -b: Book
[2013.08.14 15:55:39.736]   Option -c: I
[2013.08.14 15:55:39.736]   Option -t: TB
[2013.08.14 15:55:39.736] Argument scan ended
[2013.08.14 15:55:39.736] Watcher created
[2013.08.14 15:55:39.736] Watcher::RunLoop begun
[2013.08.14 15:55:39.736] Watcher::RunLoop waiting for gate
[2013.08.14 15:55:39.736] CoPro created
[2013.08.14 15:55:39.736] Transposition table set allocation begun
[2013.08.14 15:55:39.736] Allocating full position transposition table
[2013.08.14 15:55:40.587]   Full position table entry count: 33,554,432
[2013.08.14 15:55:40.587]   Full position table memory size: 805,306,368
[2013.08.14 15:55:40.587] Allocating material balance transposition table
[2013.08.14 15:55:40.692]   Material balance table entry count: 4,194,304
[2013.08.14 15:55:40.692]   Material balance table memory size: 100,663,296
[2013.08.14 15:55:40.692] Allocating pawn structure transposition table
[2013.08.14 15:55:40.963]   Pawn structure table entry count: 4,194,304
[2013.08.14 15:55:40.963]   Pawn structure table memory size: 268,435,456
[2013.08.14 15:55:40.963] Allocating tablebase score transposition table
[2013.08.14 15:55:41.067]   Tablebase score table entry count: 4,194,304
[2013.08.14 15:55:41.067]   Tablebase score table memory size: 100,663,296
[2013.08.14 15:55:41.067] Transposition table set allocation ended
[2013.08.14 15:55:41.067] Loading opening book file: Book
[2013.08.14 15:55:41.453]   Opening book entry count: 226,912
[2013.08.14 15:55:41.453]   Opening book memory size: 7,261,184
[2013.08.14 15:55:41.453] New game
[2013.08.14 15:55:41.453] FEN: rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
[2013.08.14 15:55:41.453] IntCoPro created
[2013.08.14 15:55:41.453] > Symbolic 2013.08.14 by S. J. Edwards
[2013.08.14 15:55:41.453] > Symbolic ready
[2013.08.14 15:55:41.453] > 
[2013.08.14 15:55:41.454] IntCoPro::RunLoop begun
[2013.08.14 15:55:41.454] Watcher::RunLoop gate open
[2013.08.14 15:56:01.009] < help
[2013.08.14 15:56:01.019] >      db  Display board
[2013.08.14 15:56:01.019] > dbcolor  Display board (color)
[2013.08.14 15:56:01.019] >  dbmono  Display board (mono)
[2013.08.14 15:56:01.019] >     dcc  Display chess clock
[2013.08.14 15:56:01.019] >      df  Display FEN
[2013.08.14 15:56:01.019] >      dg  Display game (PGN)
[2013.08.14 15:56:01.019] >     dhm  Display history moves
[2013.08.14 15:56:01.019] >     did  Display program identification
[2013.08.14 15:56:01.019] >     dif  Display initial FEN
[2013.08.14 15:56:01.019] >      dm  Display moves
[2013.08.14 15:56:01.019] >    dobm  Display opening book moves
[2013.08.14 15:56:01.019] >    dpgn  Display PGN game
[2013.08.14 15:56:01.019] >      ds  Display status
[2013.08.14 15:56:01.019] >    exit  Flip the position
[2013.08.14 15:56:01.019] >    flip  Exit program
[2013.08.14 15:56:01.019] >    help  Show help strings
[2013.08.14 15:56:01.019] > loadfen  Load FEN from file
[2013.08.14 15:56:01.019] > loadpgn  Load PGN from file
[2013.08.14 15:56:01.019] >     new  New game
[2013.08.14 15:56:01.019] >    noop  No operation
[2013.08.14 15:56:01.019] >  pcbulk  Path count (bulk mode)
[2013.08.14 15:56:01.019] >  pcfull  Path count (full mode)
[2013.08.14 15:56:01.019] >  pctran  Path count (tran mode)
[2013.08.14 15:56:01.019] >      rg  Random game generation
[2013.08.14 15:56:01.019] >      rm  Retract move
[2013.08.14 15:56:01.019] >    rmts  Retract moves to start
[2013.08.14 15:56:01.019] > savefen  Save FEN to file
[2013.08.14 15:56:01.019] > savepgn  Save PGN to file
[2013.08.14 15:56:01.019] >      sf  Set FEN
[2013.08.14 15:56:01.019] >    test  Test
[2013.08.14 15:56:01.019] >      uc  Unique position generation
[2013.08.14 15:56:01.019] > xpcpass  External path count pass
[2013.08.14 15:56:01.019] >  xpcsum  External path count sum
[2013.08.14 15:56:16.897] < df
[2013.08.14 15:56:16.907] > rnbqkbnr/pppppppp/8/8/8/8/PPPPPPPP/RNBQKBNR w KQkq - 0 1
[2013.08.14 15:56:31.919] < did
[2013.08.14 15:56:31.930] > Symbolic 2013.08.14
[2013.08.14 15:56:47.674] < pcfull 6
[2013.08.14 15:56:47.677] PCTask::RunLoop begun
[2013.08.14 15:56:47.677] PCTask::RunLoop begun
[2013.08.14 15:56:47.677] PCTask::RunLoop begun
[2013.08.14 15:56:47.677] PCTask::RunLoop begun
[2013.08.14 15:56:56.487] PCTask::RunLoop ended
[2013.08.14 15:56:56.498] PCTask::RunLoop ended
[2013.08.14 15:56:56.505] PCTask::RunLoop ended
[2013.08.14 15:56:56.511] PCTask::RunLoop ended
[2013.08.14 15:56:56.511] > PathFull(6): 119,060,324   Pt: 34.118   Wt: 8.834   F/P: 1.34771e+07/7.41997e-08
[2013.08.14 15:57:02.076] < exit
[2013.08.14 15:57:02.087] IntCoPro::Dispatch exit commanded
[2013.08.14 15:57:02.087] IntCoPro::RunLoop ended
[2013.08.14 15:57:02.088] > 
[2013.08.14 15:57:02.088] > Symbolic done
[2013.08.14 15:57:02.088] IntCoPro destroyed
[2013.08.14 15:57:02.088] Unloading opening book
[2013.08.14 15:57:02.088] Transposition table set deallocation begun
[2013.08.14 15:57:02.088] Deallocating tablebase score transposition table
[2013.08.14 15:57:02.103] Deallocating pawn structure transposition table
[2013.08.14 15:57:02.132] Deallocating material balance transposition table
[2013.08.14 15:57:02.149] Deallocating full position transposition table
[2013.08.14 15:57:02.243] Transposition table set deallocation ended
[2013.08.14 15:57:02.243] CoPro Proc time: 34.903
[2013.08.14 15:57:02.243] CoPro Wall time: 1:22.506
[2013.08.14 15:57:02.243] CoPro destroyed
[2013.08.14 15:57:02.252] Watcher::RunLoop ended
[2013.08.14 15:57:02.253] Watcher destroyed
[2013.08.14 15:57:02.253] Class termination begun
[2013.08.14 15:57:02.253] Class termination ended
[2013.08.14 15:57:02.253] Symbolic 2013.08.14   Log ended at local time 2013.08.14 11:57:02

Nice format... mine is a chaos.

Miguel

[sje]

Oops, the help strings for flip and help are swapped.

I recommend hat all authors consider having their programs make such a logfile. It is useful not just for debugging, but also as evidence to others that the program really is doing original work and is not a clone.

In the logfile, each line of user input is echoed wiht a "< " prefix. All output to the standard output is echoed with a "> " prefix.

For Symbolic, every time a major object instance (like a new thread) is created/destroyed, its constructor/deconstructor outputs an appropriate message to the logfile.

When the program concludes, it goes through the entire process of cleaning up resources in the reverse order in which they were created and initialized. While not strictly necessary, this work takes only a second or so and helps demonstrate the consistency of the program's internal resource management.

[sje]

Also, multi-iline diagram output in the logfile:

Code: Select all

[2013.08.14 16:23:03.064] < dbmono
[2013.08.14 16:23:03.075] > bRbNbBbQbKbBbNbR
[2013.08.14 16:23:03.075] > bPbPbPbPbPbPbPbP
[2013.08.14 16:23:03.075] >   ::  ::  ::  ::
[2013.08.14 16:23:03.075] > ::  ::  ::  ::  
[2013.08.14 16:23:03.075] >   ::  ::  ::  ::
[2013.08.14 16:23:03.075] > ::  ::  ::  ::  
[2013.08.14 16:23:03.075] > wPwPwPwPwPwPwPwP
[2013.08.14 16:23:03.075] > wRwNwBwQwKwBwNwR
[2013.08.14 16:23:03.075] > [w KQkq - 0 1] Available move count: 20

The program can do ANSI escape color output, but this doesn't show up well with some viewing programs or in this discussion board.

[mvk]

Also, multi-iline diagram output in the logfile:

Code: Select all

[2013.08.14 16:23:03.064] < dbmono
[2013.08.14 16:23:03.075] > bRbNbBbQbKbBbNbR
[2013.08.14 16:23:03.075] > bPbPbPbPbPbPbPbP
[2013.08.14 16:23:03.075] >   ::  ::  ::  ::
[2013.08.14 16:23:03.075] > ::  ::  ::  ::  
[2013.08.14 16:23:03.075] >   ::  ::  ::  ::
[2013.08.14 16:23:03.075] > ::  ::  ::  ::  
[2013.08.14 16:23:03.075] > wPwPwPwPwPwPwPwP
[2013.08.14 16:23:03.075] > wRwNwBwQwKwBwNwR
[2013.08.14 16:23:03.075] > [w KQkq - 0 1] Available move count: 20

The program can do ANSI escape color output, but this doesn't show up well with some viewing programs or in this discussion board.

I do that also (ANSI boards), but only when connected to a TTY. Same as with the prompt, as you describe. I have overdone it, trying to avoid ANSI codes that have no effect (e.g. when two pieces of the same color are on the same row with no enemy pieces in between). It must have cost me 1 elo because of the time wasted for not working on the chess algorithm.

I have switched from non-standard PGN date notation (YYYY.MM.DD) to standard ISO 8601 based (YYYY-MM-DD) for better recognition. But I will remove the whole logging stuff, as it suffers from the "system within a system syndrome": it can just as well be handled outside the program and therefore it should.

[sje]

The program can do ANSI escape color output, but this doesn't show up well with some viewing programs or in this discussion board.

Better answer: Any text file with ANSI escape color output (but no other fancy ANSI escape sequences), can be correctly viewed with the more (or less) application by supplying the -r (raw) option on the command call.

[sje]

I have switched from non-standard PGN date notation (YYYY.MM.DD) to standard ISO 8601 based (YYYY-MM-DD) for better recognition.

This is probably an improvement.