Syncthing didn't reuse blocks and completely re-downloaded slightly modified file

Hello,

Today I encountered the next strange situation. Lots of photos were present both on machine A and machine B. The machine A slightly modified photos (changed some meta exif information). The machine B re-downloaded modified files entirely (instead of modified blocks only) and then removed their old versions.

As an example, I’d like to attach photo_original.jpg (file which was present both on machine A and B before image processing) and photo_changed.jpg (modified version, which was re-downloaded entirely from machine A ignoring existing blocks from photo_original.jpg).

Unfortunately, new users on this forum are limited to one image and can’t upload attachments. I’ll try to upload the second image in the reply.

Both machines run v1.0.1, Linux (64 bit).

Unfortunately, I’m not allowed to upload the second image. This is frustrating…

Did you manually enable the “Use Large Blocks” setting for that share by any chance?

Nope. I didn’t touch any of “advanced” settings.

If the metadata change shifts the rest of the data forward the rest of the blocks will get new hashes. This can get picked up by the rolling hash, depending on other factors (how many blocks were changed, etc).

I’ve increased your trust level so you can upload the other file if you like, and we can take a look.

Here’s an archive of both images (state A and B):

photos.zip (1.0 MB)

Yeah, there’s nothing in common between them when seen as 128k blocks;

$ stfileinfo -s state_1.jpg
File:
  state_1.jpg

Lstat:
  Size: 544377 bytes
  Mode: 0644
  Time: 2019-02-26 14:54:58 +0100 CET
        1551189298.000000000

Blocks:
  Block{0/131072/1008768692/f8bbd24036794084eab45b764e8542ea14ed64f142694e96c20890f7eee58e24}
  Block{131072/131072/1471101789/7dd7f89f68644eb06fb356d31c0343fc56b840398ff220415fa95d72eae3ef06}
  Block{262144/131072/3396226647/5cf72fe4da3d2c3a5dbe3227d435da631a97474f8b3240b25a511c1a24ad188e}
  Block{393216/131072/977311331/ce06e4506452b4bafeaf72d60f6187a10e4d29f2793318393b87d6ed5c4d8a76}
  Block{524288/20089/1097892130/85e9ae1569411655a66cd6b3f02c774c8f15e5c0f27c7ce48640fa41000419ad}
$ stfileinfo -s state_2.jpg
File:
  state_2.jpg

Lstat:
  Size: 544566 bytes
  Mode: 0644
  Time: 2019-02-26 23:20:04 +0100 CET
        1551219604.000000000

Blocks:
  Block{0/131072/931436939/788f31a53282ec2ad94dc6ca0ba61a8ad1a64981d91a5f6c17ae088f6329eace}
  Block{131072/131072/1591885536/565646c9d3181926488a615394725ac256bdfe0c126748d79bd8938e5e8dfffe}
  Block{262144/131072/4074981175/e851b0667b2fb4b0275f95eaf2a70a16edb926d71329bf226f478bf4bdfeee3d}
  Block{393216/131072/2961151558/1c7963967cba76cd55bccaa263930be716d3eab5e7c6971058b0ff066a18541e}
  Block{524288/20278/127918582/9fffa37da28d59e0de38291192a5e9225f76369b973b349bd2d5f771bd4fe1fa}

The rolling hash finder could/should have found the blocks, hard to say after the fact.

I tested it now by setting up two instances with tracing enabled, copying in state1 and then state2 (to the same name). First time it transferred five blocks over the network (no other option):

[MRIW7] 2019/02/27 07:54:54.339986 progressemitter.go:212: DEBUG: progress emitter: registering default photo.jpg
[MRIW7] 2019/02/27 07:54:54.340054 sharedpullerstate.go:248: DEBUG: sharedPullerState default photo.jpg pullNeeded start -> 1
[MRIW7] 2019/02/27 07:54:54.340088 sharedpullerstate.go:248: DEBUG: sharedPullerState default photo.jpg pullNeeded start -> 2
[MRIW7] 2019/02/27 07:54:54.340183 model.go:2050: DEBUG: model@0xc00012c000 REQ(out): I6KAH76-66SLLLB-5PFXSOA-UFJCDZC-YAOMLEK-CP2GB32-BV5RQST-3PSROAU: "default" / "photo.jpg" o=0 s=131072 h=f8bbd24036794084eab45b764e8542ea14ed64f142694e96c20890f7eee58e24 wh=20258ea2 ft=false
[MRIW7] 2019/02/27 07:54:54.340206 sharedpullerstate.go:248: DEBUG: sharedPullerState default photo.jpg pullNeeded start -> 3
[MRIW7] 2019/02/27 07:54:54.340223 model.go:2050: DEBUG: model@0xc00012c000 REQ(out): I6KAH76-66SLLLB-5PFXSOA-UFJCDZC-YAOMLEK-CP2GB32-BV5RQST-3PSROAU: "default" / "photo.jpg" o=393216 s=131072 h=ce06e4506452b4bafeaf72d60f6187a10e4d29f2793318393b87d6ed5c4d8a76 wh=56d06655 ft=false
[MRIW7] 2019/02/27 07:54:54.340247 sharedpullerstate.go:248: DEBUG: sharedPullerState default photo.jpg pullNeeded start -> 4
[MRIW7] 2019/02/27 07:54:54.340277 sharedpullerstate.go:248: DEBUG: sharedPullerState default photo.jpg pullNeeded start -> 5
[MRIW7] 2019/02/27 07:54:54.340305 model.go:2050: DEBUG: model@0xc00012c000 REQ(out): I6KAH76-66SLLLB-5PFXSOA-UFJCDZC-YAOMLEK-CP2GB32-BV5RQST-3PSROAU: "default" / "photo.jpg" o=262144 s=131072 h=5cf72fe4da3d2c3a5dbe3227d435da631a97474f8b3240b25a511c1a24ad188e wh=6878beb7 ft=false
[MRIW7] 2019/02/27 07:54:54.340326 model.go:2050: DEBUG: model@0xc00012c000 REQ(out): I6KAH76-66SLLLB-5PFXSOA-UFJCDZC-YAOMLEK-CP2GB32-BV5RQST-3PSROAU: "default" / "photo.jpg" o=524288 s=20089 h=85e9ae1569411655a66cd6b3f02c774c8f15e5c0f27c7ce48640fa41000419ad wh=41708122 ft=false
[MRIW7] 2019/02/27 07:54:54.340356 model.go:2050: DEBUG: model@0xc00012c000 REQ(out): I6KAH76-66SLLLB-5PFXSOA-UFJCDZC-YAOMLEK-CP2GB32-BV5RQST-3PSROAU: "default" / "photo.jpg" o=131072 s=131072 h=7dd7f89f68644eb06fb356d31c0343fc56b840398ff220415fa95d72eae3ef06 wh=3bb4751c ft=false
[MRIW7] 2019/02/27 07:54:54.341608 sharedpullerstate.go:258: DEBUG: sharedPullerState default photo.jpg pullNeeded done -> 4
[MRIW7] 2019/02/27 07:54:54.341680 sharedpullerstate.go:258: DEBUG: sharedPullerState default photo.jpg pullNeeded done -> 3
[MRIW7] 2019/02/27 07:54:54.341875 sharedpullerstate.go:258: DEBUG: sharedPullerState default photo.jpg pullNeeded done -> 2
[MRIW7] 2019/02/27 07:54:54.342053 sharedpullerstate.go:258: DEBUG: sharedPullerState default photo.jpg pullNeeded done -> 1
[MRIW7] 2019/02/27 07:54:54.342203 sharedpullerstate.go:258: DEBUG: sharedPullerState default photo.jpg pullNeeded done -> 0
[MRIW7] 2019/02/27 07:54:54.355505 folder_sendrecv.go:1549: DEBUG: sendreceive/default@0xc000224000 closing photo.jpg

second time it reused three and transferred two - the first block that contains the changed metadata, and the last one which is now a different size:

[MRIW7] 2019/02/27 07:55:14.035080 progressemitter.go:212: DEBUG: progress emitter: registering default photo.jpg
[MRIW7] 2019/02/27 07:55:14.047797 sharedpullerstate.go:222: DEBUG: sharedPullerState default photo.jpg copyNeeded -> 4
[MRIW7] 2019/02/27 07:55:14.048114 sharedpullerstate.go:222: DEBUG: sharedPullerState default photo.jpg copyNeeded -> 3
[MRIW7] 2019/02/27 07:55:14.048156 sharedpullerstate.go:248: DEBUG: sharedPullerState default photo.jpg pullNeeded start -> 1
[MRIW7] 2019/02/27 07:55:14.048224 model.go:2050: DEBUG: model@0xc00012c000 REQ(out): I6KAH76-66SLLLB-5PFXSOA-UFJCDZC-YAOMLEK-CP2GB32-BV5RQST-3PSROAU: "default" / "photo.jpg" o=0 s=131072 h=788f31a53282ec2ad94dc6ca0ba61a8ad1a64981d91a5f6c17ae088f6329eace wh=c8c76b7c ft=false
[MRIW7] 2019/02/27 07:55:14.048488 sharedpullerstate.go:222: DEBUG: sharedPullerState default photo.jpg copyNeeded -> 1
[MRIW7] 2019/02/27 07:55:14.048519 sharedpullerstate.go:248: DEBUG: sharedPullerState default photo.jpg pullNeeded start -> 2
[MRIW7] 2019/02/27 07:55:14.048585 model.go:2050: DEBUG: model@0xc00012c000 REQ(out): I6KAH76-66SLLLB-5PFXSOA-UFJCDZC-YAOMLEK-CP2GB32-BV5RQST-3PSROAU: "default" / "photo.jpg" o=524288 s=20278 h=9fffa37da28d59e0de38291192a5e9225f76369b973b349bd2d5f771bd4fe1fa wh=79fe1f6 ft=false
[MRIW7] 2019/02/27 07:55:14.048911 sharedpullerstate.go:258: DEBUG: sharedPullerState default photo.jpg pullNeeded done -> 1
[MRIW7] 2019/02/27 07:55:14.049110 sharedpullerstate.go:258: DEBUG: sharedPullerState default photo.jpg pullNeeded done -> 0
[MRIW7] 2019/02/27 07:55:14.061918 folder_sendrecv.go:1549: DEBUG: sendreceive/default@0xc000224000 closing photo.jpg

I think this works as advertised.

The question becomes, how did you determine the file was completely re-downloaded?

1 Like

The matter is this file is one of 3k which are still being downloaded. I can observe that progress indicator of each individual file shows only yellow/red Downloaded/Downloading and nothing from Reused/Copied from original/Copied from elsewhere.

If it’s still ongoing, go the the destination side and open up the log in the GUI (Actions => Log). Click the debugging tab. Enable “model” among the checkboxes. Let it run for a short while, and grab the debug output from the log tab. Let’s see that.

Unfortunately, it has just completed but once the situation replicates, I’ll grab the debug output from the log tab.

Well, you can enable the debugging and do your metadata thing on a chosen photo. All the easier to figure out when there’s just the one thing to look at in the log.

1 Like

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