Re: wire protocol errors on Debian (py3/psyco 2.8) - Mailing list psycopg

Dear Adrian,

unfortunately, we don't have direct contact with the reporter
(only via our mailing list and they haven't answered so far).

> How was psycopg2 installed?

Given they are running a "standard" Debian/Unstable with a
Debian package of GNUmed installed and the matching psycopg2
package version

    psycopg2 module version: 2.8.4 (dt dec pq3 ext lo64)

I suspect they apt-get install'ed it. Which assumption seems
supported by the package file string in:

    PostgreSQL via DB-API module "<module 'psycopg2' from '/usr/lib/python3/dist-packages/psycopg2/__init__.py'>": API
level2.0, thread safety 2, parameter style "pyformat" 

The one thing that's odd is that the Python version

    Python 3.7.6 (default, Jan 19 2020, 22:34:52) <\n>[GCC 9.2.1 20200117] on linux (posix)

does not match what's available from Debian:

    python3:
      Installiert:           3.7.3-1
      Installationskandidat: 3.7.3-1
      Versionstabelle:
         3.8.2-1 500
            500 https://deb.debian.org/debian unstable/main i386 Packages
         3.7.5-3 500
            500 https://deb.debian.org/debian bullseye/main i386 Packages
     *** 3.7.3-1 990
            990 https://deb.debian.org/debian buster/main i386 Packages
            100 /var/lib/dpkg/status

> What is the code being run when the errors are thrown?

It happens (two reports so far) at different stages during
the bringup phase of the GNUmed client. The code being run is
the same, but the time of occurrence is different.

case 1:

    select vco.value from cfg.v_cfg_opts_numeric vco where vco.owner = CURRENT_USER and vco.workplace = %(wp)s and
vco.option= %(opt)s and vco.cookie is null limit 1 

case 2:

    select _(message) from cfg.db_logon_banner

where _() translates "message". This is the Python code being
run (the place of error marked with xxxxx):

def run_ro_queries(link_obj=None, queries=None, verbose=False, return_data=True, get_col_idx=False):
    """Run read-only queries.

    <queries> must be a list of dicts:
        [
            {'cmd': <string>, 'args': <dict> or <tuple>},
            {...},
            ...
        ]
    """
    if isinstance(link_obj, dbapi._psycopg.cursor):
        curs = link_obj
        curs_close = lambda *x:None
        tx_rollback = lambda *x:None
        readonly_rollback_just_in_case = lambda *x:None
    elif isinstance(link_obj, dbapi._psycopg.connection):
        curs = link_obj.cursor()
        curs_close = curs.close
        tx_rollback = link_obj.rollback
        if link_obj.autocommit is True:        # readonly connection ?
            readonly_rollback_just_in_case = link_obj.rollback
        else:
            # do not rollback readonly queries on passed-in readwrite
            # connections just in case because they may have already
            # seen fully legitimate write action which would get lost
            readonly_rollback_just_in_case = lambda *x:None
    elif link_obj is None:
        conn = get_connection(readonly = True, verbose = verbose)
        curs = conn.cursor()
        curs_close = curs.close
        tx_rollback = conn.rollback
        readonly_rollback_just_in_case = conn.rollback
    else:
        raise ValueError('link_obj must be cursor, connection or None but not [%s]' % link_obj)

    if verbose:
        _log.debug('cursor: %s', curs)

    for query in queries:
        try:
            args = query['args']
        except KeyError:
            args = None
        try:
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
            curs.execute(query['cmd'], args)
xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx
            if verbose:
                gmConnectionPool.log_cursor_state(curs)
        except PG_ERROR_EXCEPTION as pg_exc:
            _log.error('query failed in RO connection')
            gmConnectionPool.log_pg_exception_details(pg_exc)
            try:
                curs_close()
            except PG_ERROR_EXCEPTION as pg_exc2:
                _log.exception('cannot close cursor')
                gmConnectionPool.log_pg_exception_details(pg_exc2)
            try:
                tx_rollback()        # need to rollback so ABORT state isn't preserved in pooled conns
            except PG_ERROR_EXCEPTION as pg_exc2:
                _log.exception('cannot rollback transaction')
                gmConnectionPool.log_pg_exception_details(pg_exc2)
            if pg_exc.pgcode == sql_error_codes.INSUFFICIENT_PRIVILEGE:
                details = 'Query: [%s]' % curs.query.strip().strip('\n').strip().strip('\n')
                if curs.statusmessage != '':
                    details = 'Status: %s\n%s' % (
                        curs.statusmessage.strip().strip('\n').strip().strip('\n'),
                        details
                    )
                if pg_exc.pgerror is None:
                    msg = '[%s]' % pg_exc.pgcode
                else:
                    msg = '[%s]: %s' % (pg_exc.pgcode, pg_exc.pgerror)
                raise gmExceptions.AccessDenied (
                    msg,
                    source = 'PostgreSQL',
                    code = pg_exc.pgcode,
                    details = details
                )
            raise
        except Exception:
            _log.exception('error during query run in RO connection')
            gmConnectionPool.log_cursor_state(curs)
            try:
                curs_close()
            except PG_ERROR_EXCEPTION as pg_exc:
                _log.exception('cannot close cursor')
                gmConnectionPool.log_pg_exception_details(pg_exc)
            try:
                tx_rollback()        # need to rollback so ABORT state isn't preserved in pooled conns
            except PG_ERROR_EXCEPTION as pg_exc:
                _log.exception('cannot rollback transation')
                gmConnectionPool.log_pg_exception_details(pg_exc)
            raise

    data = None
    col_idx = None
    if return_data:
        data = curs.fetchall()
        if verbose:
            _log.debug('last query returned [%s (%s)] rows', curs.rowcount, len(data))
            _log.debug('cursor description: %s', curs.description)
        if get_col_idx:
            col_idx = get_col_indices(curs)

    curs_close()
    # so we can see data committed meanwhile if the
    # link object had been passed in and thusly might
    # be part of a long-running read-only transaction
    readonly_rollback_just_in_case()
    return (data, col_idx)


Thanks,
Karsten
--
GPG  40BE 5B0E C98E 1713 AFA6  5BC0 3BEA AC80 7D4F C89B