[pgpool-hackers: 3573] Re: application_name for Pgpool-II internal process
Tatsuo Ishii
ishii at sraoss.co.jp
Thu Apr 2 20:29:45 JST 2020
> Hi Pgpool-II developers,
>
> Currently it's not easy to distinguish each line in Pgpool-II log by
> it's kind: main process, child process (assigned for each session),
> health check process, replication delay check worker process, pcp main
> process and pcp child process. I mean, it's hard to tell particular
> log line belogs to which process kind.
>
> To improve this situation, I propose to assign fixed string to each
> process kind so that it can be used as a process kind marker using
> "%a" log line prefix option for "application name".
>
> Here is an initial idea for the application names assigned to each
> process kind:
>
> Pgpool-II main process: "main"
> Pgpool-II child process: "child" (should be replaced if application
> name is specified in a start up packet)
> health check process: "health_check%d" (%d is replaced with node id)
> replication delay check worker process: "delay_check_worker"
> PCP main process: "pcp_main"
> PCP child process: "pcp_child"
>
> What do you think?
I have implemented initial version of this. Below is pgpool log with
log_min_messages = debug1
and
log_line_prefix = '%t: %a: pid %p: '
(watchdog is enabled).
I gave application names to watchdog related process as well.
Patch attached.
2020-04-02 20:17:47: main: pid 17293: DEBUG: initializing pool configuration
2020-04-02 20:17:47: main: pid 17293: DETAIL: num_backends: 2 total_weight: 2.000000
2020-04-02 20:17:47: main: pid 17293: DEBUG: initializing pool configuration
2020-04-02 20:17:47: main: pid 17293: DETAIL: backend 0 weight: 1073741823.500000 flag: 0000
2020-04-02 20:17:47: main: pid 17293: DEBUG: initializing pool configuration
2020-04-02 20:17:47: main: pid 17293: DETAIL: backend 1 weight: 1073741823.500000 flag: 0000
2020-04-02 20:17:47: main: pid 17293: LOG: Backend status file /home/t-ishii/work/Pgpool-II/current/ccc/pgpool0/log/pgpool_status discarded
2020-04-02 20:17:47: main: pid 17293: DEBUG: pool_coninfo_size: num_init_children (32) * max_pool (4) * MAX_NUM_BACKENDS (128) * sizeof(ConnectionInfo) (136) = 2228224 bytes requested for shared memory
2020-04-02 20:17:47: main: pid 17293: DEBUG: ProcessInfo: num_init_children (32) * sizeof(ProcessInfo) (32) = 1024 bytes requested for shared memory
2020-04-02 20:17:47: main: pid 17293: DEBUG: Request info are: sizeof(POOL_REQUEST_INFO) 5264 bytes requested for shared memory
2020-04-02 20:17:47: main: pid 17293: DEBUG: Recovery management area: sizeof(int) 4 bytes requested for shared memory
2020-04-02 20:17:47: main: pid 17293: LOG: memory cache initialized
2020-04-02 20:17:47: main: pid 17293: DETAIL: memcache blocks :64
2020-04-02 20:17:47: main: pid 17293: DEBUG: memory cache request size : 67108864
2020-04-02 20:17:47: main: pid 17293: LOG: pool_discard_oid_maps: discarded memqcache oid maps
2020-04-02 20:17:48: main: pid 17293: LOG: health_check_stats_shared_memory_size: requested size: 12288
2020-04-02 20:17:48: main: pid 17293: LOG: health_check_stats_shared_memory_size: requested size: 12288
2020-04-02 20:17:48: main: pid 17293: LOG: waiting for watchdog to initialize
2020-04-02 20:17:48: watchdog: pid 17310: LOG: setting the local watchdog node name to "localhost:50000 Linux tishii-CFSV7-1"
2020-04-02 20:17:48: watchdog: pid 17310: LOG: watchdog cluster is configured with 2 remote nodes
2020-04-02 20:17:48: watchdog: pid 17310: LOG: watchdog remote node:0 on localhost:50006
2020-04-02 20:17:48: watchdog: pid 17310: LOG: watchdog remote node:1 on localhost:50010
2020-04-02 20:17:48: watchdog: pid 17310: LOG: interface monitoring is disabled in watchdog
2020-04-02 20:17:48: watchdog: pid 17310: INFO: IPC socket path: "/tmp/.s.PGPOOLWD_CMD.50002"
2020-04-02 20:17:48: watchdog: pid 17310: LOG: watchdog node state changed from [DEAD] to [LOADING]
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = STATE CHANGED Current State = LOADING
2020-04-02 20:17:48: watchdog: pid 17310: LOG: new watchdog node connection is received from "127.0.0.1:157"
2020-04-02 20:17:48: watchdog: pid 17310: LOG: new outbound connection to localhost:50006
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = NEW OUTBOUND_CONNECTION Current State = LOADING
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[] command id:[4] type:[ADD NODE] state:[LOADING]
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[A], command ID:4, data Length:323
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: error in outbound connection to localhost:50010
2020-04-02 20:17:48: watchdog: pid 17310: DETAIL: Connection refused
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: received watchdog packet type:A
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: reading packet type A of length 323
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: ADD NODE MESSAGE from hostname:"localhost" port:50006 pgpool_port:50004
2020-04-02 20:17:48: watchdog: pid 17310: LOG: new node joined the cluster hostname:"localhost" port:50006 pgpool_port:50004
2020-04-02 20:17:48: watchdog: pid 17310: DETAIL: Pgpool-II version:"4.2devel" watchdog messaging version: 1.1
2020-04-02 20:17:48: watchdog: pid 17310: LOG: new watchdog node connection is received from "127.0.0.1:2717"
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: received watchdog packet type:A
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: reading packet type A of length 323
2020-04-02 20:17:48: watchdog: pid 17310: DEBUG: ADD NODE MESSAGE from hostname:"localhost" port:50010 pgpool_port:50008
2020-04-02 20:17:48: watchdog: pid 17310: LOG: new node joined the cluster hostname:"localhost" port:50010 pgpool_port:50008
2020-04-02 20:17:48: watchdog: pid 17310: DETAIL: Pgpool-II version:"4.2devel" watchdog messaging version: 1.1
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = TIMEOUT Current State = LOADING
2020-04-02 20:17:53: watchdog: pid 17310: LOG: watchdog node state changed from [LOADING] to [JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = STATE CHANGED Current State = JOINING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[5] type:[REQUEST INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[B], command ID:5, data Length:0
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[5] type:[REQUEST INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[B], command ID:5, data Length:0
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[6] type:[NODE INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[I], command ID:6, data Length:323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[6] type:[NODE INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[I], command ID:6, data Length:323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received watchdog packet type:B
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: reading packet type B of length 0
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = JOINING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[5] type:[REQUEST INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: packet B with command ID 5 is reply to the command B
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[5] type:[NODE INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[I], command ID:5, data Length:323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = JOINING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[7] type:[NODE INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = JOINING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[6] type:[NODE INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = JOINING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[5] type:[NODE INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: packet I with command ID 5 is reply to the command B
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: Watchdog node "localhost:50008 Linux tishii-CFSV7-1" has replied for command id 5
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = JOINING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[5] type:[NODE INFO] state:[JOINING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: packet I with command ID 5 is reply to the command B
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: Watchdog node "localhost:50004 Linux tishii-CFSV7-1" has replied for command id 5
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: command I with command id 5 is finished with COMMAND_FINISHED_ALL_REPLIED
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = COMMAND FINISHED Current State = JOINING
2020-04-02 20:17:53: watchdog: pid 17310: LOG: watchdog node state changed from [JOINING] to [INITIALIZING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = STATE CHANGED Current State = INITIALIZING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[7] type:[NODE INFO] state:[INITIALIZING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[I], command ID:7, data Length:323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[7] type:[NODE INFO] state:[INITIALIZING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[I], command ID:7, data Length:323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = INITIALIZING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[8] type:[NODE INFO] state:[INITIALIZING]
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = INITIALIZING
2020-04-02 20:17:53: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[7] type:[NODE INFO] state:[INITIALIZING]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:S
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type S of length 0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = INITIALIZING
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[8] type:[STAND FOR COORDINATOR] state:[INITIALIZING]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = TIMEOUT Current State = INITIALIZING
2020-04-02 20:17:54: watchdog: pid 17310: LOG: watchdog node state changed from [INITIALIZING] to [STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = STATE CHANGED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[8] type:[STAND FOR COORDINATOR] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[S], command ID:8, data Length:0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[8] type:[STAND FOR COORDINATOR] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[S], command ID:8, data Length:0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[9] type:[NODE INFO] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[I], command ID:9, data Length:323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[9] type:[NODE INFO] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[I], command ID:9, data Length:323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[9] type:[NODE INFO] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:S
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type S of length 0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[9] type:[STAND FOR COORDINATOR] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[9] type:[REJECT] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[R], command ID:9, data Length:0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:G
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type G of length 0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[8] type:[ACCEPT] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: packet G with command ID 8 is reply to the command S
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: Watchdog node "localhost:50004 Linux tishii-CFSV7-1" has replied for command id 8
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[10] type:[NODE INFO] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[10] type:[NODE INFO] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[11] type:[NODE INFO] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:G
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type G of length 0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[8] type:[ACCEPT] state:[STANDING FOR MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: packet G with command ID 8 is reply to the command S
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: Watchdog node "localhost:50008 Linux tishii-CFSV7-1" has replied for command id 8
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: command G with command id 8 is finished with COMMAND_FINISHED_ALL_REPLIED
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = COMMAND FINISHED Current State = STANDING FOR MASTER
2020-04-02 20:17:54: watchdog: pid 17310: LOG: watchdog node state changed from [STANDING FOR MASTER] to [MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = STATE CHANGED Current State = MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[10] type:[DECLARE COORDINATOR] state:[MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[C], command ID:10, data Length:0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[10] type:[DECLARE COORDINATOR] state:[MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[C], command ID:10, data Length:0
2020-04-02 20:17:54: watchdog: pid 17310: LOG: I am announcing my self as master/coordinator watchdog node
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[11] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[I], command ID:11, data Length:323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[11] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[I], command ID:11, data Length:323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:G
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type G of length 0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[10] type:[ACCEPT] state:[MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: packet G with command ID 10 is reply to the command C
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: Watchdog node "localhost:50004 Linux tishii-CFSV7-1" has replied for command id 10
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:G
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type G of length 0
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[10] type:[ACCEPT] state:[MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: packet G with command ID 10 is reply to the command C
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: Watchdog node "localhost:50008 Linux tishii-CFSV7-1" has replied for command id 10
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: command G with command id 10 is finished with COMMAND_FINISHED_ALL_REPLIED
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = COMMAND FINISHED Current State = MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: declare coordinator command finished with status:[ALL NODES REPLIED]
2020-04-02 20:17:54: watchdog: pid 17310: DETAIL: The command was sent to 2 nodes and 2 nodes replied to it
2020-04-02 20:17:54: watchdog: pid 17310: LOG: I am the cluster leader node
2020-04-02 20:17:54: watchdog: pid 17310: DETAIL: our declare coordinator message is accepted by all nodes
2020-04-02 20:17:54: watchdog: pid 17310: LOG: setting the local node "localhost:50000 Linux tishii-CFSV7-1" as watchdog cluster master
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending signal:10 to the parent process with PID:17293
2020-04-02 20:17:54: watchdog: pid 17310: LOG: I am the cluster leader node but we do not have enough nodes in cluster
2020-04-02 20:17:54: watchdog: pid 17310: DETAIL: waiting for the quorum to start escalation process
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:54: main: pid 17293: LOG: watchdog process is initialized
2020-04-02 20:17:54: main: pid 17293: DETAIL: watchdog messaging data version: 1.1
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[11] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[12] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:54: main: pid 17293: DEBUG: Pgpool-II parent process received SIGUSR1
2020-04-02 20:17:54: main: pid 17293: DEBUG: Pgpool-II parent process received watchdog state change signal from watchdog
2020-04-02 20:17:54: life_check: pid 17313: DEBUG: I am watchdog lifecheck child with pid:17313
2020-04-02 20:17:54: watchdog: pid 17310: LOG: new IPC connection received
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:12, type:[7], command ID:0, data Length:34
2020-04-02 20:17:54: watchdog: pid 17310: LOG: new IPC connection received
2020-04-02 20:17:54: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:12, type:[7], command ID:0, data Length:752
2020-04-02 20:17:54: life_check: pid 17313: LOG: 3 watchdog nodes are configured for lifecheck
2020-04-02 20:17:54: life_check: pid 17313: LOG: watchdog nodes ID:0 Name:"localhost:50000 Linux tishii-CFSV7-1"
2020-04-02 20:17:54: life_check: pid 17313: DETAIL: Host:"localhost" WD Port:50002 pgpool-II port:50000
2020-04-02 20:17:54: life_check: pid 17313: LOG: watchdog nodes ID:1 Name:"localhost:50004 Linux tishii-CFSV7-1"
2020-04-02 20:17:54: life_check: pid 17313: DETAIL: Host:"localhost" WD Port:50006 pgpool-II port:50004
2020-04-02 20:17:54: life_check: pid 17313: LOG: watchdog nodes ID:2 Name:"localhost:50008 Linux tishii-CFSV7-1"
2020-04-02 20:17:54: life_check: pid 17313: DETAIL: Host:"localhost" WD Port:50010 pgpool-II port:50008
2020-04-02 20:17:54: main: pid 17293: LOG: Setting up socket for 127.0.0.1:50000
2020-04-02 20:17:54: child: pid 17314: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17316: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17318: DEBUG: initializing backend status
2020-04-02 20:17:54: life_check: pid 17313: DEBUG: watchdog checking life check is ready
2020-04-02 20:17:54: life_check: pid 17313: DETAIL: pgpool:1 at "localhost:50004" has not send the heartbeat signal yet
2020-04-02 20:17:54: life_check: pid 17313: DEBUG: watchdog checking life check is ready
2020-04-02 20:17:54: life_check: pid 17313: DETAIL: pgpool:2 at "localhost:50008" has not send the heartbeat signal yet
2020-04-02 20:17:54: child: pid 17322: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17323: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17320: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17324: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17325: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17326: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17328: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17327: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17330: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17329: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17332: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17331: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17334: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17335: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17333: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17337: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17336: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17338: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17339: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17340: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17341: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17343: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17342: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17344: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17345: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17346: DEBUG: initializing backend status
2020-04-02 20:17:54: main: pid 17293: LOG: find_primary_node_repeatedly: waiting for finding a primary node
2020-04-02 20:17:54: child: pid 17347: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17348: DEBUG: initializing backend status
2020-04-02 20:17:54: child: pid 17349: DEBUG: initializing backend status
2020-04-02 20:17:54: main: pid 17293: DEBUG: authenticate kind = 0
2020-04-02 20:17:54: main: pid 17293: DEBUG: authenticate backend: key data received
2020-04-02 20:17:54: main: pid 17293: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:17:54: main: pid 17293: DEBUG: authenticate kind = 0
2020-04-02 20:17:54: main: pid 17293: DEBUG: authenticate backend: key data received
2020-04-02 20:17:54: main: pid 17293: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:17:54: main: pid 17293: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()"
2020-04-02 20:17:54: main: pid 17293: DEBUG: do_query: extended:0 query:"SELECT current_setting('server_version_num')"
2020-04-02 20:17:54: main: pid 17293: DEBUG: get_server_version: backend 0 server version: 120000
2020-04-02 20:17:54: main: pid 17293: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()"
2020-04-02 20:17:54: main: pid 17293: DEBUG: do_query: extended:0 query:"SELECT current_setting('server_version_num')"
2020-04-02 20:17:54: main: pid 17293: DEBUG: get_server_version: backend 1 server version: 120000
2020-04-02 20:17:54: main: pid 17293: DEBUG: verify_backend_node_status: multiple standbys: 1
2020-04-02 20:17:54: main: pid 17293: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2020-04-02 20:17:54: main: pid 17293: LOG: find_primary_node: primary node is 0
2020-04-02 20:17:54: main: pid 17293: LOG: find_primary_node: standby node is 1
2020-04-02 20:17:54: main: pid 17352: DEBUG: I am PCP child with pid:17352
2020-04-02 20:17:54: main: pid 17352: LOG: PCP process: 17352 started
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: I am 17353
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: initializing backend status
2020-04-02 20:17:54: health_check0: pid 17354: DEBUG: I am health check process pid:17354 DB node id:0
2020-04-02 20:17:54: health_check0: pid 17354: DEBUG: initializing backend status
2020-04-02 20:17:54: health_check0: pid 17354: DEBUG: health check: clearing alarm
2020-04-02 20:17:54: health_check1: pid 17355: DEBUG: I am health check process pid:17355 DB node id:1
2020-04-02 20:17:54: health_check1: pid 17355: DEBUG: initializing backend status
2020-04-02 20:17:54: health_check1: pid 17355: DEBUG: health check: clearing alarm
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: authenticate kind = 0
2020-04-02 20:17:54: health_check0: pid 17354: DEBUG: authenticate kind = 0
2020-04-02 20:17:54: health_check0: pid 17354: DEBUG: authenticate backend: key data received
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: authenticate backend: key data received
2020-04-02 20:17:54: health_check0: pid 17354: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:17:54: health_check0: pid 17354: DEBUG: health check: clearing alarm
2020-04-02 20:17:54: health_check0: pid 17354: DEBUG: health check: clearing alarm
2020-04-02 20:17:54: health_check1: pid 17355: DEBUG: authenticate kind = 0
2020-04-02 20:17:54: health_check1: pid 17355: DEBUG: authenticate backend: key data received
2020-04-02 20:17:54: health_check1: pid 17355: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:17:54: health_check1: pid 17355: DEBUG: health check: clearing alarm
2020-04-02 20:17:54: health_check1: pid 17355: DEBUG: health check: clearing alarm
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: authenticate kind = 0
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: authenticate backend: key data received
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT current_setting('server_version_num')"
2020-04-02 20:17:54: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: backend 0 server version: 120000
2020-04-02 20:17:54: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT pg_current_wal_lsn()"
2020-04-02 20:17:54: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT current_setting('server_version_num')"
2020-04-02 20:17:54: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: backend 1 server version: 120000
2020-04-02 20:17:54: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT pg_last_wal_replay_lsn()"
2020-04-02 20:17:54: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT application_name, state, sync_state FROM pg_stat_replication"
2020-04-02 20:17:54: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()"
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()"
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: verify_backend_node_status: multiple standbys: 1
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: node status[0]: 1
2020-04-02 20:17:54: sr_check_worker: pid 17353: DEBUG: node status[1]: 2
2020-04-02 20:17:54: main: pid 17293: LOG: pgpool-II successfully started. version 4.2devel (chichiriboshi)
2020-04-02 20:17:54: main: pid 17293: LOG: node status[0]: 1
2020-04-02 20:17:54: main: pid 17293: LOG: node status[1]: 2
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received watchdog packet type:J
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: reading packet type J of length 0
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[12] type:[JOIN COORDINATOR] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[12] type:[ACCEPT] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[G], command ID:12, data Length:0
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[12] type:[ASK FOR POOL CONFIG] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[Y], command ID:12, data Length:0
2020-04-02 20:17:55: watchdog: pid 17310: LOG: adding watchdog node "localhost:50004 Linux tishii-CFSV7-1" to the standby list
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = CLUSTER QUORUM STATUS CHANGED Current State = MASTER
2020-04-02 20:17:55: watchdog: pid 17310: LOG: quorum found
2020-04-02 20:17:55: watchdog: pid 17310: DETAIL: starting escalation process
2020-04-02 20:17:55: watchdog: pid 17310: LOG: escalation process started with PID:17363
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[13] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[I], command ID:13, data Length:323
2020-04-02 20:17:55: watchdog_utility: pid 17363: LOG: watchdog: escalation started
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[13] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[I], command ID:13, data Length:323
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending signal:10 to the parent process with PID:17293
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:55: main: pid 17293: DEBUG: Pgpool-II parent process received SIGUSR1
2020-04-02 20:17:55: main: pid 17293: LOG: Pgpool-II parent process received watchdog quorum change signal from watchdog
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[13] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received watchdog packet type:J
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: reading packet type J of length 0
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[13] type:[JOIN COORDINATOR] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[13] type:[ACCEPT] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[G], command ID:13, data Length:0
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[14] type:[ASK FOR POOL CONFIG] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[Y], command ID:14, data Length:0
2020-04-02 20:17:55: watchdog: pid 17310: LOG: adding watchdog node "localhost:50008 Linux tishii-CFSV7-1" to the standby list
2020-04-02 20:17:55: watchdog: pid 17310: LOG: new IPC connection received
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received watchdog packet type:Z
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: reading packet type Z of length 1145
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[12] type:[CONFIG DATA] state:[MASTER]
2020-04-02 20:17:55: heart_beat_sender: pid 17317: LOG: set SO_REUSEPORT option to the socket
2020-04-02 20:17:55: heart_beat_sender: pid 17317: LOG: creating socket for sending heartbeat
2020-04-02 20:17:55: heart_beat_sender: pid 17317: DETAIL: set SO_REUSEPORT
2020-04-02 20:17:55: heart_beat_receiver: pid 17319: LOG: set SO_REUSEPORT option to the socket
2020-04-02 20:17:55: heart_beat_receiver: pid 17319: LOG: creating watchdog heartbeat receive socket.
2020-04-02 20:17:55: heart_beat_receiver: pid 17319: DETAIL: set SO_REUSEPORT
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: reading packet type I of length 323
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:55: heart_beat_sender: pid 17321: LOG: set SO_REUSEPORT option to the socket
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[14] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:55: heart_beat_sender: pid 17321: LOG: creating socket for sending heartbeat
2020-04-02 20:17:55: heart_beat_sender: pid 17321: DETAIL: set SO_REUSEPORT
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: watchdog process signal handler
2020-04-02 20:17:55: watchdog: pid 17310: LOG: watchdog escalation process with pid: 17363 exit with SUCCESS.
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received watchdog packet type:d
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: reading packet type d of length 62
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[14] type:[DATA REQUEST FOR MASTER] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[14] type:[DATA] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[D], command ID:14, data Length:100
2020-04-02 20:17:55: heart_beat_sender: pid 17317: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50007
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received watchdog packet type:d
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: reading packet type d of length 62
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[15] type:[DATA REQUEST FOR MASTER] state:[MASTER]
2020-04-02 20:17:55: heart_beat_sender: pid 17321: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50011
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[15] type:[DATA] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[D], command ID:15, data Length:100
2020-04-02 20:17:55: heart_beat_receiver: pid 17315: LOG: set SO_REUSEPORT option to the socket
2020-04-02 20:17:55: heart_beat_receiver: pid 17315: LOG: creating watchdog heartbeat receive socket.
2020-04-02 20:17:55: heart_beat_receiver: pid 17315: DETAIL: set SO_REUSEPORT
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:12, type:[7], command ID:0, data Length:34
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received watchdog packet type:Z
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: reading packet type Z of length 1145
2020-04-02 20:17:55: main: pid 17293: LOG: watchdog cluster now holds the quorum
2020-04-02 20:17:55: main: pid 17293: DETAIL: updating the state of quarantine backend nodes
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[14] type:[CONFIG DATA] state:[MASTER]
2020-04-02 20:17:55: watchdog: pid 17310: LOG: new IPC connection received
2020-04-02 20:17:55: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:12, type:[7], command ID:0, data Length:34
2020-04-02 20:17:56: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50008" node:localhost:50008 Linux tishii-CFSV7-1
2020-04-02 20:17:56: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50004" node:localhost:50004 Linux tishii-CFSV7-1
2020-04-02 20:17:57: heart_beat_sender: pid 17317: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50007
2020-04-02 20:17:57: heart_beat_sender: pid 17321: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50011
2020-04-02 20:17:58: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50008" node:localhost:50008 Linux tishii-CFSV7-1
2020-04-02 20:17:58: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50004" node:localhost:50004 Linux tishii-CFSV7-1
2020-04-02 20:17:59: heart_beat_sender: pid 17317: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50007
2020-04-02 20:17:59: heart_beat_sender: pid 17321: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50011
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = TIMEOUT Current State = MASTER
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[15] type:[IAM COORDINATOR] state:[MASTER]
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:9, type:[M], command ID:15, data Length:115
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[15] type:[IAM COORDINATOR] state:[MASTER]
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:10, type:[M], command ID:15, data Length:115
2020-04-02 20:17:59: watchdog: pid 17310: LOG: new outbound connection to localhost:50010
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = NEW OUTBOUND_CONNECTION Current State = MASTER
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: sending packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[16] type:[ADD NODE] state:[MASTER]
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: sending watchdog packet to socket:12, type:[A], command ID:16, data Length:324
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: reading packet type I of length 324
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50004 Linux tishii-CFSV7-1] command id:[15] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: packet I with command ID 15 is reply to the command M
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: Watchdog node "localhost:50004 Linux tishii-CFSV7-1" has replied for command id 15
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: received watchdog packet type:I
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: reading packet type I of length 324
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = PACKET RECEIVED Current State = MASTER
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: received packet, watchdog node:[localhost:50008 Linux tishii-CFSV7-1] command id:[15] type:[NODE INFO] state:[MASTER]
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: packet I with command ID 15 is reply to the command M
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: Watchdog node "localhost:50008 Linux tishii-CFSV7-1" has replied for command id 15
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: command I with command id 15 is finished with COMMAND_FINISHED_ALL_REPLIED
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: STATE MACHINE INVOKED WITH EVENT = COMMAND FINISHED Current State = MASTER
2020-04-02 20:17:59: watchdog: pid 17310: DEBUG: I am the cluster leader node command finished with status:[ALL NODES REPLIED]
2020-04-02 20:17:59: watchdog: pid 17310: DETAIL: The command was sent to 2 nodes and 2 nodes replied to it
2020-04-02 20:18:00: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50008" node:localhost:50008 Linux tishii-CFSV7-1
2020-04-02 20:18:00: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50004" node:localhost:50004 Linux tishii-CFSV7-1
2020-04-02 20:18:01: heart_beat_sender: pid 17317: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50007
2020-04-02 20:18:01: heart_beat_sender: pid 17321: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50011
2020-04-02 20:18:02: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50008" node:localhost:50008 Linux tishii-CFSV7-1
2020-04-02 20:18:02: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50004" node:localhost:50004 Linux tishii-CFSV7-1
2020-04-02 20:18:03: heart_beat_sender: pid 17317: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50007
2020-04-02 20:18:03: heart_beat_sender: pid 17321: DEBUG: watchdog heartbeat: send heartbeat signal to localhost:50011
2020-04-02 20:18:04: life_check: pid 17313: LOG: watchdog: lifecheck started
2020-04-02 20:18:04: life_check: pid 17313: DEBUG: watchdog life checking by heartbeat
2020-04-02 20:18:04: life_check: pid 17313: DETAIL: checking pgpool 1 (localhost:50004)
2020-04-02 20:18:04: life_check: pid 17313: DEBUG: watchdog checking if pgpool is alive using heartbeat
2020-04-02 20:18:04: life_check: pid 17313: DETAIL: the last heartbeat from "localhost:50004" received 1 seconds ago
2020-04-02 20:18:04: life_check: pid 17313: DEBUG: checking pgpool status by heartbeat
2020-04-02 20:18:04: life_check: pid 17313: DETAIL: OK; status OK
2020-04-02 20:18:04: life_check: pid 17313: DEBUG: watchdog life checking by heartbeat
2020-04-02 20:18:04: life_check: pid 17313: DETAIL: checking pgpool 2 (localhost:50008)
2020-04-02 20:18:04: life_check: pid 17313: DEBUG: watchdog checking if pgpool is alive using heartbeat
2020-04-02 20:18:04: life_check: pid 17313: DETAIL: the last heartbeat from "localhost:50008" received 1 seconds ago
2020-04-02 20:18:04: life_check: pid 17313: DEBUG: checking pgpool status by heartbeat
2020-04-02 20:18:04: life_check: pid 17313: DETAIL: OK; status OK
2020-04-02 20:18:04: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50008" node:localhost:50008 Linux tishii-CFSV7-1
2020-04-02 20:18:04: heart_beat_receiver: pid 17319: DEBUG: received heartbeat signal from "127.0.0.1(localhost):50004" node:localhost:50004 Linux tishii-CFSV7-1
2020-04-02 20:18:04: health_check0: pid 17354: DEBUG: health check: clearing alarm
2020-04-02 20:18:04: health_check1: pid 17355: DEBUG: health check: clearing alarm
2020-04-02 20:18:04: health_check1: pid 17355: DEBUG: authenticate kind = 0
2020-04-02 20:18:04: health_check1: pid 17355: DEBUG: authenticate backend: key data received
2020-04-02 20:18:04: health_check1: pid 17355: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:18:04: health_check1: pid 17355: DEBUG: health check: clearing alarm
2020-04-02 20:18:04: health_check0: pid 17354: DEBUG: authenticate kind = 0
2020-04-02 20:18:04: health_check1: pid 17355: DEBUG: health check: clearing alarm
2020-04-02 20:18:04: health_check0: pid 17354: DEBUG: authenticate backend: key data received
2020-04-02 20:18:04: health_check0: pid 17354: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:18:04: health_check0: pid 17354: DEBUG: health check: clearing alarm
2020-04-02 20:18:04: health_check0: pid 17354: DEBUG: health check: clearing alarm
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: authenticate kind = 0
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: authenticate backend: key data received
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: authenticate kind = 0
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: authenticate backend: key data received
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: authenticate backend: transaction state: I
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT pg_current_wal_lsn()"
2020-04-02 20:18:04: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT pg_last_wal_replay_lsn()"
2020-04-02 20:18:04: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT application_name, state, sync_state FROM pg_stat_replication"
2020-04-02 20:18:04: sr_check_worker: pid 17353: CONTEXT: while checking replication time lag
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()"
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: do_query: extended:0 query:"SELECT pg_is_in_recovery()"
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: verify_backend_node_status: multiple standbys: 1
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: verify_backend_node_status: detach_false_primary is off and no additional checking is performed
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: node status[0]: 1
2020-04-02 20:18:04: sr_check_worker: pid 17353: DEBUG: node status[1]: 2
-------------- next part --------------
A non-text attachment was scrubbed...
Name: application_name.diff
Type: text/x-patch
Size: 9855 bytes
Desc: not available
URL: <http://www.sraoss.jp/pipermail/pgpool-hackers/attachments/20200402/9f455610/attachment-0001.bin>
More information about the pgpool-hackers
mailing list