Story Time
This is a story about how a rather specific set of actions mysteriously caused my usual python stack to die without any warning or error.
It was a day at work like any other. Perhaps it was a little more exciting since we were cutting DEV into UAT, and perhaps I was a little more frustrated than usual: my changes werenât working. As it turns out, I had regressions in my code.
Unwilling to sort through the numerous commits that had been pushed in that time, I thought it was a perfect time to flex my Git muscles and use a git-bisect. In short, you can basically tell git a few things:
- A commit on which the regression exists
- A commit on which the regression doesnât exist
- A way to determine if the regression exists at some given commit
Git will, essentially, perform a binary search on the commits between the good and bad ones and ask at each step whether the regression is still there or not. Itâs a tool to help you determine on which commit the regression was introduced. Itâs faster due to the efficient search and because it can be done programmatically. The way I decided to implement the third requirement was to check if a certain file that I know I deleted still existed. I wrote a python2 script named bisect.py in the root of my repository (will be very important later) that basically scraped the relevant directory and exited with a 0 or 1 depending on if the file was found or not.
After a few attempts I got it to work properly, and I got the commit hash of the regression. As it turns out, while this exercise was valuable in the sense that it added another tool to my box, I ended up just committing the difference between my local version - which is was it shouldâve looked like - and the recently cut version to fix the issue. My new issue, however, is that my python was no longer working!
### An example of the bisect.py ###
#!/usr/local/bin/python2.7
import os
import sys
for top, sub_dirs, files in os.walk("/home/pzhou/git/thefruitcave"):
if "requirements.txt" in files:
sys.exit(1)
else:
sys.exit(0)
The worst part was, there wasnât even an error. Nothing, no log, no core, no stdout. Some debugging later, I realized it was something in my pystartup that was causing the crash; that is, if I opened just a plain interpreter with no imports, it would behave just fine. Then, just going down the list of imports in order, it became obvious that it broke whenever I tried to import pandas.
Strace
Now this is the part of the story where I skip the 1.5 hours of almost fruitless googling. All those years of googling obscure math proofs did nothing to help me here. The one thing I gleaned from it was the existence of system traces and the strace command. That command allows us to get some insight into what python is doing when python wouldnât give us anything.
This is all you need to run:
strace python -m "import pandas as pd"
Below I have a snippet of the strace output from a functioning version of my stack, before all this nonsense. That means before the existence of my bisect.py script. There are a few things to note:
- You can see how python finds the modules it needs to run. It searches the relevant package name with various valid file extensions in several different directories. Those directories are exactly your python path in order, with what I believe is the local module taking first priority.
- Itâs not shown here, but python will also search the imports in the files that it needs. For example, importing pandas will also force python to import numpy and then whatever dependencies numpy needs. This is also evidenced by the creation of a .pyc file in our directory (python2) or in a pycache directory (python3) after execution.
- On line 4291, python finds a relevant package and stops searching.
4266 close(6) = 0
4267 munmap(0x7fb881f71000, 4096) = 0
4268 stat("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisect", 0x7ffd3e7b3940) = -1 ENOENT (No such file or directory)
4269 open("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisect.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4270 open("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisectmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4271 open("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisect.py", O_RDONLY) = -1 ENOENT (No such file or directory)
4272 open("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisect.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
4273 stat("/home/pzhou/git/thefruitcave/strange_paths/bisect", 0x7ffd3e7b38c0) = -1 ENOENT (No such file or directory)
4274 open("/home/pzhou/git/thefruitcave/strange_paths/bisect.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4275 open("/home/pzhou/git/thefruitcave/strange_paths/bisectmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4276 open("/home/pzhou/git/thefruitcave/strange_paths/bisect.py", O_RDONLY) = -1 ENOENT (No such file or directory)
4277 open("/home/pzhou/git/thefruitcave/strange_paths/bisect.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
4278 stat("/home/pzhou/python27env/lib/python2.7/bisect", 0x7ffd3e7b38c0) = -1 ENOENT (No such file or directory)
4279 open("/home/pzhou/python27env/lib/python2.7/bisect.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4280 open("/home/pzhou/python27env/lib/python2.7/bisectmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4281 open("/home/pzhou/python27env/lib/python2.7/bisect.py", O_RDONLY) = -1 ENOENT (No such file or directory)
4282 open("/home/pzhou/python27env/lib/python2.7/bisect.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
4283 stat("/home/pzhou/python27env/lib/python2.7/lib-dynload/bisect", 0x7ffd3e7b38c0) = -1 ENOENT (No such file or directory)
4284 open("/home/pzhou/python27env/lib/python2.7/lib-dynload/bisect.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4285 open("/home/pzhou/python27env/lib/python2.7/lib-dynload/bisectmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4286 open("/home/pzhou/python27env/lib/python2.7/lib-dynload/bisect.py", O_RDONLY) = -1 ENOENT (No such file or directory)
4287 open("/home/pzhou/python27env/lib/python2.7/lib-dynload/bisect.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
4288 stat("/usr/local/lib/python2.7/bisect", 0x7ffd3e7b38c0) = -1 ENOENT (No such file or directory)
4289 open("/usr/local/lib/python2.7/bisect.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4290 open("/usr/local/lib/python2.7/bisectmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4291 open("/usr/local/lib/python2.7/bisect.py", O_RDONLY) = 6
4292 fstat(6, {st_mode=S_IFREG|0644, st_size=2595, ...}) = 0
4293 open("/usr/local/lib/python2.7/bisect.pyc", O_RDONLY) = 7
4294 fstat(7, {st_mode=S_IFREG|0644, st_size=3091, ...}) = 0
Then, with those things in mind, trying the same procedure with bisect.py in my path:
4305 munmap(0x7f81806d3000, 4096) = 0
4306 stat("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisect", 0x7ffe0c1cc3e0) = -1 ENOENT (No such file or directory)
4307 open("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisect.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4308 open("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisectmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4309 open("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisect.py", O_RDONLY) = -1 ENOENT (No such file or directory)
4310 open("/home/pzhou/python27env/lib/python2.7/site-packages/pytz/bisect.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
4311 stat("/home/pzhou/git/thefruitcave/strange_paths/bisect", 0x7ffe0c1cc360) = -1 ENOENT (No such file or directory)
4312 open("/home/pzhou/git/thefruitcave/strange_paths/bisect.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4313 open("/home/pzhou/git/thefruitcave/strange_paths/bisectmodule.so", O_RDONLY) = -1 ENOENT (No such file or directory)
4314 open("/home/pzhou/git/thefruitcave/strange_paths/bisect.py", O_RDONLY) = 6
4315 fstat(6, {st_mode=S_IFREG|0775, st_size=205, ...}) = 0
4316 open("/home/pzhou/git/thefruitcave/strange_paths/bisect.pyc", O_RDONLY) = -1 ENOENT (No such file or directory)
4317 fstat(6, {st_mode=S_IFREG|0775, st_size=205, ...}) = 0
4318 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f81806d3000
4319 read(6, "#!/usr/local/bin/python2.7\n\nimpo"..., 4096) = 205
4320 stat("/etc/sysconfig/64bit_strstr_via_64bit_strstr_sse2_unaligned", 0x7ffe0c1ccc70) = -1 ENOENT (No such file or directory)
4321 read(6, "", 4096) = 0
4322 unlink("/home/pzhou/git/thefruitcave/strange_paths/bisect.pyc") = -1 ENOENT (No such file or directory)
4323 open("/home/pzhou/git/thefruitcave/strange_paths/bisect.pyc", O_WRONLY|O_CREAT|O_EXCL|O_TRUNC, 0100664) = 7
4324 fcntl(7, F_GETFL) = 0x8001 (flags O_WRONLY|O_LARGEFILE)
4325 fstat(7, {st_mode=S_IFREG|0664, st_size=0, ...}) = 0
4326 mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f81806d2000
4327 write(7, "\3\363\r\n\0\0\0\0c\0\0\0\0\0\0\0\0\4\0\0\0@\0\0\0sh\0\0\0d\0"..., 382) = 382
4328 lseek(7, 4, SEEK_SET) = 4
4329 write(7, "\367\3137[", 4) = 4
4330 close(7) = 0
4331 munmap(0x7f81806d2000, 4096) = 0
4332 openat(AT_FDCWD, "/home/pzhou/git/thefruitcave", O_RDONLY|O_NONBLOCK|O_DIRECTORY|O_CLOEXEC) = 7
4333 getdents(7, /* 11 entries */, 32768) = 344
4334 getdents(7, /* 0 entries */, 32768) = 0
4335 close(7) = 0
4336 stat("/home/pzhou/git/thefruitcave/index.html", {st_mode=S_IFREG|0664, st_size=667, ...}) = 0
4337 stat("/home/pzhou/git/thefruitcave/requirements.txt", {st_mode=S_IFREG|0664, st_size=1131, ...}) = 0
4338 stat("/home/pzhou/git/thefruitcave/strange_paths", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
4339 stat("/home/pzhou/git/thefruitcave/.sass-cache", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
4340 stat("/home/pzhou/git/thefruitcave/.git", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
4341 stat("/home/pzhou/git/thefruitcave/_config.yml", {st_mode=S_IFREG|0664, st_size=27, ...}) = 0
4342 stat("/home/pzhou/git/thefruitcave/README.md", {st_mode=S_IFREG|0664, st_size=15, ...}) = 0
4343 stat("/home/pzhou/git/thefruitcave/Blaschke", {st_mode=S_IFDIR|0775, st_size=4096, ...}) = 0
4344 stat("/home/pzhou/git/thefruitcave/.gitignore", {st_mode=S_IFREG|0664, st_size=21, ...}) = 0
4345 close(6) = 0
4346 munmap(0x7f81806d3000, 4096) = 0
4347 close(5) = 0
4348 close(4) = 0
4349 close(3) = 0
4350 rt_sigaction(SIGINT, {SIG_DFL, [], SA_RESTORER, 0x7f81802a85e0}, {0x4336c2, [], SA_RESTORER, 0x7f81802a85e0}, 8) = 0
4351 close(15) = 0
4352 exit_group(1) = ?
4353 +++ exited with 1 +++
So it looks like weâve found the culprit! We can see on line 4314 that instead of finding the bisect.py that it needs it in the python installation it instead found our custom bisect.py script. And because these files are actually executed, the reason for the sudden exit is now clear as well: the sys.exit in my own code (the 0 or 1 based on whether it had found the file)! You can even see that the exit code was 1 at the end - indicating that it found my file - rather than 0, which would be given on successful completion.
If I had placed the bisect.py file somewhere not in my PYTHONPATH, this couldâve been averted. This problem is not surprising in a way, if I made a file named sys.py and put it in a location that came first on my PYTHONPATH, itâs expected that python might import that instead. In fact, before this exercise, Iâd just accepted the magic of how python finds and imports things but upon further inspection, the simple question of âwhat if I have a bunch of files named a.py in all locations in my PYTHONPATH?â is revealing enough to lead you to this discovery.
It was just unusually painful that the first time I encountered this, the offending file always ended in a sys.exit() call!