Refactoring

I'm now reporting a "canned" client response message giving away nothing but
the generated UUID, while the internal log message can contain a more detailed
description of the error.

I moved generation of the log message from the constructor (which was weird),
to the _dispatch outer block.

The "partial success" cases in `/datasets/delete`, `/datasets/publish`, and in
`PUT /datasets/metadata` are now *success* cases with details in the JSON
response payload. I'm not 100% happy with this, either, but with the shift to
content-free client responses on 500, this seems the new least worst option.

lib/pbench/server/api/resources/__init__.py

@@ -48,7 +48,7 @@ class APIInternalError(APIAbort):
     by an SRE
     """
 
-    def __init__(self, logger: Logger, message: str):
+    def __init__(self, details: str):
         """Construct an "internal server error" exception object.
 
         This exception is raised and will be used in the API _dispatch method
@@ -62,14 +62,19 @@ def __init__(self, logger: Logger, message: str):
         client while capturing detailed information for server developers to
         determine what happened.
 
+        NOTE: We use a fully formatted "details" message here for convenience;
+        we will report this with `logger.exception`, which is never disabled,
+        so deferring the formatting would have no value.
+
         Args:
-            logger  Python logger
-            message A brief descriptive message for the client and log
+            details: A detailed message to be logged when this exception is caught
         """
-        self.uuid = uuid.uuid4()
-        msg = f"INTERNAL error {message!r}: report error code {self.uuid} to an SRE"
-        super().__init__(http_status=HTTPStatus.INTERNAL_SERVER_ERROR, message=msg)
-        logger.exception("{}", msg)
+        u = uuid.uuid4()
+        super().__init__(
+            http_status=HTTPStatus.INTERNAL_SERVER_ERROR,
+            message=f"Internal Pbench Server Error: log reference {u}",
+        )
+        self.details = f"Internal error {u}: {details}"
 
 
 class UnauthorizedAccess(APIAbort):
@@ -1551,15 +1556,18 @@ def _dispatch(
                     method,
                     ApiParams(body=body_params, query=query_params, uri=uri_params),
                 )
+            except APIInternalError as e:
+                self.logger.exception("{} {}", api_name, e.details)
+                abort(e.http_status, message=str(e))
             except APIAbort as e:
                 self.logger.exception("{} {}", api_name, e)
                 abort(e.http_status, message=str(e))
-            except Exception as e:
-                self.logger.exception("{} API error: {}", api_name, e)
-                abort(
-                    HTTPStatus.INTERNAL_SERVER_ERROR,
-                    message=HTTPStatus.INTERNAL_SERVER_ERROR.phrase,
-                )
+            except Exception:
+                # Construct an APIInternalError to get the UUID and standard return
+                # message.
+                x = APIInternalError("Unexpected validation exception")
+                self.logger.exception("{} {}", api_name, x.details)
+                abort(x.http_status, message=str(x))
         else:
             params = ApiParams(None, None, None)
 
@@ -1576,22 +1584,30 @@ def _dispatch(
             except UnauthorizedAccess as e:
                 self.logger.warning("{}: {}", api_name, e)
                 abort(e.http_status, message=str(e))
-            except Exception as e:
-                self.logger.exception("{}: {}", api_name, e)
-                abort(
-                    HTTPStatus.INTERNAL_SERVER_ERROR,
-                    message=HTTPStatus.INTERNAL_SERVER_ERROR.phrase,
-                )
+            except APIInternalError as e:
+                self.logger.exception("{} {}", api_name, e.details)
+                abort(e.http_status, message=str(e))
+            except Exception:
+                # Construct an APIInternalError to get the UUID and standard return
+                # message.
+                x = APIInternalError("Unexpected authorize exception")
+                self.logger.exception("{} {}", api_name, x.details)
+                abort(x.http_status, message=str(x))
 
         try:
             return execute(params, request)
+        except APIInternalError as e:
+            self.logger.exception("{} {}", api_name, e.details)
+            abort(e.http_status, message=str(e))
         except APIAbort as e:
             self.logger.error("{} {}", api_name, e)
             abort(e.http_status, message=str(e))
         except Exception:
-            # Construct an APIInternalError to get the UUID and logged message
-            x = APIInternalError(self.logger, "Unexpected exception")
-            abort(x.http_status, message=x.message)
+            # Construct an APIInternalError to get the UUID and standard return
+            # message.
+            x = APIInternalError("Unexpected exception")
+            self.logger.exception("{} {}", api_name, x.details)
+            abort(x.http_status, message=str(x))
 
     def _get(self, args: ApiParams, request: Request) -> Response:
         """

lib/pbench/server/api/resources/datasets_metadata.py

@@ -1,5 +1,6 @@
 from http import HTTPStatus
 from logging import Logger
+from typing import Any
 
 from flask.json import jsonify
 from flask.wrappers import Request, Response
@@ -12,7 +13,6 @@
     APIAbort,
     ApiAuthorization,
     ApiBase,
-    APIInternalError,
     ApiParams,
     ApiSchema,
     Parameter,
@@ -172,7 +172,7 @@ def _put(self, params: ApiParams, _) -> Response:
         # Now update the metadata, which may occur in multiple SQL operations
         # across namespaces. Make a best attempt to update all even if we
         # encounter an unexpected error.
-        fail: list[str] = []
+        fail: dict[str, Any] = {}
         for k, v in metadata.items():
             native_key = Metadata.get_native_key(k)
             user_id = None
@@ -181,10 +181,10 @@ def _put(self, params: ApiParams, _) -> Response:
             try:
                 Metadata.setvalue(key=k, value=v, dataset=dataset, user_id=user_id)
             except MetadataError as e:
-                fail.append(str(e))
+                fail[k] = str(e)
 
-        if fail:
-            self.logger.error("Error setting metadata keys: {}", ", ".join(fail))
-            raise APIInternalError(self.logger, "Error setting metadata keys")
-        results = self._get_dataset_metadata(dataset, list(metadata.keys()))
+        results = {
+            "metadata": self._get_dataset_metadata(dataset, list(metadata.keys())),
+            "errors": fail,
+        }
         return jsonify(results)

lib/pbench/server/api/resources/query_apis/__init__.py

@@ -397,8 +397,7 @@ def _call(self, method: Callable, params: ApiParams):
         except UnauthorizedAccess as e:
             raise APIAbort(e.http_status, str(e))
         except KeyError as e:
-            self.logger.error("{} problem in preprocess, missing {}", klasname, e)
-            raise APIInternalError(self.logger, "Missing expected backend data")
+            raise APIInternalError(f"problem in preprocess, missing {e}") from e
         try:
             # prepare payload for Elasticsearch query
             es_request = self.assemble(params, context)
@@ -409,8 +408,8 @@ def _call(self, method: Callable, params: ApiParams):
                 url,
                 es_request.get("kwargs").get("json"),
             )
-        except Exception:
-            raise APIInternalError(self.logger, "Assembly error")
+        except Exception as e:
+            raise APIInternalError("Elasticsearch assembly error") from e
 
         try:
             # perform the Elasticsearch query
@@ -448,18 +447,10 @@ def _call(self, method: Callable, params: ApiParams):
                 HTTPStatus.GATEWAY_TIMEOUT,
                 "Connection timed out, could reach Elasticsearch",
             )
-        except requests.exceptions.InvalidURL:
-            self.logger.error(
-                "{}: invalid url {} during the Elasticsearch request", klasname, url
-            )
-            raise APIInternalError(self.logger, "Invalid backend URL")
+        except requests.exceptions.InvalidURL as e:
+            raise APIInternalError(f"Invalid Elasticsearch URL {url}") from e
         except Exception as e:
-            self.logger.exception(
-                "{}: exception {} occurred during the Elasticsearch request",
-                klasname,
-                type(e).__name__,
-            )
-            raise APIInternalError(self.logger, "Unexpected backend error")
+            raise APIInternalError("Unexpected backend error") from e
 
         try:
             # postprocess Elasticsearch response
@@ -468,8 +459,8 @@ def _call(self, method: Callable, params: ApiParams):
             msg = f"{klasname}: {str(e)}"
             self.logger.error("{}", msg)
             raise APIAbort(e.status, msg)
-        except Exception:
-            raise APIInternalError(self.logger, "Unexpected backend exception")
+        except Exception as e:
+            raise APIInternalError("Unexpected backend exception") from e
 
     def _post(self, params: ApiParams, _) -> Response:
         """
@@ -716,7 +707,6 @@ def _post(self, params: ApiParams, _) -> Response:
         Returns:
             Response to return to client
         """
-        klasname = self.__class__.__name__
 
         # Our schema requires a valid dataset and uses it to authorize access;
         # therefore the unconditional dereference is assumed safe.
@@ -744,13 +734,13 @@ def _post(self, params: ApiParams, _) -> Response:
             try:
                 results = helpers.streaming_bulk(
                     elastic,
-                    self.generate_actions(params.body, dataset, map),
+                    self.generate_actions(params, dataset, map),
                     raise_on_exception=False,
                     raise_on_error=False,
                 )
                 report = self._analyze_bulk(results)
-            except Exception:
-                raise APIInternalError(self.logger, "Unexpected backend error")
+            except Exception as e:
+                raise APIInternalError("Unexpected backend error") from e
         elif self.require_map:
             raise APIAbort(
                 HTTPStatus.CONFLICT,
@@ -764,26 +754,20 @@ def _post(self, params: ApiParams, _) -> Response:
 
         # Let the subclass complete the operation
         try:
-            self.complete(dataset, params.body, summary)
-        except Exception:
-            raise APIInternalError(self.logger, "Unexpected completion error")
+            self.complete(dataset, params, summary)
+        except Exception as e:
+            raise APIInternalError("Unexpected completion error") from e
 
         # Return the summary document as the success response, or abort with an
-        # internal error if we weren't 100% successful. Some elasticsearch
-        # documents may have been affected, but the client will be able to try
-        # again.
+        # internal error if we tried to operate on Elasticsearch documents but
+        # experienced total failure. Either way, the operation can be retried
+        # if some documents failed to update.
         #
         # TODO: switching to `pyesbulk` will automatically handle retrying on
         # non-terminal errors, but this requires some cleanup work on the
         # pyesbulk side.
-        if report.errors > 0:
-            self.logger.error(
-                "{}:dataset {}: {} successful document actions and {} failures: {}",
-                klasname,
-                dataset,
-                report.count - report.errors,
-                report.errors,
-                json.dumps(report.report),
+        if report.count and report.errors == report.count:
+            raise APIInternalError(
+                f"Failed to {self.action} any of {report.count} Elasticsearch documents: {json.dumps(report.report)}"
             )
-            raise APIInternalError(self.logger, f"Failed to {self.action} documents")
         return jsonify(summary)

lib/pbench/server/api/resources/query_apis/datasets/__init__.py

@@ -129,11 +129,13 @@ def get_index(self, dataset: Dataset, root_index_name: AnyStr) -> AnyStr:
             index_map = Metadata.getvalue(dataset=dataset, key=Metadata.INDEX_MAP)
         except MetadataError as exc:
             self.logger.error("{}", exc)
-            raise APIInternalError(self.logger, "Required metadata missing")
+            raise APIInternalError(f"Required metadata {Metadata.INDEX_MAP} missing")
 
         if index_map is None:
             self.logger.error("Index map metadata has no value")
-            raise APIInternalError(self.logger, "Required metadata missing")
+            raise APIInternalError(
+                f"Required metadata {Metadata.INDEX_MAP} has no value"
+            )
 
         index_keys = [key for key in index_map if root_index_name in key]
         indices = ",".join(index_keys)

lib/pbench/server/api/resources/query_apis/datasets/datasets_mappings.py

@@ -113,5 +113,4 @@ def _get(self, params: ApiParams, request: Request) -> Response:
             # construct response object
             return jsonify(result)
         except TemplateNotFound as e:
-            self.logger.error("{}", e)
-            raise APIInternalError(self.logger, "Unexpected template error")
+            raise APIInternalError("Unexpected template error") from e

lib/pbench/server/api/resources/query_apis/datasets/namespace_and_rows.py

@@ -85,8 +85,7 @@ def assemble(self, params: ApiParams, context: CONTEXT) -> JSON:
         try:
             mappings = self.get_mappings(document)
         except TemplateNotFound as e:
-            self.logger.error("{}", e)
-            raise APIInternalError(self.logger, "Unexpected template error")
+            raise APIInternalError("Unexpected template error") from e
 
         result = self.get_aggregatable_fields(mappings)
 
@@ -281,8 +280,7 @@ def assemble(self, params: ApiParams, context: CONTEXT) -> JSON:
         try:
             mappings = self.get_mappings(document)
         except TemplateNotFound as e:
-            self.logger.error("{}", e)
-            raise APIInternalError(self.logger, "Unexpected template error")
+            raise APIInternalError("Unexpected template error") from e
 
         # Prepare list of filters to apply for ES query
         es_filter = [{"match": {"run.id": dataset.resource_id}}]

lib/pbench/server/api/resources/server_configuration.py

@@ -97,7 +97,7 @@ def _get(self, params: ApiParams, request: Request) -> Response:
             else:
                 return jsonify(ServerConfig.get_all())
         except ServerConfigError as e:
-            raise APIInternalError(self.logger, str(e)) from e
+            raise APIInternalError(f"Error reading server configuration {key}") from e
 
     def _put_key(self, params: ApiParams) -> Response:
         """
@@ -155,7 +155,7 @@ def _put_key(self, params: ApiParams) -> Response:
         except ServerConfigBadValue as e:
             raise APIAbort(HTTPStatus.BAD_REQUEST, str(e)) from e
         except ServerConfigError as e:
-            raise APIInternalError(self.logger, str(e)) from e
+            raise APIInternalError(f"Error setting server configuration {key}") from e
         return jsonify({key: value})
 
     def _put_body(self, params: ApiParams) -> Response:
@@ -191,7 +191,7 @@ def _put_body(self, params: ApiParams) -> Response:
                 failures.append(str(e))
             except Exception as e:
                 self.logger.warning("{}", e)
-                raise APIInternalError(self.logger, "Error setting config values")
+                raise APIInternalError(f"Error setting server configuration {k}")
         if failures:
             raise APIAbort(HTTPStatus.BAD_REQUEST, message=", ".join(failures))
         return jsonify(response)

lib/pbench/test/unit/server/conftest.py

@@ -165,17 +165,20 @@ def make_logger(server_config):
 @pytest.fixture()
 def capinternal(caplog):
     def compare(message: str, response: Optional[Response]):
-        pat = re.compile(
-            f"INTERNAL error {message!r}: report error code [a-zA-Z\\d]{{8}}-([a-zA-Z\\d]{{4}}-){{3}}[a-zA-Z\\d]{{12}} to an SRE"
-        )
+        uuid = r"[a-zA-Z\d]{8}-([a-zA-Z\d]{4}-){3}[a-zA-Z\d]{12}"
+        name = r"\w+\s+"
+        external = re.compile(f"Internal Pbench Server Error: log reference {uuid}")
+        internal = re.compile(f"{name}Internal error {uuid}: {message}")
         if response:
             assert response.status_code == HTTPStatus.INTERNAL_SERVER_ERROR
-            assert pat.match(response.json["message"]), response.json["message"]
+            assert external.match(response.json["message"])
         for r in caplog.get_records("call"):
             if r.levelno == logging.ERROR:
-                if pat.match(str(r.msg)):
+                if internal.match(str(r.msg)):
                     return
-        assert False, "Expected pattern string not logged at level 'ERROR'"
+        assert (
+            False
+        ), f"Expected pattern {internal.pattern!r} not logged at level 'ERROR': {[str(r.msg) for r in caplog.get_records('call')]}"
 
     return compare
 

lib/pbench/test/unit/server/query_apis/test_datasets_delete.py

@@ -171,9 +171,8 @@ def test_partial(
             f"{server_config.rest_uri}/datasets/delete/{ds.resource_id}",
             headers={"authorization": f"Bearer {pbench_token}"},
         )
-
-        # Verify the report and status
-        capinternal("Failed to delete documents", response)
+        assert response.status_code == HTTPStatus.OK
+        assert response.json == {"ok": 28, "failure": 3}
 
         # Verify that the Dataset still exists
         Dataset.query(name="drb")

lib/pbench/test/unit/server/query_apis/test_datasets_publish.py

@@ -155,9 +155,8 @@ def test_partial(
             headers={"authorization": f"Bearer {pbench_token}"},
             query_string=self.PAYLOAD,
         )
-
-        # Verify the report and status
-        capinternal("Failed to update documents", response)
+        assert response.status_code == HTTPStatus.OK
+        assert response.json == {"ok": 28, "failure": 3}
 
         # Verify that the Dataset access didn't change
         dataset = Dataset.query(name="drb")