Aggregate output of append-only reporter

[ibezkrovnyi]

Currently on CI when any recursive command (pnpm -r --filter=xxx build) is run, and --workspace-concurrency is not equal to 1, --stream is added by default.

So, output in CI logs is as follows:

packages/a build$ pnpm build
packages/b build$ pnpm build
packages/c build$ pnpm build
packages/a build: log1 from 'build' command for package/a
packages/b build: log1 from 'build' command for package/b
packages/c build: log1 from 'build' command for package/c
... 40,000 lines more with logs mixed randomly from all 3 packages
packages/a build: log2 from 'build' command for package/a

It is very hard to understand what is going on in the logs, especially if at some steps we have thousands of lines of logs per each command, mixed together with logs from all other logs run in parallel.

Often at some line e.g. 27350 somewhere ERROR or WARN is logged, and then it is a bit painful to log back through a mixed logs to find what is going wrong.

• Where I never seen this issue: pnpm i --filter=xxx
• Where I see this issue every day: when I run Jest, Cypress, linting tools or prettier with pnpm --filter=xxx jest

It would be great to have logs output aggregated per command on CIs (at least as an option).

Some real-world examples are:

• npm-run-all --aggregate-output
• concurrently
• Microsoft Rush - stream collator (works in a slightly different way - chooses active stream, aggregates output from other streams meanwhile)

Having --aggregate-output option would be super helpful for us. At this moment to be able to read the logs we have to set --workspace-concurrency=1 in .npmrc which kills performance and just doesn't use all the potential of pnpm.

Related pull request:

• feat: aggregate-output #4109

[zkochan]

Sounds good

[ibezkrovnyi]

Tested [email protected] on 20 projects run in parallel for different tasks (jest / prettier + linting / webpack) - aggregate-output: true is fantastic on CI.

[zkochan]

what happens if one of the tasks hangs? The CI job will kill the process and it will be really hard to find out which task was hanging.

[ibezkrovnyi]

I think yes, if CI job is killed, all aggregated logs are lost. For aggregate-output we could add optional writing to .pnpm-debug.log or ndjson. Another way is try to exit gracefully (tried that on windows - I can install handlers for manually closing window with mouse and for CTRL+C, but not for killing task from task manager).

I wouldn't enable writing to .pnpm-debug.log by default. For last 5 years as I recall we had only a few cases when job on CI stuck - in all 2 cases the reason was jest, and there were no logs to indicate the reason, and now jest has options to exit even if some async task is not finished.

[ibezkrovnyi]

Option 1

pnpm --aggregate-output --write-logs-to-file-immediately

Condition can be added to https://github.com/pnpm/pnpm/blob/main/packages/file-reporter/src/index.ts#L11 to check if write-logs-to-file-immediately is enabled or not and write to log file immediately.

Option 2

process.on('exit', ...) is already handled

pnpm/packages/file-reporter/src/index.ts

Line 15 in 6058f76

process.on('exit', (code: number) => {

--aggregate-output option can install handlers for [SIGINT, SIGTERM, SIGKILL, SIGBREAK, SIGHUP and exit] and flush buffers if any of these events get fired.

My investigation:

• OS: Windows 10
• Node: 16.13.0

Event	process.on signals fired	Details
taskkill /T /IM node.exe OR terminal is clsoed by clicking 'cross' button	SIGHUP	calling process.exit manually is required, otherwise after 5 seconds windows will forcefully kill task, node will fire beforeExit and exit events with 0 as first argument
taskkill /T /F /IM node.exe	CAN'T BE CATCHED
CTRL+C	SIGINT	calling process.exit manually is required, otherwise task continues to live
CTRL+BREAK	SIGBREAK	calling process.exit manually is required, otherwise task continues to live
Windows Log-off	CAN'T BE CATCHED
Windows Shutdown	CAN'T BE CATCHED

For SIG* handlers first argument is signal name (e.g. SIGINT)

beforeExit handler is called on natural exit or after 5 seconds on catching SIGHUP, SIGINT or SIGBREAK in case there is no leading process.exit call (with first argument being 0)

For beforeExit and exit handlers to be called handler to relevant signal (SIGHUP, SIGINT or SIGBREAK) need to be installed (process.on('SIGINT', ...))

So, on Windows CI environment it depends on the Windows API used by CI to stop hanging processes. If it is not forcefull kill pnpm can catch such event and gracefully exit (with flushing log buffers and printing message about being killed)

Option 3

Another option is to have optional flush log buffers timer (.npmrc -> --aggregate-output-timeout) that can be configured with value that is 1 minute less than CI job timeout.

IMHO

For such case I would recommend in my team to temporary disable --aggregated output to find hanging process, and reenable --aggregated-output after that. If hanging process case is absolutely needed to be resolved on pnpm side - I would go with "Option 1".

//cc @zkochan please let me know your thoughts on this

[zkochan]

For such case I would recommend in my team to temporary disable --aggregated output to find hanging process,

I am fine with this solution for now. If someone will need something more sophisticated, we can come back to it.