search

bit-team / backintime

Back In Time - An easy-to-use backup tool for GNU/Linux using rsync in the back
https://backintime.readthedocs.io
GNU General Public License v2.0
2.09k stars 204 forks source link

anacron jobs starts too soon after udev triggered backup #126

Closed Germar closed 9 years ago

Germar commented 9 years ago

backintime-gnome/common 1.0.34-0.1 (ubuntu)

When creating an udev triggered, encrypted local backup to a USB attached disk from the gnome gui, the anacrontab line created fires the backintime backup job immediately after udev triggers anacron, which seems to be too early. Jun 22 10:39:22 uh552 backintime (isti): INFO: Lock Jun 22 10:39:22 uh552 backintime (isti): ERROR: A titkosított mappa konfigurációja nem található Jun 22 10:39:22 uh552 backintime (isti): INFO: Unlock

For some reason, encfs can't find it's config. The syslog roughly translated: "Cannot find encrypted folder config".

If I just add a minute delay to the anacron_line, everything works fine. A few seconds would probably suffice, but it seems only minutes can be specified for anacron.

Non-encrypted backup does not seem to need this delay.

Imported from Launchpad using lp2gh.

Germar commented 9 years ago

(by gyorsok)

Germar commented 9 years ago

(by germar) Thanks for the patch. I didn't add the 1min delay because I think it's confusing for people who test the udev/anacron schedule. They might think it doesn't work and fiddle around during the minute.

Anyways, it turns out anacron wasn't the best choice. I'll have to rewrite the part of anacron by my self because anacron does always mark a job as done for the day even if BIT failed.

Germar commented 9 years ago

(by germar) Found an easy solution for this by letting BackInTime wait 30sec for snapshot folder come available even if notifications are disabled. Please try out attached patch with 'sudo patch /usr/share/backintime/common/snapshots.py < snapshots.patch'

Germar commented 9 years ago

(by mauromol) Hi Germar, with 1.1.2 I still get this problem. As sson as I plug in the device, the BIT tray icon appears saying it can't find the folder and suggests to wait 30 seconds. But it doesn't start automatically then, I must manually start the backup process from the GUI...

Any idea?

Germar commented 9 years ago

(by germar) Hi Mauro,

Could you please attach your syslog starting from first udev messages about the new connection?

Regards, Germar

Germar commented 9 years ago

(by mauromol) Here is is:

Feb 4 22:19:00 hppb kernel: [ 7615.521927] usb 3-3: new high-speed USB device number 8 using xhci_hcd Feb 4 22:19:00 hppb kernel: [ 7615.541705] usb 3-3: New USB device found, idVendor=1bcf, idProduct=0c31 Feb 4 22:19:00 hppb kernel: [ 7615.541709] usb 3-3: New USB device strings: Mfr=1, Product=2, SerialNumber=3 Feb 4 22:19:00 hppb kernel: [ 7615.541711] usb 3-3: Product: USB to Serial-ATA bridge Feb 4 22:19:00 hppb kernel: [ 7615.541713] usb 3-3: Manufacturer: Sunplus Innovation Technology Feb 4 22:19:00 hppb kernel: [ 7615.541714] usb 3-3: SerialNumber: FDC0FD10EA00000FD0FCAF55667939 Feb 4 22:19:00 hppb kernel: [ 7615.543532] usbip-host 3-3:1.0: 3-3 is not in match_busid table... skip! Feb 4 22:19:00 hppb kernel: [ 7615.543550] usb-storage 3-3:1.0: USB Mass Storage device detected Feb 4 22:19:00 hppb kernel: [ 7615.543607] scsi7 : usb-storage 3-3:1.0 Feb 4 22:19:00 hppb mtp-probe: checking bus 3, device 8: "/sys/devices/pci0000:00/0000:00:14.0/usb3/3-3" Feb 4 22:19:00 hppb mtp-probe: bus: 3, device: 8 was not an MTP device Feb 4 22:19:00 hppb laptop-mode: Laptop mode Feb 4 22:19:00 hppb laptop-mode: enabled, not active Feb 4 22:19:00 hppb laptop-mode: Laptop mode Feb 4 22:19:00 hppb laptop-mode: enabled, not active Feb 4 22:19:01 hppb kernel: [ 7616.548233] scsi 7:0:0:0: Direct-Access WDC WD10 EADS-11M2B1 0200 PQ: 0 ANSI: 4 Feb 4 22:19:01 hppb kernel: [ 7616.548469] sd 7:0:0:0: Attached scsi generic sg2 type 0 Feb 4 22:19:01 hppb kernel: [ 7616.549535] sd 7:0:0:0: [sdb] 1953525168 512-byte logical blocks: (1.00 TB/931 GiB) Feb 4 22:19:01 hppb kernel: [ 7616.556319] sd 7:0:0:0: [sdb] Write Protect is off Feb 4 22:19:01 hppb kernel: [ 7616.556323] sd 7:0:0:0: [sdb] Mode Sense: 38 00 00 00 Feb 4 22:19:01 hppb kernel: [ 7616.563195] sd 7:0:0:0: [sdb] No Caching mode page found Feb 4 22:19:01 hppb kernel: [ 7616.563209] sd 7:0:0:0: [sdb] Assuming drive cache: write through Feb 4 22:19:01 hppb kernel: [ 7616.577746] sd 7:0:0:0: [sdb] No Caching mode page found Feb 4 22:19:01 hppb kernel: [ 7616.577760] sd 7:0:0:0: [sdb] Assuming drive cache: write through Feb 4 22:19:01 hppb kernel: [ 7616.640281] sdb: sdb1 sdb2 Feb 4 22:19:01 hppb kernel: [ 7616.655220] sd 7:0:0:0: [sdb] No Caching mode page found Feb 4 22:19:01 hppb kernel: [ 7616.655225] sd 7:0:0:0: [sdb] Assuming drive cache: write through Feb 4 22:19:01 hppb kernel: [ 7616.655228] sd 7:0:0:0: [sdb] Attached SCSI disk Feb 4 22:19:01 hppb kernel: [ 7617.025578] btrfs: device label WDC-Green devid 1 transid 832 /dev/sdb1 Feb 4 22:19:01 hppb kernel: [ 7617.026076] btrfs: device label WDC-Green devid 2 transid 832 /dev/sdb2 Feb 4 22:19:01 hppb kernel: [ 7617.049763] btrfs: device label WDC-Green devid 1 transid 832 /dev/sdb1 Feb 4 22:19:01 hppb kernel: [ 7617.050255] btrfs: device label WDC-Green devid 2 transid 832 /dev/sdb2 Feb 4 22:19:01 hppb anacron[7182]: Anacron 2.3 started on 2015-02-04 Feb 4 22:19:01 hppb anacron[7183]: Anacron 2.3 started on 2015-02-04 Feb 4 22:19:01 hppb anacron[7183]: Job 1_Profilo_principale' locked by another anacron - skipping Feb 4 22:19:01 hppb anacron[7182]: Will run job1_Profilo_principale' in 0 min. Feb 4 22:19:01 hppb anacron[7182]: Will run job 2_VirtualBox_VMs' in 0 min. Feb 4 22:19:01 hppb anacron[7182]: Jobs will be executed sequentially Feb 4 22:19:01 hppb anacron[7182]: Job1_Profilo_principale' started Feb 4 22:19:01 hppb anacron[7183]: Job 2_VirtualBox_VMs' locked by another anacron - skipping Feb 4 22:19:01 hppb anacron[7183]: Normal exit (0 jobs run) Feb 4 22:19:01 hppb anacron[7182]: Job1_Profilo_principale' terminated Feb 4 22:19:01 hppb anacron[7182]: Job 2_VirtualBox_VMs' started Feb 4 22:19:01 hppb anacron[7182]: Job2_VirtualBox_VMs' terminated Feb 4 22:19:01 hppb anacron[7182]: Normal exit (2 jobs run) Feb 4 22:19:01 hppb console-kit-daemon[2107]: GLib-CRITICAL: Source ID 91 was not found when attempting to remove it Feb 4 22:19:01 hppb console-kit-daemon[2107]: GLib-CRITICAL: Source ID 94 was not found when attempting to remove it Feb 4 22:19:01 hppb anacron[7220]: Anacron 2.3 started on 2015-02-04 Feb 4 22:19:01 hppb anacron[7220]: Normal exit (0 jobs run) Feb 4 22:19:02 hppb anacron[7223]: Anacron 2.3 started on 2015-02-04 Feb 4 22:19:02 hppb anacron[7223]: Normal exit (0 jobs run) Feb 4 22:19:02 hppb console-kit-daemon[2107]: GLib-CRITICAL: Source ID 114 was not found when attempting to remove it Feb 4 22:19:02 hppb console-kit-daemon[2107]: GLib-CRITICAL: Source ID 111 was not found when attempting to remove it Feb 4 22:19:02 hppb anacron[7257]: Anacron 2.3 started on 2015-02-04 Feb 4 22:19:02 hppb anacron[7259]: Anacron 2.3 started on 2015-02-04 Feb 4 22:19:02 hppb anacron[7257]: Will run job 1_Profilo_principale' in 0 min. Feb 4 22:19:02 hppb anacron[7257]: Jobs will be executed sequentially Feb 4 22:19:02 hppb anacron[7257]: Job1_Profilo_principale' started Feb 4 22:19:02 hppb anacron[7259]: Job 1_Profilo_principale' locked by another anacron - skipping Feb 4 22:19:02 hppb anacron[7259]: Normal exit (0 jobs run) Feb 4 22:19:02 hppb anacron[7257]: Job1_Profilo_principale' terminated Feb 4 22:19:02 hppb anacron[7257]: Normal exit (1 job run) Feb 4 22:19:02 hppb console-kit-daemon[2107]: GLib-CRITICAL: Source ID 139 was not found when attempting to remove it Feb 4 22:19:02 hppb console-kit-daemon[2107]: GLib-CRITICAL: Source ID 136 was not found when attempting to remove it Feb 4 22:19:02 hppb backintime (mauro): INFO: Lock Feb 4 22:19:02 hppb backintime (mauro): INFO: Lock Feb 4 22:19:02 hppb backintime (root): INFO: Lock Feb 4 22:19:02 hppb backintime (root): WARNING: Inhibit Suspend failed. Feb 4 22:19:02 hppb backintime (mauro): INFO: Inhibit Suspend started. Reason: take snapshot Feb 4 22:19:02 hppb backintime (mauro): INFO: Inhibit Suspend started. Reason: take snapshot Feb 4 22:19:02 hppb backintime (root): INFO: on process begins Feb 4 22:19:02 hppb backintime (root): INFO: Profile_id: 1 Feb 4 22:19:02 hppb backintime (mauro): INFO: on process begins Feb 4 22:19:02 hppb backintime (mauro): INFO: Profile_id: 1 Feb 4 22:19:02 hppb backintime (mauro): INFO: on process begins Feb 4 22:19:02 hppb backintime (mauro): INFO: Profile_id: 2 Feb 4 22:19:03 hppb /qt4systrayicon.py: INFO: [qt4systrayicon] begin loop Feb 4 22:19:03 hppb /qt4systrayicon.py: INFO: [qt4systrayicon] begin loop Feb 4 22:19:32 hppb backintime (root): WARNING: Can't find snapshots folder ! Feb 4 22:19:33 hppb backintime (mauro): WARNING: Can't find snapshots folder ! Feb 4 22:19:33 hppb backintime (mauro): WARNING: Can't find snapshots folder ! Feb 4 22:19:34 hppb backintime (root): INFO: Unlock Feb 4 22:19:35 hppb backintime (mauro): INFO: Unlock Feb 4 22:19:35 hppb backintime (mauro): INFO: Unlock Feb 4 22:19:35 hppb backintime (mauro): INFO: Release inhibit Suspend Feb 4 22:19:35 hppb backintime (mauro): INFO: Release inhibit Suspend Feb 4 22:19:35 hppb /qt4systrayicon.py: INFO: [qt4systrayicon] end loop Feb 4 22:19:35 hppb /qt4systrayicon.py: INFO: [qt4systrayicon] end loop

From this log it seems like the "Can't find snapshot folder" was produced about 30 seconds after the device connection, but I can state for sure that message in the tray icon appeared immediately after I connected the device (and not 30 seconds later!).

Also, shouldn't the schedule start as soon as the device is mounted, rather than when the device is connected? If auto-mounting is not enabled (or does not work for some reason), the backup job won't be able to start in any case... what do you think?

Germar commented 9 years ago

(by germar) First of all you still use the old method with anacron. Starting with 1.1.0 I included anacrons function into BIT and start BIT directly from udev (anacron is not used anymore). Please open Settingsdialog and press OK for both root and user mauro. BIT will automatically install the new udev rules.

The notification 'Can't find snapshot folder' will be shown as soon as BIT start to take a new snapshot but couldn't find the folder. Then it will wait for 30sec (or to be correct it waits 30x 1sec and retry) for the snapshot folder. If that failed it will write the error message to syslog and exit.

Does your drive auto-mount correctly? How log does it take? Would it help to increase the timeout? Please try attached patch with 'sudo patch /usr/share/backintime/common/snapshots.py < timeout.diff'

Sure, it would be great to start the new snapshot as soon as the device is mounted. But Udev doesn't provide that information and there is no other way to get this to work on every DE.

Germar commented 9 years ago

(by germar) Sorry, forgot to attach the patch

Germar commented 9 years ago

(by mauromol) This evening I will try to update my profiles, thank you! By the way, shouldn't this kind of update a good candidate for automatic execution on BIT deb package update? Or at least on first BIT start, when it detects the profile is still using the old anacron rules...

I will also try your patch and let you know. By the way, regarding the automatic mounting, it's something I should investigate further. In theory, I have auto-mounting enabled for all already known devices in KDE settings, however the drive I have my backups into, which has a BTRFS filesystem, seems not to mount automatically. Anyway, if I mount it manually within 30 seconds BIT should work well, am I correct?

Germar commented 9 years ago

(by germar) package updates only run as root. This must be done as your own user. On first start would've been an option. But if someone wouldn't start BIT after upgrade this wouldn't help. So I needed to make it work even with the old rule which was no big deal. And as this was not critical I made this update with the normal Settings.

Yes. If you mount it during this 30sec BIT should be fine.

Germar commented 9 years ago

(by mauromol) After I updated my scheduled tasks, BIT behaviour seems to be more polite: I don't get a notification about the fact that the target backup folder is missing as soon as I connect the drive, while the backup starts after some seconds if I mount the partition. Anyway, what is strange is that I now have 3 backup profiles (two as my normal user, one as root) and they have just started all of them at the same time!! Since the target folders are all on the same device (a traditional hard disk), I don't think this is optimal... Is this the supposed behaviour? I can't remember this happening before, but it could have been just a coincidence.

Germar commented 9 years ago

(by mauromol) There's also a small glitch. If I open the BIT main window while the two profiles for my normal user are running, I can see the correct progress information for each of these running profiles in the status bar. But if I hold the mouse cursor over the two BIT icons in the system tray, both of them show the progress of the first of these two profiles (the main profile) i.e. they both show the file being copied by the first running profile.