[pgpool-general: 8988] Re: no connection to pgpool after about 5min

Thu Dec 14 14:47:27 JST 2023

Hi,

Could you share your pgpool version?

On Wed, 13 Dec 2023 17:29:00 +0900
Bo Peng <pengbo at sraoss.co.jp> wrote:

> Hi,
> 
> > we are having an odd issue, we start up pgpool, we can connect to it and 
> > run queries against the backend databases but after about 5min if we 
> > disconnect then any attempts to re-connect just hang.
> 
> Is the *disconnect* caused by your application?
> Or the connection was terminated abnormally?
> 
> To check the process status could you share the result of "pcp_proc_info" command?
> 
> Could you check if you can run pgbench for more than 5 minutes using "pgbench -T 600 ..."?
> 
> On Sat, 9 Dec 2023 20:28:08 -0700
> Sbob <sbob at quadratum-braccas.com> wrote:
> 
> > All;
> > 
> > we are having an odd issue, we start up pgpool, we can connect to it and 
> > run queries against the backend databases but after about 5min if we 
> > disconnect then any attempts to re-connect just hang.
> > Can someone help us debug this?
> > 
> > Here is the pgpool.conf file settings we have (the rest of the file is 
> > default values):
> > 
> > 
> > 
> > listen_addresses = '*'
> > 
> > unix_socket_directories = '/run/pgpool-II'
> > backend_hostname0 = '10.3.1.111' # Host name or IP address to connect to 
> > for backend 0
> > backend_port0 = 5432 # Port number for backend 0
> > backend_weight0 = 1 # Weight for backend 0 (only in load balancing mode)
> > backend_data_directory0 = '/var/lib/pgsql/data' # Data directory for 
> > backend 0
> > backend_flag0 = 'ALLOW_TO_FAILOVER' # Controls various backend behavior
> >                                    # ALLOW_TO_FAILOVER, 
> > DISALLOW_TO_FAILOVER
> >                                    # or ALWAYS_PRIMARY
> > 
> > 
> > backend_hostname1 = '10.3.1.112'
> > backend_port1 = 5432
> > backend_weight1 = 1
> > backend_data_directory1 = '/var/lib/pgsql/data'
> > backend_flag1 = 'ALLOW_TO_FAILOVER'
> > backend_application_name1 = 'node2'
> > enable_pool_hba = off
> > 
> > 
> > pool_passwd = ''
> > 
> > allow_clear_text_frontend_auth = on
> > 
> > 
> > 
> > Below is the log after starting in debug mode, when we cannot connect to 
> > pgpool:
> > 
> > 
> > Thanks in advance
> > 
> > 
> > 
> > 
> > 023-12-09 22:07:23.957: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:23.957: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:23.957: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:23.957: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:23.957: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:23.957: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:23.959: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:23.959: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:23.959: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:23.960: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:23.960: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:23.962: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:23.962: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:23.962: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:23.962: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:23.962: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:23.964: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:23.964: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:23.964: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 0 for query= "UPDATE "users" SET 
> > "last_activity_at" = $1 WHERE "users"."id" = $2"
> > 2023-12-09 22:07:23.964: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:23.964: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:23.964: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:23.964: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: TSTATE:I
> > 2023-12-09 22:07:23.965: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:23.965: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:23.968: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:23.968: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:23.968: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:23.969: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:23.969: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:23.998: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:23.998: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:23.998: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:23.999: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:23.999: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.267: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:24.267: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:24.267: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.267: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:24.267: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:24.267: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:24.267: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.267: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:24.269: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.269: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.269: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:24.270: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.270: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.272: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.272: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.272: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:24.273: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.273: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.275: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.275: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.275: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:24.275: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.276: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 
> > "municipalities"."subdomain" FROM "municipalities""
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 
> > "municipalities"."subdomain" FROM "municipalities""
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation "municipalities"
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation "municipalities"
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: tablename:""municipalities""
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation ""municipalities""
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.277: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:24.279: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.279: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.281: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.281: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.281: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:24.281: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.281: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT "municipalities".* 
> > FROM "municipalities" INNER JOIN "user_muni
> > cipalities" ON "municipalities"."id" = 
> > "user_municipalities"."municipality_id" WHERE 
> > "user_municipalities"."user_id" = $1 ORDER BY user_municipalities.main 
> > DESC NULLS LAST, user_mun
> > icipalities.created_at LIMIT $2"
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT "municipalities".* 
> > FROM "municipalities" INNER JOIN "user_muni
> > cipalities" ON "municipalities"."id" = 
> > "user_municipalities"."municipality_id" WHERE 
> > "user_municipalities"."user_id" = $1 ORDER BY user_municipalities.main 
> > DESC NULLS LAST, user_mun
> > icipalities.created_at LIMIT $2"
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation "municipalities"
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation 
> > "user_municipalities"
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation "municipalities"
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation 
> > "user_municipalities"
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: tablename:""municipalities""
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation ""municipalities""
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: 
> > tablename:""user_municipalities""
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation 
> > ""user_municipalities""
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.283: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:24.284: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.284: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.288: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.288: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.288: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:24.289: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.289: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.290: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.290: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "BEGIN"
> > 2023-12-09 22:07:24.290: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.290: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:24.291: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.291: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:24.293: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:24.293: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.293: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 0 for query= "UPDATE "m2m_servers" SET 
> > "updated_at" = $1, "last_heartbeat_at" = $2
> > WHERE "m2m_servers"."id" = $3"
> > 2023-12-09 22:07:24.293: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.293: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.293: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: T
> > 2023-12-09 22:07:24.293: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: TSTATE:T
> > 2023-12-09 22:07:24.294: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.294: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.294: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  not SET TRANSACTION READ ONLY
> > 2023-12-09 22:07:24.295: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.295: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "COMMIT"
> > 2023-12-09 22:07:24.295: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.295: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:24.296: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.296: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:24.299: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.299: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "BEGIN"
> > 2023-12-09 22:07:24.299: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.299: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:24.300: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.300: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:24.302: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:24.302: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.302: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 0 for query= "INSERT INTO "m2m_heartbeats" 
> > ("m2m_server_id", "created_at", "updated
> > _at") VALUES ($1, $2, $3) RETURNING "id""
> > 2023-12-09 22:07:24.302: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:24.302: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:24.302: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: T
> > 2023-12-09 22:07:24.302: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: TSTATE:T
> > 2023-12-09 22:07:24.303: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:24.303: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:24.303: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  not SET TRANSACTION READ ONLY
> > 2023-12-09 22:07:24.304: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:24.304: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "COMMIT"
> > 2023-12-09 22:07:24.304: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.304: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:24.305: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:24.305: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:25.442: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:25.446: health_check1 pid 1798: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:25.446: health_check1 pid 1798: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:25.446: health_check1 pid 1798: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:25.446: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:25.446: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:25.540: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:25.545: health_check0 pid 1797: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:25.545: health_check0 pid 1797: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:25.545: health_check0 pid 1797: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:25.545: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:25.545: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:25.724: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:25.724: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:25.724: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.724: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:25.724: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  do_query: extended:0 query:"SELECT 
> > current_setting('transaction_isolation')"
> > 2023-12-09 22:07:25.724: puma: cluster worker 1: 18862 [current] pid 
> > 1765: CONTEXT:  while getting transaction isolation
> > 2023-12-09 22:07:25.725: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:25.725: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:25.725: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.725: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:25.727: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.727: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.727: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:25.728: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.728: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.729: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.729: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.729: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:25.730: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.730: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.732: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.732: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.732: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:25.733: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.733: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 
> > "municipalities"."subdomain" FROM "municipalities""
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 
> > "municipalities"."subdomain" FROM "municipalities""
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation "municipalities"
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation "municipalities"
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: tablename:""municipalities""
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation ""municipalities""
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.735: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:25.736: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.736: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.738: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.738: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.738: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:25.739: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.739: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT "municipalities".* 
> > FROM "municipalities" INNER JOIN "user_muni
> > cipalities" ON "municipalities"."id" = 
> > "user_municipalities"."municipality_id" WHERE 
> > "user_municipalities"."user_id" = $1 ORDER BY user_municipalities.main 
> > DESC NULLS LAST, user_mun
> > icipalities.created_at LIMIT $2"
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT "municipalities".* 
> > FROM "municipalities" INNER JOIN "user_muni
> > cipalities" ON "municipalities"."id" = 
> > "user_municipalities"."municipality_id" WHERE 
> > "user_municipalities"."user_id" = $1 ORDER BY user_municipalities.main 
> > DESC NULLS LAST, user_mun
> > icipalities.created_at LIMIT $2"
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation "municipalities"
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation 
> > "user_municipalities"
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation "municipalities"
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation 
> > "user_municipalities"
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: tablename:""municipalities""
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation ""municipalities""
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: 
> > tablename:""user_municipalities""
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation 
> > ""user_municipalities""
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.741: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:25.742: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.742: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.745: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.745: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.745: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:25.746: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.746: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.748: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.748: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "BEGIN"
> > 2023-12-09 22:07:25.748: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.748: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:25.749: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.749: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:25.750: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:25.750: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.750: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 0 for query= "UPDATE "m2m_servers" SET 
> > "updated_at" = $1, "last_heartbeat_at" = $2
> > WHERE "m2m_servers"."id" = $3"
> > 2023-12-09 22:07:25.750: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.750: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.751: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: T
> > 2023-12-09 22:07:25.751: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: TSTATE:T
> > 2023-12-09 22:07:25.751: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.752: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.752: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  not SET TRANSACTION READ ONLY
> > 2023-12-09 22:07:25.752: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.752: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "COMMIT"
> > 2023-12-09 22:07:25.752: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.753: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:25.753: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.753: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:25.756: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.756: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "BEGIN"
> > 2023-12-09 22:07:25.756: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.756: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:25.757: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.757: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:25.759: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:25.759: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.759: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 0 for query= "INSERT INTO "m2m_heartbeats" 
> > ("m2m_server_id", "created_at", "updated
> > _at") VALUES ($1, $2, $3) RETURNING "id""
> > 2023-12-09 22:07:25.759: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:25.759: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:25.759: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: T
> > 2023-12-09 22:07:25.759: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: TSTATE:T
> > 2023-12-09 22:07:25.760: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:25.760: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:25.760: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  not SET TRANSACTION READ ONLY
> > 2023-12-09 22:07:25.761: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:25.761: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "COMMIT"
> > 2023-12-09 22:07:25.761: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.761: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:25.762: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:25.762: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:27.095: sr_check_worker pid 1796: DEBUG: 
> >   pool_acquire_follow_primary_lock: lock was not held by anyone
> > 2023-12-09 22:07:27.095: sr_check_worker pid 1796: DEBUG: 
> >   pool_acquire_follow_primary_lock: succeeded in acquiring lock
> > 2023-12-09 22:07:27.099: sr_check_worker pid 1796: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:27.099: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:27.099: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:27.103: sr_check_worker pid 1796: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:27.103: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:27.103: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:27.103: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_current_wal_lsn()"
> > 2023-12-09 22:07:27.103: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:27.105: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_last_wal_replay_lsn()"
> > 2023-12-09 22:07:27.105: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:27.106: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT application_name, state, 
> > sync_state,(EXTRACT(EPOCH FROM replay_lag)*1000000)::BIGINT FR
> > OM pg_stat_replication"
> > 2023-12-09 22:07:27.106: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:27.109: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_is_in_recovery()"
> > 2023-12-09 22:07:27.110: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_is_in_recovery()"
> > 2023-12-09 22:07:27.111: sr_check_worker pid 1796: DEBUG: 
> >   verify_backend_node_status: multiple standbys: 1
> > 2023-12-09 22:07:27.111: sr_check_worker pid 1796: DEBUG: 
> >   verify_backend_node_status: detach_false_primary is off and no 
> > additional checking is performed
> > 2023-12-09 22:07:27.111: sr_check_worker pid 1796: DEBUG:  node 
> > status[0]: 1
> > 2023-12-09 22:07:27.111: sr_check_worker pid 1796: DEBUG:  node 
> > status[1]: 2
> > 2023-12-09 22:07:27.111: sr_check_worker pid 1796: DEBUG: 
> >   pool_release_follow_primary_lock called
> > 2023-12-09 22:07:30.446: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:30.450: health_check1 pid 1798: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:30.450: health_check1 pid 1798: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:30.450: health_check1 pid 1798: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:30.450: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:30.450: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:30.545: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:30.550: health_check0 pid 1797: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:30.550: health_check0 pid 1797: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:30.550: health_check0 pid 1797: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:30.550: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:30.550: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:31.083: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:31.083: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  result = 0
> > 2023-12-09 22:07:31.084: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  decide where to send the query
> > 2023-12-09 22:07:31.084: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:31.084: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  do_query: extended:0 query:"SELECT 
> > current_setting('transaction_isolation')"
> > 2023-12-09 22:07:31.084: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > CONTEXT:  while getting transaction isolation
> > 2023-12-09 22:07:31.085: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation:2
> > 2023-12-09 22:07:31.085: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:31.085: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  waiting for query response
> > 2023-12-09 22:07:31.085: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  result = 0
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  decide where to send the query
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  destination = 2 for query= "SELECT "m2m_queues".* FROM 
> > "m2m_queues""
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation:2
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  destination = 2 for query= "SELECT "m2m_queues".* FROM 
> > "m2m_queues""
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  system catalog walker, checking relation "m2m_queues"
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  hit local relation cache
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS n 
> > WHERE c.oid = pg_catalog.to_regclass('"
> > %s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  temporary table walker. checking relation "m2m_queues"
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  hit local relation cache
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND c
> > .relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  make table name from rangevar: tablename:""m2m_queues""
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  unlogged table walker. checking relation ""m2m_queues""
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  hit local relation cache
> > 2023-12-09 22:07:31.087: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.oid 
> > = pg_catalog.to_regclass('%s') AND
> > c.relpersistence = 'u'
> > 2023-12-09 22:07:31.088: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:31.088: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:31.088: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:31.089: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DEBUG:  processing command complete
> > 2023-12-09 22:07:31.089: sidekiq 6.4.1 current [28 of 30 busy] pid 1777: 
> > DETAIL:  set transaction state to T
> > 2023-12-09 22:07:32.111: sr_check_worker pid 1796: DEBUG: 
> >   pool_acquire_follow_primary_lock: lock was not held by anyone
> > 2023-12-09 22:07:32.111: sr_check_worker pid 1796: DEBUG: 
> >   pool_acquire_follow_primary_lock: succeeded in acquiring lock
> > 2023-12-09 22:07:32.116: sr_check_worker pid 1796: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:32.116: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:32.116: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:32.120: sr_check_worker pid 1796: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:32.120: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:32.120: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:32.120: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_current_wal_lsn()"
> > 2023-12-09 22:07:32.120: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:32.121: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_last_wal_replay_lsn()"
> > 2023-12-09 22:07:32.121: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:32.122: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT application_name, state, 
> > sync_state,(EXTRACT(EPOCH FROM replay_lag)*1000000)::BIGINT FR
> > OM pg_stat_replication"
> > 2023-12-09 22:07:32.122: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:32.127: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_is_in_recovery()"
> > 2023-12-09 22:07:32.128: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_is_in_recovery()"
> > 2023-12-09 22:07:32.129: sr_check_worker pid 1796: DEBUG: 
> >   verify_backend_node_status: multiple standbys: 1
> > 2023-12-09 22:07:32.129: sr_check_worker pid 1796: DEBUG: 
> >   verify_backend_node_status: detach_false_primary is off and no 
> > additional checking is performed
> > 2023-12-09 22:07:32.129: sr_check_worker pid 1796: DEBUG:  node 
> > status[0]: 1
> > 2023-12-09 22:07:32.129: sr_check_worker pid 1796: DEBUG:  node 
> > status[1]: 2
> > 2023-12-09 22:07:32.129: sr_check_worker pid 1796: DEBUG: 
> >   pool_release_follow_primary_lock called
> > 2023-12-09 22:07:33.134: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:33.134: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:33.134: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.134: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:33.134: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  do_query: extended:0 query:"SELECT 
> > current_setting('transaction_isolation')"
> > 2023-12-09 22:07:33.134: puma: cluster worker 1: 18862 [current] pid 
> > 1765: CONTEXT:  while getting transaction isolation
> > 2023-12-09 22:07:33.135: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:33.135: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:33.135: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:33.135: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:33.137: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.137: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.137: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:33.138: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.138: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.140: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.140: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.140: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:33.141: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.141: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.143: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.143: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.143: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:33.144: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.144: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.146: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.146: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.146: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:33.147: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.147: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.148: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT "municipalities".* 
> > FROM "municipalities" INNER JOIN "user_muni
> > cipalities" ON "municipalities"."id" = 
> > "user_municipalities"."municipality_id" WHERE 
> > "user_municipalities"."user_id" = $1 ORDER BY user_municipalities.main 
> > DESC NULLS LAST, user_mun
> > icipalities.created_at LIMIT $2"
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT "municipalities".* 
> > FROM "municipalities" INNER JOIN "user_muni
> > cipalities" ON "municipalities"."id" = 
> > "user_municipalities"."municipality_id" WHERE 
> > "user_municipalities"."user_id" = $1 ORDER BY user_municipalities.main 
> > DESC NULLS LAST, user_mun
> > icipalities.created_at LIMIT $2"
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation "municipalities"
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation 
> > "user_municipalities"
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation "municipalities"
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation 
> > "user_municipalities"
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: tablename:""municipalities""
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation ""municipalities""
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: 
> > tablename:""user_municipalities""
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation 
> > ""user_municipalities""
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.149: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:33.150: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.150: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.154: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.154: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "BEGIN"
> > 2023-12-09 22:07:33.154: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:33.154: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:33.155: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:33.155: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:33.157: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:33.157: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:33.157: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:33.157: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.157: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1 AS one FROM 
> > "device_cloud_files" WHERE "device_cloud_files".
> > "device_cloud_id" = $1 LIMIT $2"
> > 2023-12-09 22:07:33.157: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  do_query: extended:1 query:"SELECT 
> > current_setting('transaction_isolation')"
> > 2023-12-09 22:07:33.157: puma: cluster worker 1: 18862 [current] pid 
> > 1765: CONTEXT:  while getting transaction isolation
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:T 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT 1 AS one FROM 
> > "device_cloud_files" WHERE "device_cloud_files".
> > "device_cloud_id" = $1 LIMIT $2"
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation "device_cloud_files"
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation 
> > "device_cloud_files"
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: 
> > tablename:""device_cloud_files""
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation 
> > ""device_cloud_files""
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.158: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: T
> > 2023-12-09 22:07:33.162: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.162: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.164: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:33.164: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.164: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 0 for query= "INSERT INTO 
> > "device_cloud_files" ("device_cloud_id", "mac_address", "
> > file_type", "file_name", "raw_data", "queued_at", "created_at", 
> > "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8) RETURNING "id""
> > 2023-12-09 22:07:33.164: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.164: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.164: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: T
> > 2023-12-09 22:07:33.164: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: TSTATE:T
> > 2023-12-09 22:07:33.167: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.167: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.167: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  not SET TRANSACTION READ ONLY
> > 2023-12-09 22:07:33.168: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.168: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 3 for query= "COMMIT"
> > 2023-12-09 22:07:33.168: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:33.168: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:1 to complete the query
> > 2023-12-09 22:07:33.169: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  waiting for query response
> > 2023-12-09 22:07:33.169: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:33.173: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:33.173: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:33.173: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:33.173: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.173: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT "devices".* FROM 
> > "devices" WHERE "devices"."decommissioned" =
> > $1 AND (lower(mac_address) = '00:13:95:0e:90:8d' OR 
> > lower(video_card_mac_address) = '00:13:95:0e:90:8d') ORDER BY 
> > "devices"."id" ASC LIMIT $2"
> > 2023-12-09 22:07:33.173: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  do_query: extended:1 query:"SELECT 
> > current_setting('transaction_isolation')"
> > 2023-12-09 22:07:33.173: puma: cluster worker 1: 18862 [current] pid 
> > 1765: CONTEXT:  while getting transaction isolation
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT "devices".* FROM 
> > "devices" WHERE "devices"."decommissioned" =
> > $1 AND (lower(mac_address) = '00:13:95:0e:90:8d' OR 
> > lower(video_card_mac_address) = '00:13:95:0e:90:8d') ORDER BY 
> > "devices"."id" ASC LIMIT $2"
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation "devices"
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation "devices"
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: tablename:""devices""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation ""devices""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""lower""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""lower""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""lower""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""lower""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""lower""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""lower""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""lower""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""lower""
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.174: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""lower""
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""lower""
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""lower""
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""lower""
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.176: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  result = 0
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT COUNT(*) FROM 
> > "sentry_alert_types" WHERE "sentry_alert_types".
> > "name" = $1"
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation
> > :2
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  destination = 2 for query= "SELECT COUNT(*) FROM 
> > "sentry_alert_types" WHERE "sentry_alert_types".
> > "name" = $1"
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  system catalog walker, checking relation "sentry_alert_types"
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regclass(
> > '"%s"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  temporary table walker. checking relation 
> > "sentry_alert_types"
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = '%s' AND
> > c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make table name from rangevar: 
> > tablename:""sentry_alert_types""
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  unlogged table walker. checking relation 
> > ""sentry_alert_types""
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('%s') AN
> > D c.relpersistence = 'u'
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""count""
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""count""
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""count""
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""count""
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.178: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.179: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  processing command complete
> > 2023-12-09 22:07:33.179: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.179: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  make function name from funccall: funcname:""count""
> > 2023-12-09 22:07:33.179: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  function call walker, function name: ""count""
> > 2023-12-09 22:07:33.179: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  hit local relation cache
> > 2023-12-09 22:07:33.179: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  query:%s
> > 2023-12-09 22:07:33.179: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DEBUG:  checking the function volatile property
> > 2023-12-09 22:07:33.179: puma: cluster worker 1: 18862 [current] pid 
> > 1765: DETAIL:  search result = 0 (v)
> > 2023-12-09 22:07:33.237: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:33.237: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  result = 0
> > 2023-12-09 22:07:33.237: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.237: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:33.237: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  do_query: extended:0 query:"SELECT 
> > current_setting('transaction_isolation')"
> > 2023-12-09 22:07:33.237: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while getting transaction isolation
> > 2023-12-09 22:07:33.238: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation:2
> > 2023-12-09 22:07:33.238: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:33.238: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  waiting for query response
> > 2023-12-09 22:07:33.238: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:33.245: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.245: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 3 for query= "BEGIN"
> > 2023-12-09 22:07:33.245: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  waiting for query response
> > 2023-12-09 22:07:33.245: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:33.252: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.252: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.252: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: T
> > 2023-12-09 22:07:33.253: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  processing command complete
> > 2023-12-09 22:07:33.253: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.256: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:33.256: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.256: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 0 for query= "INSERT INTO "device_heartbeats" 
> > ("device_id", "created_at", "updated_at
> > ") VALUES ($1, $2, $3) RETURNING "id""
> > 2023-12-09 22:07:33.256: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:33.256: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:33.256: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: T
> > 2023-12-09 22:07:33.256: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Execute: TSTATE:T
> > 2023-12-09 22:07:33.257: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  processing command complete
> > 2023-12-09 22:07:33.257: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  set transaction state to T
> > 2023-12-09 22:07:33.257: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  not SET TRANSACTION READ ONLY
> > 2023-12-09 22:07:33.259: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  decide where to send the query
> > 2023-12-09 22:07:33.259: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 3 for query= "COMMIT"
> > 2023-12-09 22:07:33.259: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  waiting for query response
> > 2023-12-09 22:07:33.259: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:35.451: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:35.455: health_check1 pid 1798: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:35.455: health_check1 pid 1798: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:35.455: health_check1 pid 1798: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:35.455: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:35.455: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:35.550: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:35.554: health_check0 pid 1797: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:35.554: health_check0 pid 1797: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:35.554: health_check0 pid 1797: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:35.554: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:35.554: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:36.316: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:36.316: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  result = 0
> > 2023-12-09 22:07:36.316: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  decide where to send the query
> > 2023-12-09 22:07:36.316: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:36.316: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  do_query: extended:0 query:"SELECT 
> > current_setting('transaction_isolation')"
> > 2023-12-09 22:07:36.316: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while getting transaction isolation
> > 2023-12-09 22:07:36.317: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation:2
> > 2023-12-09 22:07:36.317: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 2 for query= "SELECT 1"
> > 2023-12-09 22:07:36.317: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  waiting for query response
> > 2023-12-09 22:07:36.317: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  waiting for backend:0 to complete the query
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Parse: statement name <>
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  checking if query has INSERT INTO, FOR SHARE or FOR UPDATE
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  result = 0
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  decide where to send the query
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 2 for query= "SELECT "m2m_queues".* FROM 
> > "m2m_queues""
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  checking load balance preconditions. TSTATE:I 
> > writing_transaction:0 failed_transaction:0 isolation:2
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  destination = 2 for query= "SELECT "m2m_queues".* FROM 
> > "m2m_queues""
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  system catalog walker, checking relation "m2m_queues"
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  username: "sentrylink" database_name: "sentrylink_qa"
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query: "SELECT count(*) FROM pg_class AS c, pg_namespace AS n 
> > WHERE c.oid = pg_catalog.to_regclass(
> > '"m2m_queues"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'"
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  `sentrylinkSELECT count(*) FROM pg_class AS c, pg_namespace AS 
> > n WHERE c.oid = pg_catalog.to_regcla
> > ss('"m2m_queues"') AND c.relnamespace = n.oid AND n.nspname = 
> > 'pg_catalog'sentrylink_qa' -> `3ac0e0145a280900cecc964d57fd9291'
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  fetching from cache storage
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  search key "3ac0e0145a280900cecc964d57fd9291"
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  fetching from cache storage
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query="SELECT count(*) FROM pg_class AS c, pg_namespace AS n 
> > WHERE c.oid = pg_catalog.to_regclass('
> > "m2m_queues"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'" 
> > len:13
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  hit query cache
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query:SELECT count(*) FROM pg_class AS c, pg_namespace AS n 
> > WHERE c.oid = pg_catalog.to_regclass('"
> > m2m_queues"') AND c.relnamespace = n.oid AND n.nspname = 'pg_catalog'
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  temporary table walker. checking relation "m2m_queues"
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  username: "sentrylink" database_name: "sentrylink_qa"
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query: "SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = 'm2m_que
> > ues' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'"
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  `sentrylinkSELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = 'm2m_
> > queues' AND c.relnamespace = n.oid AND n.nspname ~ 
> > '^pg_temp_'sentrylink_qa' -> `e759a95623561ab53254a2e86a933788'
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  fetching from cache storage
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  search key "e759a95623561ab53254a2e86a933788"
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  fetching from cache storage
> > 2023-12-09 22:07:36.319: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query="SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = 'm2m_queu
> > es' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'" len:13
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  hit query cache
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c, 
> > pg_namespace AS n WHERE c.relname = 'm2m_queue
> > s' AND c.relnamespace = n.oid AND n.nspname ~ '^pg_temp_'
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  make table name from rangevar: tablename:""m2m_queues""
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  unlogged table walker. checking relation ""m2m_queues""
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  username: "sentrylink" database_name: "sentrylink_qa"
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query: "SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('"m2m_qu
> > eues"') AND c.relpersistence = 'u'"
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  memcache encode key
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  `sentrylinkSELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('"m2m
> > _queues"') AND c.relpersistence = 'u'sentrylink_qa' -> 
> > `e17390464963016c0702a2123891eee5'
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  fetching from cache storage
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  search key "e17390464963016c0702a2123891eee5"
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  fetching from cache storage
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query="SELECT count(*) FROM pg_catalog.pg_class AS c WHERE 
> > c.oid = pg_catalog.to_regclass('"m2m_que
> > ues"') AND c.relpersistence = 'u'" len:13
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  hit query cache
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  query:SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.oid 
> > = pg_catalog.to_regclass('"m2m_queu
> > es"') AND c.relpersistence = 'u'
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > CONTEXT:  while searching system catalog, When relcache is missed
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Bind: waiting for main node completing the query
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Describe: waiting for main node completing the query
> > 2023-12-09 22:07:36.320: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  Execute: pool_is_writing_transaction: 0 TSTATE: I
> > 2023-12-09 22:07:36.322: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DEBUG:  processing command complete
> > 2023-12-09 22:07:36.322: sidekiq 6.4.1 current [30 of 30 busy] pid 1774: 
> > DETAIL:  set transaction state to T
> > 2023-12-09 22:07:37.129: sr_check_worker pid 1796: DEBUG: 
> >   pool_acquire_follow_primary_lock: lock was not held by anyone
> > 2023-12-09 22:07:37.130: sr_check_worker pid 1796: DEBUG: 
> >   pool_acquire_follow_primary_lock: succeeded in acquiring lock
> > 2023-12-09 22:07:37.136: sr_check_worker pid 1796: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:37.136: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:37.136: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:37.140: sr_check_worker pid 1796: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:37.140: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:37.140: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:37.140: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_current_wal_lsn()"
> > 2023-12-09 22:07:37.140: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:37.144: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_last_wal_replay_lsn()"
> > 2023-12-09 22:07:37.144: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:37.145: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT application_name, state, 
> > sync_state,(EXTRACT(EPOCH FROM replay_lag)*1000000)::BIGINT FR
> > OM pg_stat_replication"
> > 2023-12-09 22:07:37.145: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:37.150: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_is_in_recovery()"
> > 2023-12-09 22:07:37.151: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_is_in_recovery()"
> > 2023-12-09 22:07:37.152: sr_check_worker pid 1796: DEBUG: 
> >   verify_backend_node_status: multiple standbys: 1
> > 2023-12-09 22:07:37.152: sr_check_worker pid 1796: DEBUG: 
> >   verify_backend_node_status: detach_false_primary is off and no 
> > additional checking is performed
> > 2023-12-09 22:07:37.152: sr_check_worker pid 1796: DEBUG:  node 
> > status[0]: 1
> > 2023-12-09 22:07:37.152: sr_check_worker pid 1796: DEBUG:  node 
> > status[1]: 2
> > 2023-12-09 22:07:37.152: sr_check_worker pid 1796: DEBUG: 
> >   pool_release_follow_primary_lock called
> > 2023-12-09 22:07:40.455: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:40.459: health_check1 pid 1798: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:40.459: health_check1 pid 1798: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:40.459: health_check1 pid 1798: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:40.459: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:40.459: health_check1 pid 1798: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:40.554: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:40.559: health_check0 pid 1797: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:40.559: health_check0 pid 1797: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:40.559: health_check0 pid 1797: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:40.559: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:40.559: health_check0 pid 1797: DEBUG:  health check: 
> > clearing alarm
> > 2023-12-09 22:07:42.152: sr_check_worker pid 1796: DEBUG: 
> >   pool_acquire_follow_primary_lock: lock was not held by anyone
> > 2023-12-09 22:07:42.152: sr_check_worker pid 1796: DEBUG: 
> >   pool_acquire_follow_primary_lock: succeeded in acquiring lock
> > 2023-12-09 22:07:42.156: sr_check_worker pid 1796: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:42.156: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:42.156: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:42.160: sr_check_worker pid 1796: DEBUG:  authenticate 
> > kind = 0
> > 2023-12-09 22:07:42.160: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: key data received
> > 2023-12-09 22:07:42.160: sr_check_worker pid 1796: DEBUG:  authenticate 
> > backend: transaction state: I
> > 2023-12-09 22:07:42.160: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_current_wal_lsn()"
> > 2023-12-09 22:07:42.160: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:42.161: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_last_wal_replay_lsn()"
> > 2023-12-09 22:07:42.161: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:42.162: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT application_name, state, 
> > sync_state,(EXTRACT(EPOCH FROM replay_lag)*1000000)::BIGINT FR
> > OM pg_stat_replication"
> > 2023-12-09 22:07:42.162: sr_check_worker pid 1796: CONTEXT:  while 
> > checking replication time lag
> > 2023-12-09 22:07:42.166: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_is_in_recovery()"
> > 2023-12-09 22:07:42.167: sr_check_worker pid 1796: DEBUG:  do_query: 
> > extended:0 query:"SELECT pg_is_in_recovery()"
> > 2023-12-09 22:07:42.168: sr_check_worker pid 1796: DEBUG: 
> >   verify_backend_node_status: multiple standbys: 1
> > 2023-12-09 22:07:42.168: sr_check_worker pid 1796: DEBUG: 
> >   verify_backend_node_status: detach_false_primary is off and no 
> > additional checking is performed
> > 2023-12-09 22:07:42.168: sr_check_worker pid 1796: DEBUG:  node 
> > status[0]: 1
> > 2023-12-09 22:07:42.168: sr_check_worker pid 1796: DEBUG:  node 
> > status[1]: 2
> > 2023-12-09 22:07:42.168: sr_check_worker pid 1796: DEBUG: 
> >   pool_release_follow_primary_lock called
> > 
> > 
> > 
> 
> 
> -- 
> Bo Peng <pengbo at sraoss.co.jp>
> SRA OSS LLC
> TEL: 03-5979-2701 FAX: 03-5979-2702
> URL: https://www.sraoss.co.jp/
> _______________________________________________
> pgpool-general mailing list
> pgpool-general at pgpool.net
> http://www.pgpool.net/mailman/listinfo/pgpool-general

-- 
Bo Peng <pengbo at sraoss.co.jp>
SRA OSS LLC
TEL: 03-5979-2701 FAX: 03-5979-2702
URL: https://www.sraoss.co.jp/