Case Study: The Mystery of the Cropped Logs

I have been working as a tools developer in my company for almost 5 years now. This blog post is a summary of how I chased a recurring issue that we had, and the systems programming concepts that I learned along the way.

Chapter 1: a missing body 🧍‍♂️

A problem has haunted our internal build system for a long time: some teams had CI jobs whose logs were sometimes not fully displayed.

An example is:

[...]
$ nx run-many -t build
[...]
> nx run my-server:build
> mvn install -f path/to/my-server/pom.xml -N
[...]
<timestamp> INFO xx --- [my-server] [r-event-handler] [] kafka.cluster.Partition : [Partition part broker=0] No checkpointed highwatermark is found for partition part
<timestamp> INFO xx --- [my-server] [r-event-handler] [] kafka.cluster.Partition : [Partition part broker=0] Log loaded for partition part with initial high watermark 0
<timestamp> INFO xx --- [my-server] [r-event-handler] [] state.change.logger     : [Broker id=0] Leader part with topic id Some(mdxCjrB3Qsk3QWG52m
Uploading artifacts for failed job
00:02
Uploading artifacts...
Cleaning up project directory and file based variables

Note how the line containing state.change.logger is cropped halfway through an ID. The open parenthesis of Some( is not even closed. No more Maven lines, no Nx summary about the tasks run. Nothing.

After the Maven commands, we do see GitLab’s logs: uploading artifacts… and Cleaning up…. Therefore, it seems like the CI runner is alright, and simply reports back:

workload finished
last command executed finished with a nonzero exit code (that’s why it is a failed job)
wrap-up: uploading artifacts and cleaning up

Our engineers’ first instinct was: if the runner has not crashed, something must be wrong with the command itself. The last command was nx run-many -t build, which spawned several Maven builds. We verified this in 2 places:

Locally: we cloned the repository to a machine, and ran the same steps that CI did
In a monitored CI runner: we kept the runner in a busy loop, and kubectl exec -it <runner> -- bash into it, to execute the commands ourselves

Both attempts produced full logs, and the command exited with code 1: a (maven) build error, clear and visible. So the command was not broken. The mystery deepened: why did CI truncate the logs, but running the exact same command manually (even in the same container) did not?

As is often the case in our profession, more urgent matters took priority, so the team did not manage to explain the situation and continued developing the planned features. There was a log-killing murderer on the loose, and we could not find him… 🕵️‍♂️

Chapter 2: hide away from the murderer 😶‍🌫️

As a supporting team, we expect developers to be able to reproduce issues locally, and build before triggering CI. This is because the feedback loop is much faster (a ‘shift-left’ approach), and engineers can act on issues locally before jumping to another problem. Therefore, we suggested teams to check locally when the logs appear cropped in CI. We told ourselves: the issue happens very rarely, anyways… right? 😅

At some point, as adoption of our centralized build system grew, more and more teams reported the same issue. The size of our team was the same, and the volume of questions started to not be manageable. We realized we should act on it somehow, and took another look at all the datapoints.

Here we observed the first pattern: the issue always happened in Java/Maven projects. Our build system applies to many polyglot repos (Java/Typescript/Go/Python/Rust), but only Java/Maven had the issue. Many repositories had an annoyingly verbose build output, so we suggested people to reduce verbosity. Flags like --quiet or --no-transfer-progress reduced logs quite drastically. In some cases, devs got just a more readable build log. In many others, the issue seemed to completely disappear.

The more pragmatic engineers were happy with the decrease in support questions. Most teams didn’t report issues anymore, and the few that did reported issues so occasionally that running the build locally to identify the compilation error did not mean a great effort. However, some of us still felt uneasy with the current state. Essentially, some were saying that, as long as there are not too many dead logs, we would simply hide from the murderer? 🫣 Not all of us can rest well at night knowing what’s out there, waiting…

Chapter 3: some clues… not completely followed 👣

An unofficial investigation started. The team officially decided to move on, but some of us still couldn’t leave the mystery unsolved.

Like vigilante, I carried out experiments in parallel to my daily tasks. Since there was no time to waste, I reached out to one of the best platform engineers in my company, and also to a bright friend of mine.

3.1: What was running?

The first experiment consisted of checking what exactly is the GitLab runner running. Yes, the nx run-many command we saw, but… only that? To figure it out, my colleague recommended to jump again into the container, and see what processes were spawned and what commands were they running.

Here is where I found my first real use case of the Linux /proc directory, as well as the ps and pstree CLIs. In a GitLab pipeline, I saw the following tree of processes for any command that I declared in .gitlab-ci.yml:

└─ 24: sh -c (/scripts-xxx/detect_shell_script 
              /scripts-xxx/step_script 2>&1 
              | tee -a /log)
 └─ 25: /usr/bin/bash /scripts-xxx/step_script
  └─ 30: /usr/bin/bash /scripts-xxx/step_script
   └─ XX: nx run-many -t build // <---- or any command in .gitlab-ci.yml

Note that step_script appears twice (PIDs 25 and 30): PID 25 is the script itself, and PID 30 is a subshell it spawns internally via eval. Also note the 2>&1 in PID 24’s command: this redirects stderr into stdout before piping, meaning both stdout and stderr of the entire subtree are forwarded to tee. This becomes important later.

Gitlab was using:

a detect_shell_script that basically does exec /bin/bash $@, and
a step_script that does:

#!/usr/bin/env bash

trap exit 1 TERM

runner_script_trap() // ... some logs to show at the end

trap runner_script_trap EXIT
if set -o | grep pipefail > /dev/null; then set -o pipefail; fi;
set -o errexit
set +o noclobber
: | eval $'
// ... gitlab's startup commands
// ... here begin my commands from `.gitlab-ci.yml`
npx nx affected -t build --configuration=ci
// ... other commands I define in `.gitlab-ci.yml`
'

The : | eval $'...' idiom is worth unpacking: : is a shell no-op that produces no output. Piping it into eval means eval runs in a subshell that has pipefail semantics, so if any command in the eval’d block fails, the pipe as a whole fails. This is how GitLab ensures set -o pipefail applies to all the user’s commands.

In short: my command was not run as-is. Instead, it was being wrapped a few times:

a bash wrapper set failure if any command of a list fails, set a ‘trap’ to be executed at the end, and called : | eval '<my-commands>'
a shell parent command called the wrapper, and piped both its stdout and stderr (2>&1) to tee, which wrote to /log as well as to stdout

At this point, this did not provide any useful information for me. For someone with expertise in systems programming, and that understands better the behavior of writing to stdout, there might already be clues in this result… 🔎

3.2: Could I replicate this?

Even without understanding the problem, at this point I thought I had enough information to, at least, replicate the issue in a small repository.

For those interested, here is a snapshot of such repository at the time. The most important files it contained are:

scripts (Java and JS versions) that simulate Nx by spawning two processes (sp1 & sp2) and inheriting their I/O:
- sp1: prints many lines to a file, and then cats it to stdout, exiting with a nonzero code (simulating a failed maven task)
- sp2: exits with 0 (simulating a correct maven task)
wrapper script step_script and parent script parent_script.sh (simulating gitlab code)

3.3: What was crashing?

The second experiment that I carried out went in the direction of the OS. A command was failing, but we lost its stdout. Did it crash at runtime and we did not catch the error? What call crashed exactly?

A friend helped me to obtain the syscalls that were being requested. A very powerful tool in Linux is strace, which:

“runs the […] command […] and intercepts and records the system calls made by a process and the signals a process receives”.

The logs here were many, but in the repository replica we clearly see:

Start shell process and create: ‘pipe’, ‘node’, ‘cat’:

execve("/usr/bin/sh", ["sh", "-c", "node spawner.js 1000 | cat"] ...)
getpid() = 17418
pipe2([3, 4], 0)
[pid 17418] clone(...) = 17419
[pid 17418] clone(...) = 17420
[pid 17419] dup2(4, 1)
[pid 17420] dup2(3, 0)
[pid 17419] ioctl(1, FIONBIO, [1])

Start node process, which triggers ‘sp1’ & ‘sp2’:

[pid 17419] execve(... ["node", "spawner.js", "1000"] ...)
[pid 17419] clone(...) = 17427
[pid 17427] write(1, "Printing 999 [INFO] Downloading "..., 196) = 196
[pid 17427] clone(...) = 17432
[pid 17432] execve(... ["cat", "print_log.txt"] ...)
[pid 17432] read(3, "Printing 1 [INFO] Downloading"..., 131072) = 131072
[pid 17432] write(1, "1.6.RELEASE.pom\nPrinting 336"..., 65536) = 65536

Ping-pong of writes from producer (17432) and reads by consumer (17420):

[pid 17420] read(0, "1.6.RELEASE.pom\nPrinting 336"..., 131072) = 65536
[pid 17432] read(3, "://xyz-platform.maven.pkg.myc"..., 131072) = 64821
[pid 17432] write(1, "://xyz-platform.maven.pkg.myc"..., 64821) = -1 \
            EAGAIN (Resource currently unavailable)
[pid 17432] write(2, "Write error" ...)
[pid 17432] close(4) = 0
[pid 17419] write(2, "Spawner error: some child proces"..., ) = 63
[pid 17427] exit_group(62)
[pid 17420] read(0, "1.6.RELEASE.pom\nPrinting 336"..., 131072) = 65536
[pid 17419] exit_group(12)

This allowed us to have a first idea of what was happening, and draw a process tree of the command node spawner.js 1000 | cat:

17418  sh
├── declares pipe
│   ├── fd 3 → read end
│   └── fd 4 → write end
│
├── 17419  node spawner.js 1000
│   ├── stdout (fd 1) ──dup2(4,1)──► pipe write end (fd 4)
│   │
│   └── 17427  sh sp1.sh
│       └── 17432  cat        (producer)
│           └── stdout ──────────────────────► inherited pipe write end
│
└── 17420  cat                   (consumer)
    └── stdin (fd 0) ──dup2(3,0)─────────────► pipe read end (fd 3)

In this scenario, there is a data producer (17419: spawner.js, through its grandchild 17432), and a data consumer (17420: cat), connected by a kernel pipe, which buffers data allowing inter-process communication.

Important lines are:

[pid 17419] ioctl(1, FIONBIO, [1])

and:

[pid 17432] write(1, "://xyz-platform.maven.pkg.myc"..., 64821) = -1 \
            EAGAIN (Resource currently unavailable)
[pid 17432] write(2, "Write error" ...)
[pid 17432] close(4) = 0

which tell the full story of the failure: Node.js sets the pipe’s write end to non-blocking mode (O_NONBLOCK, exposed here via the FIONBIO ioctl, which is equivalent). The producer (cat, PID 17432) then tries to write 64821 bytes to the pipe, but the pipe’s kernel buffer is full and — because the fd is non-blocking — the write returns immediately with EAGAIN (“try again later”) instead of blocking. Rather than retrying, the producer writes an error to stderr and calls close(4), closing the write end of the pipe. Closing the write end signals EOF to the consumer (PID 17420): it sees no more writers on the pipe and stops reading. Any data that was still buffered in the producer and never written is permanently lost.

At this point, we thought we had identified the main suspect. The reproduction script led to a very compelling theory (Hypothesis A):

Node.js was natively setting the pipe’s write end as non-blocking (O_NONBLOCK / FIONBIO), and
When the pipe buffer filled up, child writers (like cat in our experiment, or potentially build tools spawned by Nx) received EAGAIN and closed prematurely instead of retrying the write.

It seemed like a solid explanation. However, once again, daily priorities took over. A colleague suggested the unbuffer command as a quick fix to wrap Node.js, in case the issue was a buffer (the pipe) filling up. The idea was to shim node and execute all node commands like this:

exec unbuffer $(which node) <args>

A few experiments showed promising results, so we rolled forward with this approach without properly concluding the investigation…

Chapter 4: the murderer strikes back 💀

As our standardisation efforts proceeded, we started to roll out a one-size-fits-all pipeline for all development projects in the company.

We started by eating our own dog food, and wrapped our own node commands with unbuffer. When working with a new version of npm, the following happened:

> nx run @my-company/nx-plugin-devkit:nx-release-publish
Something unexpected went wrong when checking for existing dist-tags.
Error: Command failed: 
npm view @my-company/nx-plugin-devkit versions dist-tags --json \
  --"@my-company:registry=npm warn Unknown env config \
  "manage-package-manager-versions". This will stop working in the \
  next major version of npm [...]
npm warn Unknown project config "strict-peer-dependencies" [...]
npm warn Unknown project config "auto-install-peers" [...]
https://npm-registry.mycompany.com"
npm error code ERR_INVALID_URL
npm error Invalid URL

Here we were again, with an unexpected issue. Note how the npm view command starts and gets flags --json and --"@my-company:registry=, which ends with https://npm-registry.mycompany.com" a few lines later. Seems like there are lines from several streams merged into one place…

Chapter 5: blood stains… leading somewhere 🩸

5.1: An autopsy

Now this issue was on our CI, so I had to act rapidly to unblock the team.

<aside>: where do CLIs write?

We’ve all heard of stdio, composed of stdin, stdout and stderr. These are standard streams provided by POSIX systems when a program starts. The consumer(s) of the output can be any, but the interface to write is always the same. CLIs are free to write anywhere, but there are some conventions:

stdout is the stream to write output data
stderr is the stream to write error messages or diagnostics
flags like --json, -o yaml or --porcelain ensure output data has a well-known format to be consumed by other programs

Q: Ok, so CLIs (and any other program) write to streams, and then? How does that data reach a meaningful consumer?

A: Whoever starts the program (usually a shell spawns a CLI, but can be a parent process) decides what to connect the streams to. It could be one of many kernel objects that implement read/write operations, such as a terminal (tty/pty), a pipe, a file, a socket, other devices (under /dev), etc.

</aside>

Digging deeper, I found out that unbuffer attaches a PTY (pseudo-terminal, one of those kernel objects mentioned above) to stdout and stderr. Many programs change their behavior based on the condition isatty(stdout), for example using line-buffering or interactive behavior if true. This is why unbuffer is suggested online if there are buffering issues.

Because ttys/ptys model physical terminals (devices with one screen), a PTY slave endpoint provides a single combined I/O channel. Our unbuffer node shim attached a PTY to both stdout and stderr, multiplexing both streams into one. This meant that calling newer versions of npm (which printed warnings to stderr like npm warn Unknown project config ...) resulted in stderr warnings being interleaved directly into the JSON data stream on stdout, breaking the parser in nx-release-publish!

5.2: Following the breadcrumbs

This was a step back in my investigation, but not all the time had been wasted. At this time, I had more knowledge to understand the problem better.

Why did unbuffer mask our initial log-cropping issue in the first place? Because by attaching a PTY, it forced Node.js to use synchronous, blocking I/O on stdout.

This made me re-examine Hypothesis A. While our synthetic experiment showed cat failing on EAGAIN when writing to a non-blocking pipe, was that really why production CI logs were getting cut short?

Looking again at Node.js documentation for non-blocking stdio and process exit:

Pipes (and sockets) are asynchronous on POSIX

Diving deeper into Node.js’ docs, we can see the following notes:

Calling process.exit() will force the process to exit as quickly as possible even if there are still asynchronous operations pending that have not yet completed fully, including I/O operations to process.stdout and process.stderr. Once write() returns false, do not write more chunks until the ‘drain’ event is emitted. The ‘close’ event is emitted after a process has ended and the stdio streams of a child process have been closed. […] When the ‘exit’ event is triggered, child process stdio streams might still be open.

A new theory emerged (Hypothesis B): the real problem wasn’t necessarily that child processes failed to write to a non-blocking pipe. The problem was that the parent process (Nx) was exiting prematurely, cutting off data streams before Node.js could finish reading or flushing the remaining output buffered in the OS pipe!

It had to be related to this. At this point, I started thinking the culprit could NOT be one of the bystanders:

cat, tee, other unix tools: they were reading and writing data from/to streams, like they always do
GitLab: was executing Nx in a probably unexpected, but perfectly valid way, by piping it to tee
libuv: was indeed setting O_NONBLOCK to the pipe, but it is designed for that, and all JS code running in node should have ended up using libuv to read/write, and the library would have managed it
Node.js: did not show signs of too high memory usage, or internal buffers overflowing

and had to be instead in Nx, the task orchestrator…

Chapter 6: unmask the villain! 🦹

This took me to the Nx code (~850K lines of RS/TS codebase), with three questions in mind:

Where is the core reading the outputs of the tasks it spawns?
Where is the core writing to its stdout?
Where is the core deciding to exit?

The answer turned out to be more complex than expected, and also partially solved. Nx considers many variables to set its context (isTTY, isCI, isTui, isBatch,…) and execution of tasks varies depending on them.

Dedicated classes in Nx own the processes they spawn. Examples are RunningNodeProcess and NodeChildProcessWithNonDirectOutput. At some point in the code, they both did some sorts of:

this.cp = spawn(command);
// manage data
this.cp.stdout.on('data', storeDataChunks);
// manage exit and return all data to orchestrator
this.cp.on('exit', (code, signal) => {
  this.exitCode = code;
  const data = this.joinDataChunks();
  this.callbacks.forEach(cb => cb(data));
});

and the Nx CLI did:

const status = await runCommand();
process.exit(status);

Here we see two distinct flaws leading to data loss:

Child process manager level: listening on 'exit' instead of 'close' meant the task runner collected accumulated output and moved on before the child process’ stdio streams finished emitting all pending 'data' events.
Orchestrator level: calling process.exit(status) immediately after task completion abruptly killed the main Node.js process while asynchronous log writes to stdout were still buffered in memory.

Our log killer was identified!

6.1: Existing police reports

This issue has haunted us on-and-off for at least 2 years (we have tickets mentioning it in August 2024). Surprisingly, GitHub issues and solutions only started showing up a few months ago (likely as non-interactive CI execution patterns became more widely adopted at scale):

Nx core listens on ‘exit’ instead of ‘close’, and joins terminal output of executor before flushing all ‘data’ received: PR #35422 fixed it in April 2026.
Nx core calls process.exit before flushing logs: PR #36607 fixed it in August 2026.

6.2: A missing piece

I still found one of the execution flows to make the same mistake: RunningNodeProcess still calls .on('exit') instead of .on('close'), so very verbose logs are still at risk of being lost. I have reported it in issue #36863, and maintainers are discussing a redesign.

As of today (September 2026), there are still open conversations (see PR #36580) about properly flushing remaining data in buffers before exiting the task orchestrator.

6.3: Another workaround

Our current CI wraps the Nx commands with script -qec, creating a PTY only around the main Node.js process. Because stdout is attached to a TTY, Node.js performs synchronous writes to stdout (as noted in Node.js’ docs), and the pipe remains synchronous during the whole build execution. This has shown good results so far. This is doing something equivalent to what #36607 fixes: writes from the core are synchronous, so by the time Nx reaches process.exit, all the logs have been written out. It does not solve the other open issues, but now the maintainers are aware of the nuances of this issue, and I am positive a future Nx release will contain all related fixes.

Lessons Learned

Programs don’t run in isolation. If they exist, they serve a purpose, so they have to communicate with the outside world. Part of their job is their core task (ends up affecting filesystem, making network calls, etc.), and part of it might be logging their process (like this case).
When writing somewhere, sync vs async is a big topic, and the return value of a write call is crucial, as it might indicate a failure when writing (and the need of a retry if we want to ensure all data goes through). Specifically in Node.js, we must know that process.exit is quite aggressive and will not wait for pending I/O to flush before terminating the process.
Always listen on 'close' rather than 'exit' when processing child process stdio streams. The 'exit' event fires as soon as the process terminates, but stdio streams may still have unread chunks in OS kernel buffers. Listening on 'close' guarantees all stdio data has been emitted.
The “where” we write is taken care of by the OS. We can have different elements consuming this data, such as:

pipes
terminals
sockets
files
…

Reading

Someone else was losing logs in Node.js (blogpost)
For a newbie, it is easy to get confused and simply attempt to make everything synchronous, by doing a quick search and finding recommendations such as stdbuf or unbuffer. These tools are great, but we must understand what they do in detail to be able to evaluate their trade-offs.

Thank you

To Alejandro Nadal, Tomas Satka and Stefan Peer for providing me with very valuable tools for a software engineer
To João Ferreira for reviewing and always being a helping hand