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

Sun Dec 10 12:28:08 JST 2023

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

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.pgpool.net/pipermail/pgpool-general/attachments/20231209/356e4513/attachment.htm>