WARNING: Found something of unexpected type in block list map

Support
1

I got these errors today. The chain of events was as follows.

  1. Syncthing was started after a 2-week period of inactivity.
  2. The folder was paused, then changed from SR to RO, and unpaused.
  3. Everything synced, but there were some local additions.
  4. One day later, the folder type was changed again to SR.
  5. Immediately after changing the folder type, Syncthing threw the errors.
  6. The files themselves seem to have synced properly regardless.
[6OTUH] 2021/05/27 19:47:59 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207383, Permissions:0644, ModTime:2021-05-27 00:43:35.7920375 +0900 KST, Version:{[{D4DZUGP 1621497718} {6OTUHAR 1622043944}]}, VersionHash:, Length:8196, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/8196/12067812/a01a43419df0f0fcd2f4b47e941d48d9ace495c748f5844747a0004165df3b73}], BlocksHash:d61004366a4827f4dbc370b858ac7089ad730b77c4edbbb3e2f50eda62c1a570}
[6OTUH] 2021/05/27 19:48:02 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207307, Permissions:0644, ModTime:2021-05-25 16:34:03.4876023 +0900 KST, Version:{[{D4DZUGP 1621494538} {EZZVMVI 1622043598}]}, VersionHash:, Length:139, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/139/2859543231/0b827a29f58530acc8d6609cc7f456548f7d087db02fb301101b6f240db4aab8}], BlocksHash:9559710919e52956ec7adddc0afa9f07a671cc3d19f81315695205e96a6a52d3}
[6OTUH] 2021/05/27 19:48:03 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207314, Permissions:0644, ModTime:2021-05-27 00:29:06.2899556 +0900 KST, Version:{[{D4DZUGP 1621494719} {EZZVMVI 1622043601}]}, VersionHash:, Length:35, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/35/4019391543/4c563f4f80448bddfece76b3b696b11d390c544b43303ec8aac807386c52fedc}], BlocksHash:b210e25290c82255debcb4e44d5d603d4c1a07575dfb3b19e658c59e245a41fe}
[6OTUH] 2021/05/27 19:48:03 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207315, Permissions:0644, ModTime:2021-05-27 00:29:06.309951 +0900 KST, Version:{[{D4DZUGP 1621494719} {EZZVMVI 1622043601}]}, VersionHash:, Length:624, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/624/3212752947/db490d434bca7a72f180429c2f2398ceeae840be626040353f3db3e00c936164}], BlocksHash:9b57adc3a9dd036230477b3a1b199c2cc42be0af19a19bcca0098013dc2c97e1}
[6OTUH] 2021/05/27 19:48:03 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207316, Permissions:0644, ModTime:2021-05-27 00:29:06.4171206 +0900 KST, Version:{[{D4DZUGP 1621494719} {EZZVMVI 1622043601}]}, VersionHash:, Length:570, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/570/2049884312/1982fb25a2b5045448de509164528a30154a038b9e4fbf36828f5fc4673fb033}], BlocksHash:f7b4c618927a335f0d5b1d728e7b6a3266f8c1c79321485819cdcbefb9cee77c}
[6OTUH] 2021/05/27 19:48:03 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207317, Permissions:0644, ModTime:2021-05-27 00:29:06.4321214 +0900 KST, Version:{[{D4DZUGP 1621494719} {EZZVMVI 1622043601}]}, VersionHash:, Length:34, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/34/3436710639/27d3ce7270e48b67154b7cc1f85deaf6da16b9557773a8a927c1ec62fcc1d27f}], BlocksHash:477de160a69e6877cfa0d71bdd01f0fe770b2bcb1eef28eb4768defce5466192}
[6OTUH] 2021/05/27 19:48:03 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207318, Permissions:0644, ModTime:2021-05-27 00:29:06.2949539 +0900 KST, Version:{[{D4DZUGP 1621494719} {EZZVMVI 1622043601}]}, VersionHash:, Length:32, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/32/3411872552/9ebcbede34c8422faceb765e5acf2d3b0de282aa26996192773faeba99b0fb82}], BlocksHash:dfbc322559baf2d190f2ff5a21d036b57ab98a95edb71477c29e61f47294729f}
[6OTUH] 2021/05/27 19:48:03 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207319, Permissions:0644, ModTime:2021-05-27 00:29:06.3039529 +0900 KST, Version:{[{D4DZUGP 1621494719} {EZZVMVI 1622043601}]}, VersionHash:, Length:1146, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/1146/128615983/73ca37f7e6efad7ae56011f1d251531b7a2f29868c0114b4468d77806d91ba9e}], BlocksHash:8b98392f48e6bb693f606b615245e79c72aa7f80d3e84a4204c5d4a200e01aa7}
[6OTUH] 2021/05/27 19:48:03 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207323, Permissions:0644, ModTime:2021-05-27 00:29:04.4004176 +0900 KST, Version:{[{D4DZUGP 1621494719} {EZZVMVI 1622043601}]}, VersionHash:, Length:20174, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/20174/3452098085/8ed1b945f481f58b4c49446524886af8b2af5113f1929a0de15ee8f1cf2f0ab8}], BlocksHash:99b424e92691a2dbc0f7b3318311ba91e00a4f2e718254dd622ca5d0dc67038e}
[6OTUH] 2021/05/27 19:48:19 WARNING: Mismatching block map list hashes: got  expected 93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e

What exactly are these errors about? I can only say that there are no hardware issues with this machine.

2

Firstly it means utter carnage o.O
The unexpected warnings could mean, that on change folder type it somehow managed to update the file (to be invalid) but did not remove the blocklist entry. The mismatching warning is even weirder: The file seems fine (not invalid), but doesn’t have the expected blockshash.

I definitely must add failure reporting to those conditions to see if this is a regular occurrence.

I guess I’ll see what happens if I do something similar:

  1. A and B SR in sync.
  2. Pause B
  3. Change some files on both A and B
  4. Change folder type to RO on B.
  5. Resume B.

Argh, too many things to investigate and fix right now. Which actually means: Thanks a lot for all the testing and reporting (especially but not only all the repros!).

3 Likes
3

Thanks for a super-quick reply, but I confused the folder types, and updated them too late to be noticed.

Syncthing was started essentially offline. In that state, I paused everything. Then I changed the folder type from SR to RO. Then I unpaused the folder and let it sync. Finally, I changed it from RO to SR again. Then the errors occurred.

Basically, the change was from SR to RO first, and from RO to SR later.

I also want to add that the last error seems to persist.

syncthing.log:[6OTUH] 2021/05/27 19:48:19 WARNING: Mismatching block map list hashes: got  expected 93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e
syncthing.log:[6OTUH] 2021/05/27 20:32:58 WARNING: Mismatching block map list hashes: got  expected 93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e
syncthing.log:[6OTUH] 2021/05/27 21:10:43 WARNING: Mismatching block map list hashes: got  expected 93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e

The folder seems to be fully in sync though (ignore the two failed items, those are locked files, unrelated to the issue).

image
image838×405 27.1 KB

I have standard, non-debug logs from the machine from the last two days. Would they be of any use?

4

Maybe, but I doubt it. Can’t be sure.

You said something about local additions before, which would make sense. Any details about when that (and the corresponding) changes happened might help.

5

Here is the log. I have filtered all folder and file names, and also shrank IDs.

syncthing.7z (241.4 KB)

Some points to note are as follows.

  1. Shutdown and restart after 10 days.

    [6OTUH] 2021/05/15 20:27:19 INFO: Exiting
[start] 2021/05/25 16:33:17 INFO: syncthing v1.16.1-dev.4.ge099cf57-tomasz86- v1.16.0 "xxx" (go1.16.3 windows-amd64) tomasz86@tomasz86 2021-05-04 09:48:44 UTC [noupgrade]

  2. Everything related to the folder bnroh-e3h4v. This is the one which was changed back and forth from SR to RO.

  3. I have left them as they are, but the log is basically filled with The process cannot access the file because it is being used by another process lines. These are some files used by a piece of software that is on almost all the time, and I doubt that they are the culprit here, because I use the same software everywhere else, and I have had no issues with it there. Filtering these out may be necessary though.

  4. The folder bnroh-e3h4v was paused, changed from SR to RO, and then unpaused here. There are tonnes of various errors in later lines, mainly because folder casing didn’t match. I fixed those later by manually renaming them to the same case.

    [6OTUH] 2021/05/25 21:17:19 INFO: Ready to synchronize "xxx" (bnroh-e3h4v) (receiveonly)
[6OTUH] 2021/05/25 21:17:19 INFO: Device D4DZUGP folder "xxx" (bnroh-e3h4v) has a new index ID (0x155E0AD6A82AD003)
[6OTUH] 2021/05/25 21:17:20 INFO: Unpaused folder "xxx" (bnroh-e3h4v) (receiveonly)
[6OTUH] 2021/05/25 21:17:30 INFO: Completed initial scan of receiveonly folder "xxx" (bnroh-e3h4v)

  5. The WARNING errors began to appear as soon as the folder bnroh-e3h4v was changed back from RO to SR.

    [6OTUH] 2021/05/27 19:47:51 INFO: Restarted folder "xxx" (bnroh-e3h4v) (sendreceive)
[6OTUH] 2021/05/27 19:47:59 WARNING: Found something of unexpected type in block list map: File{Name:"xxx", Sequence:207383, Permissions:0644, ModTime:2021-05-27 00:43:35.7920375 +0900 KST, Version:{[{D4DZUGP 1621497718} {6OTUHAR 1622043944}]}, VersionHash:, Length:8196, Deleted:false, Invalid:false, LocalFlags:0x8, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/8196/12067812/a01a43419df0f0fcd2f4b47e941d48d9ace495c748f5844747a0004165df3b73}], BlocksHash:d61004366a4827f4dbc370b858ac7089ad730b77c4edbbb3e2f50eda62c1a570}

PS Just in case anyone needs it, these are patterns that I used with sed to obfuscate the log file.

/"[^"]*"/ s//"xxx"/g
/(open|remove).*:/ s//\1 xxx:/g
/(([A-Z]|[0-9])+)-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+-([A-Z]|[0-9])+/ s//\1/g
1 Like
6

The errors persist on the same machine. I have just got this right after booting the computer.

2021-06-01 18:32:06 Mismatching block map list hashes: got  expected 93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e

Now I have a question. Would removing and re-adding the affected folder be enough to clear the broken state, or do I need to wipe out the entire database?

7

Removing only the folder should always do the trick, a full reset shouldn’t ever be required. Unless of course the db is entirely toast (Syncthing can’t even start). Could you make a copy of the db please. I haven’t had time to look into this yet, so can’t say whether there’s something to investigate/fix yet.

1 Like
8

I will remember to make a copy before doing anything with the folder. It may take some take, as this particular folder has hundreds of thousands of files, and I’m not feeling like having it being re-indexed at the very moment (as I need the other files to still sync).

Pardon me, but I have one more question though. Is there a simple way to find out which exact file the 93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e hash belongs to? Maybe just removing and re-adding the affected file would be enough to work around the issue?

9

Maybe an index-check will find this and even give some more hints: syncthing cli debug index check. Otherwise filtering a db dump for that hash should work: syncthing cli debug index dump. Both must be run on the database without Syncthing running and might take a while on a large db.

10

The first command only resulted in

syncthing cli --home=. debug index check
774 block list entries out of 20862 needs GC
Index check completed succesfully.

with no specific errors reported.

I then run the second one, and then filtered only lines with the hash in question.

[device] F:1 D:0 N:"xxx", Sequence:610431, Permissions:0644, ModTime:2021-06-01 18:21:51.5513006 +0900 KST, Version:{[{6OTUHAR 1622539926}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:0 N:"xxx", Sequence:594812, Permissions:0644, ModTime:2021-05-31 01:04:10.9533065 +0900 KST, Version:{[{D4DZUGP 1622390826}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:0 N:"xxx", Sequence:457229, Permissions:0644, ModTime:2021-05-15 16:05:43.4223187 +0900 KST, Version:{[{D4DZUGP 1621495333}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:0 N:"xxx", Sequence:457234, Permissions:0644, ModTime:2021-05-18 22:32:30.8760629 +0900 KST, Version:{[{D4DZUGP 1621495343}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:0 N:"xxx", Sequence:561546, Permissions:0644, ModTime:2021-05-26 18:34:29.2071812 +0900 KST, Version:{[{D4DZUGP 1621495343} {XZZTDIY 1622021809} {7LDIBZ4 1621126408}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:2 N:"xxx", Sequence:237444, Permissions:0644, ModTime:2021-06-01 18:21:51.5513006 +0900 KST, Version:{[{6OTUHAR 1622539926}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:2 N:"xxx", Sequence:235699, Permissions:0644, ModTime:2021-05-31 01:04:10.9533065 +0900 KST, Version:{[{D4DZUGP 1622390826}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:2 N:"xxx", Sequence:207658, Permissions:0644, ModTime:2021-05-15 16:05:43.4223187 +0900 KST, Version:{[{D4DZUGP 1621495333}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:2 N:"xxx", Sequence:92755, Permissions:0644, ModTime:2021-05-18 22:32:30.8760629 +0900 KST, Version:{[{D4DZUGP 1621495343}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:1 D:2 N:"xxx", Sequence:203613, Permissions:0644, ModTime:2021-05-26 18:34:29.2071812 +0900 KST, Version:{[{D4DZUGP 1621495343} {XZZTDIY 1622021809} {7LDIBZ4 1621126408}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:5 D:0 N:"xxx", Sequence:32288, Permissions:0644, ModTime:2020-01-30 13:42:35.7466441 +0900 KST, Version:{[{D4DZUGP 1621497411}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[device] F:5 D:2 N:"xxx", Sequence:14289, Permissions:0644, ModTime:2020-01-30 13:42:35.7466441 +0900 KST, Version:{[{D4DZUGP 1621497411}]}, VersionHash:, Length:13, Deleted:false, Invalid:false, LocalFlags:0x0, NoPermissions:true, BlockSize:131072, Blocks:[Block{0/13/526648267/7a6d204eb0e51a9b3bdb6fceb3ca0e397b443170886695f1d981621b45a13739}], BlocksHash:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e}
[blocklistmap] F:1 H:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e N:xxx
[blocklistmap] F:1 H:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e N:xxx
[blocklistmap] F:1 H:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e N:xxx
[blocklistmap] F:1 H:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e N:xxx
[blocklistmap] F:1 H:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e N:xxx
[blocklistmap] F:5 H:93cee6042c6e78e5ef8ee1bc3d1e2b7f273eb1788daa0f66fe2c431e0246ca0e N:xxx

I have obfuscated the file names, but it seems that there are 12 files using the same hash. Is this correct?

Also, I have looked up the file in the original logs, and what I have found is

[6OTUH] 2021/05/26 18:09:47 INFO: Puller (folder "xxx" (bnroh-e3h4v), item "xxx"): syncing: checking parent dirs: given name "xxx" differs from name in filesystem "XXX"

One of the folders in the path had its case changed on the remote computer. Then, after starting Syncthing on this one, there were case-related errors in the logs. I then manually changed the case locally to match the remote one. The hash errors appeared after that.

I guess that these case-only renames may be the clue here.

11

Yes

That part of the code has nothing to do with block map list hashes, but it would be a weird coincidence indeed.
If you move those files to a different location, scan and move them back, I’d expect the error to go away.

12

Yeah, this might just have been a coincidence. I have tried to reproduce in a clean environment, but I couldn’t trigger any unsuspected behaviour.

13

This topic was automatically closed 30 days after the last reply. New replies are no longer allowed.