[Bug]: Fixture "trace recording" timeout of 150000ms exceeded during setup (docker)

[slaven13]

Version

1.56.1

Steps to reproduce

I am running my suite that has some really long tests whose timeout is set to more than the time specified in playwright.config.ts

timeout: 2.5 * 60 * 1000,

When running very long test, the timeout is overwritten with test.setTimeout(5 min). Our system has videos on the page and when waiting for particular API condition to happen, the video might be in auto play. In any case, this only happens in docker to which I have tried increasing the CPU, memory, shared memory. Running these tests outside the docker doesn't display any errors. Running on GH runners, no issues at all.

We are using Chrome latest version 142.

Has anyone seen any similar issues?

Expected behavior

The trace recording timeout should be equal to the test timeout set with test.setTimeout.

Actual behavior

The trace recording fails with error Fixture "trace recording" timeout of 150000ms exceeded during setup.

Additional context

docker-compose.yaml service configuration

  playwright:
    platform: linux/amd64
    init: true
    ipc: host
    deploy:
      resources:
        limits:
          memory: 10G
          cpus: "4.0"
    shm_size: 4gb # Important for Chrome in Docker

Environment

System
MacBook Apple M4 Pro - Sequoia
Running Docker 3.8

Binaries
node 22.1

npmPackages
@playwright/test: 1.56.1
Chrome 142.0.7444.135

[Skn0tt]

If the Fixture setup for "trace recording" times out, then test.setTimeout hasn't been executed yet, so it doesn't take effect. It's unlikely you're running into a cpu/memory problem. Here's where the fixture is defined, there's only a single call in there that takes a while:

playwright/packages/playwright/src/index.ts

Lines 249 to 331 in 25958de

	// This fixture has a separate zero-timeout slot to ensure that artifact collection
	// happens even after some fixtures or hooks time out.
	// Now that default test timeout is known, we can replace zero with an actual value.
	testInfo.setTimeout(testInfo.project.timeout);
	const artifactsRecorder = new ArtifactsRecorder(playwright, tracing().artifactsDir(), screenshot);
	await artifactsRecorder.willStartTest(testInfo as TestInfoImpl);
	const tracingGroupSteps: TestStepInternal[] = [];
	const csiListener: ClientInstrumentationListener = {
	onApiCallBegin: (data, channel) => {
	const testInfo = currentTestInfo();
	// Some special calls do not get into steps.
	if (!testInfo || data.apiName.includes('setTestIdAttribute') || data.apiName === 'tracing.groupEnd')
	return;
	const zone = currentZone().data<TestStepInternal>('stepZone');
	const isExpectCall = data.apiName === 'locator._expect' || data.apiName === 'frame._expect' || data.apiName === 'page._expectScreenshot';
	if (zone && zone.category === 'expect' && isExpectCall) {
	// Display the internal locator._expect call under the name of the enclosing expect call,
	// and connect it to the existing expect step.
	if (zone.apiName)
	data.apiName = zone.apiName;
	if (zone.title)
	data.title = zone.title;
	data.stepId = zone.stepId;
	return;
	}
	// In the general case, create a step for each api call and connect them through the stepId.
	const step = testInfo._addStep({
	location: data.frames[0],
	category: 'pw:api',
	title: renderTitle(channel.type, channel.method, channel.params, data.title),
	apiName: data.apiName,
	params: channel.params,
	group: getActionGroup({ type: channel.type, method: channel.method }),
	}, tracingGroupSteps[tracingGroupSteps.length - 1]);
	data.userData = step;
	data.stepId = step.stepId;
	if (data.apiName === 'tracing.group')
	tracingGroupSteps.push(step);
	},
	onApiCallEnd: data => {
	// "tracing.group" step will end later, when "tracing.groupEnd" finishes.
	if (data.apiName === 'tracing.group')
	return;
	if (data.apiName === 'tracing.groupEnd') {
	const step = tracingGroupSteps.pop();
	step?.complete({ error: data.error });
	return;
	}
	const step = data.userData;
	step?.complete({ error: data.error });
	},
	onWillPause: ({ keepTestTimeout }) => {
	if (!keepTestTimeout)
	currentTestInfo()?._setDebugMode();
	},
	runAfterCreateBrowserContext: async (context: BrowserContextImpl) => {
	await artifactsRecorder?.didCreateBrowserContext(context);
	const testInfo = currentTestInfo();
	if (testInfo)
	attachConnectedHeaderIfNeeded(testInfo, context.browser());
	},
	runAfterCreateRequestContext: async (context: APIRequestContextImpl) => {
	await artifactsRecorder?.didCreateRequestContext(context);
	},
	runBeforeCloseBrowserContext: async (context: BrowserContextImpl) => {
	await artifactsRecorder?.willCloseBrowserContext(context);
	},
	runBeforeCloseRequestContext: async (context: APIRequestContextImpl) => {
	await artifactsRecorder?.willCloseRequestContext(context);
	},
	};
	const clientInstrumentation = playwright._instrumentation;
	clientInstrumentation.addListener(csiListener);
	await use();
	clientInstrumentation.removeListener(csiListener);
	await artifactsRecorder.didFinishTest();

Maybe that helps you debug things. If you can provide me with a minimal reproduction repository, I can also take a look.

[slaven13]

If the Fixture setup for "trace recording" times out, then test.setTimeout hasn't been executed yet, so it doesn't take effect. It's unlikely you're running into a cpu/memory problem. Here's where the fixture is defined, there's only a single call in there that takes a while:

playwright/packages/playwright/src/index.ts

Lines 249 to 331 in 25958de

// This fixture has a separate zero-timeout slot to ensure that artifact collection
// happens even after some fixtures or hooks time out.
// Now that default test timeout is known, we can replace zero with an actual value.
testInfo.setTimeout(testInfo.project.timeout);

const artifactsRecorder = new ArtifactsRecorder(playwright, tracing().artifactsDir(), screenshot);
await artifactsRecorder.willStartTest(testInfo as TestInfoImpl);

const tracingGroupSteps: TestStepInternal[] = [];
const csiListener: ClientInstrumentationListener = {
onApiCallBegin: (data, channel) => {
const testInfo = currentTestInfo();
// Some special calls do not get into steps.
if (!testInfo || data.apiName.includes('setTestIdAttribute') || data.apiName === 'tracing.groupEnd')
return;
const zone = currentZone().data('stepZone');
const isExpectCall = data.apiName === 'locator._expect' || data.apiName === 'frame._expect' || data.apiName === 'page._expectScreenshot';
if (zone && zone.category === 'expect' && isExpectCall) {
// Display the internal locator._expect call under the name of the enclosing expect call,
// and connect it to the existing expect step.
if (zone.apiName)
data.apiName = zone.apiName;
if (zone.title)
data.title = zone.title;
data.stepId = zone.stepId;
return;
}

 // In the general case, create a step for each api call and connect them through the stepId. 
 const step = testInfo._addStep({ 
   location: data.frames[0], 
   category: 'pw:api', 
   title: renderTitle(channel.type, channel.method, channel.params, data.title), 
   apiName: data.apiName, 
   params: channel.params, 
   group: getActionGroup({ type: channel.type, method: channel.method }), 
 }, tracingGroupSteps[tracingGroupSteps.length - 1]); 
 data.userData = step; 
 data.stepId = step.stepId; 
 if (data.apiName === 'tracing.group') 
   tracingGroupSteps.push(step); 

},
onApiCallEnd: data => {

 // "tracing.group" step will end later, when "tracing.groupEnd" finishes. 
 if (data.apiName === 'tracing.group') 
   return; 
 if (data.apiName === 'tracing.groupEnd') { 
   const step = tracingGroupSteps.pop(); 
   step?.complete({ error: data.error }); 
   return; 
 } 
 const step = data.userData; 
 step?.complete({ error: data.error }); 

},
onWillPause: ({ keepTestTimeout }) => {
if (!keepTestTimeout)
currentTestInfo()?._setDebugMode();
},
runAfterCreateBrowserContext: async (context: BrowserContextImpl) => {
await artifactsRecorder?.didCreateBrowserContext(context);
const testInfo = currentTestInfo();
if (testInfo)
attachConnectedHeaderIfNeeded(testInfo, context.browser());
},
runAfterCreateRequestContext: async (context: APIRequestContextImpl) => {
await artifactsRecorder?.didCreateRequestContext(context);
},
runBeforeCloseBrowserContext: async (context: BrowserContextImpl) => {
await artifactsRecorder?.willCloseBrowserContext(context);
},
runBeforeCloseRequestContext: async (context: APIRequestContextImpl) => {
await artifactsRecorder?.willCloseRequestContext(context);
},
};

const clientInstrumentation = playwright._instrumentation;
clientInstrumentation.addListener(csiListener);

await use();

clientInstrumentation.removeListener(csiListener);
await artifactsRecorder.didFinishTest();
Maybe that helps you debug things. If you can provide me with a minimal reproduction repository, I can also take a look.

Thanks for the reply. You are right, this probably happens in Before Hooks. I am running tests in parallel (4 workers):

The tests that failed before this one that fails with this trace recording error has properly recorded the trace. But the next 3 tests have ran out of time.

[Skn0tt]

Might be a bug in Playwright. Provide me with a reproduction case and i'll take a look.

[slaven13]

It would be really hard to create a reproduction case for you, but I will explain the setup we have:

• We have PW tests in a suite of 20 tests
• We have a dockerized environment with PW 1.56.1 and Chrome 142.
• The system under test is quite "complex" in the scenarios that we are testing as there are 3rd party systems that we handle via APIs to produce particular states of our users and their memberships (payments, subscriptions, etc.)
• We have pages where we test video playback (thus Chrome and not Chromium)
• We are running the tests with 4 workers in parallel
• In this particular failure, the tests start to fail "at the end", meaning that at one point one of the parallel executions fails for whatever reason (let's say some flaky behaviour)
• Aftert that, we have really long tests that can take more than 5 mins, during which we poll for particular APIs (3rd party). All that is recorded as trace in UI mode
• At some point the subsequent tests start to fail with this error I have sent the screenshot

It sounds as if the previous failure impacted the fixture for the subsequent tests and trace record times out.

I would gladly jump on a call with you and show you on my local machine what is going on, but unfortunately I am not able to create a repo with reproducible steps.

And this only happens inside docker. Running locally or on GH runners, no issues. I make the Docker work better when I set to record trace only on first retry, but that's not the point here.

[Skn0tt]

Sure, let's try that. Shoot me an email at firstnamelastname@microsoft.com and let's find time to look at it in a call next week.

[ipeneva]

@Skn0tt I'm also experiencing randomly the same failure. It happens for both simple and complex cases.
What I noticed is that the start date of the problem matches with the date when chrome 142 was released.

Let me know if any logs from my github actions workflow could be useful for you.

[ipeneva]

@Skn0tt I'm also experiencing randomly the same failure. It happens for both simple and complex cases. What I noticed is that the start date of the problem matches with the date when chrome 142 was released.

Let me know if any logs from my github actions workflow could be useful for you.

Just one clarification. My issue happens in the afterEach() step, the error is:

Tearing down "context" exceeded the test timeout of 180000ms.

But to me it looks quite similar to this problem

[Skn0tt]

I'm happy to take a look if you can provide me with a reproduction case.