Fix logging to avoid eagerly formatting

Don't use f-strings in logging calls - leave it to be handled by
fsd_utils.

app/__init__.py

@@ -85,8 +85,14 @@ def setup_funds_and_auth(app: Flask) -> None:
     :return: None
     """
     app.logger.info("Setting up fund configs and auth mappings")
-    app.logger.info(f"Additional TF auth details from secret: {str(Config.TF_ADDITIONAL_EMAIL_LOOKUPS)}")
-    app.logger.info(f"Additional PF auth details from secret: {str(Config.PF_ADDITIONAL_EMAIL_LOOKUPS)}")
+    app.logger.info(
+        "Adding extra Additional TF auth details from secret",
+        extra=dict(pf_additional_email=str(Config.TF_ADDITIONAL_EMAIL_LOOKUPS)),
+    )
+    app.logger.info(
+        "Adding extra PF auth details from secret",
+        extra=dict(pf_additional_email=str(Config.PF_ADDITIONAL_EMAIL_LOOKUPS)),
+    )
 
     # funds
     towns_fund: FundConfig = TOWNS_FUND_APP_CONFIG

app/const.py

@@ -1,10 +1,5 @@
 from enum import StrEnum
 
-PRE_VALIDATION_ERROR_LOG = "Pre-validation error: {error}"
-PRE_VALIDATION_LOG = "Pre-validation error(s) found during upload"
-VALIDATION_ERROR_LOG = "Validation error: {error}"
-VALIDATION_LOG = "Validation error(s) found during upload"
-
 
 class MIMETYPE(StrEnum):
     XLSX = "application/vnd.openxmlformats-officedocument.spreadsheetml.sheet"

app/main/data_requests.py

@@ -20,11 +20,13 @@ def post_ingest(file: FileStorage, data: dict = None) -> tuple[dict | None, dict
     request_url = Config.DATA_STORE_API_HOST + "/ingest"
     files = {"excel_file": (file.filename, file, MIMETYPE.XLSX)}
 
-    current_app.logger.info(f"Sending POST to {request_url}")
+    current_app.logger.info("Sending POST to {request_url}", extra=dict(request_url=request_url))
     try:
         response = requests.post(request_url, files=files, data=data)
     except ConnectionError:
-        current_app.logger.error(f"Attempted POST to {request_url} but connection failed")
+        current_app.logger.error(
+            "Attempted POST to {request_url} but connection failed", extra=dict(request_url=request_url)
+        )
         abort(500)
 
     file.seek(0)  # reset the stream position
@@ -49,10 +51,15 @@ def post_ingest(file: FileStorage, data: dict = None) -> tuple[dict | None, dict
                 # if there are no errors then 500 as this is unexpected
                 abort(500)
         case 500:
-            current_app.logger.error(f"Ingest failed for an unknown reason - failure_id={response_json.get('id')}")
+            current_app.logger.error(
+                "Ingest failed for an unknown reason - failure_id={failure_id}",
+                extra=dict(failure_id=response_json.get("id")),
+            )
             abort(500)
         case _:
-            current_app.logger.error(f"Bad response: {request_url} returned {response.status_code}")
+            current_app.logger.error(
+                "Bad response: {request_url} returned {status_code}", extra=dict(status_code=response.status_code)
+            )
             abort(500)
 
     return pre_transformation_errors, validation_errors, metadata

app/main/decorators.py

@@ -24,25 +24,30 @@ def decorated_function(*args, **kwargs):
             auth_mapping = current_app.config["AUTH_MAPPINGS"].get_auth(fund.fund_name)
             auth = auth_mapping.get_auth(g.user.email)
             if auth is None:
-                current_app.logger.info(f"User: {g.user.email} is not authorised to submit for fund: {fund.fund_name}")
+                current_app.logger.info(
+                    "User: {user_email} is not authorised to submit for fund: {fund_name}",
+                    extra=dict(user_email=g.user.email, fund_name=fund.fund_name),
+                )
                 continue
             access[fund.fund_code] = Access(fund, auth)
         if not access:
-            current_app.logger.info(f"User: {g.user.email} is not authorised for any active funds.")
+            current_app.logger.info(
+                "User: {user_email} is not authorised for any active funds.", extra=dict(user_email=g.user.email)
+            )
             # TODO: Replace with a more suitable error screen than unauthorised
             abort(401)
 
         g.access = access
 
         current_app.logger.info(
-            {
-                "Detail": "User authorised for funds. Adding access to request context.",
-                "User": g.user.email,
-                "Funds": [
-                    {"Fund": access_obj.fund.fund_name, "Organisations": access_obj.auth.get_organisations()}
+            "User {user_email} authorised for funds. Adding access to request context.",
+            extra={
+                "user_email": g.user.email,
+                "funds": [
+                    {"fund": access_obj.fund.fund_name, "organisation": access_obj.auth.get_organisations()}
                     for access_obj in access.values()
                 ],
-            }
+            },
         )
 
         return func(*args, **kwargs)

app/main/notify.py

@@ -37,10 +37,11 @@ def send_email(
             template_id=template_id,
             personalisation=personalisation,
         )
-        current_app.logger.info("Email sent via GovUK Notify")
+        current_app.logger.info("Email sent via GOV.UK Notify")
     except HTTPError as notify_exc:
         current_app.logger.error(
-            f"HTTPError when trying to send email: params={personalisation} exception={notify_exc}"
+            "HTTPError when trying to send email: params={personalisation} exception={notify_exc}",
+            extra=dict(personalisation=personalisation, notify_exc=notify_exc),
         )
 
 
@@ -55,7 +56,7 @@ def prepare_upload(file: FileStorage):
     try:
         return notify.prepare_upload(file)
     except ValueError as err:
-        current_app.logger.error(f"Submitted file is too large to send via email - {err}")
+        current_app.logger.error("Submitted file is too large to send via email - {err}", extra=dict(err=err))
 
 
 def send_confirmation_emails(
@@ -99,7 +100,8 @@ def get_personalisation(excel_file: FileStorage, fund: str, reporting_period: st
     fund_type = metadata.get("FundType_ID")
     if not (place_name or fund_type):
         current_app.logger.error(
-            f"Cannot personalise confirmation email with place and fund type due to missing metadata: {metadata}"
+            "Cannot personalise confirmation email with place and fund type due to missing metadata: {metadata}",
+            extra=dict(metadata=metadata),
         )
     personalisation = {
         "name_of_fund": fund,

app/main/routes.py

@@ -7,13 +7,7 @@
 from werkzeug.datastructures import FileStorage
 from werkzeug.exceptions import HTTPException, abort
 
-from app.const import (
-    MIMETYPE,
-    PRE_VALIDATION_ERROR_LOG,
-    PRE_VALIDATION_LOG,
-    VALIDATION_ERROR_LOG,
-    VALIDATION_LOG,
-)
+from app.const import MIMETYPE
 from app.main import bp
 from app.main.data_requests import post_ingest
 from app.main.decorators import set_user_access
@@ -47,7 +41,6 @@ def dashboard():
 @login_required(return_app=SupportedApp.POST_AWARD_SUBMIT)
 @set_user_access
 def upload(fund_code, round):
-
     if fund_code not in g.access:
         abort(401)
 
@@ -85,9 +78,11 @@ def upload(fund_code, round):
             # Pre-validation failure
             if Config.ENABLE_VALIDATION_LOGGING:
                 for pre_err in pre_errors:
-                    current_app.logger.info(PRE_VALIDATION_ERROR_LOG.format(error=pre_err))
+                    current_app.logger.info("Pre-validation error: {error}", extra=dict(error=pre_err))
             else:
-                current_app.logger.info(PRE_VALIDATION_LOG)
+                current_app.logger.info(
+                    "{num_errors} pre-validation error(s) found during upload", extra=dict(num_errors=len(pre_errors))
+                )
 
             return render_template(
                 "upload.html",
@@ -103,13 +98,17 @@ def upload(fund_code, round):
             # Validation failure
             if Config.ENABLE_VALIDATION_LOGGING:
                 for validation_err in validation_errors:
-                    current_app.logger.info(VALIDATION_ERROR_LOG.format(error=validation_err))
+                    current_app.logger.info("Validation error: {error}", extra=dict(error=validation_err))
             else:
-                current_app.logger.info(VALIDATION_LOG)
+                current_app.logger.info(
+                    "{num_errors} validation error(s) found during upload",
+                    extra=dict(num_errors=len(validation_errors)),
+                )
 
             return render_template("validation-errors.html", validation_errors=validation_errors, fund=fund)
         else:
             # Success
+
             if Config.SEND_CONFIRMATION_EMAILS:
                 send_confirmation_emails(
                     excel_file,
@@ -120,7 +119,10 @@ def upload(fund_code, round):
                     metadata=metadata,
                 )
             metadata["User"] = g.user.email
-            current_app.logger.info(f"Upload successful: {metadata}")
+            current_app.logger.info(
+                "Upload successful for {fund} round {round}: {metadata}",
+                extra=dict(metadata=metadata, fund=fund_code, round=round),
+            )
 
             return render_template("success.html", file_name=excel_file.filename)
 
@@ -157,5 +159,5 @@ def http_exception(error):
     if error.code in error_templates:
         return render_template(f"{error.code}.html"), error.code
     else:
-        current_app.logger.info(f"Unhandled HTTP error {error.code} found.")
+        current_app.logger.info("Unhandled HTTP error {error_code} found.", extra=dict(error_code=error.code))
         return render_template("500.html"), error.code

app/utils.py

@@ -17,7 +17,7 @@ def get_friendly_fund_type(fund_type_id: str) -> str | None:
     try:
         return FUND_TYPE_ID_TO_FRIENDLY_NAME[fund_type_id]
     except KeyError:
-        current_app.logger.error(f"Unknown fund type id found: {fund_type_id}")
+        current_app.logger.error("Unknown fund type id found: {fund_type_id}", extra=dict(fund_type_id=fund_type_id))
 
 
 def days_between_dates(date1: date, date2: date) -> int:

tests/test_routes.py

@@ -244,7 +244,10 @@ def test_upload_xlsx_uncaught_validation_error(
 
     assert response.status_code == 500
     assert "Sorry, there is a problem with the service" in str(page_html)
-    assert "Ingest failed for an unknown reason - failure_id=12345" in caplog.text
+
+    # caplog doesn't format log messages so let's make sure it has the string+data we expect
+    assert "Ingest failed for an unknown reason - failure_id={failure_id}" in caplog.records[2].message
+    assert caplog.records[2].failure_id == "12345"
 
 
 def test_upload_wrong_format(flask_test_client, example_ingest_wrong_format, mocker):