Author tzickel
Recipients benjamin.peterson, eric.snow, gregory.p.smith, meador.inge, ncoghlan, serhiy.storchaka, tzickel
Date 2017-10-21.09:52:59
SpamBayes Score -1.0
Marked as misclassified Yes
Message-id <1508579583.34.0.213398074469.issue25083@psf.upfronthosting.co.za>
In-reply-to
Content
OK, This issue has been biting me a few more times in production, so for now I've added the environment variable PYTHONDONTWRITEBYTECODE which resolves it (but it's a hack). I'm sure I am not the only one with it (recall that this is happening in a complex setup where I run python in windows via a network drive hosted in netapp, and runs thousands of times from many machines).

So, I've been looking for a simple way to show you it's a major fault at the python 2 import I/O error checking, and found that new strace has fault injection capability :)

In this demo I'll be running under debian sid (has strace version high enough for fault injection and latest python 2), you can use docker if you don't have it.

On my mac, I'm running (this example is on one of python's init modules, but of course can happen on any .py file):
----
user$ docker run -it --cap-add SYS_PTRACE debian:sid
----
The cap-add is needed for strace to run.
----
2dcc36934ea6">root@2dcc36934ea6:/# apt-get update && apt-get install -y strace python

2dcc36934ea6">root@2dcc36934ea6:/# python
Python 2.7.14 (default, Sep 17 2017, 18:50:44)
[GCC 7.2.0] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> exit()
----
Python works just fine.
----
2dcc36934ea6">root@2dcc36934ea6:/# strace -P /usr/lib/python2.7/sre_parse.pyc -P /usr/lib/python2.7/sre_parse.py -e trace=read -e fault=read python
read(7, 0x55c3ac2ad900, 4096)           = -1 EPERM (Operation not permitted) (INJECTED)
...
read(6, 0x55c3ac2cb680, 4096)           = -1 EPERM (Operation not permitted) (INJECTED)
...
Traceback (most recent call last):
  File "/usr/lib/python2.7/site.py", line 554, in <module>
    main()
...
  File "/usr/lib/python2.7/sre_compile.py", line 572, in compile
    p = sre_parse.parse(p, flags)
AttributeError: 'module' object has no attribute 'parse'
+++ exited with 1 +++
----
This command simply causes the python process to fail the read command on the files sre_parse.py and sre_parse.pyc (the .pyc btw already existed from previous run).
This should be OK, since it can't read a required module form disk.
----
2dcc36934ea6">root@2dcc36934ea6:/# python
Traceback (most recent call last):
  File "/usr/lib/python2.7/site.py", line 554, in <module>
    main()
...
  File "/usr/lib/python2.7/sre_compile.py", line 572, in compile
    p = sre_parse.parse(p, flags)
AttributeError: 'module' object has no attribute 'parse'
----
This is already bad, python does not work anymore, now even without an I/O error :(
----
2dcc36934ea6">root@2dcc36934ea6:/# ls -l /usr/lib/python2.7/sre_parse.pyc
-rw-r--r-- 1 root root 118 Oct 21 09:20 /usr/lib/python2.7/sre_parse.pyc
----
If we check, we see that the previous python instance with I/O error created an empty byte code valid sre_parse.pyc (you can check it by dis.dis it, and see it's empty code object), this is the crux of the bug.
----
2dcc36934ea6">root@2dcc36934ea6:/# rm /usr/lib/python2.7/sre_parse.pyc
----
let's delete the bad .pyc file
----
2dcc36934ea6">root@2dcc36934ea6:/# python
Python 2.7.14 (default, Sep 17 2017, 18:50:44)
[GCC 7.2.0] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> exit()
----
yey, python works now again
----
2dcc36934ea6">root@2dcc36934ea6:/# ls -l /usr/lib/python2.7/sre_parse.pyc
-rw-r--r-- 1 root root 21084 Oct 21 09:20 /usr/lib/python2.7/sre_parse.pyc
----
We can see now that the .pyc file has a much bigger size (21084 bytes compared to 118 from before)
----
2dcc36934ea6">root@2dcc36934ea6:/# strace -P /usr/lib/python2.7/sre_parse.pyc -P /usr/lib/python2.7/sre_parse.py -e trace=read -e fault=read python -B
read(7, 0x55ceb72a7900, 4096)           = -1 EPERM (Operation not permitted) (INJECTED)
...
read(6, 0x55ceb72c5680, 4096)           = -1 EPERM (Operation not permitted) (INJECTED)
...
Traceback (most recent call last):
  File "/usr/lib/python2.7/site.py", line 554, in <module>
    main()
...
AttributeError: 'module' object has no attribute 'parse'
+++ exited with 1 +++
----
We can now try this issue with python -B which should not try to create .pyc files
----
2dcc36934ea6">root@2dcc36934ea6:/# python
Python 2.7.14 (default, Sep 17 2017, 18:50:44)
[GCC 7.2.0] on linux2
Type "help", "copyright", "credits" or "license" for more information.
>>> exit()
----
yey, python still works (hopefully if this is an network I/O error, it will stop occurring on a future run with a watchdog for an server app)
----

A less likely variant (but possible) is that if the .pyc does not exist, and you have an I/O error on importing the .py, it will produce an bad .pyc file, you can try it:
2dcc36934ea6">root@2dcc36934ea6:/# rm /usr/lib/python2.7/sre_parse.pyc
2dcc36934ea6">root@2dcc36934ea6:/# strace -P /usr/lib/python2.7/sre_parse.py -e trace=read -e fault=read python
2dcc36934ea6">root@2dcc36934ea6:/# python
Python will not work until you delete the .pyc file.

----

(*) The I/O error needs to occur when the AST parser will still produce a valid code object, this easily happens when the error is just when starting to read the file (will produce an empty code AST which will create an empty code object)

----

You can install python3 and see that it doesn't effect it the same way (i.e. it will abort on the I/O error, but it won't produce a bad .pyc file, since it has much better I/O error handling)

----
5ef2a0658fa8">root@5ef2a0658fa8:/# strace -P /usr/lib/python3.5/encodings/aliases.py -P /usr/lib/python3.5/encodings/__pycache__/aliases.cpython-35.pyc -e trace=read -e fault=read python3
....
Aborted

5ef2a0658fa8">root@5ef2a0658fa8:/# python3
Python 3.5.2 (default, Sep 14 2017, 22:51:06)
[GCC 5.4.0 20160609] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> exit()

----
The patch previously included should fix this issue.
History
Date User Action Args
2017-10-21 09:53:03tzickelsetrecipients: + tzickel, gregory.p.smith, ncoghlan, benjamin.peterson, meador.inge, eric.snow, serhiy.storchaka
2017-10-21 09:53:03tzickelsetmessageid: <1508579583.34.0.213398074469.issue25083@psf.upfronthosting.co.za>
2017-10-21 09:53:03tzickellinkissue25083 messages
2017-10-21 09:52:59tzickelcreate