Re: wire protocol errors on Debian (py3/psyco 2.8)

On 3/14/20 9:12 AM, Karsten Hilbert wrote:
> 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 level 2.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

To me resolving the above would help with the below.

I have to go out shortly and will not be able to look over the below in
detail until later.

>
>> 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
>
>

--
Adrian Klaver
adrian(dot)klaver(at)aklaver(dot)com