How to diagnose rsync failure with new setup?

JDLH

Dabbler
Joined
Aug 10, 2019
Messages
22
Hello,

I am trying to get my new FreeNAS Mini-E file server to back up files to my old QNAP TS-219P NAS using rsync. I did what I thought was reasonable to turn on Rsync Server on the QNAP NAS, and I can rsync from my Mac to the QNAP. I did what I thought was reasonable to schedule an Rsync task in FreeNAS. I launched the job. Then… nothing.

I would like to look at logs on the FreeNAS system to get some idea of what the rsync Push-side is saying. Where do I find such logs? I see nothing from rsync in `/var/log/messages`. I don't see a `/var/log/rsync*.log` file. Where should I look?

And more generally, any tips on how can I diagnose a failing new rsync push setup?

I didn't see anything relevant in the User Guide -- Services -- Rsync or Tasks -- Rsync Tasks . I am running FreeNAS-11.2-U7 (still) on FreeNAS-Mini-E hardware. Thank you in advance for your help.
 

JDLH

Dabbler
Joined
Aug 10, 2019
Messages
22
I don't know where the logs were being written. But I added to the Extra Options field of my Tasks / Rsync Tasks / Edit task dialogue, the setting:
--log-file=/var/log/rsync.log

I also made this file --log-file=/var/log/rsync.log writable by user, group, and other. When I ran the task again, I got two lines of diagnostics in the log file.

Is this how we are supposed to get logs: by asking for the in each Rsync task?
 

JDLH

Dabbler
Joined
Aug 10, 2019
Messages
22
With more experimentation I have discovered that adding to the Extra Options field of my Tasks / Rsync Tasks / Edit task dialogue is what gets me logs. The entry --log-file=/var/log/rsync.log, pointing to a file writable by user, group, gets me initial diagnostics. Adding an entry --verbose gets me more diagnostics, both in the rsync.log file and in the console message in /var/log/messages. Adding a second entry --verbose gets me yet more diagnostics in both places.
 

JDLH

Dabbler
Joined
Aug 10, 2019
Messages
22
Another source of diagnostics: ps, the command to give process status. This lets you see how the dialogue box fields in the Rysnc Tasks dialogue are turned into an rsync command. You can then reproduce that command.

% ps -axww | grep rsync
34891 - I 0:00.01 /bin/sh -c /usr/bin/lockf -s -t 0 -k "/mnt/mypool/MyVol/mydir" /usr/local/bin/rsync -r -t -z -a -p -X --delay-updates --password-file=/usr/local/etc/rsync/qnap_rsync.secrets --log-file=/var/log/rsync.log --verbose --verbose --stats --filter="+ /mydir/" --filter="+ /mydir/inbox/" --filter="+ /mydir/inbox/Merged/***" --filter="- *" "/mnt/mypool/MyVol/mydir" rsync@192.150.23.101::"ShareName" | logger -t rsync
34892 - I 0:00.00 /usr/bin/lockf -s -t 0 -k /mnt/mypool/MyVol/mydir /usr/local/bin/rsync -r -t -z -a -p -X --delay-updates --password-file=/usr/local/etc/rsync/qnap_rsync.secrets --log-file=/var/log/rsync.log --verbose --verbose --stats --filter=+ /mydir/ --filter=+ /mydir/inbox/ --filter=+ /mydir/inbox/Merged/*** --filter=- * /mnt/mypool/MyVol/mydir rsync@192.150.23.101::ShareName
34893 - I 0:00.00 logger -t rsync
34894 - D 0:31.48 /usr/local/bin/rsync -r -t -z -a -p -X --delay-updates --password-file=/usr/local/etc/rsync/qnap_rsync.secrets --log-file=/var/log/rsync.log --verbose --verbose --stats --filter=+ /mydir/ --filter=+ /mydir/inbox/ --filter=+ /mydir/inbox/Merged/*** --filter=- * /mnt/mypool/MyVol/mydir rsync@192.150.23.101::ShareName
83937 - Is 0:00.00 /usr/local/bin/rsync --daemon --config /usr/local/etc/rsync/rsyncd.conf
34959 47 S+ 0:00.00 grep rsync


At first I was using the command ps -x | grep rsync. This gave me only the line containing "--daemon", and not the lines corresponding to my actual rsync task. The other options fix this. -a looks through tasks belonging to all users, not just those belonging to you. -w widens the output from 80 to 132 lines. The second -w makes the output width unlimited. Width limits were clipping the "rsync" part the command starting, so grep wasn't finding it for me.

As I read this command, here's what I think the parts mean. The "/bin/sh" part executes the rest of the command in a slightly better environment. The "/usr/bin/lockf" part makes sure only one task runs at a time. The pipe "|" to "logger" gets output into the system log. The part beginning with "/usr/local/bin/rsync" is the actual command.
 
Last edited:

JDLH

Dabbler
Joined
Aug 10, 2019
Messages
22
As I mentioned above, adding an entry --verbose to the Extra Options field of the Rsync Task gets me more diagnostics. It is worth reading the rsync command documentation (man page) about the --info and --debug options. In principle you make rsync be both more selective and more detailed in the diagnostics it puts out to the log file and to the console. However, in my case I got worse results, and returned to using --verbose . The problem may have been that the rsync software at the destination was a slightly older version (protocol 30 vs protocol 31 on my FreeNAS system), and that might have reduced the quality of my results.

I felt like I got much better access to diagnostics when I opened up a separate terminal window to ssh in to a shell command line on my FreeNAS server. I was able to use commands like tail -10 /var/log/messages and tail -10 /var/log/rsync.log to see the console and the rsync log respectively. And using tail -f with either of these files let me see messages as they were added to the file. My previous access to the command line was via the Shell option in the FreeNAS admin UI. This forced me to close the Rsync Task dialogue in order to see the results of my actions, and it was cumbersome. Having a separate shell window was much better.

It looks like there are no diagnostics if you may a syntax error in the Extra Options field of the Rsync Task. When you run the job, apparently nothing happens. The answer seems to be, don't make mistakes. Alternately, check the Extra Options carefully for syntax errors. You can also construct an rsync --dry-run command in the shell, and paste in the Extra Options you are using. This showed me helpful syntax error messages sometimes.

From the list of Rsync Tasks, you can click on the three-dot icon at the right, and select Run Now from the menu there. This lets you try different settings without waiting for the scheduled time to occur. I have set all my Rsync Tasks to run once a year, or even less often, and unchecked the Enabled checkbox. I run them only from the Run Now menu item. Once I get the tasks working, I will schedule them.

One of the problems I have had with my Rsync Tasks was timeouts before a task was complete. Because I kept the default setting of "Delay Updates", this meant that rsync left my copied files in temporary directories "
.~tmp~" throughout the destination. I found that I was able to use rsync's filter rules in the Extra Options of the Rsync Task. By excluding most of the source directory, and including only a few top-level directories at at time, I was able to finish smaller rsync tasks before the timeout occurred, so the files got out of their temp directories and into the right locations. Reducing the scope this way has a double benefit: not only does it reduce the amount of data to copy, it reduces the time rsync requires up front to make a list of files to examine. That list was taking tens of minutes to an hour in my case. I expect that, once most of the files are copied, I can run an Rsync Task over the entire directory, and it will be able to update the few changes without timing out.

Also, let me go a little off-topic to report one success. I realised that I was getting tunnel vision around rsync, and that my top-level goal was to get the files copied regardless of the method. I was able to copy 1TB of files using the macOS Finder. It took 10 hours, but it completed. I will then go back over it with rsync to see if rsync is happy with the result. This may be a useful way to make an end run around rsync failures.
 

JDLH

Dabbler
Joined
Aug 10, 2019
Messages
22
The "/usr/bin/lockf" part makes sure only one task runs at a time.
Looking a bit more closely at the lockf(1) documentation, it seems that lockf ensures that if a second Rsync Task starts while an existing task is already working on that path, the new Rsync Task will end at once, without doing anything. However, if Rsync Tasks are working on different pools (paths), they can run simultaneously. The relevant arguments are "/mnt/mypool/MyVol/mydir" as the thing being locked, and -t 0 as meaning, quit immediately if another process has that path locked.
 

JDLH

Dabbler
Joined
Aug 10, 2019
Messages
22
I was able to improve my logging on the QNAP NAS side also. Their rsync server uses a configuration file located at /etc/config/rsyncd.conf . It mostly follows the rsyncd.conf documentation. I added the following two lines to the first part of the config file:

Code:
log file = /var/log/rsyncd.log
max verbosity = 4


The first line tells the rsync daemon to store a log file. The second allows me to ask for more verbose diagnostics on the originating side back at FreeNAS. I created the log file on the QNAP system before running an rsync task, because I think rsync will not create the file.
 
Top