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

未关闭
#5,260 0 条评论 0 个 reaction 已指派 0 人 在 GitHub 查看

维护者通常 1 天内回复

还没有人认领这个 Issue。

评估

难度
4/5
预计耗时
3-5 天
新手友好度
55/100
Issue 类型
缺陷
描述清晰度
描述清楚
活跃度
活跃
技术栈
typescript

调研方向

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.

由索引模型根据 Issue 内容生成。

描述

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.

主要语言
Python
星标
662
派生
149
平均合并
6 小时 9 分钟
30 天内合并 PR
119

环境准备

  • 没有 Dockerfile 或 Docker Compose 文件
  • 没有 Pull Request 模板
  • 阅读贡献指南

从这里开始

  1. 先读完整个 Issue,再读项目的贡献指南。
  2. 在 Issue 下留言说明你要接手 —— 这能避免两个人做同样的事。
  3. Fork 仓库,在一个分支上完成修改。
  4. 提交 Pull Request,并在描述里引用这个 Issue 编号。

MarketSquare/robotframework-browser 的其他 Issue

查看 MarketSquare/robotframework-browser 的全部 Issue

相似的 Issue

更多 Python Issue

把新 issue 发到你的邮箱

精选适合新手参与的 GitHub issue 摘要。