Merge pull request #4120 from open-formulieren/chore/handle-flaky-test

Deal with flaky test

.github/actions/report-flaky/.gitignore

@@ -0,0 +1 @@
+node_modules/

.github/actions/report-flaky/action.yml

@@ -0,0 +1,12 @@
+---
+
+name: Report flaky tests
+description: Parses log file for flaky tests and adds annotations for them
+inputs:
+  logFile:
+    description: Log file containing the flaky test logs
+    required: true
+    default: 'log/flaky.jsonl'
+runs:
+  using: 'node20'
+  main: 'report_flaky.js'

.github/actions/report-flaky/package.json

@@ -0,0 +1,14 @@
+{
+  "name": "report-flaky",
+  "version": "1.0.0",
+  "description": "Flaky test reporter action",
+  "main": "report_flaky.js",
+  "scripts": {
+    "test": "echo \"Error: no test specified\" && exit 1"
+  },
+  "author": "",
+  "license": "MIT",
+  "dependencies": {
+    "@actions/core": "^1.10.1"
+  }
+}

.github/actions/report-flaky/report_flaky.js

@@ -0,0 +1,26 @@
+// Taken from: https://nodejs.org/api/readline.html#readline_example_read_file_stream_line_by_line
+const fs = require('node:fs');
+const readline = require('node:readline');
+
+const core = require('@actions/core');
+
+const logFilePath = core.getInput('logFile');
+
+async function emitAnnotations() {
+  const fileStream = fs.createReadStream(logFilePath);
+
+  const rl = readline.createInterface({
+    input: fileStream,
+    crlfDelay: Infinity,
+  });
+  // Note: we use the crlfDelay option to recognize all instances of CR LF
+  // ('\r\n') in input.txt as a single line break.
+
+  for await (const line of rl) {
+    // each line is expected to be valid JSON
+    const logRecord = JSON.parse(line);
+    core.warning(logRecord.msg, {file: logRecord.file, startLine: logRecord.line});
+  }
+}
+
+emitAnnotations();

.github/workflows/ci.yml

@@ -96,6 +96,10 @@ jobs:
           DB_PASSWORD: ''
           DEBUG: 'true'
 
+      - run: npm ci
+        working-directory: .github/actions/report-flaky
+      - uses: ./.github/actions/report-flaky
+
       - name: Run JS tests
         run: npm test
 
@@ -180,6 +184,10 @@ jobs:
           DB_PASSWORD: ''
           DEBUG: 'true'
 
+      - run: npm ci
+        working-directory: .github/actions/report-flaky
+      - uses: ./.github/actions/report-flaky
+
   e2etests:
     runs-on: ubuntu-latest
     strategy:
@@ -262,7 +270,7 @@ jobs:
         run: |
           python src/manage.py compilemessages
           python src/manage.py collectstatic --noinput --link
-          src/manage.py test src --parallel 4 --tag=e2e
+          src/manage.py test src --tag=e2e
         env:
           DJANGO_SETTINGS_MODULE: openforms.conf.ci
           SECRET_KEY: dummy

.gitignore

@@ -41,6 +41,7 @@ local.py
 /static/
 /mail/
 /log/*.log*
+/log/*.jsonl
 /log/nginx/*.log*
 /.env
 /docker/.env

requirements/ci.txt

@@ -953,6 +953,8 @@ tabulate==0.8.9
     #   -r requirements/base.txt
 tblib==1.7.0
     # via -r requirements/test-tools.in
+tenacity==8.2.3
+    # via -r requirements/test-tools.in
 testfixtures==6.17.1
     # via -r requirements/test-tools.in
 tinycss2==1.1.0

requirements/dev.txt

@@ -1114,6 +1114,10 @@ tblib==1.7.0
     # via
     #   -c requirements/ci.txt
     #   -r requirements/ci.txt
+tenacity==8.2.3
+    # via
+    #   -c requirements/ci.txt
+    #   -r requirements/ci.txt
 testfixtures==6.17.1
     # via
     #   -c requirements/ci.txt

requirements/test-tools.in

@@ -10,6 +10,7 @@ freezegun
 playwright
 pyquery  # integrates with webtest
 requests-mock
+tenacity
 tblib
 testfixtures
 pep8

src/openforms/conf/base.py

@@ -387,6 +387,9 @@
         "timestamped": {"format": "%(asctime)s %(levelname)s %(name)s  %(message)s"},
         "simple": {"format": "%(levelname)s  %(message)s"},
         "outgoing_requests": {"()": HttpFormatter},
+        "flaky_tests_github_actions": {
+            "format": """{"msg": "%(message)s", "file": "%(file)s", "line": %(line)d}"""
+        },
     },
     "filters": {
         "require_debug_false": {"()": "django.utils.log.RequireDebugFalse"},
@@ -431,6 +434,14 @@
             "level": "DEBUG",
             "class": "log_outgoing_requests.handlers.DatabaseOutgoingRequestsHandler",
         },
+        "flaky_tests": {
+            "level": "INFO",
+            "class": "logging.handlers.RotatingFileHandler",
+            "filename": os.path.join(LOGGING_DIR, "flaky.jsonl"),
+            "formatter": "flaky_tests_github_actions",
+            "maxBytes": 1024 * 1024 * 10,  # 10 MB
+            "backupCount": 10,
+        },
     },
     "loggers": {
         "openforms": {
@@ -466,6 +477,11 @@
             "level": "DEBUG",
             "propagate": True,
         },
+        "flaky_tests": {
+            "handlers": ["flaky_tests"],
+            "level": "INFO",
+            "propagate": False,
+        },
     },
 }
 

src/openforms/conf/utils.py

@@ -121,7 +121,9 @@ def mute_logging(config: dict) -> None:  # pragma: no cover
     """
 
     # set up the null handler for all loggers so that nothing gets emitted
-    for logger in config["loggers"].values():
+    for name, logger in config["loggers"].items():
+        if name == "flaky_tests":
+            continue
         logger["handlers"] = ["null"]
 
     # some tooling logs to a logger which isn't defined, and that ends up in the root

src/openforms/formio/tests/test_api_fileupload.py

@@ -5,6 +5,7 @@
 from unittest.mock import patch
 
 from django.conf import settings
+from django.core.cache import caches
 from django.core.files.uploadedfile import SimpleUploadedFile
 from django.test import override_settings, tag
 from django.utils.translation import gettext as _
@@ -14,12 +15,14 @@
 from rest_framework import status
 from rest_framework.reverse import reverse
 from rest_framework.test import APITestCase, APITransactionTestCase
+from tenacity import retry, retry_if_exception_type, stop_after_attempt
 
 from openforms.config.models import GlobalConfiguration
 from openforms.submissions.attachments import temporary_upload_from_url
 from openforms.submissions.constants import UPLOADS_SESSION_KEY
 from openforms.submissions.tests.factories import SubmissionFactory
 from openforms.submissions.tests.mixins import SubmissionsMixin
+from openforms.tests.utils import log_flaky
 
 TEST_FILES = Path(__file__).parent.resolve() / "files"
 
@@ -360,6 +363,7 @@ def test_cannot_connect_to_clamdav(self, m_config):
 )
 class ConcurrentUploadTests(SubmissionsMixin, APITransactionTestCase):
 
+    @retry(stop=stop_after_attempt(3), retry=retry_if_exception_type(AssertionError))
     @tag("gh-3858")
     def test_concurrent_file_uploads(self):
         submission = SubmissionFactory.from_components(
@@ -395,4 +399,18 @@ def do_upload() -> str:
         }
 
         session_uuids = set(self.client.session[UPLOADS_SESSION_KEY])
+
+        # Flaky test - provide some debug output
+        if session_uuids != uuids:
+            log_flaky()
+            print("Flaky test, dumping debug output...")
+            print(f"{session_uuids=}")
+            print(f"{uuids=}")
+            print("Session cache entries:")
+            cache = caches["session"]
+            entries = dict(cache._cache).keys()
+            for _key in entries:
+                _, _, key = _key.split(":", 2)
+                print(f"  key: {key}\nvalue: {cache.get(key)}\n")
+
         self.assertEqual(session_uuids, uuids)

src/openforms/tests/utils.py

@@ -1,10 +1,12 @@
 import contextlib
 import cProfile
 import io
+import logging
 import os
 import pstats
 import socket
 import sys
+from inspect import currentframe, getframeinfo
 from pathlib import Path
 from pstats import SortKey
 
@@ -15,6 +17,8 @@
     for name in settings.CACHES.keys()
 }
 
+flaky_test_logger = logging.getLogger("flaky_tests")
+
 
 def can_connect(hostname: str):
     # adapted from https://stackoverflow.com/a/28752285
@@ -79,3 +83,28 @@ def c_profile(sort_by=SortKey.CUMULATIVE):  # pragma: no cover
             ps = pstats.Stats(pr, stream=s).sort_stats(sort_by)
             ps.print_stats()
             print(s.getvalue(), file=outfile)
+
+
+def log_flaky():
+    """
+    Log that a/the test is flaky.
+
+    Call this function when you detect flakiness in a test. The result can be processed
+    by Github workflows to add annotations, while retrying the test to not fail the
+    build.
+    """
+    frame = currentframe()
+    assert frame is not None
+    assert (
+        frame.f_back is not None
+    ), "You may only call log_flaky inside another function"
+    frame_info = getframeinfo(frame.f_back)
+    relative_path = Path(frame_info.filename).relative_to(Path(settings.BASE_DIR))
+    flaky_test_logger.warning(
+        "Flaky test: %s",
+        frame_info.function,
+        extra={
+            "file": relative_path,
+            "line": frame_info.lineno,
+        },
+    )