Unexplained '[FAIL]' reports

Help and Support
1

Suddenly - though I have been fiddling with the my scripts that run rclone - I am getting (from the aforementioned scripts) output of this sort:

SOURCE path /usr/bin/scripts
DESTINATION path erclone:/X1/usr/bin/rootScripts/Fri/
INCLUDES & EXCLUDES
Dump FILTERS false
LOG level INFO
RCLONE_TPS 299
RCLONE_TPS_BURST 400
DRY-RUN false
TEMPORARY OUTPUT /tmp/rclone_backupJob_scriptsRoot
MAIL true

Running backup . . |2018/04/06 15:04:41 INFO : Starting bandwidth limiter at 18MBytes/s
2018/04/06 15:04:41 INFO : Starting HTTP transaction limiter: max 299 transactions/s with burst 400
-2018/04/06 15:04:44 INFO : Encrypted drive ‘erclone:/X1/usr/bin/rootScripts/Fri/’: Modify window is 1s
-2018/04/06 15:04:45 INFO : Encrypted drive ‘erclone:/X1/usr/bin/rootScripts/Fri/’: Waiting for checks to finish
2018/04/06 15:04:45 INFO : Encrypted drive ‘erclone:/X1/usr/bin/rootScripts/Fri/’: Waiting for transfers to finish
2018/04/06 15:04:45 INFO : Waiting for deletions to finish
2018/04/06 15:04:45 INFO :
Transferred: 0 Bytes (0 Bytes/s)
Errors: 0
Checks: 2
Transferred: 0
Elapsed time: 4s

[FAIL]

Now, much of that output, including the ‘[FAIL]’, is from rclone itself, but I am unsure what’s causing the ‘[FAIL]’. It doesn’t seem to be that the backup has nothing to do; for, I have another backup job that, at present, has nothing to do, and it does not report a failure - though other similar scripts do (as in the example above). Can anyone shed any light?

I am using GoogleDrive and the latest (github) version or rclone.

2

I just grepped rclone source for [FAIL] and also the binary and it isn’t in either of those, so I don’t think rclone is generating that message…

Is that rclone exiting with a non-zero return code maybe? It doesn’t seem to have counted any errors though so it looks like a successful transfer.

Can you add -vv to the log to see if it prints anything else?

3

ncw: thank you for the thoughtful response.

I feel a bit up to my eyes in techical problems at the moment, so might I ask for a bit of hand-holding? How do I ‘add -vv’ to the log? I imagine that the answer is: add something to the rclone command that I execute. But - given the complexity of rclone commands - just what? The commands I use involve already -- log-level=info.

4

Just change that to --log-level=debug to get the equivalent of -vv.

5

Thanks, ncw.

Here’s the output generated by one of the failing jobs, when the debug flag is set. The first few lines are printed by my backup script.

NAME of this script              rclone_daily                  
Backup FUNCTION to run           rclone_backupJob_scriptsSystemD
SOURCE path                      /etc/systemd/system           
DESTINATION path                 erclone:/X1/etc/systemd/system/Sun/
INCLUDES & EXCLUDES              <not shown>                   
Dump FILTERS                     false                         
LOG level                        DEBUG                         
RCLONE_TPS                       299                           
RCLONE_TPS_BURST                 400                           
DRY-RUN                          false                         
TEMPORARY OUTPUT                 /tmp/rclone_backupJob_scriptsSystemD
MAIL                             true                          

Running backup . .                                                                                                  |2018/04/08 17:50:14 DEBUG : rclone: Version "v1.40" starting with parameters ["rclone" "sync" "--drive-chunk-size=256K" "--log-level=DEBUG" "--tpslimit" "299" "--tpslimit-burst" "400" "--fast-list" "--skip-links" "--max-depth" "30" "--ask-password=false" "--bwlimit=18m" "--checkers=10" "--modify-window=1s" "/etc/systemd/system" "erclone:/X1/etc/systemd/system/Sun/"]
2018/04/08 17:50:14 DEBUG : Using config file from "/home/nicholas/.config/rclone/rclone.conf"
2018/04/08 17:50:14 INFO  : Starting bandwidth limiter at 18MBytes/s
2018/04/08 17:50:14 INFO  : Starting HTTP transaction limiter: max 299 transactions/s with burst 400
/2018/04/08 17:50:17 INFO  : Encrypted drive 'erclone:/X1/etc/systemd/system/Sun/': Modify window is 1s
-2018/04/08 17:50:18 DEBUG : vpn.service: Size and modification time the same (differ by -742.583µs, within tolerance 1s)
2018/04/08 17:50:18 DEBUG : ntp.service: Size and modification time the same (differ by 0s, within tolerance 1s)
2018/04/08 17:50:18 DEBUG : prey-agent.service: Size and modification time the same (differ by -500.3µs, within tolerance 1s)
2018/04/08 17:50:18 DEBUG : hddtemp.service: Size and modification time the same (differ by 0s, within tolerance 1s)
2018/04/08 17:50:18 DEBUG : hddtemp.service: Unchanged skipping
2018/04/08 17:50:18 DEBUG : prey-agent.service: Unchanged skipping
2018/04/08 17:50:18 DEBUG : rc-local.service: Size and modification time the same (differ by -418.322µs, within tolerance 1s)
2018/04/08 17:50:18 DEBUG : rc-local.service: Unchanged skipping
2018/04/08 17:50:18 DEBUG : unmount.service: Size and modification time the same (differ by -353.456µs, within tolerance 1s)
2018/04/08 17:50:18 DEBUG : unmount.service: Unchanged skipping
2018/04/08 17:50:18 DEBUG : vpn.service: Unchanged skipping
2018/04/08 17:50:18 DEBUG : ntp.service: Unchanged skipping
2018/04/08 17:50:18 DEBUG : lenovo_fix.service: Size and modification time the same (differ by -952.245µs, within tolerance 1s)
2018/04/08 17:50:18 DEBUG : lenovo_fix.service: Unchanged skipping
2018/04/08 17:50:18 INFO  : Encrypted drive 'erclone:/X1/etc/systemd/system/Sun/': Waiting for checks to finish
2018/04/08 17:50:18 INFO  : Encrypted drive 'erclone:/X1/etc/systemd/system/Sun/': Waiting for transfers to finish
2018/04/08 17:50:18 INFO  : Waiting for deletions to finish
2018/04/08 17:50:18 INFO  : 
Transferred:      0 Bytes (0 Bytes/s)
Errors:                 0
Checks:                 7
Transferred:            0
Elapsed time:        4.1s

2018/04/08 17:50:18 DEBUG : 7 go routines active
2018/04/08 17:50:18 DEBUG : rclone: Version "v1.40" finishing with parameters ["rclone" "sync" "--drive-chunk-size=256K" "--log-level=DEBUG" "--tpslimit" "299" "--tpslimit-burst" "400" "--fast-list" "--skip-links" "--max-depth" "30" "--ask-password=false" "--bwlimit=18m" "--checkers=10" "--modify-window=1s" "/etc/systemd/system" "erclone:/X1/etc/systemd/system/Sun/"]
[FAIL]
rclone_backupJob_scriptsSystemD - completed in 0 hour(s), 0 minute(s) and 4 second(s).

EDIT: And here’s the most relevant bit of code from my backup bash script.

rclone sync \
		$driveChunkSizeString\
		$RCLONE_DRY_RUN_STRING\
		$RCLONE_DUMP_FILTERS_STRING\
		$RCLONE_LOG_LEVEL_STRING\
		$RCLONE_TPS_STRING\
		--skip-links \
		--max-depth 30 \
		--ask-password=false \
		--bwlimit=$RCLONE_BANDWIDTH_LIMIT\
		--checkers=$RCLONE_CHECKERS\
		--modify-window=$RCLONE_MODIFY_WINDOW\
		$SOURCE_PATH $DESTINATION_PATH \
		2>&1 | tee "$OUTPUT_FULL_PATH"\
	|| exitCode=1

EDIT: perhaps I should add that the ‘fail’ message started appearing after I upgraded from a slightly older git version of rclone, and (admittedly) after I made some changes to my code.

6

The log looks like rclone finished successfully.

Can you see what is printing the [FAIL] message? I’m pretty sure it isn’t rclone or tee so I think it must be something to do with your scrpt.

7

ncw, and all

Thanks. You are right. The problem is with my script. Apologies!

8

No worries! Hopefully it is working now.