Backup forum

Astuff · 2021-03-21 15:36:39

I see this problem on both of my Windows 10 PCs, and am interested to know whether other people have this issue as well.

My backup set verification is set to occur once per day, let's say at 2PM. However, examining Tracefile.txt (in C:\ProgramData\IDrive\IBCOMMON\<user>) the verification doesn't occur at 2PM on most days.

I sleep my computer at night, and what appears to be happening is that the Verify is delayed by the length of time my computer is asleep. For example, if on Day 1 a Verify occurs correctly at 2PM, and I sleep my computer for 8 hours at midnight, the next Verify will occur on Day 2 at 10PM.

This has caused me problems, since I've timed the Verify to occur shortly before my backups, and when there is a big lag between the Verify and the Backup, sometimes the Backup fails. And depending on when I sleep the computer, and how long it sleeps, there can be several days between Verify events.

Looking in Tracefile.txt, the language makes it appear that they set a timer to determine when the next Verify occurs, e.g.:

[03/19/2021 19:54:58] [Verify Backupset]: Timer set to: 0 Days: 18 Hours: 5 Minutes: 2 Seconds

So if they set a countdown timer that's decremented by the IDrive service, that would explain why it loses time during sleep. But it doesn't explain why they didn't code it to properly account for sleep.

Can anyone else please tell me whether they see the same behavior in Tracefile.txt? All I do is open it in Notepad and search for "Set To" to find when Verifies occur. And it's easy to see how long the PC has been asleep for by scrolling through the file and noting where there are gaps in the timestamps.

I have tried to raise this issue with IDrive support, and of course all they want me to do is a clean install, which I've done several times. I asked them point blank whether they can confirm or deny the behavior I'm seeing, and they refuse to do so.

SteveA · 2021-03-24 19:33:04

Maybe this by design. They could be monitoring the "working time" of the computer, so time in sleep is not included.

I don't sleep any of my computers, but I do have a couple of VMs that I boot up infrequently and only for a few hours at a time, so they never reach the default 2 days.

Looking at the tracefile.txt on one of the VMs, it does look like the verify timer continued from when I last used the computer, however, although it stated that the verify would run in 4 hours, it started one anyway within minutes!

I don't think verify is essential for successful backups. Whenever a backup runs, it scans for changed and new files and they will be captured. I guess its just there as a tidy-up for files and folders that may have been removed.

Astuff · 2021-03-24 21:10:17

Hi Steve,

Thanks for the reply.

I don't believe this behavior is by design, because:

a) The Settings specify a time-of-day for the Verify, not an interval
b) If you perform a manual Verify, it can still do the automatic Verify at the scheduled time even a few minutes later (if the computer does not sleep in between)
c) Their tech support people recommended that I set the Verify to occur shortly before the backup

And the reason that they recommended (c) to me was that my backups *were* failing unless the Verification occurred shortly prior to the backup. I would re-run a failed backup over and over, and it would fail very time unless I performed a Verification, at which point the next backup attempt would succeed.

Since I could not control when the Verify occurred, I ended up having to not back up a certain folder that seemed to be causing the failures. So while my scaled-back backups are working now, I am looking forward to them fixing this Verify bug so that I can successfully back up this problematic folder.

And I was just trying to confirm that I'm not the only one who's seeing the Verify occurring at weird times. I'm not sure how to interpret what happened with your VMs.

It would be easy for someone to test this out by temporarily changing the verification time to occur, say, to 15 minutes in the future, then immediately performing a manual verification and putting the computer to sleep for 5 minutes. Wake the computer and wait for 20 minutes, and check to see whether the verify occurred at the scheduled time, or 5 minutes late.

SteveA · 2021-03-25 14:49:43

Astuff wrote:
It would be easy for someone to test this out by temporarily changing the verification time to occur, say, to 15 minutes in the future, then immediately performing a manual verification and putting the computer to sleep for 5 minutes. Wake the computer and wait for 20 minutes, and check to see whether the verify occurred at the scheduled time, or 5 minutes late.

Ok, I take the hint

I tried this, but in my case, the Verify still ran on time (in fact, 1 second early), despite 5 minutes sleep.

Here's the relevant parts of the log:

Force Verify...

[03/25/2021 14:08:22] [Verify Backupset]: Timer set to: 0 Days: 0 Hours: 1 Minutes: 37 Seconds
[03/25/2021 14:08:28] [Verify Backupset] : Enumeration in Progress: False
[03/25/2021 14:08:28] [Verify Backupset] : Backup in Progress: False
[03/25/2021 14:08:28] Started Cleaning Backupset. IsCDPRequest: False
[03/25/2021 14:08:28] Deleting DB file : C:\ProgramData\IDrive\IBCOMMON\xxxxxxxxx
[03/25/2021 14:08:28] DB file : C:\ProgramData\IDrive\IBCOMMON\xxxxxxxxxx
[03/25/2021 14:08:28] Ended Cleaning Backupset
[03/25/2021 14:08:28] [Verify Backupset] : Enqueued Request to Enumerate.
[03/25/2021 14:08:28] Started Enumeration for BackupsetName : Default BackupSet_xxxxx
[03/25/2021 14:08:28] Inside StartEnum()...
[03/25/2021 14:08:28] Removing Invalid folders from Backupset Files:
[03/25/2021 14:08:28] Thread to enum started...ThreadBackupSetProc() called

Set Verify to 14:25 and force another verify...

[03/25/2021 14:08:51] [Verify Backupset]: Timer set to: 0 Days: 0 Hours: 16 Minutes: 8 Seconds
[03/25/2021 14:08:58] [Verify Backupset] : Enumeration in Progress: True
[03/25/2021 14:08:58] [Verify Backupset] : Backup in Progress: False
[03/25/2021 14:09:01] Started Cleaning Backupset. IsCDPRequest: False
[03/25/2021 14:09:01] Deleting DB file : C:\ProgramData\IDrive\IBCOMMON\xxxxxxxxxxx
[03/25/2021 14:09:03] Deleting DB file : C:\ProgramData\IDrive\IBCOMMON\xxxxxxxxxxx
[03/25/2021 14:09:03] DB file : C:\ProgramData\IDrive\IBCOMMON\xxxxxxxxxx
[03/25/2021 14:09:03] Ended Cleaning Backupset
[03/25/2021 14:09:03] [Verify Backupset] : Enqueued Request to Enumerate.
[03/25/2021 14:09:06] Started Enumeration for BackupsetName : Default BackupSet_xxxxx
[03/25/2021 14:09:06] Inside StartEnum()...
[03/25/2021 14:09:06] Removing Invalid folders from Backupset Files:
[03/25/2021 14:09:06] Thread to enum started...ThreadBackupSetProc() called
[03/25/2021 14:09:40] Finished Enumeration for BackupsetName : Default BackupSet_xxxxx
[03/25/2021 14:10:20] Finished Enumeration for BackupsetName : Default BackupSet_xxxxx
[03/25/2021 14:10:24] Deleting tempCDP DB
[03/25/2021 14:10:24] Deleted status tempCDP DB is True

Sleep for 5 minutes between 14:10 and 14:15...

(irrelevant stuff between 14:15 and 14:24 redacted)
[03/25/2021 14:24:59] [Verify Backupset]: Execution started at: 14:24:59
[03/25/2021 14:25:00] [Verify Backupset] : Enumeration in Progress: False
[03/25/2021 14:25:00] [Verify Backupset] : Backup in Progress: False
[03/25/2021 14:25:00] Started Cleaning Backupset. IsCDPRequest: False
[03/25/2021 14:25:00] Deleting DB file : C:\ProgramData\IDrive\IBCOMMON\xxxxxxxxxxxx
[03/25/2021 14:25:00] DB file : C:\ProgramData\IDrive\IBCOMMON\xxxxxxxxxxxxxx
[03/25/2021 14:25:00] Ended Cleaning Backupset
[03/25/2021 14:25:00] [Verify Backupset] : Enqueued Request to Enumerate.
[03/25/2021 14:25:00] Started Enumeration for BackupsetName : Default BackupSet_xxxxx
[03/25/2021 14:25:00] [Verify Backupset]: Timer set to: 0 Days: 23 Hours: 59 Minutes: 59 Seconds
[03/25/2021 14:25:00] Removing Invalid folders from Backupset Files:
[03/25/2021 14:25:00] Thread to enum started...ThreadBackupSetProc() called
[03/25/2021 14:25:09] Finished Enumeration for BackupsetName : Default BackupSet_xxxxx

So it would appear, I don't have this issue.

Astuff · 2021-03-25 14:54:54

Wow, thanks for doing that, Steve! :-)

I should add that I'm running version 6.7.3.32, and that the error didn't happen a year ago, so it's possible that they introduced a bug in the past year.

Well, I'm officially confused. I have given up on IDrive support, as they only seem to want more and more logs, and more clean installs. Since this is happening on two different PCs, I'm assuming it's their problem and not mine, but as long as I'm able to back up most of my data and limp along, that will have to do for now.

I appreciate your help!

Alan

SteveA · 2021-03-25 15:21:20

Astuff wrote:
I should add that I'm running version 6.7.3.32

I ran that on 6.7.3.30 on a Windows 7 machine.

I don't think the OS would be the problem. I only have W10 as a VM and I'm not sure if I can simulate sleep.

SteveA · 2021-03-25 17:48:23

Update:

I now suspect Windows 10 is the problem! I simulated sleep by pausing the Guest OS for 5 minutes. After resuming it, the Verify ran 5 minutes late.

Very strange.

My Windows 10 VM has the latest feature update, 20H2. Maybe Microsoft have changed something about the way the time is reported.

Astuff · 2021-03-25 18:05:51

Interesting development. I wonder how accurately pausing the VM mimics sleep. When you unpaused the VM, did the time of day correct instantly? If so, this kinda confirms that they aren't purely using time-of-day to trigger the Verify.

It does look like Win10 20H2 did change the sleep/standby mechanisms, I think making "Modern Sleep" or "Modern Standby" the default when possible. I'm running on a PC that can't do Modern Sleep. Purely speculating here, but maybe whatever mechanism IDrive uses to count down its Verify timer continues counting during Modern Sleep, but doesn't count down during Standard (S3) sleep, and the IDrive programmers are assuming all Win10 20H2 systems use Modern Sleep.

SteveA · 2021-03-25 18:13:18

Astuff wrote:
Interesting development. I wonder how accurately pausing the VM mimics sleep. When you unpaused the VM, did the time of day correct instantly? If so, this kinda confirms that they aren't purely using time-of-day to trigger the Verify.

Yes and no!

I've always had a problem with my W10 VM time, so I have a background app running that keeps it correct by synchronizing with Internet time servers.

So when I unpaused it, the time was behind, but updated itself after a couple of minutes. It was certainly correct before the scheduled verify time was reached.

Astuff · 2021-03-25 18:25:12

OK, well, thank you...this is definitely good enough for me to assume it's IDrive's problem, and I can stop feeling paranoid, at least. :-)

Out of curiosity, what are you using for your VM...is it VirtualBox, Hyper-V, VMWare...?

SteveA · 2021-03-25 19:25:05

Virtualbox and VMWare.

I couldn't get Virtualbox to work reliably with USB devices so I moved some of my Linux VMs to VMWare.

Backup forum

Announcement

#1 2021-03-21 15:36:39

Verify backup set not occurring when it should

#2 2021-03-24 19:33:04

Re: Verify backup set not occurring when it should

#3 2021-03-24 21:10:17

Re: Verify backup set not occurring when it should

#4 2021-03-25 14:49:43

Re: Verify backup set not occurring when it should

Astuff wrote:

#5 2021-03-25 14:54:54

Re: Verify backup set not occurring when it should

#6 2021-03-25 15:21:20

Re: Verify backup set not occurring when it should

Astuff wrote:

#7 2021-03-25 17:48:23

Re: Verify backup set not occurring when it should

#8 2021-03-25 18:05:51

Re: Verify backup set not occurring when it should

#9 2021-03-25 18:13:18

Re: Verify backup set not occurring when it should

Astuff wrote:

#10 2021-03-25 18:25:12

Re: Verify backup set not occurring when it should

#11 2021-03-25 19:25:05

Re: Verify backup set not occurring when it should

Board footer