Error opening file for reading: Permission denied

16 Aug 2012, 3:38 p.m. (updated: 4 Dec 2012, 5:51 p.m.)

As we released Ralph as an open source project, new users started deploying it and very soon ran into an annoying problem. The output of each ralph command was preceeded with a meaningless message out of nowhere:

Error opening file for reading: Permission denied

Took me a while to identify the culprit and work around this.

The funny part of this error message is how it doesn't specify which file couldn't be opened. To add insult to injury, the error does not show up when you actually try to debug the process with strace:

$ ralph maxid
Error opening file for reading: Permission denied
Models from 'auth':
 Permission = 402 (297 objects)
 Group = 7 (7 objects)
...

$ strace ralph maxid 2>&1 | grep "Permission"
write(1, "Models from 'auth':\n Permission "..., 3498Models from 'auth':
Permission = 402 (297 objects)

Ditto when you try investigating the problem with gdb:

$ gdb --quiet --args ~/bin/python -m ralph maxid
Reading symbols from /home/ralph/bin/python...

(no debugging symbols found)...done.
(gdb) r
Starting program: /home/ralph/bin/python -m ralph maxid
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7fffed06b700 (LWP 20724)]
[Thread 0x7fffed06b700 (LWP 20724) exited]
Models from 'auth':
 Permission = 402 (297 objects)
 Group = 7 (7 objects)
...

PIL, it's you again!

Needless to say, it wasn't easy to find the culprit. Fortunately, the -v option passed directly to the Python interpreter could at least tell me which import caused that error message to appear:

$ python -v -m ralph maxid
...
dlopen("/home/ralph/local/lib/python2.7/site-packages/_imaging.so", 2);
Error opening file for reading: Permission denied
import _imaging # dynamically loaded from /home/ralph/local/lib/python2.7/site-packages/_imaging.so
...

So there it was! _imaging, the C extension module implementing parts of PIL. This way I could come up with a minimal example:

$ python -c "import _imaging; print _imaging.__file__"
Error opening file for reading: Permission denied
/home/ralph/local/lib/python2.7/site-packages/_imaging.so

The best part is that the import worked. Nothing of value was lost. So the error message is not only unhelpful but it seems it is a "warning" at best.

Anyway, I downloaded the sources for PIL and tried to find where the message comes from. There were no matches for that error in the whole source package which means...

The error comes from a PIL dependency

But which dependency? Let's try that strace thing again. It won't show us the error but at least it can point us at possible libraries to look at:

$ strace python -c "import _imaging" 2>&1 | grep open
...
open("/home/ralph/local/lib/python2.7/site-packages/_imaging.so", O_RDONLY|O_CLOEXEC) = 4
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 4
open("/usr/lib/x86_64-linux-gnu/libjpeg.so.8", O_RDONLY|O_CLOEXEC) = 4
open("/proc/self/auxv", O_RDONLY)       = 4

Oh, so that's probably libjpeg. Let's see:

$ python -c "import ctypes; ctypes.CDLL('libjpeg.so.8')"
Error opening file for reading: Permission denied

Hurray! We found the library responsible for the problem! But which file does it try and fail to open? strace led us to /proc/self/auxv. Indeed:

$ python -c "open('/proc/self/auxv')"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
IOError: [Errno 13] Permission denied: '/proc/self/auxv'

seteuid, Y U SO dumb?

Unfortunately, nobody besides Ralph users could reproduce the problem. Other people could open the file just fine:

$ python -c "print open('/proc/self/auxv')"
<open file '/proc/self/auxv', mode 'r' at 0x7fd7890e9f60>

After a long ghost chase I finally discovered that the problem lies in using setcap on the python binary. Ralph needs to be able to open raw sockets to send ping packets, etc. This operation is restricted to the root user. The ping tool works for unprivileged users because it has the SUID bit set on the binary:

$ ls -l /bin/ping
-rwsr-xr-x 1 root root 35712 Nov  8  2011 /bin/ping

Notice the "s"? Everytime you ping something, it happens with root privileges. We obviously didn't want to SUID the whole Python binary because that would be a massive security hole. Instead, we told users to use setcap to only allow for raw socket access:

$ setcap cap_net_raw=ep /usr/bin/python2.7

To make a long story short, this effectively creates all files in /proc/self/ with the owner set to root instead of the actual UID. When the binary then drops root privileges, it cannot access its own auxv (nor environ, io and mem for that matter). And it just so happens that libjpeg checks /proc/self/auxv to decide which performance optimizations to use.

Working around it

Now I knew what was wrong and I even found that this problem has already been reported to Ubuntu. This didn't make me feel much better though because the ugly error message still pops up and confuses our users. Not very helpful. I decided to simply force the import of _imaging as early as possible while temporarily muting stderr.

My first naive attempt to simply swap sys.stderr to /dev/null did not work as libjpeg.so.8 is C code which uses perror(). The solution instead is to duplicate the stderr file descriptor, close the current one, import the library, duplicate the descriptor back and reopen stderr. We also need to take any exceptions that might pop up in the mean time into account:

def ubuntu_1020872_workaround():
    """Workaround for spurious "Error opening file for reading: Permission
    denied" printed to stderr while importing _imaging due to libjpeg not being
    able to open /proc/self/auxv on a setcapped `python` process. Reported as
    Ubuntu bug https://bugs.launchpad.net/libjpeg-turbo/+bug/1020872.
    """
    dup = os.dup(2)
    os.close(2)
    try:
        import _imaging
    finally:
        os.dup2(dup, 2)
        try:
            sys.__stderr__.close()
            sys.stderr.close()
        except IOError:
            pass
        sys.__stderr__ = sys.stderr = os.fdopen(2, 'a')

Now you only have to ensure this code gets run as early as possible in your application entry point:

def main():
    if sys.platform.startswith('linux'):
        ubuntu_1020872_workaround()
    # ... rest of the app ...

if __name__ == "__main__":
    main()

Additionally, there's a platform check so the code is only run on Linux. This possibly protects from problems on platforms which don't not support this way of temporarily muting stderr.

Issue solved!

Update: Dec 4, 2012

Added closing of the old stderr file handle to the workaround above. Without it Python reports another problem at exit:

close failed in file object destructor:
sys.excepthook is missing
lost sys.stderr

This happens when there is some output buffered in the stderr file handle which cannot be flushed because the handle has been closed. Closing the handle explicitly silences the warning.

Entry tagged as bug , libjpeg , pil , python and ubuntu.

« HackFest 2012 Summary
Frads »