A response code of get using SLO is changed regarding a position of missing segment

[Hisashi Osanai]

[Description]
A response code of get using SLO is changed regarding a position of missing segment

I think SLO should behave same when users download an object even if
there is a difference for a position of missing segment.

[Version details]
swift 2.1.0

[Crystal clear details to reproduce the bug]

preparation:
    AUTH_TOKEN=<authentication token>
    ENDPOINT=<objectstorage endpoint>
    CONTAINER="slotest-container"
    MANIOBJECT="slotest-maniobj"
    SEGOBJECT1="segobj1"
    SEGOBJECT2="segobj2"
    SEGOBJECT3="segobj3"

(1) create files for the segments
    python -c 'open("./seg1", "w").write("a"*1024*1024)'
    python -c 'open("./seg2", "w").write("b"*1024*1024)'
    python -c 'open("./seg3", "w").write("c"*1024*1024)'

(2) create a container
    curl -i -X PUT -H "X-Auth-Token: ${AUTH_TOKEN}" ${ENDPOINT}/${CONTAINER}

(3) upload the segments
    curl -i -X PUT -H "X-Auth-Token: ${AUTH_TOKEN}" -T "./seg1" ${ENDPOINT}/${CONTAINER}/${SEGOBJECT1}
    curl -i -X PUT -H "X-Auth-Token: ${AUTH_TOKEN}" -T "./seg2" ${ENDPOINT}/${CONTAINER}/${SEGOBJECT2}
    curl -i -X PUT -H "X-Auth-Token: ${AUTH_TOKEN}" -T "./seg3" ${ENDPOINT}/${CONTAINER}/${SEGOBJECT3}

(4) upload the manifest object
    echo "[
        {
            \"path\": \"${CONTAINER}/${SEGOBJECT1}\",
            \"etag\": \"7202826a7791073fe2787f0c94603278\",
            \"size_bytes\": 1048576
        },
        {
            \"path\": \"${CONTAINER}/${SEGOBJECT2}\",
            \"etag\": \"96767d2b46489f3520698a6df536dc4c\",
            \"size_bytes\": 1048576
        },
        {
            \"path\": \"${CONTAINER}/${SEGOBJECT3}\",
            \"etag\": \"95d674ce4178cc3ef807606ecb8ec0f5\",
            \"size_bytes\": 1048576
        }
    ]" > "./manilistfile.json"
    curl -i -X PUT -H "X-Auth-Token: ${AUTH_TOKEN}" -T "./manilistfile.json" ${ENDPOINT}/${CONTAINER}/${MANIOBJECT}?multipart-manifest=put

test case1 (in case of deleting the first object):
(1) delete the first object
    curl -i -X DELETE -H "X-Auth-Token: ${AUTH_TOKEN}" ${ENDPOINT}/${CONTAINER}/${SEGOBJECT1}

(2) download the manifest object
    curl -v -X GET -H "X-Auth-Token: ${AUTH_TOKEN}" -o "./test02_1st_seg_lost" ${ENDPOINT}/${CONTAINER}/${MANIOBJECT}

=== output ===
* About to connect() to 10.124.121.74 port 80 (#0)
* Trying 10.124.121.74... connected
* Connected to 10.124.121.74 (10.124.121.74) port 80 (#0)
> GET /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/slotest-maniobj HTTP/1.1
> User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.14.0.0 zlib/1.2.3 libidn/1.18 libssh2/1.4.2
> Host: 10.124.121.74
> Accept: */*
> X-Auth-Token: snip
>
  % Total % Received % Xferd Average Speed Time Time Time Current
                                 Dload Upload Total Spent Left Speed
  0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0< HTTP/1.1 500 Internal Server Error <=== 500
< Server: GlassFish Server Open Source Edition 4.1
< X-Trans-Id: txa34efe453a504d6cbfa66-00544dc783
< Date: Mon, 27 Oct 2014 04:18:11 GMT
< Connection: close
< Content-Type: text/plain
< Content-Length: 17
<
{ [data not shown]
  0 17 0 17 0 0 145 0 --:--:-- --:--:-- --:--:-- 217* Closing connection #0

# ls -l
-rw-r--r-- 1 root root 9568 10月 27 13:10 2014 eplist.json
-rw-r--r-- 1 root root 14536 10月 27 13:10 2014 eplist_format.json
-rw-r--r-- 1 root root 423 10月 27 13:13 2014 manilistfile.json
-rw-r--r-- 1 root root 1048576 10月 27 13:11 2014 seg1
-rw-r--r-- 1 root root 1048576 10月 27 13:11 2014 seg2
-rw-r--r-- 1 root root 1048576 10月 27 13:11 2014 seg3
-rw-r--r-- 1 root root 3145728 10月 27 13:16 2014 test01_no_seg_lost
-rw-r--r-- 1 root root 17 10月 27 13:18 2014 test02_1st_seg_lost <=== failed to get the first object
===

test case2 (in case of deleting the first object):
(1) delete the first object
    curl -i -X DELETE -H "X-Auth-Token: ${AUTH_TOKEN}" ${ENDPOINT}/${CONTAINER}/${SEGOBJECT2}

(2) download the manifest object
    curl -v -X GET -H "X-Auth-Token: ${AUTH_TOKEN}" -o "./test03_2nd_seg_lost" ${ENDPOINT}/${CONTAINER}/${MANIOBJECT}

=== output ===
* About to connect() to 10.124.121.74 port 80 (#0)
* Trying 10.124.121.74... connected
* Connected to 10.124.121.74 (10.124.121.74) port 80 (#0)
> GET /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/slotest-maniobj HTTP/1.1
> User-Agent: curl/7.19.7 (x86_64-redhat-linux-gnu) libcurl/7.19.7 NSS/3.14.0.0 zlib/1.2.3 libidn/1.18 libssh2/1.4.2
> Host: 10.124.121.74
> Accept: */*
> X-Auth-Token: snip
>
  % Total % Received % Xferd Average Speed Time Time Time Current
                                 Dload Upload Total Spent Left Speed
  0 0 0 0 0 0 0 0 --:--:-- --:--:-- --:--:-- 0< HTTP/1.1 200 OK <=== 200
< Server: GlassFish Server Open Source Edition 4.1
< Accept-Ranges: bytes
< Last-Modified: Mon, 27 Oct 2014 04:13:24 GMT
< Etag: "9b2371314d9a718bbfeb6d116811c394"
< X-Timestamp: 1414383203.08729
< X-Static-Large-Object: True
< X-Trans-Id: tx03ceaa2d161c4471abb0e-00544dc901
< Date: Mon, 27 Oct 2014 04:24:33 GMT
< Connection: keep-alive
< Content-Type: application/octet-stream
< Content-Length: 3145728
<
{ [data not shown]
 33 3072k 33 1024k 0 0 35015 0 0:01:29 0:00:29 0:01:00 0* transfer closed with 2097152 bytes remaining to read
 33 3072k 33 1024k 0 0 34394 0 0:01:31 0:00:30 0:01:01 0* Closing connection #0

curl: (18) transfer closed with 2097152 bytes remaining to read

# ls -l
-rw-r--r-- 1 root root 9568 10月 27 13:10 2014 eplist.json
-rw-r--r-- 1 root root 14536 10月 27 13:10 2014 eplist_format.json
-rw-r--r-- 1 root root 423 10月 27 13:13 2014 manilistfile.json
-rw-r--r-- 1 root root 1048576 10月 27 13:11 2014 seg1
-rw-r--r-- 1 root root 1048576 10月 27 13:11 2014 seg2
-rw-r--r-- 1 root root 1048576 10月 27 13:11 2014 seg3
-rw-r--r-- 1 root root 3145728 10月 27 13:16 2014 test01_no_seg_lost
-rw-r--r-- 1 root root 3145728 10月 27 13:20 2014 test01_no_seg_lost_2
-rw-r--r-- 1 root root 17 10月 27 13:18 2014 test02_1st_seg_lost
-rw-r--r-- 1 root root 1048576 10月 27 13:25 2014 test03_2nd_seg_lost <=== got the first object
===

[Test environment details]
-

[Actual results]
-

[Expected results]
Both cases the response code is 200 (same as DLO)
with 0 byte object for a missing segment.

I would like to have this if possible.

[Samuel Merritt (torgomatic)]

The only way to achieve this is to HEAD each segment to ensure it is present* prior to serving the object. Otherwise, the knowledge that a segment is missing comes too late to do any good.

Remember that an HTTP response consists of a status line, then headers, then body. Thus, after the body has started going out to the client, there is no further possibility to change the status or headers.

Now, a SLO manifest can reference up to 1000** segments, so in the worst case, that's 1000 HEAD requests that have to complete prior to sending the status code. If that takes more than a few seconds, many clients will time out.

It's actually even worse than that: a "segment" can be another SLO manifest, in which case the sub-manifest's segments are included recursively. The only restriction here is a depth restriction on the tree formed by SLO manifests, and that depth limit is 10. The end result is that a SLO manifest may reference up to 10^30 segments; even if a particular cluster were able to perform one HEAD request per nanosecond, it would still take roughly 31 trillion years to validate all the segments.

Unfortunately, this is not possible to fix due to resource constraints.

However, notice that the Content-Length header was set to 3145728 but only 1048576 bytes were received. A client can use this to notice the truncation and handle the error appropriately.

* Yes, there's a race condition here. I am deliberately ignoring it.

** Configurable, 1000 is the default.

[clayg (clay-gerrard)]

Should test case2 (the one that returns the 200 then blows up) says "in case of deleting an object other than the first object" instead of "in case of deleting the first object" - because seems to be what the curl commands describe and matches up more intuitively with how Sam described the limitation.

I'm sort of surprised we managed to get a 500 out the door when the first object 404's - go us! On the other hand, if consistency is more important to the client we could return the 200 in either case as soon as we retrieve the manifest, leaving the client to only have to deal with the mismatched etag or incomplete read error cases (even though you sorta always have to deal with 500 on the client, i'm a little worried that the request would just get retried to no avail?)

Can you check the response codes that get logged in this case? I actually think it should be closer to a 4xx response than a 5xx - but maybe either is reasonable.

[Hisashi Osanai (osanai-hisashi)]

@Samuel, Thanks for the detailed explanation.
@clayg, Thanks for the clarification.

I think I have same understanding with Samuel but my bug report was not enough explanation.
Let me explain again with clayg's advice.

First, I summarized the result of each test.
+-----------------------+------------------------------+--------------------------+------------------------+
| Test Cases | Response code *** | Received bytes |Expected result |
+-----------------------+------------------------------+--------------------------+------------------------+
| Test Case 1 * | 500 | 17 | (1) |
+-----------------------+------------------------------+--------------------------+------------------------+
| Test Case 2 ** | 200 | 1048576 | (2) |
+-----------------------+------------------------------+--------------------------+------------------------+

* in case of deleting the first object
** in case of deleting an object other than the first object (thanks clayg!)
*** Please search the original bug report with "<==="

Then, I would like to explain my expectation for these behaviors.
(2) looks good. (Samuel's comment is perfect explanation for this)
(1) The response code should be changed from 500 to other.
       My idea for this case is a response code is 200 like Test Case 2 and
       send 0 byte object for missing segment. (but not necessary to send
       3rd segment)
       Then, client checks the object with etag or content-lengh.

[Hisashi Osanai (osanai-hisashi)]

The above table was corrupted for viewing so I put same table on paste.openstack.org
http://paste.openstack.org/show/126246/

[clayg (clay-gerrard)]

Awesome! I'm honestly not sure what causes the 500 - are we explicitly waiting to call start response until we GET the first segment and then returning a HTTPServerError on purpose, or is there just some traceback blowing up?

We need logs...

[Hisashi Osanai (osanai-hisashi)]

Thanks for the comment.

In swift/common/request_helpers.py (L339-), SLO raises SegmentError then
it's cathed at the catch_errors middleware and mapped to 500.

                if not is_success(seg_resp.status_int): <===point 1
                    close_if_possible(seg_resp.app_iter)
                    raise SegmentError( <===point 2
                        'ERROR: While processing manifest %s, '
                        'got %d while retrieving %s' %
                        (self.name, seg_resp.status_int, seg_path))

I think that it is better to check raising SegmentError cases in the code.
If this is recognized a bug, I will check them.

I put the log but the swift version is 1.13.1 instead of 2.1.0 (same logic).

# grep "txa34efe453a504d6cbfa66-00544dc783" /var/log/swift/swift.log
Oct 27 13:18:11 localhost proxy-server: - - 27/Oct/2014/04/18/11 GET /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/segobj1%3Fmultipart-manifest%3Dget HTTP/1.0 499 - curl/7.19.7%20%28x86_64-redhat-linux-gnu%29%20libcurl/7.19.7%20NSS/3.14.0.0%20zlib/1.2.3%20libidn/1.18%20libssh2/1.4.2%20%20SLO%20MultipartGET MIInHAYJKoZIhvcN... - 70 - txa34efe453a504d6cbfa66-00544dc783 - 0.0147 SLO - 1414383491.511203051 1414383491.525928020
Oct 27 13:18:11 localhost proxy-server: ERROR: While processing manifest /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/slotest-maniobj, got 404 while retrieving /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/segobj1: #012Traceback (most recent call last):#012 File "/usr/lib/python2.6/site-packages/swift/common/request_helpers.py", line 307, in __iter__#012 (self.name, seg_resp.status_int, seg_path))#012SegmentError: ERROR: While processing manifest /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/slotest-maniobj, got 404 while retrieving /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/segobj1 (txn: txa34efe453a504d6cbfa66-00544dc783)
Oct 27 13:18:11 localhost catch_errors: Error: An error occurred: #012Traceback (most recent call last):#012 File "/usr/lib/python2.6/site-packages/swift/common/middleware/catch_errors.py", line 36, in handle_request#012 resp = self._app_call(env)#012 File "/usr/lib/python2.6/site-packages/swift/common/wsgi.py", line 528, in _app_call#012 first_chunk = resp.next()#012 File "/usr/lib/python2.6/site-packages/swift/common/middleware/proxy_logging.py", line 247, in iter_response#012 chunk = iterator.next()#012 File "/usr/lib/python2.6/site-packages/swift/common/request_helpers.py", line 307, in __iter__#012 (self.name, seg_resp.status_int, seg_path))#012SegmentError: ERROR: While processing manifest /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/slotest-maniobj, got 404 while retrieving /v1/AUTH_683ca2b5c4de4ce4824c5939df04b44a/slotest-container/segobj1 (txn: txa34efe453a504d6cbfa66-00544dc783)

[clayg (clay-gerrard)]

well I think I'd be fine with seeing missing segment always return 200, I think letting the segment error bubble all the way out to catch errors is not optimal, and I would argue that regardless of client adoption returning a 500 on the first segment can't be clasified as pre-existing well defined behavior and reasonable to change. As you've accurately described any client that was handling the 500 case should also be handling the 200 incomplete read/etag error so I think we can fix this without worrying about a well behaved client getting broke any more than it already was.

[Hisashi Osanai (osanai-hisashi)]

Thanks for the comment.
I try to make a patch so I would like to have this bug. Is it OK?

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/136258

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/136258
Committed: https://git.openstack.org/cgit/openstack/swift/commit/?id=5ca49ca92485b6ba868544f12fa524d9d7b666c6
Submitter: Jenkins
Branch: master

commit 5ca49ca92485b6ba868544f12fa524d9d7b666c6
Author: Hisashi Osanai <email address hidden>
Date: Wed Nov 26 05:25:01 2014 +0900

    Fix the GET's response code when there is a missing segment in LO

    This patch changes the response code from Internal Server Error to
    Conflict when there is a missing segment and the position is first.

    Co-Authored-By: Samuel Merritt <email address hidden>
    Closes-Bug: #1386568
    Change-Id: Iac175b4dc6ac9081436738697a27fe669acce0eb

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: feature/ec
Review: https://review.openstack.org/148983

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/148983
Committed: https://git.openstack.org/cgit/openstack/swift/commit/?id=ef59cde83f176df9e36064f70142c9d8e81318fe
Submitter: Jenkins
Branch: feature/ec

commit 6f21504ccc9046e3f0b4db88f78297a00030dd3d
Author: Kota Tsuyuzaki <email address hidden>
Date: Tue Jan 13 05:34:37 2015 -0800

    Fix missing content length of Response

    This patch fixes swob.Response to set missing content
    length correctly.

    When a child class of swob.Response is initialized with
    both "body" and "headers" arguments which includes content
    length, swob.Response might loose the acutual content length
    generated from the body because "headers" will overwrite the
    content length property after the body assignment.

    It'll cause the difference between headers's content length
    and acutual body length. This would affect mainly 3rd party
    middleware(s) to make an original response as follows:

    req = swob.Request.blank('/')
    req.method = 'HEAD'
    resp = req.get_response(app)
    return HTTPOk(body='Ok', headers=resp.headers)

    This patch changes the order of headers updating and then
    fixes init() to set correct content length.

    Change-Id: Icd8b7cbfe6bbe2c7965175969af299a5eb7a74ef

commit b434be452ead0625728afedfe01bac1c30629d30
Author: Donagh McCabe <email address hidden>
Date: Thu Jan 8 14:52:32 2015 +0000

    Use TCP_NODELAY on outgoing connections

    On a loopback device (e.g., when proxy-server and object-server are on
    same node), PUTs in the range 64-200K may experience a delay due to the
    effect of Nagel interacting with the loopback MTU of 64K.

    This effect has been directly seen by Mark Seger and Rick Jones on a
    proxy-server to object-server PUT. However, you could expect to see a
    similar effect on replication via ssync if the object being replicated
    is on a different drive on the same node.

    A prior change [1] related to Nagel set TCP_NODELAY on responses. This change
    sets it on all outgoing connections.

    [1] I11f86df1f56fba1c6ab6084dc1f580c395f072dc

    Change-Id: Ife8885a42b289a5eb4ac7e4698f8889858bc8b7e
    Closes-bug: 1408622

commit b5586427e503ee22c0b20b109cad83e166ed3fd8
Author: Pete Zaitcev <email address hidden>
Date: Sat Jan 10 17:14:46 2015 -0700

    Drop redundant index output

    The output of format_device() now includes index as the first "dX"
    element, for example d1r1z2-127.0.0.1:6200R127.0.0.1:6200/db_"".

    Change-Id: Ib5f8e3a692fddbe8b1f4994787b2883130e9536f

commit c65bc49e099928801b80dce399d6098f7e10e137
Author: Pete Zaitcev <email address hidden>
Date: Sat Jan 10 08:20:25 2015 -0700

    Mark the --region as mandatory

    We used to permit to omit region in the old parameter syntax, although
    we now throw a warning if it's missing. In the new parameter syntax,
    --region is mandatory. It's enforced by build_dev_from_opts in
    swift/common/ring/utils.py.

    On the other hand, --replication-ip, --replication-port, and --meta
    are not obligatory.

    Change-Id: Ia70228f2c99595501271765286431f68e82e800b
...