Skip deleting files that we just deleted

[hsmade]

We see this happening with Swift. Because the consistency of swift is eventual, swift sometimes didn't process the deletion of the meta file yet, and so it turns up in the bkt.Iter(). The second deletion then causes a 404 and compaction fails.

• I added CHANGELOG entry for this change.
• Change is not relevant to the end user.

Changes

Verification

[hsmade]

{
  "caller": "fetcher.go:189",
  "component": "block.MetaFetcher",
  "level": "debug",
  "msg": "download meta",
  "name": "01E065XF3TXB1VQ765VJS9QTBT/meta.json",
  "ts": "2020-02-25T13:38:12.902114856Z"
}


{
  "blocks": "[data/compact/0@16967372497332894226/01E065XF3TXB1VQ765VJS9QTBT data/compact/0@16967372497332894226/01E067MCXV4G386C5R7SZF9KWM data/compact/0@16967372497332894226/01E069BAQZWB9DYZRDR20RJS6G data/compact/0@16967372497332894226/01E06B28HY6X0FD6M57BFMQHDY]",
  "caller": "compact.go:733",
  "compactionGroup": "0@16967372497332894226",
  "duration": "54.278347188s",
  "level": "debug",
  "msg": "downloaded and verified blocks",
  "ts": "2020-02-25T13:49:02.610198004Z"
}


{
  "caller": "compact.go:441",
  "count": 4,
  "duration": "1m1.290166319s",
  "level": "info",
  "maxt": 1580760000000,
  "mint": 1580752800000,
  "msg": "compact blocks",
  "sources": "[01E065XF3TXB1VQ765VJS9QTBT 01E067MCXV4G386C5R7SZF9KWM 01E069BAQZWB9DYZRDR20RJS6G 01E06B28HY6X0FD6M57BFMQHDY]",
  "ts": "2020-02-25T13:50:03.900468827Z",
  "ulid": "01E1Y9QBSJ3NHQMSRAJ6FQXPX1"
}


{
  "blocks": "[data/compact/0@16967372497332894226/01E065XF3TXB1VQ765VJS9QTBT data/compact/0@16967372497332894226/01E067MCXV4G386C5R7SZF9KWM data/compact/0@16967372497332894226/01E069BAQZWB9DYZRDR20RJS6G data/compact/0@16967372497332894226/01E06B28HY6X0FD6M57BFMQHDY]",
  "caller": "compact.go:764",
  "compactionGroup": "0@16967372497332894226",
  "duration": "1m1.33904902s",
  "level": "debug",
  "msg": "compacted blocks",
  "overlapping_blocks": false,
  "ts": "2020-02-25T13:50:03.94934599Z"
}


{
  "caller": "compact.go:834",
  "compactionGroup": "0@16967372497332894226",
  "level": "info",
  "msg": "deleting compacted block",
  "old_block": "01E065XF3TXB1VQ765VJS9QTBT",
  "ts": "2020-02-25T13:50:32.309739616Z"
}


{
  "bucket": "thanos",
  "caller": "block.go:140",
  "compactionGroup": "0@16967372497332894226",
  "file": "01E065XF3TXB1VQ765VJS9QTBT/meta.json",
  "level": "debug",
  "msg": "deleted file",
  "ts": "2020-02-25T13:50:32.907953626Z"
}


{
  "bucket": "thanos",
  "caller": "block.go:157",
  "compactionGroup": "0@16967372497332894226",
  "file": "01E065XF3TXB1VQ765VJS9QTBT/chunks/000001",
  "level": "debug",
  "msg": "deleted file",
  "ts": "2020-02-25T13:50:33.533423488Z"
}


{
  "bucket": "thanos",
  "caller": "block.go:157",
  "compactionGroup": "0@16967372497332894226",
  "file": "01E065XF3TXB1VQ765VJS9QTBT/index",
  "level": "debug",
  "msg": "deleted file",
  "ts": "2020-02-25T13:50:33.655638721Z"
}


{
  "caller": "prober.go:117",
  "level": "warn",
  "msg": "changing probe status",
  "reason": "error executing compaction: compaction failed: compaction failed for group 0@16967372497332894226: delete old block from bucket: delete block 01E065XF3TXB1VQ765VJS9QTBT from bucket: Resource not found",
  "status": "not-ready",
  "ts": "2020-02-25T13:50:34.386430986Z"
}


{
  "caller": "http.go:78",
  "component": "compact",
  "err": "error executing compaction: compaction failed: compaction failed for group 0@16967372497332894226: delete old block from bucket: delete block 01E065XF3TXB1VQ765VJS9QTBT from bucket: Resource not found",
  "level": "info",
  "msg": "internal server shutdown",
  "service": "http/server",
  "ts": "2020-02-25T13:50:34.38667029Z"
}


{
  "caller": "prober.go:137",
  "level": "info",
  "msg": "changing probe status",
  "reason": "error executing compaction: compaction failed: compaction failed for group 0@16967372497332894226: delete old block from bucket: delete block 01E065XF3TXB1VQ765VJS9QTBT from bucket: Resource not found",
  "status": "not-healthy",
  "ts": "2020-02-25T13:50:34.386719215Z"
}


{
  "caller": "main.go:194",
  "err": "error executing compaction: compaction failed: compaction failed for group 0@16967372497332894226: delete old block from bucket: delete block 01E065XF3TXB1VQ765VJS9QTBT from bucket: Resource not found",
  "level": "error",
  "msg": "running command failed",
  "ts": "2020-02-25T13:50:34.386763391Z"
}

[bwplotka]

Wow, this eventual consistency is really bad... (:

But good to know!

@khyatisoneji do you mind taking a look at this PR, how we can fix this? You have quite good experience with working with eventual consistency systems so far ❤️ !

Looks like yet another reason to finish this: https://thanos.io/proposals/201901-read-write-operations-bucket.md/

[bwplotka]

However still I can't see the problem. Even with inconsistency Iter should not repeat same file 🤔 Is it really the case now?

[hsmade]

The swift logs tell us so, I'll ask our cloud team for some logs to add to this PR.

[leeuwenrjj]

However still I can't see the problem.
Even with inconsistency Iter should not repeat same file 🤔 Is it really the case now?

The problem is the code first starts with deleting metadata.json outside of the iter loop in "Delete()"
Next it lists all items in the bucket (where also the metadata.json is located) and does the iter loop over all files it got from the list.
So if the delete is not fully processed on all nodes with the bucket index you might end up with a list that still contains the metadata.json. Now the iter items will also try to delete it but the original delete actually is processed and the object store will throw an error.

Note that Amazon S3 will have the exact same issue, from the amazon docs here :

• A process deletes an existing object and immediately lists keys within its bucket. Until the deletion is fully propagated, Amazon S3 might list the deleted object.

[hsmade]

(stripped) logs from swift:

{
  "_index": "logstash-2020.02.25",
  "_type": "doc",
  "_source": {
    "timestamp": "2020-02-25T12:21:33.408687+00:00",
    "data": {
      "_SYSTEMD_UNIT": "openstack-swift-proxy.service",
      "msg": "xx.xx.xx.xx yy.yy.yy.yy 25/Feb/2020/12/21/33 DELETE /v1/xxxxxxxxxxxxx/thanos/01E062FKFT3YMZFGCQGZSTYKVF/meta.json HTTP/1.0 204 - gophercloud/2.0.0",
      "_SOURCE_REALTIME_TIMESTAMP": "1582633293407785"
    },
    "@timestamp": "2020-02-25T12:21:33.409Z",
  }
}

{
  "_index": "logstash-2020.02.25",
  "_type": "doc",
  "_source": {
    "timestamp": "2020-02-25T12:21:34.111697+00:00",
    "data": {
      "_SYSTEMD_UNIT": "openstack-swift-proxy.service",
      "msg": "xx.xx.xx.xx yy.yy.yy.yy 25/Feb/2020/12/21/34 DELETE /v1/xxxxxxxxxxxxx/thanos/01E062FKFT3YMZFGCQGZSTYKVF/meta.json HTTP/1.0 404 - gophercloud/2.0.0",
      "_SOURCE_REALTIME_TIMESTAMP": "1582633294111419",
    },
    "@timestamp": "2020-02-25T12:21:34.112Z",
  }
}

[khyatisoneji]

I think having this extra check would be good since we are deleting the meta.json first and then iterating on the files in the folder. There can be cases when the file delete call succeeds, but a GET call still returns the file.

[bwplotka]

I mean... to me it looks like we want to actually use Delayed Delete always? @khyatisoneji

[khyatisoneji]

Just for clarification, by delayed delete do you mean that we don't straightaway delete the block right?

This case is about block.Delete function which first deletes meta.json file inside the block and then iterates over all files in the block. This scenario occurs when even after deletion of meta.json file, we get meta.json file in the bkt.Iter function call.

So this particular concern is not about deleting the blocks after some delay. Even if we delete the block after some delay, this scenario can happen

[hsmade]

Just tested this PR in our integration env, and where we had errors almost every hour, they're now gone.

[bwplotka]

Thanks for debugging this!

I explained why the current fix is a bit unsafe and may introduce bugs someday below, and gave suggestion on how to avoid it.
Hope that makes sense (:

[bwplotka]

Thank you! Small nit only 👍
LGTM

[bwplotka]

This works as intended so I would prefer no log line even.

[bwplotka]

Suggested change

	// deleteDirRec removes all objects prefixed with dir from the bucket. It skips objects that return true for the passed keep func
	// deleteDirRec removes all objects prefixed with dir from the bucket. It skips objects that return true for the passed keep function.

[bwplotka]

Suggested change

	// Delete the bucket, but skip the metaFile, if found. As we just deleted that.
	// Delete the bucket, but skip the metaFile as we just deleted that. This is required for eventual object storages (list after write).

[bwplotka]

🎉

Thanks for fixing this 💪

... and sorry for being so strict here. I hope you felt supported and I am sure next PRs will be smoother! (: