pbench-results-push: logging fixes and better reporting (#3348)

* Do not use the file logger at all in python commands.

The logger only uses the default Streamhandler now which outputs to stderr.

* - copy_result_tb: return the response to the PUT request

copy_result_tb returns the response from the server. The callers
are responsible for interpreting it. However, it can still raise an
exception (e.g. on connection error).

- push.py: construct a reasonable message out of the response and check
if the HTTP status is 201: we exit with 0 if so.

Otherwise, if the status is OK (i.e. < 400), then we exit with 0 but
print a message with a reasonably self-explanatory status on
stderr. We expect that we will only ever get two OK responses: a 201
which indicates a successful PUT with a newly created dataset and 200
which indicates a duplicate dataset.

In all non-OK cases, we output the message on stderr and exit with 1.

- move.py: check the response - if not OK (>= 400) raise exception.


* Fix the monkeypatching in test_copy_result_tb.py

Monkeypatching pathlib components (.exists() and .open()) causes
pytest to blow up. Limit the scope by using `monkeypatch.context()'
so that it is only applied to the objects under test (and not e.g.
to what is used in checking assertions).

* Use symbolic constant instead of explicit 201

* Parametrize the "normal" test

This is just the first step - see issue #3374 for some more work along these lines.

Author: ndokos

agent/config/pbench-agent-default.cfg

@@ -9,12 +9,6 @@ pbench_log = %(pbench_run)s/pbench.log
 # RPM requirement mode: strict vs relaxed
 rpm_requirement_mode = strict
 
-[logging]
-logger_type = file
-# # "log_dir" is only considered when "logger_type" is set to "file"; And by
-# # default the log file directory is the "pbench_run" directory.
-# log_dir =
-
 [results]
 user = pbench
 host_info_uri = pbench-results-host-info.versioned/pbench-results-host-info.URL002

lib/pbench/agent/__init__.py

@@ -61,13 +61,6 @@ def __init__(self, cfg_name):
             )
             self.pbench_lib_dir = self.pbench_install_dir / "lib"
 
-        if self.logger_type == "file" and self.log_dir is None:
-            # The configuration file has a logging section configured to use
-            # "file" logging, but no log directory is set.  We'll set the log
-            # directory to be the directory of the legacy ${pbench_log} value
-            # determined above.
-            self.log_dir = str(self.pbench_log.parent)
-
         try:
             self.ssh_opts = self.get("results", "ssh_opts", fallback=DEFAULT_SSH_OPTS)
         except (NoOptionError, NoSectionError):

lib/pbench/agent/base.py

@@ -54,11 +54,6 @@ def __init__(self, context):
             )
             click.get_current_context().exit(1)
 
-        # log file - N.B. not a directory
-        self.pbench_log = self.config.pbench_log
-        if self.pbench_log is None:
-            self.pbench_log = self.pbench_run / "pbench.log"
-
         self.pbench_install_dir = self.config.pbench_install_dir
         if self.pbench_install_dir is None:
             self.pbench_install_dir = "/opt/pbench-agent"
@@ -71,7 +66,7 @@ def __init__(self, context):
         self.pbench_bspp_dir = self.pbench_install_dir / "bench-scripts" / "postprocess"
         self.pbench_lib_dir = self.pbench_install_dir / "lib"
 
-        self.logger = setup_logging(debug=False, logfile=self.pbench_log)
+        self.logger = setup_logging(debug=False, logfile=None)
 
         self.ssh_opts = os.environ.get("ssh_opts", self.config.ssh_opts)
         self.scp_opts = os.environ.get("scp_opts", self.config.scp_opts)

lib/pbench/agent/results.py

@@ -313,7 +313,7 @@ def __init__(
 
     def copy_result_tb(
         self, token: str, access: Optional[str] = None, metadata: Optional[List] = None
-    ) -> None:
+    ) -> requests.Response:
         """Copies the tar ball from the agent to the configured server using upload
         API.
 
@@ -327,6 +327,9 @@ def copy_result_tb(
             metadata: list of metadata keys to be sent on PUT. (Optional)
                 Format: key:value
 
+        Returns:
+            response from the PUT request
+
         Raises:
             RuntimeError     if a connection to the server fails
             FileUploadError  if the tar ball failed to upload properly
@@ -367,17 +370,12 @@ def copy_result_tb(
                     )
                 )
 
-                response = requests.Session().send(request)
-                response.raise_for_status()
-                self.logger.info("File uploaded successfully")
+                return requests.Session().send(request)
             except requests.exceptions.ConnectionError as exc:
                 raise RuntimeError(f"Cannot connect to '{self.upload_url}': {exc}")
             except Exception as exc:
                 raise self.FileUploadError(
-                    "There was something wrong with file upload request: "
+                    "There was something wrong with the file upload request: "
                     f"file: '{self.tarball}', URL: '{self.upload_url}';"
                     f" error: '{exc}'"
                 )
-        assert (
-            response.ok
-        ), f"Logic error!  Unexpected error response, '{response.reason}' ({response.status_code})"

lib/pbench/cli/agent/commands/results/move.py

@@ -5,6 +5,7 @@
 from typing import List
 
 import click
+import requests
 
 from pbench.agent.base import BaseCommand
 from pbench.agent.results import CopyResultTb, MakeResultTb
@@ -104,9 +105,15 @@ def execute(self, single_threaded: bool, delete: bool = True) -> int:
                         self.config,
                         self.logger,
                     )
-                    crt.copy_result_tb(
+                    res = crt.copy_result_tb(
                         self.context.token, self.context.access, self.context.metadata
                     )
+                    if not res.ok:
+                        try:
+                            msg = res.json()["message"]
+                        except requests.exceptions.JSONDecodeError:
+                            msg = res.text if res.text else res.reason
+                        raise CopyResultTb.FileUploadError(msg)
                 except Exception as exc:
                     if isinstance(exc, (CopyResultTb.FileUploadError, RuntimeError)):
                         msg = "Error uploading file"

lib/pbench/cli/agent/commands/results/push.py

@@ -1,7 +1,9 @@
+from http import HTTPStatus
 from pathlib import Path
 from typing import List
 
 import click
+import requests
 
 from pbench.agent.base import BaseCommand
 from pbench.agent.results import CopyResultTb
@@ -24,10 +26,29 @@ def execute(self) -> int:
             self.config,
             self.logger,
         )
-        crt.copy_result_tb(
+        res = crt.copy_result_tb(
             self.context.token, self.context.access, self.context.metadata
         )
-        return 0
+
+        # success
+        if res.status_code == HTTPStatus.CREATED:
+            return 0
+
+        try:
+            msg = res.json()["message"]
+        except requests.exceptions.JSONDecodeError:
+            msg = res.text if res.text else res.reason
+
+        # dup or other unexpected but non-error status
+        if res.ok:
+            click.echo(msg, err=True)
+            return 0
+
+        click.echo(
+            f"HTTP Error status: {res.status_code}, message: {msg}",
+            err=True,
+        )
+        return 1
 
 
 @sort_click_command_parameters

lib/pbench/test/unit/agent/task/test_copy_result_tb.py

@@ -42,18 +42,20 @@ def test_tarball_nonexistent(self, monkeypatch, agent_logger):
         bad_tarball_name = "nonexistent-tarball.tar.xz"
         expected_error_message = f"Tar ball '{bad_tarball_name}' does not exist"
 
-        monkeypatch.setattr(
-            Path, "exists", self.get_path_exists_mock(bad_tarball_name, False)
-        )
-
-        with pytest.raises(FileNotFoundError) as excinfo:
-            CopyResultTb(
-                bad_tarball_name,
-                0,
-                "ignoremd5",
-                self.config,
-                agent_logger,
+        with monkeypatch.context() as m:
+            m.setattr(
+                Path, "exists", self.get_path_exists_mock(bad_tarball_name, False)
             )
+
+            with pytest.raises(FileNotFoundError) as excinfo:
+                CopyResultTb(
+                    bad_tarball_name,
+                    0,
+                    "ignoremd5",
+                    self.config,
+                    agent_logger,
+                )
+
         assert str(excinfo.value).endswith(
             expected_error_message
         ), f"expected='...{expected_error_message}', found='{str(excinfo.value)}'"
@@ -70,30 +72,33 @@ def request_callback(request: requests.Request):
             else:
                 assert "access" in request.params
                 assert request.params["access"] == access
-            return HTTPStatus.OK, {}, ""
+            return HTTPStatus.CREATED, {}, ""
 
         responses.add_callback(
             responses.PUT,
             f"{self.config.get('results', 'server_rest_url')}/upload/{tb_name}",
             callback=request_callback,
         )
 
-        monkeypatch.setattr(Path, "exists", self.get_path_exists_mock(tb_name, True))
-        monkeypatch.setattr(
-            Path, "open", self.get_path_open_mock(tb_name, io.StringIO(tb_contents))
-        )
+        with monkeypatch.context() as m:
+            m.setattr(Path, "exists", self.get_path_exists_mock(tb_name, True))
+            m.setattr(
+                Path, "open", self.get_path_open_mock(tb_name, io.StringIO(tb_contents))
+            )
 
-        crt = CopyResultTb(
-            tb_name,
-            len(tb_contents),
-            "someMD5",
-            self.config,
-            agent_logger,
-        )
-        if access is None:
-            crt.copy_result_tb("token")
-        else:
-            crt.copy_result_tb("token", access)
+            crt = CopyResultTb(
+                tb_name,
+                len(tb_contents),
+                "someMD5",
+                self.config,
+                agent_logger,
+            )
+            if access is None:
+                res = crt.copy_result_tb("token")
+            else:
+                res = crt.copy_result_tb("token", access)
+
+        assert res.status_code == HTTPStatus.CREATED
         # If we got this far without an exception, then the test passes.
 
     @responses.activate
@@ -111,30 +116,33 @@ def request_callback(request: requests.Request):
                 assert request.params["metadata"] == metadata
             else:
                 assert "metadata" not in request.params
-            return HTTPStatus.OK, {}, ""
+            return HTTPStatus.CREATED, {}, ""
 
         responses.add_callback(
             responses.PUT,
             f"{self.config.get('results', 'server_rest_url')}/upload/{tb_name}",
             callback=request_callback,
         )
 
-        monkeypatch.setattr(Path, "exists", self.get_path_exists_mock(tb_name, True))
-        monkeypatch.setattr(
-            Path, "open", self.get_path_open_mock(tb_name, io.StringIO(tb_contents))
-        )
+        with monkeypatch.context() as m:
+            m.setattr(Path, "exists", self.get_path_exists_mock(tb_name, True))
+            m.setattr(
+                Path, "open", self.get_path_open_mock(tb_name, io.StringIO(tb_contents))
+            )
 
-        crt = CopyResultTb(
-            tb_name,
-            len(tb_contents),
-            "someMD5",
-            self.config,
-            agent_logger,
-        )
-        if metadata is None:
-            crt.copy_result_tb("token")
-        else:
-            crt.copy_result_tb("token", access, metadata)
+            crt = CopyResultTb(
+                tb_name,
+                len(tb_contents),
+                "someMD5",
+                self.config,
+                agent_logger,
+            )
+            if metadata is None:
+                res = crt.copy_result_tb("token")
+            else:
+                res = crt.copy_result_tb("token", access, metadata)
+
+        assert res.status_code == HTTPStatus.CREATED
         # If we got this far without an exception, then the test passes.
 
     @responses.activate
@@ -147,20 +155,21 @@ def test_connection_error(self, monkeypatch, agent_logger):
             responses.PUT, upload_url, body=requests.exceptions.ConnectionError("uh-oh")
         )
 
-        monkeypatch.setattr(Path, "exists", self.get_path_exists_mock(tb_name, True))
-        monkeypatch.setattr(
-            Path, "open", self.get_path_open_mock(tb_name, io.StringIO(tb_contents))
-        )
-
-        with pytest.raises(RuntimeError) as excinfo:
-            crt = CopyResultTb(
-                tb_name,
-                len(tb_contents),
-                "someMD5",
-                self.config,
-                agent_logger,
+        with monkeypatch.context() as m:
+            m.setattr(Path, "exists", self.get_path_exists_mock(tb_name, True))
+            m.setattr(
+                Path, "open", self.get_path_open_mock(tb_name, io.StringIO(tb_contents))
             )
-            crt.copy_result_tb("token")
+
+            with pytest.raises(RuntimeError) as excinfo:
+                crt = CopyResultTb(
+                    tb_name,
+                    len(tb_contents),
+                    "someMD5",
+                    self.config,
+                    agent_logger,
+                )
+                crt.copy_result_tb("token")
 
         assert str(excinfo.value).startswith(
             expected_error_message
@@ -174,18 +183,20 @@ def test_unexpected_error(self, monkeypatch, agent_logger):
 
         responses.add(responses.PUT, upload_url, body=RuntimeError("uh-oh"))
 
-        monkeypatch.setattr(Path, "exists", self.get_path_exists_mock(tb_name, True))
-        monkeypatch.setattr(
-            Path, "open", self.get_path_open_mock(tb_name, io.StringIO(tb_contents))
-        )
-
-        with pytest.raises(CopyResultTb.FileUploadError) as excinfo:
-            crt = CopyResultTb(
-                tb_name,
-                len(tb_contents),
-                "someMD5",
-                self.config,
-                agent_logger,
+        with monkeypatch.context() as m:
+            m.setattr(Path, "exists", self.get_path_exists_mock(tb_name, True))
+            m.setattr(
+                Path, "open", self.get_path_open_mock(tb_name, io.StringIO(tb_contents))
             )
-            crt.copy_result_tb("token")
+
+            with pytest.raises(CopyResultTb.FileUploadError) as excinfo:
+                crt = CopyResultTb(
+                    tb_name,
+                    len(tb_contents),
+                    "someMD5",
+                    self.config,
+                    agent_logger,
+                )
+                crt.copy_result_tb("token")
+
         assert "something wrong" in str(excinfo.value)