Project

General

Profile

Bug #14477

Rsync command fails on importing certain media with permission errors

Added by Matt Kessler over 3 years ago. Updated about 3 years ago.

Status:
Resolved
Priority:
Nice to have
Assignee:
Suraj Ravichandran
Category:
Middleware
Severity:
New
Reason for Closing:
Reason for Blocked:
Needs QA:
Yes
Needs Doc:
Yes
Needs Merging:
Yes
Needs Automation:
No
Support Suite Ticket:
n/a
Hardware Configuration:

Build FreeNAS-9.10-STABLE-201603252134 (412fb1c)
Platform Intel(R) Celeron(R) CPU G1610T @ 2.30GHz
Memory 12225MB
Manufacturer: HP
Product Name: ProLiant MicroServer Gen8

ChangeLog Required:
No

Description

Build        FreeNAS-9.10-STABLE-201603252134 (412fb1c)
Platform     Intel(R) Celeron(R) CPU G1610T @ 2.30GHz
Memory       12225MB
Manufacturer:     HP
Product Name:     ProLiant MicroServer Gen8

Very happy to read from the release notes

The base OS version for FreeNAS 9.10 is now FreeBSD 10.3-RC3,
bringing in a huge number of OS-related bug fixes, performance
improvements and new features (new drivers, new CPU chipset support, USB 3.0, etc)

I revisited an old issue I had: Importing +900GB from a NTFS formatted USB3 drive.

Seagate Expansion Desk USB3, 3.5 HDD, 2TB, 1 NTFS partition & 1 FAT32 partition
Apr  6 18:20:24 freenas ugen1.2: <Seagate> at usbus1
Apr  6 18:20:24 freenas umass1: <Seagate Expansion Desk, class 0/0, rev 3.00/1.00, addr 1> on usbus1
Apr  6 18:20:24 freenas umass1:  SCSI over Bulk-Only; quirks = 0x0100
Apr  6 18:20:24 freenas umass1:8:1:-1: Attached to scbus8
Apr  6 18:20:24 freenas da1 at umass-sim1 bus 1 scbus8 target 0 lun 0
Apr  6 18:20:24 freenas da1: <Seagate Expansion Desk 070B> Fixed Direct Access SPC-4 SCSI device
Apr  6 18:20:24 freenas da1: Serial Number NAxxxxxxx
Apr  6 18:20:24 freenas da1: 400.000MB/s transfers
Apr  6 18:20:24 freenas da1: 1907729MB (3907029167 512 byte sectors)
Apr  6 18:20:24 freenas da1: quirks=0x2<NO_6_BYTE>
Apr  6 18:23:14 freenas sockscopy: Import of Volume /dev/da1s5 encoutered the following error <django.utils.functional.__proxy__ object at 0x8055608d0>
Apr  6 18:23:15 freenas fuse-freebsd: version 0.4.4, FUSE ABI 7.8
Apr  6 18:25:50 freenas sockscopy: User Terminated Import of Volume: /dev/da1s5
Apr  6 18:26:47 freenas sockscopy: Import of Volume /dev/da1s5 encoutered the following error <django.utils.functional.__proxy__ object at 0x8055608d0>
Apr  6 18:27:44 freenas sockscopy: User Terminated Import of Volume: /dev/da1s5
Apr  6 18:30:54 freenas sockscopy: Import of Volume /dev/da1s5 encoutered the following error <django.utils.functional.__proxy__ object at 0x8055608d0>
Apr  6 18:31:00 freenas sockscopy: User Terminated Import of Volume: /dev/da1s5
Apr  6 18:38:33 freenas sockscopy: Import of Volume /dev/da1s2 encoutered the following error <django.utils.functional.__proxy__ object at 0x8055608d0>
Apr  6 18:38:40 freenas sockscopy: User Terminated Import of Volume: /dev/da1s2
Apr  6 18:39:02 freenas sockscopy: Import of Volume /dev/da1s1 encoutered the following error <django.utils.functional.__proxy__ object at 0x8055608d0>
Apr  6 18:39:15 freenas sockscopy: User Terminated Import of Volume: /dev/da1s2

USB3 Stick, 32GB, FAT32
Apr  6 19:38:41 freenas ugen1.2: <Terra> at usbus1
Apr  6 19:38:41 freenas umass1: <Terra USThree, class 0/0, rev 3.00/1.00, addr 1> on usbus1
Apr  6 19:38:41 freenas umass1:  SCSI over Bulk-Only; quirks = 0xc100
Apr  6 19:38:41 freenas umass1:8:1:-1: Attached to scbus8
Apr  6 19:38:41 freenas da1 at umass-sim1 bus 1 scbus8 target 0 lun 0
Apr  6 19:38:41 freenas da1: <Terra USThree PMAP> Removable Direct Access SPC-4 SCSI device
Apr  6 19:38:41 freenas da1: Serial Number NAyyyyyy
Apr  6 19:38:41 freenas da1: 400.000MB/s transfers
Apr  6 19:38:41 freenas da1: 29573MB (60566016 512 byte sectors)
Apr  6 19:38:41 freenas da1: quirks=0x2<NO_6_BYTE>
Apr  6 19:41:28 freenas (da1:umass-sim1:1:0:0): READ(10). CDB: 28 00 02 12 22 80 00 00 80 00 
Apr  6 19:41:28 freenas (da1:umass-sim1:1:0:0): CAM status: CCB request completed with an error
Apr  6 19:41:28 freenas (da1:umass-sim1:1:0:0): Retrying command
…
Apr  6 19:45:52 freenas (da1:umass-sim1:1:0:0): READ(10). CDB: 28 00 02 12 32 00 00 00 80 00 
Apr  6 19:45:52 freenas (da1:umass-sim1:1:0:0): CAM status: CCB request completed with an error
Apr  6 19:45:52 freenas (da1:umass-sim1:1:0:0): Error 5, Retries exhausted
Apr  6 19:45:52 freenas g_vfs_done():da1s1[READ(offset=17786273792, length=65536)]error = 5
Apr  6 17:47:50 freenas devd: Executing '[ -e /tmp/.sync_disk_done ] && LD_LIBRARY_PATH=/usr/local/lib /usr/local/bin/python /usr/local/www/freenasUI/tools/sync_disks.py'
Apr  6 19:47:50 freenas ugen1.2: <Terra> at usbus1 (disconnected)
Apr  6 19:47:50 freenas umass1: at uhub2, port 1, addr 1 (disconnected)
Apr  6 19:47:50 freenas da1 at umass-sim1 bus 1 scbus8 target 0 lun 0
Apr  6 19:47:50 freenas da1: <Terra USThree PMAP> s/n 07083B88B71C4C20 detached
Apr  6 19:47:50 freenas (da1:umass-sim1:1:0:0): Periph destroyed

WD Elements USB3, 2.5 HDD, 1.5TB, 1 NTFS partition
Apr  6 19:48:20 freenas ugen1.2: <Western Digital> at usbus1
Apr  6 19:48:20 freenas umass1: <MSC Bulk-Only Transport> on usbus1
Apr  6 19:48:20 freenas umass1:  SCSI over Bulk-Only; quirks = 0xc101
Apr  6 19:48:20 freenas umass1:8:1:-1: Attached to scbus8
Apr  6 17:48:24 freenas devd: Executing '[ -e /tmp/.sync_disk_done ] && LD_LIBRARY_PATH=/usr/local/lib /usr/local/bin/python /usr/local/www/freenasUI/tools/sync_disks.py da1'
Apr  6 19:48:24 freenas da1 at umass-sim1 bus 1 scbus8 target 0 lun 0
Apr  6 19:48:24 freenas da1: <WD Elements 10B8 1007> Fixed Direct Access SPC-4 SCSI device
Apr  6 19:48:24 freenas da1: Serial Number NAzzzzzz
Apr  6 19:48:24 freenas da1: 400.000MB/s transfers
Apr  6 19:48:24 freenas da1: 1430767MB (2930210816 512 byte sectors)
Apr  6 19:48:24 freenas da1: quirks=0x2<NO_6_BYTE>
Apr  6 19:48:59 freenas sockscopy: Import of Volume /dev/da1s1 encoutered the following error <django.utils.functional.__proxy__ object at 0x805560890>

So, the imports from both HDDs fail right away.
The import from my USB3 stick, starts up ok and does transfer data, but fails at some stage, too.

Not sure if it's a driver/hardware problem as such, or the FUSE Driver/Modul.
I had this failure in version 9.3.x, but never reported it.

freeNAS-USB3-StickImportProblem_04.png (26.7 KB) freeNAS-USB3-StickImportProblem_04.png Import from USB3-FAT32 stick fails Matt Kessler, 04/06/2016 12:40 PM
freeNAS-generalUSB-ImportProblem_01.png (52.9 KB) freeNAS-generalUSB-ImportProblem_01.png Fails just as it reaches 100% Matt Kessler, 04/06/2016 02:53 PM
freeNAS-DiskImportProblem-TimeLine_01.png (279 KB) freeNAS-DiskImportProblem-TimeLine_01.png Matt Kessler, 04/06/2016 04:59 PM
freeNAS-DiskImportProblem-toNfsSuccessfullyDone_01.png (34.7 KB) freeNAS-DiskImportProblem-toNfsSuccessfullyDone_01.png I can confirm successful Imports to a NFS Dataset Matt Kessler, 04/07/2016 04:00 AM
5547
5572
5575
5576

Related issues

Related to FreeNAS - Feature #7307: Better message with Import Disk results in case of read errorResolved2014-12-27
Related to FreeNAS - Bug #11535: Cant import FAT32 DriveResolved2015-09-17
Related to FreeNAS - Bug #11028: Import disk utility displaying django object instead of actual error.Resolved2015-08-18

Associated revisions

Revision 567ec290 (diff)
Added by Suraj Ravichandran over 3 years ago

Improve Import Disk routines to be lesss error prone, have better error reporting and work with windows target datasets.

By default the underlying rsync command now does not save ownership (neither user nor group),
is lenient with modification times, does not copy over permissions and does not preserve device specials.

Also slightly improve stupid suraj code from 2014 (its still suraj code...)

Ticket: #11535
Ticket: #14477
Ticket: #11028
Ticket: #7307

History

#1 Updated by Matt Kessler over 3 years ago

  • File deleted (freeNAS-USB3-StickImportProblem_03.png)

#3 Updated by Alexander Motin over 3 years ago

  • Assignee changed from Alexander Motin to Suraj Ravichandran

Only one of three cases shown here may have relation to USB. I can't say there more then "many USB devices is a crap". Errors in two other cases seems like going from importer code, so I'll bounce this bug to its author.

#4 Updated by Matt Kessler over 3 years ago

5572

Alexander Motin wrote:

Only one of three cases shown here may have relation to USB.

Thanks Alexander. To me it is simply that I conect them to a USB3 port on the server…

umass1: <devices xyz> on usbus1

then sometimes the FUSE driver/module seems to be loaded, but not all the time

Apr 6 18:23:15 freenas fuse-freebsd: version 0.4.4, FUSE ABI 7.8

but all imports fail.

So I was just hoping the new base FreeBSD 10.3-RC3 would make this work better.

Here I just run a USB2 stick with ext4…

Apr  6 22:57:40 freenas ugen1.2: <SanDisk Corporation> at usbus1 (disconnected)
Apr  6 22:57:40 freenas umass1: at uhub2, port 5, addr 1 (disconnected)
Apr  6 22:57:40 freenas da1 at umass-sim1 bus 1 scbus8 target 0 lun 0
Apr  6 22:57:40 freenas da1: <SanDisk Cruzer Mini 0.1> s/n 2006087760191FA18F0A detached
Apr  6 22:57:40 freenas (da1:umass-sim1:1:0:0): Periph destroyed
Apr  6 21:27:13 freenas devd: Executing '[ -e /tmp/.sync_disk_done ] && LD_LIBRARY_PATH=/usr/local/lib /usr/local/bin/python /usr/local/www/freenasUI/tools/sync_disks.py da1'
Apr  6 23:27:14 freenas ugen1.2: <SanDisk Corporation> at usbus1
Apr  6 23:27:14 freenas umass1: <SanDisk Corporation Cruzer Mini, class 0/0, rev 2.00/0.10, addr 1> on usbus1
Apr  6 23:27:14 freenas umass1:  SCSI over Bulk-Only; quirks = 0xc100
Apr  6 23:27:14 freenas umass1:8:1:-1: Attached to scbus8
Apr  6 23:27:14 freenas da1 at umass-sim1 bus 1 scbus8 target 0 lun 0
Apr  6 23:27:14 freenas da1: <SanDisk Cruzer Mini 0.1> Removable Direct Access SCSI-2 device
Apr  6 23:27:14 freenas da1: Serial Number 2006087760191FA18F0A
Apr  6 23:27:14 freenas da1: 40.000MB/s transfers
Apr  6 23:27:14 freenas da1: 977MB (2001888 512 byte sectors)
Apr  6 23:27:14 freenas da1: quirks=0x2<NO_6_BYTE>
Apr  6 23:44:06 freenas sockscopy: User Terminated Import of Volume: /dev/da1s1

Fails just as it reaches 100% — see picture…

Is this import from external/USB disk working for someone?
I wanna use this, to do off site backups and network transfer is not an option.

#5 Updated by Suraj Ravichandran over 3 years ago

  • Status changed from Unscreened to Screened

I am looking in to this

#6 Updated by Matt Kessler over 3 years ago

  • File vol_rsync_stats.log added

Cheers Suraj.
I did some more digging too… see my upload (/var/run/importcopy/vol_rsync_stats)

rsync: mkstemp "/mnt/Sea3/TEMP/.Ubuntu-Mini.iso.ibtvPG" failed: Operation not permitted (1)
rsync: mkstemp "/mnt/Sea3/TEMP/.pfSense-LiveCD-2.2.6-RELEASE-amd64-20151221-1450.iso.UC5s72" failed: Operation not permitted (1)
rsync: mkstemp "/mnt/Sea3/TEMP/.pfSense-memstick-2.2.6-RELEASE-amd64-20151221-1450.img.tqDOhx" failed: Operation not permitted (1)

#7 Updated by Matt Kessler over 3 years ago

5575

Tried to see some correlation, but all I can see is, speed from USB3 stick is just great — well till the import starts to fail.

No idea why I'm getting: rsync: failed to set permissions

[root@freenas] ~# ls -al /var/run/importcopy
total 40
drwxr-xr-x   2 root  wheel     64 Apr  7 01:33 ./
drwxr-xr-x  13 root  wheel   2944 Apr  7 02:04 ../
-rw-r--r--   1 root  wheel  31170 Apr  7 01:33 vol_rsync_stats
[root@freenas] ~# ls -al /mnt/Sea3/TEMP
total 34
drwxrwxr-x+  4 root  wheel   4 Apr  7 02:04 ./
drwxr-xr-x  10 root  wheel  10 Apr  5 11:50 ../
drwxrwxr-x+  3 root  wheel   3 Apr 24  2015 .wd_tv/
drwxrwxr-x+  4 root  wheel   4 Mar 24 00:12 2001 A Space Odyssey/
[root@freenas] ~#

Added new picture with a kind of a timeline and another vol_rsync_stats logfile.

#8 Updated by Suraj Ravichandran over 3 years ago

  • Subject changed from Import from USB3 devices fails to Rsync command fails on importing certain media with permission errors
  • Status changed from Screened to 15
  • Priority changed from No priority to Expected

This is an rsync fail and definitely nothing to do with usb3 or any such thing.

Could you mount the usb yourself in a temp location and try the following rsync command and get back with the results:

rsync -aHA --info=progress2 path_where_you_mounted_your_usb_temporarily dataset_where_you_are_copying_it_to

this is a modified version of what freenas does to include copying of the ACLs, if that does not work trying adding -x (for xattrs)

Please get back with the results

#9 Updated by Matt Kessler over 3 years ago

  • Priority changed from Expected to No priority

Suraj Ravichandran wrote:

This is an rsync fail and definitely nothing to do with usb3 or any such thing.

Could you mount the usb yourself in a temp location

No, I can not do this!

[root@freenas] ~# ls /dev/da*
/dev/da0    /dev/da0p1  /dev/da0p2  /dev/da1    /dev/da1s1  /dev/da2    /dev/da2s1

[root@freenas] ~# mount /dev/da1s1 /media/usb1
mount: /dev/da1s1: Invalid argument

[root@freenas] ~# mount /dev/da2s1 /media/usb2
mount: /dev/da2s1: Invalid argument

My understanding is, that as of freeNAS 9.3 the option to mount was removed
and the only "supporteted" way is useing the import fuction from the GUI, am I wrong here?

Also, please read this post, where the same problem occurs:
[[https://forums.freenas.org/index.php?threads/usb-flash-drive-mount-fails.37104/]]

#10 Updated by Suraj Ravichandran over 3 years ago

Matt Kessler wrote:

Suraj Ravichandran wrote:

This is an rsync fail and definitely nothing to do with usb3 or any such thing.

Could you mount the usb yourself in a temp location

No, I can not do this!
[...]
My understanding is, that as of freeNAS 9.3 the option to mount was removed
and the only "supporteted" way is useing the import fuction from the GUI, am I wrong here?

you need to specify the correct filesystem type to the mount command with the -t flag i.e.

mount -t ufs /dev/foo /tmp/bar

Also, please read this post, where the same problem occurs:
[[https://forums.freenas.org/index.php?threads/usb-flash-drive-mount-fails.37104/]]

I am currently working on improving the robustness of this import utility in freenas 9.10

However, I also realize that you are importing this to a windows permission based dataset (please correct me if I am wrong) which opens up another whole set of complications, like now chmod would not work on it and so on.

#11 Updated by Suraj Ravichandran over 3 years ago

  • Related to Feature #7307: Better message with Import Disk results in case of read error added

#12 Updated by Suraj Ravichandran over 3 years ago

  • Related to Bug #11535: Cant import FAT32 Drive added

#13 Updated by Suraj Ravichandran over 3 years ago

  • Related to Bug #11028: Import disk utility displaying django object instead of actual error. added

#14 Updated by Matt Kessler over 3 years ago

5576

+1 for Feature #7307
In my opinion the GUI could be more informative about the import.
Bug #7561 started out as "Import NTFS Disk Fails" and turned into "The import fails if the target is a CIFS shared dataset"

So yes, I can confirm 1. successful Import to a NFS Dataset

Import of Volume /dev/da2s1 Successfully Done

#15 Updated by Suraj Ravichandran over 3 years ago

  • Category changed from 129 to 201
  • Status changed from 15 to Ready For Release
  • % Done changed from 0 to 100

#16 Updated by Suraj Ravichandran over 3 years ago

@Matt: Thank you for patiently holding on while I eventually got to doing this.

These issues with Import Disk should be fixed and available for you to try out in the Upcoming SU or if you want in tmrw's 9.10 Nightly.

#17 Updated by Vaibhav Chauhan over 3 years ago

  • Target version set to 261

#18 Updated by Vaibhav Chauhan over 3 years ago

  • Priority changed from No priority to Nice to have

#19 Updated by Vaibhav Chauhan about 3 years ago

  • Target version changed from 261 to 9.10-STABLE-201605240427

#20 Updated by Vaibhav Chauhan about 3 years ago

  • Status changed from Ready For Release to Resolved

#21 Updated by Dru Lavigne over 1 year ago

  • File deleted (fndebug.zip)

#22 Updated by Dru Lavigne over 1 year ago

  • File deleted (vol_rsync_stats.log)

#23 Updated by Dru Lavigne over 1 year ago

  • File deleted (vol_rsync_stats_04.log)

Also available in: Atom PDF