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

[Tatsuo Ishii]

> 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.

Thanks for the info. I assume you mean Flush, rather than Sync.

> 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.

You are right. I have added pool_flush() calls after
SimpleForwardToFrontend() call to make sure that messages are always
flushed. The only concern is, adding extra pool_flush() might cause
performance down. So I did some tests using pgbench -S, and found
nothing has been changed regarding performance after patching.  So
far, so good.
--
Tatsuo Ishii
SRA OSS, Inc. Japan