Feature: add log_backend_messages.

When enabled, log protocol messages from each backend. Possible
options are "none", "terse" and "verbose". "none" disables the feature
and is the default. "verbose" prints the log each time pgpool receives
a message from backend. "terse" is similar to verbose except it does
not print logs for repeated message to save log lines. If different
kind of message received, pgpool prints a log message including the
number of the message. One downside of "terse" is, the repeated
message will not be printed if the pgpool child process is killed
before different kind of message arrives.

For testing, 039.log_backend_messages is added.

Discussion: [pgpool-hackers: 4535] New feature: log_backend_messages
https://www.pgpool.net/pipermail/pgpool-hackers/2024-November/004536.html

diff --git a/doc.ja/src/sgml/connection-pooling.sgml b/doc.ja/src/sgml/connection-pooling.sgml
index 317263fa0db422a5595c4c4a1b649e46590c0c4c..66980ce8db64a14c68393e4e5227163800138b9c 100644 (file)
--- a/doc.ja/src/sgml/connection-pooling.sgml
+++ b/doc.ja/src/sgml/connection-pooling.sgml
@@ -1207,6 +1207,57 @@ local0.*    /var/log/pgpool.log
      </para>
     </listitem>
    </varlistentry>
+
+   <varlistentry id="guc-log-backend-messages" xreflabel="log_backend_messages">
+    <term><varname>log_backend_messages</varname> (<type>boolean</type>)
+     <indexterm>
+      <!--
+      <primary><varname>log_backend_messages</varname> configuration parameter</primary>
+      -->
+      <primary><varname>log_backend_messages</varname> 設定パラメータ</primary>
+     </indexterm>
+    </term>
+    <listitem>
+     <para>
+      <!--
+      Setting to <literal>terse</literal>
+      or <literal>verbose</literal>, prints backend messages to the
+      log.  With <literal>terse</literal> the number of same kind of
+      messages are recorded and is printed when different kind of
+      messages is sent. Below is an example.
+      <programlisting>
+       LOG:  last DataRow message from backend 0 repeated 10 times
+      </programlisting>
+      Thus the log will not be printed if the process corresponding to
+      the session is killed. If you want to print the log even in this
+      case, use <literal>verbose</literal> option. Note that with the
+      option each repeated message is printed and lots of log lines
+      are printed. The default is <literal>none</literal>, which
+      disables printing log messages from backend.
+      -->
+      <literal>terse</literal>または<literal>verbose</literal>に設定されている場合、バックエンドからのメッセージをログ出力します
+      <literal>terse</literal>では、同じ種類のメッセージが同じバックエンドから送られてくると、その回数を記録し、次に異なる種類のメセージが送られてきた時に繰り返し回数を報告します。
+      出力例を示します。
+      <programlisting>
+       LOG:  last DataRow message from backend 0 repeated 10 times
+      </programlisting>
+      したがって、繰り返している最中にセッションに対応するプロセスが強制終了すると、その分のログが出力されません。
+      この場合でもすべてのログを出力するには、<literal>verbose</literal>オプションを使用します。
+      ただし、このオプションでは繰り返し回数分だけの行のログが出力されるので、大量のメッセージがバックエンドから送られてくる場合は注意が必要です。
+      デフォルトは<literal>none</literal>で、バックエンドからのメッセージをログ出力しません。
+     </para>
+     <para>
+      <!--
+      This parameter can be changed by reloading the <productname>Pgpool-II</> configurations.
+      You can also use <xref linkend="SQL-PGPOOL-SET"> command to alter the value of
+      this parameter for a current session.
+      -->
+      このパラメータは、<productname>Pgpool-II</>の設定を再読み込みすることで変更可能です。
+      現在のセッションでのパラメータ値は、<xref linkend="SQL-PGPOOL-SET">コマンドで変更することもできます。
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry id="guc-log-hostname" xreflabel="log_hostname">
     <term><varname>log_hostname</varname> (<type>boolean</type>)
      <indexterm>

diff --git a/doc/src/sgml/connection-pooling.sgml b/doc/src/sgml/connection-pooling.sgml
index 439f2208e81dc70db9c1b4e0e98e68bbe31e5ba2..aff34b94b8f662f3541d6c1af6b2f5c2b0a56b0c 100644 (file)
--- a/doc/src/sgml/connection-pooling.sgml
+++ b/doc/src/sgml/connection-pooling.sgml
@@ -777,6 +777,38 @@
     </listitem>
    </varlistentry>
 
+   <varlistentry id="guc-log-backend-messages" xreflabel="log_backend_messages">
+    <term><varname>log_backend_messages</varname> (<type>boolean</type>)
+     <indexterm>
+      <primary><varname>log_backend_messages</varname> configuration parameter</primary>
+     </indexterm>
+    </term>
+    <listitem>
+     <para>
+      Setting to <literal>terse</literal>
+      or <literal>verbose</literal>, prints backend messages to the
+      log.  With <literal>terse</literal> the number of same kind of
+      messages are recorded and is printed when different kind of
+      messages is sent. Below is an example.
+      <programlisting>
+       LOG:  last DataRow message from backend 0 repeated 10 times
+      </programlisting>
+      Thus the log will not be printed if the process corresponding to
+      the session is killed. If you want to print the log even in this
+      case, use <literal>verbose</literal> option. Note that with the
+      option each repeated message is printed and lots of log lines
+      are printed. The default is <literal>none</literal>, which
+      disables printing log messages from backend.
+     </para>
+     <para>
+      This parameter can be changed by reloading
+      the <productname>Pgpool-II</> configurations.  You can also
+      use <xref linkend="SQL-PGPOOL-SET"> command to alter the value
+      of this parameter for a current session.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry id="guc-log-hostname" xreflabel="log_hostname">
     <term><varname>log_hostname</varname> (<type>boolean</type>)
      <indexterm>

diff --git a/src/config/pool_config_variables.c b/src/config/pool_config_variables.c
index 770cfc24e2109b79636a1e683560bf77f90a653f..34e6430e661689f99e041f0ab910b10f97c9027c 100644 (file)
--- a/src/config/pool_config_variables.c
+++ b/src/config/pool_config_variables.c
@@ -4,7 +4,7 @@
  * pgpool: a language independent connection pool server for PostgreSQL
  * written by Tatsuo Ishii
  *
- * Copyright (c) 2003-2023     PgPool Global Development Group
+ * Copyright (c) 2003-2024     PgPool Global Development Group
  *
  * Permission to use, copy, modify, and distribute this software and
  * its documentation for any purpose and without fee is hereby
@@ -308,6 +308,13 @@ static const struct config_enum_entry check_temp_table_options[] = {
        {NULL, 0, false}
 };
 
+static const struct config_enum_entry log_backend_messages_options[] = {
+       {"none", BGMSG_NONE, false},            /* turn off logging */
+       {"terse", BGMSG_TERSE, false},          /* terse logging (repeated messages are collapsed into count */
+       {"verbose", BGMSG_VERBOSE, false},      /* always log each message */
+       {NULL, 0, false}
+};
+
 /* From PostgreSQL's guc.c */
 /*
  * Unit conversion tables.
@@ -2399,6 +2406,17 @@ static struct config_enum ConfigureNamesEnum[] =
                NULL, NULL, NULL, NULL
        },
 
+       {
+               {"log_backend_messages", CFGCXT_SESSION, LOGGING_CONFIG,
+                       "Logs any backend messages in the pgpool logs.",
+                       CONFIG_VAR_TYPE_ENUM, false, 0
+               },
+               &g_pool_config.log_backend_messages,
+               BGMSG_NONE,
+               log_backend_messages_options,
+               NULL, NULL, NULL, NULL
+       },
+
        {
                {"wd_lifecheck_method", CFGCXT_INIT, WATCHDOG_CONFIG,
                        "method for watchdog lifecheck.",

diff --git a/src/include/pool_config.h b/src/include/pool_config.h
index 626c2ffa928d6bfe625b6cb4db609443e5ed4501..96b15af549a4660468268fe6ba1aec36656ab608 100644 (file)
--- a/src/include/pool_config.h
+++ b/src/include/pool_config.h
@@ -132,6 +132,14 @@ typedef enum CHECK_TEMP_TABLE_OPTION
        CHECK_TEMP_OFF,
 }                      CHECK_TEMP_TABLE_OPTION;
 
+/* log_backend_messages */
+typedef enum BGMSG_OPTION
+{
+       BGMSG_NONE = 1,
+       BGMSG_TERSE,
+       BGMSG_VERBOSE,
+}                      BGMSG_OPTION;
+
 /*
  * Flags for backendN_flag
  */
@@ -402,6 +410,7 @@ typedef struct
        bool            notice_per_node_statement; /* logs notice message for per node detailed SQL
                                                                                 * statements */
        bool            log_client_messages;    /* If true, logs any client messages */
+       int                     log_backend_messages;   /* logs any backend messages */
        char       *lobj_lock_table;    /* table name to lock for rewriting
                                                                         * lo_creat */
 

diff --git a/src/include/protocol/pool_proto_modules.h b/src/include/protocol/pool_proto_modules.h
index dc531af8757ee7bc38d72ef5601e88dff7c6e5c4..fc2aa31d89fd66133cbc97124931d6563671fa99 100644 (file)
--- a/src/include/protocol/pool_proto_modules.h
+++ b/src/include/protocol/pool_proto_modules.h
@@ -6,7 +6,7 @@
  * pgpool: a language independent connection pool server for PostgreSQL
  * written by Tatsuo Ishii
  *
- * Copyright (c) 2003-2023     PgPool Global Development Group
+ * Copyright (c) 2003-2024     PgPool Global Development Group
  *
  * Permission to use, copy, modify, and distribute this software and
  * its documentation for any purpose and without fee is hereby
@@ -119,6 +119,8 @@ extern void pool_emit_log_for_message_length_diff(int *length_array, char *name)
 
 extern void per_node_statement_notice(POOL_CONNECTION_POOL * backend, int node_id, char *query);
 
+extern void log_backend_messages(unsigned char kind, int backend_id);
+
 /*
  * modules defined in pool_proto2.c
  */

diff --git a/src/protocol/pool_process_query.c b/src/protocol/pool_process_query.c
index 5003b553b103c604bfa3bd25324c8caa6f684ff4..cb72e9c54c76cf4b1079f87adc50f236238f0a48 100644 (file)
--- a/src/protocol/pool_process_query.c
+++ b/src/protocol/pool_process_query.c
@@ -3431,6 +3431,8 @@ read_kind_from_backend(POOL_CONNECTION * frontend, POOL_CONNECTION_POOL * backen
                                                (errmsg("reading backend data packet kind"),
                                                 errdetail("backend:%d kind:'%c'", i, kind)));
 
+                               log_backend_messages(kind, i);
+
                                /*
                                 * Read and forward notice messages to frontend
                                 */

diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index 9aa0d7736acd18cc3e6917fd21cae1af574ee692..9baec7a780d1f1f3f92a23df1c27fed77dac0e1e 100644 (file)
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -3730,6 +3730,138 @@ per_node_statement_notice(POOL_CONNECTION_POOL * backend, int node_id, char *que
                                (errmsg("DB node id: %d statement: %s", node_id, query)));
 }
 
+/*
+ * Make backend message log when log_backend_messages is on.
+ */
+void log_backend_messages(unsigned char kind, int backend_id)
+{
+       /*
+        * Map table for message kind and message label
+        */
+       typedef struct
+       {
+               unsigned char   kind;   /* message kind */
+               char    *label;                 /* message label */
+       }               BackendMessage;
+               
+       static BackendMessage message_label[] =
+               {
+                       {'1', "ParseComplete"},
+                       {'2', "BindComplete"},
+                       {'3', "CloseComplete"},
+                       {'A', "NotificationResponse"},
+                       {'C', "CommandComplete"},
+                       {'D', "DataRow"},
+                       {'E', "ErrorResponse"},
+                       {'G', "CopyInResponse"},
+                       {'H', "CopyOutResponse"},
+                       {'I', "EmptyQueryResponse"},
+                       {'K', "BackendKeyData"},
+                       {'N', "NoticeResponse"},
+                       {'R', "AuthenticationRequest"},
+                       {'S', "ParameterStatus"},
+                       {'T', "RowDescription"},
+                       {'V', "FunctionCallResponse"},
+                       {'W', "CopyBothResponse"},
+                       {'Z', "ReadyForQuery"},
+                       {'n', "NoData"},
+                       {'s', "PortalSuspended"},
+                       {'t', "ParameterDescription"},
+                       {'v', "NegotiateProtocolVersion"},
+                       {'c', "CopyDone"},
+                       {'d', "CopyData"},
+               };
+               
+
+       /* store last kind for each backend */
+       static unsigned char kind_cache[MAX_NUM_BACKENDS];
+
+       /* number of repetitions of each kind */
+       static int kind_count[MAX_NUM_BACKENDS];
+
+       int             kind_num = sizeof(message_label)/sizeof(BackendMessage);
+       char    *label;
+       static  char    *last_label;
+       int             i;
+
+       /* do nothing if log_backend_messages is disabled */
+       if (pool_config->log_backend_messages == BGMSG_NONE)
+               return;
+
+       /* check backend_id */
+       if (backend_id < 0)
+       {
+               elog(WARNING, "log_backend_messages: invalid backend_id: %d", backend_id);
+               return;
+       }
+
+       label = NULL;
+
+       /* search matched message label */
+       for (i = 0; i < kind_num; i++)
+       {
+               if (kind == message_label[i].kind)
+               {
+                       label = message_label[i].label;
+                       break;
+               }
+       }
+       if (label == NULL)
+       {
+               elog(WARNING, "log_backend_messages: no label found for kind \"%c\" from backend_id: %d",
+                        kind, backend_id);
+               return;
+       }
+
+       /* is the setting verbose? */
+       if (pool_config->log_backend_messages == BGMSG_VERBOSE)
+       {
+               /* log everything unconditionally */
+               ereport(LOG,
+                               (errmsg("%s message from backend %d", label, backend_id)));
+               return;
+       }
+               
+       /* just to make sure the setting is terse */
+       if (pool_config->log_backend_messages != BGMSG_TERSE)
+       {
+               elog(ERROR, "unexpected log_backend_messages option: %d",
+                        pool_config->log_backend_messages);
+               return;
+       }
+
+       /*
+        * From now on We can assume that log_backend_messages is set to terse
+        */
+
+       /* same kind as before? */
+       if (kind != kind_cache[backend_id])
+       {
+               /* is the kind new? */
+               if (kind_count[backend_id] == 0)
+               {
+                       /* this is new kind. save the label */
+                       last_label = label;
+               }
+               else
+               {
+                       /* same kind was repeated */
+                       ereport(LOG,
+                                       (errmsg("last %s message from backend %d repeated %d times",
+                                                       last_label, backend_id, kind_count[backend_id])));
+                       kind_count[backend_id] = 0;
+               }
+               ereport(LOG,
+                               (errmsg("%s message from backend %d", label, backend_id)));
+
+               /* save kind for this backend */
+               kind_cache[backend_id] = kind;
+       }
+       else
+               /* same kind is repeated */
+               kind_count[backend_id]++;
+}
+
 /*
  * Check kind and produce error message.
  * Return message kind.
@@ -4649,6 +4781,9 @@ pool_emit_log_for_message_length_diff(int *length_array, char *name)
        }
 }
 
+/*
+ * Read kind from all valid backend
+ */
 signed char
 pool_read_kind(POOL_CONNECTION_POOL * cp)
 {
@@ -4667,6 +4802,7 @@ pool_read_kind(POOL_CONNECTION_POOL * cp)
                }
 
                pool_read(CONNECTION(cp, i), &kind, sizeof(kind));
+               log_backend_messages(kind, i);
 
                if (IS_MAIN_NODE_ID(i))
                {

diff --git a/src/sample/pgpool.conf.sample-stream b/src/sample/pgpool.conf.sample-stream
index dd406a84b4b20475d91c9ebc9030513b44409a6b..ee3757b17fee5d39295373c3b07b53e893c9c9fb 100644 (file)
--- a/src/sample/pgpool.conf.sample-stream
+++ b/src/sample/pgpool.conf.sample-stream
@@ -257,6 +257,10 @@ backend_clustering_mode = 'streaming_replication'
                                    # logs notice message for per node detailed SQL statements
 #log_client_messages = off
                                    # Log any client messages
+#log_backend_messages = none
+                                   # Log any backend messages
+                                   # Valid values are none, terse and verbose
+
 #log_standby_delay = 'if_over_threshold'
                                    # Log standby delay
                                    # Valid values are combinations of always,

diff --git a/src/test/regression/tests/039.log_backend_messages/expected.i b/src/test/regression/tests/039.log_backend_messages/expected.i
new file mode 100644 (file)
index 0000000..ed6e88f
--- /dev/null
+++ b/src/test/regression/tests/039.log_backend_messages/expected.i
@@ -0,0 +1,93 @@
+
+==== mode: i option: none ===
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE ParseComplete
+<= BE BindComplete
+<= BE DataRow
+<= BE DataRow
+<= BE DataRow
+<= BE CommandComplete(SELECT 3)
+<= BE ReadyForQuery(I)
+FE=> Terminate
+==== mode: i option: terse ===
+LOG:  ReadyForQuery message from backend 0
+LOG:  ReadyForQuery message from backend 1
+LOG:  RowDescription message from backend 1
+LOG:  DataRow message from backend 1
+LOG:  last DataRow message from backend 1 repeated 2 times
+LOG:  CommandComplete message from backend 1
+LOG:  ReadyForQuery message from backend 1
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+LOG:  ReadyForQuery message from backend 0
+LOG:  ReadyForQuery message from backend 1
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE NoticeResponse(S LOG C XX000 M ParseComplete message from backend 1 
+<= BE ParseComplete
+<= BE NoticeResponse(S LOG C XX000 M BindComplete message from backend 1 
+<= BE BindComplete
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 1 
+<= BE DataRow
+<= BE DataRow
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M last DataRow message from backend 1 repeated 2 times 
+<= BE NoticeResponse(S LOG C XX000 M CommandComplete message from backend 1 
+<= BE CommandComplete(SELECT 3)
+<= BE NoticeResponse(S LOG C XX000 M ReadyForQuery message from backend 1 
+<= BE ReadyForQuery(I)
+FE=> Terminate
+==== mode: i option: verbose ===
+LOG:  ReadyForQuery message from backend 0
+LOG:  ReadyForQuery message from backend 1
+LOG:  RowDescription message from backend 1
+LOG:  DataRow message from backend 1
+LOG:  DataRow message from backend 1
+LOG:  DataRow message from backend 1
+LOG:  CommandComplete message from backend 1
+LOG:  ReadyForQuery message from backend 1
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+LOG:  ReadyForQuery message from backend 0
+LOG:  ReadyForQuery message from backend 1
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE NoticeResponse(S LOG C XX000 M ParseComplete message from backend 1 
+<= BE ParseComplete
+<= BE NoticeResponse(S LOG C XX000 M BindComplete message from backend 1 
+<= BE BindComplete
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 1 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 1 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 1 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M CommandComplete message from backend 1 
+<= BE CommandComplete(SELECT 3)
+<= BE NoticeResponse(S LOG C XX000 M ReadyForQuery message from backend 1 
+<= BE ReadyForQuery(I)
+FE=> Terminate

diff --git a/src/test/regression/tests/039.log_backend_messages/expected.n b/src/test/regression/tests/039.log_backend_messages/expected.n
new file mode 100644 (file)
index 0000000..6741c4e
--- /dev/null
+++ b/src/test/regression/tests/039.log_backend_messages/expected.n
@@ -0,0 +1,91 @@
+
+==== mode: n option: none ===
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE ParseComplete
+<= BE BindComplete
+<= BE DataRow
+<= BE DataRow
+<= BE DataRow
+<= BE CommandComplete(SELECT 3)
+<= BE ReadyForQuery(I)
+FE=> Terminate
+==== mode: n option: terse ===
+LOG:  ReadyForQuery message from backend 0
+LOG:  RowDescription message from backend 0
+LOG:  DataRow message from backend 0
+LOG:  last DataRow message from backend 0 repeated 2 times
+LOG:  CommandComplete message from backend 0
+LOG:  ReadyForQuery message from backend 0
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+LOG:  ReadyForQuery message from backend 0
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE NoticeResponse(S LOG C XX000 M last ReadyForQuery message from backend 0 repeated 1 times 
+<= BE NoticeResponse(S LOG C XX000 M ParseComplete message from backend 0 
+<= BE ParseComplete
+<= BE NoticeResponse(S LOG C XX000 M BindComplete message from backend 0 
+<= BE BindComplete
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 0 
+<= BE DataRow
+<= BE DataRow
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M last DataRow message from backend 0 repeated 2 times 
+<= BE NoticeResponse(S LOG C XX000 M CommandComplete message from backend 0 
+<= BE CommandComplete(SELECT 3)
+<= BE NoticeResponse(S LOG C XX000 M ReadyForQuery message from backend 0 
+<= BE ReadyForQuery(I)
+FE=> Terminate
+==== mode: n option: verbose ===
+LOG:  ReadyForQuery message from backend 0
+LOG:  RowDescription message from backend 0
+LOG:  DataRow message from backend 0
+LOG:  DataRow message from backend 0
+LOG:  DataRow message from backend 0
+LOG:  CommandComplete message from backend 0
+LOG:  ReadyForQuery message from backend 0
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+LOG:  ReadyForQuery message from backend 0
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE NoticeResponse(S LOG C XX000 M ReadyForQuery message from backend 0 
+<= BE NoticeResponse(S LOG C XX000 M ParseComplete message from backend 0 
+<= BE ParseComplete
+<= BE NoticeResponse(S LOG C XX000 M BindComplete message from backend 0 
+<= BE BindComplete
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 0 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 0 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 0 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M CommandComplete message from backend 0 
+<= BE CommandComplete(SELECT 3)
+<= BE NoticeResponse(S LOG C XX000 M ReadyForQuery message from backend 0 
+<= BE ReadyForQuery(I)
+FE=> Terminate

diff --git a/src/test/regression/tests/039.log_backend_messages/expected.s b/src/test/regression/tests/039.log_backend_messages/expected.s
new file mode 100644 (file)
index 0000000..5877fe3
--- /dev/null
+++ b/src/test/regression/tests/039.log_backend_messages/expected.s
@@ -0,0 +1,94 @@
+
+==== mode: s option: none ===
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE ParseComplete
+<= BE BindComplete
+<= BE DataRow
+<= BE DataRow
+<= BE DataRow
+<= BE CommandComplete(SELECT 3)
+<= BE ReadyForQuery(I)
+FE=> Terminate
+==== mode: s option: terse ===
+LOG:  ReadyForQuery message from backend 0
+LOG:  ReadyForQuery message from backend 1
+LOG:  RowDescription message from backend 1
+LOG:  DataRow message from backend 1
+LOG:  last DataRow message from backend 1 repeated 2 times
+LOG:  CommandComplete message from backend 1
+LOG:  ReadyForQuery message from backend 1
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+LOG:  ReadyForQuery message from backend 0
+LOG:  ReadyForQuery message from backend 1
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE NoticeResponse(S LOG C XX000 M ParseComplete message from backend 1 
+<= BE ParseComplete
+<= BE NoticeResponse(S LOG C XX000 M BindComplete message from backend 1 
+<= BE BindComplete
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 1 
+<= BE DataRow
+<= BE DataRow
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M last DataRow message from backend 1 repeated 2 times 
+<= BE NoticeResponse(S LOG C XX000 M CommandComplete message from backend 1 
+<= BE CommandComplete(SELECT 3)
+<= BE NoticeResponse(S LOG C XX000 M ReadyForQuery message from backend 1 
+<= BE ReadyForQuery(I)
+FE=> Terminate
+==== mode: s option: verbose ===
+LOG:  ReadyForQuery message from backend 0
+LOG:  ReadyForQuery message from backend 1
+LOG:  RowDescription message from backend 1
+LOG:  DataRow message from backend 1
+LOG:  DataRow message from backend 1
+LOG:  DataRow message from backend 1
+LOG:  CommandComplete message from backend 1
+LOG:  ReadyForQuery message from backend 1
+ i 
+---
+ 1
+ 2
+ 3
+(3 rows)
+
+LOG:  ReadyForQuery message from backend 0
+LOG:  ReadyForQuery message from backend 1
+FE=> Parse(stmt="", query="SELECT * FROM t1")
+FE=> Bind(stmt="", portal="")
+FE=> Execute(portal="")
+FE=> Sync
+<= BE NoticeResponse(S LOG C XX000 M ParseComplete message from backend 1 
+<= BE ParseComplete
+<= BE NoticeResponse(S LOG C XX000 M BindComplete message from backend 1 
+<= BE BindComplete
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 1 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 1 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M DataRow message from backend 1 
+<= BE DataRow
+<= BE NoticeResponse(S LOG C XX000 M CommandComplete message from backend 1 
+<= BE CommandComplete(SELECT 3)
+<= BE NoticeResponse(S LOG C XX000 M ReadyForQuery message from backend 0 
+<= BE NoticeResponse(S LOG C XX000 M ReadyForQuery message from backend 1 
+<= BE ReadyForQuery(I)
+FE=> Terminate

diff --git a/src/test/regression/tests/039.log_backend_messages/test.sh b/src/test/regression/tests/039.log_backend_messages/test.sh
new file mode 100755 (executable)
index 0000000..d89ba54
--- /dev/null
+++ b/src/test/regression/tests/039.log_backend_messages/test.sh
@@ -0,0 +1,76 @@
+#!/usr/bin/env bash
+#-------------------------------------------------------------------
+# Test script for log_backend_messages
+#
+source $TESTLIBS
+export PGDATABASE=test
+TESTDIR=testdir
+PSQL=$PGBIN/psql
+PG_CTL=$PGBIN/pg_ctl
+PGPROTO=$PGPOOL_INSTALL_DIR/bin/pgproto
+
+# Loop test for streaming replication mode, snapshot isolation mode
+# and raw mode
+for mode in s i n
+do
+    rm -fr $TESTDIR
+    mkdir $TESTDIR
+    cd $TESTDIR
+
+    echo -n "creating test environment..."
+    $PGPOOL_SETUP -m $mode || exit 1
+    echo "done."
+
+    echo > result
+
+    # We set backend_weight0 to 0 to send ready queries to backend 1.
+    # We set client_min_messages to log so that log messages appear on
+    # the client screen.
+    # We set connection_cache to off so that each time client connects
+    # to pgpool, it receives ready for query from backend.
+        cat >> etc/pgpool.conf <<EOF
+backend_weight0 = 0
+client_min_messages = log
+log_per_node_statement = off
+connection_cache = off
+EOF
+    for option in none terse verbose
+    do
+       echo "==== mode: $mode option: $option ===" >> result
+
+       cat >> etc/pgpool.conf <<EOF
+log_backend_messages = $option
+EOF
+       source ./bashrc.ports
+       ./startall
+       wait_for_pgpool_startup
+
+       export PGPORT=$PGPOOL_PORT
+
+       $PSQL <<EOF
+DROP TABLE t1;
+CREATE TABLE t1(i int);
+INSERT INTO t1 SELECT generate_series(1,3);
+EOF
+
+       # Simple query protocol
+       $PSQL >> result 2>&1 <<EOF
+SELECT * FROM t1;
+EOF
+
+       # Extended query protocol
+       $PGPROTO -d $PGDATABASE -p $PGPOOL_PORT -f ../pgproto.data |& sed 's/F pool_proto.*//' >> result 2>&1
+
+       ./shutdownall
+    done
+
+    diff -c result ../expected.$mode
+    if [ $? != 0 ];then
+       echo "test failed in mode: $mode"
+       exit 1
+    fi
+
+    cd ..
+done
+
+exit 0

diff --git a/src/utils/pool_process_reporting.c b/src/utils/pool_process_reporting.c
index a431d0321884a5daf3c8dd9a9e90e698bcb23d3d..71f871bc4222600d13d217bb6fc868c8406c7863 100644 (file)
--- a/src/utils/pool_process_reporting.c
+++ b/src/utils/pool_process_reporting.c
@@ -479,6 +479,11 @@ get_config(int *nrows)
        StrNCpy(status[i].desc, "if non 0, logs any client messages", POOLCONFIG_MAXDESCLEN);
        i++;
 
+       StrNCpy(status[i].name, "log_backend_messages", POOLCONFIG_MAXNAMELEN);
+       snprintf(status[i].value, POOLCONFIG_MAXVALLEN, "%d", pool_config->log_backend_messages);
+       StrNCpy(status[i].desc, "if non 0, logs any backend messages", POOLCONFIG_MAXDESCLEN);
+       i++;
+
        StrNCpy(status[i].name, "log_standby_delay", POOLCONFIG_MAXNAMELEN);
        snprintf(status[i].value, POOLCONFIG_MAXVALLEN, "%d", pool_config->log_standby_delay);
        StrNCpy(status[i].desc, "how to log standby delay", POOLCONFIG_MAXDESCLEN);