[Pgpool-hackers] Fwd: Bug in SimpleForwardToFrontend()

[Gavin Sherry]

Hi all,

I hit an obscure bug in 2.2.2, which is also present in HEAD.

Here's the backend debugging output:

2009-06-24 15:12:37 DEBUG: pid 55600: new_connection: connecting 0 backend
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length: slot: 0
length: 8
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 25
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: client_encoding
value: UTF8
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 23
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: DateStyle value:
ISO, MDY
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 25
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: integer_datetimes
value: on
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 27
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: IntervalStyle
value: postgres
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 20
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: is_superuser
value: on
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 25
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: server_encoding
value: UTF8
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 26
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: server_version
value: 8.2.13
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 30
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name:
session_authorization value: swm
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 36
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name:
standard_conforming_strings value: off
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length2: master
slot: 0 length: 26
2009-06-24 15:12:37 DEBUG: pid 55600: 0 th backend: name: TimeZone value:
Europe/Paris
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length: slot: 0
length: 12
2009-06-24 15:12:37 DEBUG: pid 55600: pool_send_auth_ok: send pid 55633 to
frontend
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend Z NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: pool_process_query: kind from backend:
Z
2009-06-24 15:12:37 DEBUG: pid 55600: pool_read_message_length: slot: 0
length: 5
2009-06-24 15:12:37 DEBUG: pid 55600: ReadyForQuery: message length: 5
2009-06-24 15:12:37 DEBUG: pid 55600: ReadyForQuery: transaction state: I
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend P(50)
2009-06-24 15:12:37 DEBUG: pid 55600: Parse: portal name
<pg8000_statement_0>
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend 1 NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44)
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend t NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend n NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48)
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend P(50)
2009-06-24 15:12:37 DEBUG: pid 55600: Parse: portal name
<pg8000_statement_1>
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend 1 NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44)
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend t NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend n NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48)
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend P(50)
2009-06-24 15:12:37 DEBUG: pid 55600: Parse: portal name
<pg8000_statement_2>
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend 1 NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44)
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend t NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend n NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48)
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend P(50)
2009-06-24 15:12:37 DEBUG: pid 55600: Parse: portal name <>
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend 1 NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44)
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend t NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend T NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48)
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend B(42)
2009-06-24 15:12:37 DEBUG: pid 55600: bind message: portal_name
pg8000_portal_3 stmt_name
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend 2 NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend D(44)
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend T NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48)
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend E(45)
2009-06-24 15:12:37 DEBUG: pid 55600: Execute: portal name <pg8000_portal_3>
2009-06-24 15:12:37 DEBUG: pid 55600: waiting for backend completing the
query
2009-06-24 15:12:37 DEBUG: pid 55600: read_kind_from_backend: read kind from
0 th backend C NUM_BACKENDS: 1
2009-06-24 15:12:37 DEBUG: pid 55600: read kind from frontend H(48)

We hang there indefinitely.

As it turns out, the C (command complete) message from the backend is never
forwarded to the front end. There's nothing left to be sync'd when we
forward the 'H' (sync) message so everyone waits forever.

Attached is a simple patch which resolves this issue.

The function itself seems dangerous to me. We should probably make sure we
flush all messages, always. This will future proof pgpool against protocol
changes and further bugs.

Thanks,
Gavin
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://pgfoundry.org/pipermail/pgpool-hackers/attachments/20090624/9ac840e5/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: flush.diff
Type: application/octet-stream
Size: 649 bytes
Desc: not available
URL: <http://pgfoundry.org/pipermail/pgpool-hackers/attachments/20090624/9ac840e5/attachment.obj>