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

From: Karsten Hilbert <[email-masked]>
Date: Sat, 14 Mar 2020 16:34:21 +0100

Hi all,

we have two reports for psycopg2 2.8 under Python 3 on Debian
showing a problem with the wire protocol (full logs appended):

 psycopg2.OperationalError: datos insuficientes en el mensaje «T»

or

 psycopg2.DatabaseError: el contenido del mensaje no concuerda con el largo, en el mensaje tipo «C»

The error happens at different times when running the same
code. The  versions involved:

 psycopg2 module version: 2.8.4 (dt dec pq3 ext lo64)
 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"
 libpq version (compiled in): 120000
 libpq version (loaded now) : 120002

 Platform: uname_result(system='Linux', node='Epigen7', release='5.4.0-4-amd64', version='#1 SMP Debian 5.4.19-1 (2020-02-13)', machine='x86_64', processor='')

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

 lsb_release: {'ID': 'Debian', 'OS': 'GNU/Linux', 'DESCRIPTION': 'Debian GNU/Linux bullseye/sid', 'RELEASE': 'testing', 'CODENAME': 'bullseye'}

 threading: sys.thread_info(name='pthread', lock='semaphore', version='NPTL 2.29')

We don't yet know the exact version of PostgreSQL this is
running against but it is likely 12.2-1+b1 from
Debian/Unstable.

Any ideas or hints what to look at next ?

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

---

From: Adrian Klaver <[email-masked]>
Date: Sat, 14 Mar 2020 08:49:01 -0700

> Any ideas or hints what to look at next ?

How was psycopg2 installed?

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

-- 
Adrian Klaver
[email-masked]

---

From: Karsten Hilbert <[email-masked]>
Date: Sat, 14 Mar 2020 17:12:59 +0100

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

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

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

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

---

From: Adrian Klaver <[email-masked]>
Date: Sat, 14 Mar 2020 09:26:39 -0700

> 	  Installationskandidat: 3.7.3-1

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.

---

From: Karsten Hilbert <[email-masked]>
Date: Sat, 14 Mar 2020 18:41:26 +0100

> To me resolving the above would help with the below.

I know, that would have been my first guess, too. I will see
whether OP will return with data.

Karsten

---

From: Adrian Klaver <[email-masked]>
Date: Sat, 14 Mar 2020 11:16:50 -0700

> whether OP will return with data.

Yeah, I just know that there have been problems with the wheel(binary) 
installs of psycopg2 and mismatched external libraries:

https://www.psycopg.org/docs/install.html
Binary install from PyPI

I could see that also happening if you are using a disto build of a 
package(psycopg2) with a third party build of Python.

FYI, when I was trying to figure out the install procedure for GNUmed 
this link:

https://www.gnumed.de/documentation/InstallerGuideHome

threw a 404 error.

---

From: Daniele Varrazzo <[email-masked]>
Date: Sun, 15 Mar 2020 08:35:36 +1300

...

...

> Any ideas or hints what to look at next ?

The error comes from the libpq failing to parse messages from the server
(at a glance CommandComplete and RowDescription - see
https://www.postgresql.org/docs/current/protocol-message-formats.html)
which are probably just the most common ones.

I doubt it's a bug with libpq 12.2 or whatever server is on the other side
of the wire: we would have seen this error more often. If you want to
investigate in that direction you may ask core devs if there have been
changes in that area for those versions.

My wild guess is either faulty network or faulty memory on the machine,
most likely the latter.

-- Daniele

---

From: Adrian Klaver <[email-masked]>
Date: Sat, 14 Mar 2020 13:12:04 -0700

> 	  Installationskandidat: 3.7.3-1

Went through the function and the attached logs from the OP. I do not 
pretend to understand all of what the logs are showing. Still I do not 
see anything that stands out to me.

---

From: Adrian Klaver <[email-masked]>
Date: Sat, 14 Mar 2020 13:29:58 -0700

On 3/14/20 12:35 PM, Daniele Varrazzo wrote:

> I doubt it's a bug with libpq 12.2 or whatever server is on the other 
> side of the wire: we would have seen this error more often. If you want 
> to investigate in that direction you may ask core devs if there have 
> been changes in that area for those versions.

I did run across this:

https://www.postgresql.org/docs/12/release-12-2.html

"

Fix bugs in handling of non-blocking I/O when using GSSAPI encryption 
(Tom Lane)

These errors could result in dropping data (usually leading to 
subsequent wire-protocol-violation errors) or in a “livelock” situation 
where a sending process goes to sleep although not all its data has been 
sent. Moreover, libpq failed to keep separate encryption state for each 
connection, creating the possibility for failures in applications using 
multiple encrypted database connections.
"

Would be nice to know what actual Postgres version is and how it is 
configured?

---

From: Karsten Hilbert <[email-masked]>
Date: Sat, 14 Mar 2020 21:49:24 +0100

On Sat, Mar 14, 2020 at 01:29:58PM -0700, Adrian Klaver wrote:

> Fix bugs in handling of non-blocking I/O when using GSSAPI encryption (Tom
> Lane)
>
> These errors could result in dropping data (usually leading to subsequent
> wire-protocol-violation errors) or in a “livelock” situation where a sending
> process goes to sleep although not all its data has been sent. Moreover,
> libpq failed to keep separate encryption state for each connection, creating
> the possibility for failures in applications using multiple encrypted
> database connections.
> "
>

As long as OP doesn't get back in touch we probably can't do
much more. Many thanks for providing insights.

I'll post more if more info becomes available.

Thanks,
Karsten

---

From: Karsten Hilbert <[email-masked]>
Date: Sun, 15 Mar 2020 20:58:44 +0100

> FYI, when I was trying to figure out the install procedure for GNUmed

Thanks for bothering.

> https://www.gnumed.de/documentation/InstallerGuideHome

Thanks for reporting. I am slowly rebuilding the documention
after a foswiki proved to insecure ;-)

Here's the new site:

	https://www.gnumed.de

I have uploaded a *minimal* installation sort-of-guide:

	https://www.gnumed.de/documentation/GNUmedInstallation.html

HTH,
Karsten