From cd53e8ef9c9ef9895ec8599e294643cb2c341630 Mon Sep 17 00:00:00 2001 From: Allison Karlitskaya Date: Wed, 24 Jun 2026 11:35:24 +0200 Subject: [PATCH 1/3] lib/github: fix up debugging output We have a custom Logger in lib/github.py that's used for a single testcase that wants to check what is being fetched. We can easily manage this with the standard Python logging facilities. Add a per-file logger and use that instead, and use .assertLogs() in the test. This also means that the requests will be visible in our scripts that support `--debug`/`-d` arguments. Switch one other existing (global) log call to the new per-file logger. Finally: a very interesting thing to know is where the github token came from, or if we have one at all. Add some debugging about that. --- lib/github.py | 34 ++++++++++------------------------ test/test_github.py | 25 +++++++++---------------- 2 files changed, 19 insertions(+), 40 deletions(-) diff --git a/lib/github.py b/lib/github.py index 1be1624053..5b0a1e4677 100644 --- a/lib/github.py +++ b/lib/github.py @@ -22,7 +22,6 @@ import logging import os import re -import socket import subprocess import time import urllib.parse @@ -37,6 +36,8 @@ from lib.directories import xdg_cache_home, xdg_config_home from lib.testmap import is_valid_context +logger = logging.getLogger(__name__) + __all__ = ( 'NOT_TESTED', 'NOT_TESTED_DIRECT', @@ -65,20 +66,6 @@ _DT = TypeVar('_DT') -class Logger: - def __init__(self, directory: str): - hostname = socket.gethostname().split(".")[0] - month = time.strftime("%Y%m") - self.path = os.path.join(directory, f"{hostname}-{month}.log") - - os.makedirs(directory, exist_ok=True) - - # Yes, we open the file each time - def write(self, value: str) -> None: - with open(self.path, 'a') as f: - f.write(value) - - class Response(TypedDict): status: int reason: str @@ -150,10 +137,12 @@ def __init__( try: with open(xdg_config_home('cockpit-dev', 'github-token', envvar='COCKPIT_GITHUB_TOKEN_FILE')) as f: self.token = f.read().strip() + logger.debug("github token loaded from %s", f.name) except FileNotFoundError: try: with open(xdg_config_home('github-token')) as f: self.token = f.read().strip() + logger.debug("github token loaded from %s", f.name) except FileNotFoundError: # fall back to GitHub's CLI token try: @@ -161,9 +150,11 @@ def __init__( match = re.search(r'oauth_token:\s*(\S+)', f.read()) if match: self.token = match.group(1) + logger.debug("github token loaded from %s", f.name) + else: + logger.debug("no oauth_token found in %s", f.name) except FileNotFoundError: - # token not found anywhere, so only reading operations are available - pass + logger.debug("no github token found; only reading operations are available") # default cache directory if not cacher: @@ -171,10 +162,6 @@ def __init__( self.cache = cacher - # Create a log for debugging our GitHub access - self.log = Logger(self.cache.directory) - self.log.write("") - def config(self) -> Sequence[tuple[str, str]]: """Git config overrides for authenticating with this remote.""" @@ -249,7 +236,7 @@ def request( # success! break except (ConnectionResetError, http.client.BadStatusLine, OSError, SSLEOFError) as e: - logging.warning("Transient error during GitHub request, attempt #%s: %s", retry, e) + logger.warning("Transient error during GitHub request, attempt #%s: %s", retry, e) self.conn = None time.sleep(2 ** retry) @@ -259,8 +246,7 @@ def request( heads = {} for (header, value) in response.getheaders(): heads[header.lower()] = value - self.log.write( - f'{self.url.netloc} - - [{time.asctime()}] "{method} {resource} HTTP/1.1" {response.status} -\n') + logger.debug("%s %s %s → %d", self.url.netloc, method, resource, response.status) return { "status": response.status, "reason": response.reason, diff --git a/test/test_github.py b/test/test_github.py index da54078f86..42d2a935ed 100755 --- a/test/test_github.py +++ b/test/test_github.py @@ -17,7 +17,6 @@ # You should have received a copy of the GNU Lesser General Public License # along with Cockpit; If not, see . -import fnmatch import json import shutil import tempfile @@ -88,21 +87,15 @@ def test_cache(self) -> None: self.assertEqual(count, 1) def test_log(self) -> None: - self.api.get("/test/user") - self.api.cache.mark(time.time() + 1) - self.api.get("/test/user") - - expect = ( - '127.0.0.8:9898 - - * "GET /test/user HTTP/1.1" 200 -\n' - '127.0.0.8:9898 - - * "GET /test/user HTTP/1.1" 304 -\n' - ) - - with open(self.api.log.path, "r") as f: - data = f.read() - - match = fnmatch.fnmatch(data, expect) - if not match: - self.fail(f"'{data}' did not match '{expect}'") + with self.assertLogs('lib.github', level='DEBUG') as logs: + self.api.get("/test/user") + self.api.cache.mark(time.time() + 1) + self.api.get("/test/user") + + self.assertEqual(logs.output, [ + 'DEBUG:lib.github:127.0.0.8:9898 GET /test/user → 200', + 'DEBUG:lib.github:127.0.0.8:9898 GET /test/user → 304', + ]) def test_issues_since(self) -> None: issues = self.api.issues(since=1499838499) From cad81dc8e45412d8caf977309a9c8a11d8bf712e Mon Sep 17 00:00:00 2001 From: Allison Karlitskaya Date: Fri, 26 Jun 2026 10:52:58 +0200 Subject: [PATCH 2/3] lib/test_mock_server: two fixes for reentrancy Our various tests which use test_mock_server can't be run in parallel for two main reasons: - we statically bind to a hardcoded port number. This means that our tests can't run against each other but also means that we could just get unlucky with other things running on the system - test_job tests share a single `.json` file in a temporary directory which we create (and never delete) in /tmp which means they see each others data. Add two queues to test_mock_server: - the first replaces our "ready" event, recently added in a1f707c76653 ("lib/test_mock_server.py: wait for server startup") with a queue. We await the queue to find out when we're ready to serve but the queue passes back the listener port number. This allows specifying the port number as 0 (which all of our tests now do) and finding out which port was kernel-allocated on the server side. Why provide the address at all if all of our tests use 0? Because this code is also used by the mock-github script in the cockpituous repository and it needs a static address. - a generic other queue which can be optionally used by tests to pass data back to themselves from their handlers. This replaces the JSON file. Improvements: - no dangling temporary directories left behind in /tmp each time we run the tests - no conflicts with other processes running on the system (including a guaranteed conflict with a parallel run of the same tests, perhaps in a different worktree) - enables running the test suite under xdist, if you so fancy - less code, more self-contained --- lib/test_mock_server.py | 39 +++++++++++++++++++++------------ test/test_github.py | 11 +++++----- test/test_job.py | 48 +++++++++++------------------------------ test/test_task.py | 7 ++---- test/test_tests_scan.py | 7 ++---- 5 files changed, 48 insertions(+), 64 deletions(-) diff --git a/lib/test_mock_server.py b/lib/test_mock_server.py index ca02543d79..fc95bbdd27 100644 --- a/lib/test_mock_server.py +++ b/lib/test_mock_server.py @@ -20,7 +20,9 @@ import http.server import json import multiprocessing -from collections.abc import Mapping +import queue +from collections.abc import Mapping, Sequence +from typing import Never from lib.aio.jsonutil import JsonValue @@ -40,30 +42,39 @@ # which is why we can pass in mutable state but it's never modified. -class HTTPServer[T](http.server.HTTPServer): +class HTTPServer[T, Q = Never](http.server.HTTPServer): reply_count = 0 data: T + queue: multiprocessing.Queue[Q] -class MockServer[T]: - def __init__( - self, address: tuple[str, int], handler: type[MockHandler[T]], data: T - ): +class MockServer[T, Q = Never]: + def __init__(self, address: tuple[str, int], handler: type[MockHandler[T, Q]], data: T): self.address = address self.handler = handler self.data = data + self.queue: multiprocessing.Queue[Q] = multiprocessing.Queue() - def run(self, ready: multiprocessing.synchronize.Event) -> None: - srv = HTTPServer[T](self.address, self.handler) + def run(self, port_queue: multiprocessing.Queue[int]) -> None: + srv = HTTPServer[T, Q](self.address, self.handler) srv.data = self.data - ready.set() + srv.queue = self.queue + port_queue.put(srv.server_address[1]) srv.serve_forever() def start(self) -> None: - ready = multiprocessing.Event() - self.process = multiprocessing.Process(target=self.run, args=(ready,)) + port_queue: multiprocessing.Queue[int] = multiprocessing.Queue() + self.process = multiprocessing.Process(target=self.run, args=(port_queue,)) self.process.start() - ready.wait() + self.address = (self.address[0], port_queue.get()) + + def drain_queue(self) -> Sequence[Q]: + result: list[Q] = [] + try: + while True: + result.append(self.queue.get_nowait()) + except queue.Empty: + return result def kill(self) -> None: self.process.terminate() @@ -71,13 +82,13 @@ def kill(self) -> None: assert self.process.exitcode is not None -class MockHandler[T](http.server.BaseHTTPRequestHandler): +class MockHandler[T, Q = Never](http.server.BaseHTTPRequestHandler): # This is wrong and broken and unsafe, but we kinda need to do it. We know # that we'll only ever use this with the correct server type, but this # information doesn't get carried through the library stack (in fact, we # can't even be sure that .server here is even an HTTP server: it could be # any socket server). So let's add it back. It's just tests... - server: HTTPServer[T] + server: HTTPServer[T, Q] def replyData(self, value: str, headers: Mapping[str, str] = {}, status: int = 200) -> None: self.send_response(status) diff --git a/test/test_github.py b/test/test_github.py index 42d2a935ed..53e6e70672 100755 --- a/test/test_github.py +++ b/test/test_github.py @@ -27,7 +27,6 @@ from lib import cache, github from lib.test_mock_server import MockHandler, MockServer -ADDRESS = ("127.0.0.8", 9898) GITHUB_ISSUES = [{"number": "5", "state": "open", "created_at": "2011-04-22T13:33:48Z"}, {"number": "6", "state": "closed", "closed_at": "2011-04-21T13:33:48Z"}, {"number": "7", "state": "open"}] @@ -69,10 +68,11 @@ def do_DELETE(self) -> None: class TestGitHub(unittest.TestCase): def setUp(self) -> None: - self.server = MockServer(ADDRESS, Handler, GITHUB_ISSUES) + self.server = MockServer(("127.0.0.1", 0), Handler, GITHUB_ISSUES) self.server.start() self.temp = tempfile.mkdtemp() - self.api = github.GitHub(f"http://{ADDRESS[0]}:{ADDRESS[1]}/", cacher=cache.Cache(self.temp)) + url = f"http://{self.server.address[0]}:{self.server.address[1]}/" + self.api = github.GitHub(url, cacher=cache.Cache(self.temp)) def tearDown(self) -> None: self.server.kill() @@ -92,9 +92,10 @@ def test_log(self) -> None: self.api.cache.mark(time.time() + 1) self.api.get("/test/user") + netloc = f'{self.server.address[0]}:{self.server.address[1]}' self.assertEqual(logs.output, [ - 'DEBUG:lib.github:127.0.0.8:9898 GET /test/user → 200', - 'DEBUG:lib.github:127.0.0.8:9898 GET /test/user → 304', + f'DEBUG:lib.github:{netloc} GET /test/user → 200', + f'DEBUG:lib.github:{netloc} GET /test/user → 304', ]) def test_issues_since(self) -> None: diff --git a/test/test_job.py b/test/test_job.py index cb291a7416..5d31f7cf8f 100644 --- a/test/test_job.py +++ b/test/test_job.py @@ -1,6 +1,5 @@ import asyncio import json -import tempfile from pathlib import Path from typing import Any, AsyncGenerator, Generator, NamedTuple from unittest.mock import AsyncMock, Mock, patch @@ -14,11 +13,6 @@ from lib.aio.local import LocalLogDriver from lib.test_mock_server import MockHandler, MockServer -ADDRESS = ("127.0.0.1", 9999) - -# Global path for recording POST calls across processes -POST_CALLS_FILE = Path(tempfile.gettempdir()) / "test_job_post_calls.json" - # Mock GitHub API responses GITHUB_DATA: JsonObject = { "/repos/cockpit-project/cockpit/git/refs/heads/main": { @@ -35,18 +29,7 @@ } -class MockGitHubHandler(MockHandler[JsonObject]): - @staticmethod - def clear_post_calls() -> None: - POST_CALLS_FILE.unlink(missing_ok=True) - - @staticmethod - def get_post_calls() -> list[tuple[str, JsonObject]]: - try: - return json.loads(POST_CALLS_FILE.read_text()) - except FileNotFoundError: - return [] - +class MockGitHubHandler(MockHandler[JsonObject, tuple[str, JsonObject]]): def do_GET(self) -> None: data = self.server.data if self.path in data: @@ -60,11 +43,8 @@ def do_POST(self) -> None: post_body = self.rfile.read(content_length) post_data = typechecked(json.loads(post_body.decode('utf-8')), dict) - # Record the POST call to file - existing_calls = self.get_post_calls() - existing_calls.append((self.path, post_data)) - with POST_CALLS_FILE.open('w') as f: - json.dump(existing_calls, f) + # Record the POST call via queue + self.server.queue.put((self.path, post_data)) if self.path.startswith('/repos/') and '/statuses/' in self.path: # Mock status posting @@ -120,16 +100,13 @@ def mock_log_streamer_init(index: Any, proxy_url: URL | None = None) -> Mock: async def mock_job_context(tmp_path: Path) -> AsyncGenerator[Mock, None]: """Mock JobContext with mock GitHub forge""" - # Clear any previous POST calls from other tests - MockGitHubHandler.clear_post_calls() - - server = MockServer(ADDRESS, MockGitHubHandler, GITHUB_DATA) + server = MockServer(("127.0.0.1", 0), MockGitHubHandler, GITHUB_DATA) server.start() try: github_config: JsonObject = { - 'clone-url': f'http://{ADDRESS[0]}:{ADDRESS[1]}/', - 'api-url': f'http://{ADDRESS[0]}:{ADDRESS[1]}/', + 'clone-url': f'http://{server.address[0]}:{server.address[1]}/', + 'api-url': f'http://{server.address[0]}:{server.address[1]}/', 'user-agent': 'test-runner', 'post': True, # Enable actual POST requests 'token': 'dummy-token' # Required when post is True @@ -155,6 +132,7 @@ async def mock_job_context(tmp_path: Path) -> AsyncGenerator[Mock, None]: mock_ctx.container_run_args = ['--pull=newer'] mock_ctx.secrets_args = {} mock_ctx.resolve_subject = AsyncMock(wraps=forge.resolve_subject) + mock_ctx.server = server yield mock_ctx @@ -243,7 +221,7 @@ async def test_run_job_success( log_streamer_mocks.log_streamer_class.assert_called_once_with(log_streamer_mocks.index_instance, None) # Verify status posts were made - post_calls = MockGitHubHandler.get_post_calls() + post_calls = mock_job_context.server.drain_queue() assert len(post_calls) == 2 # First call is the 'pending' status @@ -279,7 +257,7 @@ async def test_run_job_failure( ) # Verify status posts were made - post_calls = MockGitHubHandler.get_post_calls() + post_calls = mock_job_context.server.drain_queue() assert len(post_calls) == 2 # First call is the 'pending' status @@ -308,7 +286,7 @@ async def test_run_job_failure_with_report( await run_job(job_with_report, mock_job_context) # Verify status posts were made - post_calls = MockGitHubHandler.get_post_calls() + post_calls = mock_job_context.server.drain_queue() assert len(post_calls) == 3 # First two are the status updates @@ -354,7 +332,7 @@ async def test_run_job_cancelled( ) # Verify status posts were made - post_calls = MockGitHubHandler.get_post_calls() + post_calls = mock_job_context.server.drain_queue() assert len(post_calls) == 2 # Last call is the 'error' status with 'Cancelled' message @@ -387,7 +365,7 @@ async def nix_und_zwar_langsam(*_: object, **__: object) -> None: ) # Verify status posts were made - post_calls = MockGitHubHandler.get_post_calls() + post_calls = mock_job_context.server.drain_queue() assert len(post_calls) == 2 # Last call is the 'failure' status with timeout message @@ -428,7 +406,7 @@ async def test_run_job_success_with_proxy_url( ) # Verify status posts were made with proxy URL - post_calls = MockGitHubHandler.get_post_calls() + post_calls = mock_job_context.server.drain_queue() assert len(post_calls) == 2 # First call is the 'pending' status diff --git a/test/test_task.py b/test/test_task.py index 331271da41..e96f9bf729 100755 --- a/test/test_task.py +++ b/test/test_task.py @@ -27,9 +27,6 @@ from lib.github import GitHub from lib.test_mock_server import MockHandler, MockServer -ADDRESS = ("127.0.0.9", 9898) - - GITHUB_DATA: JsonObject = { "/repos/project/repo": { "default_branch": "main" @@ -61,10 +58,10 @@ def do_POST(self) -> None: class TestGitHubHelpers(unittest.TestCase): def setUp(self) -> None: - self.server = MockServer(ADDRESS, Handler, GITHUB_DATA) + self.server = MockServer(("127.0.0.1", 0), Handler, GITHUB_DATA) self.server.start() self.temp = tempfile.mkdtemp() - os.environ["GITHUB_API"] = "http://127.0.0.9:9898" + os.environ["GITHUB_API"] = f"http://{self.server.address[0]}:{self.server.address[1]}" os.environ["GITHUB_BASE"] = "project/repo" self.github = GitHub() diff --git a/test/test_tests_scan.py b/test/test_tests_scan.py index 38dcca5092..ee21228397 100755 --- a/test/test_tests_scan.py +++ b/test/test_tests_scan.py @@ -34,9 +34,6 @@ from lib.constants import BOTS_DIR from lib.test_mock_server import MockHandler, MockServer -ADDRESS = ("127.0.0.7", 9898) - - GITHUB_DATA: dict[str, JsonValue] = { "/repos/project/repo": { "default_branch": "main" @@ -133,13 +130,13 @@ def setUp(self) -> None: self.temp = tempfile.mkdtemp() self.cache_dir = os.path.join(self.temp, "cache") os.environ["XDG_CACHE_HOME"] = self.cache_dir - self.server = MockServer(ADDRESS, Handler, GITHUB_DATA) + self.server = MockServer(("127.0.0.1", 0), Handler, GITHUB_DATA) self.server.start() self.repo = "project/repo" self.pull_number = 1 self.context = "fedora/nightly" self.revision = "abcdef" - os.environ["GITHUB_API"] = f"http://{ADDRESS[0]}:{ADDRESS[1]}" + os.environ["GITHUB_API"] = f"http://{self.server.address[0]}:{self.server.address[1]}" # expected human output for our standard mock PR #1 above self.expected_human_output = ( From 5785529558dab187672b9b8b71dad8df357b7ed2 Mon Sep 17 00:00:00 2001 From: Allison Karlitskaya Date: Fri, 26 Jun 2026 11:03:08 +0200 Subject: [PATCH 3/3] test: speed up some tests MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit These tests are the worst remaining offenders in slowing down the test suite. Make two fixes. For the aio "github api flakes" test, we want to test retry behaviour but the retries have an exponential backoff that we have to wait for (but never test). We can kill two birds with one stone by replacing the sleep with a mock which means that we don't have to wait for it and can verify that the exponential backoff is working properly. For the cache tests, they're also slow because we do long sleeps — six seconds in total. Reduce our Cache lag= to 1 second instead of 3 and sleep for fractional seconds instead. We could probably go even lower with a fractional lag but I'm worried about stability through scheduling blips on busy machines. We can't use sleep mocking here as easily because this is testing timestamps on the filesystem, but let's keep things simple: this is already enough of an improvement. With this change the tests drop from requiring ~12s (or ~42s at the start of the week) to ~4s. --- test/test_aio.py | 11 ++++++++--- test/test_cache.py | 10 +++++----- 2 files changed, 13 insertions(+), 8 deletions(-) diff --git a/test/test_aio.py b/test/test_aio.py index 83bfd94867..9a45028077 100644 --- a/test/test_aio.py +++ b/test/test_aio.py @@ -4,6 +4,7 @@ from collections.abc import AsyncIterator, Iterator, Sequence from pathlib import Path from typing import Any +from unittest.mock import AsyncMock, patch import httpx import pytest @@ -159,9 +160,13 @@ async def test_github_404(service: GitHubService, api: GitHub) -> None: async def test_github_api_flakes(service: GitHubService, api: GitHub) -> None: # Make sure 5xx errors and network issues get retries - service.flake([(503, 'Busy'), httpx.ConnectError('connection failed')]) - service.update('x', {'a': 'b'}, etag=True) - assert await api.get('x') == {'a': 'b'} + mock_sleep = AsyncMock() + with patch('asyncio.sleep', mock_sleep): + service.flake([(503, 'Busy'), httpx.ConnectError('connection failed')]) + service.update('x', {'a': 'b'}, etag=True) + assert await api.get('x') == {'a': 'b'} + # verify exponential backoff: 2^0=1s, 2^1=2s + assert mock_sleep.call_args_list == [((1,),), ((2,),)] async def test_github_cache(service: GitHubService, api: GitHub) -> None: diff --git a/test/test_cache.py b/test/test_cache.py index 5229687f7f..f15d09366b 100644 --- a/test/test_cache.py +++ b/test/test_cache.py @@ -43,27 +43,27 @@ def test_read_write(tmp_path: Path) -> None: def test_current(tmp_path: Path) -> None: - c = cache.Cache[object](f'{tmp_path}', lag=3) + c = cache.Cache[object](f'{tmp_path}', lag=1) c.write("resource2", {"value": 2}) assert c.current('resource2') is True - time.sleep(2) + time.sleep(0.6) assert c.current('resource2') is True - time.sleep(2) + time.sleep(0.6) assert c.current('resource2') is False def test_current_mark(tmp_path: Path) -> None: - c = cache.Cache[object](f'{tmp_path}', lag=3) + c = cache.Cache[object](f'{tmp_path}', lag=1) assert c.current('resource') is False c.write("resource", {"value": 1}) assert c.current('resource') is True - time.sleep(2) + time.sleep(0.5) assert c.current('resource') is True c.mark()