Date: Sat, 14 Mar 2020 17:12:59 +0100
From: Karsten Hilbert <Karsten.Hilbert@gmx.net>
To: psycopg@lists.postgresql.org, psycopg@postgresql.org
Subject: Re: wire protocol errors on Debian (py3/psyco 2.8)
Message-ID: <20200314161259.GD1104@hermes.hilbert.loc>
Mail-Followup-To: psycopg@lists.postgresql.org, psycopg@postgresql.org
References: <20200314153421.GC1104@hermes.hilbert.loc>
 <1e6ef8fb-1efd-ab1b-7dae-a880b5d53ee0@aklaver.com>
MIME-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <1e6ef8fb-1efd-ab1b-7dae-a880b5d53ee0@aklaver.com>
Ma_X_il-Followup-to: d
Re_X_turn-receipt-to: Karsten.Hilbert@gmx.net
Di_X_sposition-Notification-To: Karsten.Hilbert@gmx.net
X-Confi_X_rm-Reading-To: Karsten.Hilbert@gmx.net
X-Pri_X_ority: 2 (High)
User-Agent: Mutt/1.10.1 (2018-07-13)
Sender: <karsten.hilbert@gmx.net>
X-Provags-ID: V03:K1:loqu/3DER+TQZ8YKHdLXvKlNWwEcaIg9yy3tfcilZSzxDHt7Me3
 GL4Ghluh1jVxVoclJbLtcMFsf28FmXCZXdI7z3E/j53Wun0SGuCQE90m+OecEilfLhmjRkY
 QnXgaPCjoemaKFRwSA2AR7bLPJzkjpY6y5rBeMeNCh39xUiHdNJ0bfrAAqzkc6oQVBkoVX3
 5auj1don9uzj3JB9nxEVw==
X-Spam-Flag: NO
X-UI-Out-Filterresults: notjunk:1;V03:K0:UYN4499RSXc=:1yI4D4G1eBdbMdJSSSvDjg
 O+nUX7nKasc89tkwUgX3irVs3RB5h6vz7rp0Tl2XyDsbhBdk5nO8LpK0GaVNxeicW+oREnSCt
 SERtxXK/9VGDmvkcczeELVC1RpY0RyjVQCx1+KyI4Lk+Up/nlHgm809FDkxHOz2XmPSgiLh96
 r3iib94h/3lHY2coWvE7l42t9PEuLzPOeSylLoRn7E8scJG4aC3i5EgzXDB7VPgWIciyZWFSH
 dYe6KwEULyl+ZczOAc2ZcdNXhiY/5unSWbllC+5bUZ6gWJwsnUm+KPcY3iI1rADv5m+sAlNh2
 sRZ0E5QX2TXQyKSOX+tOz5bpMWF/DFJH5VTCql0qqN8DTdlTG7VtzM/z9s4dcxe6Tc0y8aFCe
 e8bdl6nMNTmJMZac1f1S/alqtZa3j5DSFOY5EHUeDZVazFFrKOTTr7ngGw2hUmQK6lyqa2Gy9
 FU4kTie9bWXoEi0QUEZrc0oVwN8k3C/C0niEpNgNtdZv+DOFbA6VZDnX3IW4EfUnRSjhcVvmO
 M2ToTsQ8P9Kh/uxeSyEj/03guGRug+rpURHbVuIF1t4yCbmSxAbQlYXGP3gBEK+AdxHO03upu
 7CGD0s+F2hUDq6PS+a8tnNnfonyqsR90S7C7R+5oO57BfiZkfll58a0/LYnFoIiwx9l7wMkqL
 C7HfCjw7erd+2jVKcgtOo81rYVd3K+rjX3G5XKqWLtko3vgJpRj/CTDfEbEY0Y+laSW2ssuKn
 45K1/ABsnKkLSB7+FaqTWlkFcuernkEPdULr57KeHusOYflO9nKEuJidk8vu5yHssq6/tcsPK
 FRxzFLa2iu1RVAU/IpDXZF4I6p0qu2+ikSG6Y9O+vBVnNu/d1otzdTofuNHeytFGgE7/svkhT
 4DzoGoRTHD2eMBjlSO0bv9KeKsWMiG/4Vt31hUPtzNNvLPRzIcdfthaDZVMKqaKkv5D+d7v9C
 ZFdn2XV+4nIKSl9EO4826xWm4dABy7jLW1Af5IIvPIFMyaWoxDufvPaJj8V02rCvXPJc1BdJe
 hUtnvHb54z6ZjxvbtORwCCGMNN4h7HgbGaA5yrAbjRVCoDNqOTBIA67kwzq1rdBUe+pePrakC
 NPaty/khy61oaOQlmg0z0vl8JG+pKNnzWKc3RSPHRy+FLoy6fpCygO+wKU/ZehChnuAvelNna
 5naHb0MN5VZU+uv6H0lJ0mZ4+ukRBSe9o7qDNuQmzlBvDW1ktJ6vR7Z5OYNInYiIE74xv0Tlx
 azY4vGH6gVdxCTuZV
Content-Transfer-Encoding: quoted-printable
List-Id: <psycopg.lists.postgresql.org>
List-Help: <https://lists.postgresql.org/manage/>
List-Subscribe: <https://lists.postgresql.org/manage/>
List-Post: <mailto:psycopg@lists.postgresql.org>
List-Owner: <mailto:psycopg-owner@lists.postgresql.org>
List-Archive: <https://www.postgresql.org/list/psycopg>
Precedence: bulk

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/d=
ist-packages/psycopg2/__init__.py'>": API level 2.0, thread safety 2, para=
meter 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 =3D CURR=
ENT_USER and vco.workplace =3D %(wp)s and vco.option =3D %(opt)s and vco.c=
ookie 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=3DNone, queries=3DNone, verbose=3DFalse, retur=
n_data=3DTrue, get_col_idx=3DFalse):
	"""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 =3D link_obj
		curs_close =3D lambda *x:None
		tx_rollback =3D lambda *x:None
		readonly_rollback_just_in_case =3D lambda *x:None
	elif isinstance(link_obj, dbapi._psycopg.connection):
		curs =3D link_obj.cursor()
		curs_close =3D curs.close
		tx_rollback =3D link_obj.rollback
		if link_obj.autocommit is True:		# readonly connection ?
			readonly_rollback_just_in_case =3D 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 =3D lambda *x:None
	elif link_obj is None:
		conn =3D get_connection(readonly =3D True, verbose =3D verbose)
		curs =3D conn.cursor()
		curs_close =3D curs.close
		tx_rollback =3D conn.rollback
		readonly_rollback_just_in_case =3D 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 =3D query['args']
		except KeyError:
			args =3D 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 po=
oled conns
			except PG_ERROR_EXCEPTION as pg_exc2:
				_log.exception('cannot rollback transaction')
				gmConnectionPool.log_pg_exception_details(pg_exc2)
			if pg_exc.pgcode =3D=3D sql_error_codes.INSUFFICIENT_PRIVILEGE:
				details =3D 'Query: [%s]' % curs.query.strip().strip('\n').strip().str=
ip('\n')
				if curs.statusmessage !=3D '':
					details =3D 'Status: %s\n%s' % (
						curs.statusmessage.strip().strip('\n').strip().strip('\n'),
						details
					)
				if pg_exc.pgerror is None:
					msg =3D '[%s]' % pg_exc.pgcode
				else:
					msg =3D '[%s]: %s' % (pg_exc.pgcode, pg_exc.pgerror)
				raise gmExceptions.AccessDenied (
					msg,
					source =3D 'PostgreSQL',
					code =3D pg_exc.pgcode,
					details =3D 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 po=
oled conns
			except PG_ERROR_EXCEPTION as pg_exc:
				_log.exception('cannot rollback transation')
				gmConnectionPool.log_pg_exception_details(pg_exc)
			raise

	data =3D None
	col_idx =3D None
	if return_data:
		data =3D curs.fetchall()
		if verbose:
			_log.debug('last query returned [%s (%s)] rows', curs.rowcount, len(dat=
a))
			_log.debug('cursor description: %s', curs.description)
		if get_col_idx:
			col_idx =3D 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
=2D-
GPG  40BE 5B0E C98E 1713 AFA6  5BC0 3BEA AC80 7D4F C89B