Subject: Re: wire protocol errors on Debian (py3/psyco 2.8)
To: psycopg@lists.postgresql.org, psycopg@postgresql.org
References: <20200314153421.GC1104@hermes.hilbert.loc>
 <1e6ef8fb-1efd-ab1b-7dae-a880b5d53ee0@aklaver.com>
 <20200314161259.GD1104@hermes.hilbert.loc>
From: Adrian Klaver <adrian.klaver@aklaver.com>
Message-ID: <5e856c69-00fd-900a-0635-bc434503e204@aklaver.com>
Date: Sat, 14 Mar 2020 09:26:39 -0700
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:68.0) Gecko/20100101
 Thunderbird/68.5.0
MIME-Version: 1.0
In-Reply-To: <20200314161259.GD1104@hermes.hilbert.loc>
Content-Type: text/plain; charset=utf-8; format=flowed
Content-Language: en-US
Content-Transfer-Encoding: 7bit
Precedence: bulk

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.klaver@aklaver.com