[pgpool-general: 9303] Re: pgpool Connection issue: ERROR: unable to read message kind

Mukesh Tanuku mukesh.postgres at gmail.com
Tue Dec 24 11:07:22 JST 2024 

Sometimes i see destination = 3, what this meas?


BTW, Yes, I tried setting it to "remote_apply", but from then on I'm
getting connection timed-out errors from client.

Error in Virtual User 1: Error: Connection to database failed
connection to server at "10.35.8.4", port 6211 failed: Connection timed out
(0x0000274C/10060)
Is the server running on that host and accepting TCP/IP connections?

Nothing is been logged in pgpool.log


2024-12-24 01:59:52.917: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 01:59:53.911: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 01:59:54.918: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 01:59:55.912: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 01:59:56.918: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 01:59:57.912: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 01:59:58.920: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 01:59:59.172: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = TIMEOUT Current State = LEADER
2024-12-24 01:59:59.172: watchdog pid 1582758: DEBUG:  sending packet,
watchdog node:[10.35.8.21:9999 Linux azlpgNkax-0] command id:[80] type:[IAM
COORDINATOR] state:[LEADER]
2024-12-24 01:59:59.172: watchdog pid 1582758: DEBUG:  sending watchdog
packet to socket:8, type:[M], command ID:80, data Length:118
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  received watchdog
packet type:I
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  reading packet type
I of length 346
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = PACKET RECEIVED Current State = LEADER
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  received packet,
watchdog node:[10.35.8.21:9999 Linux azlpgNkax-0] command id:[80]
type:[NODE INFO] state:[LEADER]
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  packet I with
command ID 80 is reply to the command M
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  Watchdog node "
10.35.8.21:9999 Linux azlpgNkax-0" has replied for command id 80
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  command I with
command id 80 is finished with COMMAND_FINISHED_ALL_REPLIED
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = COMMAND FINISHED Current State = LEADER
2024-12-24 01:59:59.174: watchdog pid 1582758: DEBUG:  I am the cluster
leader node command finished with status:[ALL NODES REPLIED]
2024-12-24 01:59:59.174: watchdog pid 1582758: DETAIL:  The command was
sent to 1 nodes and 1 nodes replied to it
2024-12-24 01:59:59.912: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:00.797: life_check pid 1582760: DEBUG:  watchdog life
checking by heartbeat
2024-12-24 02:00:00.798: life_check pid 1582760: DETAIL:  checking pgpool 1
(10.35.8.21:9999)
2024-12-24 02:00:00.798: life_check pid 1582760: DEBUG:  watchdog checking
if pgpool is alive using heartbeat
2024-12-24 02:00:00.798: life_check pid 1582760: DETAIL:  the last
heartbeat from "10.35.8.21:9999" received 1 seconds ago
2024-12-24 02:00:00.798: life_check pid 1582760: DEBUG:  checking pgpool
status by heartbeat
2024-12-24 02:00:00.798: life_check pid 1582760: DETAIL:  OK; status OK
2024-12-24 02:00:00.919: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:01.907: child pid 1582785: DEBUG:  I am 1582785 accept fd 7
2024-12-24 02:00:01.911: child pid 1582785: LOG:  new connection received
2024-12-24 02:00:01.911: child pid 1582785: DETAIL:  connecting
host=168.63.129.16 port=56755
2024-12-24 02:00:01.912: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:02.189: watchdog pid 1582758: DEBUG:  new IPC connection
received
2024-12-24 02:00:02.190: watchdog pid 1582758: DEBUG:  sending watchdog
packet to socket:9, type:[7], command ID:0, data Length:34
2024-12-24 02:00:02.190: sr_check_worker pid 1582799: DEBUG:  watchdog
status: 4
2024-12-24 02:00:02.190: sr_check_worker pid 1582799: DEBUG:
 pool_acquire_follow_primary_lock: lock was not held by anyone
2024-12-24 02:00:02.190: sr_check_worker pid 1582799: DEBUG:
 pool_acquire_follow_primary_lock: succeeded in acquiring lock
2024-12-24 02:00:02.190: sr_check_worker pid 1582799: DEBUG:  SSL is
requested but SSL support is not available
2024-12-24 02:00:02.194: sr_check_worker pid 1582799: DEBUG:  authenticate
kind = 0
2024-12-24 02:00:02.194: sr_check_worker pid 1582799: DEBUG:  authenticate
backend: key data received
2024-12-24 02:00:02.194: sr_check_worker pid 1582799: DEBUG:  authenticate
backend: transaction state: I
2024-12-24 02:00:02.196: sr_check_worker pid 1582799: DEBUG:  SSL is
requested but SSL support is not available
2024-12-24 02:00:02.201: sr_check_worker pid 1582799: DEBUG:  authenticate
kind = 0
2024-12-24 02:00:02.201: sr_check_worker pid 1582799: DEBUG:  authenticate
backend: key data received
2024-12-24 02:00:02.201: sr_check_worker pid 1582799: DEBUG:  authenticate
backend: transaction state: I
2024-12-24 02:00:02.201: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT pg_catalog.pg_current_wal_lsn()"
2024-12-24 02:00:02.201: sr_check_worker pid 1582799: CONTEXT:  while
checking replication time lag
2024-12-24 02:00:02.202: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT pg_catalog.pg_last_wal_replay_lsn()"
2024-12-24 02:00:02.202: sr_check_worker pid 1582799: CONTEXT:  while
checking replication time lag
2024-12-24 02:00:02.203: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT application_name, state, sync_state,(EXTRACT(EPOCH
FROM replay_lag)*1000000)::BIGINT
 FROM pg_catalog.pg_stat_replication"
2024-12-24 02:00:02.203: sr_check_worker pid 1582799: CONTEXT:  while
checking replication time lag
2024-12-24 02:00:02.206: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2024-12-24 02:00:02.206: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2024-12-24 02:00:02.207: sr_check_worker pid 1582799: DEBUG:
 verify_backend_node_status: multiple standbys: 1
2024-12-24 02:00:02.207: sr_check_worker pid 1582799: DEBUG:
 verify_backend_node_status: detach_false_primary is off and no additional
checking is performed
2024-12-24 02:00:02.207: sr_check_worker pid 1582799: DEBUG:  node
status[0]: 1
2024-12-24 02:00:02.207: sr_check_worker pid 1582799: DEBUG:  node
status[1]: 2
2024-12-24 02:00:02.207: sr_check_worker pid 1582799: DEBUG:
 pool_release_follow_primary_lock called
2024-12-24 02:00:02.919: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:03.913: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:04.919: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:05.913: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:06.919: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:07.914: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:08.920: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:09.196: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = TIMEOUT Current State = LEADER
2024-12-24 02:00:09.196: watchdog pid 1582758: DEBUG:  sending packet,
watchdog node:[10.35.8.21:9999 Linux azlpgNkax-0] command id:[81] type:[IAM
COORDINATOR] state:[LEADER]
2024-12-24 02:00:09.196: watchdog pid 1582758: DEBUG:  sending watchdog
packet to socket:8, type:[M], command ID:81, data Length:118
2024-12-24 02:00:09.197: watchdog pid 1582758: DEBUG:  received watchdog
packet type:I
2024-12-24 02:00:09.198: watchdog pid 1582758: DEBUG:  reading packet type
I of length 346
2024-12-24 02:00:09.198: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = PACKET RECEIVED Current State = LEADER
2024-12-24 02:00:09.198: watchdog pid 1582758: DEBUG:  received packet,
watchdog node:[10.35.8.21:9999 Linux azlpgNkax-0] command id:[81]
type:[NODE INFO] state:[LEADER]
2024-12-24 02:00:09.198: watchdog pid 1582758: DEBUG:  packet I with
command ID 81 is reply to the command M
2024-12-24 02:00:09.198: watchdog pid 1582758: DEBUG:  Watchdog node "
10.35.8.21:9999 Linux azlpgNkax-0" has replied for command id 81
2024-12-24 02:00:09.198: watchdog pid 1582758: DEBUG:  command I with
command id 81 is finished with COMMAND_FINISHED_ALL_REPLIED
2024-12-24 02:00:09.198: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = COMMAND FINISHED Current State = LEADER
2024-12-24 02:00:09.198: watchdog pid 1582758: DEBUG:  I am the cluster
leader node command finished with status:[ALL NODES REPLIED]
2024-12-24 02:00:09.198: watchdog pid 1582758: DETAIL:  The command was
sent to 1 nodes and 1 nodes replied to it
2024-12-24 02:00:09.914: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:10.798: life_check pid 1582760: DEBUG:  watchdog life
checking by heartbeat
2024-12-24 02:00:10.798: life_check pid 1582760: DETAIL:  checking pgpool 1
(10.35.8.21:9999)
2024-12-24 02:00:10.798: life_check pid 1582760: DEBUG:  watchdog checking
if pgpool is alive using heartbeat
2024-12-24 02:00:10.798: life_check pid 1582760: DETAIL:  the last
heartbeat from "10.35.8.21:9999" received 1 seconds ago
2024-12-24 02:00:10.798: life_check pid 1582760: DEBUG:  checking pgpool
status by heartbeat
2024-12-24 02:00:10.798: life_check pid 1582760: DETAIL:  OK; status OK
2024-12-24 02:00:10.920: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:11.915: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:12.208: watchdog pid 1582758: DEBUG:  new IPC connection
received
2024-12-24 02:00:12.208: watchdog pid 1582758: DEBUG:  sending watchdog
packet to socket:9, type:[7], command ID:0, data Length:34
2024-12-24 02:00:12.208: sr_check_worker pid 1582799: DEBUG:  watchdog
status: 4
2024-12-24 02:00:12.208: sr_check_worker pid 1582799: DEBUG:
 pool_acquire_follow_primary_lock: lock was not held by anyone
2024-12-24 02:00:12.208: sr_check_worker pid 1582799: DEBUG:
 pool_acquire_follow_primary_lock: succeeded in acquiring lock
2024-12-24 02:00:12.208: sr_check_worker pid 1582799: DEBUG:  SSL is
requested but SSL support is not available
2024-12-24 02:00:12.212: sr_check_worker pid 1582799: DEBUG:  authenticate
kind = 0
2024-12-24 02:00:12.212: sr_check_worker pid 1582799: DEBUG:  authenticate
backend: key data received
2024-12-24 02:00:12.212: sr_check_worker pid 1582799: DEBUG:  authenticate
backend: transaction state: I
2024-12-24 02:00:12.214: sr_check_worker pid 1582799: DEBUG:  SSL is
requested but SSL support is not available
2024-12-24 02:00:12.219: sr_check_worker pid 1582799: DEBUG:  authenticate
kind = 0
2024-12-24 02:00:12.219: sr_check_worker pid 1582799: DEBUG:  authenticate
backend: key data received
2024-12-24 02:00:12.219: sr_check_worker pid 1582799: DEBUG:  authenticate
backend: transaction state: I
2024-12-24 02:00:12.219: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT pg_catalog.pg_current_wal_lsn()"
2024-12-24 02:00:12.219: sr_check_worker pid 1582799: CONTEXT:  while
checking replication time lag
2024-12-24 02:00:12.220: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT pg_catalog.pg_last_wal_replay_lsn()"
2024-12-24 02:00:12.220: sr_check_worker pid 1582799: CONTEXT:  while
checking replication time lag
2024-12-24 02:00:12.221: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT application_name, state, sync_state,(EXTRACT(EPOCH
FROM replay_lag)*1000000)::BIGINT
 FROM pg_catalog.pg_stat_replication"
2024-12-24 02:00:12.221: sr_check_worker pid 1582799: CONTEXT:  while
checking replication time lag
2024-12-24 02:00:12.224: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2024-12-24 02:00:12.224: sr_check_worker pid 1582799: DEBUG:  do_query:
extended:0 query:"SELECT pg_catalog.pg_is_in_recovery()"
2024-12-24 02:00:12.225: sr_check_worker pid 1582799: DEBUG:
 verify_backend_node_status: multiple standbys: 1
2024-12-24 02:00:12.225: sr_check_worker pid 1582799: DEBUG:
 verify_backend_node_status: detach_false_primary is off and no additional
checking is performed
2024-12-24 02:00:12.225: sr_check_worker pid 1582799: DEBUG:  node
status[0]: 1
2024-12-24 02:00:12.225: sr_check_worker pid 1582799: DEBUG:  node
status[1]: 2
2024-12-24 02:00:12.225: sr_check_worker pid 1582799: DEBUG:
 pool_release_follow_primary_lock called
2024-12-24 02:00:12.920: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:13.916: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:14.921: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:15.916: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:16.921: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:16.924: child pid 1582767: DEBUG:  I am 1582767 accept fd 7
2024-12-24 02:00:16.926: child pid 1582767: LOG:  new connection received
2024-12-24 02:00:16.926: child pid 1582767: DETAIL:  connecting
host=168.63.129.16 port=56930
2024-12-24 02:00:17.917: heart_beat_sender pid 1582763: DEBUG:  watchdog
heartbeat: send heartbeat signal to 10.35.8.21:9694
2024-12-24 02:00:18.921: heart_beat_receiver pid 1582762: DEBUG:  received
heartbeat signal from "10.35.8.21(10.35.8.21):9999" node:10.35.8.21:9999
Linux azlpgNkax-0
2024-12-24 02:00:19.214: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = TIMEOUT Current State = LEADER
2024-12-24 02:00:19.214: watchdog pid 1582758: DEBUG:  sending packet,
watchdog node:[10.35.8.21:9999 Linux azlpgNkax-0] command id:[82] type:[IAM
COORDINATOR] state:[LEADER]
2024-12-24 02:00:19.214: watchdog pid 1582758: DEBUG:  sending watchdog
packet to socket:8, type:[M], command ID:82, data Length:118
2024-12-24 02:00:19.215: watchdog pid 1582758: DEBUG:  received watchdog
packet type:I
2024-12-24 02:00:19.216: watchdog pid 1582758: DEBUG:  reading packet type
I of length 346
2024-12-24 02:00:19.216: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = PACKET RECEIVED Current State = LEADER
2024-12-24 02:00:19.216: watchdog pid 1582758: DEBUG:  received packet,
watchdog node:[10.35.8.21:9999 Linux azlpgNkax-0] command id:[82]
type:[NODE INFO] state:[LEADER]
2024-12-24 02:00:19.216: watchdog pid 1582758: DEBUG:  packet I with
command ID 82 is reply to the command M
2024-12-24 02:00:19.216: watchdog pid 1582758: DEBUG:  Watchdog node "
10.35.8.21:9999 Linux azlpgNkax-0" has replied for command id 82
2024-12-24 02:00:19.216: watchdog pid 1582758: DEBUG:  command I with
command id 82 is finished with COMMAND_FINISHED_ALL_REPLIED
2024-12-24 02:00:19.216: watchdog pid 1582758: DEBUG:  STATE MACHINE
INVOKED WITH EVENT = COMMAND FINISHED Current State = LEADER
2024-12-24 02:00:19.216: watchdog pid 1582758: DEBUG:  I am the cluster
leader node command finished with status:[ALL NODES REPLIED]





On Tue, Dec 24, 2024 at 6:45 AM Tatsuo Ishii <ishii at postgresql.org> wrote:

> Hello Mukesh,
>
> > Hello Tatsuo,
> >
> > I have few questions, If you again look back the pgpool.log
> >
> > at 2024-12-23 04:17:00.310: [unknown] pid 1227285: DETAIL:  SSLRequest
> from
> > client, there is connection to DB and
> > at 2024-12-23 04:17:00.392: [unknown] pid 1227285: DETAIL:  destination
> = 0
> > for query= "CREATE DATABASE "tpcc" OWNER "tpcc""
> > query got fired to create database tpcc
> >
> > again there is new connection at 2024-12-23 04:17:00.653: [unknown] pid
> > 1227285: DETAIL:  SSLRequest from client
> > then this connection got failed with error message
> >
> > Questions:
> > 1. what is the destination = 0 means
>
> The query (CREATE DATABASE) will be sent to primary PostgreSQL.
>
> > 2. How can we see which backend node got selected while the connection
> got
> > established?
>
> Enabling log_per_node_statement to on will log the info you need.
>
> > 3. According to your recommendation i have set synchronous commit, but
> this
> > parameter *synchronous_commit = on, *but still failing (intermittently).
> So
> > is the replication delay might be purely on Azure networking?
>
> "on" is not sufficient. You need to use "remote_apply".
>
> Best reagards,
> --
> Tatsuo Ishii
> SRA OSS K.K.
> English: http://www.sraoss.co.jp/index_en/
> Japanese:http://www.sraoss.co.jp
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.pgpool.net/pipermail/pgpool-general/attachments/20241224/59a222c4/attachment-0001.htm>

More information about the pgpool-general mailing list