src/flog.c

   1 /*
   2 Support for logging to file. Logging is made to a file called
   3 matilda_YYMMDD_XXXXXX.log where YYMMDD is the date and XXXXXX is a random
   4 string. When logging a mask of log categories specifies the types of messages to
   5 be written to file. Having a very high degree of detail in very fast matches
   6 actively hurts the performance.
   7
   8 Writing to files is synchronous (with fsync) to avoid loss of data in case of
   9 crashes, but it is impossible to guarantee this in all cases.
  10 */
  11
  12 #include "config.h"
  13
  14 #include <stdio.h>
  15 #include <string.h>
  16 #include <stdlib.h>
  17 #include <time.h> /* localtime */
  18
  19 #include "alloc.h"
  20 #include "amaf_rave.h"
  21 #include "engine.h"
  22 #include "file_io.h"
  23 #include "flog.h"
  24 #include "game_record.h"
  25 #include "mcts.h"
  26 #include "pat3.h"
  27 #include "playout.h"
  28 #include "scoring.h"
  29 #include "stringm.h"
  30 #include "time_ctrl.h"
  31 #include "timem.h"
  32 #include "version.h"
  33
  34 static int log_file = -1;
  35
  36 /*
  37 By default print everything to standard output. Only the main matilda executable
  38 changes this by default.
  39 */
  40 static u16 log_mode = (LOG_MODE_ERROR | LOG_MODE_WARN | LOG_MODE_PROT | LOG_MODE_INFO | LOG_MODE_DEBUG);
  41 static u16 log_dest = LOG_DEST_STDF;
  42
  43 /*
  44 For non-default values for build_info
  45 */
  46 extern u64 max_size_in_mbs;
  47 extern double prior_stone_scale_factor;
  48 extern u16 prior_even;
  49 extern u16 prior_nakade;
  50 extern u16 prior_self_atari;
  51 extern u16 prior_attack;
  52 extern u16 prior_defend;
  53 extern u16 prior_pat3;
  54 extern u16 prior_near_last;
  55 extern u16 prior_line2;
  56 extern u16 prior_line3;
  57 extern u16 prior_empty;
  58 extern u16 prior_corner;
  59 extern double rave_equiv;
  60 extern u16 pl_skip_saving;
  61 extern u16 pl_skip_nakade;
  62 extern u16 pl_skip_pattern;
  63 extern u16 pl_skip_capture;
  64 extern u16 pl_ban_self_atari;
  65 extern d16 komi;
  66
  67 static void open_log_file();
  68
  69 static void flog(
  70     const char * severity,
  71     const char * context,
  72     const char * msg
  73 );
  74
  75 /*
  76 Sets the logging messages that are written to file based on a mask of the
  77 combination of available message types. See flog.h for more information.
  78 */
  79 void flog_config_modes(
  80     u16 new_mode
  81 ) {
  82     if (new_mode == log_mode) {
  83         return;
  84     }
  85
  86     if (new_mode != 0) {
  87         if (log_file != -1) {
  88             log_mode = new_mode;
  89
  90             char * s = alloc();
  91             u32 idx = 0;
  92             idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "log mask changed: ");
  93             if (log_mode == 0) {
  94                 snprintf(s + idx, MAX_PAGE_SIZ - idx, "none");
  95             } else {
  96                 if (log_mode & LOG_MODE_ERROR) {
  97                     idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "crit,");
  98                 }
  99                 if (log_mode & LOG_MODE_WARN) {
 100                     idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "warn,");
 101                 }
 102                 if (log_mode & LOG_MODE_PROT) {
 103                     idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "prot,");
 104                 }
 105                 if (log_mode & LOG_MODE_INFO) {
 106                     idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "info,");
 107                 }
 108                 if (log_mode & LOG_MODE_DEBUG) {
 109                     idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "dbug,");
 110                 }
 111
 112                 s[idx - 1] = 0;
 113             }
 114
 115             flog(NULL, NULL, s);
 116             release(s);
 117             return;
 118         }
 119     } else {
 120         if (log_file != -1) {
 121             flog(NULL, NULL, "logging disabled");
 122             close(log_file);
 123         }
 124
 125         log_file = -1;
 126     }
 127
 128     log_mode = new_mode;
 129 }
 130
 131 /*
 132     Define the destinations for logging.
 133 */
 134 void flog_config_destinations(
 135     u16 new_dest
 136 ) {
 137     log_dest = new_dest;
 138 }
 139
 140 static bool ends_in_new_line(
 141     const char * s
 142 ) {
 143     u32 l = strlen(s);
 144
 145     return (l > 0) && (s[l - 1] == '\n');
 146 }
 147
 148 static bool multiline(
 149     const char * s
 150 ) {
 151     char * t = strchr(s, '\n');
 152
 153     return !(t == NULL || t == s + (strlen(s) - 1));
 154 }
 155
 156 static void flog(
 157     const char * restrict severity,
 158     const char * restrict context,
 159     const char * restrict msg
 160 ) {
 161     if (!log_dest) {
 162         return;
 163     }
 164
 165     /* Prepare payload */
 166     char * s = alloc();
 167     char * ts = alloc();
 168     timestamp(ts);
 169
 170     if (severity == NULL) {
 171         severity = "    ";
 172     }
 173     if (context == NULL) {
 174         context = "    ";
 175     }
 176
 177     if (multiline(msg)) {
 178         snprintf(s, MAX_PAGE_SIZ, "%s | %4s | %4s | [\n%s%s]\n", ts, severity, context, msg, ends_in_new_line(msg) ? "" : "\n");
 179     } else {
 180         snprintf(s, MAX_PAGE_SIZ, "%s | %4s | %4s | %s%s", ts, severity, context, msg, ends_in_new_line(msg) ? "" : "\n");
 181     }
 182
 183     if (log_dest & LOG_DEST_FILE) {
 184         open_log_file();
 185         u32 len = strlen(s);
 186         write(log_file, s, len);
 187         fsync(log_file);
 188     }
 189
 190     if (log_dest & LOG_DEST_STDF) {
 191         fprintf(stderr, "%s", s);
 192     }
 193
 194     release(ts);
 195     release(s);
 196 }
 197
 198 static void open_log_file() {
 199     if (log_file == -1) {
 200         char * log_filename = alloc();
 201         log_file = create_and_open_file(log_filename, MAX_PAGE_SIZ, "matilda", "log");
 202         release(log_filename);
 203
 204         if (log_file == -1) {
 205             fprintf(stderr, "Failed to create log file.\n");
 206             log_dest &= ~LOG_DEST_FILE;
 207             return;
 208         }
 209
 210         char * s = alloc();
 211
 212         u32 idx = 0;
 213         idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "logging enabled with mask: ");
 214
 215         if (log_mode == 0) {
 216             snprintf(s + idx, MAX_PAGE_SIZ - idx, "none");
 217         } else {
 218             if (log_mode & LOG_MODE_ERROR) {
 219                 idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "crit,");
 220             }
 221             if (log_mode & LOG_MODE_WARN) {
 222                 idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "warn,");
 223             }
 224             if (log_mode & LOG_MODE_PROT) {
 225                 idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "prot,");
 226             }
 227             if (log_mode & LOG_MODE_INFO) {
 228                 idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "info,");
 229             }
 230             if (log_mode & LOG_MODE_DEBUG) {
 231                 idx += snprintf(s + idx, MAX_PAGE_SIZ - idx, "dbug,");
 232             }
 233
 234             s[idx - 1] = 0;
 235         }
 236
 237         flog(NULL, NULL, s);
 238         release(s);
 239     }
 240 }
 241
 242
 243 /*
 244 Obtain a textual description of the capabilities and configuration options of
 245 matilda. This mostly concerns compile time constants.
 246 RETURNS string with build information
 247 */
 248 void build_info(
 249     char * dst
 250 ) {
 251     u32 idx = 0;
 252     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Matilda build information\n");
 253
 254     if (MATILDA_RELEASE_MODE) {
 255         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Compiled for: release\n");
 256     } else {
 257         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Compiled for: debugging\n");
 258     }
 259
 260     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Version: %s\n", MATILDA_VERSION);
 261     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Data folder: %s\n", data_folder());
 262
 263     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Board size: %ux%u\n", BOARD_SIZ, BOARD_SIZ);
 264
 265     char * kstr = alloc();
 266     komi_to_string(kstr, komi);
 267     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Komidashi: %s stones\n", kstr);
 268     release(kstr);
 269
 270     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Resign/pass bellow win rate: %.2f\n", UCT_RESIGN_WINRATE);
 271     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Minimum simulations: %u\n", UCT_RESIGN_PLAYOUTS);
 272
 273     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Can stop MCTS early: %s\n", YN(UCT_CAN_STOP_EARLY));
 274
 275     if (UCT_CAN_STOP_EARLY) {
 276         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  At win rate: %.2f\n", UCT_EARLY_WINRATE);
 277     }
 278
 279     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Winrate for passing always: %.2f\n", JUST_PASS_WINRATE);
 280
 281     char * s = alloc();
 282     format_mem_size(s, max_size_in_mbs * 1048576);
 283     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Transpositions table memory: %s\n", s);
 284     release(s);
 285
 286     if (pl_skip_saving) {
 287         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Chance of skipping save: %u/128\n", pl_skip_saving);
 288     }
 289     if (pl_skip_capture) {
 290         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Chance of skipping capture: %u/128\n", pl_skip_capture);
 291     }
 292     if (pl_skip_pattern) {
 293         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Chance of skipping pattern: %u/128\n", pl_skip_pattern);
 294     }
 295     if (pl_skip_nakade) {
 296         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Chance of skipping nakade: %u/128\n", pl_skip_nakade);
 297     }
 298     if (pl_ban_self_atari) {
 299         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Chance of prohibiting self-atari: %u/128\n", pl_ban_self_atari);
 300     }
 301
 302     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Use pattern weights: %s\n", YN(USE_PATTERN_WEIGHTS));
 303     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Use AMAF/RAVE: %s\n", YN(USE_AMAF_RAVE));
 304
 305     if (USE_AMAF_RAVE) {
 306         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  MSE equiv: %.2f\n", rave_equiv);
 307         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Criticality threshold: %u\n", CRITICALITY_THRESHOLD);
 308     }
 309
 310     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Stone value scale factor: %.1f\n", prior_stone_scale_factor);
 311     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Even: %u (x2)\n", prior_even);
 312     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Nakade: %u\n", prior_nakade);
 313     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Self-atari: -%u\n", prior_self_atari);
 314     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Attack 1/2 lib group: %u\n", prior_attack);
 315     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Defend 1/2 lib group: %u\n", prior_defend);
 316     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  MoGo patterns: %u\n", prior_pat3);
 317     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Near last play: %u\n", prior_near_last);
 318     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Empty L2/3/other: -%u/%u/%u\n", prior_line2, prior_line3, prior_empty);
 319     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "  Corners: -%u\n", prior_corner);
 320
 321     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Max UCT depth: %u\n", MAX_UCT_DEPTH);
 322     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "UCT expansion delay: %u\n", UCT_EXPANSION_DELAY);
 323     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Playout depth over number of empty points: %u\n", MAX_PLAYOUT_DEPTH_OVER_EMPTY);
 324     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Mercy threshold: %u stones\n", MERCY_THRESHOLD);
 325
 326     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Constant latency compensation: %u ms\n", LATENCY_COMPENSATION);
 327     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Time allotment factor: %.2f\n", TIME_ALLOT_FACTOR);
 328
 329     u32 num_threads;
 330     #pragma omp parallel
 331     #pragma omp master
 332     {
 333         num_threads = omp_get_num_threads();
 334     }
 335
 336     if (DEFAULT_NUM_THREADS == 0) {
 337         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Default number of threads: automatic (%u)\n", num_threads);
 338     } else {
 339         idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Default number of threads: %u (%u)\n", DEFAULT_NUM_THREADS, num_threads);
 340     }
 341     idx += snprintf(dst + idx, MAX_PAGE_SIZ - idx, "Maximum number of threads: %u\n", MAXIMUM_NUM_THREADS);
 342     snprintf(dst + idx, MAX_PAGE_SIZ - idx, "\n");
 343 }
 344
 345 /*
 346 Log a message with verbosity level critical.
 347 */
 348 void flog_crit(
 349     const char * restrict ctx,
 350     const char * restrict msg
 351 ) {
 352     if ((log_mode & LOG_MODE_ERROR) != 0) {
 353         flog("crit", ctx, msg);
 354         flog(NULL, NULL, "execution aborted due to program panic");
 355     } else {
 356         fprintf(stderr, "execution aborted due to program panic\n");
 357     }
 358
 359     exit(EXIT_FAILURE);
 360 }
 361
 362
 363 /*
 364 Log a message with verbosity level warning.
 365 */
 366 void flog_warn(
 367     const char * restrict ctx,
 368     const char * restrict msg
 369 ) {
 370     if ((log_mode & LOG_MODE_WARN) != 0) {
 371         flog("warn", ctx, msg);
 372     }
 373 }
 374
 375
 376 /*
 377 Log a message with verbosity level communication protocol.
 378 */
 379 void flog_prot(
 380     const char * restrict ctx,
 381     const char * restrict msg
 382 ) {
 383     if ((log_mode & LOG_MODE_PROT) != 0) {
 384         flog("prot", ctx, msg);
 385     }
 386 }
 387
 388
 389 /*
 390     Log a message with verbosity level informational.
 391 */
 392 void flog_info(
 393     const char * restrict ctx,
 394     const char * restrict msg
 395 ) {
 396     if ((log_mode & LOG_MODE_INFO) != 0) {
 397         flog("info", ctx, msg);
 398     }
 399 }
 400
 401
 402 /*
 403     Log a message with verbosity level debug.
 404 */
 405 void flog_debug(
 406     const char * restrict ctx,
 407     const char * restrict msg
 408 ) {
 409     if ((log_mode & LOG_MODE_DEBUG) != 0) {
 410         flog("dbug", ctx, msg);
 411     }
 412 }