(re)sync failing to Amazon Drive

Suspected Bug
1

Hi,

I made an initial backup to Amazon Drive using rclone sync. Re-ran the same command a week later and the sync failed (after many hours of checking and/or copying) with a few errors. Most worrying:

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0x565596]

rclone is reporting some local files as being missing, but they are present. Script was run as root both times.

Previous files with names containing spaces and apostrophes were backed up, so do not believe it’s the filenames.

Any advice would be appreciated.

Cheers,

Paul

##########

Command run:

/usr/sbin/rclone --checksum --log-file=/var/log/rclone_backup-201610 --max-size 50G --bwlimit 1536k sync /backup/kate/data/latest AmazonDrive:backups/kate/data/latest

##########

Start of log:

2016/10/19 17:31:07 Starting bandwidth limiter at 1.500MBytes/s

##########

Excerpt from log:

[root@kate ~]# tail -75 /var/log/rclone_backup-201610 | more
2016/10/20 03:31:10
Transferred: 760.902 MBytes (21.641 kBytes/s)
Errors: 1
Checks: 175656
Transferred: 554
Elapsed time: 10h0m3.1s
Checking:

  • images/2009/200907/School/2009-07-04–17.47.20/img_0707.jpg
  • images/2013/Working/Canon2/IMG_4261.JPG
  • images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20131123_201149.jpg
  • images/2015/Working/Paul’s Nexus 5 - 20150417/VID_20140920_125422.mp4
  • personal/Hagyard Consulting Ltd/Laptop/tc3
  • personal/sam/Laptop/Windows 8 file history/sam/CYBERRAT/Data/$OF/1306/1302 (2016_03_28 19_28_07 UTC).mp4
  • personal/sam/MATRIX ENERGY GAMING/OVERWATCH/Clips to sort/Overwatch 14_07_2016 11_17_25.mp4
  • personal/sam/MATRIX ENERGY GAMING/OVERWATCH/Clips to sort/Overwatch 14_07_2016 12_57_22.mp4

2016/10/20 03:32:10
Transferred: 760.902 MBytes (21.605 kBytes/s)
Errors: 1
Checks: 175871
Transferred: 554
Elapsed time: 10h1m3.1s
Checking:

  • images/2006/200601/Muriwai beach - go kart/P1020084.JPG
  • images/2013/201312/Chris Denhams wedding/RAW/DSC_7481.NEF
  • images/2013/Working/WSL_REV/WPD-A 16/Rear/WPD-A-16-rear_misc2.JPG
  • images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20150218_105223.jpg
  • images/2015/Working/Paul’s Nexus 5 - 20150417/VID_20140920_125422.mp4
  • personal/Hagyard Consulting Ltd/Laptop/tc3
  • personal/sam/Laptop/Windows 8 file history/sam/CYBERRAT/Data/$OF/1306/1302 (2016_03_28 19_28_07 UTC).mp4
  • personal/sam/MATRIX ENERGY GAMING/OVERWATCH/Clips to sort/Overwatch 14_07_2016 12_57_22.mp4

2016/10/20 03:33:10
Transferred: 760.902 MBytes (21.569 kBytes/s)
Errors: 1
Checks: 176196
Transferred: 554
Elapsed time: 10h2m3.1s
Checking:

  • images/2009/200901/Zoo visit/DSC_0856.JPG
  • images/2013/Working/Canon2/IMG_4262.JPG
  • images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20150102_122710.jpg
  • images/2015/Working/Paul’s Nexus 5 - 20150417/VID_20141004_133103.mp4
  • images/2015/Working/Paul’s Nexus 5 - 20150417/VID_20150331_161151.mp4
  • personal/Hagyard Consulting Ltd/Internet and phone/Vodafone/Internet issues - 20120614/20120703-0544/Router-WAN-stats-20120703-0547.PNG
  • personal/Hagyard Consulting Ltd/Laptop/tc3
  • personal/sam/MATRIX ENERGY GAMING/OVERWATCH/Clips to sort/Overwatch 14_07_2016 12_57_22.mp4

2016/10/20 03:33:44 images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20150205_150121.jpg: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 2015
0417/IMG_20150205_150121.jpg: no such file or directory
2016/10/20 03:33:44 images/2006/200601/Pureora camping/Steph, Andrew, Sam, and Paul - Pureora Link Track sign #2 - 200601.JPG: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/image
s/2006/200601/Pureora camping/Steph, Andrew, Sam, and Paul - Pureora Link Track sign #2 - 200601.JPG: no such file or directory
2016/10/20 03:33:44 images/2006/200604/1/P1020499.JPG: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/images/2006/200604/1/P1020499.JPG: no such file or directory
2016/10/20 03:33:44 images/2013/Working/Nikon/DSC_7179.NEF: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/images/2013/Working/Nikon/DSC_7179.NEF: no such file or directory
2016/10/20 03:33:44 images/2013/201312/Abseiling/IMG_4758.JPG: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/images/2013/201312/Abseiling/IMG_4758.JPG: no such file or directory
2016/10/20 03:33:44 images/2013/Working/Nikon/DSC_7179.NEF: Failed to copy: failed to open source object: open /backup/kate/data/latest/images/2013/Working/Nikon/DSC_7179.NEF: no such file or directory
2016/10/20 03:33:44 images/2006/200612/1/p1030519.jpg: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/images/2006/200612/1/p1030519.jpg: no such file or directory
2016/10/20 03:33:44 images/2007/200702/Zane’s 7th birthday/p1030617.jpg: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/images/2007/200702/Zane’s 7th birthday/p1030617.jpg: no suc
h file or directory
2016/10/20 03:33:44 images/2009/200903/Jennifers_birthday/DSC_1282.jpg: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/images/2009/200903/Jennifers_birthday/DSC_1282.jpg: no such
file or directory
2016/10/20 03:33:44 images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20141025_125146.jpg: Failed to calculate src hash: hash: failed to stat: lstat /backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 2015
0417/IMG_20141025_125146.jpg: no such file or directory
2016/10/20 03:33:44 images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20150205_150121.jpg: Failed to copy: failed to open source object: open /backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 20150417/IM
G_20150205_150121.jpg: no such file or directory
2016/10/20 03:33:44 images/2006/200601/Pureora camping/Steph, Andrew, Sam, and Paul - Pureora Link Track sign #2 - 200601.JPG: Failed to copy: failed to open source object: open /backup/kate/data/latest/images/2006/
200601/Pureora camping/Steph, Andrew, Sam, and Paul - Pureora Link Track sign #2 - 200601.JPG: no such file or directory
2016/10/20 03:33:44 images/2006/200604/1/P1020499.JPG: Failed to copy: failed to open source object: open /backup/kate/data/latest/images/2006/200604/1/P1020499.JPG: no such file or directory
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x40 pc=0x565596]

goroutine 42853 [running]:
panic(0xa26660, 0xc42000e090)
/usr/local/go/src/runtime/panic.go:500 +0x1a1
github.com/ncw/rclone/local.(*Object).Size(0xc4211b2c00, 0xde25c0)
/home/ncw/Code/Go/src/github.com/ncw/rclone/local/local.go:520 +0x26
github.com/ncw/rclone/fs.Copy(0xde8f80, 0xc420160910, 0xde9580, 0xc4252d2780, 0xde9880, 0xc4211b2c00, 0xdde740, 0xc424f349a0)
/home/ncw/Code/Go/src/github.com/ncw/rclone/fs/operations.go:228 +0x1018
github.com/ncw/rclone/fs.(*syncCopyMove).pairCopier(0xc4204348c0, 0xc425c204e0, 0xde8f80, 0xc420160910, 0xc420434948)
/home/ncw/Code/Go/src/github.com/ncw/rclone/fs/sync.go:238 +0x296
created by github.com/ncw/rclone/fs.(*syncCopyMove).startTransfers
/home/ncw/Code/Go/src/github.com/ncw/rclone/fs/sync.go:332 +0x108
[root@kate ~]#

##########

Checking for files

[root@kate ~]# ls -l “/backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20150205_150121.jpg”
-rw-rw-r-- 117 share share 1780255 Feb 5 2015 /backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20150205_150121.jpg
[root@kate ~]# ls -l “/backup/kate/data/latest/images/2006/200601/Pureora camping/Steph, Andrew, Sam, and Paul - Pureora Link Track sign #2 - 200601.JPG”
-rw–w---- 117 share share 1676499 Jan 3 2006 /backup/kate/data/latest/images/2006/200601/Pureora camping/Steph, Andrew, Sam, and Paul - Pureora Link Track sign #2 - 200601.JPG
[root@kate ~]# ls -l "/backup/kate/data/latest/images/2006/200604/1/P1020499.JPG

^C
[root@kate ~]# ls -l “/backup/kate/data/latest/images/2006/200604/1/P1020499.JPG”
-rw–w---- 117 share share 1603940 Apr 8 2006 /backup/kate/data/latest/images/2006/200604/1/P1020499.JPG
[root@kate ~]# ls -l /backup/kate/data/latest/images/2013/Working/Nikon/DSC_7179.NEF
-rw-rw-r-- 117 share share 10982900 Jun 8 2013 /backup/kate/data/latest/images/2013/Working/Nikon/DSC_7179.NEF
[root@kate ~]# ls -l /backup/kate/data/latest/images/2013/201312/Abseiling/IMG_4758.JPG
-rw-rw-r-- 117 share share 2317740 Dec 27 2013 /backup/kate/data/latest/images/2013/201312/Abseiling/IMG_4758.JPG
[root@kate ~]# ls -l /backup/kate/data/latest/images/2013/Working/Nikon/DSC_7179.NEF
-rw-rw-r-- 117 share share 10982900 Jun 8 2013 /backup/kate/data/latest/images/2013/Working/Nikon/DSC_7179.NEF
[root@kate ~]# ls -l /backup/kate/data/latest/images/2006/200612/1/p1030519.jpg
-rw–w---- 117 share share 1088114 Nov 18 2006 /backup/kate/data/latest/images/2006/200612/1/p1030519.jpg
[root@kate ~]# ls -l “/backup/kate/data/latest/images/2007/200702/Zane’s 7th birthday/p1030617.jpg”
-rw–w---- 117 share share 1736929 Feb 24 2007 /backup/kate/data/latest/images/2007/200702/Zane’s 7th birthday/p1030617.jpg
[root@kate ~]# ls -l /backup/kate/data/latest/images/2009/200903/Jennifers_birthday/DSC_1282.jpg
-rw–w---- 117 share share 1649582 Apr 4 2009 /backup/kate/data/latest/images/2009/200903/Jennifers_birthday/DSC_1282.jpg
[root@kate ~]# ls -l “/backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20141025_125146.jpg”
-rw-rw-r-- 117 share share 4111836 Oct 25 2014 /backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20141025_125146.jpg
[root@kate ~]# ls -l “/backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20150205_150121.jpg”
-rw-rw-r-- 117 share share 1780255 Feb 5 2015 /backup/kate/data/latest/images/2015/Working/Paul’s Nexus 5 - 20150417/IMG_20150205_150121.jpg
[root@kate ~]# ls -l “/backup/kate/data/latest/images/2006/200601/Pureora camping/Steph, Andrew, Sam, and Paul - Pureora Link Track sign #2 - 200601.JPG”
-rw–w---- 117 share share 1676499 Jan 3 2006 /backup/kate/data/latest/images/2006/200601/Pureora camping/Steph, Andrew, Sam, and Paul - Pureora Link Track sign #2 - 200601.JPG
[root@kate ~]# ls -l /backup/kate/data/latest/images/2006/200604/1/P1020499.JPG
-rw–w---- 117 share share 1603940 Apr 8 2006 /backup/kate/data/latest/images/2006/200604/1/P1020499.JPG
[root@kate ~]#

2

That seems to be the root cause of the problem.

The panic is bad - rclone should never panic :frowning:

Musings to self: What it looks like is that local.Object.Size() was called with a nil info. I can’t how an Object can be created without a valid info though

Can I get you to retest with the latest beta? http://beta.rclone.org/v1.33-72-ga4a44a4/ There have been several fixes in that area which I’d like to rule out.

If it fails again, the log you posted was perfect so can you post that again?

Which OS did you run rclone on and which filing system are the files stored on?

I would be surprised if that was the problem but it isn’t impossible!

Thanks

Nick

3

Hi Nick,

Thanks for the response. I’ve got the beta running now, I’ll check the logs in a few hours and will post an update.

To answer your other questions:

##########

OS details

[root@kate ~]# cat /etc/centos-release
CentOS release 6.8 (Final)
[root@kate ~]# uname -a
Linux kate 2.6.32-642.4.2.el6.x86_64 #1 SMP Tue Aug 23 19:58:13 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

##########

Filesystem is ext4

[root@kate ~]# df -hT | grep backup
/dev/sdc1 ext4 3.6T 3.1T 549G 86% /backup
[root@kate ~]#

The host is a virtual machine on VMware ESXi 6.0 update 2, the underlying physical host is not heavily loaded. The filesystem is a virtual disk file on a dedicated physical SATA3 disk - so no contention for IO.

Cheers,

Paul

4

Hi,

The sync completed successfully with the beta version :slight_smile: Is there anything else I can run/help with to assist with this, or is it enough to know that it’s fixed in the beta?

Awesome software, thank you!

##########

End of rclone log

2016/10/21 03:39:52 amazon drive root ‘backups/kate/data/latest’: Waiting for transfers to finish
2016/10/21 03:39:52 Waiting for deletions to finish
2016/10/21 03:40:06
Transferred: 332.767 MBytes (25.042 kBytes/s)
Errors: 0
Checks: 63686
Transferred: 36
Elapsed time: 3h46m46.9s

Sync ending at Fri Oct 21 03:40:06 NZDT 2016
##################################################

On an unrelated matter as I was looking through the logs, a couple of suggestions:

  1. Insert a blank line before the “Checking:” line - it’s a bit hard to see where a new section of checks starts
  2. It logs which files are checked. Is there a way (verbosity level?) to show which of the files checked were actually transferred (if any)? Maybe adding the transferred files as a list under the transferred bytes.

##########

Reference log excerpt.

Checking:

  • Audio/MP3/Paul Simon/Pau lSimon - Loves me like a rock.mp3
  • Home network/Servers/Firewalls/Build documentation/SmartCenter/finish_build.sh
  • Home network/Servers/Virtualisation/Backups/ESXi-5.5-20151123-1301.img
  • Home network/Servers/Virtualisation/Backups/esxi-6.0-20160321-1328.img
  • Video/Family/June_October_Christmas_2004.avi
  • images/2008/200801/Western Springs/img_1779.jpg
  • images/2008/Kaz/dscf0134.jpg
  • personal/andrew/Minecraft/Minecraft saves/New Worl/DIM-1/region/r.0.0.mca

2016/10/21 00:56:23
Transferred: 199.465 kBytes (53 Bytes/s)
Errors: 0
Checks: 9512
Transferred: 2
Elapsed time: 1h3m4.1s
Checking:

  • Home network/Servers/Virtualisation/Backups/ESXi-5.5-20151123-1301.img
  • Home network/Servers/Virtualisation/Backups/esxi-6.0-20160321-1328.img
  • Manuals/Asus/P4PE motherboard/User manual.pdf
  • Video/Family/June_October_Christmas_2004.avi
  • images/2011/201106/Sam’s 10th birthday/1/Originals/DSC_4278.JPG
  • images/Ready to print 201003/Andrew_7th_bday_#23-20100227.jpg
  • images/Ready to print 201003/SI_081_Te_Anau_panorama_1-201001.tif
  • personal/Lego/2013/Programs/2013.11.19_19.46.57/Default/Bridge.rbt

2016/10/21 00:57:23
Transferred: 199.465 kBytes (53 Bytes/s)
Errors: 0
Checks: 10067
Transferred: 2
Elapsed time: 1h4m4.1s

Cheers,

Paul

5

Should have looked more carefully, ignore my comment about which files were transferred.
##########

Transferred file log

Transferring:

  • … - Pureora Link Track sign #2 - 200601.JPG: 100% done. avg: 391.7, cur: 272.3 kByte/s. ETA: 0s

2016/10/21 02:31:23
Transferred: 17.511 MBytes (1.891 kBytes/s)
Errors: 0
Checks: 49777
Transferred: 11
Elapsed time: 2h38m4.1s

6

Fixed is good! I'd say just keep an eye out for it going wrong again - if it does then let me know.

I see what you mean! You can get both Checking and Transferring files at once. You can control how often these messages get printed with --stats.

The stats shows you the files that are being transferred at that moment. There is an issue for logging each transferred file only here...