Improved logging, especially for solve

7 files changed, 73 insertions, 59 deletions

diff --git a/src/solvers/coord/gendata.h b/src/solvers/coord/gendata.h
index 6abb5eb..ae7b39e 100644
--- a/src/solvers/coord/gendata.h
+++ b/src/solvers/coord/gendata.h
@@ -22,7 +22,7 @@ gendata_coord_dispatch(const char *coordstr, void *buf)
         parse_coord_and_axis(strlen(coordstr), coordstr, &coord, NULL);
 
         if (coord == NULL) {
-                LOG("Could not parse coordinate '%s'\n", coordstr);
+                LOG("Error: could not parse coordinate '%s'\n", coordstr);
                 return NISSY_ERROR_INVALID_SOLVER;
         }
 
@@ -82,7 +82,7 @@ gendata_coord_return_size:
         return ninfo * INFOSIZE + coord_dsize + tablesize;
 
 gendata_coord_error:
-        LOG("An unexpected error occurred when generating the data.\n");
+        LOG("Unexpected error generating coordinate data\n");
         return 0;
 }
 
@@ -136,8 +136,9 @@ genptable_coord(
                 }
                 tot += t;
                 info.distribution[d] = t;
-                LOG("Depth %" PRIu64 ": found %" PRIu64 " (%" PRIu64 " of %"
-                    PRIu64 ")\n", d, t, tot, coord->max);
+                LOG("[%s gendata] Depth %" PRIu64 ": found %" PRIu64 " (%"
+                    PRIu64 " of %" PRIu64 ")\n",
+                    coord->name, d, t, tot, coord->max);
         }
         info.maxvalue = d-1;
 
diff --git a/src/solvers/coord/solve.h b/src/solvers/coord/solve.h
index b289e3f..072aa27 100644
--- a/src/solvers/coord/solve.h
+++ b/src/solvers/coord/solve.h
@@ -121,7 +121,8 @@ solve_coord_dfs(dfsarg_solve_coord_t arg[static 1])
                 if (!coord_solution_admissible(arg))
                         return 0;
                 return appendsolution(arg->solution_moves,
-                    arg->solution_settings, arg->solution_list, true);
+                    arg->solution_settings, arg->solution_list, true,
+                    arg->coord->name);
         }
 
         if (solve_coord_dfs_stop(arg))
@@ -220,12 +221,13 @@ solve_coord_dispatch(
             strlen(coord_and_axis), coord_and_axis, &coord, &axis);
 
         if (coord == NULL) {
-                LOG("Could not parse coordinate from '%s'\n", coord_and_axis);
+                LOG("Error: could not parse coordinate from '%s'\n",
+                    coord_and_axis);
                 return NISSY_ERROR_INVALID_SOLVER;
         }
 
         if (axis == UINT8_ERROR) {
-                LOG("Could not parse axis from '%s'\n", coord_and_axis);
+                LOG("Error: could not parse axis from '%s'\n", coord_and_axis);
                 return NISSY_ERROR_INVALID_SOLVER;
         }
 
@@ -316,8 +318,8 @@ solve_coord(
         };
 
         if (coord->coord(c, coord_data) == 0) {
-                if (minmoves == 0 && !appendsolution(
-                    &solution_moves, &solution_settings, &solution_list, true))
+                if (minmoves == 0 && !appendsolution(&solution_moves,
+                    &solution_settings, &solution_list, true, coord->name))
                                 goto solve_coord_error_buffer;
                 goto solve_coord_done;
         }
@@ -327,18 +329,17 @@ solve_coord(
             !solutions_done(&solution_list, &solution_settings, d);
             d++
         ) {
-                if (d >= 10)
-                        LOG("Found %" PRIu64 " solutions, searching at depth %"
-                            PRId8 "\n", solution_list.nsols, d);
+                if (d >= 12)
+                        LOG("[%s solve] Found %" PRIu64 " solutions, "
+                            "searching at depth %" PRId8 "\n",
+                            coord->name, solution_list.nsols, d);
 
                 arg.target_depth = d;
                 solution_moves_reset(arg.solution_moves);
                 ndepth = solve_coord_dfs(&arg);
 
-                if (ndepth < 0) {
-                        LOG("Error %" PRId64 "\n", ndepth);
+                if (ndepth < 0)
                         return ndepth;
-                }
 
                 solution_list.nsols += (uint64_t)ndepth;
         }
@@ -347,14 +348,15 @@ solve_coord_done:
         return (int64_t)solution_list.nsols;
 
 solve_coord_error_data:
-        LOG("solve_coord: error reading table\n");
+        LOG("[%s solve] Error reading table\n", coord->name);
         return NISSY_ERROR_DATA;
 
 solve_coord_error_buffer:
-        LOG("Could not append solution to buffer: size too small\n");
+        LOG("[%s solve] Error appending solution to buffer: size too small\n",
+            coord->name);
         return NISSY_ERROR_BUFFER_SIZE;
 
 solve_coord_error_unsolvable:
-        LOG("Cube not ready for solving %s\n", coord->name);
+        LOG("[%s solve] Error: cube not ready\n", coord->name);
         return NISSY_ERROR_UNSOLVABLE_CUBE;
 }
diff --git a/src/solvers/coord/utils.h b/src/solvers/coord/utils.h
index 5407de3..ef3f817 100644
--- a/src/solvers/coord/utils.h
+++ b/src/solvers/coord/utils.h
@@ -59,7 +59,7 @@ dataid_coord(const char *ca, char dataid[static NISSY_SIZE_DATAID])
         parse_coord_and_axis(strlen(ca), ca, &c, NULL);
 
         if (c == NULL) {
-                LOG("dataid_coord: cannot parse coordinate from '%s'\n", ca);
+                LOG("Error: cannot parse coordinate from '%s'\n", ca);
                 return NISSY_ERROR_INVALID_SOLVER;
         }
 
diff --git a/src/solvers/h48/gendata_cocsep.h b/src/solvers/h48/gendata_cocsep.h
index cda1608..f07b71a 100644
--- a/src/solvers/h48/gendata_cocsep.h
+++ b/src/solvers/h48/gendata_cocsep.h
@@ -67,7 +67,7 @@ gendata_cocsep(
             "cocsep: computed %" PRIu16 " symmetry classes, "
             "expected %zu\n", n, COCSEP_CLASSES);
 
-        LOG("cocsep data computed\n");
+        LOG("[H48 gendata] cocsep data computed\n");
 
         /* The following output is just noise
 
diff --git a/src/solvers/h48/gendata_h48.h b/src/solvers/h48/gendata_h48.h
index 4478e9e..18157dc 100644
--- a/src/solvers/h48/gendata_h48.h
+++ b/src/solvers/h48/gendata_h48.h
@@ -87,7 +87,7 @@ gendata_h48(gendata_h48_arg_t arg[static 1])
                 return size; /* Dry-run */
 
         if (arg->buf_size < size) {
-                LOG("Error computing H48 data: buffer is too small "
+                LOG("[H48 gendata] Error data: buffer is too small "
                     "(needed %" PRId64 " bytes but received %" PRId64 ")\n",
                     size, arg->buf_size);
                 return NISSY_ERROR_BUFFER_SIZE;
@@ -106,22 +106,24 @@ gendata_h48(gendata_h48_arg_t arg[static 1])
         } else if (arg->k == 2) {
                 gendata_h48k2(arg);
         } else {
-                LOG("Cannot generate data for h = %" PRIu8 " and k = %" PRIu8
-                    " (not implemented yet)\n", arg->h, arg->k);
+                LOG("[H48 gendata] Error: cannot generate data for h = %" PRIu8
+                    " and k = %" PRIu8 " (not implemented yet)\n",
+                    arg->h, arg->k);
                 return NISSY_ERROR_INVALID_SOLVER;
         }
 
         r = readtableinfo(arg->buf_size, arg->buf, &cocsepinfo);
         if (r != NISSY_OK) {
-                LOG("gendata_h48: could not read info for cocsep table\n");
+                LOG("[H48 gendata] Error: could not read info "
+                    "for cocsep table\n");
                 return NISSY_ERROR_UNKNOWN;
         }
 
         cocsepinfo.next = cocsepsize;
         r = writetableinfo(&cocsepinfo, arg->buf_size, arg->buf);
         if (r != NISSY_OK) {
-                LOG("gendata_h48: could not write info for cocsep table"
-                    " with updated 'next' value\n");
+                LOG("[H48 gendata] Error: could not write info for "
+                    "cocsep table with updated 'next' value\n");
                 return NISSY_ERROR_UNKNOWN;
         }
 
@@ -149,21 +151,23 @@ gendata_h48(gendata_h48_arg_t arg[static 1])
 
         r = readtableinfo_n(arg->buf_size, arg->buf, 2, &h48info);
         if (r != NISSY_OK) {
-                LOG("gendata_h48: could not read info for h48 table\n");
+                LOG("[H48 gendata] Error: could not read info "
+                    "for h48 table\n");
                 return NISSY_ERROR_UNKNOWN;
         }
         h48info.next = h48size;
         r = writetableinfo(&h48info,
              arg->buf_size - cocsepsize, (char *)arg->buf + cocsepsize);
         if (r != NISSY_OK) {
-                LOG("gendata_h48: could not write info for h48 table\n");
+                LOG("[H48 gendata] Error: could not write info "
+                    "for h48 table\n");
                 return NISSY_ERROR_UNKNOWN;
         }
 
         if (arg->k == 2) {
                 r = readtableinfo_n(arg->buf_size, arg->buf, 3, &fallbackinfo);
                 if (r != NISSY_OK) {
-                        LOG("gendata_h48: could not read info for h48 "
+                        LOG("[H48 gendata] Error: could not read info for h48 "
                             "fallback table\n");
                         return NISSY_ERROR_UNKNOWN;
                 }
@@ -173,8 +177,8 @@ gendata_h48(gendata_h48_arg_t arg[static 1])
                 r = writetableinfo(&fallbackinfo,
                     arg->buf_size - of, (char *)arg->buf + of);
                 if (r != NISSY_OK) {
-                        LOG("gendata_h48: could not write info for h48 "
-                            "fallback table\n");
+                        LOG("[H48 gendata] Error: could not write info for "
+                            "h48 fallback table\n");
                         return NISSY_ERROR_UNKNOWN;
                 }
         }
@@ -233,7 +237,7 @@ gendata_h48h0k4(gendata_h48_arg_t arg[static 1])
                         bfsarg[t].table_mutex[tt] = &table_mutex[tt];
         }
         for (done = 1, d = 1; done < h48max && d <= arg->maxdepth; d++) {
-                LOG("h48: generating depth %" PRId64 "\n", d);
+                LOG("[H48 gendata] Generating depth %" PRId64 "\n", d);
 
                 for (t = 0; t < THREADS; t++) {
                         bfsarg[t].depth = d;
@@ -252,7 +256,7 @@ gendata_h48h0k4(gendata_h48_arg_t arg[static 1])
                 done += cc;
                 arg->info.distribution[d] = cc;
 
-                LOG("found %" PRId64 "\n", cc);
+                LOG("[H48 gendata] Found %" PRId64 "\n", cc);
         }
 
         arg->info.maxvalue = d - 1;
@@ -382,7 +386,7 @@ gendata_h48k2(gendata_h48_arg_t arg[static 1])
         table = (uint8_t *)arg->h48buf + INFOSIZE;
         memset(table, 0xFF, H48_TABLESIZE(arg->h, arg->k));
 
-        LOG("Computing depth <=%" PRIu8 "\n", shortdepth)
+        LOG("[H48 gendata] Computing depth <=%" PRIu8 "\n", shortdepth)
         h48map_create(&shortcubes, capacity, randomizer);
         shortarg = (gendata_h48short_arg_t) {
                 .maxdepth = shortdepth,
@@ -392,7 +396,7 @@ gendata_h48k2(gendata_h48_arg_t arg[static 1])
                 .map = &shortcubes
         };
         gendata_h48short(&shortarg);
-        LOG("Computed %" PRIu64 " positions\n", shortarg.map->n);
+        LOG("[H48 gendata] Computed %" PRIu64 " positions\n", shortarg.map->n);
 
         if (arg->base >= 20)
                 arg->base = base[arg->h];
@@ -459,7 +463,8 @@ gendata_h48k2_runthread(void *arg)
                 pthread_mutex_unlock(dfsarg->shortcubes_mutex);
 
                 if (count % UINT64_C(1000000) == 0)
-                        LOG("Processing %" PRIu64 "th short cube\n", count);
+                        LOG("[H48 gendata] Processing %" PRIu64
+                            "th short cube\n", count);
 
                 if (kv.val < dfsarg->shortdepth) {
                         coord = kv.key >> (int64_t)(11 - dfsarg->h);
@@ -780,15 +785,16 @@ gendata_h48_derive(uint8_t h, const void *fulltable, void *buf)
 
         bufsize = COCSEP_FULLSIZE + INFOSIZE;
         if (readtableinfo(bufsize, buf, &cocsepinfo) != NISSY_OK) {
-                LOG("gendata_h48: could not read info for cocsep table\n");
+                LOG("[H48 derive gendata] Error: could not read info for "
+                    "cocsep table\n");
                 goto gendata_h48_derive_error;
         }
 
         cocsepinfo.next = cocsepsize;
         bufsize = COCSEP_FULLSIZE + INFOSIZE;
         if (writetableinfo(&cocsepinfo, bufsize, buf) != NISSY_OK) {
-                LOG("gendata_h48_derive: could not write info for cocsep table"
-                    " with updated 'next' value\n");
+                LOG("[H48 derive gendata] Error: could not write info for "
+                    "cocsep table with updated 'next' value\n");
                 goto gendata_h48_derive_error;
         }
 
@@ -801,7 +807,8 @@ gendata_h48_derive(uint8_t h, const void *fulltable, void *buf)
         h48max = H48_COORDMAX(fulltableinfo.h48h);
         for (i = 0; i < h48max; i++) {
                 if (i % INT64_C(1000000000) == 0 && i > 0)
-                        LOG("Processing %" PRId64 "th coordinate\n", i);
+                        LOG("[H48 derive gendata] Processing %" PRId64
+                            "th coordinate\n", i);
                 j = i >> (int64_t)(fulltableinfo.h48h - h);
                 val_full = get_h48_pval(h48full, i, arg.k);
                 val_derive = get_h48_pval(h48derive, j, arg.k);
@@ -813,7 +820,8 @@ gendata_h48_derive(uint8_t h, const void *fulltable, void *buf)
 
         bufsize = arg.buf_size - COCSEP_FULLSIZE - INFOSIZE;
         if (writetableinfo(&arg.info, bufsize, arg.h48buf) != NISSY_OK) {
-                LOG("gendata_h48_derive: could not write info for table\n");
+                LOG("H48 derive gendata] Error: could not write info "
+                    "for table\n");
                 goto gendata_h48_derive_error;
         }
 
diff --git a/src/solvers/h48/solve.h b/src/solvers/h48/solve.h
index 78b4c97..0fd419d 100644
--- a/src/solvers/h48/solve.h
+++ b/src/solvers/h48/solve.h
@@ -162,7 +162,7 @@ solve_h48_dfs(dfsarg_solve_h48_t arg[static 1])
                         return 0;
                 pthread_mutex_lock(arg->solutions_mutex);
                 ret = appendsolution(arg->solution_moves,
-                    arg->solution_settings, arg->solution_list, true);
+                    arg->solution_settings, arg->solution_list, true, "H48");
                 pthread_mutex_unlock(arg->solutions_mutex);
                 return ret;
         }
@@ -295,7 +295,7 @@ solve_h48_maketasks(
                     maketasks_arg->moves, maketasks_arg->nmoves);
 
                 appret = appendsolution(&moves, solve_arg->solution_settings,
-                    solve_arg->solution_list, true);
+                    solve_arg->solution_list, true, "H48");
                 return appret < 0 ? appret : NISSY_OK;
         }
 
@@ -458,16 +458,17 @@ solve_h48(
                 arg[i].tasks = tasks;
         }
 
-        LOG("Prepared %d tasks\n", ntasks);
+        LOG("[H48 solve] Prepared %d tasks\n", ntasks);
 
         for (
             d = MAX(minmoves, STARTING_MOVES + 1);
             !solutions_done(&sollist, &settings, d);
             d++
         ) {
-                if (d >= 10)
-                        LOG("Found %" PRId64 " solutions, searching at depth %"
-                            PRId8 "\n", sollist.nsols, d);
+                if (d >= 15)
+                        LOG("[H48 solve] Found %" PRId64 " solutions, "
+                            "searching at depth %" PRId8 "\n",
+                            sollist.nsols, d);
                 for (i = 0; i < threads; i++) {
                         arg[i].target_depth = d;
                         pthread_create(
@@ -491,16 +492,16 @@ solve_h48_done:
         lookups_per_node = table_lookups / (long double)nodes_visited;
         fallback_rate = nodes_visited == 0 ? 0.0 :
             (table_fallbacks * 100) / (long double)table_lookups;
-        LOG("Nodes visited: %" PRId64 "\n", nodes_visited);
-        LOG("Lookups: %" PRId64 " (%.3Lf per node)\n",
+        LOG("[H48 solve] Nodes visited: %" PRId64 "\n", nodes_visited);
+        LOG("[H48 solve] Lookups: %" PRId64 " (%.3Lf per node)\n",
             table_lookups, lookups_per_node);
-        LOG("Table fallbacks: %" PRId64 " (%.3Lf%%)\n",
+        LOG("[H48 solve] Table fallbacks: %" PRId64 " (%.3Lf%%)\n",
             table_fallbacks, fallback_rate);
 
         return sollist.nsols;
 
 solve_h48_error_data:
-        LOG("solve_h48: error reading table\n");
+        LOG("[H48 solve] Error reading data table\n");
         return NISSY_ERROR_DATA;
 
 solve_h48_error_solutions_buffer:
diff --git a/src/solvers/solutions.h b/src/solvers/solutions.h
index 95c1d1a..c9a1313 100644
--- a/src/solvers/solutions.h
+++ b/src/solvers/solutions.h
@@ -7,7 +7,8 @@ STATIC bool solution_moves_equal(
 STATIC bool solution_moves_is_duplicate(size_t n, const solution_moves_t[n+1]);
 STATIC bool appendchar(solution_list_t [static 1], char);
 STATIC int64_t appendsolution(const solution_moves_t [static 1],
-    const solution_settings_t [static 1], solution_list_t [static 1], bool);
+    const solution_settings_t [static 1], solution_list_t [static 1], bool,
+    const char *);
 STATIC bool solutions_done(const solution_list_t [static 1],
     const solution_settings_t [static 1], int8_t depth);
 
@@ -34,7 +35,7 @@ STATIC bool
 solution_list_init(solution_list_t sols[static 1], size_t n, char buf[n])
 {
         if (n == 0) {
-                LOG("Cannot use solution buffer with size 0\n");
+                LOG("Error: cannot use solution buffer with size 0\n");
                 return false;
         }
 
@@ -98,7 +99,8 @@ appendsolution(
         const solution_moves_t moves[static 1],
         const solution_settings_t settings[static 1],
         solution_list_t list[static 1],
-        bool log
+        bool log,
+        const char *solver_name
 )
 {
         int64_t r, strl;
@@ -184,8 +186,8 @@ appendsolution(
 
                 if (log) {
                         list->buf[list->used-1] = '\0';
-                        LOG("Found solution #%" PRIu64 ": %s\n",
-                            list->nsols, last_start);
+                        LOG("[%s solve] Found solution #%" PRIu64 ": %s\n",
+                            solver_name, list->nsols, last_start);
                         list->buf[list->used-1] = '\n';
                 }
         }
@@ -194,14 +196,14 @@ appendsolution(
         return r;
 
 appendsolution_error_buffer:
-        LOG("Could not append solution to buffer: size too small\n");
+        LOG("[%s solve] Error: buffer too small\n", solver_name);
         list->buf[0] = '\0';
         return NISSY_ERROR_BUFFER_SIZE;
 
 appendsolution_error_solution_length:
-        LOG("Error: solution is too long (%" PRIu8 ").\n"
+        LOG("[%s solve] Error: solution is too long (%" PRIu8 ").\n"
             "This is a bug, please report it.\n",
-            moves->nmoves + moves->npremoves);
+            solver_name, moves->nmoves + moves->npremoves);
         list->buf[0] = '\0';
         return NISSY_ERROR_UNKNOWN;
 }