The support forum

Exact Same Files Recopied

blackhawk8863 :

Dec 28, 2019

I have a backup using destination snapshot, copying files in full, archiving backup copies, standard "more options...", and with revision control enabled (conf.archive_modified 1). I am having an issue where files are archived then copied even if files are the same between the source and backup locations, verified with a SHA-256 hash via 7-zip. The end result is files being copied during a backup which shouldn't, and taking up resulting space if revision control is enabled. In the logs, the "Raw" information for the files are different, which seems to be an indicator. Here are the steps and log data:

-

Running Bvckup 79.25
Disabled revision control (conf.archive_modified 0)
Ran entire backup successfully for the first time.

Kicked off backup...

2019.12.27 23:15:59.793 (UTC-5) 2 1     Processing ...
2019.12.27 23:15:59.793 (UTC-5) 3 2         A total of 98 steps
2019.12.27 23:15:59.793 (UTC-5) 2 2         1. Updating file [filename]
2019.12.27 23:15:59.793 (UTC-5) 3 3             Details
2019.12.27 23:15:59.793 (UTC-5) 3 4                 Source: 72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2019.12.27 23:15:59.793 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2019.12.27 23:15:59.793 (UTC-5) 3 4                 Backup: 72.93 GB, created 2018.11.26 21:16:29.100, modified 2018.11.26 16:31:42.000, archive
2019.12.27 23:15:59.793 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891000000 / 131877415020000000 / 00000020
2019.12.27 23:27:18.286 (UTC-5) 3 3             Completed in 11 min 18 sec, copied in full
2019.12.27 23:27:18.286 (UTC-5) 3 4                 110.07 MBps | 144.39 reading, 167.15 writing

Kicked off backup...

2019.12.28 10:52:44.898 (UTC-5) 2 1     Processing ...
2019.12.28 10:52:44.898 (UTC-5) 3 2         A total of 88 steps
2019.12.28 10:52:44.898 (UTC-5) 2 2         1. Updating file [filename]
2019.12.28 10:52:44.898 (UTC-5) 3 3             Details
2019.12.28 10:52:44.898 (UTC-5) 3 4                 Source: 72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2019.12.28 10:52:44.898 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2019.12.28 10:52:44.898 (UTC-5) 3 4                 Backup: 72.93 GB, created 2018.11.26 21:16:29.100, modified 2018.11.26 16:31:42.000, archive
2019.12.28 10:52:44.898 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891000000 / 131877415020000000 / 00000020

Started another backup, saw same file was being copied again, cancelled backup, locked up windows explorer, prompted to end windows explorer task. Restarted machine.
Started another backup, saw same file was being copied again, cancelled backup, locked up windows explorer, prompted to end windows explorer task. Restarted machine.

Upgraded to Bvckup 80.8

Deleted all files from the backup location which are acting oddly. (Deleted 88 of 2420 files)

Kicked off backup...

2019.12.28 13:23:59.875 (UTC-5) 2 1     Processing ...
2019.12.28 13:23:59.875 (UTC-5) 3 2         A total of 124 steps
2019.12.28 13:23:59.875 (UTC-5) 2 2         1. Copying file [filename]
2019.12.28 13:23:59.875 (UTC-5) 3 3             72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2019.12.28 13:23:59.875 (UTC-5) 3 4                 Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2019.12.28 13:34:21.481 (UTC-5) 3 3             Completed in 10 min 21 sec, copied in full
2019.12.28 13:34:21.481 (UTC-5) 3 4                 120.14 MBps | 123.79 reading, 269.61 writing

Kicked off backup...

2019.12.28 15:04:38.597 (UTC-5) 2 1     Processing ...
2019.12.28 15:04:38.597 (UTC-5) 3 2         A total of 72 steps
2019.12.28 15:04:38.597 (UTC-5) 2 2         1. Updating file [filename]
2019.12.28 15:04:38.597 (UTC-5) 3 3             Details
2019.12.28 15:04:38.597 (UTC-5) 3 4                 Source: 72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2019.12.28 15:04:38.597 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2019.12.28 15:04:38.597 (UTC-5) 3 4                 Backup: 72.93 GB, created 2018.11.26 21:16:29.200, modified 2018.11.26 16:31:42.000, archive
2019.12.28 15:04:38.597 (UTC-5) 3 5                     Raw: 78307320231 / 131877585892000000 / 131877415020000000 / 00000020
2019.12.28 15:14:56.561 (UTC-5) 3 3             Completed in 10 min 17 sec, copied in full
2019.12.28 15:14:56.561 (UTC-5) 3 4                 120.85 MBps | 124.67 reading, 271.29 writing

Started another backup, saw same file was being copied again, paused then cancelled backup. Did not crash explorer.

Enabled revision control (conf.archive_modified 1)

Files are now archived every time instead of being overwritten. Since the files are huge (73 GB shown above) this takes up a ton of space.

-


Any idea what could be causing Bvckup to see these files as different or how to resolve the issue?
Thank you.

Alex Pankratov :

Dec 29, 2019



Are you backing up to QNAP?

The files are being recopied because last-modified timestamps on its backup copy is different:

    2019.12.27 23:15:59     Source:  ... modified 2018.11.26 16:31:41.041
    2019.12.27 23:15:59     Backup: ... modified 2018.11.26 16:31:42.000

This is not unusual, because different file systems have different timestamps granularity - some (FAT) will trim times to the second, some (NTFS) will record them with 100-ns precision, etc. Bvckup 2 tests both the source and backup volumes for their timestamp precision and then compares timestamps accordingly.

It does not however run these file system tests on every run, because they can be "expensive."

In your case it appears that the timestamp precision on the backup volume went down, e.g. it used to be in a millisecond range and now it's a second. This is an odd thing to do for a device storage vendor. At the very least it's not backwards compatible.

However QNAP released an update recently that did just that. Hence the leading question.

In any case, you can fix this by re-running the backup with Ctrl-Go. Holding Ctrl down forces the program to discard all cached information and re-query everything afresh, including file system properties.

Alex Pankratov :

Dec 29, 2019



Re: Windows Explorer hangs - that's between you and your setup I'm afraid. The hang, almost certainly, is in a 3rd party code that extends or hooks into the Explorer - can be anything from custom file indexers to alternative copiers, antiviruses, etc.

blackhawk8863 :

Dec 31, 2019

Well this is a learning experience, and you hit the nail on the head. I am not using QNAP, but I am backing up a NTFS system to exFAT, and I didn't realize that the destination wasn't NTFS or that timestamp trimming could occur.

On the hangs, that was kind of my expectation (issue on my end) but didn't know if that was any kind of indicator in terms of diagnostics.

Thank you.

blackhawk8863 :

Jan 01, 2020

So, I reformatted the destination hard drive to NTFS to match the source Stablebit Drivepool (NTFS) and ran the backup from scratch. Stablebit Scanner is indicating that all drives are healthy. I disabled revision control (conf.archive_modified 0) so that I could see source and backup detail (raw info) together at runtime. Then, I re-ran it to see if the same thing would happen.

2020.01.01 16:06:45.850 (UTC-5) 3 4                 Source: 72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2020.01.01 16:06:45.850 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2020.01.01 16:06:45.850 (UTC-5) 3 4                 Backup: 72.93 GB, created 2018.11.26 21:16:29.201, modified 2018.11.26 16:31:41.041, archive
2020.01.01 16:06:45.850 (UTC-5) 3 5                     Raw: 78307320231 / 131877585892017590 / 131877415010412092 / 00000020

The modified times now appear exactly the same now, but the created times do not. I tried changing "Detecting Changes" to "Re-scan destination" along with deleting the snapshot file in the log folder and ran again with the same result.

2020.01.01 16:06:45.850 (UTC-5) 3 4                 Source: 72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2020.01.01 16:06:45.850 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2020.01.01 16:06:45.850 (UTC-5) 3 4                 Backup: 72.93 GB, created 2018.11.26 21:16:29.201, modified 2018.11.26 16:31:41.041, archive
2020.01.01 16:06:45.850 (UTC-5) 3 5                     Raw: 78307320231 / 131877585892017590 / 131877415010412092 / 00000020

Then, I ran the Ctrl+Go, which yielded slightly different ms creation time but still the same modified time.

2020.01.01 16:17:58.142 (UTC-5) 3 4                 Source: 72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2020.01.01 16:17:58.142 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2020.01.01 16:17:58.142 (UTC-5) 3 4                 Backup: 72.93 GB, created 2018.11.26 21:16:29.107, modified 2018.11.26 16:31:41.041, archive
2020.01.01 16:17:58.142 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891079602 / 131877415010412092 / 00000020

Then, I ran Ctrl+Go again to make sure it wasn't a fluke, and it output the same times.

2020.01.01 16:33:14.744 (UTC-5) 3 4                 Source: 72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2020.01.01 16:33:14.744 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2020.01.01 16:33:14.744 (UTC-5) 3 4                 Backup: 72.93 GB, created 2018.11.26 21:16:29.107, modified 2018.11.26 16:31:41.041, archive
2020.01.01 16:33:14.744 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891079602 / 131877415010412092 / 00000020

Then, I cloned the backup just to see if it would do anything different. On the last run (pre-clone), I cancelled after the file in question was finished copying. On first run of the cloned backup job, skipped the file in question and continued through the remainder of the files with the same issue. Then, I re-ran the cloned backup job, and the issue appeared again:

2020.01.01 17:36:06.884 (UTC-5) 3 4                 Source: 72.93 GB, created 2018.11.26 21:16:29.186, modified 2018.11.26 16:31:41.041, archive
2020.01.01 17:36:06.884 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891860959 / 131877415010412092 / 00000020
2020.01.01 17:36:06.884 (UTC-5) 3 4                 Backup: 72.93 GB, created 2018.11.26 21:16:29.107, modified 2018.11.26 16:31:41.041, archive
2020.01.01 17:36:06.884 (UTC-5) 3 5                     Raw: 78307320231 / 131877585891079602 / 131877415010412092 / 00000020

Alex Pankratov :

Jan 02, 2020



Can you show me a copy of this part of the log?

    Running the backup ...
        Preparing ...
            Deducing changes ...

Basically, the key moment here is whether the support for "created" timestamps was detected on both volumes. It looks like it was, but there's something wrong with it on the backup side - timestamps *are* getting set, but they end up being set to the wrong value.

With regards to this -

I am backing up a NTFS system to exFAT


This is perfectly normal and it works right out of the box. The program tests timestamp granularity of both source and backup volumes and then uses the most coarse one when comparing the timestamps.

However, there is a known class of issues with Samba-based NAS boxes that expose their storage space as NTFS while in reality it's not (e.g. just FAT). This leads to all sorts of funky errors.

With regards to this -

The modified times now appear exactly the same now, but the created times do not.


You can work around this by suppressing the comparison of "created" timestamps as described here - https://bvckup2.com/support/forum/topic/1267.

This *will* solve the issue... though by sweeping it under the carpet.

blackhawk8863 :

Jan 04, 2020

2020.01.03 19:20:59.882 (UTC-5) 2 0 Running the backup ...
2020.01.03 19:20:59.883 (UTC-5) 2 1     Preparing ...
2020.01.03 19:20:59.883 (UTC-5) 3 2         Run number: 29
2020.01.03 19:20:59.883 (UTC-5) 3 3             Version: 80.8
2020.01.03 19:20:59.883 (UTC-5) 3 3             Source: Z:\
2020.01.03 19:20:59.883 (UTC-5) 3 3             Destination: N:\
2020.01.03 19:20:59.883 (UTC-5) 3 3             Copying: contents, timestamps (modified, created, accessed), attributes
2020.01.03 19:20:59.883 (UTC-5) 2 2         Verifying configuration ...
2020.01.03 19:20:59.883 (UTC-5) 2 2         Checking source...
2020.01.03 19:20:59.883 (UTC-5) 3 3             Normalized path: \\?\Z:\
2020.01.03 19:20:59.920 (UTC-5) 2 2         Checking destination...
2020.01.03 19:20:59.920 (UTC-5) 3 3             Normalized path: \\?\N:\
2020.01.03 19:20:59.938 (UTC-5) 2 2         Checking environment...
2020.01.03 19:20:59.938 (UTC-5) 2 2         Scanning source ...
2020.01.03 19:20:59.938 (UTC-5) 3 3             Setup
2020.01.03 19:20:59.938 (UTC-5) 3 4                 Using 3 threads, depth first, basic info, large fetch
2020.01.03 19:20:59.942 (UTC-5) 3 3             Excluded: $RECYCLE.BIN
2020.01.03 19:20:59.942 (UTC-5) 3 3             Excluded: System Volume Information
2020.01.03 19:21:00.039 (UTC-5) 3 3             Completed in 101 ms
2020.01.03 19:21:00.039 (UTC-5) 3 4                 269 folders, 9630 files,
2020.01.03 19:21:00.039 (UTC-5) 2 2         Scanning destination ...
2020.01.03 19:21:00.039 (UTC-5) 3 3             Setup
2020.01.03 19:21:00.039 (UTC-5) 3 4                 Using 3 threads, depth first, basic info, large fetch
2020.01.03 19:21:00.040 (UTC-5) 3 3             Excluded: $RECYCLE.BIN
2020.01.03 19:21:00.040 (UTC-5) 3 3             Excluded: System Volume Information
2020.01.03 19:21:00.062 (UTC-5) 3 3             Completed in 23 ms
2020.01.03 19:21:00.062 (UTC-5) 3 4                 269 folders, 9599 files,
2020.01.03 19:21:00.062 (UTC-5) 2 2         Running archive maintenance ...
2020.01.03 19:21:00.062 (UTC-5) 3 3             Location: N:\$Archive (Bvckup 2)\
2020.01.03 19:21:00.062 (UTC-5) 3 3             Scanning...
2020.01.03 19:21:00.062 (UTC-5) 3 4                 Setup
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Using 3 threads, depth first, basic info, large fetch
2020.01.03 19:21:00.062 (UTC-5) 3 4                 Completed in 1 ms
2020.01.03 19:21:00.062 (UTC-5) 3 5                     4 folders, 7 files, 30.76 GB
2020.01.03 19:21:00.062 (UTC-5) 3 3             No items older than 10000 weeks
2020.01.03 19:21:00.062 (UTC-5) 3 3             Next maintenance in 1 hour

blackhawk8863 :

Jan 04, 2020

2020.01.03 19:21:00.062 (UTC-5) 2 2         Deducing changes ...
2020.01.03 19:21:00.062 (UTC-5) 3 3             File system information
2020.01.03 19:21:00.062 (UTC-5) 2 4                 Source
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Device : local, slot 9, non-removable
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Type : NTFS
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Created timestamps : supported
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Created granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Modified granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Supported attributes : read-only, hidden, system, archive
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Supported API mask: 0x0d
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Volume : flags 018500DF, serial
2020.01.03 19:21:00.062 (UTC-5) 3 6                         Encryption: NOT supported
2020.01.03 19:21:00.062 (UTC-5) 3 6                         Compression: supported
2020.01.03 19:21:00.062 (UTC-5) 3 6                         NTFS streams: supported
2020.01.03 19:21:00.062 (UTC-5) 2 4                 Destination
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Device : local, slot 10, removable, USB 3.0
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Type : NTFS
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Created timestamps : supported
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Created granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Modified granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Supported attributes : read-only, hidden, system, archive
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Supported API mask: 0x0d
2020.01.03 19:21:00.062 (UTC-5) 2 5                     Volume : flags 03E700FF, serial
2020.01.03 19:21:00.062 (UTC-5) 3 6                         Encryption: supported
2020.01.03 19:21:00.062 (UTC-5) 3 6                         Compression: supported
2020.01.03 19:21:00.062 (UTC-5) 3 6                         NTFS streams: supported
2020.01.03 19:21:00.062 (UTC-5) 3 3             Timestamp granularity
2020.01.03 19:21:00.062 (UTC-5) 3 4                 Created: 100 ns
2020.01.03 19:21:00.062 (UTC-5) 3 4                 Modified: 100 ns
2020.01.03 19:21:00.062 (UTC-5) 3 3             Preparing backup plan ...
2020.01.03 19:21:00.062 (UTC-5) 3 4                 Planner setup
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Created timestamps: compare and update
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Modified timestamps: compare and update
2020.01.03 19:21:00.062 (UTC-5) 3 5                     1-hour offset: disabled
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Update folder timestamps: yes
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Preserve newer files: off
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Skip offline files: no
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Attributes: read-only hidden system archive
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Security info: don't compare, don't update
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Alternate streams: ignore
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Clone top folder info: no
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Files to ID: all
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Move detection: folders, files (by name/size/times, by file ID)
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Delete policy: execute delete steps
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Archive deleted: yes
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Archive modified: no
2020.01.03 19:21:00.062 (UTC-5) 3 5                     Precomp delta: no
2020.01.03 19:21:00.107 (UTC-5) 3 4                 Retrieving IDs of 9630 new files ...
2020.01.03 19:21:00.107 (UTC-5) 3 5                     Using 3 threads
2020.01.03 19:21:01.134 (UTC-5) 3 5                     Completed in 1.03 sec
2020.01.03 19:21:01.134 (UTC-5) 3 4                 Completed in 1.07 sec

blackhawk8863 :

Jan 04, 2020

I am using Stablebit Drivepool as the source and a WD My Book USB HDD as the destination, no NAS box involved. Both the source and destination are now NTFS. (reformatted exFAT destination to NTFS)

I enabled (conf.ctime_match  1) to ignore creation timestamps, and now only one file is copying every run due to different modified timestamps:

Run 1

2020.01.03 19:40:52.614 (UTC-5) 2 2         37. Updating file
2020.01.03 19:40:52.614 (UTC-5) 3 3             Details
2020.01.03 19:40:52.614 (UTC-5) 3 4                 Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
2020.01.03 19:40:52.614 (UTC-5) 3 5                     Raw: 7046006894 / 132196465169453979 / 132196466564602485 / 00000020
2020.01.03 19:40:52.614 (UTC-5) 3 4                 Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive
2020.01.03 19:40:52.614 (UTC-5) 3 5                     Raw: 7046006894 / 132196465169453979 / 132196466564758444 / 00000020

Run 2

2020.01.03 19:46:11.342 (UTC-5) 2 2         37. Updating file
2020.01.03 19:46:11.342 (UTC-5) 3 3             Details
2020.01.03 19:46:11.342 (UTC-5) 3 4                 Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
2020.01.03 19:46:11.342 (UTC-5) 3 5                     Raw: 7046006894 / 132196465169453979 / 132196466564602485 / 00000020
2020.01.03 19:46:11.342 (UTC-5) 3 4                 Backup: 6.56 GB, created 2020.01.03 19:40:52.624, modified 2019.11.30 23:04:16.475, archive
2020.01.03 19:46:11.342 (UTC-5) 3 5                     Raw: 7046006894 / 132225720526244550 / 132196466564758444 / 00000020

This file is in a directory with 6 total files, so I cloned the backup job, excluded everything except that directory, and changed the destination to a dummy folder on the C drive. Everything is running as expected, and each re-run of the cloned job yields "no changes". Running a 7-zip SHA-256 on all 3 files (source, external HDD, and C drive) yields the same hash.

To rule out the WD My Book USB HDD being the issue, I grabbed a spare WD Elements USB HDD (NTFS), and changed the clone destination to the WD Elements. Running repeatedly keeps copying the file like the WD My Book USB HDD.

2020.01.03 20:25:12.136 (UTC-5) 2 2         1. Updating file
2020.01.03 20:25:12.136 (UTC-5) 3 3             Details
2020.01.03 20:25:12.136 (UTC-5) 3 4                 Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
2020.01.03 20:25:12.136 (UTC-5) 3 5                     Raw: 7046006894 / 132196465169453979 / 132196466564602485 / 00000020
2020.01.03 20:25:12.136 (UTC-5) 3 4                 Backup: 6.56 GB, created 2020.01.03 20:23:31.521, modified 2019.11.30 23:04:16.475, archive
2020.01.03 20:25:12.136 (UTC-5) 3 5                     Raw: 7046006894 / 132225746115215645 / 132196466564758444 / 00000020

To check USB in general, I grabbed a Sandisk flash drive, reformatted NTFS, and changed the clone destination to the flash drive.

2020.01.03 21:39:54.438 (UTC-5) 2 2         1. Updating file
2020.01.03 21:39:54.438 (UTC-5) 3 3             Details
2020.01.03 21:39:54.438 (UTC-5) 3 4                 Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
2020.01.03 21:39:54.438 (UTC-5) 3 5                     Raw: 7046006894 / 132196465169453979 / 132196466564602485 / 00000020
2020.01.03 21:39:54.438 (UTC-5) 3 4                 Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive
2020.01.03 21:39:54.438 (UTC-5) 3 5                     Raw: 7046006894 / 132196465169453979 / 132196466564758444 / 00000020

I have a second machine with Bvckup2 on it, so I set up a new backup with the source being the first machine over network share, and the WD Elements USB HDD as the destination. Running repeatedly keeps copying the file like the other machine with both drives.

2020.01.03 21:04:02.460 (UTC-5) 2 2         1. Updating file
2020.01.03 21:04:02.460 (UTC-5) 3 3             Details
2020.01.03 21:04:02.460 (UTC-5) 3 4                 Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
2020.01.03 21:04:02.460 (UTC-5) 3 5                     Raw: 7046006894 / 132196465169453979 / 132196466564602485 / 00000020
2020.01.03 21:04:02.460 (UTC-5) 3 4                 Backup: 6.56 GB, created 2020.01.03 21:00:29.211, modified 2019.11.30 23:04:16.475, archive
2020.01.03 21:04:02.460 (UTC-5) 3 5                     Raw: 7046006894 / 132225768292114096 / 132196466564758444 / 00000020

...So I just looked back at the backup created timestamps, and I have no idea why they are today, and I'm not sure if I screwed something up, but I'm usually pretty meticulous. I'm shooting from the hip here, sorry if this is a bit scattered...

Alex Pankratov :

Jan 07, 2020



Something in your setup is touching this file 15 ms after it is updated by Bvckup2. What it is I cannot tell you, but I can tell you that the cause is external to Bvckup2.

You can give ProcMon (from Microsoft/SysInternals) to try and catch the culprit. If you can't see one, that this is a firmware issue with My Book.

Perhaps see if there's a firmware update for MyBook. Alternatively, you can try and change the last-modified timestamp on this file, see if it makes any difference.

You can do the latter by setting the pre-backup command in the backup settings to

        $touch x:\path\with no quotes\to\the\file

Run the backup once, clear the pre-backup command, run it again and then again. See if it gets re-copied on the last run.

blackhawk8863 :

Jan 08, 2020

Procmon is only showing bvckup and explorer when filtering "Path" "begins with" "X:\...\directory"

In terms of devices/firmware:
- Using a internal hard drive: Works as expected
- Using a WD Mybook USB HDD: Timestamp issue
- Using a WD Elements USB HDD: Timestamp issue
- Using a Sandisk Flash Drive: Timestamp issue
If it was just one device acting this way, I would agree about firmware, but this appears to be specific to USB mass storage devices in general?

Using touch successfully updated the modified timestamp, but not created timestamp. Upon successive re-runs, the modified timestamp is the same between source and destination, but created timestamp is not.

I can send some smaller files which are exhibiting the created timestamp only issue (not modified timestamp) if you want to see if you can reproduce on your end, just PM/email me.

As a workaround, is there an option to change the threshold for time comparison, such that if source file and destination file timestamps are within a minute of each other, they are considered the same, rather than the having to be the same down to the ns? It looks like the following post uses conf.ctime_gran and conf.mtime_gran to manually set the resolution of the timestamps, but I'm not sure if this is effectively rounding to the nearest second which would effectively end up the same result, or something else? Setting both of these to 20000000 (2 seconds) would mean that any timestamps within 2 seconds of each other are equal?
https://bvckup2.com/support/forum/topic/236

blackhawk8863 :

Jan 08, 2020

I tested modifying conf.ctime_gran and conf.mtime_gran, which appears to work for the vast majority of files which had issues, but the plot thickens: I'm now getting a destination timestamp which is minutes different from the source for two files:

Source: 6.56 GB, created 2020.01.07 18:10:17.729, modified 2020.01.07 19:00:10.382, archive
Backup: 6.56 GB, created 2020.01.07 18:07:50.174, modified 2020.01.07 19:00:10.382, archive

Source: 46.01 GB, created 2019.10.14 17:48:34.962, modified 2019.10.12 21:55:32.507, archive
Backup: 46.01 GB, created 2019.10.14 17:48:37.698, modified 2019.10.12 21:55:32.507, archive

Also, I was getting a ton of timestamp updates for directories on repeated runs, and  setting 'conf.update_folder_times 0' successfully suppressed them.

dymojan :

Jan 08, 2020

Could you try copying the culprit files directly from HDD instead of StableBit's DrivePool volume?

Alex Pankratov :

Jan 08, 2020

Using touch successfully updated the modified timestamp, but not created timestamp.


That's how $touch works.

Upon successive re-runs, the modified timestamp is the same between source and destination, but created timestamp is not.


Do I understand correctly that changing last-modified timestamps on trouble files caused these timestamps to stop changing on the backup copies after a backup?

I can send some smaller files which are exhibiting the created timestamp only issue (not modified timestamp) if you want to see if you can reproduce on your end, just PM/email me.


This won't do much I'm afraid. What you have is an _exceptionally_ bizarre issue that is specific to your setup. You take files out of the context and the issue will be gone.

The way timestamps are copied is that they are simply queried from the source copy and set, as is, on the backup copy. Literally a pair of get/set requests to the OS.

Based on the symptoms you described there are three explanations:

1. Get request returns invalid (+15ms) timestamps.
2. Set request adds 15ms to requested values before setting them.
3. Get/set work correctly, but something else changes timestamps after they are set.

To me this looks like some sort of bug somewhere in the file stack. Since you don't have anything particularly exotic on the destination side (plus it's reproducible with different devices), then it's something on the source side OR it's something that messes with the file stack in general.

The latter would mean all sorts of antiviruses, file indexing programs, etc. Anything that shims itself into the file stack and polices the requests going up and down it.

StableBit volume could also be the source of that (kudos to @dymojan for pointing it out). It is a complex bit of software, so the issue may in fact be rooted there.

Finally, you can also try this - you can tell bvckup2 to NOT use fast native API for getting/setting basic file information. This is done by adding the following override:

        conf.copying.general.use_fast_api    0

If this helps, then at least you will know which part of the file management API is misfiring on your machine.

blackhawk8863 :

Jan 09, 2020

@dymojan

I set up two jobs, one cloned from the other with the only difference being source location, destination to the same root level directory on an external USB HDD. and a single culprit file in both source directories. Once source directory is in the drivepool volume in a nested directory, and one source directory is in the C drive (SATA SSD) root. The single culprit file was copied from DrivePool to C drive using windows explorer, which reset the created time. The file in the DrivePool volume has been sitting unmodified in that directory since Nov 30 2019, and DrivePool duplication has been enabled since before the file was created and duplication includes the culprit file.

Repeatedly running the job from the C drive yields "no changes" and performs as expected.

Repeatedly running the job from the DrivePool yeilds consistent source timestamps, erratic backup created timestamps, and consistently +15ms backup modified timestamps. On EVERY run, the file was copied in full.

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 17:42:36.614, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 17:42:36.614, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 17:51:55.149, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 17:54:16.213, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 17:56:31.168, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 18:19:43.133, modified 2019.11.30 23:04:16.475, archive

After repeatedly running the job from DrivePool, I re-ran (repeatedly) the job from the C drive, which again yielded "no changes" and performed as expected. Then, I ran the DrivePool job once which copied the file, and re-ran (repeatedly) the job from the C drive, which again yielded "no changes" and performed as expected.

Since behavior could potentially be changed by manually copying the file across drives using explorer, I created a new folder in the DrivePool, copied the culprit file to the new directory in the DrivePool, and modified the source for the DrivePool job to be the new DrivePool directory containing the copied file. I then repeated the same procedure as above and had the same results but different timestamp behavior for the DrivePool job. Again, on EVERY run of the DrivePool job, the file was copied.

2020.01.08 18:43:59.502 (UTC-5) 2 1     Processing ... (Started repeately running DrivePool job)

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2019.11.30 23:04:16.475, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2019.11.30 23:04:16.475, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2019.11.30 23:04:16.475, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2019.11.30 23:04:16.475, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2019.11.30 23:04:16.475, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2019.11.30 23:04:16.475, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2019.11.30 23:04:16.475, archive

blackhawk8863 :

Jan 09, 2020

@dymojan

Next, I added the $touch command to Pre-backup for the DrivePool job, which is still using the copied file, and ran it one time which updated the source modified timestamp and copied the file. Then, I removed the touch command and repeatedly re-ran the DrivePool job, showing these timestamps and copying the file on every run.

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2020.01.08 19:04:29.940, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2020.01.08 19:04:29.940, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2020.01.08 19:04:29.940, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2020.01.08 19:04:29.940, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2020.01.08 19:04:29.940, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2020.01.08 19:04:29.940, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2020.01.08 19:04:29.940, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2020.01.08 19:04:29.940, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2020.01.08 19:04:29.940, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2020.01.08 19:04:29.940, archive

Source: 6.56 GB, created 2020.01.08 18:33:54.998, modified 2020.01.08 19:04:29.940, archive
Backup: 6.56 GB, created 2020.01.08 18:33:55.005, modified 2020.01.08 19:04:29.940, archive

Next, for the DrivePool job, I modified (conf.copying.general.use_fast_api 0) and modified the source to the original DrivePool folder containing the original culprit file (not copied and touched file), and ran repeatedly which copied the file on every run.

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 19:25:27.021, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 19:28:25.865, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Next, I created a directory on the C drive, and pointed the DrivePool job desination to it instead of the external USB HDD. Source was still original file in DrivePool.

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 20:49:48.007, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2020.01.08 20:52:03.012, modified 2019.11.30 23:04:16.475, archive

Source: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.460, archive
Backup: 6.56 GB, created 2019.11.30 23:01:56.945, modified 2019.11.30 23:04:16.475, archive

Finally, I pulled out a spare laptop and restored a disk image which was created when it was brand new aside from updating windows. I installed all of the same software (Including Bvckup, DrivePool, and Scanner trials), mimiced all of the same settings and procedures, and copied over a culprit file (same as tests above) via flash drive into a test DrivePool on the laptop. Running the backup job repeatedly yielded "no changes" and performed as expected. I could not get it to produce the same timestamp behavior as the other two computers.

blackhawk8863 :

Jan 09, 2020

@Alex Pankratov

Correct: changing last-modified timestamps on trouble files caused these timestamps to stop changing on the backup copies after a backup, but only for the modified timestamp, not the created timestamp. I repeated a test on this above.

I don't have any software installed which shims into the file stack aside from what DrivePool obviously does under the hood. It's a bare bones machine which just runs DrivePool, Scanner, and Bvckup. Overall, it looks like you are right and something in my setup is causing the issue, sorry for the rabbit hole, and thank you for taking the time to respond. Bumping up conf.ctime_gran and conf.mtime_gran to 5 minutes seems to be working in terms of sweeping the problem under the rug. Although it's not the prettiest solution, it seems to work.

Alex Pankratov :

Jan 09, 2020

I'm betting on a DrivePool bug. I had a quick look at their support forum and there's at least one thread describing strange timestamp behavior (albeit with some 3rd party software mixed in).

I would strongly suggest reporting this to them. Perhaps even point them to this very thread. If their devs have any questions or need help, I'd be happy to help.

dymojan :

Jan 09, 2020

I can confirm that when using drivepool, it also copied a lot of the files, which didn't change, over and over again. However, setting the conf.ctime_gran to 1 second solved all my issues.

blackhawk8863 :

Jan 10, 2020

@Alex Pankratov

I posted on the stablebit forum. For anyone else reading this and running into similar issues in the future:
https://community.covecube.com/index.php?/topic/5043-erratic-timestamps/

Also, is there any chance you could add timestamp information for archived files to the log, similar to copied files? Running with archiving and (conf.archive_modified 1) doesn't appear to provide timestamp info about existing destination files.
Processing...
     Archiving file ...
          xx.xx GB, created xxx, modified xxx, archive
     Copying file ...
          xx.xx GB, created xxx, modified xxx, archive

@dymojan

Thank you for the confirmation. Unfortunately, this appears to be dependent both on individual files and the phase of the moon: I adjusted conf.ctime_gran and conf.mtime_gran to 5 minutes which worked fine yesterday, but isn't enough today, and I'm getting a different file repeatedly copying.

New topic

Create
Made by IO Bureau in Switzerland
Support

Updates
Blog / RSS
Follow Twitter
Reddit
Miscellanea Press kit
Testimonials
Company Imprint

Legal Terms
Privacy