Merge ~cjwatson/lp-archive:log-translate-fault into lp-archive:main

[Colin Watson]

Log faults other than NotFound from translatePath

Otherwise it's quite hard to debug what's going on if the XML-RPC backend OOPSes.

[Jürgen Gmach (jugmac00)]

review: Approve

diff --git a/lp_archive/archive.py b/lp_archive/archive.py
index 27de11f..ef0a1a5 100644
--- a/lp_archive/archive.py
+++ b/lp_archive/archive.py
@@ -84,6 +84,7 @@ def translate(
         if f.faultCode == 320:  # NotFound
             return "Not found", 404, {"Content-Type": "text/plain"}
         else:
+            current_app.logger.info("%s %s: %s", archive, path, f.faultString)
             return "Internal server error", 500, {"Content-Type": "text/plain"}
     assert isinstance(url, str)
     return "", 307, {"Location": url}
diff --git a/tests/test_archive.py b/tests/test_archive.py
index e5ef1dc..d6b926c 100644
--- a/tests/test_archive.py
+++ b/tests/test_archive.py
@@ -1,6 +1,7 @@
 # Copyright 2022 Canonical Ltd.  This software is licensed under the
 # GNU Affero General Public License version 3 (see the file LICENSE).
 
+import logging
 from datetime import datetime, timezone
 from threading import Thread
 from typing import Any
@@ -61,7 +62,8 @@ def archive_proxy(app):
     cache.clear()
 
 
-def test_auth_failed(client, archive_proxy):
+def test_auth_failed(client, archive_proxy, caplog):
+    caplog.set_level(logging.INFO, logger="flask.app")
     response = client.get(
         "/~user/ubuntu/private/dists/focal/InRelease",
         auth=("user", "secret"),
@@ -76,9 +78,17 @@ def test_auth_failed(client, archive_proxy):
     assert archive_proxy.call_log == [
         ("checkArchiveAuthToken", "~user/ubuntu/private", "user", "secret")
     ]
+    assert caplog.record_tuples == [
+        (
+            "flask.app",
+            logging.INFO,
+            "user@~user/ubuntu/private: Password does not match.",
+        )
+    ]
 
 
-def test_auth_not_found(client, archive_proxy):
+def test_auth_not_found(client, archive_proxy, caplog):
+    caplog.set_level(logging.INFO, logger="flask.app")
     response = client.get(
         "/~user/ubuntu/nonexistent/dists/focal/InRelease",
         auth=("user", "secret"),
@@ -93,9 +103,13 @@ def test_auth_not_found(client, archive_proxy):
     assert archive_proxy.call_log == [
         ("checkArchiveAuthToken", "~user/ubuntu/nonexistent", "user", "secret")
     ]
+    assert caplog.record_tuples == [
+        ("flask.app", logging.INFO, "user@~user/ubuntu/nonexistent: Not found")
+    ]
 
 
-def test_auth_positive_cached(client, archive_proxy):
+def test_auth_positive_cached(client, archive_proxy, caplog):
+    caplog.set_level(logging.INFO, logger="flask.app")
     response = client.get(
         "/~user/ubuntu/authorized/dists/focal/InRelease",
         auth=("user", "secret"),
@@ -111,7 +125,15 @@ def test_auth_positive_cached(client, archive_proxy):
             None,
         ),
     ]
+    assert caplog.record_tuples == [
+        (
+            "flask.app",
+            logging.INFO,
+            "user@~user/ubuntu/authorized: Authorized.",
+        )
+    ]
     archive_proxy.call_log = []
+    caplog.clear()
     response = client.get(
         "/~user/ubuntu/authorized/dists/focal/InRelease",
         auth=("user", "secret"),
@@ -126,9 +148,17 @@ def test_auth_positive_cached(client, archive_proxy):
             None,
         ),
     ]
+    assert caplog.record_tuples == [
+        (
+            "flask.app",
+            logging.INFO,
+            "user@~user/ubuntu/authorized: Authorized.",
+        )
+    ]
 
 
-def test_auth_negative_not_cached(client, archive_proxy):
+def test_auth_negative_not_cached(client, archive_proxy, caplog):
+    caplog.set_level(logging.INFO, logger="flask.app")
     response = client.get(
         "/~user/ubuntu/private/dists/focal/InRelease",
         auth=("user", "secret"),
@@ -138,7 +168,15 @@ def test_auth_negative_not_cached(client, archive_proxy):
     assert archive_proxy.call_log == [
         ("checkArchiveAuthToken", "~user/ubuntu/private", "user", "secret"),
     ]
+    assert caplog.record_tuples == [
+        (
+            "flask.app",
+            logging.INFO,
+            "user@~user/ubuntu/private: Password does not match.",
+        )
+    ]
     archive_proxy.call_log = []
+    caplog.clear()
     response = client.get(
         "/~user/ubuntu/private/dists/focal/InRelease",
         auth=("user", "secret"),
@@ -148,9 +186,17 @@ def test_auth_negative_not_cached(client, archive_proxy):
     assert archive_proxy.call_log == [
         ("checkArchiveAuthToken", "~user/ubuntu/private", "user", "secret"),
     ]
+    assert caplog.record_tuples == [
+        (
+            "flask.app",
+            logging.INFO,
+            "user@~user/ubuntu/private: Password does not match.",
+        )
+    ]
 
 
-def test_translate(client, archive_proxy):
+def test_translate(client, archive_proxy, caplog):
+    caplog.set_level(logging.INFO, logger="flask.app")
     response = client.get(
         "/ubuntu/dists/focal/InRelease",
         headers=[("Host", "snapshot.ubuntu.test")],
@@ -162,9 +208,13 @@ def test_translate(client, archive_proxy):
         ("checkArchiveAuthToken", "ubuntu", None, None),
         ("translatePath", "ubuntu", "dists/focal/InRelease", None),
     ]
+    assert caplog.record_tuples == [
+        ("flask.app", logging.INFO, "<anonymous>@ubuntu: Authorized.")
+    ]
 
 
-def test_translate_not_found(client, archive_proxy):
+def test_translate_not_found(client, archive_proxy, caplog):
+    caplog.set_level(logging.INFO, logger="flask.app")
     response = client.get(
         "/ubuntu/nonexistent", headers=[("Host", "snapshot.ubuntu.test")]
     )
@@ -176,9 +226,13 @@ def test_translate_not_found(client, archive_proxy):
         ("checkArchiveAuthToken", "ubuntu", None, None),
         ("translatePath", "ubuntu", "nonexistent", None),
     ]
+    assert caplog.record_tuples == [
+        ("flask.app", logging.INFO, "<anonymous>@ubuntu: Authorized.")
+    ]
 
 
-def test_translate_at_timestamp(client, archive_proxy):
+def test_translate_at_timestamp(client, archive_proxy, caplog):
+    caplog.set_level(logging.INFO, logger="flask.app")
     response = client.get(
         "/ubuntu/20220101T120000Z/dists/focal/InRelease",
         headers=[("Host", "snapshot.ubuntu.test")],
@@ -195,9 +249,13 @@ def test_translate_at_timestamp(client, archive_proxy):
             datetime(2022, 1, 1, 12, 0, 0, tzinfo=timezone.utc),
         ),
     ]
+    assert caplog.record_tuples == [
+        ("flask.app", logging.INFO, "<anonymous>@ubuntu: Authorized.")
+    ]
 
 
-def test_translate_oops(client, archive_proxy):
+def test_translate_oops(client, archive_proxy, caplog):
+    caplog.set_level(logging.INFO, logger="flask.app")
     response = client.get(
         "/ubuntu/oops", headers=[("Host", "snapshot.ubuntu.test")]
     )
@@ -209,3 +267,7 @@ def test_translate_oops(client, archive_proxy):
         ("checkArchiveAuthToken", "ubuntu", None, None),
         ("translatePath", "ubuntu", "oops", None),
     ]
+    assert caplog.record_tuples == [
+        ("flask.app", logging.INFO, "<anonymous>@ubuntu: Authorized."),
+        ("flask.app", logging.INFO, "ubuntu oops: Oops"),
+    ]