proxy server reports 202 even though backend didn't accept object

[Caleb Tennis]

I tried a test where I was going to overwrite an object, but before doing so I failed some disks and also purposely set the date back in time on the object nodes. The various disks returned errors, and none of the fragments were overwritten...however, the proxy server returned a 202.

Oct 1 12:03:42 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:42 +0000] "PUT /d4/1002/AUTH_user1/testcontainer3/74mb" 409 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0008 "-" 1769 1
Oct 1 12:03:42 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:42 +0000] "PUT /d6/1002/AUTH_user1/testcontainer3/74mb" 507 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0004 "-" 1771 1
Oct 1 12:03:42 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:42 +0000] "PUT /d5/1002/AUTH_user1/testcontainer3/74mb" 409 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0007 "-" 1766 1
Oct 1 12:03:42 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:42 +0000] "PUT /d3/1002/AUTH_user1/testcontainer3/74mb" 409 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0008 "-" 1768 1
Oct 1 12:03:42 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:42 +0000] "PUT /d7/1002/AUTH_user1/testcontainer3/74mb" 507 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0004 "-" 1768 1
Oct 1 12:03:42 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:42 +0000] "PUT /d1/1002/AUTH_user1/testcontainer3/74mb" 499 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0047 "-" 1771 1

Oct 1 12:03:38 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:38 +0000] "PUT /d21/1002/AUTH_user1/testcontainer3/74mb" 409 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0008 "-" 12771 1
Oct 1 12:03:38 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:38 +0000] "PUT /d19/1002/AUTH_user1/testcontainer3/74mb" 409 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0007 "-" 12771 1
Oct 1 12:03:38 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:38 +0000] "PUT /d23/1002/AUTH_user1/testcontainer3/74mb" 507 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0005 "-" 12772 1
Oct 1 12:03:38 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:38 +0000] "PUT /d16/1002/AUTH_user1/testcontainer3/74mb" 409 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0014 "-" 12771 1
Oct 1 12:03:38 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:38 +0000] "PUT /d22/1002/AUTH_user1/testcontainer3/74mb" 507 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0007 "-" 12771 1
Oct 1 12:03:38 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:38 +0000] "PUT /d20/1002/AUTH_user1/testcontainer3/74mb" 499 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0046 "-" 12771 1
Oct 1 12:03:38 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:38 +0000] "PUT /d17/1002/AUTH_user1/testcontainer3/74mb" 499 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0081 "-" 12807 1

Oct 1 12:03:36 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:36 +0000] "PUT /d11/1002/AUTH_user1/testcontainer3/74mb" 507 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0020 "-" 4725 1
Oct 1 12:03:36 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:36 +0000] "PUT /d12/1002/AUTH_user1/testcontainer3/74mb" 409 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0018 "-" 4725 1
Oct 1 12:03:36 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:36 +0000] "PUT /d10/1002/AUTH_user1/testcontainer3/74mb" 507 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0011 "-" 4725 1
Oct 1 12:03:36 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:36 +0000] "PUT /d14/1002/AUTH_user1/testcontainer3/74mb" 409 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0008 "-" 4736 1
Oct 1 12:03:36 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:36 +0000] "PUT /d9/1002/AUTH_user1/testcontainer3/74mb" 499 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0032 "-" 4718 1
Oct 1 12:03:36 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:36 +0000] "PUT /d8/1002/AUTH_user1/testcontainer3/74mb" 499 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0070 "-" 4718 1
Oct 1 12:03:36 localhost object-server: 172.30.3.45 - - [01/Oct/2010:12:03:36 +0000] "PUT /d15/1002/AUTH_user1/testcontainer3/74mb" 499 - "PUT http://172.30.3.45/v1/AUTH_user1/testcontainer3/74mb" "txcfd2dc583d734458809b3-004ca5ce1a" "proxy-server 12744" 0.0040 "-" 4730 1

proxy server response:

Oct 1 12:03:38 localhost proxy-server: 172.30.3.180 172.30.3.180 01/Oct/2010/12/03/38 PUT /v1/AUTH_user1/testcontainer3/74mb HTTP/1.0 202 - python-requests/2.2.1%20CPython/2.7.6%20Linux/3.13.0-48-generic user1%2CAUTH_tk9b2... - 76 - txcfd2dc583d734458809b3-004ca5ce1a - 0.0385 - - 1285934618.750157118 1285934618.788640022 1

[Caleb Tennis (ctennis)]

I turned on debug log and also got this added info (was a separate request, so timestamps may not be the same as above)

Oct 1 12:02:05 localhost proxy-server: Object PUT returning 202 for 409: 1285934525.82910 <= '409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942), 409 (1441293773.02942)' (txn: tx6809c557b9b3464297615-004ca5cdbd) (client_ip: 172.30.3.180)

[John Dickinson (notmyname)]

This is more related to container sync than EC (even though it was seen with an EC policy). It should also be happening under replicated date.

Updated tags and title to reflect this

[Hisashi Osanai (osanai-hisashi)]

I think this bug is related to client side behavior to fix this we need to support 100 continue flow in swiftclient and SimpleClient.

[Hisashi Osanai (osanai-hisashi)]

Additional explanation:

This behavior is expected one. When each object-server gets an object that has old timestamp than existed one.
https://github.com/openstack/swift/blob/master/swift/obj/server.py#L483

Then proxy-server summarizes the response codes from 409 to 202.
https://github.com/openstack/swift/blob/master/swift/proxy/controllers/obj.py#L595

The problem here is:
After object-servers responded 409, proxy-server has been consuming data from client. If data is small, the behavior
is same as the description of this bug report but if data is big, client tries to send the data until chunk timeout happened.

[Hisashi Osanai (osanai-hisashi)]

The solution was decided at the hackathon in Bristol:
https://review.openstack.org/#/c/270961/

[OpenStack Infra (hudson-openstack)]

Change abandoned by Hisashi Osanai (<email address hidden>) on branch: master
Review: https://review.openstack.org/279417
Reason: The decision was made in the hackathon in Bristol.
A solution using 100-continue is better one but intoroduce additional dependency so we decided to head before put approach.

[Oshrit Feder (oshritf)]

https://review.openstack.org/#/c/270961/ merged

[clayg (clay-gerrard)]

I think now that container sync doesn't require the 202 we can consider deprecating compatibility with old container sync agents and returning the 409 directly as the error it is

https://github.com/openstack/swift/blob/a30351bdfc60f827979c5afe76ad40bf3a2b05c3/swift/proxy/controllers/obj.py#L482

We should *not* revert the behavior that allowed the proxy to place the object on handoff nodes and return 201 - we should just return the 409 from the object servers that already have the same ts or newer and know that new-ish container-sync will be fine with that (it will right?).