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

[Sbob]

I think we figured it out, the client had more than one app pointed to 
it and the second app (that we were unaware of) flooded pgpool and 
filled up the available pools within about 5min of restarting pgpool



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