View Issue Details

IDProjectCategoryView StatusLast Update
0000573Pgpool-IIBugpublic2020-01-15 07:39
ReporterstillgbxAssigned Tot-ishii 
PriorityurgentSeveritycrashReproducibilityalways
Status resolvedResolutionopen 
PlatformLinuxOSUbuntuOS Version18.04 / 16.04
Product Version4.1.0 
Target Version4.1.1Fixed in Version 
Summary0000573: LISTEN/NOTIFY no longer completely work after 4.1.0 upgrade (C# Npgsql)
DescriptionAfter upgrading to 4.1.0 in our environments (2 nodes, primary/slave), it seems that LISTEN/NOTIFY no longer completely work.

Not completly because it's ok in pgAdmin (in the same session "LISTEN test_channel" then "NOTIFY test_channel, 'test payload'), but not in our C# implementation (or with the code provided) and with Npgsql (4.1.2 or older version).

We have trouble identifying the real moment, but in our more complex implementation we receive the notifications "in bundle" but not instantly. As if they were stacked and then sent.

We tried to encapsulate NOTIFY/pg_notify in pgsql functions, we also tried to modify some configuration parameters (like load_balance_mode or black_function_list)... without success.

Could you confirm this behavior or direct us to something that can solve the issue ?
Steps To Reproduce- Run provided code
- Trigger a "NOTIFY channel_test" (e.g. in pgAdmin)
Additional Information// see https://www.npgsql.org/doc/wait.html

using Npgsql;
using System;

namespace TestListenNotify
{
    class Program
    {
        static void Main(string[] args)
        {
            // Via pgpool
            var connectionString = "Host=192.168.NNN.NN0;Port=9999;Database=DB_NAME;Username=DB_USERNAME;Password=DB_PASSWORD;Pooling=false;Keepalive=120;";

            // Direct
            // var connectionString = "Host=192.168.NNN.NN1;Port=5432;Database=DB_NAME;Username=DB_USERNAME;Password=DB_PASSWORD;Pooling=true;Keepalive=120;";

            var conn = new NpgsqlConnection(connectionString);
            conn.Open();
            conn.Notification += (o, e) =>
            {
                // Via pgpool -> KO
                // Direct -> OK
                Console.WriteLine("Received notification");
            };

            using (var cmd = new NpgsqlCommand("LISTEN channel_test", conn))
            {
                cmd.ExecuteNonQuery();
            }

            while (true)
            {
                conn.Wait();
            }
        }
    }
}
TagsNo tags attached.

Activities

t-ishii

2020-01-07 09:57

developer   ~0003040

If there's any difference regarding LISTEN/NOTIFY behavior between PgAdmin and npgsql, the former uses simple protocol while the latter uses extended protocol. To confirm that, i need a pgpool log with log_client_messages = on. Can you please provide it?

stillgbx

2020-01-07 18:56

reporter   ~0003041

Here is a part of the log file when I use LISTEN/NOTIFY from pgadmin.

Parameters of the config file:
log_connections = on
log_hostname = on
log_statement = on
log_per_node_statement = on
log_client_messages = on
debug_level = 1
log_error_verbosity = verbose
client_min_messages = debug1
log_min_messages = debug1

pgpool.log (9,331 bytes)
listen-notify-pgadmin.png (69,990 bytes)
listen-notify-pgadmin.png (69,990 bytes)

stillgbx

2020-01-07 19:45

reporter   ~0003042

The log with the provided simple test code running (LISTEN) and a NOTIFY manually triggered from pgAdmin.
By the way, when I set client_min_messages > notice (e.g. debug1) the program is not able to obtain the connection.
And oddly the program receive the notification but after 1 minute and 40 / 45 seconds.

pgpool_001.log (2,387 bytes)

stillgbx

2020-01-07 20:55

reporter   ~0003043

Changing Keepalive=N (e.g. 120 to 10) in the connection string has an impact on the behavior.
Maybe it's related to https://www.postgresql.org/docs/12/sql-notify.html :
"NOTIFY interacts with SQL transactions in some important ways. Firstly, if a NOTIFY is executed inside a transaction, the notify events are not delivered until and unless the transaction is committed. This is appropriate, since if the transaction is aborted, all the commands within it have had no effect, including NOTIFY. But it can be disconcerting if one is expecting the notification events to be delivered immediately. Secondly, if a listening session receives a notification signal while it is within a transaction, the notification event will not be delivered to its connected client until just after the transaction is completed (either committed or aborted). Again, the reasoning is that if a notification were delivered within a transaction that was later aborted, one would want the notification to be undone somehow — but the server cannot “take back” a notification once it has sent it to the client. So notification events are only delivered between transactions. The upshot of this is that applications using NOTIFY for real-time signaling should try to keep their transactions short."

stillgbx

2020-01-07 21:26

reporter   ~0003044

Npgsql Keepalive https://www.npgsql.org/doc/keepalive.html:
"Some clients keep idle connections for long periods of time - this is especially frequent when waiting for PostgreSQL notifications. In this scenario, how can the client know the connection is still up, and hasn't been broken by a server or network outage? For this purpose, Npgsql has a keepalive feature, which makes it send periodic SELECT NULL queries. This feature is by default disabled, and must be enabled via the Keepalive connection string parameter, setting the number of seconds between each keepalive."

t-ishii

2020-01-08 09:29

developer   ~0003045

> The log with the provided simple test code running (LISTEN) and a NOTIFY manually triggered from pgAdmin.
What I wanted was the log while you are using npgsql, not pgAdmin. Can you please resend the log?

stillgbx

2020-01-08 18:44

reporter   ~0003050

An extraction of the log file when running this code:

using Npgsql;
using System;
using System.Threading;

namespace TestListenNotify
{
    class Program
    {
        static void Main(string[] args)
        {
            // Via pgpool
            var connectionString = "Host=192.168.NNN.NN0;Port=9999;Database=DB_NAME;Username=DB_USER;Password=DB_PASSWORD;Pooling=false;Keepalive=20;";

            // Direct
            // connectionString = "Host=192.168.NNN.NN1;Port=5432;Database=DB_NAME;Username=DB_USER;Password=DB_PASSWORD;Pooling=true;Keepalive=120;";

            var listenConn = new NpgsqlConnection(connectionString);
            try
            {
                listenConn.Open();
                listenConn.Notification += (o, e) =>
                {
                    // Via pgpool -> KO
                    // Direct -> OK
                    Console.WriteLine($"Received notification: '{e.Payload}' at {DateTime.Now.TimeOfDay}");
                };

                using (var cmd = new NpgsqlCommand("LISTEN channel_test", listenConn))
                {
                    cmd.ExecuteNonQuery();
                }

                //
                var notifyThread = new Thread(new ThreadStart(delegate
                {
                    Thread.Sleep(2000);

                    var notifyConn = new NpgsqlConnection(connectionString);
                    notifyConn.Open();

                    int notificationId = 1;
                    while (true)
                    {
                        using (var cmd = new NpgsqlCommand($"NOTIFY channel_test, 'test payload from simple code {notificationId}'", notifyConn))
                        {
                            Console.WriteLine($"Sended notification: '{notificationId}' at {DateTime.Now.TimeOfDay}");
                            cmd.ExecuteNonQuery();
                        }
                        notificationId++;
                        Thread.Sleep(3000);
                    }
                }));
                notifyThread.IsBackground = true;
                notifyThread.Start();

                //
                while (true)
                {
                    listenConn.Wait();
                }
            }
            catch (Exception ex)
            {
                Console.Write(ex);
            }
        }
    }
}

pgpool_002.log (21,046 bytes)

stillgbx

2020-01-08 19:58

reporter   ~0003051

and for better understanding, a screenshot of the output:

output.png (61,201 bytes)
output.png (61,201 bytes)

stillgbx

2020-01-09 02:20

reporter   ~0003053

don't really know if it could help but:

t-ishii

2020-01-10 11:18

developer   ~0003056

In my local test using pgproto it works. To find put why you have problem with it, I need more detailed pgpool log with log_min_messages = debug5. Can you please provide it?

stillgbx

2020-01-10 18:00

reporter   ~0003057

Here is it (pgsql version 9.5 but we have the same behavior with version 12):

pgpool-debug5.log (14,115,880 bytes)

t-ishii

2020-01-12 07:20

developer   ~0003058

I found an oversight in Pgpool-II 4.1. The notification messages was surely received by Pgpool-II:

Jan 10 09:25:20 gomsgpool-0 pgpool[11411]: [4200-3] 2020-01-10 09:25:20: pid 11411: LOCATION: pool_process_query.c:3282
Jan 10 09:25:20 gomsgpool-0 pgpool[11411]: [4201-1] 2020-01-10 09:25:20: pid 11411: DEBUG: processing backend response
Jan 10 09:25:20 gomsgpool-0 pgpool[11411]: [4201-2] 2020-01-10 09:25:20: pid 11411: DETAIL: received kind 'A'(41) from backend
Jan 10 09:25:20 gomsgpool-0 pgpool[11411]: [4201-3] 2020-01-10 09:25:20: pid 11411: LOCATION: pool_proto_modules.c:2714

but was buffered and never sent to frontend. Can you please try attached patch to fix the issue?

notification-fix.diff (1,566 bytes)
diff --git a/src/protocol/pool_process_query.c b/src/protocol/pool_process_query.c
index 7002ff23..a6470e15 100644
--- a/src/protocol/pool_process_query.c
+++ b/src/protocol/pool_process_query.c
@@ -761,17 +761,18 @@ SimpleForwardToFrontend(char kind, POOL_CONNECTION * frontend,
 
 	/*
 	 * Optimization for other than "Command Complete", "Ready For query",
-	 * "Error response" and "Notice message" messages.  Especially, since it
-	 * is too often to receive and forward "Data Row" message, we do not flush
-	 * the message to frontend now. We expect that "Command Complete" message
-	 * (or "Error response" or "Notice response" message) follows the stream
-	 * of data row message anyway, so flushing will be done at that time.
+	 * "Error response" ,"Notice message" and "Notification response"
+	 * messages.  Especially, since it is too often to receive and forward
+	 * "Data Row" message, we do not flush the message to frontend now. We
+	 * expect that "Command Complete" message (or "Error response" or "Notice
+	 * response" message) follows the stream of data row message anyway, so
+	 * flushing will be done at that time.
 	 *
 	 * Same thing can be said to CopyData message. Tremendous number of
 	 * CopyData messages are sent to frontend (typical use case is pg_dump).
 	 * So eliminating per CopyData flush significantly enhances performance.
 	 */
-	if (kind == 'C' || kind == 'Z' || kind == 'E' || kind == 'N')
+	if (kind == 'C' || kind == 'Z' || kind == 'E' || kind == 'N' || kind == 'A')
 	{
 		pool_write_and_flush(frontend, p1, len1);
 	}
notification-fix.diff (1,566 bytes)

stillgbx

2020-01-13 20:53

reporter   ~0003062

Thank you, It works with the patch.

t-ishii

2020-01-13 22:37

developer   ~0003063

Thank you for the feedback. May I close this issue?

stillgbx

2020-01-13 22:49

reporter   ~0003064

Yes you can.

Issue History

Date Modified Username Field Change
2020-01-07 04:11 stillgbx New Issue
2020-01-07 09:47 t-ishii Assigned To => t-ishii
2020-01-07 09:47 t-ishii Status new => assigned
2020-01-07 09:57 t-ishii Note Added: 0003040
2020-01-07 09:57 t-ishii Status assigned => feedback
2020-01-07 18:56 stillgbx File Added: pgpool.log
2020-01-07 18:56 stillgbx File Added: listen-notify-pgadmin.png
2020-01-07 18:56 stillgbx Note Added: 0003041
2020-01-07 18:56 stillgbx Status feedback => assigned
2020-01-07 19:45 stillgbx File Added: pgpool_001.log
2020-01-07 19:45 stillgbx Note Added: 0003042
2020-01-07 20:55 stillgbx Note Added: 0003043
2020-01-07 21:26 stillgbx Note Added: 0003044
2020-01-08 09:29 t-ishii Note Added: 0003045
2020-01-08 09:30 t-ishii Status assigned => feedback
2020-01-08 18:44 stillgbx File Added: pgpool_002.log
2020-01-08 18:44 stillgbx Note Added: 0003050
2020-01-08 18:44 stillgbx Status feedback => assigned
2020-01-08 19:58 stillgbx File Added: output.png
2020-01-08 19:58 stillgbx Note Added: 0003051
2020-01-09 02:20 stillgbx File Added: wireshark-notify-compare.png
2020-01-09 02:20 stillgbx Note Added: 0003053
2020-01-10 11:18 t-ishii Note Added: 0003056
2020-01-10 11:18 t-ishii Status assigned => feedback
2020-01-10 18:00 stillgbx File Added: pgpool-debug5.log
2020-01-10 18:00 stillgbx Note Added: 0003057
2020-01-10 18:00 stillgbx Status feedback => assigned
2020-01-12 07:20 t-ishii File Added: notification-fix.diff
2020-01-12 07:20 t-ishii Note Added: 0003058
2020-01-12 07:21 t-ishii Status assigned => feedback
2020-01-13 20:53 stillgbx Note Added: 0003062
2020-01-13 20:53 stillgbx Status feedback => assigned
2020-01-13 22:37 t-ishii Note Added: 0003063
2020-01-13 22:37 t-ishii Target Version => 4.1.1
2020-01-13 22:49 stillgbx Note Added: 0003064
2020-01-15 07:39 t-ishii Status assigned => resolved