pgpool2.git / summary / log / commit / refs
commit 54503f4c87f1853ec1e71e65331adddc05531312
Author: Tatsuo Ishii <ishii@postgresql.org>
Date: Fri Jul 27 08:35:41 2018 +0000
Add new log_client_messages directive.
This allows to log messages from frontend.
Note that the regression test for this (019.log_client_messages)
requires pgproto command. We will eventually import pgproto in the
future but for now we just check the existence of pgproto in
019.log_client_messages/test.sh. If pgproto does not exist in the
command search pass, just skip the test with "ok" status.
Patch contributed by Takuma Hoshiai.
doc.ja/src/sgml/connection-pooling.sgml | 28 ++++
doc/src/sgml/connection-pooling.sgml | 18 +++
src/config/pool_config_variables.c | 10 ++
src/include/pool_config.h | 1 +
src/protocol/child.c | 4 +
src/protocol/pool_proto_modules.c | 67 +++++++-
src/sample/pgpool.conf.sample | 2 +
src/sample/pgpool.conf.sample-logical | 2 +
src/sample/pgpool.conf.sample-master-slave | 2 +
src/sample/pgpool.conf.sample-replication | 2 +
src/sample/pgpool.conf.sample-stream | 2 +
.../tests/019.log_client_messages/test.sh | 169 +++++++++++++++++++++
src/utils/pool_process_reporting.c | 5 +
13 files changed, 311 insertions(+), 1 deletion(-)
diff --git a/doc.ja/src/sgml/connection-pooling.sgml b/doc.ja/src/sgml/connection-pooling.sgml
index 7015c56eb..cf67c8674 100644
--- a/doc.ja/src/sgml/connection-pooling.sgml
+++ b/doc.ja/src/sgml/connection-pooling.sgml
@@ -864,6 +864,34 @@ onに設定されている場合、全てのSQL文をログ出力します。
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-client-messages" xreflabel="log_client_messages">
+ <term><varname>log_client_messages</varname> (<type>boolean</type>)
+ <indexterm>
+<!--
+ <primary><varname>log_client_messages</varname> configuration parameter</primary>
+-->
+ <primary><varname>log_client_messages</varname> 設定パラメータ</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+<!--
+ Setting to on, prints client messages to the messages.
+-->
+onに設定されている場合、クライアントメッセージをログ出力します。
+ </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 50c6212aa..b61d893bb 100644
--- a/doc/src/sgml/connection-pooling.sgml
+++ b/doc/src/sgml/connection-pooling.sgml
@@ -560,6 +560,24 @@ local0.* /var/log/pgpool.log
</listitem>
</varlistentry>
+ <varlistentry id="guc-log-client-messages" xreflabel="log_client_messages">
+ <term><varname>log_client_messages</varname> (<type>boolean</type>)
+ <indexterm>
+ <primary><varname>log_client_messages</varname> configuration parameter</primary>
+ </indexterm>
+ </term>
+ <listitem>
+ <para>
+ Setting to on, prints client messages to the log.
+ </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 aa4486fda..bca7b22a4 100644
--- a/src/config/pool_config_variables.c
+++ b/src/config/pool_config_variables.c
@@ -427,6 +427,16 @@ static struct config_bool ConfigureNamesBool[] =
NULL, NULL,NULL
},
+ {
+ {"log_client_messages", CFGCXT_SESSION, LOGING_CONFIG,
+ "Logs any client messages in the pgpool logs.",
+ CONFIG_VAR_TYPE_BOOL,false, 0
+ },
+ &g_pool_config.log_client_messages,
+ false,
+ NULL, NULL,NULL
+ },
+
{
{"use_watchdog", CFGCXT_INIT, WATCHDOG_CONFIG,
"Enables the pgpool-II watchdog.",
diff --git a/src/include/pool_config.h b/src/include/pool_config.h
index 05c3a3f1c..4d0d49cf7 100644
--- a/src/include/pool_config.h
+++ b/src/include/pool_config.h
@@ -236,6 +236,7 @@ typedef struct {
bool ignore_leading_white_space; /* ignore leading white spaces of each query */
bool log_statement; /* logs all SQL statements */
bool log_per_node_statement; /* logs per node detailed SQL statements */
+ bool log_client_messages; /* If true, logs any client messages */
char *lobj_lock_table; /* table name to lock for rewriting lo_creat */
BackendDesc *backend_desc; /* PostgreSQL Server description. Placed on shared memory */
diff --git a/src/protocol/child.c b/src/protocol/child.c
index eca917767..9914c1e83 100644
--- a/src/protocol/child.c
+++ b/src/protocol/child.c
@@ -746,6 +746,10 @@ void cancel_request(CancelPacket *sp)
CancelPacket cp;
bool found = false;
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("CancelRequest: Cancel message from frontend."),
+ errdetail("process id: %d", ntohl(sp->pid) )));
ereport(DEBUG1,
(errmsg("Cancel request received")));
diff --git a/src/protocol/pool_proto_modules.c b/src/protocol/pool_proto_modules.c
index d25843b0d..56ee7b93d 100644
--- a/src/protocol/pool_proto_modules.c
+++ b/src/protocol/pool_proto_modules.c
@@ -689,6 +689,10 @@ POOL_STATUS Execute(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
/* Get session context */
session_context = pool_get_session_context(false);
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Execute: Execute message from frontend."),
+ errdetail("portal: \"%s\"",contents)));
ereport(DEBUG2,
(errmsg("Execute: portal name <%s>", contents)));
@@ -963,6 +967,11 @@ POOL_STATUS Parse(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
name = contents;
stmt = contents + strlen(contents) + 1;
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Parse: Parse message from frontend."),
+ errdetail("statement: \"%s\", query: \"%s\"",name, stmt)));
+
/* parse SQL string */
MemoryContext old_context = MemoryContextSwitchTo(query_context->memory_context);
parse_tree_list = raw_parser(stmt, &error);
@@ -1301,6 +1310,10 @@ POOL_STATUS Bind(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
portal_name = contents;
pstmt_name = contents + strlen(portal_name) + 1;
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Bind: Bind message from frontend."),
+ errdetail("portal: \"%s\", statement: \"%s\"",portal_name, pstmt_name)));
parse_msg = pool_get_sent_message('Q', pstmt_name, POOL_SENT_MESSAGE_CREATED);
if (!parse_msg)
parse_msg = pool_get_sent_message('P', pstmt_name, POOL_SENT_MESSAGE_CREATED);
@@ -1443,6 +1456,10 @@ POOL_STATUS Describe(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
/* Prepared Statement */
if (*contents == 'S')
{
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Describe: Describe message from frontend."),
+ errdetail("statement: \"%s\"",contents+1 )));
msg = pool_get_sent_message('Q', contents+1, POOL_SENT_MESSAGE_CREATED);
if (!msg)
msg = pool_get_sent_message('P', contents+1, POOL_SENT_MESSAGE_CREATED);
@@ -1455,6 +1472,10 @@ POOL_STATUS Describe(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
/* Portal */
else
{
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Describe: Describe message from frontend."),
+ errdetail("portal: \"%s\"",contents+1 )));
msg = pool_get_sent_message('B', contents+1, POOL_SENT_MESSAGE_CREATED);
if (!msg)
ereport(FATAL,
@@ -1520,12 +1541,20 @@ POOL_STATUS Close(POOL_CONNECTION *frontend, POOL_CONNECTION_POOL *backend,
if (*contents == 'S')
{
msg = pool_get_sent_message('Q', contents+1, POOL_SENT_MESSAGE_CREATED);
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Close: Close message from frontend."),
+ errdetail("statement: \"%s\"",contents+1)));
if (!msg)
msg = pool_get_sent_message('P', contents+1, POOL_SENT_MESSAGE_CREATED);
}
/* Portal */
else if (*contents == 'P')
{
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Close: Close message from frontend."),
+ errdetail("portal: \"%s\"",contents+1)));
msg = pool_get_sent_message('B', contents+1, POOL_SENT_MESSAGE_CREATED);
}
else
@@ -2362,6 +2391,9 @@ POOL_STATUS ProcessFrontendResponse(POOL_CONNECTION *frontend,
case 'X': /* Terminate */
if(contents)
pfree(contents);
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Terminate: Terminate message from frontend.")));
ereport(DEBUG5,
(errmsg("Frontend terminated"),
errdetail("received message kind 'X' from frontend")));
@@ -2369,6 +2401,10 @@ POOL_STATUS ProcessFrontendResponse(POOL_CONNECTION *frontend,
case 'Q': /* Query */
allow_close_transaction = 1;
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Query: Query message from frontend."),
+ errdetail("query: \"%s\"",contents)));
status = SimpleQuery(frontend, backend, len, contents);
break;
@@ -2404,6 +2440,9 @@ POOL_STATUS ProcessFrontendResponse(POOL_CONNECTION *frontend,
break;
case 'S': /* Sync */
+ if (pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Sync: Sync message from frontendend.")));
pool_set_doing_extended_query_message();
if (pool_is_ignore_till_sync())
pool_unset_ignore_till_sync();
@@ -2429,6 +2468,14 @@ POOL_STATUS ProcessFrontendResponse(POOL_CONNECTION *frontend,
break;
case 'F': /* FunctionCall */
+ if (pool_config->log_client_messages)
+ {
+ int oid;
+ memcpy(&oid, contents, sizeof(int));
+ ereport(LOG,
+ (errmsg("FunctionCall: FunctionCall message from frontend."),
+ errdetail("oid: \"%d\"", ntohl(oid) )));
+ }
/*
* Create dummy query context as if it were an INSERT.
*/
@@ -2456,6 +2503,9 @@ POOL_STATUS ProcessFrontendResponse(POOL_CONNECTION *frontend,
case 'd': /* CopyData */
case 'f': /* CopyFail */
case 'H': /* Flush */
+ if (fkind == 'H' && pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("Flush: Flush message from frontend.")));
if (MAJOR(backend) == PROTO_MAJOR_V3)
{
if (fkind == 'H')
@@ -2814,12 +2864,14 @@ POOL_STATUS CopyDataRows(POOL_CONNECTION *frontend,
char *string = NULL;
int len;
int i;
+ int copy_count;
#ifdef DEBUG
int j = 0;
char buf[1024];
#endif
+ copy_count=0;
for (;;)
{
if (copyin)
@@ -2844,12 +2896,25 @@ POOL_STATUS CopyDataRows(POOL_CONNECTION *frontend,
/* CopyData? */
if (kind == 'd')
+ {
+ copy_count++;
continue;
+ }
else
{
+ if (pool_config->log_client_messages && copy_count !=0 )
+ ereport(LOG,
+ (errmsg("CopyData: CopyData message from frontend."),
+ errdetail("count: %d", copy_count)));
+ if (kind == 'c' && pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("CopyDone: CopyDone message from frontend.")));
+ if (kind == 'f' && pool_config->log_client_messages)
+ ereport(LOG,
+ (errmsg("CopyFail: CopyFail message from frontend.")));
ereport(DEBUG1,
(errmsg("copy data rows"),
- errdetail("invalid copyin kind. expected 'd' got '%c'", kind)));
+ errdetail("invalid copyin kind. expected 'd' got '%c'", kind)));
break;
}
}
diff --git a/src/sample/pgpool.conf.sample b/src/sample/pgpool.conf.sample
index 21344258b..e2acf06de 100644
--- a/src/sample/pgpool.conf.sample
+++ b/src/sample/pgpool.conf.sample
@@ -165,6 +165,8 @@ log_statement = off
log_per_node_statement = off
# Log all statements
# with node and backend informations
+log_client_messages = off
+ # Log any client messages
log_standby_delay = 'none'
# Log standby delay
# Valid values are combinations of always,
diff --git a/src/sample/pgpool.conf.sample-logical b/src/sample/pgpool.conf.sample-logical
index 3429a07d1..064f6d1c8 100644
--- a/src/sample/pgpool.conf.sample-logical
+++ b/src/sample/pgpool.conf.sample-logical
@@ -166,6 +166,8 @@ log_statement = off
log_per_node_statement = off
# Log all statements
# with node and backend informations
+log_client_messages = off
+ # Log any client messages
log_standby_delay = 'if_over_threshold'
# Log standby delay
# Valid values are combinations of always,
diff --git a/src/sample/pgpool.conf.sample-master-slave b/src/sample/pgpool.conf.sample-master-slave
index fcc4a0aef..d67512296 100644
--- a/src/sample/pgpool.conf.sample-master-slave
+++ b/src/sample/pgpool.conf.sample-master-slave
@@ -165,6 +165,8 @@ log_statement = off
log_per_node_statement = off
# Log all statements
# with node and backend informations
+log_client_messages = off
+ # Log any client messages
log_standby_delay = 'none'
# Log standby delay
# Valid values are combinations of always,
diff --git a/src/sample/pgpool.conf.sample-replication b/src/sample/pgpool.conf.sample-replication
index fc70c4a32..2fd2906bf 100644
--- a/src/sample/pgpool.conf.sample-replication
+++ b/src/sample/pgpool.conf.sample-replication
@@ -164,6 +164,8 @@ log_statement = off
log_per_node_statement = off
# Log all statements
# with node and backend informations
+log_client_messages = off
+ # Log any client messages
log_standby_delay = 'none'
# Log standby delay
# Valid values are combinations of always,
diff --git a/src/sample/pgpool.conf.sample-stream b/src/sample/pgpool.conf.sample-stream
index 7adce85b1..b64432f6d 100644
--- a/src/sample/pgpool.conf.sample-stream
+++ b/src/sample/pgpool.conf.sample-stream
@@ -166,6 +166,8 @@ log_statement = off
log_per_node_statement = off
# Log all statements
# with node and backend informations
+log_client_messages = off
+ # Log any client messages
log_standby_delay = 'if_over_threshold'
# Log standby delay
# Valid values are combinations of always,
diff --git a/src/test/regression/tests/019.log_client_messages/test.sh b/src/test/regression/tests/019.log_client_messages/test.sh
new file mode 100755
index 000000000..4e649d3c5
--- /dev/null
+++ b/src/test/regression/tests/019.log_client_messages/test.sh
@@ -0,0 +1,169 @@
+#!/usr/bin/env bash
+#-------------------------------------------------------------------
+# test script for log_client_messages
+#
+source $TESTLIBS
+TESTDIR=`pwd`/testdir
+PSQL=$PGBIN/psql
+PGBENCH=$PGBENCH_PATH
+WHOAMI=`whoami`
+PGPROTO=`which pgproto`
+if [ $? != 0 ];then
+ echo -n "pgproto not found. skipping test"
+ exit 0
+fi
+LD_LIBRARY_PATH=$PGBIN/../lib
+
+#test parameter
+timeout=30
+num_tests=14
+success_count=0
+
+rm -fr $TESTDIR
+mkdir $TESTDIR
+cd $TESTDIR
+
+# create test environment
+echo -n "creating test environment..."
+$PGPOOL_SETUP -n 1 || exit 1
+echo "done."
+
+source ./bashrc.ports
+export PGPORT=$PGPOOL_PORT
+export LD_LIBRARY_PATH=$LD_LIBRARY_PATH
+echo $LD_LIBRARY_PATH
+
+# log_client_messages paramater change
+./startall
+wait_for_pgpool_startup
+
+echo "log_client_messages = on" >> etc/pgpool.conf
+./pgpool_reload
+sleep 1
+wait_for_pgpool_startup
+
+$PSQL -c "PGPOOL SHOW log_client_messages" test > psql_status 2>&1
+if [ !`cat psql_status |grep 'on'` ]
+then
+ ./shutdownall
+ exit 1
+fi
+
+$PGBENCH -i test
+
+# pgproto test
+cp -r ../tests ./
+tests=`(ls tests)`
+
+for i in $tests
+do
+ echo -n "testing $i ..."
+ timeout $timeout $PGPROTO -u $WHOAMI -p $PGPOOL_PORT -d test -f tests/$i
+done
+
+# send cancel request
+# executing long runing query
+$PSQL -c "select pg_sleep(30);" test &
+# get psql process pid
+psqlpid=$!
+sleep 2
+# send CtrlC to psql to cancel the query
+kill -INT $psqlpid
+sleep 2
+
+
+
+./shutdownall
+#Bind
+grep -A 1 -e "Bind: Bind message from frontend." log/pgpool.log |grep -E "portal: \".*\", statement: \".*\"" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Bind log"
+ success_count=$(( success_count + 1 ))
+fi
+#CancelRequest
+grep -A 1 -e "CancelRequest: Cancel message from frontend" log/pgpool.log |grep -E "process id: .+" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: CancelRequest log"
+ success_count=$(( success_count + 1 ))
+fi
+#Close
+grep -A 1 -e "Close: Close message from frontend" log/pgpool.log |grep -E "(portal|statement): \".*\"" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Close log"
+ success_count=$(( success_count + 1 ))
+fi
+#CopyData
+grep -A 1 -e "CopyData message from frontend" log/pgpool.log |grep -E "count: [0-9]+" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: CopyData log"
+ success_count=$(( success_count + 1 ))
+fi
+#CopyDone
+grep -e "CopyDone message from frontend" log/pgpool.log >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: CopyDone log"
+ success_count=$(( success_count + 1 ))
+fi
+#CopyFail
+grep -e "CopyFail message from frontend" log/pgpool.log >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: CopyFail log"
+ success_count=$(( success_count + 1 ))
+fi
+#Describe
+grep -A 1 -e "Describe: Describe message from frontend." log/pgpool.log |grep -E "(portal|statement): \".*\"" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Describe log"
+ success_count=$(( success_count + 1 ))
+fi
+#Execute
+grep -A 1 -e "Execute: Execute message from frontend." log/pgpool.log |grep -E "portal: \".*\"" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Execute log"
+ success_count=$(( success_count + 1 ))
+fi
+#Flush
+grep -e "Flush: Flush message from frontend" log/pgpool.log >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Flush log"
+ success_count=$(( success_count + 1 ))
+fi
+#FunctionCall
+grep -A 1 -e "FunctionCall message from frontend." log/pgpool.log |grep -E "oid: \".+\"" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: FunctionCall log"
+ success_count=$(( success_count + 1 ))
+fi
+#Parse
+grep -A 1 -e "Parse: Parse message from frontend." log/pgpool.log |grep -E "statement: \".*\", query: \".*\"" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Parse log"
+ success_count=$(( success_count + 1 ))
+fi
+#Query
+grep -A 1 -e "Query: Query message from frontend." log/pgpool.log |grep -E "query: \".*\"" >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Query log"
+ success_count=$(( success_count + 1 ))
+fi
+#Sync
+grep -e "Sync: Sync message from frontend." log/pgpool.log >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Sync log"
+ success_count=$(( success_count + 1 ))
+fi
+#Terminate
+grep -e "Terminate: Terminate message from frontend." log/pgpool.log >/dev/null 2>&1
+if [ $? = 0 ];then
+ echo "success: Terminate log"
+ success_count=$(( success_count + 1 ))
+fi
+
+echo "$success_count out of $num_tests successfull";
+
+if test $success_count -eq $num_tests
+then
+ exit 0;
+fi
+
+exit 1;
diff --git a/src/utils/pool_process_reporting.c b/src/utils/pool_process_reporting.c
index b755c261d..1a04cd94a 100644
--- a/src/utils/pool_process_reporting.c
+++ b/src/utils/pool_process_reporting.c
@@ -332,6 +332,11 @@ POOL_REPORT_CONFIG* get_config(int *nrows)
StrNCpy(status[i].desc, "if non 0, logs all SQL statements on each node", POOLCONFIG_MAXDESCLEN);
i++;
+ StrNCpy(status[i].name, "log_client_messages", POOLCONFIG_MAXNAMELEN);
+ snprintf(status[i].value, POOLCONFIG_MAXVALLEN, "%d", pool_config->log_client_messages);
+ StrNCpy(status[i].desc, "if non 0, logs any client 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);
[parent: ae8dad50cd9f]