Skip to content

Commit 447cb45

Browse files
andystaplesCopilot
andauthored
Fix Azure Functions E2E log framing and host isolation (#332)
* Fix Functions E2E host log record framing Split concatenated timestamped records before returning matched host output, preserving strict logging assertions. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> * Isolate Functions E2E sample hosts by task hub Give each FunctionApp its own stable task hub instead of sharing the Nox session hub, and verify rewind starts from the intended activity failure. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --------- Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com>
1 parent 6684cba commit 447cb45

5 files changed

Lines changed: 103 additions & 8 deletions

File tree

‎noxfile.py‎

Lines changed: 0 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -509,9 +509,6 @@ def functions_e2e(session: nox.Session) -> None:
509509
),
510510
)
511511
try:
512-
session.env[
513-
"AzureFunctionsJobHost__extensions__durableTask__hubName"
514-
] = _new_test_namespace("nox")
515512
session.env["E2E_PAYLOAD_CONTAINER"] = _new_test_namespace("payloads")
516513
session.install("-r", "requirements.txt")
517514
_install_packages(session, editable=True)

‎tests/azure-functions-durable/e2e/_harness.py‎

Lines changed: 16 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -16,6 +16,7 @@
1616

1717
import json
1818
import os
19+
import re
1920
import shutil
2021
import signal
2122
import socket
@@ -259,7 +260,8 @@ class FunctionApp:
259260
260261
Use as a context manager. On entry it starts the host and blocks until the
261262
app's ``/api/ping`` route responds; on exit it terminates the whole process
262-
group and surfaces the captured host log if startup failed.
263+
group and surfaces the captured host log if startup failed. Each instance
264+
uses a unique task hub so sample hosts cannot consume each other's work.
263265
"""
264266

265267
# ``func start`` binds the HTTP port itself, some time after we pick a free
@@ -274,6 +276,7 @@ def __init__(self, app_name: str, port: Optional[int] = None):
274276
raise FileNotFoundError(f"Sample app not found: {self.app_dir}")
275277
self.port = port or find_free_port()
276278
self.base_url = f"http://127.0.0.1:{self.port}"
279+
self._task_hub_name = f"e2e{uuid.uuid4().hex}"
277280
self._process: Optional[subprocess.Popen[str]] = None
278281
self._log_path = self.app_dir / "_func_host.log"
279282

@@ -331,6 +334,7 @@ def start(self) -> None:
331334

332335
def _build_env(self) -> dict[str, str]:
333336
env = os.environ.copy()
337+
env["AzureFunctionsJobHost__extensions__durableTask__hubName"] = self._task_hub_name
334338
# Start the host exactly as a developer would after activating the
335339
# app's OWN virtual environment (``<app>/.venv``). The environment MUST
336340
# live inside the app directory: the Functions Python worker only
@@ -416,7 +420,7 @@ def read_host_log(self) -> str:
416420
return self._read_log()
417421

418422
def wait_for_host_log(self, text: str, timeout: float = 30) -> str:
419-
"""Wait until captured Functions host output contains ``text``."""
423+
"""Wait for ``text`` and return its host record, not its physical line."""
420424
deadline = time.time() + timeout
421425
log = self._read_log()
422426
while text not in log and time.time() < deadline:
@@ -426,7 +430,16 @@ def wait_for_host_log(self, text: str, timeout: float = 30) -> str:
426430
raise TimeoutError(
427431
f"Functions host log did not contain {text!r} within {timeout}s.\n"
428432
f"{log}")
429-
return next(line for line in log.splitlines() if text in line)
433+
# Host stdout/stderr can concatenate timestamped records without a newline.
434+
return next(
435+
record
436+
for line in log.splitlines()
437+
for record in re.split(
438+
r"(?=\[\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(?:\.\d+)?Z\] )",
439+
line,
440+
)
441+
if text in record
442+
)
430443

431444
def stop(self) -> None:
432445
proc = self._process
Lines changed: 28 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,28 @@
1+
# Copyright (c) Microsoft Corporation.
2+
# Licensed under the MIT License.
3+
4+
import os
5+
import re
6+
7+
import pytest
8+
9+
from ._harness import FunctionApp
10+
11+
12+
def test_sample_hosts_use_independent_task_hubs(monkeypatch: pytest.MonkeyPatch) -> None:
13+
setting = "AzureFunctionsJobHost__extensions__durableTask__hubName"
14+
monkeypatch.setenv(setting, "sharedhub")
15+
apps = [FunctionApp(name) for name in (
16+
"v1_style", "dtask_style", "tracing", "v1_style")]
17+
environments = [
18+
app._build_env() # pyright: ignore[reportPrivateUsage]
19+
for app in apps
20+
]
21+
task_hubs = [env[setting] for env in environments]
22+
23+
assert len(set(task_hubs)) == len(apps)
24+
assert all(re.fullmatch(r"[A-Za-z][A-Za-z0-9]{2,49}", hub) for hub in task_hubs)
25+
assert "sharedhub" not in task_hubs
26+
assert os.environ[setting] == "sharedhub"
27+
for app, env in zip(apps, environments):
28+
assert app._build_env()[setting] == env[setting] # pyright: ignore[reportPrivateUsage]
Lines changed: 57 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,57 @@
1+
# Copyright (c) Microsoft Corporation.
2+
# Licensed under the MIT License.
3+
4+
from pathlib import Path
5+
6+
import pytest
7+
8+
from ._harness import FunctionApp
9+
10+
11+
@pytest.mark.parametrize("message", [
12+
"Starting new 'activity_chain' instance with ID = 'test-instance'.",
13+
"test-instance: Orchestration activity_chain completed with status: COMPLETED",
14+
])
15+
@pytest.mark.parametrize(("before", "after"), [
16+
("", ""),
17+
("", "[2026-11-02T19:42:58.870Z] Request GET http://127.0.0.1:10002/"),
18+
("[2026-11-02T19:42:58.869Z] Previous record", ""),
19+
("[2026-11-02T19:42:58.869Z] Previous record",
20+
"[2026-11-02T19:42:58.871Z] Next record"),
21+
("[2026-11-02T19:42:58Z] Previous record",
22+
"[2026-11-02T19:42:58.8701234Z] Next record"),
23+
("[2026-11-02T19:42:58.869Z] Previous record\n",
24+
"\n[2026-11-02T19:42:58.871Z] Next record"),
25+
("[2026-11-02T19:42:58.869Z] Previous record\r\n",
26+
"\r\n[2026-11-02T19:42:58.871Z] Next record"),
27+
])
28+
def test_wait_for_host_log_extracts_timestamped_record(
29+
tmp_path: Path, monkeypatch: pytest.MonkeyPatch,
30+
message: str, before: str, after: str) -> None:
31+
app = FunctionApp("dtask_style")
32+
log_path = tmp_path / "host.log"
33+
monkeypatch.setattr(app, "_log_path", log_path)
34+
expected = f"[2026-11-02T19:42:58.870Z] {message}"
35+
log_path.write_text(before + expected + after, encoding="utf-8")
36+
37+
record = app.wait_for_host_log(message, timeout=0)
38+
39+
assert record == expected
40+
41+
42+
@pytest.mark.parametrize("output", [
43+
"SDK message",
44+
"[2026-11-02T19:42:58.870Z]\nSDK message",
45+
"[2026-11-02T19:42:58.870Z] Unrelated record SDK message",
46+
"[2026-11-02T19:42:58.870Z] SDK message unexpected suffix",
47+
])
48+
def test_wait_for_host_log_preserves_nonmatching_records(
49+
tmp_path: Path, monkeypatch: pytest.MonkeyPatch, output: str) -> None:
50+
app = FunctionApp("dtask_style")
51+
log_path = tmp_path / "host.log"
52+
monkeypatch.setattr(app, "_log_path", log_path)
53+
log_path.write_text(output, encoding="utf-8")
54+
55+
record = app.wait_for_host_log("SDK message", timeout=0)
56+
57+
assert record == output.splitlines()[-1]

‎tests/azure-functions-durable/e2e/test_v1_client_e2e.py‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -6,8 +6,7 @@
66
Covers ``suspend``/``resume``, ``restart``, ``get_status_all``,
77
``get_status_by``, ``purge_instance_history_by``,
88
``create_http_management_payload`` / ``get_client_response_links``,
9-
``wait_for_completion_or_create_check_status_response``, and the ``rewind``
10-
NotImplementedError stub.
9+
``wait_for_completion_or_create_check_status_response``, and ``rewind``.
1110
"""
1211

1312
from datetime import datetime, timedelta, timezone
@@ -110,6 +109,7 @@ def test_rewind(v1_app):
110109
instance_id = v1_app.start_orchestration("rewind_target")
111110
failed = v1_app.wait_for_completion(instance_id)
112111
assert failed["runtimeStatus"] == "Failed"
112+
assert "failing on first attempt (rewind to retry)" in failed["output"]
113113

114114
result = http_request("POST", f"{v1_app.base_url}/api/rewind/{instance_id}")
115115
assert result.status == 202

0 commit comments

Comments
 (0)