[pgpool-general: 8985] Re: no connection to pgpool after about 5min
Bo Peng
pengbo at sraoss.co.jp
Wed Dec 13 17:29:00 JST 2023
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/
More information about the pgpool-general
mailing list