Instrumentor breaks psycopg2

[vslavik]

Using Python 3.4 and psycopg2 2.6.1, my application is getting exceptions pretty clearly related to proxy types used by the instrumentor:

TypeError: argument 2 must be a connection, cursor or None
  File "celery/app/trace.py", line 240, in trace_task
    R = retval = fun(*args, **kwargs)
  File "CENSORED/__init__.py", line 77, in __call__
    return TaskBase.__call__(self, *args, **kwargs)
  File "celery/app/trace.py", line 438, in __protected_call__
    return self.run(*args, **kwargs)
  File "CENSORED/foo.py", line 238, in a_celery_task_function
    db.session.commit()
  File "sqlalchemy/orm/scoping.py", line 150, in do
    return getattr(self.registry(), name)(*args, **kwargs)
  File "sqlalchemy/orm/session.py", line 790, in commit
    self.transaction.commit()
  File "sqlalchemy/orm/session.py", line 392, in commit
    self._prepare_impl()
  File "sqlalchemy/orm/session.py", line 372, in _prepare_impl
    self.session.flush()
  File "sqlalchemy/orm/session.py", line 2004, in flush
    self._flush(objects)
  File "sqlalchemy/orm/session.py", line 2122, in _flush
    transaction.rollback(_capture_exception=True)
  File "sqlalchemy/util/langhelpers.py", line 60, in __exit__
    compat.reraise(exc_type, exc_value, exc_tb)
  File "sqlalchemy/util/compat.py", line 182, in reraise
    raise value
  File "sqlalchemy/orm/session.py", line 2086, in _flush
    flush_context.execute()
  File "sqlalchemy/orm/unitofwork.py", line 373, in execute
    rec.execute(self)
  File "sqlalchemy/orm/unitofwork.py", line 532, in execute
    uow
  File "sqlalchemy/orm/persistence.py", line 149, in save_obj
    base_mapper, states, uowtransaction
  File "sqlalchemy/orm/persistence.py", line 270, in _organize_states_for_save
    states):
  File "sqlalchemy/orm/persistence.py", line 1032, in _connections_for_states
    connection = uowtransaction.transaction.connection(base_mapper)
  File "sqlalchemy/orm/session.py", line 232, in connection
    return self._connection_for_bind(bind, execution_options)
  File "sqlalchemy/orm/session.py", line 323, in _connection_for_bind
    conn = self._parent._connection_for_bind(bind, execution_options)
  File "sqlalchemy/orm/session.py", line 334, in _connection_for_bind
    conn = bind.contextual_connect()
  File "sqlalchemy/engine/base.py", line 2039, in contextual_connect
    self._wrap_pool_connect(self.pool.connect, None),
  File "sqlalchemy/engine/base.py", line 2074, in _wrap_pool_connect
    return fn()
  File "sqlalchemy/pool.py", line 376, in connect
    return _ConnectionFairy._checkout(self)
  File "sqlalchemy/pool.py", line 713, in _checkout
    fairy = _ConnectionRecord.checkout(pool)
  File "sqlalchemy/pool.py", line 480, in checkout
    rec = pool._do_get()
  File "sqlalchemy/pool.py", line 1060, in _do_get
    self._dec_overflow()
  File "sqlalchemy/util/langhelpers.py", line 60, in __exit__
    compat.reraise(exc_type, exc_value, exc_tb)
  File "sqlalchemy/util/compat.py", line 182, in reraise
    raise value
  File "sqlalchemy/pool.py", line 1057, in _do_get
    return self._create_connection()
  File "sqlalchemy/pool.py", line 323, in _create_connection
    return _ConnectionRecord(self)
  File "sqlalchemy/pool.py", line 455, in __init__
    pool.dispatch.connect(self.connection, self)
  File "sqlalchemy/event/attr.py", line 256, in __call__
    fn(*args, **kw)
  File "sqlalchemy/engine/strategies.py", line 156, in on_connect
    do_on_connect(conn)
  File "sqlalchemy/dialects/postgresql/psycopg2.py", line 668, in on_connect
    fn(conn)
  File "sqlalchemy/dialects/postgresql/psycopg2.py", line 632, in on_connect
    extras.register_uuid(None, conn)
  File "psycopg2/extras.py", line 487, in register_uuid
    _ext.register_type(_ext.UUID, conn_or_curs)

They don't happen w/o Librato instrumentor enabled.

Details of relevant packages used:

amqp==1.4.6
anyjson==0.3.3
billiard==3.3.0.20
blinker==1.4
celery==3.1.18
Flask==0.10.1
Flask-SQLAlchemy==2.0
gevent==1.1b3
greenlet==0.4.9
itsdangerous==0.24
Jinja2==2.8
kombu==3.0.26
librato-metrics==0.8.6
MarkupSafe==0.23
psycopg2==2.6.1
pytz==2015.4
raven==5.7.2
redis==2.10.3
requests==2.7.0
six==1.10.0
SQLAlchemy==1.0.8
statsd==3.2.1
Werkzeug==0.10.4
-e git+git://github.com/librato/librato-python-web.git@6a2f927c39e5eb30e3a2a0d45670adfa4aa8fa44#egg=librato-python-web

[vaidyg]

As a temporary workaround, agent-conf.json can specify a "libraries" option which you can use to disable psycopg2. There isn't a way to exclude a library yet, so you'll need to specify the ones you want. E.g. { ... "libraries": ["flask", "logging", ...] }

[hheimbuerger]

I have a related issue when using the psycopg2 instrumentation on Heroku.

I'm running Python 2.7 and psycopg2 2.6.1 (which is the latest version on PyPI and the version listed as "tested" in your readme). I'm using the librato-launch integration.

[EXCEPTION] librato_python_web.instrumentor.bootstrap - Error instrumenting psycopg2
Traceback (most recent call last):
  File "/app/.heroku/python/lib/python2.7/site-packages/librato_python_web/instrumentor/bootstrap.py", line 178, in import2
    instrumentor.run()
  File "/app/.heroku/python/lib/python2.7/site-packages/librato_python_web/instrumentor/data/psycopg2.py", line 55, in run
    super(Psycopg2Instrumentor, self).run()
  File "/app/.heroku/python/lib/python2.7/site-packages/librato_python_web/instrumentor/base_instrumentor.py", line 66, in run
    override_classes(self.overridden_classes, self.wrapped)
  File "/app/.heroku/python/lib/python2.7/site-packages/librato_python_web/instrumentor/instrument.py", line 108, in override_classes
    wrap_methods(cls, targeted_methods, wrapped)
  File "/app/.heroku/python/lib/python2.7/site-packages/librato_python_web/instrumentor/instrument.py", line 166, in wrap_methods
    overrides[targeted_method] = wrapped_returned_instance(target, targeted_method, return_type, rules)
  File "/app/.heroku/python/lib/python2.7/site-packages/librato_python_web/instrumentor/instrument.py", line 190, in wrapped_returned_instance
    original_method = getattr(cls, targeted_method)
AttributeError: 'module' object has no attribute 'connect'

This is reproducible (occurs multiple times on every launch). Explicitly disabling the psycopg2 instrumentation with the libraries option prevents it.

[vaidyg]

Thanks, Henrik. We'll investigate and provide a fix asap.

[vaidyg]

Hi Henrik. We've pushed version 0.40.2, which has a fix for this issue. Please let us know if that resolves the problem you're seeing. Thanks!

[hheimbuerger]

@vaidy4github Unfortunately, that didn't fix it. Using psycopg2==2.6.1 and librato-python-web==0.40.2 on Python 2.7, I'm getting the following (slighly different) stacktrace the first time I'm querying my Postgres DB:

ERROR [Web/django.request] Internal Server Error: /login/ 
Traceback (most recent call last): 
  File "/app/.heroku/python/lib/python2.7/site-packages/django/core/handlers/base.py", line 132, in get_response 
    response = wrapped_callback(request, *callback_args, **callback_kwargs) 
  [... internal stack frames which lead to the first database call ...]
  File "/app/.heroku/python/lib/python2.7/site-packages/django/db/models/manager.py", line 127, in manager_method 
    return getattr(self.get_queryset(), name)(*args, **kwargs) 
  File "/app/.heroku/python/lib/python2.7/site-packages/librato_python_web/instrumentor/instrument.py", line 429, in wrapper 
    return f.__get__(self)(*args[1:], **keywords) 
  File "/app/.heroku/python/lib/python2.7/site-packages/django/db/models/query.py", line 328, in get 
    num = len(clone) 
  File "/app/.heroku/python/lib/python2.7/site-packages/django/db/models/query.py", line 144, in __len__ 
    self._fetch_all() 
  File "/app/.heroku/python/lib/python2.7/site-packages/django/db/models/query.py", line 965, in _fetch_all 
    self._result_cache = list(self.iterator()) 
  File "/app/.heroku/python/lib/python2.7/site-packages/django/db/models/query.py", line 238, in iterator 
    results = compiler.execute_sql() 
  File "/app/.heroku/python/lib/python2.7/site-packages/django/db/models/sql/compiler.py", line 840, in execute_sql 
    cursor.execute(sql, params) 
  File "/app/.heroku/python/lib/python2.7/site-packages/django/db/backends/utils.py", line 64, in execute 
    return self.cursor.execute(sql, params) 
  File "/app/.heroku/python/lib/python2.7/site-packages/librato_python_web/instrumentor/instrument.py", line 435, in wrapper 
    return f(*args, **keywords) 
TypeError: descriptor 'execute' requires a 'psycopg2.extensions.cursor' object but received a 'cursor' 

[jstockdale]

+1 we're seeing this issue currently

[jlev]

Still getting this issue with librato-python-web==0.50 and psycopg2==2.7.1 on Heroku

I was able to work around by explicitly setting libraries without psycopg2 in agent-conf.json

My traceback:

TypeError: cursor() got an unexpected keyword argument 'cursor_factory'
  File "django/core/handlers/exception.py", line 41, in inner
    response = get_response(request)
  File "django/core/handlers/base.py", line 244, in _legacy_get_response
    response = middleware_method(request)
  File "temba/middleware.py", line 94, in process_request
    if not user.is_anonymous():
  File "django/utils/functional.py", line 238, in inner
    self._setup()
  File "django/utils/functional.py", line 386, in _setup
    self._wrapped = self._setupfunc()
  File "django/contrib/auth/middleware.py", line 24, in <lambda>
    request.user = SimpleLazyObject(lambda: get_user(request))
  File "django/contrib/auth/middleware.py", line 12, in get_user
    request._cached_user = auth.get_user(request)
  File "django/contrib/auth/__init__.py", line 217, in get_user
    user = backend.get_user(user_id)
  File "django/contrib/auth/backends.py", line 102, in get_user
    user = UserModel._default_manager.get(pk=user_id)
  File "django/db/models/manager.py", line 85, in manager_method
    return getattr(self.get_queryset(), name)(*args, **kwargs)
  File "librato_python_web/instrumentor/instrument.py", line 161, in delegator
    return wrapper_method(original_method, *args, **kwargs)
  File "librato_python_web/instrumentor/instrument.py", line 109, in complex_wrapper
    return func(*args, **keywords)
  File "django/db/models/query.py", line 374, in get
    num = len(clone)
  File "django/db/models/query.py", line 232, in __len__
    self._fetch_all()
  File "django/db/models/query.py", line 1118, in _fetch_all
    self._result_cache = list(self._iterable_class(self))
  File "django/db/models/query.py", line 53, in __iter__
    results = compiler.execute_sql(chunked_fetch=self.chunked_fetch)
  File "django/db/models/sql/compiler.py", line 882, in execute_sql
    cursor = self.connection.cursor()
  File "django/db/backends/base/base.py", line 254, in cursor
    return self._cursor()
  File "django/db/backends/base/base.py", line 229, in _cursor
    self.ensure_connection()
  File "django/db/backends/base/base.py", line 213, in ensure_connection
    self.connect()
  File "django/db/backends/base/base.py", line 192, in connect
    connection_created.send(sender=self.__class__, connection=self)
  File "django/dispatch/dispatcher.py", line 193, in send
    for receiver in self._live_receivers(sender)
  File "django/contrib/postgres/signals.py", line 14, in register_type_handlers
    register_hstore(connection.connection, globally=True, unicode=True)
  File "psycopg2/extras.py", line 949, in register_hstore
    oid = HstoreAdapter.get_oids(conn_or_curs)
  File "psycopg2/extras.py", line 888, in get_oids
    conn, curs = _solve_conn_curs(conn_or_curs)
  File "psycopg2/extras.py", line 775, in _solve_conn_curs
    curs = conn.cursor(cursor_factory=_cursor)