SOLVED Troubleshooting rysnc backup failed (scheduled rsync push from FreeNAS to Raspberry pi)

dj_jazzn

Dabbler
Joined
Apr 14, 2014
Messages
31
So my well intentioned self thought I could solve this problem on my own and post the solution for anyone else who may have the same issue. However, after many attempts, I have not resolved this issue, and I was hoping the greater FreeNAS community could provide some input.

Here's the Issue:
Around the time I updated to 11.3-U1, my scheduled rsync tasks failed. Prior to updating from 11.2-U7, rsync worked flawlessly. I would role back to my previous version, except this time I upgraded my pool and rolling back is no longer an option. Normally, I wait a period of time before upgrading my pool. Don't ask me why I didn't wait this time...lesson learned. I can say for certain if this is related to the 11.3-U1 update, but this is when I noticed it. Around the same time, I noticed my backup drive had ran out of disk space. I freed up space on the backup system, but could not restore the rsync functionality. What puzzles me is that through the terminal, the backupuser is able to perform rysnc command and successfully push files from my FreeNAS to the raspberry pi.

Below are all the technical details that I could scrape together describing the issue. Hoping someone has seen this before and knows of a solution. Any input would be greatly appreciated.

The Details:
Intended rsync Functionality: In the Freenas GUI, schedule rsync task to run perodically and backup datasets from my FreeNAS Box to a raspberry pi over my internal home network.

Here is what happens when clicking the rsync "RUN NOW" button through the FreeNAS task GUI (or when run as a scheduled task):

Error 1
rsync error 1.PNG


Code:
[EFAULT] rsync command returned 12. Check logs for further information.

More info...
Error: Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/middlewared/job.py", line 349, in run
    await self.future
  File "/usr/local/lib/python3.7/site-packages/middlewared/job.py", line 388, in __run_body
    rv = await self.middleware.run_in_thread(self.method, *([self] + args))
  File "/usr/local/lib/python3.7/site-packages/middlewared/utils/run_in_thread.py", line 10, in run_in_thread
    return await self.loop.run_in_executor(self.run_in_thread_executor, functools.partial(method, *args, **kwargs))
  File "/usr/local/lib/python3.7/site-packages/middlewared/utils/io_thread_pool_executor.py", line 25, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/middlewared/schema.py", line 965, in nf
    return f(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/middlewared/plugins/rsync.py", line 609, in run
    f'rsync command returned {cp.returncode}. Check logs for further information.'
middlewared.service_exception.CallError: [EFAULT] rsync command returned 12. Check logs for further information.

Download Logs...
Could not create directory '/mnt/{Pool}/home/{rsync user}/.ssh'.
No ECDSA host key is known for {backup server ip address} and you have requested strict checking.
Host key verification failed.
rsync: connection unexpectedly closed (0 bytes received so far) [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(226) [sender=3.1.3]


I don't know why the message Could not create directory '/mnt/{Pool}/home/{rsync user}/.ssh is displayed. This directory already exists.
Likewise, I don't know why the message No ECDSA host key is known for {backup server ip address} is displayed. An ECDSA entry is present in the known_hosts file on the FreeNAS backupuser .ssh folder.

According to the freeBSD rsync manual pages error in rsync protocol data stream (code 12) is an "Error in rsync protocol data stream". Not sure what that means.


Error 2
rsync error 2.png


Code:
[EFAULT] rsync command returned 73. Check logs for further information.
remove_circle_outline

More info...
Error: Traceback (most recent call last):
  File "/usr/local/lib/python3.7/site-packages/middlewared/job.py", line 349, in run
    await self.future
  File "/usr/local/lib/python3.7/site-packages/middlewared/job.py", line 388, in __run_body
    rv = await self.middleware.run_in_thread(self.method, *([self] + args))
  File "/usr/local/lib/python3.7/site-packages/middlewared/utils/run_in_thread.py", line 10, in run_in_thread
    return await self.loop.run_in_executor(self.run_in_thread_executor, functools.partial(method, *args, **kwargs))
  File "/usr/local/lib/python3.7/site-packages/middlewared/utils/io_thread_pool_executor.py", line 25, in run
    result = self.fn(*self.args, **self.kwargs)
  File "/usr/local/lib/python3.7/site-packages/middlewared/schema.py", line 965, in nf
    return f(*args, **kwargs)
  File "/usr/local/lib/python3.7/site-packages/middlewared/plugins/rsync.py", line 609, in run
    f'rsync command returned {cp.returncode}. Check logs for further information.'
middlewared.service_exception.CallError: [EFAULT] rsync command returned 73. Check logs for further information.

Download Logs...
lockf: cannot open /mnt/{Pool}/{dataset}: Permission denied


I don't understand why this message is displayed too. The backupuser on FreeNAS has read privileges for all the dataset being backed up. I verified this by navigating to the data set in a terminal where backupuser can freely navigate the folders and read file contents to the terminal eg. cat filename

I found nothing in the freeBSD rsync manual pages for rsync command returned 73.

One other observation. After the update all of my terminal prompts seamed to change. I use to get a host name and file path on the terminal prompt. Now only the host name shows and I have to determine what folder I'm in using the pwd command.

Things I Have Tried to Resolve the Issue:
  • Confirmed that rsync functions through terminal commands:
    • rsync -r --del /mnt/{pool}/{dataset} backupuser@{rasberry pi IP address}:/mnt/usb_drive
    • Under this scenario, ssh works, rsync works, files are pushed to the pi and files are deleted on the pi.
  • Create a new set of test users on each system with new public/private keys, setup a new rsync task in FreeNAS GUI with the new user.
    • Result: Same outcome as described in this post: (GUI rsync fails, terminal rsync command works)
  • Dabbled with ssh-agent for the test user a bit, but put this off until after resolving the primary concerns
  • Checked permissions on backupuser .ssh files for both machines
    • .ssh folder set to: drwx------
    • id_rsa file set to: -rw-------
    • id_rsa.pub file set to: -rw-r--r--
    • authorized_keys file set to: -rw-------
    • known_hosts file set to: -rw-------
  • If I type ssh-copy-id ~/.ssh/id_rsa.pub backupuser@{rasberry pi IP address
    • I get the following message: Could not open a connection to your authentication agent. no keys found
  • Modified sshd_config on the raspberry pi to accept key pair ssh logins only :
    • Code:
      ChallengeResponseAuthentication no
      Password Authentication no
      UsePAM no
  • Followed forum recommendation here.
    • ssh-keyscan -t ecdsa {rasberry pi IP address} >> /mnt/{pool}/home/backupuser/.ssh/known_hosts
    • This eliminated all but one of the first error rsync command returned 12. But was followed with a permission error on the data set. When I checked and resolved the user permissions through ACL, the first error returned rsync command returned 12

OS: FreeNAS 11.3-U1 Stable
Internals: Intel Xenon E3-1231v3 | Supermicro X10SL7-F | 4X8GB Crucial 1600Mhz ECC CT2KIT102472BD160B
Boot: 1X16GB innodisk SATADOM-MV 3ME4
Storage Pool: 6X4TB WD40EFRX - ZFS2
Case: Fractal Define R4 | Seasonic FOCUS GX-650 | 2X Noctua NF-A14 Industrial PPC-3000 PWM, 2X Cougar Vortex PWM CF-V12HP
UPS: CyberPower CP1350PFCLCD
Static IP assigned

On the FreeNAS - Defined a dedicated user for backup tasks: backupuser:
  • Sudo not permitted
  • member of Primary Group: backupuser
  • member of Auxiliary Groups: owner groups of each datasets to be backed up, and wheel
  • backupuser Home Directory permissions at drwx------
  • backupuser .ssh folder permissions at drwx------
  • ~/.ssh folder setup with id_rsa (no passphrase), id_rsa.pub, authorized_keys, and known_hosts
  • public key copied into freeNAS user GUI
  • the home folders for all non-builtin users reside in a dataset called {home} on the main pool

Setup rsync tasks in FreeNAS GUI:
Code:
Path: {path to data set for backup}
User: backupuser
remote host: {raspberry pi ip address}
Rsync mode: SSH
Remote SSH Port: 22
Remote Path: {path to remote data set backup location}
Validate Remote Path: enabled
Direction: Push
Short Description: "Backup of {dataset}"
Schedule the Rsync Task: {timing depends on the dataset}
Recursive: Enabled
Times: Enabled
Compress: Enabled
Archive: Not Enabled
Delete: Enabled
Quiet: Not Enabled
Preserve permissions: Enabled
Preserve extended attributes: Enabled
Delay Updates: Enabled
Extra options: "--ignore-errors"
Enabled: Enabled

OS: Raspbian GNU/Linux 9 (stretch)
Static IP assigned
Western Digital My Book 6TB USB drive mounted during boot with entry in /etc/fstab

On the Raspberry PI - Defined a dedicated user for backup tasks: backupuser:
  • Sudo not permitted
  • member of Primary Group: backupuser
  • backupuser Home Directory permissions at drwx------
  • backupuser .ssh folder permissions at drwx------
  • ~/.ssh folder setup with id_rsa (no passphrase), id_rsa.pub, authorized_keys, and known_hosts

Update - 2020.APR.03

How the Issue was Actually Resolved:
Run the rsync tasks as root user.

1) Create public/private key pairs on raspberry pi root user.
Code:
ssh-keygen -t rsa

  • .ssh folder set to: drwx------
  • id_rsa file set to: -rw-------
  • id_rsa.pub file set to: -rw-r--r--
2) Repeat step (1) for FreeNAS root user
3) log into raspberry pi as root and create an authorized_keys file
nano /root/.ssh/authorized_keys
copy the FreeNAS root user public key id_rsa.pub into raspberry pi's root user authorized_keys file.
4) Test the ssh connection from freeNAS user account
Code:
FreeNAS# ssh root@{raspberrypi.ip.address}

The authenticity of host '{raspberrypi.ip.address}' can't be established.
ECDSA key fingerprint is SHA256:6.XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX
No matching host key fingerprint found in DNS.
Are you sure you want to continue connecting (yes/no)? {type: yes}
Warning: Permanently added '{raspberrypi.ip.address}' (ECDSA) to the list of known hosts.


Optional:
Modify /etc/ssh/sshd_config on the raspberry pi to accept key pair ssh logins only :
  • Code:
    ChallengeResponseAuthentication no
    Password Authentication no
    UsePAM no
5) Once ssh connection has been confirmed as working, test the rsync functionality from FreeNAS
  • Code:
    FreeNAS# rsync -r --del /mnt/{pool}/{dataset/test_folder} backupuser@{rasberry pi IP address}:/mnt/usb_drive/test_folder
  • Verify that files synchronized to the raspberry pi
  • Delete some file content in test_folder on FreeNas and run the rsycnc command (above) again
  • Verify file deletion on raspberry pi
6) Setup rsync task in FreeNAS GUI using the root user, configure according to specific needs and environment. Scheduled rysnc tasks should now run as intended.
 
Last edited:

Hazimil

Contributor
Joined
May 26, 2014
Messages
172
Hi, not a rsync user, but wonder if this is linked to the change in the $HOME variable in 11.3.

This link might help.

Jonathan
 

dj_jazzn

Dabbler
Joined
Apr 14, 2014
Messages
31
Thanks for the reference Jonathan.

I created a cron job with the script in the link you provided.

Code:
echo $HOME > /tmp/myoutput.txt


When this is run as root, the home variable is $HOME = /
When this is run as backupuser, the home variable is still $HOME = /

Considering that an rsync or cron task run as either root or some other user results in a $HOME=/, then where should things like public/private keys be stored and for what user?

I will have to explore this a bit further.
 
Last edited:

dj_jazzn

Dabbler
Joined
Apr 14, 2014
Messages
31
This link might help.
Jonathan

Looking at the link you provided above and your forum post, I see how one could resolve the root user home location discrepancy when scheduling a script. I am not sure how to perform the same fix when using rsync as there no script to add code:
Code:
export HOME=/root

or in my case:
Code:
export HOME=/mnt/{pool}/home/backupuser 

In my setup, I have explicitly created non-root users for backing up data from FreeNAS to my backup Raspberry pi. I may need to rethink this and use the root users on each system.
 

Hazimil

Contributor
Joined
May 26, 2014
Messages
172
I am not sure how to perform the same fix when using rsync as there no script to add code:

I suppose you could write a short script to do the work for you, i.e.:

Code:
#!/bin/bash
export HOME=/mnt/{pool}/home/backupuser 
"rsync command"


Then just run that via cron? Or you can log the $HOME issue as a bug and see if you get further than what I did.

Jonathan
 

dj_jazzn

Dabbler
Joined
Apr 14, 2014
Messages
31
I suppose you could write a short script to do the work for you, i.e.:

Code:
#!/bin/bash
export HOME=/mnt/{pool}/home/backupuser
"rsync command"


Then just run that via cron? Or you can log the $HOME issue as a bug and see if you get further than what I did.

Jonathan

Thanks for the suggestion. I may look at implementing something like this to continue the operation as backupuser.

I have come up with a workaround/solution that uses the rsync GUI.
Capture.PNG


Basically I setup the same rsync tasks but as the root user. This required generating ssh keys on each machines root user accounts and then setting up the known_hosts file on the FreeNAS and authorized_keys file on the raspberry pi. Scheduled tasks are now running as they should.
 
Last edited:
Top