Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug]: Timescaledb fails on CREATE INDEX #4058

Closed
npakudin opened this issue Feb 4, 2022 · 3 comments
Closed

[Bug]: Timescaledb fails on CREATE INDEX #4058

npakudin opened this issue Feb 4, 2022 · 3 comments

Comments

@npakudin
Copy link

npakudin commented Feb 4, 2022

What type of bug is this?

Crash

What subsystems and features are affected?

Query executor

What happened?

Reproduced in k8s
https://github.com/timescale/timescaledb-kubernetes/blob/v0.8.2/charts/timescaledb-single/values.yaml

git diff

diff --git a/charts/timescaledb-single/values.yaml b/charts/timescaledb-single/values.yaml
index ee030ca..91582e8 100644
--- a/charts/timescaledb-single/values.yaml
+++ b/charts/timescaledb-single/values.yaml
@@ -1,7 +1,7 @@
 # This file and its contents are licensed under the Apache License 2.0.
 # Please see the included NOTICE for copyright information and LICENSE for a copy of the license.
 
-replicaCount: 3
+replicaCount: 1
 
 # To prevent very long names, we override the name, otherwise it would default to
 # timescaledb-single (the name of the chart)
@@ -170,7 +170,7 @@ patroni:
           autovacuum_vacuum_cost_limit: 500
           autovacuum_vacuum_scale_factor: 0.05
           log_autovacuum_min_duration: 1min
-          hot_standby: 'on'
+          hot_standby: 'off'
           log_checkpoints: 'on'
           log_connections: 'on'
           log_disconnections: 'on'
@@ -178,7 +178,7 @@ patroni:
           log_lock_waits: 'on'
           log_min_duration_statement: '1s'
           log_statement: ddl
-          max_connections: 100
+          max_connections: 30
           max_prepared_transactions: 150
           shared_preload_libraries: timescaledb,pg_stat_statements
           ssl: 'on'
@@ -186,12 +186,14 @@ patroni:
           ssl_key_file: '/etc/certificate/tls.key'
           tcp_keepalives_idle: 900
           tcp_keepalives_interval: 100
-          temp_file_limit: 1GB
+          temp_file_limit: 20GB
+          max_files_per_process: 10000
           timescaledb.passfile: '../.pgpass'
           unix_socket_directories: "/var/run/postgresql"
           unix_socket_permissions: '0750'
           wal_level: hot_standby
           wal_log_hints: 'on'
+          work_mem: 16MB
         use_pg_rewind: true
         use_slots: true
       retry_timeout: 10
@@ -211,8 +213,6 @@ patroni:
       no_master: true
     basebackup:
     - waldir: "/var/lib/postgresql/wal/pg_wal"
-    recovery_conf:
-      restore_command: /etc/timescaledb/scripts/pgbackrest_archive_get.sh %f "%p"
     callbacks:
       on_role_change: /etc/timescaledb/scripts/patroni_callback.sh
       on_start: /etc/timescaledb/scripts/patroni_callback.sh
@@ -228,7 +228,7 @@ patroni:
     pg_hba:
     - local     all             postgres                              peer
     - local     all             all                                   md5
-    - hostnossl all,replication all                all                reject
+    - hostnossl all,replication all                all                md5
     - hostssl   all             all                127.0.0.1/32       md5
     - hostssl   all             all                ::1/128            md5
     - hostssl   replication     standby            all                md5
@@ -303,7 +303,7 @@ persistentVolumes:
   # https://www.postgresql.org/docs/current/creating-cluster.html#CREATING-CLUSTER-MOUNT-POINTS
   data:
     enabled: true
-    size: 2Gi
+    size: 150Gi
     ## database data Persistent Volume Storage Class
     ## If defined, storageClassName: <storageClass>
     ## If set to "-", storageClassName: "", which disables dynamic provisioning
@@ -321,7 +321,7 @@ persistentVolumes:
   # volume for the WAL files should just work for new pods.
   wal:
     enabled: true
-    size: 1Gi
+    size: 50Gi
     subPath: ""
     storageClass:
     # When changing this mountPath ensure you also change the following key to reflect this:
@@ -353,15 +353,15 @@ fullWalPrevention:
     readWriteFreePercent: 8
     readWriteFreeMB: 128
 
-resources: {}
+resources:
   # If you do want to specify resources, uncomment the following
   # lines, adjust them as necessary, and remove the curly braces after 'resources:'.
-  # limits:
-  #   cpu: 100m
-  #   memory: 128Mi
-  # requests:
-  #   cpu: 100m
-  #   memory: 128Mi
+  limits:
+    cpu: 2000m
+    memory: 16384Mi
+  requests:
+    cpu: 1500m
+    memory: 8192Mi
 
 sharedMemory:
   # By default Kubernetes only provides 64MB to /dev/shm
@@ -376,7 +376,7 @@ sharedMemory:
   #   No space left on device
   #
   # you may wish to use a mount to Memory, by setting useMount to true
-  useMount: false
+  useMount: true
 
 # timescaledb-tune will be run with the Pod resources requests or - if not set - its limits.
 # This should give a reasonably tuned PostgreSQL instance.
@@ -534,7 +534,7 @@ serviceAccount:
 # Setting unsafe to true will generate some random credentials. This is meant
 # for development or first evaluation of the Helm Charts. It should *not* be
 # used for anything beyong the evaluation phase.
-unsafe: false
+unsafe: true
 
 debug:
   # This setting is mainly for during development, debugging or troubleshooting.

Both in Amazon and local minikube

When memory load is too high, it fails

Example 1.
Hypertable with 78M+ records structure like

create table my_table
(
    id bigserial not null,
    field1 varchar(64) not null,
    field2 smallint,
    field3 varchar(16) not null,
    field4 varchar(16) not null,
    field5 integer not null,
    field6 double precision not null,
    field7 double precision not null,
    field8 double precision not null,
    field9 double precision not null,
    field10 double precision not null,
    field11 boolean not null,
    record_date integer not null,
    capture_date integer not null,
    created_at timestamp(0) not null
);
SELECT * FROM timescaledb_information.dimensions where hypertable_name like 'my_table' order by hypertable_name, dimension_number;
 hypertable_schema | hypertable_name | dimension_number | column_name |         column_type         | dimension_type | time_interval | integer_interval | integer_now_func | num_partitions 
-------------------+-----------------+------------------+-------------+-----------------------------+----------------+---------------+------------------+------------------+----------------
 public            | my_table      |                1 | created_at  | timestamp without time zone | Time           | 7 days        |                  |                  |               
(1 row)

When try to execute, it fails

create index if not exists my_table_record_date_idx_2 on my_table(record_date);

ohlcdb_prod=# create index if not exists my_table_record_date_idx_2 on my_table(record_date);
LOG:  statement: create index if not exists my_table_record_date_idx_2 on my_table(record_date);
WARNING:  terminating connection because of crash of another server process
DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
HINT:  In a moment you should be able to reconnect to the database and repeat your command.
server closed the connection unexpectedly
	This probably means the server terminated abnormally
	before or while processing the request.
The connection to the server was lost. Attempting reset: Failed.
Time: 319954.963 ms (05:19.955)
!>  

Settings

show shared_buffers;
 shared_buffers 
----------------
 4GB
(1 row)

top command a few seconds before failure

top - 19:30:45 up  1:44,  0 users,  load average: 6.62, 3.83, 1.80
Tasks:  20 total,   1 running,  19 sleeping,   0 stopped,   0 zombie
%Cpu0  :  10.9/12.2   23[                                                                                                    ]
%Cpu1  :  13.5/15.7   29[                                                                                                    ]
MiB Mem : 55.2/5954.9   [|||||||||||||||||||||||||||||||||||||||||||||||||||||||                                             ]
%Cpu0  :  18.0/28.6   47[                                                                                                    ]

MiB Mem : 59.1/5954.9   [|||||||||||||||||||||||||||||||||||||||||||||||||||||||||||                                         ]
   1162 postgres  20   0 1995960   1.3g   1.2g D  22.9  21.8   1:10.72 postgres                                                                                                                    

    PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                                                     
   1162 postgres  20   0 2236772   1.5g   1.2g D  43.6  25.7   1:10.03 postgres                                                                                                                    
    940 postgres  20   0 1950828  26120  23228 S   0.3   0.4   0:00.21 postgres                                                                                                                    
   4695 postgres  20   0 1946820  12448   9840 S   0.0   0.2   0:00.00 postgres                                                                                                                    
    932 postgres  20   0 1946572   8632   6328 S   0.3   0.1   0:01.69 postgres                                                                                                                    
    935 postgres  20   0 1946392   6804   4608 S   0.0   0.1   0:00.00 postgres                                                                                                                    
    934 postgres  20   0 1946380   8220   5988 S   0.0   0.1   0:00.02 postgres                                                                                                                    
    902 postgres  20   0 1941208 124712 122708 S   0.0   2.0   0:01.42 postgres                                                                                                                    
    903 postgres  20   0 1941112  29236  27268 S   0.3   0.5   0:00.89 postgres                                                                                                                    
    831 postgres  20   0 1938476 405892 403944 S   0.0   6.7   0:09.08 postgres                                                                                                                    
    931 postgres  20   0 1938476  22380  20432 D  19.9   0.4   0:06.16 postgres                                                                                                                    
     17 postgres  20   0  500396  36536  12476 S   0.0   0.6   0:11.67 patroni                                                                                                                     
    919 postgres  20   0   70524   5728   3640 D   0.0   0.1   0:04.79 postgres                                                                                                                    
    933 postgres  20   0   70244   5716   3768 D   0.0   0.1   0:00.21 postgres                                                                                                                    
      1 postgres  20   0   30820  17456   5912 S   0.0   0.3   0:00.48 patroni                                                                                                                     
   1155 postgres  20   0   24216   8564   7252 S   0.0   0.1   0:00.20 psql                                                                                                                        
    292 postgres  20   0   12740   1604   1128 R   0.0   0.0   0:06.38 top                                                                                                                         
    284 postgres  20   0    8716   1516   1020 S   0.0   0.0   0:00.05 bash                                                                                                                        

TimescaleDB version affected

2.0.1

PostgreSQL version used

PostgreSQL 12.6 (Debian 12.6-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit

What operating system did you use?

Linux timescaledb-0 4.19.202 #1 SMP Wed Oct 27 22:52:27 UTC 2021 x86_64 GNU/Linux

What installation method did you use?

Docker, Other

What platform did you run on?

Amazon Web Services (AWS), Other

Relevant log output and stack trace

2022-02-04 19:25:57 UTC [4288]: [61fd7dc5.10c0-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:26:25 UTC [1162]: [61fd6b6d.48a-18] postgres@ohlcdb_prod,app=psql [00000] LOG:  00000: statement: create index if not exists my_table_record_date_idx_2 on my_table(record_date);
2022-02-04 19:26:25 UTC [1162]: [61fd6b6d.48a-19] postgres@ohlcdb_prod,app=psql [00000] LOCATION:  exec_simple_query, postgres.c:1045
2022-02-04 19:26:27 UTC [4310]: [61fd7de3.10d6-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:26:27 UTC [4310]: [61fd7de3.10d6-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:26:27 UTC [4310]: [61fd7de3.10d6-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:26:27 UTC [4310]: [61fd7de3.10d6-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:26:27 UTC [4310]: [61fd7de3.10d6-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.026 user=postgres database=postgres host=[local]
2022-02-04 19:26:27 UTC [4310]: [61fd7de3.10d6-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:26:57 UTC [4357]: [61fd7e01.1105-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:26:57 UTC [4357]: [61fd7e01.1105-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:26:57 UTC [4357]: [61fd7e01.1105-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:26:57 UTC [4357]: [61fd7e01.1105-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:26:57 UTC [4357]: [61fd7e01.1105-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.004 user=postgres database=postgres host=[local]
2022-02-04 19:26:57 UTC [4357]: [61fd7e01.1105-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:27:28 UTC [4409]: [61fd7e20.1139-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:27:28 UTC [4409]: [61fd7e20.1139-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:27:28 UTC [4409]: [61fd7e20.1139-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:27:28 UTC [4409]: [61fd7e20.1139-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:27:28 UTC [4409]: [61fd7e20.1139-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.004 user=postgres database=postgres host=[local]
2022-02-04 19:27:28 UTC [4409]: [61fd7e20.1139-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:27:58 UTC [4464]: [61fd7e3e.1170-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:27:58 UTC [4464]: [61fd7e3e.1170-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:27:58 UTC [4464]: [61fd7e3e.1170-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:27:58 UTC [4464]: [61fd7e3e.1170-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:27:58 UTC [4464]: [61fd7e3e.1170-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.014 user=postgres database=postgres host=[local]
2022-02-04 19:27:58 UTC [4464]: [61fd7e3e.1170-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:28:32 UTC [4505]: [61fd7e60.1199-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:28:32 UTC [4505]: [61fd7e60.1199-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:28:32 UTC [4505]: [61fd7e60.1199-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:28:32 UTC [4505]: [61fd7e60.1199-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:28:32 UTC [4505]: [61fd7e60.1199-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.003 user=postgres database=postgres host=[local]
2022-02-04 19:28:32 UTC [4505]: [61fd7e60.1199-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:28:57 UTC [4550]: [61fd7e79.11c6-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:28:57 UTC [4550]: [61fd7e79.11c6-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:28:57 UTC [4550]: [61fd7e79.11c6-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:28:57 UTC [4550]: [61fd7e79.11c6-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:28:57 UTC [4550]: [61fd7e79.11c6-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.018 user=postgres database=postgres host=[local]
2022-02-04 19:28:57 UTC [4550]: [61fd7e79.11c6-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:29:27 UTC [4599]: [61fd7e97.11f7-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:29:27 UTC [4599]: [61fd7e97.11f7-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:29:27 UTC [4599]: [61fd7e97.11f7-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:29:27 UTC [4599]: [61fd7e97.11f7-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:29:27 UTC [4599]: [61fd7e97.11f7-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.029 user=postgres database=postgres host=[local]
2022-02-04 19:29:27 UTC [4599]: [61fd7e97.11f7-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:29:57 UTC [4641]: [61fd7eb5.1221-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:29:57 UTC [4641]: [61fd7eb5.1221-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:29:57 UTC [4641]: [61fd7eb5.1221-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:29:57 UTC [4641]: [61fd7eb5.1221-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:29:57 UTC [4641]: [61fd7eb5.1221-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.043 user=postgres database=postgres host=[local]
2022-02-04 19:29:57 UTC [4641]: [61fd7eb5.1221-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:30:15 UTC [902]: [61fd69a0.386-29] @,app= [00000] LOG:  00000: checkpoint starting: time
2022-02-04 19:30:15 UTC [902]: [61fd69a0.386-30] @,app= [00000] LOCATION:  LogCheckpointStart, xlog.c:8439
2022-02-04 19:30:29 UTC [4662]: [61fd7ed5.1236-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:30:29 UTC [4662]: [61fd7ed5.1236-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:30:29 UTC [4662]: [61fd7ed5.1236-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:30:29 UTC [4662]: [61fd7ed5.1236-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:30:29 UTC [4662]: [61fd7ed5.1236-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.010 user=postgres database=postgres host=[local]
2022-02-04 19:30:29 UTC [4662]: [61fd7ed5.1236-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:30:30 UTC [902]: [61fd69a0.386-31] @,app= [00000] LOG:  00000: checkpoint complete: wrote 50 buffers (0.0%); 0 WAL file(s) added, 0 removed, 62 recycled; write=5.062 s, sync=6.145 s, total=14.313 s; sync files=24, longest=6.083 s, average=0.257 s; distance=991543 kB, estimate=991543 kB
2022-02-04 19:30:30 UTC [902]: [61fd69a0.386-32] @,app= [00000] LOCATION:  LogCheckpointEnd, xlog.c:8507
2022-02-04 19:30:50,346 ERROR: Request to server https://10.96.0.1:443 failed: ReadTimeoutError("HTTPSConnectionPool(host='10.96.0.1', port=443): Read timed out. (read timeout=4.999408710000353)")
2022-02-04 19:30:53,054 ERROR: Request to server https://10.96.0.1:443 failed: ReadTimeoutError("HTTPSConnectionPool(host='10.96.0.1', port=443): Read timed out. (read timeout=2.0580822309611904)")
2022-02-04 19:30:55,340 ERROR: Request to server https://10.96.0.1:443 failed: ReadTimeoutError("HTTPSConnectionPool(host='10.96.0.1', port=443): Read timed out. (read timeout=1.6442477842338121)")
2022-02-04 19:30:55,340 ERROR: failed to update leader lock
2022-02-04 19:30:55 UTC [831]: [61fd6977.33f-13] @,app= [00000] LOG:  00000: received immediate shutdown request
2022-02-04 19:30:55 UTC [831]: [61fd6977.33f-14] @,app= [00000] LOCATION:  pmdie, postmaster.c:2845
2022-02-04 19:30:55 UTC [947]: [61fd69ae.3b3-5] postgres@postgres,app=Patroni [57P02] WARNING:  57P02: terminating connection because of crash of another server process
2022-02-04 19:30:55 UTC [947]: [61fd69ae.3b3-6] postgres@postgres,app=Patroni [57P02] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-04 19:30:55 UTC [947]: [61fd69ae.3b3-7] postgres@postgres,app=Patroni [57P02] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-04 19:30:55 UTC [947]: [61fd69ae.3b3-8] postgres@postgres,app=Patroni [57P02] LOCATION:  quickdie, postgres.c:2717
2022-02-04 19:30:55 UTC [932]: [61fd69a9.3a4-1] @,app= [57P02] WARNING:  57P02: terminating connection because of crash of another server process
2022-02-04 19:30:55 UTC [932]: [61fd69a9.3a4-2] @,app= [57P02] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-04 19:30:55 UTC [932]: [61fd69a9.3a4-3] @,app= [57P02] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-04 19:30:55 UTC [932]: [61fd69a9.3a4-4] @,app= [57P02] LOCATION:  quickdie, postgres.c:2717
2022-02-04 19:30:55 UTC [1162]: [61fd6b6d.48a-20] postgres@ohlcdb_prod,app=psql [57P02] WARNING:  57P02: terminating connection because of crash of another server process
2022-02-04 19:30:55 UTC [1162]: [61fd6b6d.48a-21] postgres@ohlcdb_prod,app=psql [57P02] DETAIL:  The postmaster has commanded this server process to roll back the current transaction and exit, because another server process exited abnormally and possibly corrupted shared memory.
2022-02-04 19:30:55 UTC [1162]: [61fd6b6d.48a-22] postgres@ohlcdb_prod,app=psql [57P02] HINT:  In a moment you should be able to reconnect to the database and repeat your command.
2022-02-04 19:30:55 UTC [1162]: [61fd6b6d.48a-23] postgres@ohlcdb_prod,app=psql [57P02] LOCATION:  quickdie, postgres.c:2717
2022-02-04 19:30:55 UTC [1162]: [61fd6b6d.48a-24] postgres@ohlcdb_prod,app=psql [57P02] STATEMENT:  create index if not exists my_table_record_date_idx_2 on my_table(record_date);
2022-02-04 19:30:55 UTC [831]: [61fd6977.33f-15] @,app= [00000] LOG:  00000: archiver process (PID 933) exited with exit code 2
2022-02-04 19:30:55 UTC [831]: [61fd6977.33f-16] @,app= [00000] LOCATION:  LogChildExit, postmaster.c:3671
2022-02-04 19:30:56 UTC [831]: [61fd6977.33f-17] @,app= [00000] LOG:  00000: database system is shut down
2022-02-04 19:30:56 UTC [831]: [61fd6977.33f-18] @,app= [00000] LOCATION:  UnlinkLockFiles, miscinit.c:860
2022-02-04 19:30:56,703 WARNING: Loop time exceeded, rescheduling immediately.
2022-02-04 19:30:58 UTC [4716]: [61fd7ef2.126c-1] @,app= [00000] INFO:  00000: timescaledb loaded
2022-02-04 19:30:58 UTC [4716]: [61fd7ef2.126c-2] @,app= [00000] LOCATION:  _PG_init, loader.c:543
/var/run/postgresql:5432 - no response
2022-02-04 19:30:58 UTC [4716]: [61fd7ef2.126c-3] @,app= [00000] LOG:  00000: starting PostgreSQL 12.6 (Debian 12.6-1.pgdg100+1) on x86_64-pc-linux-gnu, compiled by gcc (Debian 8.3.0-6) 8.3.0, 64-bit
2022-02-04 19:30:58 UTC [4716]: [61fd7ef2.126c-4] @,app= [00000] LOCATION:  PostmasterMain, postmaster.c:1019
2022-02-04 19:30:58 UTC [4716]: [61fd7ef2.126c-5] @,app= [00000] LOG:  00000: listening on IPv4 address "0.0.0.0", port 5432
2022-02-04 19:30:58 UTC [4716]: [61fd7ef2.126c-6] @,app= [00000] LOCATION:  StreamServerPort, pqcomm.c:590
2022-02-04 19:30:58 UTC [4716]: [61fd7ef2.126c-7] @,app= [00000] LOG:  00000: listening on Unix socket "/var/run/postgresql/.s.PGSQL.5432"
2022-02-04 19:30:58 UTC [4716]: [61fd7ef2.126c-8] @,app= [00000] LOCATION:  StreamServerPort, pqcomm.c:584
2022-02-04 19:30:59 UTC [4719]: [61fd7ef3.126f-1] @,app= [00000] LOG:  00000: database system was interrupted; last known up at 2022-02-04 19:30:29 UTC
2022-02-04 19:30:59 UTC [4719]: [61fd7ef3.126f-2] @,app= [00000] LOCATION:  StartupXLOG, xlog.c:6305
2022-02-04 19:30:59 UTC [4720]: [61fd7ef3.1270-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:30:59 UTC [4720]: [61fd7ef3.1270-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:30:59 UTC [4720]: [61fd7ef3.1270-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:30:59 UTC [4720]: [61fd7ef3.1270-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:00 UTC [4722]: [61fd7ef4.1272-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:00 UTC [4722]: [61fd7ef4.1272-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:00 UTC [4722]: [61fd7ef4.1272-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:00 UTC [4722]: [61fd7ef4.1272-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:01 UTC [4724]: [61fd7ef5.1274-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:01 UTC [4724]: [61fd7ef5.1274-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:01 UTC [4724]: [61fd7ef5.1274-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:01 UTC [4724]: [61fd7ef5.1274-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:02 UTC [4726]: [61fd7ef6.1276-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:02 UTC [4726]: [61fd7ef6.1276-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:02 UTC [4726]: [61fd7ef6.1276-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:02 UTC [4726]: [61fd7ef6.1276-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:03 UTC [4728]: [61fd7ef7.1278-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:03 UTC [4728]: [61fd7ef7.1278-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:03 UTC [4728]: [61fd7ef7.1278-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:03 UTC [4728]: [61fd7ef7.1278-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:04 UTC [4730]: [61fd7ef8.127a-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:04 UTC [4730]: [61fd7ef8.127a-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:04 UTC [4730]: [61fd7ef8.127a-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:04 UTC [4730]: [61fd7ef8.127a-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:05 UTC [4732]: [61fd7ef9.127c-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:05 UTC [4732]: [61fd7ef9.127c-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:05 UTC [4732]: [61fd7ef9.127c-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:05 UTC [4732]: [61fd7ef9.127c-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:06 UTC [4734]: [61fd7efa.127e-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:06 UTC [4734]: [61fd7efa.127e-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:06 UTC [4734]: [61fd7efa.127e-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:06 UTC [4734]: [61fd7efa.127e-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:07 UTC [4736]: [61fd7efb.1280-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:07 UTC [4736]: [61fd7efb.1280-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:07 UTC [4736]: [61fd7efb.1280-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:07 UTC [4736]: [61fd7efb.1280-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:08 UTC [4738]: [61fd7efc.1282-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:08 UTC [4738]: [61fd7efc.1282-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:08 UTC [4738]: [61fd7efc.1282-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:08 UTC [4738]: [61fd7efc.1282-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:08 UTC [4719]: [61fd7ef3.126f-3] @,app= [01000] WARNING:  01000: specified neither primary_conninfo nor restore_command
2022-02-04 19:31:08 UTC [4719]: [61fd7ef3.126f-4] @,app= [01000] HINT:  The database server will regularly poll the pg_wal subdirectory to check for files placed there.
2022-02-04 19:31:08 UTC [4719]: [61fd7ef3.126f-5] @,app= [01000] LOCATION:  validateRecoveryParameters, xlog.c:5432
2022-02-04 19:31:08 UTC [4719]: [61fd7ef3.126f-6] @,app= [00000] LOG:  00000: entering standby mode
2022-02-04 19:31:08 UTC [4719]: [61fd7ef3.126f-7] @,app= [00000] LOCATION:  StartupXLOG, xlog.c:6360
2022-02-04 19:31:08 UTC [4719]: [61fd7ef3.126f-8] @,app= [00000] LOG:  00000: database system was not properly shut down; automatic recovery in progress
2022-02-04 19:31:08 UTC [4719]: [61fd7ef3.126f-9] @,app= [00000] LOCATION:  StartupXLOG, xlog.c:6808
2022-02-04 19:31:09 UTC [4719]: [61fd7ef3.126f-10] @,app= [00000] LOG:  00000: redo starts at 64/F185E600
2022-02-04 19:31:09 UTC [4719]: [61fd7ef3.126f-11] @,app= [00000] LOCATION:  StartupXLOG, xlog.c:7083
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:09 UTC [4742]: [61fd7efd.1286-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:09 UTC [4742]: [61fd7efd.1286-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:09 UTC [4742]: [61fd7efd.1286-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:09 UTC [4742]: [61fd7efd.1286-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
2022-02-04 19:31:10 UTC [4744]: [61fd7efe.1288-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:10 UTC [4744]: [61fd7efe.1288-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:10 UTC [4744]: [61fd7efe.1288-3] postgres@postgres,app=[unknown] [57P03] FATAL:  57P03: the database system is starting up
2022-02-04 19:31:10 UTC [4744]: [61fd7efe.1288-4] postgres@postgres,app=[unknown] [57P03] LOCATION:  ProcessStartupPacket, postmaster.c:2298
/var/run/postgresql:5432 - rejecting connections
2022-02-04 19:31:11 UTC [4719]: [61fd7ef3.126f-12] @,app= [00000] LOG:  00000: consistent recovery state reached at 65/89CE68
2022-02-04 19:31:11 UTC [4719]: [61fd7ef3.126f-13] @,app= [00000] LOCATION:  CheckRecoveryConsistency, xlog.c:7930
2022-02-04 19:31:11 UTC [4716]: [61fd7ef2.126c-9] @,app= [00000] LOG:  00000: database system is ready to accept read only connections
2022-02-04 19:31:11 UTC [4716]: [61fd7ef2.126c-10] @,app= [00000] LOCATION:  sigusr1_handler, postmaster.c:5188
2022-02-04 19:31:11 UTC [4747]: [61fd7eff.128b-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:11 UTC [4747]: [61fd7eff.128b-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:11 UTC [4747]: [61fd7eff.128b-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:31:11 UTC [4747]: [61fd7eff.128b-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:31:11 UTC [4747]: [61fd7eff.128b-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.036 user=postgres database=postgres host=[local]
2022-02-04 19:31:11 UTC [4747]: [61fd7eff.128b-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
/var/run/postgresql:5432 - accepting connections
2022-02-04 19:31:11 UTC [4749]: [61fd7eff.128d-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:11 UTC [4749]: [61fd7eff.128d-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:11 UTC [4749]: [61fd7eff.128d-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=Patroni
2022-02-04 19:31:11 UTC [4749]: [61fd7eff.128d-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:31:11 UTC [4751]: [61fd7eff.128f-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=127.0.0.1 port=54452
2022-02-04 19:31:11 UTC [4751]: [61fd7eff.128f-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4343
2022-02-04 19:31:11 UTC [4751]: [61fd7eff.128f-3] standby@[unknown],app=[unknown] [28P01] FATAL:  28P01: password authentication failed for user "standby"
2022-02-04 19:31:11 UTC [4751]: [61fd7eff.128f-4] standby@[unknown],app=[unknown] [28P01] DETAIL:  Password does not match for user "standby".
	Connection matched pg_hba.conf line 8: "hostssl   replication     standby            all                md5"
2022-02-04 19:31:11 UTC [4751]: [61fd7eff.128f-5] standby@[unknown],app=[unknown] [28P01] LOCATION:  auth_failed, auth.c:333
2022-02-04 19:31:11 UTC [4752]: [61fd7eff.1290-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=127.0.0.1 port=54454
2022-02-04 19:31:11 UTC [4752]: [61fd7eff.1290-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4343
2022-02-04 19:31:11 UTC [4752]: [61fd7eff.1290-3] standby@[unknown],app=[unknown] [28P01] FATAL:  28P01: password authentication failed for user "standby"
2022-02-04 19:31:11 UTC [4752]: [61fd7eff.1290-4] standby@[unknown],app=[unknown] [28P01] DETAIL:  Password does not match for user "standby".
	Connection matched pg_hba.conf line 5: "hostnossl all,replication all                all                md5"
2022-02-04 19:31:11 UTC [4752]: [61fd7eff.1290-5] standby@[unknown],app=[unknown] [28P01] LOCATION:  auth_failed, auth.c:333
2022-02-04 19:31:11,945 ERROR: Can not fetch local timeline and lsn from replication connection
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/patroni/postgresql/__init__.py", line 737, in get_replica_timeline
    with self.get_replication_connection_cursor(**self.config.local_replication_address) as cur:
  File "/usr/lib/python3.7/contextlib.py", line 112, in __enter__
    return next(self.gen)
  File "/usr/lib/python3/dist-packages/patroni/postgresql/__init__.py", line 732, in get_replication_connection_cursor
    with get_connection_cursor(**conn_kwargs) as cur:
  File "/usr/lib/python3.7/contextlib.py", line 112, in __enter__
    return next(self.gen)
  File "/usr/lib/python3/dist-packages/patroni/postgresql/connection.py", line 43, in get_connection_cursor
    with psycopg2.connect(**kwargs) as conn:
  File "/usr/lib/python3/dist-packages/psycopg2/__init__.py", line 127, in connect
    conn = _connect(dsn, connection_factory=connection_factory, **kwasync)
psycopg2.OperationalError: FATAL:  password authentication failed for user "standby"
FATAL:  password authentication failed for user "standby"

2022-02-04 19:31:12 UTC [4719]: [61fd7ef3.126f-14] @,app= [00000] LOG:  00000: received promote request
2022-02-04 19:31:12 UTC [4719]: [61fd7ef3.126f-15] @,app= [00000] LOCATION:  CheckForStandbyTrigger, xlog.c:12295
2022-02-04 19:31:12 UTC [4719]: [61fd7ef3.126f-16] @,app= [00000] LOG:  00000: redo done at 65/89B0A8
2022-02-04 19:31:12 UTC [4719]: [61fd7ef3.126f-17] @,app= [00000] LOCATION:  StartupXLOG, xlog.c:7345
server promoting
2022-02-04 19:31:12 UTC [4719]: [61fd7ef3.126f-18] @,app= [00000] LOG:  00000: selected new timeline ID: 59
2022-02-04 19:31:12 UTC [4719]: [61fd7ef3.126f-19] @,app= [00000] LOCATION:  StartupXLOG, xlog.c:7480
2022-02-04 19:31:12 UTC [4719]: [61fd7ef3.126f-20] @,app= [00000] LOG:  00000: archive recovery complete
2022-02-04 19:31:12 UTC [4719]: [61fd7ef3.126f-21] @,app= [00000] LOCATION:  exitArchiveRecovery, xlog.c:5593
2022-02-04 19:31:12 UTC [4739]: [61fd7efd.1283-1] @,app= [00000] LOG:  00000: checkpoint starting: force
2022-02-04 19:31:12 UTC [4739]: [61fd7efd.1283-2] @,app= [00000] LOCATION:  LogCheckpointStart, xlog.c:8439
2022-02-04 19:31:12 UTC [4716]: [61fd7ef2.126c-11] @,app= [00000] LOG:  00000: database system is ready to accept connections
2022-02-04 19:31:12 UTC [4716]: [61fd7ef2.126c-12] @,app= [00000] LOCATION:  reaper, postmaster.c:3001
2022-02-04 19:31:12 UTC [4759]: [61fd7f00.1297-1] @,app= [00000] LOG:  00000: TimescaleDB background worker launcher connected to shared catalogs
2022-02-04 19:31:12 UTC [4759]: [61fd7f00.1297-2] @,app= [00000] LOCATION:  ts_bgw_cluster_launcher_main, bgw_launcher.c:765
2022-02-04 19:31:13 UTC [4770]: [61fd7f01.12a2-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:13 UTC [4770]: [61fd7f01.12a2-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:13 UTC [4770]: [61fd7f01.12a2-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=Patroni
2022-02-04 19:31:13 UTC [4770]: [61fd7f01.12a2-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:31:23 UTC [4749]: [61fd7eff.128d-5] postgres@postgres,app=Patroni [57014] ERROR:  57014: canceling statement due to statement timeout
2022-02-04 19:31:23 UTC [4749]: [61fd7eff.128d-6] postgres@postgres,app=Patroni [57014] LOCATION:  ProcessInterrupts, postgres.c:3106
2022-02-04 19:31:23 UTC [4749]: [61fd7eff.128d-7] postgres@postgres,app=Patroni [57014] STATEMENT:  SELECT slot_name, slot_type, plugin, database FROM pg_catalog.pg_replication_slots
2022-02-04 19:31:23,803 ERROR: Exception when changing replication slots
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/patroni/postgresql/__init__.py", line 256, in _query
    cursor.execute(sql, params)
psycopg2.errors.QueryCanceled: canceling statement due to statement timeout


During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/patroni/postgresql/slots.py", line 45, in sync_replication_slots
    self.load_replication_slots()
  File "/usr/lib/python3/dist-packages/patroni/postgresql/slots.py", line 27, in load_replication_slots
    cursor = self._query('SELECT slot_name, slot_type, plugin, database FROM pg_catalog.pg_replication_slots')
  File "/usr/lib/python3/dist-packages/patroni/postgresql/slots.py", line 22, in _query
    return self._postgresql.query(sql, *params, retry=False)
  File "/usr/lib/python3/dist-packages/patroni/postgresql/__init__.py", line 274, in query
    return self._query(sql, *args)
  File "/usr/lib/python3/dist-packages/patroni/postgresql/__init__.py", line 270, in _query
    raise PostgresConnectionException('connection problems')
patroni.exceptions.PostgresConnectionException: 'connection problems'
2022-02-04 19:31:23 UTC [4749]: [61fd7eff.128d-8] postgres@postgres,app=Patroni [00000] LOG:  00000: disconnection: session time: 0:00:11.961 user=postgres database=postgres host=[local]
2022-02-04 19:31:23 UTC [4749]: [61fd7eff.128d-9] postgres@postgres,app=Patroni [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:31:23 UTC [4739]: [61fd7efd.1283-3] @,app= [00000] LOG:  00000: checkpoint complete: wrote 33803 buffers (20.6%); 0 WAL file(s) added, 0 removed, 14 recycled; write=9.510 s, sync=1.323 s, total=11.034 s; sync files=18, longest=1.298 s, average=0.074 s; distance=246010 kB, estimate=246010 kB
2022-02-04 19:31:23 UTC [4739]: [61fd7efd.1283-4] @,app= [00000] LOCATION:  LogCheckpointEnd, xlog.c:8507
2022-02-04 19:31:23 UTC [4739]: [61fd7efd.1283-5] @,app= [00000] LOG:  00000: checkpoint starting: immediate force wait
2022-02-04 19:31:23 UTC [4739]: [61fd7efd.1283-6] @,app= [00000] LOCATION:  LogCheckpointStart, xlog.c:8439
2022-02-04 19:31:24 UTC [4739]: [61fd7efd.1283-7] @,app= [00000] LOG:  00000: checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.015 s, sync=0.001 s, total=0.045 s; sync files=0, longest=0.000 s, average=0.000 s; distance=0 kB, estimate=221409 kB
2022-02-04 19:31:24 UTC [4739]: [61fd7efd.1283-8] @,app= [00000] LOCATION:  LogCheckpointEnd, xlog.c:8507
2022-02-04 19:31:24 UTC [4770]: [61fd7f01.12a2-5] postgres@postgres,app=Patroni [00000] LOG:  00000: duration: 10760.852 ms  statement: CHECKPOINT
2022-02-04 19:31:24 UTC [4770]: [61fd7f01.12a2-6] postgres@postgres,app=Patroni [00000] LOCATION:  exec_simple_query, postgres.c:1296
2022-02-04 19:31:24 UTC [4770]: [61fd7f01.12a2-7] postgres@postgres,app=Patroni [00000] LOG:  00000: disconnection: session time: 0:00:10.797 user=postgres database=postgres host=[local]
2022-02-04 19:31:24 UTC [4770]: [61fd7f01.12a2-8] postgres@postgres,app=Patroni [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:31:24,114 WARNING: Loop time exceeded, rescheduling immediately.
2022-02-04 19:31:24 UTC [4773]: [61fd7f0c.12a5-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:24 UTC [4773]: [61fd7f0c.12a5-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:24 UTC [4773]: [61fd7f0c.12a5-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=Patroni
2022-02-04 19:31:24 UTC [4773]: [61fd7f0c.12a5-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:31:27 UTC [4781]: [61fd7f0f.12ad-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:27 UTC [4781]: [61fd7f0f.12ad-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:27 UTC [4781]: [61fd7f0f.12ad-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:31:27 UTC [4781]: [61fd7f0f.12ad-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:31:27 UTC [4781]: [61fd7f0f.12ad-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.008 user=postgres database=postgres host=[local]
2022-02-04 19:31:27 UTC [4781]: [61fd7f0f.12ad-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:31:57 UTC [4794]: [61fd7f2d.12ba-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:31:57 UTC [4794]: [61fd7f2d.12ba-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:31:57 UTC [4794]: [61fd7f2d.12ba-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:31:57 UTC [4794]: [61fd7f2d.12ba-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:31:57 UTC [4794]: [61fd7f2d.12ba-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.003 user=postgres database=postgres host=[local]
2022-02-04 19:31:57 UTC [4794]: [61fd7f2d.12ba-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:32:27 UTC [4808]: [61fd7f4b.12c8-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:32:27 UTC [4808]: [61fd7f4b.12c8-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:32:27 UTC [4808]: [61fd7f4b.12c8-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:32:27 UTC [4808]: [61fd7f4b.12c8-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:32:27 UTC [4808]: [61fd7f4b.12c8-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.014 user=postgres database=postgres host=[local]
2022-02-04 19:32:27 UTC [4808]: [61fd7f4b.12c8-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691
2022-02-04 19:32:57 UTC [4822]: [61fd7f69.12d6-1] [unknown]@[unknown],app=[unknown] [00000] LOG:  00000: connection received: host=[local]
2022-02-04 19:32:57 UTC [4822]: [61fd7f69.12d6-2] [unknown]@[unknown],app=[unknown] [00000] LOCATION:  BackendInitialize, postmaster.c:4347
2022-02-04 19:32:57 UTC [4822]: [61fd7f69.12d6-3] postgres@postgres,app=[unknown] [00000] LOG:  00000: connection authorized: user=postgres database=postgres application_name=pg_isready
2022-02-04 19:32:57 UTC [4822]: [61fd7f69.12d6-4] postgres@postgres,app=[unknown] [00000] LOCATION:  PerformAuthentication, postinit.c:292
2022-02-04 19:32:57 UTC [4822]: [61fd7f69.12d6-5] postgres@postgres,app=pg_isready [00000] LOG:  00000: disconnection: session time: 0:00:00.012 user=postgres database=postgres host=[local]
2022-02-04 19:32:57 UTC [4822]: [61fd7f69.12d6-6] postgres@postgres,app=pg_isready [00000] LOCATION:  log_disconnections, postgres.c:4691

How can we reproduce the bug?

Data contains 78M+ rows
If you're ready to debug version 2.0.1, I will generate a script filling this table
@npakudin npakudin added the bug label Feb 4, 2022
@mfundul
Copy link
Contributor

mfundul commented Feb 4, 2022

Did you check if the OOM killer is killing the postgres process? If this is a crash and not an out of memory condition then you could try to gather a core dump.

If it easy for you to generate this workload you could also test the latest version and see if the same problem does not occur anymore.

@NunoFilipeSantos
Copy link
Contributor

NunoFilipeSantos commented Mar 7, 2022

@npakudin can you test with the latest TimescaleDB version (2.6.0) and get back to us? thank you!

@konskov
Copy link
Contributor

konskov commented Apr 18, 2022

@npakudin thank you for the bug report. We haven't managed to reproduce this from the information provided, so I will close it for now, but we can always come back to it if there's more information that can help investigate this.

@konskov konskov closed this as completed Apr 18, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

5 participants