Replication: Restore fails with permission denied cannot receive: failed to read from stream

TrueNAS Scale ElectricEel-24.10.1

I successfully replicated a dataset from on TrueNAS box (SysA) to another (SysB) (both running the same version of Scale) and then tried to restore back to SysA by using the Restore button for the replication task. This brought up a helper window to generate a PULL replication task which I used. However when I try to run the restore task, if fails with the error in this post’s title. Full debug log below. My restore is going to a different dataset than I originally replicated from, but believe that shouldn’t be a problem. The log indicates that the SSH connection seems to succeed. And also shows I’m using truenas_admin as the user. Not sure where to look to resolve the permission issue, since everything is within the TrueNAS ecosystem…

The only way I’ve found to restore the replicated dataset is to log onto the SysB and create a replication task to replicate back to SysA. I’ve seen the problem on two different datasets.

[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@10.42.118.13] [shell:67] Connecting...
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] starting thread (client mode): 0x681b1690
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Local version/idstring: SSH-2.0-paramiko_2.12.0
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Remote version/idstring: SSH-2.0-OpenSSH_9.2p1 Debian-2+deb12u3
[2025/01/26 15:47:15] INFO     [Thread-186] [zettarepl.paramiko.replication_task__task_13] Connected (version 2.0, client OpenSSH_9.2p1)
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] === Key exchange possibilities ===
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] kex algos: sntrup761x25519-sha512@openssh.com, curve25519-sha256, curve25519-sha256@libssh.org, ecdh-sha2-nistp256, ecdh-sha2-nistp384, ecdh-sha2-nistp521, diffie-hellman-group-exchange-sha256, diffie-hellman-group16-sha512, diffie-hellman-group18-sha512, diffie-hellman-group14-sha256, kex-strict-s-v00@openssh.com
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] server key: rsa-sha2-512, rsa-sha2-256, ecdsa-sha2-nistp256, ssh-ed25519
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] client encrypt: chacha20-poly1305@openssh.com, aes128-ctr, aes192-ctr, aes256-ctr, aes128-gcm@openssh.com, aes256-gcm@openssh.com, aes128-cbc
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] server encrypt: chacha20-poly1305@openssh.com, aes128-ctr, aes192-ctr, aes256-ctr, aes128-gcm@openssh.com, aes256-gcm@openssh.com, aes128-cbc
... 124 more lines ...
    raise self.process_exception
  File "/usr/lib/python3/dist-packages/zettarepl/replication/process_runner.py", line 37, in _wait_process
    self.replication_process.wait()
  File "/usr/lib/python3/dist-packages/zettarepl/transport/ssh.py", line 167, in wait
    stdout = self.async_exec.wait()
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/zettarepl/transport/async_exec_tee.py", line 104, in wait
    raise ExecException(exit_event.returncode, self.output)
zettarepl.transport.interface.ExecException: warning: cannot send 'Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive@auto-2025-01-26_14-15': permission denied
cannot receive: failed to read from stream

1st: sorry to hear you have issues. Is there any data at risk at this stage?

Can you confirm whether the failures are due to trying to restore to a different dataset? (perhaps use a dummy dataset for a test?)

Its seems that you have not managed to get PULL replication working at all?
Maybe that’s where we should start.

There can be sensitivity to recursive settings and child datasets.

Thanks for your response, Captain. Being a newbie to ZFS and TrueNAS is making this quite a learning adventure! I know the replication "wizard’ is trying to help, but it seems the basic options aren’t quite enough and the Advanced screen has so many options that it’s difficult to comprehend what they all do and how they might interact.

I don’t have any real data at risk at the moment (as far as I know!) and I do have my workaround of doing a PUSH from SysB if needed, but it would be nice have things work as intended.

It’s gotten quite late here now, but I will re-read the docs and try an experiment with restoring to the original source dataset (I created one to test with) tomorrow when I’m a little more awake. In the meantime I found the actual log file (vs the excerpts that TN displays) and discovered it had some additional interesting error messages that seem to indicate failing zfs commands. See below. [I apologize for the in-line log length, not sure if there’s some better way to post long logs, and don’t want to leave out important details]

  • Note error from zfs command “missing snapshot argument”
    – Looks like a zfs command failed
    – Search for [shell:67] to see some interesting error messages
>>>>>>>>>>>>>>>>>>>>>>>>>>>>>> /BEGIN 9519.log
 
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] Connecting...
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] starting thread (client mode): 0x681b1690
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Local version/idstring: SSH-2.0-paramiko_2.12.0
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Remote version/idstring: SSH-2.0-OpenSSH_9.2p1 Debian-2+deb12u3
[2025/01/26 15:47:15] INFO     [Thread-186] [zettarepl.paramiko.replication_task__task_13] Connected (version 2.0, client OpenSSH_9.2p1)
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] === Key exchange possibilities ===
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] kex algos: sntrup761x25519-sha512@openssh.com, curve25519-sha256, curve25519-s
ha256@libssh.org, ecdh-sha2-nistp256, ecdh-sha2-nistp384, ecdh-sha2-nistp521, diffie-hellman-group-exchange-sha256, diffie-hellman-group16-sha512, diffie-hellman-group18
-sha512, diffie-hellman-group14-sha256, kex-strict-s-v00@openssh.com
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] server key: rsa-sha2-512, rsa-sha2-256, ecdsa-sha2-nistp256, ssh-ed25519
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] client encrypt: chacha20-poly1305@openssh.com, aes128-ctr, aes192-ctr, aes256-
ctr, aes128-gcm@openssh.com, aes256-gcm@openssh.com, aes128-cbc
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] server encrypt: chacha20-poly1305@openssh.com, aes128-ctr, aes192-ctr, aes256-
ctr, aes128-gcm@openssh.com, aes256-gcm@openssh.com, aes128-cbc
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] client mac: umac-64-etm@openssh.com, umac-128-etm@openssh.com, hmac-sha2-256-e
tm@openssh.com, hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com, umac-64@openssh.com, umac-128@openssh.com, hmac-sha2-256, hmac-sha2-512, hmac-sha1
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] server mac: umac-64-etm@openssh.com, umac-128-etm@openssh.com, hmac-sha2-256-e
tm@openssh.com, hmac-sha2-512-etm@openssh.com, hmac-sha1-etm@openssh.com, umac-64@openssh.com, umac-128@openssh.com, hmac-sha2-256, hmac-sha2-512, hmac-sha1
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] client compress: none
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] server compress: none
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] client lang: <none>
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] server lang: <none>
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] kex follows: False
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] === Key exchange agreements ===
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Kex: curve25519-sha256@libssh.org
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] HostKey: ssh-ed25519
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Cipher: aes128-ctr
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] MAC: hmac-sha2-256
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Compression: none
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] === End of kex handshake ===
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] kex engine KexCurve25519 specified hash_algo <built-in function openssl_sha256
>
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Switch to new keys ...
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Got EXT_INFO: {'server-sig-algs': b'ssh-ed25519,sk-ssh-ed25519@openssh.com,ecd
sa-sha2-nistp256,ecdsa-sha2-nistp384,ecdsa-sha2-nistp521,sk-ecdsa-sha2-nistp256@openssh.com,webauthn-sk-ecdsa-sha2-nistp256@openssh.com,ssh-dss,ssh-rsa,rsa-sha2-256,rsa-
sha2-512', 'publickey-hostbound@openssh.com': b'0'}
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.paramiko.replication_task__task_13] Trying SSH key b'dda806d6352c1ccc835f8e14e5f37cc0'
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] userauth is OK
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Finalizing pubkey algorithm for key of type 'ssh-rsa'
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Our pubkey algorithm list: ['rsa-sha2-512', 'rsa-sha2-256', 'ssh-rsa']
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Server-side algorithm list: ['ssh-ed25519', 'sk-ssh-ed25519@openssh.com', 'ecd
sa-sha2-nistp256', 'ecdsa-sha2-nistp384', 'ecdsa-sha2-nistp521', 'sk-ecdsa-sha2-nistp256@openssh.com', 'webauthn-sk-ecdsa-sha2-nistp256@openssh.com', 'ssh-dss', 'ssh-rsa
', 'rsa-sha2-256', 'rsa-sha2-512']
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Agreed upon 'rsa-sha2-512' pubkey algorithm
[2025/01/26 15:47:15] INFO     [Thread-186] [zettarepl.paramiko.replication_task__task_13] Authentication (publickey) successful!
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4138] Running ['zfs', '
get', '-H', '-p', '-t', 'filesystem,volume', 'type', 'Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive'] with sudo=False
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.paramiko.replication_task__task_13] [chan 0] Max packet in: 32768 bytes
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Received global request "hostkeys-00@openssh.com"
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Rejecting "hostkeys-00@openssh.com" global request from server.
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Debug msg: b'/home/truenas_admin/.ssh/authorized_keys:2: key options: agent-fo
rwarding port-forwarding pty user-rc x11-forwarding'
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 0] Max packet out: 32768 bytes
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Secsh channel 0 opened.
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 0] Sesch channel 0 request ok
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4138] Reading stdout
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 0] EOF received (0)
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 0] EOF sent (0)
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4138] Waiting for exit 
status
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4138] Success: 'Pool_00
/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive\ttype\tfilesystem\t-\n'
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4143] Running ['zfs', 'get', '-H', '-p', '-t', 'filesystem,v
olume', 'type', 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore']
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4143] Success: 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNa
sRep_PveBackup_Restore\ttype\tfilesystem\t-\n'
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4144] Running ['zfs', '
list', '-t', 'filesystem,volume', '-H', '-o', 'name', '-s', 'name', '-r', 'Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive'] with sudo=False
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.paramiko.replication_task__task_13] [chan 1] Max packet in: 32768 bytes
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 1] Max packet out: 32768 bytes
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Secsh channel 1 opened.
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 1] Sesch channel 1 request ok
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4144] Reading stdout
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 1] EOF received (1)
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4144] Waiting for exit 
status
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 1] EOF sent (1)
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4144] Success: 'Pool_00
/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive\n'
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4145] Running ['zfs', '
list', '-t', 'snapshot', '-H', '-o', 'name', '-s', 'name', '-r', 'Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive'] with sudo=False
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.paramiko.replication_task__task_13] [chan 2] Max packet in: 32768 bytes
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 2] Max packet out: 32768 bytes
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Secsh channel 2 opened.
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 2] Sesch channel 2 request ok
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4145] Reading stdout
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 2] EOF received (2)
[2025/01/26 15:47:15] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 2] EOF sent (2)
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4145] Waiting for exit 
status
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4145] Success: 'Pool_00
/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive@auto-2025-01-26_14-15\n'
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4147] Running ['zfs', '
list', '-t', 'filesystem,volume', '-H', '-o', 'encryption,name', '-s', 'name', '-r', 'Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive'] with sudo=False
[2025/01/26 15:47:15] DEBUG    [replication_task__task_13] [zettarepl.paramiko.replication_task__task_13] [chan 3] Max packet in: 32768 bytes
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 3] Max packet out: 32768 bytes
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Secsh channel 3 opened.
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 3] Sesch channel 3 request ok
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4147] Reading stdout
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 3] EOF received (3)
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 3] EOF sent (3)
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4147] Waiting for exit 
status
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4147] Success: 'aes-256
-gcm\tPool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive\n'
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4149] Running ['zfs', '
get', '-H', '-p', '-t', 'filesystem,volume', 'sharesmb,mountpoint,sharenfs', 'Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive'] with sudo=False
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.paramiko.replication_task__task_13] [chan 4] Max packet in: 32768 bytes
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 4] Max packet out: 32768 bytes
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Secsh channel 4 opened.
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 4] Sesch channel 4 request ok
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4149] Reading stdout
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 4] EOF received (4)
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 4] EOF sent (4)
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4149] Waiting for exit 
status
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4149] Success: 'Pool_00
/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive\tsharesmb\toff\tdefault\nPool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive\tmountpoint\t/mnt/Pool_00/_Dset_TestRepArch
iveNoEnc/Dset_TestRepArchive\tdefault\nPool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive\tsharenfs\toff\tdefault\n'
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4150] Running ['zfs', 'list', '-t', 'filesystem,volume', '-H
', '-o', 'readonly,receive_resume_token,name', '-s', 'name', '-r', 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore']
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4150] Success: 'off\t-\tPool_01_Test/Dset_TestRestore_01/Dse
t_TestNasRep_PveBackup_Restore\n'
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4151] Running ['zfs', 'list', '-t', 'snapshot', '-H', '-o', 
'name', '-s', 'name', '-r', 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore']
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4151] Success: ''
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4152] Running ['zfs', 'get', '-H', '-p', '-t', 'filesystem,v
olume', 'encryption,encryptionroot', 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore']
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4152] Success: 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNa
sRep_PveBackup_Restore\tencryption\toff\tdefault\nPool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore\tencryptionroot\t-\t-\n'
[2025/01/26 15:47:16] INFO     [replication_task__task_13] [zettarepl.replication.pre_retention] Pre-retention destroying snapshots: []
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4153] Running ['zfs', 'get', '-H', '-p', '-t', 'filesystem,v
olume', 'type,mounted,mountpoint,referenced,snapdir,used', 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore']
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4153] Success: 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNa
sRep_PveBackup_Restore\ttype\tfilesystem\t-\nPool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore\tmounted\tno\t-\nPool_01_Test/Dset_TestRestore_01/Dset_Te
stNasRep_PveBackup_Restore\tmountpoint\t/mnt/Pool_0....ol_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore\treferenced\t98304\t-\nPool_01_Test/Dset_TestRest
ore_01/Dset_TestNasRep_PveBackup_Restore\tsnapdir\thidden\tdefault\nPool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore\tused\t98304\t-\n'
[2025/01/26 15:47:16] INFO     [replication_task__task_13] [zettarepl.replication.run] For replication task 'task_13': doing pull from 'Pool_00/_Dset_TestRepArchiveNoEnc
/Dset_TestRepArchive' to 'Pool_01_Test/Dset_TestRestore_01/Dset_TestNasRep_PveBackup_Restore' of snapshot='auto-2025-01-26_14-15' incremental_base=None include_intermedi
ate=False receive_resume_token=None encryption=False
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4155] Running ['zfs', 'umount', 'Pool_01_Test/Dset_TestResto
re_01/Dset_TestNasRep_PveBackup_Restore']
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4155] Error 1: "cannot unmount 'Pool_01_Test/Dset_TestRestor
e_01/Dset_TestNasRep_PveBackup_Restore': not currently mounted\n"
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4157] Running ['zfs', '
send', '-V'] with sudo=False
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.paramiko.replication_task__task_13] [chan 5] Max packet in: 32768 bytes
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 5] Max packet out: 32768 bytes
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] Secsh channel 5 opened.
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 5] Sesch channel 5 request ok
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4157] Reading stdout
[2025/01/26 15:47:16] DEBUG    [Thread-186] [zettarepl.paramiko.replication_task__task_13] [chan 5] EOF received (5)
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4157] Waiting for exit 
status
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.base_ssh] [ssh:truenas_admin@xxx.xxx.xxx.13] [shell:67] [async_exec:4157] Error 2: 'missing
 snapshot argument\nusage:\n\tsend [-DLPbcehnpsVvw] [-i|-I snapshot]\n\t     [-R [-X dataset[,dataset]...]]     <snapshot>\n\tsend [-DnVvPLecw] [-i snapshot|bookmark] <f
ilesystem|volume|snapshot>\n\tsend [-DnPpVvLec] [-i bookmark|snapshot] --redact <bookmark> <snapshot>\n\tsend [-nVvPe] -t <receive_resume_token>\n\tsend [-PnVv] --saved 
filesystem\n\nFor the property list, run: zfs set|get\n\nFor the delegated permission list, run: zfs allow|unallow\n\nFor further help on a command or topic, run: zfs he
lp [<topic>]\n'
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.paramiko.replication_task__task_13] [chan 5] EOF sent (5)
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13] [zettarepl.transport.local] [shell:1] [async_exec:4160] Running Pipe((['ssh', '-i', '/tmp/tmp3kqr_kxo', '-o', 
'UserKnownHostsFile=/tmp/tmp5ddxs51c', '-o', 'StrictHostKeyChecking=yes', '-o', 'BatchMode=yes', '-o', 'ConnectTimeout=10', '-p22', 'truenas_admin@xxx.xxx.xxx.13', 'sh -c 
\'PATH=$PATH:/usr/local/sbin:/usr/sbin:/sbin sh -c \'"\'"\'(zfs send -V -p -w -L -c Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive@auto-2025-01-26_14-15 & PID=$!;
 echo "zettarepl: zfs send PID is $PID" 1>&2; wait $PID)\'"\'"\'\''], ['zfs', 'recv', '-s', '-F', '-x', 'sharesmb', '-x', 'mountpoint', '-x', 'sharenfs', 'Pool_01_Test/D
set_TestRestore_01/Dset_TestNasRep_PveBackup_Restore']))
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13.async_exec_tee.wait] [zettarepl.transport.local] [shell:1] [async_exec:4160] Error 1: None
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13.process] [zettarepl.transport.local] [shell:1] [async_exec:4159] Error 1: "warning: cannot send 'Pool_00/_Dset_
TestRepArchiveNoEnc/Dset_TestRepArchive@auto-2025-01-26_14-15': permission denied\ncannot receive: failed to read from stream\n"
[2025/01/26 15:47:16] DEBUG    [replication_task__task_13.monitor] [zettarepl.transport.local] [shell:1] [async_exec:4160] Stopping
[2025/01/26 15:47:16] ERROR    [replication_task__task_13] [zettarepl.replication.run] For task 'task_13' unhandled replication error ExecException(1, "warning: cannot s
end 'Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive@auto-2025-01-26_14-15': permission denied\ncannot receive: failed to read from stream\n")
Traceback (most recent call last):
  File "/usr/lib/python3/dist-packages/zettarepl/replication/run.py", line 181, in run_replication_tasks
    retry_contains_partially_complete_state(
  File "/usr/lib/python3/dist-packages/zettarepl/replication/partially_complete_state.py", line 16, in retry_contains_partially_complete_state
    return func()
           ^^^^^^
  File "/usr/lib/python3/dist-packages/zettarepl/replication/run.py", line 182, in <lambda>
    lambda: run_replication_task_part(replication_task, source_dataset, src_context, dst_context,
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/zettarepl/replication/run.py", line 278, in run_replication_task_part
    run_replication_steps(step_templates, observer)
  File "/usr/lib/python3/dist-packages/zettarepl/replication/run.py", line 672, in run_replication_steps
    replicate_snapshots(step_template, incremental_base, snapshots, include_intermediate, encryption, observer)
  File "/usr/lib/python3/dist-packages/zettarepl/replication/run.py", line 713, in replicate_snapshots
    run_replication_step(step, observer)
  File "/usr/lib/python3/dist-packages/zettarepl/replication/run.py", line 793, in run_replication_step
    ReplicationProcessRunner(process, monitor).run()
  File "/usr/lib/python3/dist-packages/zettarepl/replication/process_runner.py", line 33, in run
    raise self.process_exception
  File "/usr/lib/python3/dist-packages/zettarepl/replication/process_runner.py", line 37, in _wait_process
    self.replication_process.wait()
  File "/usr/lib/python3/dist-packages/zettarepl/transport/ssh.py", line 167, in wait
    stdout = self.async_exec.wait()
             ^^^^^^^^^^^^^^^^^^^^^^
  File "/usr/lib/python3/dist-packages/zettarepl/transport/async_exec_tee.py", line 104, in wait
    raise ExecException(exit_event.returncode, self.output)
zettarepl.transport.interface.ExecException: warning: cannot send 'Pool_00/_Dset_TestRepArchiveNoEnc/Dset_TestRepArchive@auto-2025-01-26_14-15': permission denied
cannot receive: failed to read from stream


<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< /END 9519.log

You might want to check is sudo privileges are needed…
zfs commands need that.

1 Like

Bingo! Thanks for that. Believe it or not, I did read through the docs, and I think they are quite good. But while they pretty much cover everything one CAN do, it’s not always so easy to figure out what one SHOULD do. And there’s so much to absorb and at some point I feel some experimentation is needed to fully grok the process.

It turns out the auto-generated restore task did NOT have the “sudo for zfs” box checked, even though the original replication task did. I can see leaving the box unchecked by default for security reasons, but it would have been nice to get a warning message.

Then the “failed to read from stream” error message the restore task generated led me to believe it was some sort of SSH stream problem, and when I finally found the zfs errors in the log, they looked more like a problem with bad or missing function arguments than a permissions issue. So I will live and learn.

Anyway, after checking the sudo box on in the restore task config and doing a bit of dancing with the getting the encryption set correctly on the target (Oh target needs to be encrypted to restore an encrypted source. Oops, can’t encrypt an existing dataset. Ok re-create it. Oops that will delete the referencing restore task. Ok create a dummy dataset and move the reference to a dummy temporarily. Got the target recreated as encrypted, restore the original task reference to it, Run again… “Can’t restore to an encrypted dataset that is it’s own encryption root, encrypt the parent” … Move the task reference to dummy, delete the target AND it’s parent. Recreate both as encrypted. Restore the task target reference. Run again.) And it WORKS!!!
And look at that, the restored target dataset automagically changed it’s encryption key from the passphrase I gave it to the one that the source used.

I kind of envisioned that using a NAS would be about as simple as using an external USB drive with maybe the wrinkle of needing to type in an IP address. I now see I’m going to be much more thoroughly entertained.

Nonetheless, I do appreciate your help Captain, and I hope that my other replication posts can be resolved more easily.