[pgpool-general: 1661] Extended protocol error reemerged?
Сергей Мелехин
cpro29a at gmail.com
Wed Apr 24 09:58:51 JST 2013
Hello!
I tried to connect to my pgpool-II 3.2.3 instance using py-postgresql
library (it uses extended protocol) and failed with the following error:
---------------------------------------------------
>>> c = postgresql.open('pq://postgres:***@dev01:5434/hr')
Traceback (most recent call last):
File "<stdin>", line 1, in <module>
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/__init__.py",
line 94, in open
c.connect()
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/driver/pq3.py",
line 2438, in connect
self._establish()
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/driver/pq3.py",
line 2578, in _establish
sd = self.sys.startup_data()
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/lib/__init__.py",
line 398, in __getattr__
bs = BoundSymbol(sym, db)
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/lib/__init__.py",
line 288, in __init__
ps = database.prepare(symbol)
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/driver/pq3.py",
line 2346, in prepare
ps._fini()
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/driver/pq3.py",
line 1454, in _fini
self.database._pq_complete()
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/driver/pq3.py",
line 2618, in _pq_complete
self.typio.raise_error(x.error_message, cause = getattr(x, 'exception',
None))
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/driver/pq3.py",
line 509, in raise_error
self.raise_client_error(error_message, **kw)
File
"/home/kb_iface/env/lib/python3.2/site-packages/postgresql/driver/pq3.py",
line 484, in raise_client_error
raise client_error
postgresql.exceptions.ConnectionFailureError: unexpected EOF from server
CODE: 08006
LOCATION: CLIENT
DETAIL: Zero-length read from the connection's socket.
STATEMENT: [parsing]
statement_id: py:0xcffa90
string:
SYMBOL: startup_data
source:
SELECT
pg_catalog.version()::text AS version,
backend_start::text,
client_addr::text,
client_port::int
FROM pg_catalog.pg_stat_activity WHERE pid =
pg_catalog.pg_backend_pid()
UNION ALL SELECT
pg_catalog.version()::text AS version,
NULL::text AS backend_start,
NULL::text AS client_addr,
NULL::int AS client_port
LIMIT 1;
LIBRARY:
/home/kb_iface/env/lib/python3.2/site-packages/postgresql/lib/libsys.sql
CONNECTION: [closed]
CONNECTOR: [Host] pq://postgres:***@dev01:5434/hr
category: None
DRIVER: postgresql.driver.pq3.Driver
-----------------------------------------------------------------------------------
Corresponding log from pgpool contains "Close: cannot get parse message",
which lead me to this bugreport
http://www.sraoss.jp/pipermail/pgpool-general/2012-August/000898.html
I looked through 3.2.3 code, and it seems that patch, that should have
fixed this is there
http://git.postgresql.org/gitweb/?p=pgpool2.git;a=commitdiff;h=479e9d1416ff0294519e9155084bc1d60c75c850;hp=8af289e6d02ce29f0f5d0ca04dee6992a2cb258d
But error stil reproduces.
Here is pgpool log with debugging enabled:
--------------------------------------
Apr 24 04:36:34 dev01 pgpool[14047]: I am 14047 accept fd 8
Apr 24 04:36:34 dev01 pgpool[14047]: connection received: host=dev01
port=50093
Apr 24 04:36:34 dev01 pgpool[14047]: Protocol Major: 1234 Minor: 5679
database: user:
Apr 24 04:36:34 dev01 pgpool[14047]: SSLRequest from client
Apr 24 04:36:34 dev01 pgpool[14047]: pool_ssl: SSL requested but SSL
support is not available
Apr 24 04:36:34 dev01 pgpool[14047]: Protocol Major: 3 Minor: 0 database:
hr user: postgres
Apr 24 04:36:34 dev01 pgpool[14047]: new_connection: connecting 0 backend
Apr 24 04:36:34 dev01 pgpool[14047]: new_connection: connecting 1 backend
Apr 24 04:36:34 dev01 pgpool[14047]: pool_ssl: SSL requested but SSL
support is not available
Apr 24 04:36:34 dev01 pgpool[14047]: pool_ssl: SSL requested but SSL
support is not available
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length: slot: 0
length: 12
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length: slot: 1
length: 12
Apr 24 04:36:34 dev01 pgpool[14047]: pool_do_auth: auth kind:5
Apr 24 04:36:34 dev01 pgpool[14047]: trying md5 authentication
Apr 24 04:36:34 dev01 pgpool[14047]: DB node id: 0 salt: d61f8565
Apr 24 04:36:34 dev01 pgpool[14047]: trying md5 authentication
Apr 24 04:36:34 dev01 pgpool[14047]: DB node id: 1 salt: 68cc7e18
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 22
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 22
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: application_name
value:
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: application_name
value:
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 25
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 25
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: client_encoding
value: UTF8
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: client_encoding
value: UTF8
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 23
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 23
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: DateStyle value:
ISO, MDY
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: DateStyle value:
ISO, MDY
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 25
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 25
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: integer_datetimes
value: on
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: integer_datetimes
value: on
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 27
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 27
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: IntervalStyle
value: postgres
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: IntervalStyle
value: postgres
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 20
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 20
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: is_superuser
value: on
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: is_superuser
value: on
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 25
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 25
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: server_encoding
value: UTF8
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: server_encoding
value: UTF8
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 25
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 25
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: server_version
value: 9.2.4
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: server_version
value: 9.2.4
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 35
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 35
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name:
session_authorization value: postgres
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name:
session_authorization value: postgres
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 35
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 35
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name:
standard_conforming_strings value: on
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name:
standard_conforming_strings value: on
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 0 length: 17
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length2: master
slot: 1 length: 17
Apr 24 04:36:34 dev01 pgpool[14047]: 0 th backend: name: TimeZone value: GMT
Apr 24 04:36:34 dev01 pgpool[14047]: 1 th backend: name: TimeZone value: GMT
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length: slot: 0
length: 12
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length: slot: 1
length: 12
Apr 24 04:36:34 dev01 pgpool[14047]: pool_do_auth:
cp->info[i]:0x7f47c3e4f000 pid:21018
Apr 24 04:36:34 dev01 pgpool[14047]: pool_do_auth:
cp->info[i]:0x7f47c3e4f088 pid:19510
Apr 24 04:36:34 dev01 pgpool[14047]: pool_send_auth_ok: send pid 19510 to
frontend
Apr 24 04:36:34 dev01 pgpool[14047]: select_load_balancing_node: selected
backend id is 0
Apr 24 04:36:34 dev01 pgpool[14047]: selected load balancing node: 0
Apr 24 04:36:34 dev01 pgpool[14047]: pool_unset_query_in_progress: done
Apr 24 04:36:34 dev01 pgpool[14047]: pool_unset_command_success: done
Apr 24 04:36:34 dev01 pgpool[14047]: pool_unset_writing_transaction: done
Apr 24 04:36:34 dev01 pgpool[14047]: pool_unset_failed_transaction: done
Apr 24 04:36:34 dev01 pgpool[14047]: pool_unset_transaction_isolation: done
Apr 24 04:36:34 dev01 pgpool[14047]: pool_unset_skip_reading_from_backends:
done
Apr 24 04:36:34 dev01 pgpool[14047]: pool_unset_ignore_till_sync: done
Apr 24 04:36:34 dev01 pgpool[14047]: read_kind_from_one_backend: read kind
from 0 th backend Z
Apr 24 04:36:34 dev01 pgpool[14047]: read_kind_from_backend: kind: Z from 0
th backend
Apr 24 04:36:34 dev01 pgpool[14047]: read_kind_from_backend: read kind from
0 th backend Z NUM_BACKENDS: 2
Apr 24 04:36:34 dev01 pgpool[14047]: read_kind_from_backend: kind: Z from 1
th backend
Apr 24 04:36:34 dev01 pgpool[14047]: read_kind_from_backend: read kind from
1 th backend Z NUM_BACKENDS: 2
Apr 24 04:36:34 dev01 pgpool[14047]: ProcessBackendResponse: kind from
backend: Z
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length: slot: 0
length: 5
Apr 24 04:36:34 dev01 pgpool[14047]: pool_read_message_length: slot: 1
length: 5
Apr 24 04:36:34 dev01 pgpool[14047]: ReadyForQuery: transaction state:
Apr 24 04:36:34 dev01 pgpool[14047]: ReadyForQuery: transaction state:I
Apr 24 04:36:34 dev01 pgpool[14047]: ProcessBackendResponse: Ready For Query
Apr 24 04:36:34 dev01 pgpool[14047]: ProcessFrontendResponse: kind from
frontend C(43)
Apr 24 04:36:34 dev01 pgpool[14047]:
pool_unset_doing_extended_query_message: done
Apr 24 04:36:34 dev01 pgpool[14047]: pool_set_query_in_progress: done
Apr 24 04:36:34 dev01 pgpool[14047]: Close: cannot get parse message
Apr 24 04:36:34 dev01 pgpool[14047]: do_child: exits with status 1 due to
error
Apr 24 04:36:34 dev01 pgpool[14014]: reap_handler called
Apr 24 04:36:34 dev01 pgpool[14014]: reap_handler: call wait3
Apr 24 04:36:34 dev01 pgpool[14014]: child 14047 exits with status 256
Apr 24 04:36:34 dev01 pgpool[14014]: fork a new child pid 21019
Apr 24 04:36:34 dev01 pgpool[14014]: reap_handler: normally exited
----------------------------
Meanwhile psycopg2 based python app connects and works successfuly, psql
and other tools connect and work too.
If I change connection string to
postgresql.open('pq://postgres:***@localhost:5432/hr')
to connect to postgresql directly - all works perfectly.
Please, help!
I use py-postgresql 1.1.0, python 3.2.3, pgpool 3.2.3, postgresql 9.2.4
I have 2 postgres instances in streaming replication and pgpool2 configured
for load balancing - it works ok if I try from psql or pgadmin.
With best regards, Sergey Melekhin
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.sraoss.jp/pipermail/pgpool-general/attachments/20130424/3e9c83ff/attachment-0001.html>
More information about the pgpool-general
mailing list