Pythonic Nightmares from 1969

tl;dr - If you've tried literally everything to get python to find your packages and it still doesn't work, double check that the directory's mtime is correct. Python on Ubuntu ignores packages in directories whose modification time is before the UNIX epoch.

I recently lost an entire work day to a bug in the heart of Python. As it often is with such things, half of this time was spent convinced I was doing something wrong and that there's no way the bug could possibly be in the programming language itself. Yet here we are. I couldn't find anything about the issue on GitHub, Stack Overflow, other random blogs (and of course the LLMs were useless), so let's get crackin' documenting history!

The Issue

It all started innocently enough: a CI pipeline that failed to build. Locally, everything was running smoothly. My docker image built fine, tests passed, modules were imported, and life was good. But in CI? Python acted as though half my files didn’t exist. ModuleNotFoundError popped up like clockwork for files that were definitely present in my source tree.

Reluctantly, I started the incredibly painful process of debugging a remote environment without SSH access and started logging everything I could think of. Directory tree? Identical. File permissions? Perfectly accessible. Python version? Matchy-matchy. As far as I could tell, the CI environment perfectly mirrored my local machine, and yet, Python imports just wouldn’t get picked up. What the actual f***!?

I started walking through the steps my code took before it was run, what could possibly have happened to it? I started retrying those on my own to match CI as closely as I could in case I had overlooked something. One difference jumped out. The files arrived in the CI environment via a network drive which was rsync'd rather than a local disk. I was pretty familiar with rsync and it's ability to carbon copy files down to the last byte of metadata, so I was still skeptical that was the issue, but I gave it a whirl. BOOM reproduced! And funnily enough when I cp -R'd the files from that same network drive, everything was fine. So ironically preservation of my metadata was the problem. WTF again!?

I started bisecting the flags that composed rsync's -a. Timestamps were it! Tantalizingly close, inspected the directory one more time with timestamp data this time.

The stat . output for the problematic namespace directories revealed a suspicious detail: the modification times were set to 1969-12-31 23:59:59.

File: .
Size: 4096 Blocks: 8 IO Block: 4096 directory
Device: 2ch/44d Inode: 16653015 Links: 17
Access: (0750/drwxr-x---) Uid: ( 0/ root) Gid: ( 0/ root)
Access: 2024-08-14 17:48:57.336576043 +0000
Modify: 1969-12-31 23:59:59.000000000 +0000
Change: 2024-08-14 17:47:57.847543170 +0000
Birth: 2024-08-14 17:47:57.835542962 +0000

The modification time predated the Unix epoch (1970-01-01 00:00:00 UTC), a rather humorous anamoly that I always love encountering in the wild. It's always been one of those things that makes me feel in the know, and explaining to my uncle in middle school why his emails in Outlook appeared to be from 1969 until they fully loaded off the network will always take the cake, but I digress. We were finally on to something. The network filesystem it was using must have been corrupting the modification time!

Reproducing the Bug

With the sweet taste of victory teasing my buds, I set out to build the minified repro. If a 1969 modification time really was causing Python to misbehave, it should be straightforward to test:

docker run -it python:3.11-slim-bullseye /bin/bash # If not already on Linux :)

cd $(mktemp -d)
mkdir test_package/
touch test_package/__init__.py
python -c "import test_package" # This works!
touch -m -t 196912312359.59 .
python -c "import test_package" # This does not! 🤯
touch -m -t 197001010000.00 .
python -c "import test_package" # This works again!

Sure enough, Python threw a fit. My packages became effectively invisible to Python's import machinery, even though it was perfectly accessible. Mystery solved!

Why Does This Happen?

I'm sorry to say I have no freaking clue and that I've exhausted my patience on this one for now, but it's reproducible on every python3 version I tried from 3.7-3.12.

One day when I have luxurious free time I may be able to finally hunt down the source of this nasty little bugger, but for now I'm content to just shed light on the fact that it happens and hopefully help some poor soul googling this next time.

Fixing the Problem

To resolve the issue in the CI pipeline, I ended up just removing -t from rsync (and critically reexamining every other flag -a brings along for whether they made sense to avoid future traps).

This reset the modification times to the current timestamp, ensuring Python could interact with the directories without issue.

The Takeaway

This bug was a perfect storm of obscure filesystem behavior, timestamp quirks, and python internals. It’s a good reminder of how the smallest details like a directory’s modification time can cascade into seemingly unrelated (and fatal 😬) problems.

If you’re ever debugging a Python import issue and have lost your mind ruling out every recommendation on every forum out there, don’t overlook your filesystem metadata. You might just stumble across your very own python time machine moment.