RF suite/test context in the node logger is module-global, so log lines are attributed to the wrong worker when a node process is shared

Aperta
  • Qualcosa non va?
#5,260 0 commenti 0 reazioni 0 assegnatari Vedi su GitHub

I maintainer di solito rispondono entro 1 giorno

Nessuno ha ancora preso questa issue.

Valutazione

Difficoltà
4/5
Tempo stimato
3-5 giorni
Idoneità per principianti
55/100
Tipo di issue
Bug
Chiarezza
Specificata chiaramente
Stato di attività
Attiva
Stack tecnologico
typescript
Ambito
backend-api-design, observability

Direzione di ricerca

Start with node/playwright-wrapper/browser_logger.ts, then trace the per-peer state in node/playwright-wrapper/playwright-state.ts and the gRPC wrappers in node/playwright-wrapper/grpc-service.ts. Review the shared context and wrapper lifetimes, using the shared-node acceptance setup in tasks.py as the concurrency case. Done means concurrent sessions produce log lines with their own suite, test, and keyword context while preserving the emitted JSON shape.

Scritto dal modello di indicizzazione a partire dal testo della issue.

Descrizione

priority: medium
Describe the bug

The Robot Framework context that every node-side log line is stamped with is a module-level singleton:

const currentRFContext: RFKeywordContext = {};
const _kwContextStack: Array<{ kw_name?: string; kw_file?: string; kw_line?: number }> = [];

node/playwright-wrapper/browser_logger.ts:41-42

The pino mixin() reads it on every log call:

mixin() {
    const { kw_name, kw_file, kw_line, test_id, test_name, suite_id, suite_name } = currentRFContext;
    return {
        seq: ++_seq,
        ...(suite_id !== undefined && { suite_id }),
        ...(suite_name !== undefined && { suite_name }),
        ...

node/playwright-wrapper/browser_logger.ts:139-153

and setRFContext writes it:

export async function setRFContext(request: Request_RFContext): Promise<Response_Empty> {
    setRFTestContext(request.testId, request.testName);
    setRFSuiteContext(request.suiteId, request.suiteName);
    return emptyWithLog('RF context updated');
}

node/playwright-wrapper/playwright-state.ts:999-1003

Every other piece of state in the node process is kept per gRPC peer — PlaywrightServer holds one PlaywrightState per connection (node/playwright-wrapper/grpc-service.ts:39-57). The logging context is now the exception; the only other one, highlightDisposableCache, was made per-peer in #5211.

That matters whenever several Robot Framework processes share one node process, which is what ROBOT_FRAMEWORK_BROWSER_NODE_PORT is for. This repository's own acceptance tests do exactly that: tasks.py:1078-1081 spawns one node process and exports the port into the environment every pabot worker inherits.

With one writer per worker and one global destination, last writer wins for every worker. A log line emitted while worker A is inside a long-running call is stamped with whatever worker B most recently set, so suite_name, test_name and suite_id name a suite that has nothing to do with the line.

_kwContextStack is worse than last-writer-wins: setRFKeywordContext pushes and clearRFKeywordContext pops a single shared stack (browser_logger.ts:44-93). With concurrent workers the pairs interleave, so one worker's clearRFKeywordContext can restore another worker's saved kw_name/kw_file/kw_line, or pop a frame that was never its own.

Observed behaviour

From the artifact of run 35185010944 (Test results-windows-latest-1-3.10-22.x), playwright-log.txt:

{"level":"error","time":"2026-09-17T05:23:53.051Z","seq":63,
 "suite_id":"s1-s1-s1-s1-s1",
 "suite_name":"Test.08 Scope Tests.Suite 1.Suite 1.1.Suite 1.1.1",
 "test_name":"Test.08 Scope Tests.Suite 1.Suite 1.1.Suite 1.1.1.Test Scope Settings Override Global Defaults",
 "component":"browser-library","event_kind":"grpc_error","status":"failed","error_type":"TimeoutError2",
 "msg":"page.goto: Timeout 5000ms exceeded.\nCall log:\n  - navigating to \"http://localhost:54763/error.html\", waiting until \"load\""}

The line is attributed to Test.08 Scope Tests. It does not belong to that suite. Port 54763 is another worker's test server, and its own log (test-app/test-app-54763.log in the same artifact) says who owns it:

{"timestamp":"2026-09-17T05:23:46.976Z","event":"start_suite","name":"Auto Closing","pid":6272}

output.xml from the same run confirms it: the failure with that message is the suite setup of
Test.01 Browser Management.Auto Closing.Auto Closing, at 05:23:53.057.

So the one log line that explains the failure names the wrong suite, the wrong test, and the wrong suite id. The same applies to the surrounding newBrowser/newPage lines of that worker.

Why it matters

playwright-log.txt is the file the library points users at whenever a keyword fails:

See also file:///.../playwright-log.txt for additional details.

When a node process is shared, the suite/test fields in that file are not reliable, and there is nothing in the file to say so. Reconstructing which worker produced a line currently means cross-referencing unrelated evidence — in the case above, the context default-timeout values (5000 vs 10000 vs 1000) and the per-port test app logs.

This is an observability defect, not a behavioural one: no keyword does the wrong thing because of it. It is being filed separately because it is blocking an unrelated CI flake investigation, and because anyone running parallel Robot Framework against a shared node process is reading the same misattributed log.

Expected behaviour

A log line produced while serving one session's gRPC call carries that session's suite_id, suite_name, test_id, test_name and keyword fields, regardless of what other sessions are doing at the same time.

Suggested fix

The two halves have different lifetimes and want different mechanisms:

  • Suite/test context is durable per session. It is set by its own SetRFContext call and has to survive until the next one, so it belongs with the other per-peer state — on PlaywrightState, which grpc-service.ts already keys per peer.
  • Keyword context is per call. setRFKeywordContext/clearRFKeywordContext are a push/pop pair around a single invocation, which is what AsyncLocalStorage is for. Using a store per gRPC call removes the shared stack and its cross-worker pops.

mixin() then reads the current store rather than a module global. The gRPC wrappers in grpc-service.ts (wrapping, wrappingState, wrappingPage, wrappingStatePage, wrappingDebug) are a single choke point where the store can be established, since they already resolve the peer's state.

Nothing above changes keyword behaviour or the shape of the emitted JSON; only which worker's values appear in the fields.

Environment

Browser 20.5.0, Playwright 1.63.0, Robot Framework 7.1.1, Python 3.10.11, Windows, chromium. Observed against main at b986d017. Not platform specific — it needs only a shared node process with more than one worker.

Lingua principale
Python
Stelle
662
Fork
149
Merge medio
6h 9m
PR unite (30g)
119

Preparare l'ambiente

Come iniziare

  1. Leggi tutta la issue e poi la guida ai contributi del progetto.
  2. Commenta sulla issue per dire che te ne occupi tu — evita che due persone facciano lo stesso lavoro.
  3. Fai un fork del repository e lavora su un branch.
  4. Apri una pull request che faccia riferimento al numero della issue.

Altre issue di MarketSquare/robotframework-browser

Tutte le issue di MarketSquare/robotframework-browser

Issue simili

Altre issue su Python

Ricevi le nuove issue nella tua casella

Un breve riepilogo di issue GitHub adatte ai principianti.