feat: add logging for validation failures and misconfiguration (#46)

Signed-off-by: tdruez <tdruez@aboutcode.org>

Author: tdruez

README.md

@@ -217,6 +217,48 @@ Only loaded when `ALTCHA_INCLUDE_TRANSLATIONS` is `True`.
 Set to `False` to skip Altcha validation altogether.
 Defaults to `True`.
 
+## Logging
+
+Django Altcha uses the standard Python `logging` module under the logger name
+`django_altcha`. No logs are emitted under normal operation; logging fires only
+on validation failures and misconfiguration.
+
+### What gets logged
+
+- **WARNING** on invalid or missing CAPTCHA tokens submitted to a form.
+- **WARNING** on replay attempts (a challenge reused after it has already been validated).
+- **ERROR** when `ALTCHA_HMAC_KEY` is not configured.
+- **Exception with traceback** when verification or payload decoding raises
+  unexpectedly.
+
+Payloads, challenge values, and the HMAC key are never included in log
+messages.
+
+### Enabling logs
+
+Add the `django_altcha` logger to your project's `LOGGING` setting:
+
+```python
+LOGGING = {
+    "version": 1,
+    "disable_existing_loggers": False,
+    "handlers": {
+        "console": {
+            "class": "logging.StreamHandler",
+        },
+    },
+    "loggers": {
+        "django_altcha": {
+            "handlers": ["console"],
+            "level": "WARNING",
+        },
+    },
+}
+```
+
+Set `"level": "ERROR"` to see only misconfiguration and unexpected failures,
+or `"level": "DEBUG"` to see additional diagnostic messages during development.
+
 ## Contributing
 
 We welcome contributions to improve this library.

django_altcha/__init__.py

@@ -8,6 +8,7 @@
 import base64
 import datetime
 import json
+import logging
 
 from django import forms
 from django.core.cache import caches
@@ -26,11 +27,14 @@
 __version__ = "0.10.0"
 VERSION = __version__
 
+logger = logging.getLogger(__name__)
+
 
 def get_hmac_key():
     """Return the HMAC key, raising if not configured."""
     hmac_key = get_setting("ALTCHA_HMAC_KEY")
     if not hmac_key:
+        logger.error("ALTCHA_HMAC_KEY setting is not configured")
         raise ImproperlyConfigured("The ALTCHA_HMAC_KEY setting must be provided.")
     return hmac_key
 
@@ -228,11 +232,15 @@ def __init__(self, *args, **kwargs):
     def validate(self, value):
         """Validate the CAPTCHA token and verify its authenticity."""
         if not get_setting("ALTCHA_VERIFICATION_ENABLED"):
+            logger.debug(
+                "ALTCHA validation skipped: ALTCHA_VERIFICATION_ENABLED is False"
+            )
             return
 
         super().validate(value)
 
         if not value:
+            logger.warning("ALTCHA validation failed: missing token")
             raise forms.ValidationError(
                 self.error_messages["required"], code="required"
             )
@@ -244,9 +252,11 @@ def validate(self, value):
                 check_expires=True,
             )
         except Exception:
+            logger.exception("ALTCHA validation raised an unexpected exception")
             raise forms.ValidationError(self.error_messages["error"], code="error")
 
         if not verified:
+            logger.warning("ALTCHA validation failed: %s", error)
             raise forms.ValidationError(self.error_messages["invalid"], code="invalid")
 
         self.replay_attack_protection(payload=value)
@@ -258,9 +268,13 @@ def replay_attack_protection(self, payload):
             payload_data = json.loads(base64.b64decode(payload).decode())
             challenge = payload_data["challenge"]
         except Exception:
+            logger.exception(
+                "ALTCHA payload could not be decoded for replay protection"
+            )
             raise forms.ValidationError(self.error_messages["error"], code="error")
 
         if is_challenge_used(challenge):
+            logger.warning("ALTCHA replay attack detected: challenge already used")
             raise forms.ValidationError(self.error_messages["replay"], code="invalid")
 
         # Mark as used for the same duration as challenge expiration
@@ -281,4 +295,5 @@ def get(self, request, *args, **kwargs):
         expires = kwargs.get("expires", self.expires)
 
         challenge = get_altcha_challenge(max_number=max_number, expires=expires)
+        logger.debug("ALTCHA challenge issued")
         return JsonResponse(challenge.__dict__)

tests/test_logging.py

@@ -0,0 +1,70 @@
+#
+# Copyright (c) nexB Inc. and others. All rights reserved.
+# SPDX-License-Identifier: MIT
+# See https://github.com/aboutcode-org/django-altcha for support or download.
+# See https://aboutcode.org for more information about AboutCode FOSS projects.
+#
+
+from unittest import mock
+
+from django import forms
+from django.core.exceptions import ImproperlyConfigured
+from django.test import TestCase
+from django.test import override_settings
+
+from django_altcha import AltchaField
+
+from .test_field import make_valid_payload
+
+
+class AltchaFieldLoggingTest(TestCase):
+    def setUp(self):
+        class TestForm(forms.Form):
+            altcha_field = AltchaField()
+
+        self.form_class = TestForm
+
+    @mock.patch("altcha.verify_solution")
+    def test_invalid_token_logs_warning(self, mock_verify_solution):
+        mock_verify_solution.return_value = (False, "bad signature")
+        form = self.form_class(data={"altcha_field": "anything"})
+        with self.assertLogs("django_altcha", level="WARNING") as captured:
+            form.is_valid()
+        self.assertEqual(len(captured.records), 1)
+        self.assertEqual(captured.records[0].levelname, "WARNING")
+        self.assertIn("bad signature", captured.output[0])
+
+    @mock.patch("altcha.verify_solution")
+    def test_verification_exception_is_logged_with_traceback(
+        self, mock_verify_solution
+    ):
+        mock_verify_solution.side_effect = RuntimeError("boom")
+        form = self.form_class(data={"altcha_field": "anything"})
+        with self.assertLogs("django_altcha", level="ERROR") as captured:
+            form.is_valid()
+        self.assertEqual(captured.records[0].levelname, "ERROR")
+        # Confirms traceback is captured
+        self.assertIsNotNone(captured.records[0].exc_info)
+
+    @mock.patch("altcha.verify_solution")
+    def test_replay_attempt_logs_warning(self, mock_verify_solution):
+        mock_verify_solution.return_value = (True, None)
+        valid_payload = make_valid_payload(challenge="replay-test-1")
+        # First submission succeeds and marks the challenge as used.
+        self.form_class(data={"altcha_field": valid_payload}).is_valid()
+        # Second submission should log a replay warning.
+        form = self.form_class(data={"altcha_field": valid_payload})
+        with self.assertLogs("django_altcha", level="WARNING") as captured:
+            form.is_valid()
+        self.assertTrue(
+            any("replay" in r.getMessage().lower() for r in captured.records)
+        )
+
+    @override_settings(ALTCHA_HMAC_KEY=None)
+    def test_missing_hmac_key_logs_error(self):
+        from django_altcha import get_hmac_key
+
+        with self.assertLogs("django_altcha", level="ERROR") as captured:
+            with self.assertRaises(ImproperlyConfigured):
+                get_hmac_key()
+        self.assertEqual(captured.records[0].levelname, "ERROR")