[pgpool-general: 5362] Question about pcp_recovery_node in pgpool-II 3.6.1

[晓庆]

Hello everyone,


My environment is CentOS 7.2 + postgresql-9.6.2 + pgpool-II 3.6.1, I use the source code make install pgpool-II 3.6.1 and postgresql-9.6.2.
I have two servers, and I configured failover and recovery in the two servers , failover can work properly, but recovery has some issue as the following:


[postgres at pg-server2 ~]$ pcp_recovery_node -n 0 -d -h 192.168.1.141 -p 9898 -U postgres -W
Password: 
DEBUG: recv: tos="m", len=8
DEBUG: recv: tos="r", len=21
DEBUG: send: tos="D", len=6
DEBUG: recv: tos="N", len=90
BACKEND WARNING:  failed to lock semaphore error:"Invalid argument"
DEBUG: recv: tos="N", len=92
BACKEND WARNING:  failed to unlock semaphore error:"Invalid argument"
DEBUG: recv: tos="N", len=90
BACKEND WARNING:  failed to lock semaphore error:"Invalid argument"
DEBUG: recv: tos="N", len=92
BACKEND WARNING:  failed to unlock semaphore error:"Invalid argument"
DEBUG: recv: tos="E", len=133
ERROR:  executing recovery, execution of command failed at "1st stage"
DETAIL:  command:"recovery_1st_stage.sh"
DEBUG: send: tos="X", len=4


in pgpool.log:


Mar 14 12:09:20 pg-server1 pgpool[1612]: [94-1] 2017-03-14 12:09:20: pid 1612: LOG:  fork a new worker child process with pid: 2269
Mar 14 12:09:21 pg-server1 pgpool[2262]: [24-1] 2017-03-14 12:09:21: pid 2262: WARNING:  failed to lock semaphore error:"Invalid argument"
Mar 14 12:09:21 pg-server1 pgpool[2262]: [25-1] 2017-03-14 12:09:21: pid 2262: WARNING:  failed to unlock semaphore error:"Invalid argument"
Mar 14 12:09:21 pg-server1 pgpool[2262]: [26-1] 2017-03-14 12:09:21: pid 2262: LOG:  new connection received
Mar 14 12:09:21 pg-server1 pgpool[2262]: [26-2] 2017-03-14 12:09:21: pid 2262: DETAIL:  connecting host=pg-server1 port=53453
Mar 14 12:09:23 pg-server1 pgpool[2262]: [27-1] 2017-03-14 12:09:23: pid 2262: LOG:  statement: show pool_nodes;
Mar 14 12:09:26 pg-server1 pgpool[2262]: [28-1] 2017-03-14 12:09:26: pid 2262: LOG:  statement: show pool_nodes;
Mar 14 12:10:20 pg-server1 pgpool[2268]: [28-1] 2017-03-14 12:10:20: pid 2268: LOG:  forked new pcp worker, pid=2330 socket=8
Mar 14 12:10:20 pg-server1 pgpool[2330]: [28-1] 2017-03-14 12:10:20: pid 2330: WARNING:  failed to lock semaphore error:"Invalid argument"
Mar 14 12:10:20 pg-server1 pgpool[2330]: [29-1] 2017-03-14 12:10:20: pid 2330: WARNING:  failed to unlock semaphore error:"Invalid argument"
Mar 14 12:10:20 pg-server1 pgpool[2330]: [30-1] 2017-03-14 12:10:20: pid 2330: LOG:  starting recovering node 0
Mar 14 12:10:20 pg-server1 pgpool[2330]: [31-1] 2017-03-14 12:10:20: pid 2330: LOG:  executing recovery
Mar 14 12:10:20 pg-server1 pgpool[2330]: [31-2] 2017-03-14 12:10:20: pid 2330: DETAIL:  starting recovery command: "SELECT pgpool_recovery('recovery_1st_stage.sh', 'pg-server1', '/pgdata', '5432')"
Mar 14 12:10:20 pg-server1 pgpool[2330]: [32-1] 2017-03-14 12:10:20: pid 2330: LOG:  executing recovery
Mar 14 12:10:20 pg-server1 pgpool[2330]: [32-2] 2017-03-14 12:10:20: pid 2330: DETAIL:  disabling statement_timeout
Mar 14 12:10:20 pg-server1 pgpool[2330]: [33-1] 2017-03-14 12:10:20: pid 2330: WARNING:  failed to lock semaphore error:"Invalid argument"
Mar 14 12:10:20 pg-server1 pgpool[2330]: [34-1] 2017-03-14 12:10:20: pid 2330: WARNING:  failed to unlock semaphore error:"Invalid argument"
Mar 14 12:10:20 pg-server1 pgpool[2330]: [35-1] 2017-03-14 12:10:20: pid 2330: ERROR:  executing recovery, execution of command failed at "1st stage"
Mar 14 12:10:20 pg-server1 pgpool[2330]: [35-2] 2017-03-14 12:10:20: pid 2330: DETAIL:  command:"recovery_1st_stage.sh"


recovery_1st_stage.sh will output log when it is called. But I didn't see the log or log file when it went wrong. So I feel that recovery_1st_stage.sh is not being executed.
note: recovery_1st_stage.sh in the $PGDATA directory.I think pgpool should have found the recovery_1st_stage.sh,because If I put the file in the wrong directory, the error is completely different.


"recovery_1st_stage.sh"
#!/bin/bash
# Recovers a standby server.
echo "recovery_1st_stage - at: ${HOSTNAME}"
echo "recovery_1st_stage - at: ${HOSTNAME}" >> /var/log/pgpool/recovery_1st_stage.log

.......


I tested this script recovery_1st_stage.sh, it can be executed successfully.
[postgres at pg-server2 pgdata]$ ./recovery_1st_stage.sh /pgdata pg-server1 /pgdata 5432


and, pgpool_recovery() can also be successfully executed
postgres=# SELECT pgpool_recovery('recovery_1st_stage.sh', 'pg-server1', '/pgdata', '5432');        
 pgpool_recovery 
-----------------
 t
(1 row)



Finally, pcp_attach_node can perform successfully, but there will be an alarm


[postgres at pg-server2 pgdata]$ pcp_attach_node -d -n 0 -h pg-server1 -p 9898 -U postgres -W
Password: 
DEBUG: recv: tos="m", len=8
DEBUG: recv: tos="r", len=21
DEBUG: send: tos="C", len=6
DEBUG: recv: tos="N", len=90
BACKEND WARNING:  failed to lock semaphore error:"Invalid argument"
DEBUG: recv: tos="N", len=92
BACKEND WARNING:  failed to unlock semaphore error:"Invalid argument"
DEBUG: recv: tos="c", len=20
pcp_attach_node -- Command Successful
DEBUG: send: tos="X", len=4


The attachment is my pgpool.conf on two servers.
Can you give me some advice to make pcp_recovery_node work properly?
Any advice will be appreciated! Thank you very much!





paul_wang79 at qq.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.sraoss.jp/pipermail/pgpool-general/attachments/20170314/dca7240f/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pgpool.conf_pg-server1
Type: application/octet-stream
Size: 34855 bytes
Desc: not available
URL: <http://www.sraoss.jp/pipermail/pgpool-general/attachments/20170314/dca7240f/attachment-0002.obj>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: pgpool.conf_pg-server2
Type: application/octet-stream
Size: 34855 bytes
Desc: not available
URL: <http://www.sraoss.jp/pipermail/pgpool-general/attachments/20170314/dca7240f/attachment-0003.obj>