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 blogpost is a summary of how I chased a recurrent 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 thought: if the runner has not crashed, then something must be wrong with the command being run. The last command was nx run-many -t build, which spawned several maven builds. The check for this crash was easy, and we could perform it in 2 places:

1. Locally: we cloned the repository to a machine, and ran the same steps that CI did
2. 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 commands led to the same result: the logs were completely shown, and the command finished indeed with an exit code of 1. There was a (javac) compilation error that the owner of the application should solve, that’s clear, but… Why is CI not showing it? And why did it work when we ran the command ourselves, even with the same container as CI?

Like always in our profession, there are always more urgent matters, so the team did not manage to explain the situation and kept on developing planned features. There was a murderer around (a log killer), 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 (shift left), 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 annoyinly 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, did so 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 decided to move on, but the mystery was still unsolved, and we couldn’t leave it there.

Like an illegal citizen patrol, 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:

    PID    PPID COMMAND
     24       1 sh -c (/scripts-6039-16459848/detect_shell_script /scripts-6039-16459848/step_script 2>&1 | tee -a /log)
     25      24 /usr/bin/bash /scripts-6039-16459848/step_script
     30      25 /usr/bin/bash /scripts-6039-16459848/step_script
     XX      30 nx run-many -t build // <------ or any command I declare in my `.gitlab-ci.yml`

Which uses:

• 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`
'

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 its stdout 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 fr"..., 131072) = 131072
[pid 17432] write(1, "1.6.RELEASE.pom\nPrinting 336 [IN"..., 65536) = 65536

// ... Ping-pong of writes in 'sp1' and reads in 'cat'
[pid 17420] read(0, "1.6.RELEASE.pom\nPrinting 336 [IN"..., 131072) = 65536
[pid 17432] read(3, "://xyz-platform.maven.pkg.mycomp"..., 131072) = 64821
[pid 17432] write(1, "://xyz-platform.maven.pkg.mycomp"..., 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 [IN"..., 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.mycomp"..., 64821) = -1 EAGAIN (Resource currently unavailable)
[pid 17432] write(2, "Write error" ...)
[pid 17432] close(4) = 0

which indicate that NodeJS is setting the open file descriptor as non-blocking with FIONBIO, and the cat writer is receiving an EAGAIN (try again later), but simply closes instead of trying again.

---

In hindsight, at this point the perpetrator should have been identified. We were almost there. We knew that:

• NodeJS was natively setting the output as non-blocking, and
• the child process (cat in the example repo, mvn for our developers) was not trying again when the pipe was full

However, once again priorities were other. A colleague suggested the unbuffer command as a quick fix to wrap NodeJS, in case the issue was some buffer (the pipe) not being flushed. The idea was to shim node and execute all node commads 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. See `npm help npmrc` for supported config options.
npm warn Unknown project config "strict-peer-dependencies". This will stop working in the next major version of npm. See `npm help npmrc` for supported config options.
npm warn Unknown project config "auto-install-peers". This will stop working in the next major version of npm. See `npm help npmrc` for supported config options.
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.

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.

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), our unbuffer node shim was making all node processes believe that they were writing to a terminal, and also collecting their output into a single stream before forwarding it to the consumer. This meant that calling newer versions of npm, which threw many warnings in stderr (such as npm warn Unknown project config ...), meant receiving both the prettified --json data AND the warnings in the same string, breaking the parser in nx-release-publish!

5.2: Following the breadcrumbs

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

Looking again at the strace and syscalls, I focused again on the non-blocking pipe. As documented by node and libuv (its I/O library):

Pipes (and sockets) are asyncronous on POSIX

Diving deeper into Nodejs’ 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.

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: did not show signs of too high memory usage, or internal buffers overflowing

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

Chapter 5: 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 answered 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 a similar issue (delegating execution to a worker/process, getting its exit code, and reporting back immediately without waiting for data streams to flush) at two different levels:

• individual task manager -> spawned process
• global task orchestrator -> individual task manager

our logs killer was identified!

5.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:

• 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 #36607fixed it in August 2026.

5.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 and I am waiting for a response from the maintainers (PR #36863).

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.

5.3: Another workaround

Our current CI wraps the nx commands with script -qec, creating a PTY around node, making writes to stdout blocking as per node’s docs. This has shown good results so far. This is probably 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 on 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).

If writing somewhere, sync vs async is a big topic, and the return value of write command 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, we must know that process.exit is quite aggressive, and

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
• …

TODO

• evaluate if this is a better mimic of the issue: /private/tmp/claude-501/-Users-mpsanchis-development-nx/2614fe85-c8e2-4daf-9a38-99b554224e97/

Reading

• Someone else was losing logs in node (blogpost)

Thank you

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