Metadata was reported as not changed, but still requires being added?

iperov · April 24, 2018, 4:01am

I upgraded windows from 7 to 10, changed IP, used saved job json, repaired base at first start, and got this after job complete every time.

DeletedFiles: 0
DeletedFolders: 0
ModifiedFiles: 0
ExaminedFiles: 120197
OpenedFiles: 45359
AddedFiles: 0
SizeOfModifiedFiles: 0
SizeOfAddedFiles: 0
SizeOfExaminedFiles: 10759036755
SizeOfOpenedFiles: 8461393783
NotProcessedFiles: 0
AddedFolders: 0
TooLargeFiles: 0
FilesWithError: 0
ModifiedFolders: 0
ModifiedSymlinks: 0
AddedSymlinks: 0
DeletedSymlinks: 0
PartialBackup: False
Dryrun: False
MainOperation: Backup
CompactResults:
    DeletedFileCount: 2
    DownloadedFileCount: 0
    UploadedFileCount: 0
    DeletedFileSize: 1706
    DownloadedFileSize: 0
    UploadedFileSize: 0
    Dryrun: False
    MainOperation: Compact
    ParsedResult: Warning
    EndTime: 24.04.2018 7:50:46 (1524545446)
    BeginTime: 24.04.2018 7:50:43 (1524545443)
    Duration: 00:00:02.4068250
    Messages: [
        2018-04-24 07:47:08 +03 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Началась операция Backup,
        2018-04-24 07:47:09 +03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-04-24 07:47:37 +03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (119 байт),
        2018-04-24 07:50:15 +03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bcd2ffa7a6f484b87b459f16749a726b2.dblock.zip.aes (829 байт),
        2018-04-24 07:50:41 +03 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bcd2ffa7a6f484b87b459f16749a726b2.dblock.zip.aes (829 байт),
...
    ]
    Warnings: [
        2018-04-24 07:47:37 +03 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-UnexpextedMetadataLookup]: Metadata was reported as not changed, but still requires being added?
Hash: JyiamZ4Zw9uu7ZDZ458mpCJb18r9Pu9O4B3C/4F6TsE=, Length: 149, ID: 14699,
        2018-04-24 07:47:40 +03 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-UnexpextedMetadataLookup]: Metadata was reported as not changed, but still requires being added?
Hash: GKiUCE4QHK+ipqY0dyyGcf8KXtixoIudnuD61H0mh+o=, Length: 149, ID: 14700,
        2018-04-24 07:47:42 +03 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-UnexpextedMetadataLookup]: Metadata was reported as not changed, but still requires being added?
Hash: xLQevAc4f/Lpp6VK9dzc82CtJo8oSytWpcXLth/NjGw=, Length: 153, ID: 97972,
        2018-04-24 07:47:42 +03 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-UnexpextedMetadataLookup]: Metadata was reported as not changed, but still requires being added?

and so on

samw · April 25, 2018, 12:01pm

What OS and File System are we talking about here? So far file meta data such as ACLs are not supported on Windows so this could be related to `nix type of OS. Anything special about those files?

mr-flibble · April 26, 2018, 11:28am

Hello, I have similar problem - but problem started after upgrading to newest cannary
2.0.3.6_canary_2018-04-23

No errors before upgrade.
Windows 7 x64

Backup job is stuck and need to be stopped and Duplicati restarted (database in use)

 Messages: [
        2018-04-24 01:00:00 +02 - [Information-Duplicati.Library.Main.Controller-StartingOperation]: Operace Backup zahájena,
        2018-04-24 01:02:04 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Started:  (),
        2018-04-24 01:02:09 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: List - Completed:  (4,82 KB),
        2018-04-24 01:26:02 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Started: duplicati-bb25b766bdca94bce9dc82cc5dae92c67.dblock.zip (49,90 MB),
        2018-04-24 01:26:03 +02 - [Information-Duplicati.Library.Main.BasicResults-BackendEvent]: Backend event: Put - Completed: duplicati-bb25b766bdca94bce9dc82cc5dae92c67.dblock.zip (49,90 MB),
...
    ]
    Warnings: [
        2018-04-24 01:23:28 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-UnexpextedMetadataLookup]: Metadata was reported as not changed, but still requires being added?
Hash: C1zih1Yvex+TYRUDG4YByiZXOAxwS0KjQyXEaWPYlXI=, Length: 137, ID: 6694,
        2018-04-24 01:25:30 +02 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-UnexpextedMetadataLookup]: Metadata was reported as not changed, but still requires being added?
Hash: xWw6+ADklL0O1x9kZdP8VCA2CQ/NrMPm7amHJQImw+0=, Length: 137, ID: 6704

Full log:
https://pastebin.com/qA8MpZCa

Edit:

I started new backup with verbose logging to file, so I add more information if I get them

mmiat · May 2, 2018, 2:21pm

me too after upgrading

mr-flibble · May 14, 2018, 2:19pm

@iperov and @mmiat
Did you tried downgrade to 2.0.3.5 (or 4)?
I had this problem to, but it turn out that this error can be only symptom to Canary 2.0.3.6 and slow queries · Issue #3194 · duplicati/duplicati · GitHub problem

Edit:

I have this problem after upgrading to 2.0.3.7
issue on github:

ethauvin · June 19, 2018, 1:46am

I have the same issue after updating to 2.0.3.7_canary_2018-06-17, from 2.0.3.5_canary_2018-04-13.

Recreating the database doesn’t help. Backups now take hours instead of minutes.

I’m using --check-filetime-only=true on all backups if that matters.

JonMikelV · June 22, 2018, 4:01am

is your issue that you are getting the “Metadata was reported as not changed, but still requires being added” errors, that the backups on 2.0.3.7 are slow, or both?

ethauvin · June 22, 2018, 4:16am

Both. The metadata checks are slowing the backups down to a crawl.

JonMikelV · June 22, 2018, 4:30am

Just as test (certainly not a solution) does adding --skip-metadata=true improve things at all?

--skip-metadata
Use this option to disable the storage of metadata, such as file timestamps. Disabling metadata storage will speed up the backup and restore operations, but does not affect file size much.
Default value: “false”

The Github post mentioned above suggests maybe the issue is related to the multi-threaded processing added in 2.0.3.6. Does setting any of the following to 0 improve things?

--concurrency-max-threads
--concurrency-block-hashers
--concurrency-compressors

ethauvin · June 22, 2018, 6:36am

--skip-metadata made no differences. I’ll test the concurrency stuff in the morning.

Thanks.

ethauvin · June 23, 2018, 12:56am

The concurrency options didn’t make a difference either. Still getting thousands of meta-data warnings, and thus taking forever to complete backups.

JonMikelV · June 24, 2018, 4:27am

Thanks for doing those tests. It sounds like the bug was introduced with the multi-threading code in 2.0.3.6 but isn’t actually caused BY the multi-threading.

If reverting to 2.0.3.5 is an option for you give that a try.

Oh, and it looks like I’m not seeing any answers to @samw’s request for OS and filesystem info, can you provide that? Since I can’t replicate the problem on my Windows 10 / NTFS machine I’m assuming that’s not what you are using, but I could be wrong (maybe it’s Domain or other permission related).

ethauvin · June 25, 2018, 8:50pm

Using Windows 10 too…

Host Name:                 HAVOK
OS Name:                   Microsoft Windows 10 Pro
OS Version:                10.0.17134 N/A Build 17134
OS Manufacturer:           Microsoft Corporation
OS Configuration:          Standalone Workstation
OS Build Type:             Multiprocessor Free
Registered Owner:          Windows User
Registered Organization:
Product ID:                <removed>
Original Install Date:     5/20/2018, 18:45:54
System Boot Time:          6/21/2018, 16:01:51
System Manufacturer:       HP-Pavilion
System Model:              GC385AV-ABA d4890y
System Type:               x64-based PC
Processor(s):              1 Processor(s) Installed.
                           [01]: Intel64 Family 6 Model 15 Stepping 7 GenuineIntel ~2400 Mhz
BIOS Version:              Phoenix Technologies, LTD  5.06, 5/4/2007
Windows Directory:         C:\WINDOWS
System Directory:          C:\WINDOWS\system32
Boot Device:               \Device\HarddiskVolume1
System Locale:             en-us;English (United States)
Input Locale:              en-us;English (United States)
Time Zone:                 (UTC-08:00) Pacific Time (US & Canada)
Total Physical Memory:     8,190 MB
Available Physical Memory: 2,854 MB
Virtual Memory: Max Size:  10,877 MB
Virtual Memory: Available: 3,287 MB
Virtual Memory: In Use:    7,590 MB
Page File Location(s):     C:\pagefile.sys
Domain:                    THAUVIN
Logon Server:              \\HAVOK
Hotfix(s):                 3 Hotfix(s) Installed.
                           [01]: KB4103729
                           [02]: KB4287903
                           [03]: KB4284835
Network Card(s):           2 NIC(s) Installed.
                           [01]: TAP-Windows Adapter V9
                                 Connection Name: Ethernet 2
                                 Status:          Media disconnected
                           [02]: Intel(R) 82566DC Gigabit Network Connection
                                 Connection Name: Ethernet
                                 DHCP Enabled:    Yes
                                 DHCP Server:     192.168.1.1
                                 IP address(es)
                                 [01]: 192.168.1.198
                                 [02]: fe80::55d9:32cf:1c35:b7ef
Hyper-V Requirements:      VM Monitor Mode Extensions: Yes
                           Virtualization Enabled In Firmware: Yes
                           Second Level Address Translation: No
                           Data Execution Prevention Available: Yes

Chipmaster · June 25, 2018, 10:11pm

I have the same issue as ethauvin and I’m on debian:

Linux 4.9.0-6-amd64 #1 SMP Debian 4.9.88-1 (2018-04-29) x86_64 GNU/Linux
/dev/mapper/raid on /media/raid type xfs (rw,relatime,attr2,inode64,sunit=1024,swidth=2048,noquota)

A commonality between us is the use of --check-filetime-only=true

JonMikelV · June 26, 2018, 1:51am

I’ll try to give that a test, but I was under the impression that parameter was added as an attempt to STOP the metadata errors, is that not correct?

Chipmaster · June 26, 2018, 10:16am

No, I had that setting prior to the upgrade from 2.0.3.5 to 2.0.3.7. I was using it to speed up the 2.0.3.5 backups.

JonMikelV · June 26, 2018, 4:19pm

Yeah - and there’s no need to test now because one of my backups just came up with that warning yesterday! Yay?

So this was with 2.0.3.7 on Windows 10 w/NTFS and I’m not using --check-filetime-only.

In looking at my history it seems this has happened 3 times total, all since May 11 and on two machines (both Windows 10 w/NTFS). Since I update pretty much as soon as I see an update is available I’m going to assume it started with the 2.0.3.6 version that cam out on April 23.

There were plenty of success runs between these warning runs so whatever the issue is is seems to be transient.

@kenkendk, it seems this message has a typo (“UnexpextedMetadataLookup” vs. “UnexpectedMetadataLookup”) is it worth fixing that BEFORE the surrounding issue is resolved or should it be left alone so as not to muddy the error messages?

...
MainOperation: Backup
ParsedResult: Warning
Version: 2.0.3.7 (2.0.3.7_canary_2018-06-17)
EndTime: 6/25/2018 10:06:30 PM (1529982390)
BeginTime: 6/25/2018 8:57:09 PM (1529978229)
Duration: 01:09:21.5726887
Log data:
2018-06-25 21:51:24 -05 - [Warning-Duplicati.Library.Main.Operation.Backup.FileBlockProcessor.FileEntry-UnexpextedMetadataLookup]: Metadata was reported as not changed, but still requires being added?
Hash: di0UFaGBUyBsWxogpGsL3G2GmRk2kxnigX+IxpcupEU=, Length: 137, ID: 51067

Chipmaster · June 26, 2018, 10:41pm

In my case, almost every single file I backup for every backup produces this warning. So my backup of 38083 files produces “38051 warning(s)”.

ethauvin · June 26, 2018, 11:41pm

Same here. Multiple backups (local and remotes) all having the same behaviors now.

ethauvin · June 26, 2018, 11:42pm

Not transient for me. Every time, every single backups.