Repository: project-improv/improv

Issue:
better error messages and failed starts
When we fail to 

1. connect to store or
2. fail to read ports from the log file

we currently encounter uninformative errors downstream. I propose that we should emit a more informative error message and abort starting _improv_ in these cases.

Discussion:

Patch:
diff --git a/.github/workflows/CI.yaml b/.github/workflows/CI.yaml
index 3ba0986..0ab20f1 100644
--- a/.github/workflows/CI.yaml
+++ b/.github/workflows/CI.yaml
@@ -51,7 +51,7 @@ jobs:
     
     steps:
       - uses: actions/checkout@v3
-      - name: Test with Python 3.10
+      - name: Set up Python 3.10
         uses: actions/setup-python@v4
         with:
           python-version: '3.10'
diff --git a/improv/cli.py b/improv/cli.py
index e18e2da..899c5ee 100644
--- a/improv/cli.py
+++ b/improv/cli.py
@@ -62,7 +62,6 @@ def is_valid_ip_addr(addr):
         port = addr
 
     port = str(is_valid_port(port))
-
     return ip + ":" + port
 
 
@@ -294,7 +293,7 @@ def run_cleanup(args, headless=False):
             print("No running processes found.")
 
 
-def run(args):
+def run(args, timeout=10):
     apath_opts = []
     for p in args.actor_path:
         if p:
@@ -316,39 +315,56 @@ def run(args):
     server_opts.extend(apath_opts)
     server_opts.append(args.configfile)
 
-    # save current datetime so we can see when server has started up
-    curr_dt = datetime.datetime.now().replace(microsecond=0)
-
     with open(args.logfile, mode="a+") as logfile:
         server = subprocess.Popen(server_opts, stdout=logfile, stderr=logfile)
 
     # wait for server to start up
-    timeout = 10
-    increment = 0.05
-    time_now = 0
-    while time_now < timeout:
-        server_start_time = _server_start_logged(args.logfile)
-        if server_start_time and server_start_time >= curr_dt:
-            control_port, output_port, logging_port = _get_ports(args.logfile)
-            break
-        else:
-            time.sleep(increment)
-            time_now += increment
-
-    args.logging_port = logging_port
-    args.control_port = control_port
-    args.server_port = output_port
-    run_client(args)
+    ports = get_server_ports(args, timeout)
+    if ports:
+        control_port, output_port, logging_port = ports
+        args.logging_port = logging_port
+        args.control_port = control_port
+        args.server_port = output_port
+        run_client(args)
 
     try:
         server.wait(timeout=2)
     except subprocess.TimeoutExpired:
         print("Cleaning up the hard way. May have exited dirty.")
         server.terminate()
-        server.wait(10)
+        server.wait(timeout)
         run_cleanup(args, headless=True)
 
 
+def get_server_ports(args, timeout):
+    # save current datetime so we can see when server has started up
+    curr_dt = datetime.datetime.now().replace(microsecond=0)
+
+    increment = 0.05
+    time_now = 0
+    ports = None
+    while time_now < timeout:
+        server_start_time = _server_start_logged(args.logfile)
+        if server_start_time and server_start_time >= curr_dt:
+            ports = _get_ports(args.logfile)
+            if ports:
+                break
+
+        time.sleep(increment)
+        time_now += increment
+
+    if not server_start_time:
+        print(
+            f"Unable to read server start time from {args.logfile}.\n"
+            "This may be because the server could not be started or"
+            "did not log its activity."
+        )
+    elif not ports:
+        print(f"Unable to read ports from {args.logfile}.")
+
+    return ports
+
+
 def _server_start_logged(logfile):
     # read logfile to make sure new session and ports are logged
     with open(logfile, mode="r") as logfile:


Test patch:
diff --git a/test/test_cli.py b/test/test_cli.py
index e4c921f..7e18363 100644
--- a/test/test_cli.py
+++ b/test/test_cli.py
@@ -1,7 +1,7 @@
 import pytest
 import os
-
-# import sys
+import datetime
+from collections import namedtuple
 import subprocess
 import asyncio
 import signal
@@ -61,6 +61,20 @@ async def server(setdir, ports):
         pass
 
 
+@pytest.fixture()
+async def cli_args(setdir, ports):
+    logfile = "tmp.log"
+    control_port, output_port, logging_port = ports
+    config_file = "configs/minimal.yaml"
+    Args = namedtuple(
+        "cli_args",
+        "control_port output_port logging_port logfile configfile actor_path",
+    )
+
+    args = Args(control_port, output_port, logging_port, logfile, config_file, [])
+    return args
+
+
 def test_configfile_required(setdir):
     with pytest.raises(SystemExit):
         cli.parse_cli_args(["run"])
@@ -242,3 +256,29 @@ async def test_get_ports_from_logfile(setdir):
     assert control_port == test_control_port
     assert output_port == test_output_port
     assert logging_port == test_logging_port
+
+
+async def test_no_server_start_in_logfile_raises_error(setdir, cli_args, capsys):
+    with open(cli_args.logfile, mode="w") as f:
+        f.write("this is some placeholder text")
+
+    cli.get_server_ports(cli_args, timeout=1)
+
+    captured = capsys.readouterr()
+    assert "Unable to read server start time" in captured.out
+
+    os.remove(cli_args.logfile)
+    cli.run_cleanup("", headless=True)
+
+
+async def test_no_ports_in_logfile_raises_error(setdir, cli_args, capsys):
+    curr_dt = datetime.datetime.now().replace(microsecond=0)
+    with open(cli_args.logfile, mode="w") as f:
+        f.write(f"{curr_dt} Server running on (control, output, log) ports XXX\n")
+
+    cli.get_server_ports(cli_args, timeout=1)
+    captured = capsys.readouterr()
+    assert f"Unable to read ports from {cli_args.logfile}." in captured.out
+
+    os.remove(cli_args.logfile)
+    cli.run_cleanup("", headless=True)