)]}'
{"/COMMIT_MSG":[{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"82f36d40c48162c0bca335f67cf534612f28a8d7","unresolved":true,"context_lines":[{"line_number":23,"context_line":"This change in the GetOrHeadHandler mimics a similar change in the"},{"line_number":24,"context_line":"ECFragGetter [1]."},{"line_number":25,"context_line":""},{"line_number":26,"context_line":"[1] Related-Chage: I0654815543be3df059eb2875d9b3669dbd97f5b4"},{"line_number":27,"context_line":"Change-Id: I6dd53e239f5e7eefcf1c74229a19b1df1c989b4a"}],"source_content_type":"text/x-gerrit-commit-message","patch_set":9,"id":"9912fe1c_c7e79491","line":26,"updated":"2023-12-06 05:32:19.000000000","message":"hrmm... those tests seem to assert on ChunkReadTimeout in the *log lines* - not that the timeout was actually *raised*","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"607cd26954435f92e94cde5ea50e6ae071d08ee1","unresolved":true,"context_lines":[{"line_number":23,"context_line":"This change in the GetOrHeadHandler mimics a similar change in the"},{"line_number":24,"context_line":"ECFragGetter [1]."},{"line_number":25,"context_line":""},{"line_number":26,"context_line":"[1] Related-Chage: I0654815543be3df059eb2875d9b3669dbd97f5b4"},{"line_number":27,"context_line":"Change-Id: I6dd53e239f5e7eefcf1c74229a19b1df1c989b4a"}],"source_content_type":"text/x-gerrit-commit-message","patch_set":9,"id":"49b0dc85_8dd015ce","line":26,"in_reply_to":"9912fe1c_c7e79491","updated":"2023-12-06 15:26:28.000000000","message":"yes, but I\u0027ll add an EC test that does raise the timeout. It only leaks out once the resp body is being iterated, which takes a bit more in the EC case (presumably because the proxy isn\u0027t calling start response until it\u0027s got some frag getters??)","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"}],"/PATCHSET_LEVEL":[{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"82f36d40c48162c0bca335f67cf534612f28a8d7","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"6ca198c0_927a0c88","updated":"2023-12-06 05:32:19.000000000","message":"I wanted to understand what happens in a functional test when this ChunkReadTimeout gets hit for real in the proxy:\n\nhttps://review.opendev.org/c/openstack/swift/+/902742\n\nI was thinking we can\u0027t raise the Timeout to eventlet/WSGI, right?  It has to get caught somewhere and translated into a regular Exception?  But so far I don\u0027t think I\u0027ve found found the place for the sleep in my object server to trigger ChunkReadTimeout like I\u0027m seeing in the log messages of this unittest.","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"607cd26954435f92e94cde5ea50e6ae071d08ee1","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":10,"id":"919f36cb_5dea7923","updated":"2023-12-06 15:26:28.000000000","message":"@Clay your func test experiment *is* very interesting. At first I thought that proxy_logging was gobbling up the ChunkReadTimeout (it reiterates the resp_iter so any timeout early in the resp_iter will morph to a 500 there I think). But even dropping that didn\u0027t make the test break in the way expected.\n\nThen I noticed that the error logs do NOT have \"(retrying)\" so it seems that the proxy is timing out in conn.getresponse() in _make_node_request(), which is curious - obviously the unit test stub *is* looking like it has begun but IRL the object server connection it timing out in begin() (or somewhere in getresponse).\n\nIt *would* be good to get to the bottom of that!","commit_id":"f1c935710deb12725a0cc3eed4555a2c4f22446c"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"a91267e1353acce355e29c7f54e671cbb5c648fc","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":11,"id":"60c42395_4047f917","updated":"2023-12-07 05:47:41.000000000","message":"made a bit more progress on the functional repro:\n\nhttps://review.opendev.org/c/openstack/swift/+/902742\n\nI don\u0027t think eventlet *likes* the ChunkReadTimeout:\n\n```\nDec  7 05:35:37 saio proxy-server: STDERR: 127.0.0.1 - - [07/Dec/2023 05:35:37] \"GET /v1/AUTH_test/871a85876676400eafee5c031a51c9d1/9e09a6c1212f4c1d8788f5c05a6192b7 HTTP/1.1\" 206 2565\n45 1.575537 (txn: tx06d9812c4dd34829b052e-00657159a8)\nDec  7 05:35:37 saio proxy-server: STDERR: Traceback (most recent call last):\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/hubs/hub.py\", line 476, in fire_timers#012    timer()\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/hubs/timer.py\", line 59, in __call__#012    cb(*args, **kw)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/queue.py\", line 351, in _unlock#012    getter.switch(item)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/queue.py\", line 118, in switch#012    self.greenlet.switch(value)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/greenthread.py\", line 221, in main#012    result \u003d function(*args, **kwargs)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/wsgi.py\", line 837, in process_request#012    proto.__init__(conn_state, self)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/http_protocol.py\", line 39, in __init__#012    wsgi.HttpProtocol.__init__(self, *args, **kwargs)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/wsgi.py\", line 350, in __init__#012    self.handle()\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/wsgi.py\", line 383, in handle#012    self.handle_one_request()\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/http_protocol.py\", line 242, in handle_one_request#012    got \u003d wsgi.HttpProtocol.handle_one_request(self)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/wsgi.py\", line 459, in handle_one_request#012    self.handle_one_response()\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/wsgi.py\", line 587, in handle_one_response#012    for data in result:\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/middleware/catch_errors.py\", line 39, in enforce_byte_count#012    for chunk in inner_iter:\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/utils/__init__.py\", line 3704, in __next__#012    return next(self.chained_iter)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/middleware/proxy_logging.py\", line 444, in iter_response#012    for chunk in iterator:\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/middleware/catch_errors.py\", line 39, in enforce_byte_count#012    for chunk in inner_iter:\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/utils/__init__.py\", line 3704, in __next__#012    return next(self.chained_iter)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4373, in document_iters_to_multipart_byteranges#012    for range_spec in ranges_i\nter:\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/proxy/controllers/base.py\", line 1673, in \u003cgenexpr\u003e#012    (add_content_type(pi) for pi in parts_iter),\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/proxy/controllers/base.py\", line 1425, in _iter_parts_from_response#012    self._get_next_response_part()\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/proxy/controllers/base.py\", line 1365, in _get_next_response_part#012    start_byte, end_byte, length, headers, p\nart \u003d next(\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4476, in multipart_byteranges_to_document_iters#012    for headers, body in mime_\nto_document_iters(input_file, boundary,\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4335, in mime_to_document_iters#012    headers \u003d parse_mime_headers(doc_file)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4299, in parse_mime_headers#012    line \u003d doc_file.readline()\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4222, in readline#012    chunk \u003d self.wsgi_input.read(self.read_chunk_size)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/vagrant/swift/swift/common/bufferedhttp.py\", line 140, in read#012    return HTTPResponse.read(self, amt)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/green/http/client.py\", line 503, in read#012    n \u003d self.readinto(b)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/green/http/client.py\", line 547, in readinto#012    n \u003d self.fp.readinto(b)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/lib/python3.10/socket.py\", line 705, in readinto#012    return self._sock.recv_into(b)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/greenio/base.py\", line 376, in recv_into#012    return self._recv_loop(self.fd.recv_i\nnto, 0, buffer, nbytes, flags)\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/greenio/base.py\", line 364, in _recv_loop#012    self._read_trampoline()\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/greenio/base.py\", line 332, in _read_trampoline#012    self._trampoline(\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/greenio/base.py\", line 211, in _trampoline#012    return trampoline(fd, read\u003dread, write\u003dwrite, timeout\u003dtimeout,\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/hubs/__init__.py\", line 159, in trampoline#012    return hub.switch()\nDec  7 05:35:37 saio proxy-server: STDERR: File \"/usr/local/lib/python3.10/dist-packages/eventlet/hubs/hub.py\", line 313, in switch#012    return self.greenlet.switch()\nDec  7 05:35:38 saio proxy-server: STDERR: swift.common.exceptions.ChunkReadTimeout: 0.5 seconds\n```\n\n... but it\u0027s just a squelched hub traceback.  The client gets a truncated read, the proxy process doesn\u0027t *die* or anything\n\n\nFWIW changing the bare re-raise to raise ValueError(\u0027short read\u0027) \"fixes\" the status code in proxy logging:\n\n```\nDec  7 05:44:58 saio proxy-server: 127.0.0.1 127.0.0.1 07/Dec/2023/05/44/58 GET /v1/AUTH_test/1a57bf31ed77486dbcba05c0876bf494/aa0dae69ca64437e9d446a9bc06671f5 HTTP/1.0 500 - - AUTH_t\nk2291d380d... - 256127 - tx1bcd2b226f16441fa5fe2-0065715bd9 - 1.5767 - - 1701927897.254181862 1701927898.830878735 0\nDec  7 05:44:58 saio proxy-server: STDERR: Traceback (most recent call last):#012  File \"/vagrant/swift/swift/proxy/controllers/base.py\", line 1365, in _get_next_response_part#012    \nstart_byte, end_byte, length, headers, part \u003d next(#012  File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4476, in multipart_byteranges_to_document_iters#012    for headers,\n body in mime_to_document_iters(input_file, boundary,#012  File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4335, in mime_to_document_iters#012    headers \u003d parse_mime_heade\nrs(doc_file)#012  File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4299, in parse_mime_headers#012    line \u003d doc_file.readline()#012  File \"/vagrant/swift/swift/common/utils\n/__init__.py\", line 4222, in readline#012    chunk \u003d self.wsgi_input.read(self.read_chunk_size)#012  File \"/vagrant/swift/swift/common/bufferedhttp.py\", line 140, in read#012    retur\nn HTTPResponse.read(self, amt)#012  File \"/usr/local/lib/python3.10/dist-packages/eventlet/green/http/client.py\", line 503, in read#012    n \u003d self.readinto(b)#012  File \"/usr/local/l\nib/python3.10/dist-packages/eventlet/green/http/client.py\", line 547, in readinto#012    n \u003d self.fp.readinto(b)#012  File \"/usr/lib/python3.10/socket.py\", line 705, in readinto#012  \n  return self._sock.recv_into(b)#012  File \"/usr/local/lib/python3.10/dist-packages/eventlet/greenio/base.py\", line 376, in recv_into#012    return self._recv_loop(self.fd.recv_into, \n0, buffer, nbytes, flags)#012  File \"/usr/local/lib/python3.10/dist-packages/eventlet/greenio/base.py\", line 364, in _recv_loop#012    self._read_trampoline()#012  File \"/usr/local/li\nb/python3.10/dist-packages/eventlet/greenio/base.py\", line 332, in _read_trampoline#012    self._trampoline(#012  File \"/usr/local/lib/python3.10/dist-packages/eventlet/greenio/base.p\ny\", line 211, in _trampoline#012    return trampoline(fd, read\u003dread, write\u003dwrite, timeout\u003dtimeout,#012  File \"/usr/local/lib/python3.10/dist-packages/eventlet/hubs/__init__.py\", line \n159, in trampoline#012    return hub.switch()#012  File \"/usr/local/lib/python3.10/dist-packages/eventlet/hubs/hub.py\", line 313, in switch#012    return self.greenlet.switch()#012swi\nft.common.exceptions.ChunkReadTimeout: 0.5 seconds#012#012During handling of the above exception, another exception occurred:#012#012Traceback (most recent call last):#012  File \"/usr\n/local/lib/python3.10/dist-packages/eventlet/wsgi.py\", line 587, in handle_one_response#012    for data in result:#012  File \"/vagrant/swift/swift/common/middleware/catch_errors.py\", \nline 39, in enforce_byte_count#012    for chunk in inner_iter:#012  File \"/vagrant/swift/swift/common/utils/__init__.py\", line 3704, in __next__#012    return next(self.chained_iter)#\n012  File \"/vagrant/swift/swift/common/middleware/proxy_logging.py\", line 444, in iter_response#012    for chunk in iterator:#012  File \"/vagrant/swift/swift/common/middleware/catch_e\nrrors.py\", line 39, in enforce_byte_count#012    for chunk in inner_iter:#012  File \"/vagrant/swift/swift/common/utils/__init__.py\", line 3704, in __next__#012    return next(self.cha\nined_iter)#012  File \"/vagrant/swift/swift/common/utils/__init__.py\", line 4373, in document_iters_to_multipart_byteranges#012    for range_spec in ranges_iter:#012  File \"/vagrant/swift/swift/proxy/controllers/base.py\", line 1673, in \u003cgenexpr\u003e#012    (add_content_type(pi) for pi in parts_iter),#012  File \"/vagrant/swift/swift/proxy/controllers/base.py\", line 1425, in _iter_parts_from_response#012    self._get_next_response_part()#012  File \"/vagrant/swift/swift/proxy/controllers/base.py\", line 1371, in _get_next_response_part#012    raise ValueError(\u0027short read\u0027)#012ValueError: short read (txn: tx1bcd2b226f16441fa5fe2-0065715bd9) (client_ip: 127.0.0.1)\n```\n\nand the traceback is a little cleaner.","commit_id":"75dc134f9c986c5b9bec83d33a582b66f603bf85"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"8ecd13701c0a35403ef3dfc2cfef70e520023249","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":13,"id":"b705f42e_56ea8183","updated":"2024-02-03 00:24:07.000000000","message":"I\u0027ll see about an eventlet patch to handle `Timeout`-in-app-iter a little more gracefully.","commit_id":"cc01563c3873e4ef53d7d6e1d1ca02fa0cdf8f66"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"90f20777a22ceea0e2a50b37c4bbb6c409046634","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":13,"id":"d4956971_009da3a5","in_reply_to":"b705f42e_56ea8183","updated":"2024-02-03 01:11:45.000000000","message":"https://github.com/eventlet/eventlet/pull/911","commit_id":"cc01563c3873e4ef53d7d6e1d1ca02fa0cdf8f66"}],"swift/proxy/controllers/base.py":[{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"82f36d40c48162c0bca335f67cf534612f28a8d7","unresolved":true,"context_lines":[{"line_number":1447,"context_line":"        except ChunkReadTimeout:"},{"line_number":1448,"context_line":"            self.app.exception_occurred(self.source.node, \u0027Object\u0027,"},{"line_number":1449,"context_line":"                                        \u0027Trying to read during GET\u0027)"},{"line_number":1450,"context_line":"            raise"},{"line_number":1451,"context_line":"        except ChunkWriteTimeout:"},{"line_number":1452,"context_line":"            self.logger.info("},{"line_number":1453,"context_line":"                \u0027Client did not read from proxy within %ss\u0027,"}],"source_content_type":"text/x-python","patch_set":9,"id":"ada5dfa1_375206f9","side":"PARENT","line":1450,"updated":"2023-12-06 05:32:19.000000000","message":"less obvious to me that this log line should go, I didn\u0027t see any assertions change WRT \"one less useless/duplicated log line\"\n\nI guess the point was trying to avoid adding *another* log line:\n\n```\nproxy-server ERROR: Trying to read object during GET (retrying) 10.0.0.0:1000/sda (txn: txe9d0794bc6d444f5acbcc-00656f93b3)\nproxy-server ERROR: Trying to read object during GET (retrying) 10.0.0.2:1002/sdc (txn: txe9d0794bc6d444f5acbcc-00656f93b3)\nproxy-server ERROR: Trying to read object during GET (retrying) 10.0.0.1:1001/sdb (txn: txe9d0794bc6d444f5acbcc-00656f93b3)\nproxy-server ERROR: ERROR with Object server 10.0.0.1:1001/sdb re: Trying to read during GET: ChunkReadTimeout (0.01s after 0.01s) (txn: txe9d0794bc6d444f5acbcc-00656f93b3)\n```","commit_id":"36ce42f54e48cdbf6edfc63dcb7a20a08b4e89a4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"607cd26954435f92e94cde5ea50e6ae071d08ee1","unresolved":true,"context_lines":[{"line_number":1447,"context_line":"        except ChunkReadTimeout:"},{"line_number":1448,"context_line":"            self.app.exception_occurred(self.source.node, \u0027Object\u0027,"},{"line_number":1449,"context_line":"                                        \u0027Trying to read during GET\u0027)"},{"line_number":1450,"context_line":"            raise"},{"line_number":1451,"context_line":"        except ChunkWriteTimeout:"},{"line_number":1452,"context_line":"            self.logger.info("},{"line_number":1453,"context_line":"                \u0027Client did not read from proxy within %ss\u0027,"}],"source_content_type":"text/x-python","patch_set":9,"id":"a418a3bc_277eeef1","side":"PARENT","line":1450,"in_reply_to":"ada5dfa1_375206f9","updated":"2023-12-06 15:26:28.000000000","message":"yes, if you put this back you\u0027ll see test fail because the final ChunkReadTimeout is logged twice but also the final node\u0027s error counter is incremented twice - once in _replaces_source_node and once here.\n\nAFAICT, on master this except clause was never reached.\n\nIt *is* weird to not be able to make an assertion about a change other than the assertions that are already in the tests 😞 I have some node error count assertions that I can pull forwards from later in the patch chain, but they also will only fail if this clause is added back.","commit_id":"36ce42f54e48cdbf6edfc63dcb7a20a08b4e89a4"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"82f36d40c48162c0bca335f67cf534612f28a8d7","unresolved":true,"context_lines":[{"line_number":1368,"context_line":"            except ChunkReadTimeout:"},{"line_number":1369,"context_line":"                if not self._replace_source("},{"line_number":1370,"context_line":"                        \u0027Trying to read object during GET (retrying)\u0027):"},{"line_number":1371,"context_line":"                    raise"},{"line_number":1372,"context_line":""},{"line_number":1373,"context_line":"    def _iter_bytes_from_response_part(self, part_file, nbytes):"},{"line_number":1374,"context_line":"        # yield chunks of bytes from a single response part; if an error"}],"source_content_type":"text/x-python","patch_set":9,"id":"fd3707d0_85e1c4a8","line":1371,"updated":"2023-12-06 05:32:19.000000000","message":"this just looks obvious - the ChunkReadTimeout \u003d\u003e StopIteration was always a smell","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"607cd26954435f92e94cde5ea50e6ae071d08ee1","unresolved":false,"context_lines":[{"line_number":1368,"context_line":"            except ChunkReadTimeout:"},{"line_number":1369,"context_line":"                if not self._replace_source("},{"line_number":1370,"context_line":"                        \u0027Trying to read object during GET (retrying)\u0027):"},{"line_number":1371,"context_line":"                    raise"},{"line_number":1372,"context_line":""},{"line_number":1373,"context_line":"    def _iter_bytes_from_response_part(self, part_file, nbytes):"},{"line_number":1374,"context_line":"        # yield chunks of bytes from a single response part; if an error"}],"source_content_type":"text/x-python","patch_set":9,"id":"c7ad1e9c_cf8bc530","line":1371,"in_reply_to":"fd3707d0_85e1c4a8","updated":"2023-12-06 15:26:28.000000000","message":"Acknowledged","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"}],"test/unit/proxy/controllers/test_obj.py":[{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"82f36d40c48162c0bca335f67cf534612f28a8d7","unresolved":true,"context_lines":[{"line_number":1779,"context_line":"            actual_body \u003d resp.body"},{"line_number":1780,"context_line":""},{"line_number":1781,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":1782,"context_line":"        self.assertEqual(2, len(log))"},{"line_number":1783,"context_line":"        # note: client response uses boundary from first backend response"},{"line_number":1784,"context_line":"        self.assertEqual(resp_body1, actual_body)"},{"line_number":1785,"context_line":"        error_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)"}],"source_content_type":"text/x-python","patch_set":9,"id":"0a30063a_24a4126c","side":"PARENT","line":1782,"updated":"2023-12-06 05:32:19.000000000","message":"hrm.. yeah log is kind of ambiguous\n\nreq_log might have been ok, captured_requests is definately better","commit_id":"36ce42f54e48cdbf6edfc63dcb7a20a08b4e89a4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"607cd26954435f92e94cde5ea50e6ae071d08ee1","unresolved":false,"context_lines":[{"line_number":1779,"context_line":"            actual_body \u003d resp.body"},{"line_number":1780,"context_line":""},{"line_number":1781,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":1782,"context_line":"        self.assertEqual(2, len(log))"},{"line_number":1783,"context_line":"        # note: client response uses boundary from first backend response"},{"line_number":1784,"context_line":"        self.assertEqual(resp_body1, actual_body)"},{"line_number":1785,"context_line":"        error_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)"}],"source_content_type":"text/x-python","patch_set":9,"id":"bf94c6b4_f2a962ef","side":"PARENT","line":1782,"in_reply_to":"0a30063a_24a4126c","updated":"2023-12-06 15:26:28.000000000","message":"Acknowledged","commit_id":"36ce42f54e48cdbf6edfc63dcb7a20a08b4e89a4"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"82f36d40c48162c0bca335f67cf534612f28a8d7","unresolved":true,"context_lines":[{"line_number":1859,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":1860,"context_line":"        self.assertEqual(6, len(log))"},{"line_number":1861,"context_line":"        resp_boundary \u003d resp.headers[\u0027content-type\u0027].rsplit(\u0027\u003d\u0027, 1)[1].encode()"},{"line_number":1862,"context_line":"        self.assertEqual(b\u0027--%s--\u0027 % resp_boundary, actual_body)"},{"line_number":1863,"context_line":"        error_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)"},{"line_number":1864,"context_line":"        self.assertEqual(3, len(error_lines))"},{"line_number":1865,"context_line":"        for line in error_lines:"}],"source_content_type":"text/x-python","patch_set":9,"id":"e5ca6692_6155bcec","side":"PARENT","line":1862,"updated":"2023-12-06 05:32:19.000000000","message":"and this is why i\u0027m generally pretty positive on adding a unittest for existing code even if it demonstrates a questionable behavior:\n\nhttps://review.opendev.org/c/openstack/swift/+/895802\n\nit makes the fix that much more trivial to already have pre-existing crank turn that covers the behavior we want to change!","commit_id":"36ce42f54e48cdbf6edfc63dcb7a20a08b4e89a4"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"607cd26954435f92e94cde5ea50e6ae071d08ee1","unresolved":false,"context_lines":[{"line_number":1859,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":1860,"context_line":"        self.assertEqual(6, len(log))"},{"line_number":1861,"context_line":"        resp_boundary \u003d resp.headers[\u0027content-type\u0027].rsplit(\u0027\u003d\u0027, 1)[1].encode()"},{"line_number":1862,"context_line":"        self.assertEqual(b\u0027--%s--\u0027 % resp_boundary, actual_body)"},{"line_number":1863,"context_line":"        error_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)"},{"line_number":1864,"context_line":"        self.assertEqual(3, len(error_lines))"},{"line_number":1865,"context_line":"        for line in error_lines:"}],"source_content_type":"text/x-python","patch_set":9,"id":"0373c29d_a7874cd9","side":"PARENT","line":1862,"in_reply_to":"e5ca6692_6155bcec","updated":"2023-12-06 15:26:28.000000000","message":"Acknowledged\n\nI always feel like I\u0027m walking a thin line between adding an assertion so that it clearly gets fixed by the next patch, vs adding an assertion that by it very existence suggests correct behavior.","commit_id":"36ce42f54e48cdbf6edfc63dcb7a20a08b4e89a4"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"82f36d40c48162c0bca335f67cf534612f28a8d7","unresolved":true,"context_lines":[{"line_number":1854,"context_line":"        with capture_http_requests(get_response) as log:"},{"line_number":1855,"context_line":"            resp \u003d req.get_response(self.app)"},{"line_number":1856,"context_line":"            with self.assertRaises(ChunkReadTimeout):"},{"line_number":1857,"context_line":"                _ \u003d resp.body"},{"line_number":1858,"context_line":""},{"line_number":1859,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":1860,"context_line":"        self.assertEqual(6, len(log))"}],"source_content_type":"text/x-python","patch_set":9,"id":"c2b18aac_185d8db3","line":1857,"updated":"2023-12-06 05:32:19.000000000","message":"I think I need to refresh my understanding of why *this* is the reasonable behavior change.\n\nI do vaugley remember thinking some where that an exception (but not a timeout?) was a reasonable way to communicate to eventlet/WSGI that the connection should be aborted.\n\nBut ... here we\u0027re raising a Timeout?  Is something else wrapping this?","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"54812ad38e8ce4711893dc7720f6bcd080af0d07","unresolved":false,"context_lines":[{"line_number":1854,"context_line":"        with capture_http_requests(get_response) as log:"},{"line_number":1855,"context_line":"            resp \u003d req.get_response(self.app)"},{"line_number":1856,"context_line":"            with self.assertRaises(ChunkReadTimeout):"},{"line_number":1857,"context_line":"                _ \u003d resp.body"},{"line_number":1858,"context_line":""},{"line_number":1859,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":1860,"context_line":"        self.assertEqual(6, len(log))"}],"source_content_type":"text/x-python","patch_set":9,"id":"3ae57382_9bc3d920","line":1857,"in_reply_to":"25306676_4aa16b5b","updated":"2024-02-05 18:10:40.000000000","message":"Done","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"8ecd13701c0a35403ef3dfc2cfef70e520023249","unresolved":true,"context_lines":[{"line_number":1854,"context_line":"        with capture_http_requests(get_response) as log:"},{"line_number":1855,"context_line":"            resp \u003d req.get_response(self.app)"},{"line_number":1856,"context_line":"            with self.assertRaises(ChunkReadTimeout):"},{"line_number":1857,"context_line":"                _ \u003d resp.body"},{"line_number":1858,"context_line":""},{"line_number":1859,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":1860,"context_line":"        self.assertEqual(6, len(log))"}],"source_content_type":"text/x-python","patch_set":9,"id":"25306676_4aa16b5b","line":1857,"in_reply_to":"2f09a3eb_64b6f77b","updated":"2024-02-03 00:24:07.000000000","message":"\u003e I do vaugley remember thinking some where that an exception (but not a timeout?) was a reasonable way to communicate to eventlet/WSGI that the connection should be aborted.\n\nAlright, so [the PEP](https://peps.python.org/pep-3333/#error-handling) isn\u0027t really helpful -- only guidance I see there is\n\n\u003e Servers **should** trap and log any exception that aborts an application or the iteration of its return value. If a partial response has already been written to the browser when an application error occurs, the server or gateway **may** attempt to add an error message to the output, if the already-sent headers indicate a `text/*` content type that the server knows how to modify cleanly.\n\nwhich frankly seems like an insane position, all but certain to cause HTTP framing issues. Elsewhere it also says\n\n\u003e Applications and middleware are forbidden from using HTTP/1.1 “hop-by-hop” features or headers, any equivalent features in HTTP/1.0, or any headers that would affect the persistence of the client’s connection to the web server. These features are the exclusive province of the actual web server, and a server or gateway **should** consider it a fatal error for an application to attempt sending them, and raise an error if they are supplied to `start_response()`.\n\nso we have limited options when it comes to wanting to disrupt the connection, even when we know it\u0027s in a bad state.\n\n[Eventlet source](https://github.com/eventlet/eventlet/blob/v0.35.1/eventlet/wsgi.py#L634-L635) won\u0027t lie, though it also doesn\u0027t offer much explanation. They\u0027d probably accept a patch to catch `(Exception, Timeout)`, though.\n\n---\n\nI was kinda expecting to see something like\n```\nAssertionError: Lists differ: [b\u0027--81eb9c110b32ced5fe--\u0027] !\u003d []\n```\nsomewhere when I backed out the fix, though -- I don\u0027t really like masking what got yielded out with `.body`. Maybe something like\n```\ndiff --git a/test/unit/proxy/controllers/test_obj.py b/test/unit/proxy/controllers/test_obj.py\nindex 501407b84..56095a0be 100644\n--- a/test/unit/proxy/controllers/test_obj.py\n+++ b/test/unit/proxy/controllers/test_obj.py\n@@ -1854,9 +1854,11 @@ class TestReplicatedObjController(CommonObjectControllerMixin,\n             \u0027Range\u0027: \u0027bytes\u003d0-49,100-104\u0027})\n         with capture_http_requests(get_response) as log:\n             resp \u003d req.get_response(self.app)\n+            response_chunks \u003d []\n             with self.assertRaises(ChunkReadTimeout):\n-                # note: the error is raised while the resp_iter is read...\n-                _ \u003d resp.body\n+                for chunk in resp.app_iter:\n+                    response_chunks.append(chunk)\n+            self.assertEqual(response_chunks, [])\n \n         self.assertEqual(resp.status_int, 206)\n         self.assertEqual([1, 1, 1],\n```","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"607cd26954435f92e94cde5ea50e6ae071d08ee1","unresolved":true,"context_lines":[{"line_number":1854,"context_line":"        with capture_http_requests(get_response) as log:"},{"line_number":1855,"context_line":"            resp \u003d req.get_response(self.app)"},{"line_number":1856,"context_line":"            with self.assertRaises(ChunkReadTimeout):"},{"line_number":1857,"context_line":"                _ \u003d resp.body"},{"line_number":1858,"context_line":""},{"line_number":1859,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":1860,"context_line":"        self.assertEqual(6, len(log))"}],"source_content_type":"text/x-python","patch_set":9,"id":"2f09a3eb_64b6f77b","line":1857,"in_reply_to":"c2b18aac_185d8db3","updated":"2023-12-06 15:26:28.000000000","message":"It may not ultimately be reasonable for us to punt a Timeout to wsgi, but we do (eek). I\u0027ll add an EC path test that demonstrates current behavior on master.\n\nThe question is where do we convert the Timeout to something wsgi handles gracefully (ranging from right here, to in wsgi itself)? \n\nI tried to address this in catch_errors in https://review.opendev.org/c/openstack/swift/+/899197 . The thinking there was to have ONE place where we sanitise exceptions while iterating a response body.\n\nThat ONE place could alternatively be on the \"edge\" of the proxy app. But I think I prefer doing it in one obvious place rather than identifying those timeouts down in the guts of our nested iters that might leak out. Maybe I\u0027ll become confident enough that there is only ONE place down in the guts (but for now there\u0027s at least 2 - in EC and replicated paths).\n\nSo, do we need to do that *before* we fix this bug? originally I had https://review.opendev.org/c/openstack/swift/+/899197 at the start of the chain, but that seemed like it was another can of worms, so I pressed ahead with this patch to at least clean up the client-visible bug.","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"82f36d40c48162c0bca335f67cf534612f28a8d7","unresolved":true,"context_lines":[{"line_number":1861,"context_line":"        error_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)"},{"line_number":1862,"context_line":"        self.assertEqual(3, len(error_lines))"},{"line_number":1863,"context_line":"        for line in error_lines:"},{"line_number":1864,"context_line":"            self.assertIn(\u0027Trying to read object during GET \u0027, line)"},{"line_number":1865,"context_line":""},{"line_number":1866,"context_line":"    def test_GET_resuming_ignores_416(self):"},{"line_number":1867,"context_line":"        # verify that a resuming getter will not try to use the content of a"}],"source_content_type":"text/x-python","patch_set":9,"id":"a1c9c4a1_82a28751","line":1864,"updated":"2023-12-06 05:32:19.000000000","message":"so the log call you removed wasn\u0027t actually this one?","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":7847,"name":"Alistair Coles","email":"alistairncoles@gmail.com","username":"acoles"},"change_message_id":"607cd26954435f92e94cde5ea50e6ae071d08ee1","unresolved":true,"context_lines":[{"line_number":1861,"context_line":"        error_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)"},{"line_number":1862,"context_line":"        self.assertEqual(3, len(error_lines))"},{"line_number":1863,"context_line":"        for line in error_lines:"},{"line_number":1864,"context_line":"            self.assertIn(\u0027Trying to read object during GET \u0027, line)"},{"line_number":1865,"context_line":""},{"line_number":1866,"context_line":"    def test_GET_resuming_ignores_416(self):"},{"line_number":1867,"context_line":"        # verify that a resuming getter will not try to use the content of a"}],"source_content_type":"text/x-python","patch_set":9,"id":"b6796d1a_dda0ec98","line":1864,"in_reply_to":"a1c9c4a1_82a28751","updated":"2023-12-06 15:26:28.000000000","message":"well, yes and no! these log lines come out of  _replace_source_node(). The log I \"removed\" was never called on master (because we raised a StopIteration).\n\nSwitching to raising a ChunkReadTimeout caused that except clause to be hit and another log line popped out which seemed superfluous.\n\nWorse, the error limit counter for the final node would be incremented *twice*. I have some node error count assertions I can pull in from later in the chain.","commit_id":"21d99bb287dc70e5a40498a9324929f057b009d2"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"8ecd13701c0a35403ef3dfc2cfef70e520023249","unresolved":true,"context_lines":[{"line_number":4949,"context_line":"            resp \u003d req.get_response(self.app)"},{"line_number":4950,"context_line":"            with self.assertRaises(ChunkReadTimeout):"},{"line_number":4951,"context_line":"                # note: the error is raised while the resp_iter is read"},{"line_number":4952,"context_line":"                _ \u003d resp.body"},{"line_number":4953,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":4954,"context_line":"        self.assertEqual(len(log), self.policy.ec_n_unique_fragments * 2)"},{"line_number":4955,"context_line":"        log_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)"}],"source_content_type":"text/x-python","patch_set":13,"id":"7fb8027d_4e2eff8c","line":4952,"updated":"2024-02-03 00:24:07.000000000","message":"So the test has `body_started` in the name -- how much made it out? Better with something like\n\n```\ndiff --git a/test/unit/proxy/controllers/test_obj.py b/test/unit/proxy/controllers/test_obj.py\nindex 501407b84..13790b92a 100644\n--- a/test/unit/proxy/controllers/test_obj.py\n+++ b/test/unit/proxy/controllers/test_obj.py\n@@ -4947,9 +4947,22 @@ class TestECObjController(ECObjectControllerMixin, unittest.TestCase):\n             \u0027Range\u0027: \u0027bytes\u003d1000-2000,14000-15000\u0027})\n         with capture_http_requests(get_response) as log:\n             resp \u003d req.get_response(self.app)\n+            response_chunks \u003d []\n             with self.assertRaises(ChunkReadTimeout):\n-                # note: the error is raised while the resp_iter is read\n-                _ \u003d resp.body\n+                for chunk in resp.app_iter:\n+                    response_chunks.append(chunk)\n+        boundary \u003d resp.headers[\u0027Content-Type\u0027].split(\u0027\u003d\u0027, 1)[1]\n+        self.assertEqual(response_chunks, [\n+            b\u0027\\r\\n\u0027.join([\n+                b\u0027--\u0027 + boundary.encode(\u0027ascii\u0027),\n+                b\u0027Content-Type: application/octet-stream\u0027,\n+                b\u0027Content-Range: bytes 1000-2000/16384\u0027,\n+                b\u0027\u0027,\n+                b\u0027\u0027,\n+            ]),\n+            test_body[0:1001],\n+            b\u0027\\r\\n\u0027,\n+        ])\n         self.assertEqual(resp.status_int, 206)\n         self.assertEqual(len(log), self.policy.ec_n_unique_fragments * 2)\n         log_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)\n```","commit_id":"cc01563c3873e4ef53d7d6e1d1ca02fa0cdf8f66"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"54812ad38e8ce4711893dc7720f6bcd080af0d07","unresolved":false,"context_lines":[{"line_number":4949,"context_line":"            resp \u003d req.get_response(self.app)"},{"line_number":4950,"context_line":"            with self.assertRaises(ChunkReadTimeout):"},{"line_number":4951,"context_line":"                # note: the error is raised while the resp_iter is read"},{"line_number":4952,"context_line":"                _ \u003d resp.body"},{"line_number":4953,"context_line":"        self.assertEqual(resp.status_int, 206)"},{"line_number":4954,"context_line":"        self.assertEqual(len(log), self.policy.ec_n_unique_fragments * 2)"},{"line_number":4955,"context_line":"        log_lines \u003d self.app.logger.get_lines_for_level(\u0027error\u0027)"}],"source_content_type":"text/x-python","patch_set":13,"id":"13cc03cb_07740b87","line":4952,"in_reply_to":"7fb8027d_4e2eff8c","updated":"2024-02-05 18:10:40.000000000","message":"Done","commit_id":"cc01563c3873e4ef53d7d6e1d1ca02fa0cdf8f66"}]}