I Chased an Empty Log for 48 Hours. lsof Showed a Deleted Inode.

Have you ever tailed a log path that stayed empty while the writer process still looked perfectly healthy? I did, and I burned two days staring at a filename that no longer mapped to the live inode. The job appended JSON lines through Python's logging.FileHandler, and the path on disk went silent after rotation. Disk usage still climbed, which felt contradictory until I stopped treating the path as the file.

This write-up is reconstructed field notes you can rerun, not a scoreboard of fake production metrics. Every command below fits on a throwaway Linux login you are allowed to break. If you keep only one question, keep this one: is the path I am tailing the same inode the process still holds?

Hours 0-12: I blamed Python logging, because that is my reflex

I started where I always start, by poking handler flags and logger names until the config looked over-explained. Was force=True missing on basicConfig? Did I attach two handlers to aliases of the same logger? Had I skipped encoding="utf-8" again and blamed the platform later?

The writer I used for the lab is intentionally dull, which is why I trusted it too long. It opens one file handler, prints its pid, and then ticks forever.

# lab_writer.py — reconstructed lab, not production code
import logging
import os
import time
from pathlib import Path

LOG_PATH = Path("/tmp/nightly-lab.log")

def build_logger() -> logging.Logger:
    logger = logging.getLogger("nightly")
    logger.setLevel(logging.INFO)
    logger.handlers.clear()
    handler = logging.FileHandler(LOG_PATH, encoding="utf-8")
    handler.setFormatter(logging.Formatter("%(asctime)s %(message)s"))
    logger.addHandler(handler)
    logger.propagate = False
    return logger

def main() -> None:
    logger = build_logger()
    st = os.stat(LOG_PATH)
    logger.info("pid=%s dev=%s ino=%s", os.getpid(), st.st_dev, st.st_ino)
    n = 0
    while True:
        n += 1
        logger.info("tick=%s", n)
        time.sleep(1)

if __name__ == "__main__":
    main()

I launched it in the background and tailed the path like a reasonable operator. The first minutes printed ticks, so I assumed rotation would be someone else's problem overnight.

What I tried before lunch:

1. Restart the writer and celebrate the first line, which taught me nothing durable.
2. Sprinkle extra logger.info calls until the function looked nervous.
3. Print LOG_PATH.resolve() in case a symlink had sent me into the woods.
4. Glance at df -h /tmp and relax, because free space still existed.

Have you noticed how a live ps line makes you skip the boring descriptor checks? I had a healthy pid and a quiet path, and I treated that pair as a logging bug.

Hours 12-24: rotation looked successful, which made the hole deeper

The logrotate snippet was the kind of block people paste from a wiki and never read twice. It created a new file at the original path and left the running handler glued to the old inode.

/tmp/nightly-lab.log {
    daily
    rotate 3
    missingok
    notifempty
    create 0644
    # no copytruncate
    # no postrotate kill -HUP
}

After the rotate, I opened the path and found nothing new. I read that silence as "the loop died," then I restarted the process and erased the crime scene. A restart opens a fresh inode, so the deleted one vanishes when the last descriptor closes.

I even wandered through ghosts from earlier weeks in this series: working directory, a SIGTERM that hit a wrapper, IPv6 localhost. Those were real bugs on other days. They were not this bug.

False leads I will not repeat:

• Blaming FileHandler buffering without listing file descriptors.
• Restarting the writer before capturing /proc/$PID/fd.
• Assuming tail -F is a window into the process rather than into a name.
• Treating du on the log directory as the whole disk story.

A small naming trap is worth spelling out, because I mixed the flags myself. tail -f follows the descriptor it already opened. tail -F retries the name when the path is recreated. Either way, you can still miss the inode the process holds after a create rotation.

Hours 24-36: df and du stopped agreeing

This is when the story stopped being about Python. df -h /tmp showed shrinking free space, while du -sh /tmp stayed almost calm. Have you seen that split? It usually means a deleted file is still held open.

# reconstructed lab commands — Linux only
python3 lab_writer.py &
sleep 3
PID=$!
stat -c 'path_inode=%i dev=%d' /tmp/nightly-lab.log
echo "pid=$PID"

# simulate the rotation mistake: drop the name, keep the writer
rm -f /tmp/nightly-lab.log
# equivalent idea: mv the file aside and create a new empty path

ls -l /tmp/nightly-lab.log || echo "path missing or replaced"
ls -l /proc/$PID/fd
lsof -nP -p "$PID"

On Linux the descriptor line should mention (deleted). The process is fine. Your filename is a new empty inode, or it is gone. The bytes remain in the old inode until the last file descriptor closes.

Recover evidence before you send any signal:

# copy the live deleted inode while the writer still holds it
ls -l /proc/$PID/fd
# pick the fd number N whose target says (deleted)
cp "/proc/$PID/fd/N" /tmp/recovered-nightly.log
wc -l /tmp/recovered-nightly.log

That copy from /proc is the artifact I wanted on hour two. It turns a ghost file into something you can grep. Kill the process first, and the inode is gone for good.

Decision table I now keep next to the laptop

What you see	What it is probably not	Check this	If the check hits
Path empty, process alive	"logging is broken"	ls -l /proc/$PID/fd	reopen the handler or send HUP
df grows, du does not	quota on another mount	`lsof -nP \	grep deleted`
tail goes quiet after rotate	firewall, DNS, IPv6	stat inode before vs after	create rotation without reopen
Restart "fixes" it	a Heisenbug in JSON	did restart open a new inode?	you destroyed the crime scene

Hours 36-48: I needed a machine I was allowed to break

I still needed a Linux login where deleting an open log was a lesson, not an incident. My laptop is the wrong operating system for /proc stories, and I will not rehearse rm on a shared box.

Disclosure: This article was prepared as part of MonkeyCode's product outreach.

I pasted the df versus du mismatch into MonkeyCode's free model access and asked for a hypothesis list. Then I reproduced the deleted-inode case on the free server option, as a disposable Linux login. The model suggested lsof and /proc/PID/fd; it did not magically read my descriptors. I ran the commands myself, because a checklist is not the same thing as evidence.

The lab on that box stayed small on purpose:

python3 lab_writer.py >/tmp/writer-stdout.txt 2>&1 &
PID=$!
sleep 2
stat -c 'before ino=%i' /tmp/nightly-lab.log
rm -f /tmp/nightly-lab.log
sleep 2
lsof -nP -p "$PID"
ls -l /proc/$PID/fd
# optional: watch the held inode still accept writes
sleep 5

Would I let a model rewrite logrotate unreviewed? No. The unit test is still a pid, an inode, and a command I can paste.

Proposal: reopen on SIGHUP instead of hoping the path is honest

copytruncate keeps the same inode, which can be enough for a single writer, and it can also stall on a huge copy. A cleaner contract is to reopen the name after rotation. Treat the next snippet as a proposal until you send kill -HUP and compare inodes.

# proposal — unexecuted until you wire it into your supervisor
import logging
import os
import signal
from logging import FileHandler

LOG_PATH = "/tmp/nightly-lab.log"
logger = logging.getLogger("nightly")

def install_handler() -> None:
    logger.handlers.clear()
    handler = FileHandler(LOG_PATH, encoding="utf-8")
    handler.setFormatter(logging.Formatter("%(asctime)s %(message)s"))
    logger.addHandler(handler)

def reopen(_signum, _frame) -> None:
    install_handler()
    st = os.stat(LOG_PATH)
    logger.info("reopened dev=%s ino=%s", st.st_dev, st.st_ino)

install_handler()
signal.signal(signal.SIGHUP, reopen)

logging.handlers.WatchedFileHandler can also reopen when the path is recreated under the same name. You should still prove it with stat and /proc, because folklore is how I lost the first day.

A test plan you can tick without production

Run this on Linux only, and keep the pid alive until the last copy finishes.

1. Start lab_writer.py, then record pid, device, and inode with stat and a log line.
2. Confirm tail -f /tmp/nightly-lab.log shows ticks for several seconds.
3. Remove or replace the path (rm or a create rotation) without killing the writer.
4. Confirm the path is missing or empty, while ps still shows the same pid.
5. Confirm /proc/$PID/fd or lsof lists the log as (deleted).
6. If you let it write long enough, confirm df and du on /tmp disagree.
7. Copy /proc/$PID/fd/N to a recovery file and grep for tick=.
8. Only after the copy, install a reopen path and prove SIGHUP changes the inode.

If step 5 never shows (deleted), you are on the wrong pid or not on Linux. Stop adding logger lines and re-check identity first.

What I would repeat next time

I would start with process identity instead of framework superstition. Pid, uid, cwd, device, and inode beat another hour of logger folklore.

Repeatable order:

1. Record pid and stat inode before rotate, restart, or rm.
2. Compare df and du on the filesystem that holds the log.
3. List /proc/$PID/fd and search lsof output for (deleted).
4. Copy the live descriptor to a recovery file before SIGTERM.
5. Only then change rotation, signals, or handler classes.

I would also print device and inode from Python at startup, because that line is cheap.

st = os.stat(LOG_PATH)
logging.getLogger("nightly").info(
    "pid=%s dev=%s ino=%s", os.getpid(), st.st_dev, st.st_ino
)

If those numbers change while the process stays up, you are no longer looking at the same file. That sentence would have saved me a day.

Limitations, and who should skip this

This lab assumes Linux /proc and a process you are allowed to inspect. macOS will not rhyme with these file descriptor paths, and Windows deletion semantics are a different argument. If you cannot read /proc/$PID/fd, use whatever your supervisor already exposes and stop guessing.

Do not use this approach when:

• You do not own the process and inspecting /proc would break policy.
• The "log" is journald, a pipe, or a socket rather than a regular file.
• You want copytruncate on a huge file without measuring the copy stall.
• You expect a model answer to replace a single lsof on the real pid.

Free model access is handy for a checklist. It is not evidence. A free Linux login is handy when you need a shell you can wreck. It is not production, and I will not invent CPU, quota, or uptime numbers for it.

The durable lesson is smaller than the two-day detour. Trust inodes, not filenames, and recover the open descriptor before you restart anything.