New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Seemingly random occurences of error "module 'psycopg2' has no attribute 'extensions'" #550

Closed
TotempaaltJ opened this Issue Apr 26, 2017 · 25 comments

Comments

Projects
None yet
5 participants
@TotempaaltJ
Copy link

TotempaaltJ commented Apr 26, 2017

Hello,

I'm trying to get some better insight into why this error is occurring on our systems. I've googled the error and couldn't find anything else, so here I am.

For a situation sketch: we're installing psycopg2 as a dependency of SQLAlchemy, through Pip, on a Python3.6 installation, in Alpine Linux, on Docker (image python:3.6-alpine—see the illustrative Docker file). Seemingly at random times, we get an AttributeError: module 'psycopg2' has no attribute 'extensions' (also see partial stack trace below). I've been trying to figure out what causes this error, but I haven't been able to reproduce it or pinpoint really anything that could lead to reproduction about it.

Currently, my hunch is that it occurs for every run of a certain Docker build, but that it's still random at build time. I am still in the process of confirming that suspicion though.

I will continue my research of course, and report back. I've opened this issue hoping that maybe someone has an idea of how to reproduce this, or some pointers, or a fix even.


Main exception

Traceback (most recent call last):
…
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/__init__.py", line 387, in create_engine
    return strategy.create(*args, **kwargs)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/engine/strategies.py", line 80, in create
    dbapi = dialect_cls.dbapi(**dbapi_args)
  File "/usr/local/lib/python3.6/site-packages/sqlalchemy/dialects/postgresql/psycopg2.py", line 554, in dbapi
    import psycopg2
  File "/usr/local/lib/python3.6/site-packages/psycopg2/__init__.py", line 67, in <module>
    import psycopg2.extensions as _ext
AttributeError: module 'psycopg2' has no attribute 'extensions'

Dockerfile (illustrative, not tested/reproducing)

FROM python:3.6-alpine

RUN apk add --no-cache \
    postgresql \
    postgresql-dev \
    python3-dev \

COPY requirements.txt .
RUN pip install -r requirements.txt

CMD …
@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Apr 26, 2017

It doesn't seem anything psycopg2 specific. Leaving it here for the moment just in case someone stumbles it it. I suggest you take a look at your environment when it happens because it seems a problem with the image. e.g.:

try:
    import psycopg2
except AttributeError:
    print(sp.check_call(['ls', '-l', '/usr/local/lib/python3.6/site-packages/psycopg2']))
    import psycopg2 # maybe it's a race condition and now it works?

and compare it with the state of a working image.
@TotempaaltJ

This comment has been minimized.

Copy link

TotempaaltJ commented Apr 26, 2017

Thanks, yeah I agree. I've been going on the assumption that it is an issue with the image and not with psycopg2.

If it were a race condition, that'd mean the package wasn't fully installed when the module is run, but the pip install definitely needs to complete for Docker to continue with the running.

I'll see if I can inspect a broken image and hopefully find what the issue could be.

@TotempaaltJ

This comment has been minimized.

Copy link

TotempaaltJ commented Apr 26, 2017

I can confirm it's not bound to the image. There's no working or non-working images. Seems to be determined on launch of the image.

@rshk

This comment has been minimized.

Copy link

rshk commented May 22, 2017

Same issue here.. using python:3.6.1 image, not the alpine one. Image IDs I had this problem with are 787e9f4da78e and b6cc5d70bc28 (I cannot confirm if others didn't have this problem); actually it used to work fine with 787e9f4da78e until around a month ago or so.

I'm still trying to reproduce reliably too; I can confirm it is launch-dependant, and it will either fail or succeed all the time for each started instance.

It is triggered for us when attempting to create the first database connection, calling create_engine(), down to:

File "/usr/local/lib/python3.6/site-packages/sqlalchemy/dialects/postgresql/psycopg2.py", line 564, in _psycopg2_extras

which runs a from psycopg2 import extras, and in turn from psycopg2 import extensions as _ext inside psycopg2.extras is raising the exception.

I tried this too in an attempt to reproduce, but without success (it always succeeds):

for i in {1..20}; do echo "Run #${i}"; docker-compose run --rm my-container python -c 'from psycopg2 import extras'; done

Just to add more context, the app is also using Flask, and SQLAlchemy Core (no ORM).

I'll post updates here if I find anything relevant

@rshk

This comment has been minimized.

Copy link

rshk commented May 22, 2017

Just another question that comes to mind: are you using docker-compose as well? Which version?
We recently experienced an (unrelated?) issue with an old version of compose that caused the main app package not to be installed correctly (it was installed, but not found by pkg_resources). I'm starting to think docker might be to blame here, rather than psycopg2 -- perhaps something getting messy when composing the "layered" filesystem?

@TotempaaltJ

This comment has been minimized.

Copy link

TotempaaltJ commented May 24, 2017

@rshk no docker-compose. This was occurring on our EC2 deployments only (have since switched to pg8000).

@TotempaaltJ

This comment has been minimized.

Copy link

TotempaaltJ commented May 24, 2017

@richardasaurus I managed to reproduce the exception with your script on macOS 10.12.4 as well.

@rshk

This comment has been minimized.

Copy link

rshk commented May 24, 2017

@richardasaurus ok, it defintely seems there is a race condition of some kind, really weird I have to say (why is that module sometimes not reachable?)

I was able to reproduce on python 3.6 / psycopg2 2.7.1, even stripping down to:

from multiprocessing.pool import ThreadPool

from sqlalchemy import create_engine

def do_stuff(*args, **kwargs):
    create_engine('postgresql://a:b@c:5432/d')

pool = ThreadPool(2)
pool.map(do_stuff, range(100))

Also, adding a import psycopg2.extensions would fix this (but of course, that's mostly just hiding the problem).

@rshk

This comment has been minimized.

Copy link

rshk commented May 24, 2017

Even more interesting, this is enough to trigger the issue, at times:

from multiprocessing.pool import ThreadPool

def do_stuff(*args, **kwargs):
    from psycopg2 import connect

pool = ThreadPool(2)
pool.map(do_stuff, range(100))

I was thinking about some circular import, the weird thing is the issue only seems to be triggered by concurrently importing that module..

@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Jun 8, 2017

Closing here as the most likely culprit is the layered fs. Let me know if you find the hidden if random() < 0.01: raise ImportError we have cleverly hidden in the code.

@dvarrazzo dvarrazzo closed this Jun 8, 2017

@rshk

This comment has been minimized.

Copy link

rshk commented Jun 14, 2017

@dvarrazzo it doesn't just happen inside docker, it looks like there is some race condition somewhere in the code. I put an import psycopg2.extensions in my app's entry point to work around this, but I think it still needs to be considered a psycopg2 bug.

See example:

samu@TrentoRaiser /home/samu 
% cd $( mktemp -d )                                             

samu@TrentoRaiser /tmp/tmp.K5XNcFjb5m 
% virtualenv --python=/usr/bin/python3.6 --no-site-packages venv
Running virtualenv with interpreter /usr/bin/python3.6
Using base prefix '/usr'
New python executable in /tmp/tmp.K5XNcFjb5m/venv/bin/python3.6
Also creating executable in /tmp/tmp.K5XNcFjb5m/venv/bin/python
Installing setuptools, pip, wheel...done.

samu@TrentoRaiser /tmp/tmp.K5XNcFjb5m 
% . venv/bin/activate

samu@TrentoRaiser /tmp/tmp.K5XNcFjb5m py3.6:venv
% pip install psycopg2
Collecting psycopg2
  Using cached psycopg2-2.7.1-cp36-cp36m-manylinux1_x86_64.whl
Installing collected packages: psycopg2
Successfully installed psycopg2-2.7.1

samu@TrentoRaiser /tmp/tmp.K5XNcFjb5m py3.6:venv
% cat > foo.py
from multiprocessing.pool import ThreadPool

def do_stuff(*args, **kwargs):
    from psycopg2 import connect

pool = ThreadPool(2)
pool.map(do_stuff, range(100))

samu@TrentoRaiser /tmp/tmp.K5XNcFjb5m py3.6:venv
% python foo.py 
Traceback (most recent call last):
  File "foo.py", line 7, in <module>
    pool.map(do_stuff, range(100))
  File "/usr/lib64/python3.6/multiprocessing/pool.py", line 260, in map
    return self._map_async(func, iterable, mapstar, chunksize).get()
  File "/usr/lib64/python3.6/multiprocessing/pool.py", line 608, in get
    raise self._value
  File "/usr/lib64/python3.6/multiprocessing/pool.py", line 119, in worker
    result = (True, func(*args, **kwds))
  File "/usr/lib64/python3.6/multiprocessing/pool.py", line 44, in mapstar
    return list(map(*args))
  File "foo.py", line 4, in do_stuff
    from psycopg2 import connect
  File "/tmp/tmp.K5XNcFjb5m/venv/lib/python3.6/site-packages/psycopg2/__init__.py", line 68, in <module>
    import psycopg2.extensions as _ext
AttributeError: module 'psycopg2' has no attribute 'extensions'
 Exit status: 1                                                                                                                                                        

samu@TrentoRaiser /tmp/tmp.K5XNcFjb5m py3.6:venv
% python
Python 3.6.1 (default, Mar 27 2017, 00:27:06) 
[GCC 6.3.1 20170306] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import psycopg2.extensions
>>> 
@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Jun 14, 2017

@rshk I've tried running that script and I can't reproduce the issue.

# bug-550.py
from multiprocessing.pool import ThreadPool

def do_stuff(*args, **kwargs):
    from psycopg2 import connect

pool = ThreadPool(2)
pool.map(do_stuff, range(100))
piro@risotto:~/src/psycopg2$ make PYTHON=python3
piro@risotto:~/src/psycopg2$ export PYTHONPATH=build/lib.3.5
piro@risotto:~/src/psycopg2$ for i in $(seq 10); do python3 bug-550.py; done
piro@risotto:~/src/psycopg2$ for i in $(seq 100); do python3 bug-550.py; done

it's Python 3.5, but still, if it only happens with Py 3.6, then it's a Py 3.6 bug. If it happens in virtualenv it's virtualenv bug. If it happens in Dockers it's Dockers' bug. Psycopg doesn't do anything strange here: in the __init__ module it imports a submodule, it's Python bread and butter, which I expect to work and I wouldn't know what to fix.

@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Jun 14, 2017

@richardasaurus the error happens in a normal python package which imports a normal python module with a normal import statement. My take is that if it fails your python is broken, I don't know how and by whom. So, if you can reproduce the bug (because I cannot, not with the script provided) and provide a patch, I'll be happy to apply it. Otherwise I have no idea what to fix in

import psycopg2.extensions as _ext

which could magically make your problem go away.

@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Jun 14, 2017

@richardasaurus, @rshk I've added your test to the test suite and pushed it to the CI to test with Python 3.6. As you can see the test didn't fail. If you can change the test in a way to make if fail I can fix it, otherwise I can't do much.

@rshk

This comment has been minimized.

Copy link

rshk commented Jun 14, 2017

@dvarrazzo looks like there is a race condition with import package.module as _alias on (some?) python 3.6. Tried with 3.5 on my machine, everything seems to be fine. I guess I'll gather some more information and report a bug.

I created a repo with some code to reproduce in the meantime: https://github.com/rshk/python36-import-alias-concurrency-bug/

You were right, something seems to be horribly broken in the interpreter ☹️

One thing you might want to do to mitigate is to use from psycopg2 import extensions as _ext instead, that seems to be working perfectly fine in 3.6 too (I wonder what got messed up there?)..

Thanks

@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Jun 14, 2017

@rshk admittedly blaming the interpreter was a long shot... I'm actually surprised that seems to be the case.

Is that one in __init__.py the only import occurrence that creates this problem? It would be no problem to replace it with the semantically equivalent version you propose. Thank you for testing :)

@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Jun 14, 2017

@rshk note that the travis run linked above also uses Python 3.6.1. Have you got any idea about why is that not failing, or if we could fix the test in a way that makes that fail?

In your git repos test example it seems you are using virtualenv too (the package is in a temp dir). Have you tried running it with the system python?

dvarrazzo added a commit that referenced this issue Jun 15, 2017

Use an import style reported not broken on Python 3.6
Couldn't reproduce the issue but it has been documented in #550.
@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Jun 15, 2017

So we are saying these may be problematic?

piro@risotto:~/src/psycopg2$ ag '^import [^ ]+\.[^ ]+ as' lib/
lib/__init__.py
68:import psycopg2.extensions as _ext

lib/pool.py
28:import psycopg2.extensions as _ext

lib/psycopg1.py
31:import psycopg2._psycopg as _2psycopg   # noqa
36:import psycopg2.extensions as _ext

I've changed them as suggested in the branch bug-550. Please test: if it works for you I'll merge it and release it in 2.7.2.

dvarrazzo added a commit that referenced this issue Jun 17, 2017

Use an import style reported not broken on Python 3.6
Couldn't reproduce the issue but it has been documented in #550.
@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Jun 17, 2017

No feedback... merged to master anyway.

@kolapapa

This comment has been minimized.

Copy link

kolapapa commented Jun 30, 2017

please merge, I have this problem, too

@hkhatod

This comment has been minimized.

Copy link

hkhatod commented Nov 28, 2017

Was this issue resolved ? I am still having this issue. How do I get the latest version with issue resolved ? I am currently on psyvopg2 2.6.2

@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Nov 28, 2017

Yes, the issue was resolved. It was released in 2.7.2.

@dvarrazzo

This comment has been minimized.

Copy link
Member

dvarrazzo commented Nov 28, 2017

@hkhatod More details: the change in psycopg is a workaround for python bug 30814 which AFAICS was resolved in python/cpython#2580 and affects python 3.6.0 and 3.6.1 only.

@dvarrazzo dvarrazzo added the wheel label Mar 16, 2018

@dvarrazzo dvarrazzo removed the wheel label Apr 17, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment