Skip to content

Unable to restore from backups #67

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.

Sign up for GitHub

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

Jump to bottom
Open
samip5 opened this issue Oct 16, 2024 · 12 comments
Open

Unable to restore from backups #67

samip5 opened this issue Oct 16, 2024 · 12 comments
Labels
question Further information is requested

Comments

@samip5
Copy link

samip5 commented Oct 16, 2024

Unfortunately it seems that the backed up archives are not able to be restored..

ghcr.io/tensorchord/cloudnative-pgvecto.rs:16.2-v0.2.1

Cluster CRD:

---
apiVersion: postgresql.cnpg.io/v1
kind: Cluster
metadata:
  name: cluster16-vector
  namespace: databases
spec:
  instances: 2
  imageName: ghcr.io/tensorchord/cloudnative-pgvecto.rs:16.2-v0.2.1
  primaryUpdateStrategy: unsupervised
  storage:
    size: 15Gi
    storageClass: local-hostpath
  superuserSecret:
    name: cloudnative-pg-secret
  enableSuperuserAccess: true
  resources:
    requests:
      memory: 1Gi
    limits:
      memory: 2Gi
#  bootstrap:
#    initdb:
#      postInitSQL:
#        - ALTER SYSTEM SET search_path TO "$user", public, vectors;
#        - CREATE EXTENSION IF NOT EXISTS "vectors";
  bootstrap:
    recovery:
      source: &previousCluster postgres-vector-v11
  affinity:
    enablePodAntiAffinity: true
    topologyKey: kubernetes.io/hostname
    podAntiAffinityType: required
    nodeSelector:
      kubernetes.io/arch: amd64

  postgresql:
    shared_preload_libraries:
      - "vectors.so"
    enableAlterSystem: true
    parameters:
      max_connections: "600"
      shared_buffers: 512MB
  monitoring:
    enablePodMonitor: true
    # https://github.com/cloudnative-pg/cloudnative-pg/issues/2501
    podMonitorMetricRelabelings:
        - { sourceLabels: [ "cluster" ], targetLabel: cnpg_cluster, action: replace }
        - { regex: cluster, action: labeldrop }
  backup:
    retentionPolicy: "30d"
    barmanObjectStore:
      wal:
        compression: bzip2
        maxParallel: 4
      data:
        compression: bzip2
      destinationPath: s3://cnpg-main/
      endpointURL: https://s3.skym.fi
      serverName: &currentCluster postgres-vector-v12
      s3Credentials:
        accessKeyId:
          name: cloudnative-pg-secret
          key: aws-access-key-id
        secretAccessKey:
          name: cloudnative-pg-secret
          key: aws-secret-access-key
  externalClusters:
    - name: *previousCluster
      barmanObjectStore:
        wal:
          compression: bzip2
          maxParallel: 8
        destinationPath: s3://cnpg-main/
        endpointURL: https://s3.skym.fi
        s3Credentials:
          accessKeyId:
            name: cloudnative-pg-secret
            key: aws-access-key-id
          secretAccessKey:
            name: cloudnative-pg-secret
            key: aws-secret-access-key
{"level":"info","ts":"2024-10-16T09:49:40Z","msg":"barman-cloud-check-wal-archive checking the first wal","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:49:40Z","msg":"Recovering from external cluster","logging_pod":"cluster16-vector-1-full-recovery","sourceName":"postgres-vector-v11"}
{"level":"info","ts":"2024-10-16T09:49:42Z","msg":"Target backup found","logging_pod":"cluster16-vector-1-full-recovery","backup":{"backup_name":"backup-20241016083833","backup_label":"'START WAL LOCATION: 46/8E0000E8 (file 00000007000000460000008E)\\nCHECKPOINT LOCATION: 46/8F000060\\nBACKUP METHOD: streamed\\nBACKUP FROM: standby\\nSTART TIME: 2024-10-16 08:38:34 UTC\\nLABEL: Barman backup cloud 20241016T083833\\nSTART TIMELINE: 7\\n'","begin_time":"Wed Oct 16 08:38:34 2024","end_time":"Wed Oct 16 08:38:56 2024","BeginTime":"2024-10-16T08:38:34Z","EndTime":"2024-10-16T08:38:56Z","begin_wal":"00000007000000460000008E","end_wal":"000000070000004600000090","begin_xlog":"46/8E0000E8","end_xlog":"46/90000000","systemid":"7368693795026370580","backup_id":"20241016T083833","error":"","timeline":7}}
{"level":"info","ts":"2024-10-16T09:49:42Z","msg":"Starting barman-cloud-restore","logging_pod":"cluster16-vector-1-full-recovery","options":["--endpoint-url","https://s3.skym.fi","s3://cnpg-main/","postgres-vector-v11","20241016T083833","--cloud-provider","aws-s3","/var/lib/postgresql/data/pgdata"]}
{"level":"info","ts":"2024-10-16T09:49:53Z","msg":"Restore completed","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:49:53Z","msg":"Creating new data directory","logging_pod":"cluster16-vector-1-full-recovery","pgdata":"/controller/recovery/datadir_1530716887","initDbOptions":["--username","postgres","-D","/controller/recovery/datadir_1530716887","--no-sync"]}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"initdb","msg":"The files belonging to this database system will be owned by user \"postgres\".\nThis user must also own the server process.\n\nThe database cluster will be initialized with locale \"en_US.utf8\".\nThe default database encoding has accordingly been set to \"UTF8\".\nThe default text search configuration will be set to \"english\".\n\nData page checksums are disabled.\n\nfixing permissions on existing directory /controller/recovery/datadir_1530716887 ... ok\ncreating subdirectories ... ok\nselecting dynamic shared memory implementation ... posix\nselecting default max_connections ... 100\nselecting default shared_buffers ... 128MB\nselecting default time zone ... Etc/UTC\ncreating configuration files ... ok\nrunning bootstrap script ... ok\nperforming post-bootstrap initialization ... ok\n\nSync to disk skipped.\nThe data directory might become corrupt if the operating system crashes.\n\n\nSuccess. You can now start the database server using:\n\n    pg_ctl -D /controller/recovery/datadir_1530716887 -l logfile start\n\n","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"initdb","msg":"initdb: warning: enabling \"trust\" authentication for local connections\ninitdb: hint: You can change this by editing pg_hba.conf or using the option -A, or --auth-local and --auth-host, the next time you run initdb.\n","pipe":"stderr","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:49:54Z","msg":"Installed configuration file","logging_pod":"cluster16-vector-1-full-recovery","pgdata":"/controller/recovery/datadir_1530716887","filename":"pg_hba.conf"}
{"level":"info","ts":"2024-10-16T09:49:54Z","msg":"Installed configuration file","logging_pod":"cluster16-vector-1-full-recovery","pgdata":"/controller/recovery/datadir_1530716887","filename":"pg_ident.conf"}
{"level":"info","ts":"2024-10-16T09:49:54Z","msg":"Installed configuration file","logging_pod":"cluster16-vector-1-full-recovery","pgdata":"/controller/recovery/datadir_1530716887","filename":"custom.conf"}
{"level":"info","ts":"2024-10-16T09:49:54Z","msg":"Generated recovery configuration","logging_pod":"cluster16-vector-1-full-recovery","configuration":"recovery_target_action = promote\nrestore_command = 'barman-cloud-wal-restore --endpoint-url https://s3.skym.fi s3://cnpg-main/ postgres-vector-v11 --cloud-provider aws-s3 %f %p'\n"}
{"level":"info","ts":"2024-10-16T09:49:54Z","msg":"Aligned PostgreSQL configuration to satisfy both pg_controldata and cluster spec","logging_pod":"cluster16-vector-1-full-recovery","enforcedParams":{"max_connections":"600","max_locks_per_transaction":"64","max_prepared_transactions":"0","max_wal_senders":"10","max_worker_processes":"32"},"controldataParams":{"max_connections":600,"max_locks_per_transaction":64,"max_prepared_transactions":0,"max_wal_senders":10,"max_worker_processes":32},"clusterParams":{"max_connections":600,"max_worker_processes":32}}
{"level":"info","ts":"2024-10-16T09:49:54Z","msg":"Starting up instance","logging_pod":"cluster16-vector-1-full-recovery","pgdata":"/var/lib/postgresql/data/pgdata","options":["start","-w","-D","/var/lib/postgresql/data/pgdata","-o","-c port=5432 -c unix_socket_directories=/controller/run","-t 40000000","-o","-c listen_addresses='127.0.0.1'"]}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"pg_ctl","msg":"waiting for server to start....2024-10-16 09:49:54.578 UTC [38] LOG:  redirecting log output to logging collector process","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"pg_ctl","msg":"2024-10-16 09:49:54.578 UTC [38] HINT:  Future log output will appear in directory \"/controller/log\".","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:54.578 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"1","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"ending log output to stderr","hint":"Future log output will go to log destination \"csvlog\".","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:54.578 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"2","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"starting PostgreSQL 16.2 (Debian 16.2-1.pgdg110+2) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:54.578 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"3","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"listening on IPv4 address \"127.0.0.1\", port 5432","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:54.582 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"4","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"listening on Unix socket \"/controller/run/.s.PGSQL.5432\"","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:54.587 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"1","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system was interrupted while in recovery at log time 2024-10-16 07:51:31 UTC","hint":"If this has occurred more than once some data might be corrupted and you might need to choose an earlier recovery target.","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:54Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:54.587 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"2","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"creating missing WAL directory \"pg_wal/archive_status\"","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:55Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:55.732 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"3","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"starting archive recovery","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:55Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:55.737 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"4","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"starting backup recovery with redo LSN 46/8E0000E8, checkpoint LSN 46/8F000060, on timeline ID 7","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:56Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:56.254 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"5","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000007.history\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:56Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:56.852 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"6","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000007000000460000008F\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:57Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:57.509 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"7","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000007000000460000008E\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:58Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:58.720 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"8","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"redo starts at 46/8E0000E8","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:59Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:59.270 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"9","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000007000000460000008F\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:59Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:59.831 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"10","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"completed backup recovery with redo LSN 46/8E0000E8 and end LSN 46/90000000","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:59Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:59.831 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"11","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"consistent recovery state reached at 46/90000000","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:59Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:49:59.831 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"5","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system is ready to accept read-only connections","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:49:59Z","logger":"pg_ctl","msg":"..... done","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:49:59Z","logger":"pg_ctl","msg":"server started","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:00Z","msg":"Checking if the server is still in recovery","logging_pod":"cluster16-vector-1-full-recovery","recovery":true}
{"level":"info","ts":"2024-10-16T09:50:00Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:00.316 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"12","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"redo done at 46/8F000110 system usage: CPU: user: 0.00 s, system: 0.00 s, elapsed: 1.59 s","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:00Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:00.957 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"13","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000007000000460000008F\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:01Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:01.506 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"14","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"selected new timeline ID: 8","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:02Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:02.112 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"15","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"restored log file \"00000007.history\" from archive","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:02Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:02.120 UTC","process_id":"42","session_id":"670f8c42.2a","session_line_num":"16","session_start_time":"2024-10-16 09:49:54 UTC","virtual_transaction_id":"1/0","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive recovery complete","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:02Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:02.122 UTC","process_id":"40","session_id":"670f8c42.28","session_line_num":"1","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"checkpoint starting: end-of-recovery immediate wait","backend_type":"checkpointer","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:02Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:02.132 UTC","process_id":"40","session_id":"670f8c42.28","session_line_num":"2","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"checkpoint complete: wrote 2 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.004 s, total=0.013 s; sync files=3, longest=0.002 s, average=0.002 s; distance=32767 kB, estimate=32767 kB; lsn=46/90000028, redo lsn=46/90000028","backend_type":"checkpointer","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:02Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:02.138 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"6","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system is ready to accept connections","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:02Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:02.139 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"1","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:03Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:03.140 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"2","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:04Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:04.141 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"3","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:04Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:04.141 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"4","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"WARNING","sql_state_code":"01000","message":"archiving write-ahead log file \"00000008.history\" failed too many times, will try again later","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:05Z","msg":"Checking if the server is still in recovery","logging_pod":"cluster16-vector-1-full-recovery","recovery":false}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"pg_ctl","msg":"pg_ctl: server is running (PID: 38)\n/usr/lib/postgresql/16/bin/postgres \"-D\" \"/var/lib/postgresql/data/pgdata\" \"-c\" \"port=5432\" \"-c\" \"unix_socket_directories=/controller/run\" \"-c\" \"listen_addresses=127.0.0.1\"\n","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:05Z","msg":"Shutting down instance","logging_pod":"cluster16-vector-1-full-recovery","pgdata":"/var/lib/postgresql/data/pgdata","mode":"fast","timeout":null}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:05.047 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"7","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"received fast shutdown request","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:05.049 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"8","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"aborting any active transactions","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:05.050 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"9","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"background worker \"logical replication launcher\" (PID 86) exited with exit code 1","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:05.052 UTC","process_id":"40","session_id":"670f8c42.28","session_line_num":"3","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"shutting down","backend_type":"checkpointer","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:05.129 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"5","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:05.129 UTC","process_id":"40","session_id":"670f8c42.28","session_line_num":"4","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"checkpoint starting: shutdown immediate","backend_type":"checkpointer","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:05.199 UTC","process_id":"40","session_id":"670f8c42.28","session_line_num":"5","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"checkpoint complete: wrote 0 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.001 s, total=0.071 s; sync files=0, longest=0.000 s, average=0.000 s; distance=16384 kB, estimate=31129 kB; lsn=46/91000028, redo lsn=46/91000028","backend_type":"checkpointer","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:05Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:05.202 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"6","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:06Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:06.203 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"7","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:06Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:06.203 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"8","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"WARNING","sql_state_code":"01000","message":"archiving write-ahead log file \"00000008.history\" failed too many times, will try again later","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:06Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:06.204 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"9","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:07Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:07.205 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"10","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.206 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"11","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.206 UTC","process_id":"85","session_id":"670f8c4a.55","session_line_num":"12","session_start_time":"2024-10-16 09:50:02 UTC","transaction_id":"0","error_severity":"WARNING","sql_state_code":"01000","message":"archiving write-ahead log file \"00000008.history\" failed too many times, will try again later","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.216 UTC","process_id":"38","session_id":"670f8c42.26","session_line_num":"10","session_start_time":"2024-10-16 09:49:54 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system is shut down","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"pg_ctl","msg":"waiting for server to shut down....... done","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"pg_ctl","msg":"server stopped","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","msg":"Exited log pipe","fileName":"/controller/log/postgres.csv","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","msg":"Updated replication settings","logging_pod":"cluster16-vector-1-full-recovery","filename":"override.conf"}
{"level":"info","ts":"2024-10-16T09:50:08Z","msg":"Starting up instance","logging_pod":"cluster16-vector-1-full-recovery","pgdata":"/var/lib/postgresql/data/pgdata","options":["start","-w","-D","/var/lib/postgresql/data/pgdata","-o","-c port=5432 -c unix_socket_directories=/controller/run","-t 40000000","-o","-c listen_addresses='127.0.0.1'"]}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"pg_ctl","msg":"waiting for server to start....2024-10-16 09:50:08.321 UTC [102] LOG:  redirecting log output to logging collector process","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"pg_ctl","msg":"2024-10-16 09:50:08.321 UTC [102] HINT:  Future log output will appear in directory \"/controller/log\".","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.321 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"1","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"ending log output to stderr","hint":"Future log output will go to log destination \"csvlog\".","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.321 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"2","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"starting PostgreSQL 16.2 (Debian 16.2-1.pgdg110+2) on x86_64-pc-linux-gnu, compiled by gcc (Debian 10.2.1-6) 10.2.1 20210110, 64-bit","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.321 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"3","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"listening on IPv4 address \"127.0.0.1\", port 5432","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.324 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"4","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"listening on Unix socket \"/controller/run/.s.PGSQL.5432\"","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.329 UTC","process_id":"106","session_id":"670f8c50.6a","session_line_num":"1","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system was shut down at 2024-10-16 09:50:05 UTC","backend_type":"startup","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.334 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"5","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system is ready to accept connections","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.335 UTC","process_id":"114","session_id":"670f8c50.72","session_line_num":"1","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"pg_ctl","msg":" done","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"pg_ctl","msg":"server started","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","msg":"Configuring new PostgreSQL instance","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","msg":"Executing post-init SQL instructions","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","msg":"Executing post-init template SQL instructions","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"pg_ctl","msg":"pg_ctl: server is running (PID: 102)\n/usr/lib/postgresql/16/bin/postgres \"-D\" \"/var/lib/postgresql/data/pgdata\" \"-c\" \"port=5432\" \"-c\" \"unix_socket_directories=/controller/run\" \"-c\" \"listen_addresses=127.0.0.1\"\n","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:08Z","msg":"Shutting down instance","logging_pod":"cluster16-vector-1-full-recovery","pgdata":"/var/lib/postgresql/data/pgdata","mode":"fast","timeout":null}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.488 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"6","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"received fast shutdown request","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.490 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"7","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"aborting any active transactions","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.492 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"8","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"background worker \"logical replication launcher\" (PID 115) exited with exit code 1","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.494 UTC","process_id":"104","session_id":"670f8c50.68","session_line_num":"1","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"shutting down","backend_type":"checkpointer","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:08Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:08.565 UTC","process_id":"104","session_id":"670f8c50.68","session_line_num":"2","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"checkpoint starting: shutdown immediate","backend_type":"checkpointer","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:09Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:09.336 UTC","process_id":"114","session_id":"670f8c50.72","session_line_num":"2","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:09Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:09.603 UTC","process_id":"104","session_id":"670f8c50.68","session_line_num":"3","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"checkpoint complete: wrote 3 buffers (0.0%); 0 WAL file(s) added, 0 removed, 0 recycled; write=0.002 s, sync=0.004 s, total=1.041 s; sync files=4, longest=0.002 s, average=0.001 s; distance=16384 kB, estimate=16384 kB; lsn=46/92000028, redo lsn=46/92000028","backend_type":"checkpointer","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:09Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:09.606 UTC","process_id":"114","session_id":"670f8c50.72","session_line_num":"3","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:09Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:09.606 UTC","process_id":"114","session_id":"670f8c50.72","session_line_num":"4","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"WARNING","sql_state_code":"01000","message":"archiving write-ahead log file \"00000008.history\" failed too many times, will try again later","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:09Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:09.607 UTC","process_id":"114","session_id":"670f8c50.72","session_line_num":"5","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:10Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:10.608 UTC","process_id":"114","session_id":"670f8c50.72","session_line_num":"6","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:11Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:11.609 UTC","process_id":"114","session_id":"670f8c50.72","session_line_num":"7","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"archive command failed with exit code 1","detail":"The failed archive command was: false","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:11Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:11.609 UTC","process_id":"114","session_id":"670f8c50.72","session_line_num":"8","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"WARNING","sql_state_code":"01000","message":"archiving write-ahead log file \"00000008.history\" failed too many times, will try again later","backend_type":"archiver","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:11Z","logger":"postgres","msg":"record","logging_pod":"cluster16-vector-1-full-recovery","record":{"log_time":"2024-10-16 09:50:11.619 UTC","process_id":"102","session_id":"670f8c50.66","session_line_num":"9","session_start_time":"2024-10-16 09:50:08 UTC","transaction_id":"0","error_severity":"LOG","sql_state_code":"00000","message":"database system is shut down","backend_type":"postmaster","query_id":"0"}}
{"level":"info","ts":"2024-10-16T09:50:11Z","logger":"pg_ctl","msg":"waiting for server to shut down....... done","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:11Z","logger":"pg_ctl","msg":"server stopped","pipe":"stdout","logging_pod":"cluster16-vector-1-full-recovery"}
{"level":"info","ts":"2024-10-16T09:50:11Z","msg":"Exited log pipe","fileName":"/controller/log/postgres.csv","logging_pod":"cluster16-vector-1-full-recovery"}
@bo0tzz
Copy link
Member

bo0tzz commented Oct 16, 2024

There's errors in there, but none that are particularly clear about what's going on (as far as I can see). Can you give some more detail about what the Cluster resource does, jobs/pods that are going around, logs from the cnpg operator, etc?

@samip5
Copy link
Author

samip5 commented Oct 16, 2024

I think this is the problem of the name being too long?

@gaocegege gaocegege added the question Further information is requested label Oct 18, 2024
@VoVAllen
Copy link
Member

We have patched it in tensorchord/pgvecto.rs#588. However updating version with immich database is quite complicated. We'll work with immich when we have a new production release ready

@bw210343
Copy link

Encountered this issue today after deleting a cloudpg pod & pvc.

{"level":"info","ts":"2024-11-30T09:31:26.034648069Z","logger":"pg_basebackup","msg":"pg_basebackup: error: backup failed: ERROR:  file name too long for tar format: \"pg_vectors/indexes/000000000000000000000000000000006747a0ed798020150000400100019e7d/segments/2b3bf6d0-682c-4488-bf92-f2ef6c500353\"","pipe":"stderr","logging_pod":"cloudpg-immich-cluster-4-join"}

Thanks for for patching. It looks like the fix is in 0.4.0 but as yet immich only supports < 0.4.0. I tried, it wouldn't start 😢 .

I have database dumps for a full restore so all is good. Just wondering if it would it be possible to fix on 0.3.0 also? Thanks!

@VoVAllen
Copy link
Member

VoVAllen commented Dec 4, 2024

@beyondwatts Are you experiencing problem at restore or backup?

@bw210343
Copy link

bw210343 commented Dec 5, 2024

This was after deleting a pod & pvc in the cluster so I guess restoring

@syntax922
Copy link

Came here after running into the same issue, for the same reason (immich only supporting <0.4.0) and my HA postgres deployment can't scale or recover a secondary node because of this error.

@hagak
Copy link

hagak commented Jan 27, 2025

Seeing the same issue, even tried recovering with 0.4.0 and same error. I suspect because that fix is for going forward?

Is the only way forward to recover to a single pod instance (which works fine) Create a new cluster and do pg_dumps from the old to the new one?

@VoVAllen
Copy link
Member

@hagak You can just drop all the vector index and rebuild them.

@hagak
Copy link

hagak commented Jan 27, 2025

@hagak You can just drop all the vector index and rebuild them.

Any info on this procedure? Do I just drop the index via sql on the single instance that came up and the replicas will then start up? After that just add the vector index back?

@hagak
Copy link

hagak commented Jan 27, 2025

@VoVAllen So I deployed a single CNPG instance from backup and it starts. I then deleted the 2 vector indexes I could find in immich db. Then tried to deploy a replicate instance and same file name too long error.

The two indexes i found are under the "face_search" and "smart_search" tables. Did I miss one?

@whezzel
Copy link

whezzel commented Mar 22, 2025

@hagak, I'm not a db expert and used the help of grok to resolve this issue. Make sure you have backups.

For context, this is the error i was getting when trying to rebuild my cluster:

pg_basebackup: error: backup failed: ERROR: file name too long for tar format: "pg_vectors/indexes/000000000000000000000000000000006797019500ff10200000419800004672/segments/fda89865-9b1c-4838-92c7-0d6e44c1abaf"

i started my cluster with 1 instance, let it rebuild from s3, then i searched for indexes with:

SELECT indexname, indexdef, schemaname
FROM pg_indexes
WHERE indexdef ILIKE '%USING vectors%';

and got the following output:

indexname  |                                                        indexdef                                                        | schemaname
------------+------------------------------------------------------------------------------------------------------------------------+------------
 clip_index | CREATE INDEX clip_index ON public.smart_search USING vectors (embedding vector_cos_ops) WITH (options='[indexing.hnsw]+| public
            | m = 16                                                                                                                +|
            | ef_construction = 300')                                                                                                |
 face_index | CREATE INDEX face_index ON public.face_search USING vectors (embedding vector_cos_ops) WITH (options='[indexing.hnsw] +| public
            | m = 16                                                                                                                +|
            | ef_construction = 300')                                                                                                |
(2 rows)

I dropped the 2 indexes with:

DROP INDEX public.clip_index;
DROP INDEX public.face_index;

i was then able to scale up the number of instances without error. After verifying immich was running as expected, i recreated the indexes with:

CREATE INDEX clip_index ON public.smart_search USING vectors (embedding vector_cos_ops) WITH (options = $$
[indexing.hnsw]
m=16
ef_construction=300
$$);

and

CREATE INDEX face_index ON public.face_search USING vectors (embedding vector_cos_ops) WITH (options = $$
[indexing.hnsw]
m=16
ef_construction=300
$$);

If anyone here, with more knowledge, notices anything wrong about this, please let me know so I can correct it.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
question Further information is requested
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
8 participants
@whezzel @samip5 @gaocegege @VoVAllen @hagak @bo0tzz @syntax922 @bw210343