[pgpool-hackers: 3779] Re: 073.pg_terminate_backend sometimes fails
Muhammad Usama
m.usama at gmail.com
Fri Aug 14 03:28:44 JST 2020
Hi Ishii-San
I have tried like a dozen times but never got the failure even once.
Looking at the log snippet you shared it appears that this failure
is a random timing-based and it is not really a problem with the
handling of pg_terminate_backend but somehow it is related to
missing connection_count_down() call.
I suppose connection_count_down() is not called in one of the code
path that gets executed when we get this "write on backend failed"
warning
i.e.
.WARNING: write on backend 0 failed with error :"Success"
DETAIL: while trying to write data from offset: 0 wlen: 5
The reason I suspect that is, I never saw this above warning message in
pg_terminate_backend test case logs, but it is present in the log snippet
you shared above so I suspect if the backend gets terminated when
pgpool process is about to write to the backend socket then in that code
patch somehow we don't execute the connection_count_down() function
that leads to this regression test failure.
Thanks
Best regards
Muhammad Usama
On Mon, Aug 3, 2020 at 10:40 AM Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
> Hi Usama,
>
> Recently 073.pg_terminate_backend sometimes fails (like 5 of 10).
>
> count_up: 2
> count_down: 1
> connection count is not matched.
>
> Is this somewhat related to the regression failure?
>
> creating test environment...PostgreSQL major version: 123
> Starting set up in streaming replication mode
> creating startall and shutdownall
> creating failover script
> creating database cluster
> /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/073.pg_terminate_backend/testdir/data0...done.
> update postgresql.conf
> creating pgpool_remote_start
> creating basebackup.sh
> creating recovery.conf
> creating database cluster
> /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/073.pg_terminate_backend/testdir/data1...done.
> update postgresql.conf
> creating pgpool_remote_start
> creating basebackup.sh
> creating recovery.conf
> temporarily start data0 cluster to create extensions
> temporarily start pgpool-II to create standby nodes
> node_id | hostname | port | status | lb_weight | role | select_cnt |
> load_balance_node | replication_delay | replication_state |
> replication_sync_state | last_status_change
>
> ---------+----------+-------+--------+-----------+---------+------------+-------------------+-------------------+-------------------+------------------------+---------------------
> 0 | /tmp | 11002 | up | 0.500000 | primary | 0 |
> true | 0 | |
> | 2020-08-01 15:34:15
> 1 | /tmp | 11003 | down | 0.500000 | standby | 0 |
> false | 0 | |
> | 2020-08-01 15:34:14
> (2 rows)
>
> recovery node 1...pcp_recovery_node -- Command Successful
> done.
> creating follow master script
> node_id | hostname | port | status | lb_weight | role | select_cnt |
> load_balance_node | replication_delay | replication_state |
> replication_sync_state | last_status_change
>
> ---------+----------+-------+--------+-----------+---------+------------+-------------------+-------------------+-------------------+------------------------+---------------------
> 0 | /tmp | 11002 | up | 0.500000 | primary | 0 |
> false | 0 | |
> | 2020-08-01 15:34:15
> 1 | /tmp | 11003 | up | 0.500000 | standby | 0 |
> true | 0 | |
> | 2020-08-01 15:34:19
> (2 rows)
>
> shutdown all
>
> pgpool-II setting for streaming replication mode is done.
> To start the whole system, use
> /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/073.pg_terminate_backend/testdir/startall.
> To shutdown the whole system, use
> /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/073.pg_terminate_backend/testdir/shutdownall.
> pcp command user name is "t-ishii", password is "t-ishii".
> Each PostgreSQL, pgpool-II and pcp port is as follows:
> #1 port is 11002
> #2 port is 11003
> pgpool port is 11000
> pcp port is 11001
> The info above is in README.port.
> done.
> waiting for server to start....15620 2020-08-01 15:34:25 JST LOG:
> starting PostgreSQL 12.3 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu
> 7.5.0-3ubuntu1~18.04) 7.5.0, 64-bit
> 15620 2020-08-01 15:34:25 JST LOG: listening on IPv4 address "0.0.0.0",
> port 11002
> 15620 2020-08-01 15:34:25 JST LOG: listening on IPv6 address "::", port
> 11002
> 15620 2020-08-01 15:34:25 JST LOG: listening on Unix socket
> "/tmp/.s.PGSQL.11002"
> 15620 2020-08-01 15:34:25 JST LOG: redirecting log output to logging
> collector process
> 15620 2020-08-01 15:34:25 JST HINT: Future log output will appear in
> directory "log".
> done
> server started
> waiting for server to start....15633 2020-08-01 15:34:25 JST LOG:
> starting PostgreSQL 12.3 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu
> 7.5.0-3ubuntu1~18.04) 7.5.0, 64-bit
> 15633 2020-08-01 15:34:25 JST LOG: listening on IPv4 address "0.0.0.0",
> port 11003
> 15633 2020-08-01 15:34:25 JST LOG: listening on IPv6 address "::", port
> 11003
> 15633 2020-08-01 15:34:25 JST LOG: listening on Unix socket
> "/tmp/.s.PGSQL.11003"
> 15633 2020-08-01 15:34:25 JST LOG: redirecting log output to logging
> collector process
> 15633 2020-08-01 15:34:25 JST HINT: Future log output will appear in
> directory "log".
> done
> server started
> pg_terminate_backend
> ----------------------
> t
> (1 row)
>
> FATAL: terminating connection due to administrator command
> ERROR: unable to forward message to frontend
> DETAIL: FATAL error occured on backend
> server closed the connection unexpectedly
> This probably means the server terminated abnormally
> before or while processing the request.
> connection to server was lost
> 2020-08-01 15:34:28: psql pid 15671: LOG: found the pg_terminate_backend
> request for backend pid:15693 on backend node:0
> count_up: 2
> count_down: 2
> 2020-08-01 15:34:33: main pid 15719: DEBUG: initializing pool
> configuration
> 2020-08-01 15:34:33: main pid 15719: DETAIL: num_backends: 2
> total_weight: 2.000000
> 2020-08-01 15:34:33: main pid 15719: DEBUG: initializing pool
> configuration
> 2020-08-01 15:34:33: main pid 15719: DETAIL: backend 0 weight:
> 1073741823.500000 flag: 0000
> 2020-08-01 15:34:33: main pid 15719: DEBUG: initializing pool
> configuration
> 2020-08-01 15:34:33: main pid 15719: DETAIL: backend 1 weight:
> 1073741823.500000 flag: 0000
> 2020-08-01 15:34:33: main pid 15719: LOG: stop request sent to pgpool.
> waiting for termination...
> .done.
> 2020-08-01 15:34:34: main pid 15719: DEBUG: shmem_exit(-1): 2 callbacks
> to make
> 2020-08-01 15:34:34: main pid 15719: DEBUG: proc_exit(-1): 0 callbacks to
> make
> waiting for server to shut down.... done
> server stopped
> waiting for server to shut down.... done
> server stopped
> creating test environment...PostgreSQL major version: 123
> Starting set up in native replication mode
> creating startall and shutdownall
> creating failover script
> creating database cluster
> /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/073.pg_terminate_backend/testdir/data0...done.
> update postgresql.conf
> creating pgpool_remote_start
> creating basebackup.sh
> creating database cluster
> /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/073.pg_terminate_backend/testdir/data1...done.
> update postgresql.conf
> creating pgpool_remote_start
> creating basebackup.sh
> start all
> waiting for pgpool-II coming up...done.
> create extensions
> node_id | hostname | port | status | lb_weight | role | select_cnt |
> load_balance_node | replication_delay | replication_state |
> replication_sync_state | last_status_change
>
> ---------+----------+-------+--------+-----------+--------+------------+-------------------+-------------------+-------------------+------------------------+---------------------
> 0 | /tmp | 11002 | up | 0.500000 | master | 0 |
> true | 0 | |
> | 2020-08-01 15:34:37
> 1 | /tmp | 11003 | up | 0.500000 | slave | 0 |
> false | 0 | |
> | 2020-08-01 15:34:37
> (2 rows)
>
> shutdown all
>
> pgpool-II setting for native replication mode is done.
> To start the whole system, use
> /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/073.pg_terminate_backend/testdir/startall.
> To shutdown the whole system, use
> /home/t-ishii/work/Pgpool-II/current/pgpool2/src/test/regression/tests/073.pg_terminate_backend/testdir/shutdownall.
> pcp command user name is "t-ishii", password is "t-ishii".
> Each PostgreSQL, pgpool-II and pcp port is as follows:
> #1 port is 11002
> #2 port is 11003
> pgpool port is 11000
> pcp port is 11001
> The info above is in README.port.
> done.
> waiting for server to start....15952 2020-08-01 15:34:45 JST LOG:
> starting PostgreSQL 12.3 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu
> 7.5.0-3ubuntu1~18.04) 7.5.0, 64-bit
> 15952 2020-08-01 15:34:45 JST LOG: listening on IPv4 address "0.0.0.0",
> port 11002
> 15952 2020-08-01 15:34:45 JST LOG: listening on IPv6 address "::", port
> 11002
> 15952 2020-08-01 15:34:45 JST LOG: listening on Unix socket
> "/tmp/.s.PGSQL.11002"
> 15952 2020-08-01 15:34:45 JST LOG: redirecting log output to logging
> collector process
> 15952 2020-08-01 15:34:45 JST HINT: Future log output will appear in
> directory "log".
> done
> server started
> waiting for server to start....15967 2020-08-01 15:34:45 JST LOG:
> starting PostgreSQL 12.3 on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu
> 7.5.0-3ubuntu1~18.04) 7.5.0, 64-bit
> 15967 2020-08-01 15:34:45 JST LOG: listening on IPv4 address "0.0.0.0",
> port 11003
> 15967 2020-08-01 15:34:45 JST LOG: listening on IPv6 address "::", port
> 11003
> 15967 2020-08-01 15:34:45 JST LOG: listening on Unix socket
> "/tmp/.s.PGSQL.11003"
> 15967 2020-08-01 15:34:45 JST LOG: redirecting log output to logging
> collector process
> 15967 2020-08-01 15:34:45 JST HINT: Future log output will appear in
> directory "log".
> done
> server started
> pg_terminate_backend
> ----------------------
> t
> (1 row)
>
> 2020-08-01 15:34:48: psql pid 16011: LOG: found the pg_terminate_backend
> request for backend pid:16028 on backend node:0
> count_up: 2
> count_down: 1
> connection count is not matched.
> 2020-08-01 15:34:53: main pid 16057: DEBUG: initializing pool
> configuration
> 2020-08-01 15:34:53: main pid 16057: DETAIL: num_backends: 2
> total_weight: 2.000000
> 2020-08-01 15:34:53: main pid 16057: DEBUG: initializing pool
> configuration
> 2020-08-01 15:34:53: main pid 16057: DETAIL: backend 0 weight:
> 1073741823.500000 flag: 0000
> 2020-08-01 15:34:53: main pid 16057: DEBUG: initializing pool
> configuration
> 2020-08-01 15:34:53: main pid 16057: DETAIL: backend 1 weight:
> 1073741823.500000 flag: 0000
> 2020-08-01 15:34:53: main pid 16057: LOG: stop request sent to pgpool.
> waiting for termination...
> .WARNING: write on backend 0 failed with error :"Success"
> DETAIL: while trying to write data from offset: 0 wlen: 5
> server closed the connection unexpectedly
> This probably means the server terminated abnormally
> before or while processing the request.
> connection to server was lost
> done.
> 2020-08-01 15:34:54: main pid 16057: DEBUG: shmem_exit(-1): 2 callbacks
> to make
> 2020-08-01 15:34:54: main pid 16057: DEBUG: proc_exit(-1): 0 callbacks to
> make
> waiting for server to shut down....... done
> server stopped
> waiting for server to shut down....... done
> server stopped
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.sraoss.jp/pipermail/pgpool-hackers/attachments/20200813/347a94b2/attachment.html>
More information about the pgpool-hackers
mailing list