Bug 1494236

Summary:

rdiff-backup fails with error IOError: [Errno 61] No data available

Product:

[Fedora] Fedora EPEL

Reporter:

chris kruijntjens <chris>

Component:

rdiff-backup

Assignee:

Kevin Fenzi <kevin>

Status:

CLOSED ERRATA

QA Contact:

Fedora Extras Quality Assurance <extras-qa>

Severity:

urgent

Docs Contact:

Priority:

unspecified

Version:

epel7

CC:

chris, evangelos, frank, kevin

Target Milestone:

---

Target Release:

---

Hardware:

x86_64

OS:

Linux

Whiteboard:

Fixed In Version:

rdiff-backup-1.2.8-24.fc27 rdiff-backup-1.2.8-24.fc26 rdiff-backup-1.2.8-13.el7

Doc Type:

If docs needed, set a value

Doc Text:

Story Points:

---

Clone Of:

Environment:

Last Closed:

2017-12-12 11:22:05 UTC

Type:

Bug

Regression:

---

Mount Type:

---

Documentation:

---

CRM:

Verified Versions:

Category:

---

oVirt Team:

---

RHEL 7.3 requirements from Atomic Host:

Cloudforms Team:

---

Target Upstream Version:

Embargoed:

Attachments:

Description	Flags
Ignore ENODATA when clearing xattrs	none

Description chris kruijntjens 2017-09-21 19:10:53 UTC

Description of problem:

Rdiff-backup fails on second run. (first run is ok, but when the second run runs we get the error IOError: [Errno 61] No data available)

____________________________________________________________________________

Traceback (most recent call last):
  File "/usr/bin/rdiff-backup", line 30, in <module>
    rdiff_backup.Main.error_check_Main(sys.argv[1:])
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/Main.py", line 304, in error_check_Main
    try: Main(arglist)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/Main.py", line 324, in Main
    take_action(rps)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/Main.py", line 280, in take_action
    elif action == "backup": Backup(rps[0], rps[1])
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/Main.py", line 337, in Backup
    backup_final_init(rpout)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/Main.py", line 501, in backup_final_init
    checkdest_if_necessary(rpout)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/Main.py", line 920, in checkdest_if_necessary
    dest_rp.conn.regress.Regress(dest_rp)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/regress.py", line 71, in Regress
    for rf in iterate_meta_rfs(mirror_rp, inc_rpath): ITR(rf.index, rf)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/rorpiter.py", line 281, in __call__
    last_branch.fast_process(*args)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/regress.py", line 268, in fast_process
    if rf.metadata_rorp.isreg(): self.restore_orig_regfile(rf)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/regress.py", line 292, in restore_orig_regfile
    rpath.copy_attribs(rf.metadata_rorp, tf)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/rpath.py", line 181, in copy_attribs
    if Globals.eas_write: rpout.write_ea(rpin.get_ea())
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/rpath.py", line 1347, in write_ea
    ea.write_to_rp(self)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/eas_acls.py", line 111, in write_to_rp
    self.clear_rp(rp)
  File "/usr/lib64/python2.7/site-packages/rdiff_backup/eas_acls.py", line 91, in clear_rp
    rp.conn.xattr.removexattr(rp.path, name, rp.issym())
IOError: [Errno 61] No data available
Version-Release number of selected component (if applicable):


How reproducible:

-delete the backup destination and start over.
-2th backup run always fails.

Comment 1 Kevin Fenzi 2017-09-22 21:55:33 UTC

What kind of filesystem is both the source and the destination?

Does a 'rdiff-backup --check-destination-dir /destination' complete ok?

Comment 2 chris kruijntjens 2017-09-23 06:45:40 UTC

Both are xfs.

Check-destination-dir fails with the same error.

Comment 3 Kevin Fenzi 2017-09-25 22:16:33 UTC

And no filesystem errors in dmesg or on mounting those volumes?

Does running with '--no-eas' work? It seems like it's some extended attribute that it doesn't know how to process. 

ALso can you do a run with -v9 and see if you can tell what exact file it has problems with so we can narrow down what EA is the problem? (NOTE: this will result in a ton of output)

Comment 4 chris kruijntjens 2017-09-26 16:02:55 UTC

Hi Kevin,

No filesystem errors waht so ever. I am now trying with the option --no-eas to see if that works.

if that works i will try again without the option --no-eas and will log to file with -v9 option to see if and which file is cousing problems.

How can this happen? it always worked before?

Comment 5 chris kruijntjens 2017-09-26 19:41:41 UTC

hi,

i just tested it and when i use --no-eas the backup works as designed. how can i find the file that is causing trouble? -v9 gives me lots of output.

Comment 6 chris kruijntjens 2017-09-26 20:10:41 UTC

this is the log. If i want to backup eas again it fails again.


Tue Sep 26 22:07:04 2017  Using rdiff-backup version 1.2.8
Tue Sep 26 22:07:04 2017  Executing ssh -C root@dcfs01 rdiff-backup --server
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.get with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'version'
Tue Sep 26 22:07:04 2017  Client received (0): '1.2.8'
Tue Sep 26 22:07:04 2017  Registering connection 1
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: SetConnections.init_connection_remote with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 1
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: log.Log.setverbosity with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 9
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: log.Log.setterm_verbosity with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 9
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'print_statistics'
Tue Sep 26 22:07:04 2017  Client sending (0): 1
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): '/'
Tue Sep 26 22:07:04 2017  Client received (0): {'size': 262, 'uid': 0, 'perms': 365, 'inode': 64, 'devloc': 64768L, 'nlink': 18, 'mtime': 1506456398, 'gid': 0, 'atime': 1506455573, 'type': 'dir', 'ctime': 1506456398}
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): Path: /
Index: ()
Data: {'size': 262, 'uid': 0, 'perms': 365, 'inode': 64, 'devloc': 64768L, 'nlink': 18, 'mtime': 1506456398, 'gid': 0, 'atime': 1506455573, 'type': 'dir', 'ctime': 1506456398}
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): '/'
Tue Sep 26 22:07:04 2017  Client received (0): {'size': 262, 'uid': 0, 'perms': 365, 'inode': 64, 'devloc': 64768L, 'nlink': 18, 'mtime': 1506456398, 'gid': 0, 'atime': 1506455573, 'type': 'dir', 'ctime': 1506456398}
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): Path: /
Index: ()
Data: {'size': 262, 'uid': 0, 'perms': 365, 'inode': 64, 'devloc': 64768L, 'nlink': 18, 'mtime': 1506456398, 'gid': 0, 'atime': 1506455573, 'type': 'dir', 'ctime': 1506456398}
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: rpath.make_file_dict with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): '/'
Tue Sep 26 22:07:04 2017  Client received (0): {'size': 262, 'uid': 0, 'perms': 365, 'inode': 64, 'devloc': 64768L, 'nlink': 18, 'mtime': 1506456398, 'gid': 0, 'atime': 1506455573, 'type': 'dir', 'ctime': 1506456398}
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: rpath.setdata_local with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): Path: /
Index: ()
Data: {'size': 262, 'uid': 0, 'perms': 365, 'inode': 64, 'devloc': 64768L, 'nlink': 18, 'mtime': 1506456398, 'gid': 0, 'atime': 1506455573, 'type': 'dir', 'ctime': 1506456398}
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: os.getuid with 0 arguments
Tue Sep 26 22:07:04 2017  Client received (0): 0
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: os.listdir with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): '/'
Tue Sep 26 22:07:04 2017  Client received (0): ['boot', 'dev', 'home', 'proc', 'run', 'sys', 'etc', 'root', 'var', 'tmp', 'usr', 'bin', 'sbin', 'lib', 'lib64', 'media', 'mnt', 'opt', 'srv', '.autorelabel', 'lost+found']
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.get with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'restrict_path'
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Time.setcurtime_local with 1 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 1506456424
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'client_conn'
Tue Sep 26 22:07:04 2017  Client sending (0): LocalConnection
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.postset_regexp_local with 3 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'no_compression_regexp'
Tue Sep 26 22:07:04 2017  Client sending (0): '(?i).*\\.(gz|z|bz|bz2|tgz|zip|rpm|deb|jpg|jpeg|gif|png|jp2|mp3|ogg|avi|wmv|mpeg|mpg|rm|mov|flac|shn|pgp|gpg|rz|lzh|zoo|lharc|rar|arj|asc)$'
Tue Sep 26 22:07:04 2017  Client sending (0): None
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: robust.install_signal_handlers with 0 arguments
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Hardlink.initialize_dictionaries with 0 arguments
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'isbackup_reader'
Tue Sep 26 22:07:04 2017  Client sending (0): 1
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'backup_reader'
Tue Sep 26 22:07:04 2017  Client sending (0): PipeConnection 1
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'backup_writer'
Tue Sep 26 22:07:04 2017  Client sending (0): LocalConnection
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'rbdir'
Tue Sep 26 22:07:04 2017  Client sending (0): Path: /home/usb_backup/dcfs01/rdiff-backup-data
Index: ()
Data: {'uid': 0, 'perms': 448, 'type': 'dir', 'gname': 'root', 'ctime': 1506456317, 'devloc': 64772L, 'uname': 'root', 'nlink': 3, 'gid': 0, 'mtime': 1506456317, 'atime': 1506456318, 'inode': 1657467696, 'size': 4096}
Tue Sep 26 22:07:04 2017  Client received (0): None
Tue Sep 26 22:07:04 2017  Client sending (0): ConnectionRequest: fs_abilities.get_readonly_fsa with 2 arguments
Tue Sep 26 22:07:04 2017  Client sending (0): 'source'
Tue Sep 26 22:07:04 2017  Client sending (0): Path: /
Index: ()
Data: {'size': 262, 'uid': 0, 'perms': 365, 'inode': 64, 'devloc': 64768L, 'nlink': 18, 'mtime': 1506456398, 'gid': 0, 'atime': 1506455573, 'type': 'dir', 'ctime': 1506456398}
Tue Sep 26 22:07:04 2017  Client received (0): -----------------------------------------------------------------
Detected abilities for source (read only) file system:
  Access control lists                         On
  Extended attributes                          On
  Windows access control lists                 Off
  Case sensitivity                             On
  Escape DOS devices                           Off
  Escape trailing spaces                       Off
  Mac OS X style resource forks                Off
  Mac OS X Finder information                  Off
-----------------------------------------------------------------
Tue Sep 26 22:07:04 2017  -----------------------------------------------------------------
Detected abilities for source (read only) file system:
  Access control lists                         On
  Extended attributes                          On
  Windows access control lists                 Off
  Case sensitivity                             On
  Escape DOS devices                           Off
  Escape trailing spaces                       Off
  Mac OS X style resource forks                Off
  Mac OS X Finder information                  Off
-----------------------------------------------------------------
Tue Sep 26 22:07:04 2017  Making directory /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0
Tue Sep 26 22:07:04 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/5-_ a.snapshot.gz
Tue Sep 26 22:07:04 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/5-_ a.snapshot.gz
Tue Sep 26 22:07:04 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/uniᄉ
Tue Sep 26 22:07:04 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/uniᄉ
Tue Sep 26 22:07:04 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/:\"
Tue Sep 26 22:07:04 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/:\"
Tue Sep 26 22:07:04 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/A
Tue Sep 26 22:07:04 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/A
Tue Sep 26 22:07:04 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/foo
Tue Sep 26 22:07:04 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/foo
Tue Sep 26 22:07:04 2017  Making directory /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/hl
Tue Sep 26 22:07:04 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/hardlinked_file1
Tue Sep 26 22:07:04 2017  Hard linking /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/hl/hardlinked_file2 to /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/hardlinked_file1
Tue Sep 26 22:07:05 2017  Unable to import win32security module. Windows ACLs
not supported by filesystem at /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0
Tue Sep 26 22:07:05 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/dir_inc_check
Tue Sep 26 22:07:05 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/dir_inc_check
Tue Sep 26 22:07:05 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/regfile
Tue Sep 26 22:07:05 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/regfile
Tue Sep 26 22:07:05 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/high_perms_file
Tue Sep 26 22:07:05 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/high_perms_dir
Tue Sep 26 22:07:05 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/high_perms_file
Tue Sep 26 22:07:05 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/high_perms_dir
Tue Sep 26 22:07:05 2017  Touching /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/symlinked_file1
Tue Sep 26 22:07:05 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/symlinked_file2
Tue Sep 26 22:07:05 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0/symlinked_file1
Tue Sep 26 22:07:05 2017  escape_dos_devices not required by filesystem at /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0
Tue Sep 26 22:07:05 2017  Deleting /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0
Tue Sep 26 22:07:05 2017  Removing directory /home/usb_backup/dcfs01/rdiff-backup-data/rdiff-backup.tmp.0
Tue Sep 26 22:07:05 2017  -----------------------------------------------------------------
Detected abilities for destination (read/write) file system:
  Ownership changing                           On
  Hard linking                                 On
  fsync() directories                          On
  Directory inc permissions                    On
  High-bit permissions                         On
  Symlink permissions                          Off
  Extended filenames                           On
  Windows reserved filenames                   Off
  Access control lists                         On
  Extended attributes                          On
  Windows access control lists                 Off
  Case sensitivity                             On
  Escape DOS devices                           Off
  Escape trailing spaces                       Off
  Mac OS X style resource forks                Off
  Mac OS X Finder information                  Off
-----------------------------------------------------------------
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'eas_active'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'eas_write'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'eas_conn'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'eas_active'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set_local with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'eas_conn'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'eas_write'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'acls_active'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'acls_write'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'acls_conn'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'acls_active'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set_local with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'acls_conn'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'acls_write'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'win_acls_active'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'win_acls_write'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'win_acls_conn'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'resource_forks_active'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'resource_forks_write'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'resource_forks_conn'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'carbonfile_active'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'carbonfile_write'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'carbonfile_conn'
Tue Sep 26 22:07:05 2017  Client sending (0): None
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'preserve_hardlinks'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'fsync_directories'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'change_ownership'
Tue Sep 26 22:07:05 2017  Client sending (0): 1
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'symlink_perms'
Tue Sep 26 22:07:05 2017  Client sending (0): 0
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'chars_to_quote'
Tue Sep 26 22:07:05 2017  Client sending (0): ''
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'escape_dos_devices'
Tue Sep 26 22:07:05 2017  Client sending (0): 0
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'escape_trailing_spaces'
Tue Sep 26 22:07:05 2017  Client sending (0): 0
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'must_escape_dos_devices'
Tue Sep 26 22:07:05 2017  Client sending (0): 0
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Backup: must_escape_dos_devices = 0
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: Globals.set with 2 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): 'must_escape_trailing_spaces'
Tue Sep 26 22:07:05 2017  Client sending (0): 0
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Client sending (0): ConnectionRequest: log.Log.open_logfile_allconn with 1 arguments
Tue Sep 26 22:07:05 2017  Client sending (0): LocalConnection
Tue Sep 26 22:07:05 2017  Client received (0): None
Tue Sep 26 22:07:05 2017  Regressing to Tue Sep 26 17:39:22 2017
Tue Sep 26 22:07:05 2017  Regressing file home/.htpasswd
Tue Sep 26 22:07:05 2017  Writing file object to /home/usb_backup/dcfs01/home/rdiff-backup.tmp.1
Tue Sep 26 22:07:05 2017  Copying attributes from ('home', '.htpasswd') to /home/usb_backup/dcfs01/home/rdiff-backup.tmp.1
Tue Sep 26 22:07:05 2017  Setting time of /home/usb_backup/dcfs01/home/rdiff-backup.tmp.1 to 1458974360
Tue Sep 26 22:07:05 2017  Renaming /home/usb_backup/dcfs01/home/rdiff-backup.tmp.1 to /home/usb_backup/dcfs01/home/.htpasswd
Tue Sep 26 22:07:05 2017  Regressing file home/.sql_backup.sh.swp
Tue Sep 26 22:07:05 2017  Writing file object to /home/usb_backup/dcfs01/home/rdiff-backup.tmp.2
Tue Sep 26 22:07:05 2017  Copying attributes from ('home', '.sql_backup.sh.swp') to /home/usb_backup/dcfs01/home/rdiff-backup.tmp.2
Tue Sep 26 22:07:05 2017  Setting time of /home/usb_backup/dcfs01/home/rdiff-backup.tmp.2 to 1483522012
Tue Sep 26 22:07:05 2017  Renaming /home/usb_backup/dcfs01/home/rdiff-backup.tmp.2 to /home/usb_backup/dcfs01/home/.sql_backup.sh.swp
Tue Sep 26 22:07:05 2017  Regressing file home/Printer_drivers/AUTORUN.INF
Tue Sep 26 22:07:05 2017  Writing file object to /home/usb_backup/dcfs01/home/Printer_drivers/rdiff-backup.tmp.3
Tue Sep 26 22:07:05 2017  Copying attributes from ('home', 'Printer_drivers', 'AUTORUN.INF') to /home/usb_backup/dcfs01/home/Printer_drivers/rdiff-backup.tmp.3
Tue Sep 26 22:07:05 2017  Setting time of /home/usb_backup/dcfs01/home/Printer_drivers/rdiff-backup.tmp.3 to 1384418825
Tue Sep 26 22:07:05 2017  Renaming /home/usb_backup/dcfs01/home/Printer_drivers/rdiff-backup.tmp.3 to /home/usb_backup/dcfs01/home/Printer_drivers/AUTORUN.INF
Tue Sep 26 22:07:05 2017  Regressing file home/Printer_drivers/Application/SPD/Setup.exe
Tue Sep 26 22:07:05 2017  Writing file object to /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/rdiff-backup.tmp.4
Tue Sep 26 22:07:06 2017  Copying attributes from ('home', 'Printer_drivers', 'Application', 'SPD', 'Setup.exe') to /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/rdiff-backup.tmp.4
Tue Sep 26 22:07:06 2017  Setting time of /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/rdiff-backup.tmp.4 to 1414543105
Tue Sep 26 22:07:06 2017  Renaming /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/rdiff-backup.tmp.4 to /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/Setup.exe
Tue Sep 26 22:07:06 2017  Regressing file home/Printer_drivers/Application/SPD/VERSION.VER
Tue Sep 26 22:07:06 2017  Writing file object to /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/rdiff-backup.tmp.5
Tue Sep 26 22:07:06 2017  Copying attributes from ('home', 'Printer_drivers', 'Application', 'SPD', 'VERSION.VER') to /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/rdiff-backup.tmp.5
Tue Sep 26 22:07:06 2017  Setting time of /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/rdiff-backup.tmp.5 to 1430109823
Tue Sep 26 22:07:06 2017  Renaming /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/rdiff-backup.tmp.5 to /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD/VERSION.VER
Tue Sep 26 22:07:06 2017  Regressing attributes of /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD
Tue Sep 26 22:07:06 2017  Copying attributes from ('home', 'Printer_drivers', 'Application', 'SPD') to /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD
Tue Sep 26 22:07:06 2017  Setting time of /home/usb_backup/dcfs01/home/Printer_drivers/Application/SPD to 1495129026
Tue Sep 26 22:07:06 2017  Regressing attributes of /home/usb_backup/dcfs01/home/Printer_drivers/Application
Tue Sep 26 22:07:06 2017  Copying attributes from ('home', 'Printer_drivers', 'Application') to /home/usb_backup/dcfs01/home/Printer_drivers/Application

Comment 7 Evangelos Foutras 2017-10-05 12:34:46 UTC

Created attachment 1334796 [details]
Ignore ENODATA when clearing xattrs

On a problematic directory, rdiff-backup tries to remove the following attributes:

system.posix_acl_access
trusted.SGI_ACL_FILE

I believe the issue originates from the fact that deleting the first attribute also clears the second.

Steps to reproduce:

# mkdir -p rdiff-test/test
# setfacl -m u:nobody:x rdiff-test/test
# rdiff-backup rdiff-test rdiff-test-backup
# touch rdiff-test/test/kitten
# rdiff-backup rdiff-test rdiff-test-backup

Upstream report: https://github.com/sol1/rdiff-backup/issues/20

For now I've addressed this locally by adding a clause that ignores errno 61. Perhaps the attached patch could be included in the epel/rdiff-backup package.

Comment 8 Kevin Fenzi 2017-12-02 22:34:22 UTC

Sorry the massive delay here. 

Yes, that looks reasonable, I will push out updates with the patch. Thanks!

Comment 9 Fedora Update System 2017-12-02 23:04:06 UTC

rdiff-backup-1.2.8-24.fc26 has been submitted as an update to Fedora 26. https://bodhi.fedoraproject.org/updates/FEDORA-2017-00d432f6fc

Comment 10 Fedora Update System 2017-12-02 23:04:15 UTC

rdiff-backup-1.2.8-24.fc27 has been submitted as an update to Fedora 27. https://bodhi.fedoraproject.org/updates/FEDORA-2017-ec4c70433e

Comment 11 Fedora Update System 2017-12-02 23:04:21 UTC

rdiff-backup-1.2.8-13.el7 has been submitted as an update to Fedora EPEL 7. https://bodhi.fedoraproject.org/updates/FEDORA-EPEL-2017-f3006764de

Comment 12 Fedora Update System 2017-12-03 22:02:17 UTC

rdiff-backup-1.2.8-24.fc27 has been pushed to the Fedora 27 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-ec4c70433e

Comment 13 Fedora Update System 2017-12-03 22:18:12 UTC

rdiff-backup-1.2.8-13.el7 has been pushed to the Fedora EPEL 7 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-EPEL-2017-f3006764de

Comment 14 Fedora Update System 2017-12-03 22:46:52 UTC

rdiff-backup-1.2.8-24.fc26 has been pushed to the Fedora 26 testing repository. If problems still persist, please make note of it in this bug report.
See https://fedoraproject.org/wiki/QA:Updates_Testing for
instructions on how to install test updates.
You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-00d432f6fc

Comment 15 Fedora Update System 2017-12-12 11:22:05 UTC

rdiff-backup-1.2.8-24.fc27 has been pushed to the Fedora 27 stable repository. If problems still persist, please make note of it in this bug report.

Comment 16 Fedora Update System 2017-12-12 13:43:09 UTC

rdiff-backup-1.2.8-24.fc26 has been pushed to the Fedora 26 stable repository. If problems still persist, please make note of it in this bug report.

Comment 17 Fedora Update System 2017-12-19 19:13:04 UTC

rdiff-backup-1.2.8-13.el7 has been pushed to the Fedora EPEL 7 stable repository. If problems still persist, please make note of it in this bug report.