The support forum

Issues with Synology DSM 6 firmware update (!)

Mar 30, 2016

[ Admin edit ]


If you are using a Synology NAS and you started seeing needless recopying of the files, then this might be due to a recent Synology firmware upgrade (DSM 6) - it messes with file timestamps in a way that makes it impossible for any backup app to track which files have changed since the last run.

The only option is to downgrade to the older version (5.2) and then complain to Synology so that they would fix this on their end asap.

Alex

[ Original post by @jfsimon ]


Hello there,

I've been trying to evaluate Bvckup 2 for the past few hours and I must say it looks really cool indeed. I would like to use it to keep a mirror copy of my personal files on my Synology NAS for primary backup purposes.

However I'm struggling with a weird issue and I can't figure out what's going on, when I try to mirror a folder on my local D drive to a network share on my private network.

Let's say I have a test source folder and a remote test destination folder, both empty. When I first run the job, it says "no change" whithin milliseconds. Then if a one or more files in the source folder and I run the job again, the new files are indeed copied.

but when I run the job again, these files are copied in full again, even though it says "updating file XXX...". Then (still with the same files in the source, not adding any) from the 3rd pass (and onwards), it's ok, I get the "no change" as expected. Should I add new files to the source, it will again take two passes of the job to see them as "not changed".

I've been playing with the "use destination snapshot" vs "rescan everytime", as well as "copy/don't copy the file attributes".

If I'm not mistaken the "copy/don't copy file attributes" setting doesn't change anything for the purpose of this test, so I'll forget it for a minute.

Here is the result of my experiments, in chronological order :

1) the destination being a share accessed with its full network path (\\server\backup\dest), but having as well a mapped folder on the same server in my windows explorer
a) use destination snapshot : symptoms as described (2 passes needed)
b) rescan everytime : this time the unchanged files are not copied again (whohoooo !)

2) source and destination are both local folders on my D drive
-> whatever the settings, it always work 1st time, no problem

3) after a reboot and this time the destination is my \\server\ share, but I've unmounted my other mapped folder.
-> whatever the settings, always the same symptoms; 2 passes needed (even with "rescan everytime" checked)

4) this time, trying to replicate the 1) situation : (same settings)
-> I can't, 2 passes are always needed and I can't replicate 1)a) as before


So here I am, completely stuck ! Maybe it's trivial but I can't figure it out. I guess the issue may be with the timestamps. Each time Bvckup does a (seemingly unnecessary) 2nd copy of an unchanged file, I get this kind of thing in the log :

"2016.03.30 15:18:36.081 (UTC+1) 2 2         1. Updating file 201504_special-commodities_04.pdf
2016.03.30 15:18:36.081 (UTC+1) 3 3             Details
2016.03.30 15:18:36.081 (UTC+1) 3 4                 Source: created  2016.03.30  15:18:16.529 , modified  2016.02.25  16:03:59.434 , 4.69 MB, archived
2016.03.30 15:18:36.081 (UTC+1) 3 5                     Raw: 131038174965291927 / 131008826394340683 / 4915884 / 00000020
2016.03.30 15:18:36.081 (UTC+1) 3 4                 Backup: created  2016.03.30  15:18:16.529 , modified  2016.03.30  15:18:28.973 , 4.69 MB, archived
2016.03.30 15:18:36.081 (UTC+1) 3 5                     Raw: 131038174965291927 / 131038175089731317 / 4915884 / 00000020
2016.03.30 15:18:37.145 (UTC+1) 3 3             Performance
2016.03.30 15:18:37.145 (UTC+1) 3 4                 4.41 MBps / 4621308 bps, 1.06 sec in total
2016.03.30 15:18:37.145 (UTC+1) 3 5                     Raw metrics - 82 / 16 / 12030 / 59 / 2097152 / 2097152 / 2 / 978245 / 3488 / 1873 / 2 / 0 / 20 / 56772 / 9194
2016.03.30 15:18:37.145 (UTC+1) 3 3             Completed in 1.06 sec, copied in full"

(I'm testing over a crap 802.11 link, hence the slow speed)

This behavior is kind of problematic because as I have thousands of <500bytes files in my "Contacts" folder, and many 1-2GB movies, each "unnecessary 2nd copy" is painfully slow.

I hope someone will be able to help, sorry for this long post, and greetings from Geneva by the way

Cheers and many thanks in advance
JF

Mabroc :

Mar 30, 2016

Hello jfsimon, I was about to start a TOPIC about the same issue but the difference is that Im using Bvckup since version 1, I got a license for version 2 a year ago and never have a problem with it. I use it too with a Synology NAS, I have BACKUP JOBS to other Hard Drives and others to backup to the NAS unit.
I didn't change any settings on the NAS or my PC but since yesterday the USE DESTINATION SNAPSHOT doesn't work anymore, Re-Scan Destination On Every Run works fine but is slower of course
The NAS jobs are on manual but I usually run them 2 or 3 times a day, the jobs copying to the other HD are on automatic and still works perfectly with the destination snapshot option.

For example:
2016.03.30 13:34:48.595 (UTC-3) 2 1     Processing ...
2016.03.30 13:34:48.595 (UTC-3) 3 2         A total of 1 step
2016.03.30 13:34:48.595 (UTC-3) 2 2         1. Updating file Shadowhunters - Season 1\Shadowhunters.1x12.Malec.720p.HDTV.x264-2HD.[tvu.org.ru].mkv
2016.03.30 13:34:48.595 (UTC-3) 3 3             Details
2016.03.30 13:34:48.595 (UTC-3) 3 4                 Source: created  2016.03.30  13:21:41.475 , modified  2016.03.30  12:56:14.463 , 736.52 MB, archived
2016.03.30 13:34:48.595 (UTC-3) 3 5                     Raw: 131038285014759917 / 131038269744637118 / 772294568 / 00000020
2016.03.30 13:34:48.595 (UTC-3) 3 4                 Backup: created  2016.03.30  13:21:41.475 , modified  2016.03.30  13:34:55.540 , 736.52 MB, archived
2016.03.30 13:34:48.595 (UTC-3) 3 5                     Raw: 131038285014759917 / 131038292955405944 / 772294568 / 00000020
2016.03.30 13:34:48.601 (UTC-3) 2 3             Resetting the delta state...
2016.03.30 13:34:48.601 (UTC-3) 3 4                 Destination file timestamps have changed since the last run
2016.03.30 13:35:03.172 (UTC-3) 3 3             Performance
2016.03.30 13:35:03.172 (UTC-3) 3 4                 50.54 MBps / 52991202 bps, 14 sec in total
2016.03.30 13:35:03.172 (UTC-3) 3 5                     Raw metrics - 53 / 3 / 1899 / 10 / 2097152 / 2097152 / 3 / 6 / 14564464 / 5658 / 289 / 48 / 367 / 21910 / 22471
2016.03.30 13:35:03.172 (UTC-3) 3 3             Completed in 14 sec, copied in full
2016.03.30 13:35:03.325 (UTC-3) 2 1     Completed in 14 sec with no errors
2016.03.30 13:35:03.325 (UTC-3) 3 2         Read 736.52 MB, wrote 736.52 MB, throughput 50.54 MBps / 52991202 bps

that file was already on the NAS but it was UPDATED fully without reason, unless this is one: Destination file timestamps have changed since the last run

Before this behaviour I never had an issue, if for example I renamed the file on my HD when later I run the backup job the file on the NAS was accordingly renamed too in a flash without copying it full. I got a OUTLOOK email database on another job and when I run the job it's updated using the DELTA method copying only the new data of the new emails to the NAS. Well that was before, now it's copying the file fully once then it checks ok the second time I run it 2 seconds later and doing again the full copy the third time I run the job:

Mabroc :

Mar 30, 2016

Running the backup ...
2016.03.30 14:18:50.344 (UTC-3) 2 1     Preparing ...
2016.03.30 14:18:50.344 (UTC-3) 3 2         Run number: 968
2016.03.30 14:18:50.344 (UTC-3) 3 2         Source: C:\Users\Mabroc\Documents\
2016.03.30 14:18:50.344 (UTC-3) 3 2         Destination: A:\
2016.03.30 14:18:50.344 (UTC-3) 3 2         Copying: contents, timestamps (created, modified, accessed), attributes
2016.03.30 14:18:50.344 (UTC-3) 3 3             Using delta copier
2016.03.30 14:18:50.344 (UTC-3) 2 2         Verifying configuration ...
2016.03.30 14:18:50.344 (UTC-3) 3 3             Normalized src path: \\?\C:\Users\Mabroc\Documents\
2016.03.30 14:18:50.344 (UTC-3) 3 3             Normalized dst path: \\?\A:\
2016.03.30 14:18:50.344 (UTC-3) 2 2         Checking source location ...
2016.03.30 14:18:50.344 (UTC-3) 3 3             OK
2016.03.30 14:18:50.344 (UTC-3) 2 2         Checking destination location ...
2016.03.30 14:18:50.347 (UTC-3) 3 3             OK
2016.03.30 14:18:50.347 (UTC-3) 2 2         Filtering rules
2016.03.30 14:18:50.347 (UTC-3) 3 3             Include everything by default
2016.03.30 14:18:50.347 (UTC-3) 3 3             Additional rules
2016.03.30 14:18:50.347 (UTC-3) 3 4                 [Exclude] [files] matching [~*.tmp]
2016.03.30 14:18:50.347 (UTC-3) 3 4                 [Exclude] [files] matching [.tickle]
2016.03.30 14:18:50.347 (UTC-3) 3 4                 [Exclude] [folders] matching [Temporary Internet Files]
2016.03.30 14:18:50.347 (UTC-3) 3 4                 [Exclude] [folders] matching [CryptNetUrlCache]
2016.03.30 14:18:50.347 (UTC-3) 3 4                 [Exclude] [folders] matching [Mozilla\Firefox\Profiles\*\Cache*]
2016.03.30 14:18:50.347 (UTC-3) 3 4                 [Exclude] [folders] matching [Google\Chrome\User Data\*\Cache]
2016.03.30 14:18:50.348 (UTC-3) 2 2         Scanning source ...
2016.03.30 14:18:50.371 (UTC-3) 3 3             Completed in 23 ms
2016.03.30 14:18:50.371 (UTC-3) 3 3             504 folders, 4124 files, 3.47 GB
2016.03.30 14:18:50.371 (UTC-3) 2 2         Loading destination snapshot ...
2016.03.30 14:18:50.378 (UTC-3) 3 3             504 folders, 4124 files, 3.47 GB
2016.03.30 14:18:50.378 (UTC-3) 2 2         Deducing changes ...
2016.03.30 14:18:50.378 (UTC-3) 3 3             File system information
2016.03.30 14:18:50.384 (UTC-3) 3 4                 Source
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Device : local, non-removable, physical disk 0
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Type : NTFS
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Created timestamps : supported
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Created granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Modified granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Supported attributes : read-only, hidden, system, archive
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Volume : flags 03E700FF, serial 78E9ADC1
2016.03.30 14:18:50.384 (UTC-3) 3 4                 Destination
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Device : remote, over SMB 3.0.0
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Type : NTFS
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Created timestamps : supported
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Created granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Modified granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Supported attributes : read-only, hidden, system, archive
2016.03.30 14:18:50.384 (UTC-3) 3 5                     Volume : flags 0005002F, serial FAE7ECB3
2016.03.30 14:18:50.384 (UTC-3) 3 3             Timestamp granularity
2016.03.30 14:18:50.384 (UTC-3) 3 4                 Created: 100 ns
2016.03.30 14:18:50.384 (UTC-3) 3 4                 Modified: 100 ns
2016.03.30 14:18:50.384 (UTC-3) 3 3             Preparing the backup plan ...
2016.03.30 14:18:50.397 (UTC-3) 3 4                 Completed in 13 ms
2016.03.30 14:18:50.397 (UTC-3) 2 2         Checking disk space ...
2016.03.30 14:18:50.397 (UTC-3) 2 3             Space use change afterwards : no change
2016.03.30 14:18:50.399 (UTC-3) 2 3             Space available : 555.66 GB
2016.03.30 14:18:50.399 (UTC-3) 3 4                 Exactly 596631228416 bytes

Mabroc :

Mar 30, 2016

2016.03.30 14:18:50.500 (UTC-3) 2 1     Processing ...
2016.03.30 14:18:50.500 (UTC-3) 3 2         A total of 1 step
2016.03.30 14:18:50.500 (UTC-3) 2 2         1. Updating file E-mails OUTLOOK 2010\Outlook.pst
2016.03.30 14:18:50.500 (UTC-3) 3 3             Details
2016.03.30 14:18:50.500 (UTC-3) 3 4                 Source: created  2013.06.20  14:39:02.483 , modified  2016.03.30  13:49:53.013 , 392.36 MB, archived / not-indexed
2016.03.30 14:18:50.500 (UTC-3) 3 5                     Raw: 130162235424831753 / 131038301930139021 / 411419648 / 00002020
2016.03.30 14:18:50.500 (UTC-3) 3 4                 Backup: created  2013.06.20  14:39:02.483 , modified  2016.03.30  14:19:42.262 , 392.36 MB, archived / not-indexed
2016.03.30 14:18:50.500 (UTC-3) 3 5                     Raw: 130162235424831753 / 131038319822620827 / 411419648 / 00002020
2016.03.30 14:18:51.301 (UTC-3) 3 3             Performance
2016.03.30 14:18:51.301 (UTC-3) 3 4                 492.05 MBps / 515955284 bps, 797 ms in total
2016.03.30 14:18:51.301 (UTC-3) 3 5                     Raw metrics - 48 / 4 / 131 / 1208 / 2097152 / 2097152 / 3 / 6 / 787355 / 5861 / 122 / 20 / 195 / 12225 / 0
2016.03.30 14:18:51.301 (UTC-3) 3 3             Completed in 801 ms, no data copied
2016.03.30 14:18:51.461 (UTC-3) 2 1     Completed in 1.12 sec with no errors
2016.03.30 14:18:51.461 (UTC-3) 3 2         Read 392.36 MB, wrote 0 bytes, throughput 492.05 MBps / 515955284 bps
2016.03.30 14:20:42.555 (UTC-3) 2 0 Running the backup ...
2016.03.30 14:20:42.555 (UTC-3) 2 1     Preparing ...
2016.03.30 14:20:42.555 (UTC-3) 3 2         Run number: 969
2016.03.30 14:20:42.555 (UTC-3) 3 2         Source: C:\Users\Mabroc\Documents\
2016.03.30 14:20:42.555 (UTC-3) 3 2         Destination: A:\
2016.03.30 14:20:42.555 (UTC-3) 3 2         Copying: contents, timestamps (created, modified, accessed), attributes
2016.03.30 14:20:42.555 (UTC-3) 3 3             Using delta copier
2016.03.30 14:20:42.555 (UTC-3) 2 2         Verifying configuration ...
2016.03.30 14:20:42.555 (UTC-3) 3 3             Normalized src path: \\?\C:\Users\Mabroc\Documents\
2016.03.30 14:20:42.555 (UTC-3) 3 3             Normalized dst path: \\?\A:\
2016.03.30 14:20:42.555 (UTC-3) 2 2         Checking source location ...
2016.03.30 14:20:42.556 (UTC-3) 3 3             OK
2016.03.30 14:20:42.556 (UTC-3) 2 2         Checking destination location ...
2016.03.30 14:20:42.560 (UTC-3) 3 3             OK
2016.03.30 14:20:42.560 (UTC-3) 2 2         Filtering rules
2016.03.30 14:20:42.560 (UTC-3) 3 3             Include everything by default
2016.03.30 14:20:42.560 (UTC-3) 3 3             Additional rules
2016.03.30 14:20:42.560 (UTC-3) 3 4                 [Exclude] [files] matching [~*.tmp]
2016.03.30 14:20:42.560 (UTC-3) 3 4                 [Exclude] [files] matching [.tickle]

Mabroc :

Mar 30, 2016

2016.03.30 14:20:42.560 (UTC-3) 3 4                 [Exclude] [folders] matching [Temporary Internet Files]
2016.03.30 14:20:42.560 (UTC-3) 3 4                 [Exclude] [folders] matching [CryptNetUrlCache]
2016.03.30 14:20:42.560 (UTC-3) 3 4                 [Exclude] [folders] matching [Mozilla\Firefox\Profiles\*\Cache*]
2016.03.30 14:20:42.560 (UTC-3) 3 4                 [Exclude] [folders] matching [Google\Chrome\User Data\*\Cache]
2016.03.30 14:20:42.560 (UTC-3) 2 2         Scanning source ...
2016.03.30 14:20:42.583 (UTC-3) 3 3             Completed in 23 ms
2016.03.30 14:20:42.583 (UTC-3) 3 3             504 folders, 4124 files, 3.47 GB
2016.03.30 14:20:42.583 (UTC-3) 2 2         Loading destination snapshot ...
2016.03.30 14:20:42.590 (UTC-3) 3 3             504 folders, 4124 files, 3.47 GB
2016.03.30 14:20:42.590 (UTC-3) 2 2         Deducing changes ...
2016.03.30 14:20:42.590 (UTC-3) 3 3             File system information
2016.03.30 14:20:42.607 (UTC-3) 3 4                 Source
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Device : local, non-removable, physical disk 0
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Type : NTFS
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Created timestamps : supported
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Created granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Modified granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Supported attributes : read-only, hidden, system, archive
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Volume : flags 03E700FF, serial 78E9ADC1
2016.03.30 14:20:42.607 (UTC-3) 3 4                 Destination
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Device : remote, over SMB 3.0.0
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Type : NTFS
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Created timestamps : supported
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Created granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Modified granularity : 100 ns  ( 100 ns probed, 100 ns deduced )
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Supported attributes : read-only, hidden, system, archive
2016.03.30 14:20:42.607 (UTC-3) 3 5                     Volume : flags 0005002F, serial FAE7ECB3
2016.03.30 14:20:42.607 (UTC-3) 3 3             Timestamp granularity
2016.03.30 14:20:42.607 (UTC-3) 3 4                 Created: 100 ns
2016.03.30 14:20:42.607 (UTC-3) 3 4                 Modified: 100 ns
2016.03.30 14:20:42.607 (UTC-3) 3 3             Preparing the backup plan ...
2016.03.30 14:20:42.621 (UTC-3) 3 4                 Completed in 14 ms
2016.03.30 14:20:42.621 (UTC-3) 2 2         Checking disk space ...
2016.03.30 14:20:42.621 (UTC-3) 2 3             Space use change afterwards : no change
2016.03.30 14:20:42.623 (UTC-3) 2 3             Space available : 555.66 GB
2016.03.30 14:20:42.623 (UTC-3) 3 4                 Exactly 596631171072 bytes
2016.03.30 14:20:42.725 (UTC-3) 2 1     Processing ...
2016.03.30 14:20:42.725 (UTC-3) 3 2         A total of 1 step
2016.03.30 14:20:42.725 (UTC-3) 2 2         1. Updating file E-mails OUTLOOK 2010\Outlook.pst
2016.03.30 14:20:42.725 (UTC-3) 3 3             Details
2016.03.30 14:20:42.725 (UTC-3) 3 4                 Source: created  2013.06.20  14:39:02.483 , modified  2016.03.30  13:49:53.013 , 392.36 MB, archived / not-indexed
2016.03.30 14:20:42.725 (UTC-3) 3 5                     Raw: 130162235424831753 / 131038301930139021 / 411419648 / 00002020
2016.03.30 14:20:42.725 (UTC-3) 3 4                 Backup: created  2013.06.20  14:39:02.483 , modified  2016.03.30  14:19:42.262 , 392.36 MB, archived / not-indexed
2016.03.30 14:20:42.725 (UTC-3) 3 5                     Raw: 130162235424831753 / 131038319822620827 / 411419648 / 00002020
2016.03.30 14:20:42.730 (UTC-3) 2 3             Resetting the delta state...
2016.03.30 14:20:42.730 (UTC-3) 3 4                 Destination file timestamps have changed since the last run
2016.03.30 14:20:50.094 (UTC-3) 3 3             Performance
2016.03.30 14:20:50.094 (UTC-3) 3 4                 53.27 MBps / 55856014 bps, 7.37 sec in total
2016.03.30 14:20:50.094 (UTC-3) 3 5                     Raw metrics - 48 / 3 / 1937 / 20 / 2097152 / 2097152 / 3 / 6 / 7354794 / 7046 / 260 / 43 / 195 / 11716 / 11933
2016.03.30 14:20:50.094 (UTC-3) 3 3             Completed in 7.37 sec, copied in full
2016.03.30 14:20:50.255 (UTC-3) 2 1     Completed in 7.70 sec with no errors
2016.03.30 14:20:50.255 (UTC-3) 3 2         Read 392.36 MB, wrote 392.36 MB, throughput 53.27 MBps / 55856014 bps

So, it's like the snapshot it's not updated after the backup job finished and the next time it's doing it again OR the date stamp are confusing the program, but how? the NAS server it's suddenly changing date stamps on the files? Any input would be apreciated
Thanks

Alex Pankratov :

Mar 30, 2016

@jfsimon

So here I am, completely stuck !


Fear not!

The most likely cause is that there's some other process (either on the NAS or on your local machine) goes through the backup after each run and touches all new files, changing their time stamps. For example, this could be some sort of file or search indexer.

The way to troubleshoot this is to look at the backup logs. The app logs exact timestamps for each file being copied:

   Source:  created  2016.03.30  15:18:16.529 ,
                   modified  2016.02.25  16:03:59.434

   Backup:  created  2016.03.30  15:18:16.529 ,
                   modified  2016.03.30  15:18:28.973

The part that should raise your eyebrows is "15:18:28.973" - this timestamp has no business being set to this value. When Bvckup 2 copies a file it *always* synchronizes the "modified" timestamp.

So either the NAS reported that the "16:03:59.434" timestamp was successfully set when it was not (unlikely) - OR - something else actually opened that file for writing after it was backed up.

Alex Pankratov :

Mar 30, 2016

@Mabroc

the NAS server it's suddenly changing date stamps on the files?


It looks like that.

    Source:  created  2016.03.30  13:21:41.475 ,
                   modified  2016.03.30  12:56:14.463

    Backup:  created  2016.03.30  13:21:41.475 ,
                    modified  2016.03.30  13:34:55.540

"Modified" timestamps must match. If they don't, then something has opened the backup copy of a file for writing around 13:34:55, or just plain reset its "modified" timestamp to the current time.

It's EXACTLY the same problem as @jfsimon has, so it might make sense for you guys to compare NAS models and firmware revisions as well as what you have in common in terms of a file indexing/monitoring software running on your computers.

I would guess that it has to do either with a NAS firmware update (that introduced some sort of intrusive file indexing) or a buggy update to the antivirus software that you might be running on the computers.

Mabroc :

Mar 30, 2016

Thanks for your input Alex. I have a DS215j Synology NAS and a week or two ago the entire operating system was upgraded and then a couple of days ago some apps on it were updated too, like MEDIA SERVER which is running and indexing the files. But never had any problem with other updates since I got it.
But you are probably right, gonna try copying some files with the apps disabled on the NAS. Tomorrow morning, Im in the late shift right now on my job, totally working and not web surfing.
Thanks, I will post again with my findings

Mabroc :

Mar 30, 2016

Seems to be a bug, we are not the only ones:

https://forum.synology.com/enu/viewtopic.php?f=159&t=116046&p=424446&hilit=Bug+with+File+Timestamps+in+DSM#p424446

jfsimon :

Mar 31, 2016

Hello, thanks guys for the replies.

I'm using a DS115J and running DSM 6.0-7321.

I just looked and apparently there were several "packages" running in the background on the NAS : Hyper Backup, Hyper Backup Vault, PHP, Storage Analyzer, Text Editor.

I killed them one at a time and tried again each time; the same behavior as previously described is still here :/

The file indexing on this share is disabled in the DSM GUI, I don't know if there's some other sort of hidden indexing happening.

It may be an issue with DSM 6, unfortunately I haven't had a chance to test Bvckup 2 before updating from DSM 5.2.... As we are at least three in the past month with the same kind of issue. Still googling though, but I didn't have much luck yet.

What baffles me is that I have no clue about what could be messing with the timestamps.

Today I tried again : (source and dest folders both empty, setting up a job with default settings, adding one file to source, click Go)

and after the first run of the job, the new file pops (as expected) in the destination folder, and if I have this folder open in Windows explorer, I can indeed see it pop in, and it has an incorrect "last modified" stamp (directly visible with the "detailed" view of Explorer) ; it shows a weird time as Alex pointed out. However if I hit F5, the "last modified" stamps immediately returns back to its normal value (but I can't see it with a nanosecond resolution as windows properties only show hh:mm:ss)

so if I understand correctly:
-after one *single* run of the job, the file is copied, most probably with a  correct "last modified" stamp as I would expect from Bvckup, then "something" modifies it to current date/time, then immediately after "something" modifies it again to a date which is close enough to  what one could expect from a Windows point of view (1sec accuracy) but maybe not the exact same stamp as the source file at the nanosecond scale, which causes Bvckup to consider files as different on the 2nd run. Then the file is copied again, but this time the weird "something" is not active anymore, the stamps stay synced, and the same file won't be copied anymore.

How could I check if my guesses are correct ? What tool can I use to see the exact timestamps of source and destination files with optimum resolution ?

And then, if the root cause is indeed a bug from Synology and there's (maybe) nothing to do except waiting for an update from them, is there a trick to make Bvckup 2 still work in the meantime ? I saw other threads on this forum talking about changing the time granularity in the conf files of any specific job, I gave it a try with 2 sec threshold, but the issue is still there.

Thanks again
JF

Alex Pankratov :

Mar 31, 2016

What tool can I use to see the exact timestamps of source and destination files with optimum resolution ?


I think you can extract high-precision timestamp values with PowerShell. Try and google in that direction.

I gave it a try with 2 sec threshold, but the issue is still there.


I can only suggest setting the threshold to something like 2 minutes, but this increases the risk of missing modified files during a backup run.

All in all, the best course of action is to make Synology look at this and fix it up on their end. It's fairly obvious that it's an issue with their firmware.

jfsimon :

Apr 01, 2016

Many thanks Alex for your help !

Anyway, I managed to downgrade to DSM 5.2. That was not easy, but still easier than dealing with Synology support...

let's hope that this will be fixed in a later rev of DSM 6, before year 2036 if possible !

Bvckup 2 works a treat now :-)

Mabroc :

Apr 01, 2016

Yep, 5.2 works fine and to be fair DSM seems to be updated regularly with bug fixes and new options, the same for the apps like media server, download manager, etc. But I don't want to downgrade risking my current configuration and losing even more time. For now I will keep the Ā«Rescan every time optionĀ» enabled.
I tried the granularity trick using 120.000.000 value in two lined in the config as that is 2 minutes (I think) following the instructions of Alex in another post (sorry, on phone can't look it up now)  but after I saved the config file It didn't work, so I checked the file and it reverted to value 0 in both places. Tried editing again and fail again. Reverting to 0 again, maybe the value is not more calculated on the same scale and my nunber was too big? Or I need to pit the file on READ ONLY mode?
Any input Alex? Maybe adding the option to change the granularity on the GUI? So we can be more tolerant on the conditions to check for date stamps for updating or not the files.
Or in other words to fix other people fucking it up on their side of programming.
Thanks for your help guys

Alex Pankratov :

Apr 04, 2016

120.000.000 value


Those values are in 100-nanosecond intervals. So

    10 is 1 microsecond,
    1000,0 is 1 millisecond
    1,000,000,0 is 1 second

and 2 minutes will be 120,000,000,0 (note the extra zero at the end).

Or I need to pit the file on READ ONLY mode?


You have to exit the app before editing any configuration files. These INIs are read only once, on the app launch and they are being written out by the app when it runs and when it exits. So any changes you make while the app's running are effectively ignored and discarded.

Maybe adding the option to change the granularity on the GUI?


Coming up shortly. Contrary to my expectations this worked out to be a frequently needed function, so I'll be adding it into the UI.

Mabroc :

Apr 04, 2016

Thanks Alex for the granularity explanation, would try to edit it again later. Currently I have the flu and some fever, thanks to modern medicine I managing it hahaha. I feel a little high right now.

Mabroc :

Apr 08, 2016

Well I tried using this values with the program closed:
conf.ctime_gran       1200000000
conf.mtime_gran     1200000000

Aaaaaand still its not working right, I checked and the edit are still there (not resetting to "0" I mean). You run the job, copies/updates are made, you try again 10 seconds later and the same files are getting pointlessly updated again.

Sigh....

Waiting for a fix from SYNOLOGY now

Mabroc :

Apr 16, 2016

OK, they released a update 1 for DSM 6.0 and it seems they fixed it among other tiny bugs.
Will try it a couple of days and then post again

CrazyCanuck :

Apr 18, 2016

As of this morning I'm running DSM 6.0-7321 Update 2 and all is well again with Bvckup jobs...   ;)

Alex Pankratov :

Apr 18, 2016

Well. If this is not a reason for a drink, then I don't know what is :)

Mabroc :

Apr 19, 2016

Cheers!!!! Everything working fine the last couple of days since the update 1. Thanks for all info and help guys.

pbilling :

Apr 28, 2016

It got fixed on my DS216+ in Update 3, which also crashed it, though I was able to recover.  Got Update 4 yesterday, which fixes..... Start-up Stability issues with DS216+.  :-)

Simon :

May 16, 2016

Hi Alex, hi everyone,

sorry for bringing that old thread up again. Everything works fine for me when backing up files from my laptop to my NAS. The problem occurs when syncing the NAS to an attached USB hard drive. Then, bvckup updates all the files although I didn't change anything.

The log shows the same issues as Mabroc's. The time stamp is slightly changed, so everything gets copied again. I've tried to enable/disable every single option (such as copy file attributes, shadow copying, use destination snapshot, delta copying) and also changed conf.ctime_gran and conf.mtime_gran to 2 seconds - none of those attempts has changed anything.

Does anyone have the same problem? It's most possibly related to Synology, so Alex probably won't be able to help me. But if there are more users suffering from this, I have a bit of hope that Synology might fix it with an upcoming release.

Laptop: Thinkpad T440s, Windows 10
NAS: Synology DS216j
External drive: WD MyBook

Any idea how to solve the issue would be highly appreciated. Thanks!
Simon

Alex Pankratov :

May 17, 2016

Is the WD drive attached to the NAS or the laptop?

Simon :

May 18, 2016

It is attached to the NAS. Sorry for not making this clear enough.

Alex Pankratov :

May 18, 2016

Hmm, I don't know then, sorry. It might be another variation of the same issue from DSM 6.0. I'd report it to Synology, see what they have to say.

PS. I'm assuming you are running their latest (fixed up) DSM 6 build.

Simon :

May 19, 2016

Yes, I'm running DSM 6.0-7321 Update 6. Thanks for your response anyway. I'll report the issue and hope that they fix it.

CrazyCanuck :

May 20, 2016

@Simon...  I'm using the Synology 216+ box with DSM 6.0-7321.  On my device latest version update is 7.  I've tried replicating your problem with a test backup job from NAS directory to a USB key via its USB-share connection...  but everything works as expected.    

Simon :

May 20, 2016

Thanks a lot for testing it, @CrazyCanuck. That's interesting. My DSM ist still on update 6, maybe they have fixed it with the latest version. I hope that they release the update also for the DS216j.

Obviously, it's not related to the files on the NAS itself. I've tried to run the backup job from files on my laptop to the external USB hard drive attached to my NAS. The result was the same (endless updating of files). So Synology seems to update the files on the external drive some milliseconds after writing the data.

mastershakes :

Jul 06, 2019

Sorry for reviving an old thread but I have a similar issue with updating (delta) of unchanged files.  See my log below.   I have the latest DSM.  Is there a setting on the Synology I need to change?

[ log removed ]

mastershakes :

Jul 06, 2019

2019.07.06 06:59:47.616 (UTC-6) 3 3             Preparing backup plan ...
2019.07.06 06:59:47.616 (UTC-6) 3 4                 Planner setup
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Created timestamps: compare and update
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Modified timestamps: compare and update
2019.07.06 06:59:47.616 (UTC-6) 3 5                     1-hour offset: disabled
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Update folder timestamps: yes
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Preserve newer files: off
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Attributes: read-only hidden system archive
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Security info: don't compare, don't update
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Alternate streams: ignore
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Clone top folder info: no
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Files to ID: new
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Move detection: folders, files (by name/size/times, by file ID, by fuzzy matching)
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Delete policy: execute delete steps
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Archive deleted: no
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Archive modified: no
2019.07.06 06:59:47.616 (UTC-6) 3 5                     Precomp delta: no
2019.07.06 06:59:47.617 (UTC-6) 3 4                 Forcing update of MacriumRescue.iso
2019.07.06 06:59:47.617 (UTC-6) 3 4                 Forcing update of reflect\A12D392D16913C7A-00-00.mrimg
2019.07.06 06:59:47.617 (UTC-6) 3 4                 Forcing update of reflect\A12D392D16913C7A-01-01.mrimg
2019.07.06 06:59:47.617 (UTC-6) 3 4                 Forcing update of reflect\A12D392D16913C7A-02-02.mrimg
2019.07.06 06:59:47.617 (UTC-6) 3 4                 Completed in 1 ms

[ log trimmed ]

mastershakes :

Jul 06, 2019

2019.07.06 06:59:47.650 (UTC-6) 2 1     Processing ...
2019.07.06 06:59:47.650 (UTC-6) 3 2         A total of 4 steps
2019.07.06 06:59:47.650 (UTC-6) 2 2         1. Updating file MacriumRescue.iso
2019.07.06 06:59:47.650 (UTC-6) 3 3             Details
2019.07.06 06:59:47.650 (UTC-6) 3 4                 Source: 561.38 MB, created 2019.02.24 22:45:34.601, modified 2019.07.05 17:21:51.436, archive
2019.07.06 06:59:47.650 (UTC-6) 3 5                     Raw: 588644352 / 131955399346010256 / 132068389114369972 / 00000020
2019.07.06 06:59:47.650 (UTC-6) 3 4                 Backup: 561.38 MB, created 2019.02.24 22:45:34.601, modified 2019.07.05 17:21:51.436, archive
2019.07.06 06:59:47.650 (UTC-6) 3 5                     Raw: 588644352 / 131955399346010256 / 132068389114369972 / 00000020
2019.07.06 06:59:51.113 (UTC-6) 3 3             Completed in 3.46 sec, no data copied
2019.07.06 06:59:51.113 (UTC-6) 3 4                 162.13 MBps | 168.37 reading, 445.96 hashing, 0.00 writing

[ log trimmed ]

2019.07.06 07:08:44.385 (UTC-6) 2 2         4. Updating file reflect\A12D392D16913C7A-02-02.mrimg
2019.07.06 07:08:44.385 (UTC-6) 3 3             Details
2019.07.06 07:08:44.385 (UTC-6) 3 4                 Source: 1.80 GB, created 2019.07.06 03:00:35.940, modified 2019.07.06 03:01:48.276, archive
2019.07.06 07:08:44.385 (UTC-6) 3 5                     Raw: 1932857013 / 132068736359409036 / 132068737082767697 / 00000020
2019.07.06 07:08:44.385 (UTC-6) 3 4                 Backup: 1.80 GB, created 2019.07.06 03:00:35.940, modified 2019.07.06 03:01:48.276, archive
2019.07.06 07:08:44.385 (UTC-6) 3 5                     Raw: 1932857013 / 132068736359409036 / 132068737082767697 / 00000020
2019.07.06 07:08:54.606 (UTC-6) 3 3             Completed in 10 sec, no data copied
2019.07.06 07:08:54.606 (UTC-6) 3 4                 180.35 MBps | 182.58 reading, 401.77 hashing, 0.00 writing
2019.07.06 07:08:54.666 (UTC-6) 2 1     Completed in 9 min 7 sec with no errors
2019.07.06 07:08:54.666 (UTC-6) 3 2         Read 115.97 GB, wrote 0 bytes, throughput 217.12 MBps / 227669045 bps

Alex Pankratov :

Jul 08, 2019



You have an override [1] in place that forces the update of these files:

2019.07.06 06:59:47      Preparing backup plan ...
2019.07.06 06:59:47          Forcing update of MacriumRescue.iso
2019.07.06 06:59:47          Forcing update of reflect\A1...C7A-00-00.mrimg
2019.07.06 06:59:47          Forcing update of reflect\A1...C7A-01-01.mrimg
2019.07.06 06:59:47          Forcing update of reflect\A1...C7A-02-02.mrimg

[1] https://bvckup2.com/support/forum/topic/415

mastershakes :

Jul 08, 2019

Ugh.....that is correct.  I cloned another job that was backing up a Truecrypt container.  I changed it and it works perfect now.   Sorry.

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