Merge pull request #100 from kiudee/debug

Improvements to log output and cutechess-cli forwarding

HISTORY.rst

@@ -2,6 +2,13 @@
 History
 =======
 
+0.7.0 (unreleased)
+------------------
+* Log cutechess-cli output continuously.
+* Add ``"debug_mode"`` parameter which will pass ``-debug`` to cutechess-cli.
+* Add support for pondering using ``engineX_ponder``.
+* Fix passing boolean UCI options correctly.
+
 0.6.0 (2020-09-20)
 ------------------
 * Add support for input warping, allowing the tuner to automatically transform

docs/parameters.myst

@@ -211,7 +211,14 @@ fitting process:
     assumed that engine1_tc is provided
 * - `"engine2_npm"`
   -
-  - See `engine_npm`.
+  - See `engine1_npm`.
+* - `"engine1_ponder"`
+  -
+  - Whether the engine is allowed to ponder the next move during the opponent
+    move.
+* - `"engine2_ponder"`
+  -
+  - See `engine1_ponder`.
 * - `"timemargin"`
   -
   -  Allowed number of milliseconds the engines are allowed to go over the time
@@ -270,6 +277,10 @@ fitting process:
   - Number of games to run in parallel. Be careful when running time control
     games, since the engines can negatively impact each other when running
     in parallel. [default: 1]
+* - `"debug_mode"`
+  - `-vv`
+  - Run cutechess-cli in debug mode. This will produce a lot of debug output and
+    should only be used to diagnose problems. [default: False]
 ```
 
 ## Miscellaneous parameters
@@ -313,7 +324,7 @@ fitting process:
     [default: True]
 * -
   - `-v --verbose`
-  - Turn on debug output.
+  - Turn on debug output. `-vv` turns on the debug flag for cutechess-cli.
 ```
 ```{warning}
 If `--no-resume` is passed it will overwrite any data found at `data-path`.

tune/cli.py

@@ -226,9 +226,7 @@ def run_server(verbose, logfile, command, experiment_file, dbconfig):
     help="Let the optimizer resume, if it finds points it can use.",
     show_default=True,
 )
-@click.option(
-    "--verbose", "-v", is_flag=True, default=False, help="Turn on debug output."
-)
+@click.option("--verbose", "-v", count=True, default=0, help="Turn on debug output.")
 @click.option(
     "--warp-inputs/--no-warp-inputs",
     default=True,
@@ -254,7 +252,7 @@ def local(  # noqa: C901
     random_seed=0,
     result_every=1,
     resume=True,
-    verbose=False,
+    verbose=0,
     warp_inputs=True,
 ):
     """Run a local tune.
@@ -263,7 +261,7 @@ def local(  # noqa: C901
     """
     json_dict = json.load(tuning_config)
     settings, commands, fixed_params, param_ranges = load_tuning_config(json_dict)
-    log_level = logging.DEBUG if verbose else logging.INFO
+    log_level = logging.DEBUG if verbose > 0 else logging.INFO
     log_format = logging.Formatter("%(asctime)s %(levelname)-8s %(message)s")
     root_logger = logging.getLogger("ChessTuner")
     root_logger.setLevel(log_level)
@@ -283,7 +281,8 @@ def local(  # noqa: C901
     random_state = np.random.RandomState(np.random.MT19937(ss.spawn(1)[0]))
     gp_kwargs = dict(
         # TODO: Due to a bug in scikit-learn 0.23.2, we set normalize_y=False:
-        normalize_y=False, warp_inputs=settings.get("warp_inputs", warp_inputs)
+        normalize_y=False,
+        warp_inputs=settings.get("warp_inputs", warp_inputs),
     )
     opt = Optimizer(
         dimensions=list(param_ranges.values()),
@@ -444,11 +443,17 @@ def local(  # noqa: C901
         write_engines_json(engine_json, point_dict)
         root_logger.info("Start experiment")
         now = datetime.now()
-        out_exp, out_exp_err = run_match(**settings)
+        settings["debug_mode"] = settings.get(
+            "debug_mode", False if verbose <= 1 else True
+        )
+        out_exp = []
+        for output_line in run_match(**settings):
+            root_logger.debug(output_line.rstrip())
+            out_exp.append(output_line)
+        out_exp = "".join(out_exp)
         later = datetime.now()
         difference = (later - now).total_seconds()
         root_logger.info(f"Experiment finished ({difference}s elapsed).")
-        root_logger.debug(f"Raw result:\n{out_exp}\n{out_exp_err}")
 
         score, error = parse_experiment_result(out_exp, **settings)
         root_logger.info("Got score: {} +- {}".format(score, error))

tune/db_workers/tuning_client.py

@@ -292,7 +292,9 @@ def run(self):
             with self.sessionmaker() as session:
                 rows = (
                     session.query(SqlJob, SqlResult)
-                    .filter(SqlJob.id == SqlResult.job_id, SqlJob.active == True)  # noqa: E712
+                    .filter(
+                        SqlJob.id == SqlResult.job_id, SqlJob.active == True
+                    )  # noqa: E712
                     .all()
                 )
                 if len(rows) == 0:

tune/db_workers/tuning_server.py

@@ -167,7 +167,9 @@ def parse_priors(self, priors):
                         )
                     else:
                         # The lengthscale(s) are in positive domain
-                        prior = lambda x, dist=dist: dist.logpdf(np.exp(x)) + x  # noqa: E731
+                        prior = (
+                            lambda x, dist=dist: dist.logpdf(np.exp(x)) + x
+                        )  # noqa: E731
                 result.append(prior)
         return result
 
@@ -280,7 +282,8 @@ def change_engine_config(engine_config, params):
     def insert_jobs(self, session, new_x):
         # First set all active jobs to inactive:
         session.query(SqlJob).filter(
-            SqlJob.active == True, SqlJob.tune_id == self.experiment["tune_id"]  # noqa: E712
+            SqlJob.active == True,
+            SqlJob.tune_id == self.experiment["tune_id"],  # noqa: E712
         ).update(
             {"active": False}
         )  # noqa

tune/io.py

@@ -33,6 +33,8 @@ def uci_tuple(uci_string):
 
 
 def _set_option(name, value):
+    if str(value) in ("False", "True"):
+        value = str(value).lower()
     return f"setoption name {name} value {value}"
 
 

tune/local.py

@@ -158,7 +158,12 @@ def parse_experiment_result(
 
 
 def _construct_engine_conf(
-    id, engine_npm=None, engine_tc=None, engine_st=None, timemargin=None
+    id,
+    engine_npm=None,
+    engine_tc=None,
+    engine_st=None,
+    engine_ponder=False,
+    timemargin=None,
 ):
     result = ["-engine", f"conf=engine{id}"]
     if engine_npm is not None:
@@ -168,12 +173,16 @@ def _construct_engine_conf(
         result.append(f"st={str(engine_st)}")
         if timemargin is not None:
             result.append(f"timemargin={str(timemargin)}")
+        if engine_ponder:
+            result.append("ponder")
         return result
     if isinstance(engine_tc, str):
         engine_tc = TimeControl.from_string(engine_tc)
     result.append(f"tc={str(engine_tc)}")
     if timemargin is not None:
         result.append(f"timemargin={str(timemargin)}")
+    if engine_ponder:
+        result.append("ponder")
     return result
 
 
@@ -185,6 +194,8 @@ def run_match(
     engine2_st=None,
     engine1_npm=None,
     engine2_npm=None,
+    engine1_ponder=False,
+    engine2_ponder=False,
     timemargin=None,
     opening_file=None,
     adjudicate_draws=False,
@@ -197,7 +208,7 @@ def run_match(
     adjudicate_tb=False,
     tb_path=None,
     concurrency=1,
-    output_as_string=True,
+    debug_mode=False,
     **kwargs,
 ):
     """Run a cutechess-cli match of two engines with paired random openings.
@@ -223,6 +234,10 @@ def run_match(
         If None, it is assumed that engine1_tc or engine1_st is provided.
     engine2_npm : str or int, default=None
         See engine1_npm.
+    engine1_ponder : bool, default=False
+        If True, allow engine1 to ponder.
+    engine2_ponder : bool, default=False
+        See engine1_ponder.
     timemargin : str or int, default=None
         Allowed number of milliseconds the engines are allowed to go over the time
         limit. If None, the margin is 0.
@@ -267,17 +282,13 @@ def run_match(
         Number of games to run in parallel. Be careful when running time control
         games, since the engines can negatively impact each other when running
         in parallel.
-    output_as_string : bool, default=True
-        If True, only return the cutechess-cli output as string.
-        If False, the complete subprocess.CompletedProcess object will be
-        returned for debugging purposes.
+    debug_mode : bool, default=False
+        If True, pass ``-debug`` to cutechess-cli.
 
-    Returns
+    Yields
     -------
-    out : str or subprocess.CompletedProcess object
-        Results of the cutechess-cli match as string.
-        If output_as_string was set to False, returns the
-        CompletedProcess object for debugging purposes.
+    out : str
+        Results of the cutechess-cli match streamed as str.
     """
     string_array = ["cutechess-cli"]
     string_array.extend(("-concurrency", str(concurrency)))
@@ -287,10 +298,24 @@ def run_match(
     ):
         raise ValueError("A valid time control or nodes configuration is required.")
     string_array.extend(
-        _construct_engine_conf(1, engine1_npm, engine1_tc, engine1_st, timemargin)
+        _construct_engine_conf(
+            id=1,
+            engine_npm=engine1_npm,
+            engine_tc=engine1_tc,
+            engine_st=engine1_st,
+            engine_ponder=engine1_ponder,
+            timemargin=timemargin,
+        )
     )
     string_array.extend(
-        _construct_engine_conf(2, engine2_npm, engine2_tc, engine2_st, timemargin)
+        _construct_engine_conf(
+            id=2,
+            engine_npm=engine2_npm,
+            engine_tc=engine2_tc,
+            engine_st=engine2_st,
+            engine_ponder=engine2_ponder,
+            timemargin=timemargin,
+        )
     )
 
     if opening_file is None:
@@ -342,12 +367,15 @@ def run_match(
     string_array.extend(("-games", "2"))
     string_array.append("-repeat")
     string_array.append("-recover")
+    if debug_mode:
+        string_array.append("-debug")
     string_array.extend(("-pgnout", "out.pgn"))
 
-    out = subprocess.run(string_array, capture_output=True)
-    if output_as_string:
-        return out.stdout.decode("utf-8"), out.stderr.decode("utf-8")
-    return out
+    with subprocess.Popen(
+        string_array, stdout=subprocess.PIPE, stderr=subprocess.STDOUT, text=True
+    ) as popen:
+        for line in iter(popen.stdout.readline, ""):
+            yield line
 
 
 def reduce_ranges(X, y, noise, space):

tune/plots.py

@@ -313,5 +313,9 @@ def plot_objective(
             continue
         plot_dims.append((row, space.dimensions[row]))
     return _format_scatter_plot_axes(
-        ax, space, ylabel="Partial dependence", plot_dims=plot_dims, dim_labels=dimensions
+        ax,
+        space,
+        ylabel="Partial dependence",
+        plot_dims=plot_dims,
+        dim_labels=dimensions,
     )