Re: [rdiff-backup-users] --check-destination-dir taking a very long time

[Walt Mankowski]

Thanks for the suggestions, but while that might have caused the
problem over the weekend, the most recent log I posted failed on a
completely different exception:

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/lib/python2.7/dist-packages/rdiff_backup/Main.py", line 304, in 
error_check_Main                                                                
          
    try: Main(arglist)
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/Main.py", line 324, in 
Main
    take_action(rps)
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/Main.py", line 280, in 
take_action                                                                     
          
    elif action == "backup": Backup(rps[0], rps[1])
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/Main.py", line 343, in 
Backup
    backup.Mirror_and_increment(rpin, rpout, incdir)
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/backup.py", line 51, in 
Mirror_and_increment                                                            
         
    DestS.patch_and_increment(dest_rpath, source_diffiter, inc_rpath)
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/backup.py", line 243, in 
patch_and_increment                                                             
        
    ITR(diff.index, diff)
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/rorpiter.py", line 268, 
in __call__                                                                     
         
    else: self.root_branch.start_process(*args)
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/backup.py", line 721, in 
start_process                                                                   
        
    inc = increment.Increment(diff_rorp, self.base_rp, inc_prefix)
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/increment.py", line 41, 
in Increment                                                                    
         
    elif mirror.isdir(): incrp = makedir(mirror, incpref)
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/increment.py", line 103, 
in makedir                                                                      
        
    dirsign = get_inc(incpref, "dir")
  File "/usr/lib/python2.7/dist-packages/rdiff_backup/increment.py", line 123, 
in get_inc                                                                      
        
    assert not incrp.lstat(), incrp
AssertionError: Path: 
/backup/scruffy/rdiff-backup-data/increments.2019-09-07T03:01:01-04:00.dir      
                                                                 
Index: ('increments.2019-09-07T03:01:01-04:00.dir',)
Data: {'acl': <rdiff_backup.eas_acls.AccessControlLists instance at 
0x7ff36b8edc68>, 'uid': 0, 'perms': 493, 'type': 'reg', 'gname': 'root', 'ea': 
<rdiff_backup.eas_acls.ExtendedAttributes instance at 0x7ff36b8edc20>, 'ctime': 
1567926069, 'devloc': 2113L, 'uname': 'root', 'nlink': 1, 'gid': 0, 'mtime': 
1567531730, 'atime': 1567926069, 'inode': 29941839, 'size': 0}


On Tue, Sep 10, 2019 at 02:36:00PM +0200, Ilario Gelmetti wrote:
> As Dominic pointed out, I also suspect that the message refers to the
> /tmp partition.
> On some system, that partition is in RAM, so the available space on /tmp
> may not relate to free disk space.
> Can you try with the --tempdir (e.g. --tempdir /opt) option suggested by
> Dominic?
> Ciao,
> Ilario
> 
> On 9/10/19 1:49 PM, Walt Mankowski wrote:
> > It's not likely. That partition has 14 GB free.
> > 
> > On Tue, Sep 10, 2019 at 07:52:38AM +0300, Dominic Raferd wrote:
> >> Is it possible you are running out of temporary file space? You can specify
> >> a different tmp location with switch --tempdir (or, if running to remote
> >> server, --remote-tempdir). When checking an archive rdiff-backup may need a
> >> lot of temporary space for all that unpacking. By the way, it may not be
> >> apparent that the temporary file location is being used (or running out of
> >> space) as the temporary files that rdiff-backup creates are not visible
> >> there (there is some technical reason for this that I don't understand).
> >>
> >> On Tue, 10 Sep 2019 at 04:53, Walt Mankowski <address@hidden> wrote:
> >>
> >>> I found a file named
> >>>
> >>>   rdiff-backup-data/current_mirror.2019-09-08T03:01:02-04:00.data
> >>>
> >>> which contained
> >>>
> >>>   4351
> >>>
> >>> I moved it out of the way and reran the backup command. This time it
> >>> through an exception. The output is in the attached log file.
> >>>
> >>> Walt
> >>>
> >>> On Mon, Sep 09, 2019 at 08:17:04PM -0400, Walt Mankowski wrote:
> >>>> I ran
> >>>>
> >>>>   $ sudo rdiff-backup -v9 --print-statistics --exclude-filelist
> >>> /usr/local/etc/rdiff_exclude / /backup/scruffy 2>&1 | tee rdiff-backup.txt
> >>>>
> >>>> This time it exited right away. I've attached the log file, where the
> >>>> key message is
> >>>>
> >>>>   Fatal Error: It appears that a previous rdiff-backup session with
> >>>>   process id 4351 is still running.
> >>>>
> >>>> Process 4351 is /lib/systemd/systemd-resolved
> >>>>
> >>>> Is it safe to rerun it with --force?
> >>>>
> >>>> Walt
> >>>>
> >>>> On Mon, Sep 09, 2019 at 08:04:46PM -0400, Patrik Dufresne wrote:
> >>>>> At this point, I would just kill all the rdiff-backup process. Then
> >>>>> manually start the backup again to the USB drive. Run it with -v9 and
> >>> post
> >>>>> the logs here.
> >>>>>
> >>>>> That should provide us enough guidance about what is going on. Either
> >>> the
> >>>>> process will fail quickly (this is what I expect). If the process is
> >>> taking
> >>>>> too long, try to give us the logs that you gather.
> >>>>>
> >>>>> Since it's USB, could you check if the USB speed is alright ? If for
> >>>>> whatever reason the USB speed switched from USB 3.0 to USB 2.0. It
> >>> might
> >>>>> take for ever to do a backup. You could double check this with "lsusb
> >>> -t".
> >>>>> Expect 5000M for USB 3
> >>>>>
> >>>>> ikus060@ikus060-laptop:~/workspace/HPUCA/hpuca-valuepack.git$ lsusb -t
> >>>>> /:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/8p, 10000M
> >>>>>     |__ Port 4: Dev 2, If 0, Class=Mass Storage, Driver=usb-storage,
> >>> 5000M
> >>>>> /:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/16p, 480M
> >>>>>     |__ Port 5: Dev 14, If 0, Class=Hub, Driver=hub/3p, 480M
> >>>>>
> >>>>> A look to "dmesg" might also reveal some information about a change to
> >>> the
> >>>>> usb channel.
> >>>>>
> >>>>> --
> >>>>> Patrik Dufresne Service Logiciel inc.
> >>>>> http://www.patrikdufresne.com <http://patrikdufresne.com/>/
> >>>>> 514-971-6442
> >>>>> 130 rue Doris
> >>>>> St-Colomban, QC J5K 1T9
> >>>>>
> >>>>>
> >>>>> On Mon, Sep 9, 2019 at 7:47 PM Walt Mankowski <address@hidden>
> >>> wrote:
> >>>>>
> >>>>>> On Mon, Sep 09, 2019 at 07:38:52PM -0400, Patrik Dufresne wrote:
> >>>>>>> Hum, this is strange. It should not fail with a "no space left on
> >>>>>> device".
> >>>>>>
> >>>>>> Agreed! That's why I originally thought it must have been some sort
> >>> of
> >>>>>> USB glitch.
> >>>>>>
> >>>>>>> Could you provide the log generate with -v9 ? Plz provide the full
> >>>>>> command
> >>>>>>> line you used.
> >>>>>>
> >>>>>> So kill the run with -v8?
> >>>>>>
> >>>>>>> What is the filesystem of your USB drive ?
> >>>>>>
> >>>>>> ext4
> >>>>>>
> >>>>>>> If you try to run the backup again do you have an error?
> >>>>>>
> >>>>>> In fact that happened last night. My normal nightly backup kicked in
> >>>>>> while a previous attempt at running --check-destination-dir was still
> >>>>>> running. The cronjob reported:
> >>>>>>
> >>>>>>   Previous backup seems to have failed, regressing destination now.
> >>>>>>   Fatal Error: Killed with signal 15
> >>>>>>
> >>>>>> The latter was when I killed it when I woke up and saw that both of
> >>>>>> them were running.
> >>>>>>
> >>>>>> Walt
> >>>>>>
> >>>>>>> On Mon, Sep 9, 2019, 7:33 PM Walt Mankowski, <address@hidden>
> >>> wrote:
> >>>>>>>
> >>>>>>>> Good idea! But unfortunately it doesn't seem to be the problem:
> >>>>>>>>
> >>>>>>>> % df -hi /backup
> >>>>>>>> Filesystem     Inodes IUsed IFree IUse% Mounted on
> >>>>>>>> /dev/sde1        117M   19M   98M   17% /backup
> >>>>>>>>
> >>>>>>>>
> >>>>>>>> On Mon, Sep 09, 2019 at 07:23:14PM -0400, Patrik Dufresne wrote:
> >>>>>>>>> Hello Walt, could you double check the disk space. Especially
> >>> the
> >>>>>> number
> >>>>>>>> of
> >>>>>>>>> inode ? It's probably the root cause of your issue.
> >>>>>>>>>
> >>>>>>>>> On Mon, Sep 9, 2019, 7:19 PM Walt Mankowski, <
> >>> address@hidden>
> >>>>>> wrote:
> >>>>>>>>>
> >>>>>>>>>> I've been running rdiff-backup to an external USB drive for
> >>> years
> >>>>>>>>>> without any problems. Over the weekend my backup failed with
> >>>>>>>>>>
> >>>>>>>>>>   Exception '[Errno 28] No space left on device
> >>>>>>>>>>
> >>>>>>>>>> This is odd, since there is 1.2 TB free on the drive. I
> >>> didn't see
> >>>>>> any
> >>>>>>>>>> errors in syslog, and I was able to create a new file on the
> >>> drive
> >>>>>>>>>> without any problem.
> >>>>>>>>>>
> >>>>>>>>>> Thinking it might have been a USB glitch I rebooted the
> >>> machine and
> >>>>>>>>>> now I'm running
> >>>>>>>>>>
> >>>>>>>>>>   rdiff-backup --check-destination-dir
> >>>>>>>>>>
> >>>>>>>>>> to recover the backup directory. It was taking a very long
> >>> time,
> >>>>>> and I
> >>>>>>>>>> restarted it with the -v8 hoping I might get some clue as to
> >>> what
> >>>>>> it
> >>>>>>>>>> was doing. Unfortunately after spitting out some
> >>> routine-looking
> >>>>>>>>>> output in the first few seconds it's now been running in
> >>> silence
> >>>>>> for
> >>>>>>>>>> nearly 12 hours.
> >>>>>>>>>>
> >>>>>>>>>> It's getting CPU time and I don't see any errors in syslog,
> >>> so I'm
> >>>>>>>>>> assuming that it's doing something. But I don't have any
> >>> idea what
> >>>>>>>>>> it's doing, if it's working correctly, or how much longer
> >>> it's
> >>>>>> likely
> >>>>>>>>>> to take.
> >>>>>>>>>>
> >>>>>>>>>> Is it normal that a regression takes this long? /backup is
> >>>>>> currently
> >>>>>>>>>> at 527 GB.
> >>>>>>>>>>
> >>>>>>>>>> Thanks.
> >>>>>>>>>>
> >>>>>>>>>> Walt
> >>>>>>>>>>
> >>>>>>>>>> _______________________________________________
> >>>>>>>>>> rdiff-backup-users mailing list at
> >>> address@hidden
> >>>>>>>>>> https://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
> >>>>>>>>>> Wiki URL:
> >>>>>>>>>>
> >>>>>> http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
> >>>>>>>>
> >>>>>>>> _______________________________________________
> >>>>>>>> rdiff-backup-users mailing list at address@hidden
> >>>>>>>> https://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
> >>>>>>>> Wiki URL:
> >>>>>>>>
> >>> http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
> >>>>>>
> >>>>>> _______________________________________________
> >>>>>> rdiff-backup-users mailing list at address@hidden
> >>>>>> https://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
> >>>>>> Wiki URL:
> >>>>>> http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki
> >>>
> >>>> Mon Sep  9 20:09:56 2019  Using rdiff-backup version 1.2.8
> >>>> Mon Sep  9 20:09:57 2019  Unable to import win32security module. Windows
> >>> ACLs
> >>>> not supported by filesystem at /
> >>>> Mon Sep  9 20:09:57 2019  escape_dos_devices not required by filesystem
> >>> at /
> >>>> Mon Sep  9 20:09:57 2019
> >>> -----------------------------------------------------------------
> >>>> 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
> >>>> -----------------------------------------------------------------
> >>>> Mon Sep  9 20:09:57 2019  Making directory
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/5-_ a.snapshot.gz
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/5-_ a.snapshot.gz
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/uniᄉ
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/uniᄉ
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/:\"
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/:\"
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/A
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/A
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/foo
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/foo
> >>>> Mon Sep  9 20:09:57 2019  Making directory
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/hl
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/hardlinked_file1
> >>>> Mon Sep  9 20:09:57 2019  Hard linking
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/hl/hardlinked_file2 
> >>> to
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/hardlinked_file1
> >>>> Mon Sep  9 20:09:57 2019  Unable to import win32security module. Windows
> >>> ACLs
> >>>> not supported by filesystem at
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/dir_inc_check
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/dir_inc_check
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/regfile
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/regfile
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/high_perms_file
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/high_perms_dir
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/high_perms_file
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/high_perms_dir
> >>>> Mon Sep  9 20:09:57 2019  Touching
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/symlinked_file1
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/symlinked_file2
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0/symlinked_file1
> >>>> Mon Sep  9 20:09:57 2019  escape_dos_devices not required by filesystem
> >>> at /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0
> >>>> Mon Sep  9 20:09:57 2019  Deleting
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0
> >>>> Mon Sep  9 20:09:57 2019  Removing directory
> >>> /backup/scruffy/rdiff-backup-data/rdiff-backup.tmp.0
> >>>> Mon Sep  9 20:09:57 2019
> >>> -----------------------------------------------------------------
> >>>> Detected abilities for destination (read/write) file system:
> >>>>   Ownership changing                         Mon Sep  9 20:09:57 2019
> >>> Fatal Error: It appears that a previous rdiff-backup session with process
> >>>> id 4351 is still running.  If two different rdiff-backup processes write
> >>>> the same repository simultaneously, data corruption will probably
> >>>> result.  To proceed with regress anyway, rerun rdiff-backup with the
> >>>> --force option.
> >>>>   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
> >>>> -----------------------------------------------------------------
> >>>> Mon Sep  9 20:09:57 2019  Backup: must_escape_dos_devices = 0
> 




> _______________________________________________
> rdiff-backup-users mailing list at address@hidden
> https://lists.nongnu.org/mailman/listinfo/rdiff-backup-users
> Wiki URL: http://rdiff-backup.solutionsfirst.com.au/index.php/RdiffBackupWiki