SFTP to TrueNAS Core 13.0-U6.1 - unable to open file backup_label.zst

[StomproLARL2023]

Please provide the following information when submitting an issue (feature requests or general comments can skip this):

1. pgBackRest version: 2.51

2. PostgreSQL version: 13.12-1.pgdg120+1

3. Operating system/version - if you have more than one server (for example, a database server, a repository host server, one or more standbys), please specify each: Debian 12.2 - Trying to backup to a SFTP Repo on a
   TrueNAS-13.0-U6.1 Core machine, FreeBSD 13.1-Release-p9

4. Did you install pgBackRest from source or from a package? Debian Package

5. Please attach the following as applicable:

2024-03-29 14:06:38.851 P00 DEBUG: storage/storage::storageNewWrite: (this: {type: sftp, path: /mnt/tank/pgbackrest/storage/egdb3/main, write: true}, fileExp: {"REPO:BACKUP/20240329-140410F/pg_data/backup_label.zst"}, param.modeFile: 0000, param.modePath: 0000, param.user: null, param.group: null, param.timeModified: 0, param.noCreatePath: false, param.noSyncFile: false, param.noSyncPath: false, param.noAtomic: false, param.noTruncate: false, param.compressible: true)
2024-03-29 14:06:38.851 P00 DEBUG: storage/storage::storageNewWrite: => {type: sftp, name: /mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-140410F/pg_data/backup_label.zst, modeFile: 0640, modePath: 0750, createPath: true, syncFile: true, syncPath: false, atomic: true}
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: hash})
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: zst-cmp})
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: cipher-blk})
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: hash})
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: size})
2024-03-29 14:06:38.851 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:06:38.851 P00 DEBUG: storage/storage::storagePut: (file: {type: sftp, name: /mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-140410F/pg_data/backup_label.zst, modeFile: 0640, modePath: 0750, createPath: true, syncFile: true, syncPath: false, atomic: true}, buffer: {used: 261, size: 261})
2024-03-29 14:06:38.860 P00 DEBUG: command/exit::exitSafe: (result: 0, error: true, signalType: 0)
ERROR: [041]: unable to open file '/mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-140410F/pg_data/backup_label.zst' for write: libssh2 error [-43]
--------------------------------------------------------------------
If SUBMITTING AN ISSUE please provide the following information:

   version: 2.51
   command: backup
   options: --archive-timeout=300 --compress-type=zst --exec-id=2922792-15221063 --log-level-console=debug --pg1-path=/var/lib/postgresql/13/main --process-max=8 --repo=4 --repo1-bundle --repo4-bundle --repo4-cipher-pass=<redacted> --repo4-cipher-type=aes-256-cbc --repo1-path=/var/lib/pgbackrest --repo4-path=/mnt/tank/pgbackrest/storage/egdb3/main --repo1-retention-full=5 --repo4-retention-full=12 --repo4-sftp-host=192.168.46.39 --repo4-sftp-host-key-hash-type=sha256 --repo4-sftp-host-user=pgbackrest --repo4-sftp-private-key-file=/var/lib/postgresql/.ssh/id_ed25519_sftp --repo4-sftp-public-key-file=/var/lib/postgresql/.ssh/id_ed25519_sftp.pub --repo4-type=sftp --no-resume --stanza=main --start-fast --type=full

   stack trace:
   storage/sftp/storage.c:storageSftpEvalLibSsh2Error:363:(test build required for parameters)
       ... function(s) omitted ...
   storage/sftp/write.c:storageWriteSftpOpen:(trace log level required for parameters)
   common/io/write.c:ioWriteOpen:(trace log level required for parameters)
   storage/storage.c:storagePut:(file: {type: sftp, name: /mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-140410F/pg_data/backup_label.zst, modeFile: 0640, modePath: 0750, createPath: true, syncFile: true, syncPath: false, atomic: true}, buffer: {used: 261, size: 261})
   command/backup/backup.c:backupFilePut:(backupData: {BackupData}, manifest: {Manifest}, name: {"backup_label"}, timestamp: 1711739198, content: {"START WAL LOCATION: 96/E4000028 (file 0000000100000096000000E4)
   CHECKPOINT LOCATION: 96/E4016760
   BACKUP METHOD: streamed
   BACKUP FROM: master
   START TIME: 2024-03-29 14:04:11 CDT
   LABEL: pgBackRest backup started at 2024-03-29 14:04:10.451302-05
   START TIMELINE: 1
   "})
   command/backup/backup.c:backupStop:(backupData: {BackupData}, manifest: {Manifest})
   command/backup/backup.c:cmdBackup:(void)
   main.c:main:(debug log level required for parameters)
   --------------------------------------------------------------------

- log file in `/var/log/pgbackrest` for the commands run (e.g. `/var/log/pgbackrest/mystanza_backup.log`)

-------------------PROCESS START-------------------
2024-03-29 13:54:02.809 P00 INFO: backup command begin 2.51: --archive-timeout=300 --compress-type=zst --exec-id=2913581-b78fd95c --log-level-console=info --pg1-path=/var/lib/postgresql/13/main --process-max=8 --repo=4 --repo1-bundle --repo4-bundle --repo4-cipher-pass= --repo4-cipher-type=aes-256-cbc --repo1-path=/var/lib/pgbackrest --repo4-path=/mnt/tank/pgbackrest/storage/egdb3/main --repo1-retention-full=5 --repo4-retention-full=12 --repo4-sftp-host=192.168.46.39 --repo4-sftp-host-key-hash-type=sha256 --repo4-sftp-host-user=pgbackrest --repo4-sftp-private-key-file=/var/lib/postgresql/.ssh/id_ed25519_sftp --repo4-sftp-public-key-file=/var/lib/postgresql/.ssh/id_ed25519_sftp.pub --repo4-type=sftp --no-resume --stanza=main --start-fast --type=full
2024-03-29 13:54:03.655 P00 INFO: execute non-exclusive backup start: backup begins after the requested immediate checkpoint completes
2024-03-29 13:54:04.657 P00 INFO: backup start archive = 0000000100000096000000E0, lsn = 96/E0000028
2024-03-29 13:54:04.657 P00 INFO: check archive for prior segment 0000000100000096000000DF
2024-03-29 13:54:05.204 P00 INFO: backup '20240329-134836F' cannot be resumed: resume is disabled
2024-03-29 13:56:46.428 P00 INFO: execute non-exclusive backup stop and wait for all WAL segments to archive
2024-03-29 13:56:46.628 P00 INFO: backup stop archive = 0000000100000096000000E0, lsn = 96/E0760C78
2024-03-29 13:56:46.637 P00 ERROR: [041]: unable to open file '/mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-135403F/pg_data/backup_label.zst' for write: libssh2 error [-43]
2024-03-29 13:56:46.637 P00 INFO: backup command end: aborted with exception [041]

-------------------PROCESS START-------------------
2024-03-29 13:57:17.636 P00 INFO: backup command begin 2.51: --archive-timeout=300 --compress-type=zst --exec-id=2916269-f76349f5 --log-level-console=debug --pg1-path=/var/lib/postgresql/13/main --process-max=8 --repo=4 --repo1-bundle --repo4-bundle --repo4-cipher-pass= --repo4-cipher-type=aes-256-cbc --repo1-path=/var/lib/pgbackrest --repo4-path=/mnt/tank/pgbackrest/storage/egdb3/main --repo1-retention-full=5 --repo4-retention-full=12 --repo4-sftp-host=192.168.46.39 --repo4-sftp-host-key-hash-type=sha256 --repo4-sftp-host-user=pgbackrest --repo4-sftp-private-key-file=/var/lib/postgresql/.ssh/id_ed25519_sftp --repo4-sftp-public-key-file=/var/lib/postgresql/.ssh/id_ed25519_sftp.pub --repo4-type=sftp --no-resume --stanza=main --start-fast --type=full
2024-03-29 13:57:18.485 P00 INFO: execute non-exclusive backup start: backup begins after the requested immediate checkpoint completes
2024-03-29 13:57:19.487 P00 INFO: backup start archive = 0000000100000096000000E2, lsn = 96/E2000028
2024-03-29 13:57:19.487 P00 INFO: check archive for prior segment 0000000100000096000000E1
2024-03-29 13:57:20.204 P00 INFO: backup '20240329-135403F' cannot be resumed: partially deleted by prior resume or invalid
2024-03-29 13:59:55.760 P00 INFO: execute non-exclusive backup stop and wait for all WAL segments to archive
2024-03-29 13:59:55.961 P00 INFO: backup stop archive = 0000000100000096000000E2, lsn = 96/E23256C8
2024-03-29 13:59:55.969 P00 ERROR: [041]: unable to open file '/mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-135718F/pg_data/backup_label.zst' for write: libssh2 error [-43]
2024-03-29 13:59:55.969 P00 INFO: backup command end: aborted with exception [041]

-------------------PROCESS START-------------------
2024-03-29 14:04:09.403 P00 INFO: backup command begin 2.51: --archive-timeout=300 --compress-type=zst --exec-id=2922792-15221063 --log-level-console=debug --pg1-path=/var/lib/postgresql/13/main --process-max=8 --repo=4 --repo1-bundle --repo4-bundle --repo4-cipher-pass= --repo4-cipher-type=aes-256-cbc --repo1-path=/var/lib/pgbackrest --repo4-path=/mnt/tank/pgbackrest/storage/egdb3/main --repo1-retention-full=5 --repo4-retention-full=12 --repo4-sftp-host=192.168.46.39 --repo4-sftp-host-key-hash-type=sha256 --repo4-sftp-host-user=pgbackrest --repo4-sftp-private-key-file=/var/lib/postgresql/.ssh/id_ed25519_sftp --repo4-sftp-public-key-file=/var/lib/postgresql/.ssh/id_ed25519_sftp.pub --repo4-type=sftp --no-resume --stanza=main --start-fast --type=full
2024-03-29 14:04:10.250 P00 INFO: execute non-exclusive backup start: backup begins after the requested immediate checkpoint completes
2024-03-29 14:04:11.252 P00 INFO: backup start archive = 0000000100000096000000E4, lsn = 96/E4000028
2024-03-29 14:04:11.252 P00 INFO: check archive for prior segment 0000000100000096000000E3
2024-03-29 14:04:12.204 P00 INFO: backup '20240329-135718F' cannot be resumed: partially deleted by prior resume or invalid
2024-03-29 14:06:38.650 P00 INFO: execute non-exclusive backup stop and wait for all WAL segments to archive
2024-03-29 14:06:38.850 P00 INFO: backup stop archive = 0000000100000096000000E5, lsn = 96/E53C86B0
2024-03-29 14:06:38.860 P00 ERROR: [041]: unable to open file '/mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-140410F/pg_data/backup_label.zst' for write: libssh2 error [-43]
2024-03-29 14:06:38.860 P00 INFO: backup command end: aborted with exception [041]

7. Describe the issue:

Trying to backup to sftp repo on a TrueNAS-13.0-U6.1 Core machine, FreeBSD 13.1-Release-p9. OpenSSH_8.8p1, OpenSSL 1.1.1o-freebsd 3 may 2022

Just upgraded to 2.51 from 2.48 after seeing the fixes related to RSYNC.net sftp backups since I was running into the file deletion errors.

#2219

Got past those with version 2.51, but now I'm getting an error about not being able to open the backup_label.zst for writing.

ERROR: [041]: unable to open file '/mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-143216F/pg_data/backup_label.zst' for write: libssh2 error [-43]

The backup seems complete copying all the files, then I get:
2024-03-29 14:39:58.567 P00 DEBUG: command/backup/backup::backupFilePut: (backupData: {BackupData}, manifest: {Manifest}, name: {"backup_label"}, timestamp: 1711741198, content: {"START WAL LOCATION: 96/ED000028 (file 0000000100000096000000ED)
CHECKPOINT LOCATION: 96/ED000060
BACKUP METHOD: streamed
BACKUP FROM: master
START TIME: 2024-03-29 14:37:10 CDT
LABEL: pgBackRest backup started at 2024-03-29 14:37:10.114533-05
START TIMELINE: 1
"})
2024-03-29 14:39:58.567 P00 DEBUG: storage/storage::storageNewWrite: (this: {type: sftp, path: /mnt/tank/pgbackrest/storage/egdb3/main, write: true}, fileExp: {"REPO:BACKUP/20240329-143709F/pg_data/backup_label.zst"}, param.modeFile: 0000, param.modePath: 0000, param.user: null, param.group: null, param.timeModified: 0, param.noCreatePath: false, param.noSyncFile: false, param.noSyncPath: false, param.noAtomic: false, param.noTruncate: false, param.compressible: true)
2024-03-29 14:39:58.567 P00 DEBUG: storage/storage::storageNewWrite: => {type: sftp, name: /mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-143709F/pg_data/backup_label.zst, modeFile: 0640, modePath: 0750, createPath: true, syncFile: true, syncPath: false, atomic: true}
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: hash})
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: zst-cmp})
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: cipher-blk})
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: hash})
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: (this: {inputSame: false, done: false}, filter: {type: size})
2024-03-29 14:39:58.567 P00 DEBUG: common/io/filter/group::ioFilterGroupAdd: => {inputSame: false, done: false}
2024-03-29 14:39:58.567 P00 DEBUG: storage/storage::storagePut: (file: {type: sftp, name: /mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-143709F/pg_data/backup_label.zst, modeFile: 0640, modePath: 0750, createPath: true, syncFile: true, syncPath: false, atomic: true}, buffer: {used: 261, size: 261})
2024-03-29 14:39:58.576 P00 DEBUG: command/exit::exitSafe: (result: 0, error: true, signalType: 0)
ERROR: [041]: unable to open file '/mnt/tank/pgbackrest/storage/egdb3/main/backup/main/20240329-143709F/pg_data/backup_label.zst' for write: libssh2 error [-43]

[jreidthompson]

The ERROR: [041] is a pgbackrest file open error that appears to be being triggered by an error in the libssh2 libraries -43 (defined as LIBSSH2_ERROR_SOCKET_RECV) when libssh2 is attempting to communicate with the sftp server.

Can you advise which libssh2 library version you are using(looking online, it looks like deb12 uses v1.10)?

Checking the libssh2 code, LIBSSH2_ERROR_SOCKET_RECV is only returned in a few places, but doesn't output any messages in several of these unless compiled with LIBSSH2DEBUG.

Is this using the same repo that had deletion issues with v2.48, or on a newly created repo?
(i.e. does the error occur with a new repo:
pgbackrest stanza-create...
pgbackrest check...
pgbackrest backup...)
Does the error occur with a different or no compression and smaller value for process-max?

[StomproLARL2023]

Info about the libssh2 library version.
libssh2-1:amd64 1.10.0-3+b1

Yes same repo as the v2.48. I'll try a new repo and report back. As well as the other options you mentioned.

[StomproLARL2023]

Deleted the stanza on the sftp repo and re-created it.

Received a different error
ERROR: [053]: unable to list file info for path '/mnt/tank/pgbackrest/storage/egdb3/main/archive/main/13-1/0000000100000097': libssh2 error [-43]
2024-04-01 16:10:49.473 P00 INFO: backup command end: aborted with exception [053]

Tried --compress-type=none and --process-max=1 and backup failed with this error.

2024-04-01 16:21:53.801 P01 DETAIL: backup file /var/lib/postgresql/13/main/base/4601745/5927508.1 (976.2MB, 32.12%) checksum 7d3dc9307ef4db251736b32e5e24ee74ca9034b6
ERROR: [039]: client state is 'data-get' but expected 'idle'
2024-04-01 16:21:53.902 P00 DETAIL: statistics: {"socket.client":{"total":2},"socket.session":{"total":2}}
2024-04-01 16:21:53.902 P00 INFO: backup command end: aborted with exception [039]
WARN: unable to wait on child process: [10] No child processes

Tried "--compress-type=none --process-max=4"

Maybe it is looking for the non compressed wal archive... I'll give it another try tomorrow.

[StomproLARL2023]

I'll try and get back to this later once I setup a test system. I'll just plan on not using Truenas as a repo for now.