Adding metadata with POST after the creation of an object shows 404 (multi DC) after upgrading from Kilo to Ussuri

Bug #1889661 reported by toto
14
This bug affects 2 people
Affects Status Importance Assigned to Milestone
OpenStack Object Storage (swift)
New
Undecided
Unassigned

Bug Description

Hello,

We are encountering a change of behavior in our swift clusters, while trying to upgrade from Kilo to Ussuri version.

Below are some explanations of the problem/bug we are seeing, we are requesting your help/input :

When adding the following metadata: ‘x-deleted-at : 30’ on a newly created object, we should be expecting a return code 2XX as we were seeing with Kilo version.
However, in Ussuri version now, it's actually returning a 404 Not Found return code, despite the header successfully added to the object. We are seeing a successfull POST & 202 return code on the local DC, but 404 on the others DC because the object is not yet replicated. And the client is getting back a 404 on the POST request at the end. Getting back the headers from the object shows that the x-delete-at header has been succesfully added to the object.

This behavior is happening only in our multi datacenter swift environment, not in our second environment which only has 1 datacenter. We also are using the region feature with 3 regions inside our cluster.

After some digging and testing, we found out the following article : https://specs.openstack.org/openstack/swift-specs/specs/in_progress/fastpostupdates.html and option obect_copy_as_post was removed since 2.13.0 and set by default to false.
Our cluster is currently running Kilo version and we were upgrading to Ussuri version, when we found out that issue during the upgrade process.

Since copy post-as-copy option default config is now set to false, and since the removal of all post_as_copy related code and configs, there is a regression in the behavior of adding meta headers on a newly created object in a multidata center openstack swift context.

We have a test script that do the following 4 tasks in a row :
- Create an object PUT
- Read that object GET
- Add an x-delete-at header POST
- read the header HEAD
- GET the obejct to ensure it has been correctly expired/deleted
Before upgrading the swift proxy (to ussuri or anything after octaca) , this test script was working 100 % of the time .

After upgrading to Stein/Ussuri version, with post_as_copy=true support or fast-copy , adding meta failed with 404, while the header is in fact added and confirmed with a HEAD.
Adding meta will failed with 404 as long as the object is not fully replicated on our 3 datacenters.

Once an existing object fully already replicated, adding META works 100% of the time again.

What is really messy is the post operation always succeed even if it is reported as 404. We found out that on the proxy server which is receiving the POST operation, the local storage (same datacenter) is returning a 202 success, when the 2 others are returning a 404, which leads into a 404 not found when returning the response to the swift-client.
Whereas we are expecting to get 20X on adding META on a new object.

We tried to revert back a proxy to Kilo version, and we are getting back the previous behavior when creating/adding metadata on a new object.

From what I understand, with the removal of the post_as_copy code support on new release, we can not have the original behaviour back again.

Is there any workarounds to implement this behaviour again, or at least try to mitigate it ?
Our clients using our cluster will need to do a lot of changes on their scripts/projects in order to handle this new behavior.

--------------------------------------------------------

Below are some logs to show the process in Ussuri and also what we are seing in Kilo in our production environment with the same test operations :

Current preproduction environment (1 proxy - 1 storage per datacenter)
USSURI
DC 1 proxy01 :
28/Jul/2020/14/38/25 PUT /v1/AUTH_XXXXXX/NEW/freezer100.mts HTTP/1.0 201
28/Jul/2020/14/38/25 GET /v1/AUTH_XXXXXX/NEW/freezer100.mts HTTP/1.0 200
28/Jul/2020/14/38/31 POST /v1/AUTH_XXXXXX/NEW/freezer100.mts HTTP/1.0 404
/28/Jul/2020/14/38/31 HEAD /v1/AUTH_XXXXXX/NEW/freezer100.mts HTTP/1.0 200

DC 1 Storage01 (local)

[28/Jul/2020:14:38:25 +0000] "PUT /d4/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
[28/Jul/2020:14:38:25 +0000] "PUT /d5/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
[28/Jul/2020:14:38:25 +0000] "PUT /d6/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
[28/Jul/2020:14:38:25 +0000] "GET /d5/4185/AUTH_XXXXXX/NEW/freezer100.mts" 200 93 "GET http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
[28/Jul/2020:14:38:31 +0000] "POST /d5/4185/AUTH_XXXXXX/NEW/freezer100.mts" 202 76 "POST http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
[28/Jul/2020:14:38:31 +0000] "HEAD /d5/4185/AUTH_XXXXXX/NEW/freezer100.mts" 200 93 "HEAD http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"

DC 2 Storage
28/Jul/2020:14:38:31 +0000] "POST /d4/4185/AUTH_XXXXXX/NEW/freezer100.mts" 404 70 "POST http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
DC 3 Storage
28/Jul/2020:14:38:31 +0000] "POST /d4/4185/AUTH_XXXXXX/NEW/freezer100.mts" 404 70 "POST http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"

Whereas in Kilo version, you can see that the POST are converted to PUT operations on storage servers, and there are also replicated on other storage servers:

KILO (current production environment - 2 proxy - 3 storage nodes per datacenter)
DC 1 proxy01
30/Jul/2020/08/24/13 PUT /v1/AUTH_XXXXXX/NEW/freezer100.mts HTTP/1.0 201
30/Jul/2020/08/24/14 GET /v1/AUTH_XXXXXX/NEW/freezer100.mts HTTP/1.0 200
30/Jul/2020/08/24/17 POST /v1/AUTH_XXXXXX/NEW/freezer100.mts%3Fmultipart-manifest%3Dget HTTP/1.0 202
30/Jul/2020/08/24/17 HEAD /v1/AUTH_XXXXXX/NEW/freezer100.mts HTTP/1.0 200

DC 1 storage1
[30/Jul/2020:08:24:13 +0000] "PUT /d16/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
[30/Jul/2020:08:24:14 +0000] "GET /d16/4185/AUTH_XXXXXX/NEW/freezer100.mts" 200 93 "GET http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
[30/Jul/2020:08:24:17 +0000] "GET /d16/4185/AUTH_XXXXXX/NEW/freezer100.mts" 200 93 "GET http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts?multipart-manifest=get"
[30/Jul/2020:08:24:17 +0000] "PUT /d16/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts?multipart-manifest=get"
[30/Jul/2020:08:24:17 +0000] "HEAD /d16/4185/AUTH_XXXXXX/NEW/freezer100.mts" 200 93 "HEAD http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"

DC 1 storage2
[30/Jul/2020:08:24:13 +0000] "PUT /d14/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
[30/Jul/2020:08:24:17 +0000] "PUT /d14/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts?multipart-manifest=get"
DC 1 storage3
[30/Jul/2020:08:24:13 +0000] "PUT /d1/1560/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/d14/4185/AUTH_XXXXXX/NEW/freezer100.mts" "
[30/Jul/2020:08:24:17 +0000] "PUT /d1/1560/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/d5/4185/AUTH_XXXXXX/NEW/freezer100.mts"
[30/Jul/2020:08:24:13 +0000] "PUT /d5/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts"
30/Jul/2020:08:24:17 +0000] "GET /d5/4185/AUTH_XXXXXX/NEW/freezer100.mts" 200 93 "GET http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts?multipart-manifest=get"
[30/Jul/2020:08:24:17 +0000] "PUT /d5/4185/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/v1/AUTH_XXXXXX/NEW/freezer100.mts?multipart-manifest=get"

DC 2 Storage01
[30/Jul/2020:08:24:13 +0000] "PUT /d9/1560/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/d16/4185/AUTH_XXXXXX/NEW/freezer100.mts"
[30/Jul/2020:08:24:17 +0000] "PUT /d6/381/.expiring_objects/1596067178/1596098457-AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/d14/4185/AUTH_XXXXXX/NEW/freezer100.mts"
30/Jul/2020:08:24:17 +0000] "PUT /d9/1560/AUTH_XXXXXX/NEW/freezer100.mts" 201 - "PUT http://swiftserviceurl.com/d14/4185/AUTH_XXXXXX/NEW/freezer100.mts"

Revision history for this message
clayg (clay-gerrard) wrote :

this is a very detailed bug report, thank you! I think this is describing the same issue as https://bugs.launchpad.net/swift/+bug/1818931

I think roughly we know how the code should work (we fixed a similar issue for DELETE https://bugs.launchpad.net/swift/+bug/1318375) but I haven't gotten any further than the failing unittest.

I normally discourage the use of write affinity - can you turn it off in your multi-datacenter deployment?

Revision history for this message
toto (locklock) wrote :

Hi,

thank you for your answer, and sorry for getting back to you only now, we were discussing this issue internally and testing your option.

So after few tests on our side, we are not seeing any improvement by disabling the write-affinity on the proxy servers on the 3 regions we have.

We are still seeing 20X return code on the local storage and 404 in the 2 other regions when checking the logs of the storage servers with the POST request.

We tried the write_affinity_handoff_delete_count option, without luck, as per the documentation, it only affects the PUT/DELETE requests, so no chance on this one.

To give you more informations on the issue:
- At the creation of the object, when adding the metadata immediatly after that, the POST is returning a 404.
- But after few minutes, once the object has been replicated in the 2 other regions, we are succesfully getting a 20X return code on the POST request when adding the metadata.

In order to continue our upgrade, we are thinking to ask our teams who are using this feature post_as_copy, to upload/create their object on our 3 sites in the same time, so that their POST requests won't fail when adding the metadata immediatly after the object's creation, but it looks a bit overkill just to mitigate this issue and will potentially add more load on our servers.

Surely, this object_post_as_copy feature which has been deleted may have impacted other swift' users using the multi-region feature. We are only seeing this on our side, now that we want to upgrade our swift platform unfortunately.

We have looked at the bugs you're referencing, and it looks like the same issue to me indeed. Your patch could be a good solution for us and maybe other people.

Do you have any chance to continue your work on the POST_with_write_affinity feature you were working on and an ETA ? :) or if you have any other ideas/configuration we could try to mitigate the issue while you are working on this ? So that we can wait for the feature to be added in one of the upcoming releases.

Thank you a lot in advance for your answer and help.

Revision history for this message
clayg (clay-gerrard) wrote :

I don't have any plans to work on this right now. I'll set the priority to medium and would love to work with someone who submits a working fix.

I don't think I understand how you could possibly have experienced a "404 POST after PUT" when write-affinity was turned *off*. If you can provide logs (from the PUT and POST) with swift-get-nodes output for the object - we could see what was really going on.

If this issue effects non write-affinity clusters as well, it would probably deserve a higher priority; but as of now the recommendation is to "just" not use write-affinity. In the future we'll probably have to deprecate the option if we don't find someone who is successfully USING write-affinity to maintain the feature (by fixing bugs like this).

Revision history for this message
toto (locklock) wrote :
Download full text (7.0 KiB)

Hello !

My bad, you are correct :)

We did set the write affinity to "none" instead of removing it from our configuration, which was perhaps causing the same issue, we probably did a mistake in the configuration when we were testing your workaround.
Now that we have removed it from our configuration, it's all good.
As you can see from the below logs, we are seeing the correct behaviour now.

But it's quite impacting for us, as we are using the region feature in order to provider a better latency/response time to our internal clients to manage their object on different DCs.
It would be great indeed to have this functionnality back, with the write_affinity, which was working perfectly with Kilo version.
As for now, it's a regression for us to not have this post_as_copy feature anymore.

Do you know if it will be difficult to develop a working fix for this ? Or to reimplement it by any chance ?
We would be happy to help and try the fix you can provide to "beta-test" it.

In the meantime, we will probably remove the write_affinity on our production environnement due to this bug, which will cause some latency for some of our clients.

Thanks in advance for your answer.

----------

PUT objet

./chkjmeter.pl -s dc1 -e preprod -p TESTCONTAINER -c NEW -o testsanswriteaffinity -D 3 -a 1000

--------------------------------------------------
ENV :preprod
SITE :dc1
RESOURCE :NEW/testsanswriteaffinity.dc1
URL :http://api.swift.com/v1/AUTH_TESTCONTAINER
--------------------------------------------------
OBJECT CREATE OK CHECK OK http://api.swift.com/v1/AUTH_TESTCONTAINER/NEW/testsanswriteaffinity.dc1
META ADD OK CHECK OK expired on Tue Aug 11 14:21:14 2020, NOW Tue Aug 11 14:04:35 2020

Proxy DC 1
Aug 11 14:04:30 localhost swift-proxy: 127.0.0.1 127.0.0.1 11/Aug/2020/12/04/30 PUT /v1/AUTH_TESTCONTAINER/NEW/testsanswriteaffinity.dc1 HTTP/1.0 201 - HTTP-Tiny/0.070 gAAAAABfMokIHh2x... 93 - - tx9f716ff5a39a447eb3d03-005f32894d - 0.3986 - - 1597147469.603407621 1597147470.001974583 0
Aug 11 14:04:30 localhost swift-proxy: 127.0.0.1 127.0.0.1 11/Aug/2020/12/04/30 GET /v1/AUTH_TESTCONTAINER/NEW/testsanswriteaffinity.dc1 HTTP/1.0 200 - HTTP-Tiny/0.070 gAAAAABfMokIHh2x... - 93 - tx4a6f045b844e4f12bd15d-005f32894e - 0.0176 - - 1597147470.022356033 1597147470.039961100 0
Aug 11 14:04:34 localhost swift-proxy: 127.0.0.1 127.0.0.1 11/Aug/2020/12/04/34 POST /v1/AUTH_TESTCONTAINER/NEW/testsanswriteaffinity.dc1 HTTP/1.0 202 - HTTP-Tiny/0.070 gAAAAABfMokIHh2x... - 76 - txc4d7538e50394b9a93a46-005f328951 - 0.5977 - x-delete-at:1597148474 1597147474.152446032 1597147474.750192642 0
Aug 11 14:04:35 localhost swift-proxy: 127.0.0.1 127.0.0.1 11/Aug/2020/12/04/35 HEAD /v1/AUTH_TESTCONTAINER/NEW/testsanswriteaffinity.dc1 HTTP/1.0 200 - HTTP-Tiny/0.070 gAAAAABfMokIHh2x... - - - tx213479caa1464bfa8c15d-005f328952 - 0.0184 - - 1597147475.246030569 1597147475.264401913 0

Storage DC 1

Aug 11 14:04:29 storage01.dc1 swift-object: X - - [11/Aug/2020:12:04:29 +0000] "PUT /d6/3633/AUTH_TESTCONTAINER/NEW/testsanswriteaffinity.dc1" 201 - "PUT http://api.swift.com/v1/AUTH_TESTCONTAINER/NEW/testsanswriteaffinity.dc1" "tx9f716ff5a39a447eb3d03-005f32894d" ...

Read more...

Revision history for this message
clayg (clay-gerrard) wrote :

I've heard 'em say "given enough eyeballs all bugs are shallow" - but they don't tell you it still takes perseverance. The bazaar is messy way to write software, and on projects of some age and importance it seems to me it can be kinda SLOW... the only reason I can imagine we put up with it (and all the best software we love and use ends up being open source) is because somehow the results justify the cost?!

> Do you know if it will be difficult to develop a working fix for this ?

I don't think it'll be "difficult" but there's a lot of ramp up to contributing initially; Matt is amazing and has been working on Swift a long time - it still took him a month to get a fix for a similar bug landed:

https://review.opendev.org/#/c/114120/

> Or to reimplement it by any chance ?

post_as_copy was a questionable trade off since the beginning; it took Alistair two years to get "fast-post" working the way we wanted so we could start to deprecate post_as_copy:

https://review.opendev.org/#/c/135380/

I understand for your workflows and configuration it's a regression, but from a maintainers perspective I can't imagine a realistic path back to post_as_copy. You'd have a much better shot advocating/contributing to getting this bug fixed.

But honestly, if you're operating a growing cluster - you'll be happier running with write-affinity turned off. Thanks for confirming the issue with write-affinity + POST; I'll mark the other bug as a duplicate of this one.

Revision history for this message
clayg (clay-gerrard) wrote :

Actually, this is a better example of how we fixed the similar bug with DELETE (it built on Matt's work)

https://review.opendev.org/#/c/470158/

Revision history for this message
Florian Coutard (flo06800) wrote :

Hi Clay,

Sorry we did not get back to you since august about this bug, we have been delayed by some issues.
We are on our way to upgrade our production cluster to Ussuri version around mid January like we said earlier in this topic.
Have you made any progress on this by any chance ?

We will let you know how it goes with our production cluster, if we keep the write affinity enabled or not.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.