)]}'
{"/COMMIT_MSG":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"f4213970bb0ee458fd96d81d0f17c40372420fd9","unresolved":true,"context_lines":[{"line_number":14,"context_line":"until it was ready."},{"line_number":15,"context_line":"So instead add a wait loop and timeout to try and get the ancilary data,"},{"line_number":16,"context_line":"this worked really well, really fast and even when setting the timeout"},{"line_number":17,"context_line":"to 0.1 got the data on every request."},{"line_number":18,"context_line":"To be honest maybe 0.1 still too high, but it\u0027s a timeout, so only a"},{"line_number":19,"context_line":"maximum wait."},{"line_number":20,"context_line":""},{"line_number":21,"context_line":"This wait has been made configurable via an ancdata_wait config option"},{"line_number":22,"context_line":"that defaults to 0.01."}],"source_content_type":"text/x-gerrit-commit-message","patch_set":7,"id":"75519642_a0d9f337","line":19,"range":{"start_line":17,"start_character":0,"end_line":19,"end_character":13},"updated":"2025-04-07 16:24:36.000000000","message":"Probably need to reword this now.","commit_id":"13b99c6f99b74db3a5dfb9b5f77be0cc1e83347a"}],"/PATCHSET_LEVEL":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"1e23ce3549053d6a0db1b2194ab69f8cbc7682b0","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":1,"id":"30fdc3dc_77a7f8da","updated":"2025-03-12 11:20:04.000000000","message":"```\nvagrant@saio7:~/swift$ python3 swift/proxy/server.py /etc/swift/proxy-server/proxy-server.conf.d/ -v\n...\nproxy-server: STDERR: (41894) accepted (\u0027127.0.0.1\u0027, 33394)\nproxy-server: STDOUT: SOCKET_TIMESTAMP 1741777755.928609 (txn: txe4ed36b2d8b64cc79cd6c-0067d16b5b) \nproxy-server: 127.0.0.1 127.0.0.1 12/Mar/2025/11/09/15 GET /auth/v1.0 HTTP/1.0 200 - python-swiftclient-4.5.0.dev8 - - - - txe4ed36b2d8b64cc79cd6c-0067d16b5b - 0.0019 - - 1741777755.931307793 1741777755.933179379 -\nproxy-server: STDERR: 127.0.0.1 - - [12/Mar/2025 11:09:15] \"GET /auth/v1.0 HTTP/1.1\" 200 412 0.007564 (txn: txe4ed36b2d8b64cc79cd6c-0067d16b5b)\n```\n\nNot sure it\u0027s happening on every request. Seem to get:\n```\n[Errno 11] Resource temporarily unavailable\n```\n\nWhen attempting to call socket.recvmsg(..) to get the ancdata. Works in my own simple server, but maybe something something eventlet blocking?","commit_id":"05891bccaaf83c89d548e7d8cd03c5e8542556c8"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"75f2cdfc4381ade043d3b7e3d982c823b6046bad","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":1,"id":"b727a143_ac1e113a","in_reply_to":"30fdc3dc_77a7f8da","updated":"2025-03-12 11:20:50.000000000","message":"Sometimes get.","commit_id":"05891bccaaf83c89d548e7d8cd03c5e8542556c8"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e2bca88b73e3508961c3420260799d8fa556018","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":2,"id":"4e9d85d6_cdb3c747","updated":"2025-03-13 03:01:12.000000000","message":"Woo consistent socket_timestamps!\n```\nproxy-server: STDERR: (44135) accepted (\u0027127.0.0.1\u0027, 53360)\nproxy-server: STDOUT: \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d SOCKET_TIMESTAMP 1741833075.531288 \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d (txn: tx308bd32a5cbc4b0d9b108-0067d24373)\nproxy-server: 127.0.0.1 127.0.0.1 13/Mar/2025/02/31/15 GET /auth/v1.0 HTTP/1.0 200 - python-swiftclient-4.5.0.dev8 - - - - tx308bd32a5cbc4b0d9b108-0067d24373 - 0.0016 - - 1741833075.533010721 1741833075.534631491 -\nproxy-server: STDERR: 127.0.0.1 - - [13/Mar/2025 02:31:15] \"GET /auth/v1.0 HTTP/1.1\" 200 412 0.004028 (txn: tx308bd32a5cbc4b0d9b108-0067d24373)\nproxy-server: STDERR: (44135) accepted (\u0027127.0.0.1\u0027, 53364)\nproxy-server: STDOUT: \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d SOCKET_TIMESTAMP 1741833075.536058 \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d (txn: txb6d648872b924095a6c1b-0067d24373)\nproxy-server: User: test:tester uses token AUTH_tka69c492e689747beb0f1c17c795e7c03 (trans_id txb6d648872b924095a6c1b-0067d24373)\nproxy-server: - - 13/Mar/2025/02/31/15 HEAD /v1/AUTH_test%3Fformat%3Djson HTTP/1.0 200 - Swift - - - - txb6d648872b924095a6c1b-0067d24373 - 0.0306 RL - 1741833075.538270235 1741833075.568908453 -\nproxy-server: User test:tester has admin authorizing. (txn: txb6d648872b924095a6c1b-0067d24373) (client_ip: 127.0.0.1)\nproxy-server: removed response headers: [(\u0027X-Backend-Fake-Account-Listing\u0027, \u0027yes\u0027), (\u0027X-Backend-Recheck-Account-Existence\u0027, \u002760\u0027)] (txn: txb6d648872b924095a6c1b-0067d24373) (client_ip: 127.0.0.1)\nproxy-server: 127.0.0.1 127.0.0.1 13/Mar/2025/02/31/15 HEAD /v1/AUTH_test%3Fformat%3Djson HTTP/1.0 200 - python-swiftclient-4.5.0.dev8 AUTH_tka69c492e6... - - - txb6d648872b924095a6c1b-0067d24373 - 0.0436 - - 1741833075.537377357 1741833075.580986738 -\n```","commit_id":"4bdb7b997c36c5c6cf173cd1106149b3e709e230"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":4,"id":"7803545c_cef8128d","updated":"2025-03-13 17:02:10.000000000","message":"I\u0027d really love to see this what we could do in proxy logging with this\n\nparticularly I think it\u0027d be quite smart to have it replace `start_time`\n\nhttps://github.com/NVIDIA/swift/blob/master/swift/common/middleware/proxy_logging.py#L402\n\nand maybe extend the log line with a new \"queue_delta\" or something\n\nI also need to think about the difference between a tcp connection waiting in the accept queue vs a pipeline request sitting idle in eventlet.wsgi.server\n\nit\u0027s possible only one of those is interesting, or we should at least want to figure out how to tell the difference.\n\n\"connection start\" vs \"request start\" vs \"wsgi start\"","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":4,"id":"feeb1a88_b87a680d","updated":"2025-03-13 23:24:49.000000000","message":"Thanks clay!\n\nYeah next is to add to proxy_logging and maybe even return a 504 or something if older then client_timeout. But where? proxy? Something right of proxy_logging I guess.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":4,"id":"96bbad3f_37c768fc","in_reply_to":"7803545c_cef8128d","updated":"2025-03-13 23:24:49.000000000","message":"yeah. So long as we somehow track when we get the connection so we can better match our client timings. But also tracking how fast we\u0027re doing a request (from what we can control) ie our current tracking I think is still something to track. That\u0027s something we\u0027re actaully in control of, how long something is on the accept queue is somewhat out of our hands, but good to know about.\n\nSo maybe a connection_start on the log line and a - if it doesn\u0027t exist, the delta can always be calculated in opensearch. But also not opposed to adding a queue_delta field. OR maybe even a queue_delta.{0_1,1_5,5_15,15_30,..n_n+1}sec bucket increment stats so we can track timings in the cluster might also be interesting, where n can be client_timeout or something.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":8,"id":"e98ca6dd_399a5711","updated":"2025-05-01 19:43:11.000000000","message":"Still need to play with it, but an initial read-through seems to make sense.","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":8,"id":"80837caa_9bd64b15","updated":"2025-05-02 05:30:59.000000000","message":"Thanks Tim","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"c7650eae58d60c7248f590040e451b4ede1bb77d","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"df877513_bf32b598","updated":"2025-05-06 23:18:16.000000000","message":"I\u0027m still trying to find info on how these timestamps interact with TCP keep-alives -- not clear on whether we get the timestamp for the oldest or newest packet...","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"cb4b0297e0280d62a2d370c876b957119451da0b","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"c7c38e8a_83e548aa","updated":"2025-05-02 21:22:30.000000000","message":"So I\u0027ve been playing with this in a bit of a pathological case: drop `max_clients` and `workers` both all the way down to 1, then run `swift-bench` to do 1000 PUTs with 100 concurrency, all the while using `lsof -i :8080 -T qs` to monitor queue depths. It gets weird! Setting `keepalive_timeout \u003d 5` at least helped avoid some early delays/timeouts, leading to a start-up that looked like\n```\nvagrant@saio:~$ tail -n 0 -f /var/log/syslog | awk \u0027/proxy-server: 127.0.0.1/{ print $1, $25, $22, $23, $19, $26, $7, $8 }\u0027\n2025-05-02T21:00:33.295368+00:00 1746219633.292946100 1746219633.294643641 1746219633.295144558 0.0005 0.001697540 GET /auth/v1.0\n2025-05-02T21:00:39.389633+00:00 1746219633.300460100 1746219639.303086996 1746219639.389325142 0.0862 6.002626896 PUT /v1/AUTH_test/cont\n2025-05-02T21:00:45.399063+00:00 1746219639.394234896 1746219645.396388054 1746219645.398479939 0.0021 6.002153158 GET /auth/v1.0\n2025-05-02T21:00:46.462411+00:00 1746219645.456794024 1746219646.405605555 1746219646.462182760 0.0566 0.948811531 PUT /v1/AUTH_test/cont/95f25802d5c547f185cb9af2a0b8fb70\n2025-05-02T21:00:46.503154+00:00 0.000000000 1746219646.465538263 1746219646.502915382 0.0374 - PUT /v1/AUTH_test/cont/d9dd263d9bb14a3489734138fe0ec409\n2025-05-02T21:00:46.546762+00:00 0.000000000 1746219646.505640030 1746219646.546576500 0.0409 - PUT /v1/AUTH_test/cont/f7039842193c4768a2d378a3c15741fc\n...\n```\nfollowed by a whole bunch of pipelined requests. My `lsof` shows the queues backed up:\n```\nCOMMAND     PID    USER   FD   TYPE  DEVICE SIZE/OFF NODE NAME\nswift-pro 30248 vagrant   29u  IPv4 4893160      0t0  TCP *:http-alt (LISTEN QR\u003d98 QS\u003d0)\nswift-pro 30258 vagrant   28u  IPv4 4893678      0t0  TCP localhost:http-alt-\u003elocalhost:48152 (ESTABLISHED QR\u003d267 QS\u003d0)\nswift-pro 30258 vagrant   29u  IPv4 4893160      0t0  TCP *:http-alt (LISTEN QR\u003d98 QS\u003d0)\nswift-pro 30258 vagrant   33u  IPv4 4893578      0t0  TCP localhost:http-alt-\u003elocalhost:48140 (ESTABLISHED QR\u003d0 QS\u003d0)\n```\nSo, 98 queued connections, one accepted and waiting for handler to spawn, and one that\u0027s actually getting work done. We get through all the pipelined requests (they\u0027re reasonably snappy, bam-bam-bam), then start seeing logs for the connections that were sitting in the accept queue:\n```\n...\n2025-05-02T21:01:32.760471+00:00 0.000000000 1746219692.712908983 1746219692.760242224 0.0473 - PUT /v1/AUTH_test/cont/bfd41af400334843a71e5fb227927e8e\n2025-05-02T21:01:32.818384+00:00 0.000000000 1746219692.763310671 1746219692.818123817 0.0548 - PUT /v1/AUTH_test/cont/5979af3cd46542f1a1994a58878d9b39\n2025-05-02T21:01:36.637041+00:00 1746219695.474230051 1746219696.586881399 1746219696.636852026 0.0500 1.112651348 PUT /v1/AUTH_test/cont/b52cb4f761cc4785b6428323d992281d\n2025-05-02T21:01:37.696917+00:00 1746219695.502861023 1746219697.639647961 1746219697.696673632 0.0570 2.136786938 PUT /v1/AUTH_test/cont/905c1ec64a9a4b2a8884a6f03a945bdb\n2025-05-02T21:01:38.739126+00:00 1746219695.504017115 1746219698.700636864 1746219698.738929510 0.0383 3.196619749 PUT /v1/AUTH_test/cont/365b10acc82940649eb68c570af0a529\n...\n```\nThe SO_TIMESTAMP times seem weird, though: I would\u0027ve expected them to roughly match the start of the first PUT, but it\u0027s more than 50s later! Also weird: the `start_time` for the first backed-up connection is _less_ than the 5s keepalive timeout after the `end_time` for the last pipelined request! \n\nIt continues logging these at ~1/s (!?) until it\u0027s handled all of them:\n```\n...\n2025-05-02T21:03:18.004523+00:00 1746219695.565129042 1746219797.950864315 1746219798.004324675 0.0535 102.385735273 PUT /v1/AUTH_test/cont/fe39102e74244adbb55b351292d40ed1\n2025-05-02T21:03:19.056774+00:00 1746219695.565196991 1746219799.006800413 1746219799.056572914 0.0498 103.441603422 PUT /v1/AUTH_test/cont/890403d64f3c4dacbd509cdcd85d674b\n2025-05-02T21:03:20.111847+00:00 1746219695.565243959 1746219800.059646130 1746219800.111657381 0.0520 104.494402170 PUT /v1/AUTH_test/cont/572d36defa3342e89c1a6aae89bd918c\n```\nSo I\u0027m not entirely sure we\u0027re getting the signal we were hoping for, but it\u0027s definitely more/better info than what we had before (ie, nothing).","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"220c86e673618cfe679fef4ae7812dd90340ce73","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"344bb936_e8715f70","updated":"2025-05-06 07:33:00.000000000","message":"So having a quick look, and your right, it\u0027s alittle weird, but I think it might be about how we\u0027re acceptiong packets.. \n\nI changed my log output to:\n```\nvagrant@saio3:~$ grep log_msg_template /etc/swift/proxy-server/default.conf-template\nlog_msg_template \u003d {client_ip} {remote_addr} {end_time.datetime} {method} {connection_start} {queue_time} {start_time} {end_time}\n```\n\nThen run a slow client that waits a 0.5 seconds after puting most of the expected data:\n```\ntime ./bad_put_client.py -n 10 -t 10 --size 1 --chunk-size 1048575 --sleep 0.5\n```\n\nThe time output is:\n```\nreal    1m1.334s\nuser    0m0.312s\nsys     0m0.056s\n```\n\nSo it took about a minute, and after setting it to RX software and hardware. The accept sockets queued up to 9, then took about 59 seconds before I got log output for the requests, and they all seem to state they were waiting that long:\n\n```\nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.211949110 59.858967543 1746516254.070916653 1746516254.193141460 (txn: txa033ffa772184caeaa528-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.215954065 59.979025841 1746516254.194979906 1746516254.272416353 (txn: tx18d9cd8bed224fad9e400-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.215951920 60.058138371 1746516254.274090290 1746516254.344206572 (txn: tx20eecdd85a7e420da00df-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.215950012 60.129819155 1746516254.345769167 1746516254.434432507 (txn: tx1c4175cf451348eaa47c5-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.215945005 60.220984221 1746516254.436929226 1746516254.511817455 (txn: txc8bd713d0ace40708fd02-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.219948053 60.293509722 1746516254.513457775 1746516254.583345175 (txn: tx40394a94e91a4bf289a4a-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.219944954 60.365351915 1746516254.585296869 1746516254.672358513 (txn: tx7e9f66b3f6bd4b2a9b657-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.223948956 60.450185537 1746516254.674134493 1746516254.748083353 (txn: tx48379161f72743559a796-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.227952003 60.521626234 1746516254.749578238 1746516254.839731216 (txn: tx6af30ac96a9b425cb715e-006819b91e)                                                                                                                         \nMay 06 07:24:14 saio3 proxy-server[222862]: 127.0.0.1 127.0.0.1 06/May/2025/07/24/14 PUT 1746516194.227946997 60.613335371 1746516254.841282368 1746516254.914169788 (txn: tx6fa2ac5e0d944641a5601-006819b91e)\n```\n\nSo the queuing timing seems about right :shrug:?","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"98d47a5a57d51db33b96c45ccae9cf90ca9530a8","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"960ee383_41a28fbc","updated":"2025-05-07 23:44:15.000000000","message":"So this is kinda weird -- I managed to get *one run* today (concurrency 40, num puts 100, on your `SO_TIMESTAMPING` diff) that looked like https://paste.opendev.org/show/boCpT62nokgiH3wG6UCI/ -- i.e. it starts out like what I posted a couple days ago, but when we start processing the backlogged connections, a handful had kernel timestamps that matched (or at any rate were close to) the timestamp on the good connection! That is to say, it actually behaved how I was expecting!\n\nI\u0027m beginning to think that what I\u0027m seeing is largely an artifact of how swift-bench works and isn\u0027t representative of real workloads.","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"00eec2fd2fc590bed119b242ea644cbe557bce88","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"68636d6f_18ca174c","updated":"2025-05-07 10:02:21.000000000","message":"Working on a new version that uses SO_TIMESTAMPING, and focusing on the _NEW version.\n\nNeed to pass another flag to actually enable it it seems. Not that that\u0027s mentioned anywhere, except some random forum somewhere, but needed to do it to get it all working.\n\nWill push up a new version soon.. but current working version needs this patch: https://paste.openstack.org/show/827704/ \n\n@tburke@nvidia.com In my testing this is still returning about right on my limited testing (sitting on the queue for 60 seconds and then they all come through), but I wonder if they\u0027ll behave better in your envionment?","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"1177ebad6544a5527e04b138d6e989fe050de9ea","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"ddd18e58_86a4d1a8","in_reply_to":"68636d6f_18ca174c","updated":"2025-05-07 17:36:06.000000000","message":"\u003e focusing on the _NEW version.\n\nOne thing to watch out for with the `_NEW` versions is what kernel it requires -- looks like 5.1 for both `SO_TIMESTAMP_NEW` and  `SO_TIMESTAMPING_NEW`... meanwhile, our Cent7 nodes are back on 3.10, and even once we migrate to Rocky8, we\u0027ll only have gotten up to 4.18? :-/\n\nI think we\u0027ll have to use the old option for a while...","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"d93a58c9f6aaefad2c789d18fc67927448d4e7ed","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"97c3946c_d69041a4","in_reply_to":"c7c38e8a_83e548aa","updated":"2025-05-04 23:09:41.000000000","message":"hmm, that seems a little disappointing :( \n\nI wonder if we make it just RX rathern the TX and RX. Maybe we\u0027re updating the timestamp when we send a keep alive or something? OR the kernel adds it later then expected.. maybe TX hardware too.","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"3f955409a884e4a56f388dbd43115292f0f7cda3","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":9,"id":"20f4d433_7b88e105","in_reply_to":"ddd18e58_86a4d1a8","updated":"2025-05-07 23:24:50.000000000","message":"oh good call. KK, will move it to the OLD first.","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"25e48574e995594b87e71739293d985e82ac8abe","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":11,"id":"112813d3_6c0014a8","updated":"2025-05-13 02:05:01.000000000","message":"opps more draft comments 😞","commit_id":"0af4128a418ad56b8db74ce6566409f5e215be08"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"708e4145b1be43cd2ad9158652ebdbb983daf468","unresolved":false,"context_lines":[],"source_content_type":"","patch_set":13,"id":"0d66457d_3c164471","updated":"2025-12-10 06:38:59.000000000","message":"This seems to be working well for me. When I set the workers to 1 and max_clients to 2. I then use `swift-bench --saio` and as the bench goes the requests are getting queued up and taking longer and longer.\n\nI went and changed the proxy_logging output to me easier to read:\n```\n[filter:proxy-logging]\nuse \u003d egg:swift#proxy_logging\nlog_msg_template \u003d {method} {path} {status_int} {transaction_id} {source} C:{connection_start} S:{start_time} E:{end_time} [{queue_time}]\n```\n\nSo C:\u003cconnection start from kernel\u003e S:\u003creq make it to proxy logging\u003e E:\u003cresp back to proxy logging\u003e [\u003ctime in queue (S - C)\u003e]\n\nHere is a snippet of some the the delete logs (towards the end of the bench):\n\n```\nDec 10 06:28:46 saio proxy-server[25875]: DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_12 204 tx9ba029e289304b26a9857-006939131e - C:1765347885.820095301 S:1765348126.546327829 E:1765348126.705564737 [240.726232529]                             \nDec 10 06:28:46 saio proxy-server[25875]: STDERR: 127.0.0.1 - - [10/Dec/2025 06:28:46] \"DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_12 HTTP/1.1\" 204 231 0.160323 (txn: tx9ba029e289304b26a9857-006939131e)                                        \nDec 10 06:28:46 saio proxy-server[25875]: DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_13 204 tx88f5e14bc66f454da8b4c-006939131e - C:1765347885.826669693 S:1765348126.550049782 E:1765348126.716457844 [240.723380089]                             \nDec 10 06:28:46 saio proxy-server[25875]: STDERR: 127.0.0.1 - - [10/Dec/2025 06:28:46] \"DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_13 HTTP/1.1\" 204 231 0.166811 (txn: tx88f5e14bc66f454da8b4c-006939131e)                                    \nDec 10 06:28:46 saio proxy-server[25875]: DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_12 204 tx9ba029e289304b26a9857-006939131e - C:1765347885.820095301 S:1765348126.546327829 E:1765348126.705564737 [240.726232529]     \nDec 10 06:28:46 saio proxy-server[25875]: STDERR: 127.0.0.1 - - [10/Dec/2025 06:28:46] \"DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_12 HTTP/1.1\" 204 231 0.160323 (txn: tx9ba029e289304b26a9857-006939131e)                                    \nDec 10 06:28:46 saio proxy-server[25875]: DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_13 204 tx88f5e14bc66f454da8b4c-006939131e - C:1765347885.826669693 S:1765348126.550049782 E:1765348126.716457844 [240.723380089]\n...                                                                                                     \nDec 10 06:29:46 saio proxy-server[25875]: DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_15 204 txd84eea4807634bb095062-006939135a - C:1765347885.939354420 S:1765348186.789629698 E:1765348186.924643755 [300.850275278]\nDec 10 06:29:46 saio proxy-server[25875]: STDERR: 127.0.0.1 - - [10/Dec/2025 06:29:46] \"DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_15 HTTP/1.1\" 204 231 0.136185 (txn: txd84eea4807634bb095062-006939135a)                                        \nDec 10 06:29:46 saio proxy-server[25875]: DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_15 204 txd84eea4807634bb095062-006939135a - C:1765347885.939354420 S:1765348186.789629698 E:1765348186.924643755 [300.850275278]                             \nDec 10 06:29:46 saio proxy-server[25875]: STDERR: 127.0.0.1 - - [10/Dec/2025 06:29:46] \"DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_15 HTTP/1.1\" 204 231 0.136185 (txn: txd84eea4807634bb095062-006939135a)                \nDec 10 06:29:46 saio proxy-server[25875]: DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_14 204 txb352ff87f06947689425b-006939135a - C:1765347885.935421228 S:1765348186.783581495 E:1765348186.931988239 [300.848160267]                             \nDec 10 06:29:46 saio proxy-server[25875]: STDERR: 127.0.0.1 - - [10/Dec/2025 06:29:46] \"DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_14 HTTP/1.1\" 204 231 0.151644 (txn: txb352ff87f06947689425b-006939135a)                                        \nDec 10 06:29:46 saio proxy-server[25875]: DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_14 204 txb352ff87f06947689425b-006939135a - C:1765347885.935421228 S:1765348186.783581495 E:1765348186.931988239 [300.848160267]     \nDec 10 06:29:46 saio proxy-server[25875]: STDERR: 127.0.0.1 - - [10/Dec/2025 06:29:46] \"DELETE /v1/AUTH_test/10e3fdcf6fb74893afc2f368e8533399_14 HTTP/1.1\" 204 231 0.151644 (txn: txb352ff87f06947689425b-006939135a)                \nDec 10 06:30:46 saio proxy-server[25875]: STDERR: (25875) timed out (\u0027127.0.0.1\u0027, 45028) (txn: txd84eea4807634bb095062-006939135a)                                                                                       \n```\nWhich are then timing out, as they are older then client connection time.","commit_id":"237343267c012d26643358fafd0b3b98b843e811"}],"doc/source/config/account_server_config.rst":[{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":true,"context_lines":[{"line_number":165,"context_line":"                                               ionice_class."},{"line_number":166,"context_line":"                                               Ignored if IOPRIO_CLASS_IDLE is set."},{"line_number":167,"context_line":"ancdata_wait                   0.1             How long to wait for ancilary data to"},{"line_number":168,"context_line":"                                               be sent from the kernel. Used for SO_TIMESTAMP"},{"line_number":169,"context_line":"\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d  \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d  \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d"},{"line_number":170,"context_line":""},{"line_number":171,"context_line":"********************"}],"source_content_type":"text/x-rst","patch_set":4,"id":"07ff4581_35fe5f0e","line":168,"updated":"2025-03-13 17:02:10.000000000","message":"I don\u0027t understand why or why this times out... if you turn on the socket option is *really* just optional/best-effort?\n\nIt seems like if a client makes a connection they\u0027re going to send a request - and if they sent a request we should get the ancdata?","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":true,"context_lines":[{"line_number":165,"context_line":"                                               ionice_class."},{"line_number":166,"context_line":"                                               Ignored if IOPRIO_CLASS_IDLE is set."},{"line_number":167,"context_line":"ancdata_wait                   0.1             How long to wait for ancilary data to"},{"line_number":168,"context_line":"                                               be sent from the kernel. Used for SO_TIMESTAMP"},{"line_number":169,"context_line":"\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d  \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d  \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d"},{"line_number":170,"context_line":""},{"line_number":171,"context_line":"********************"}],"source_content_type":"text/x-rst","patch_set":4,"id":"e5b6cb24_a14bfe58","line":168,"in_reply_to":"07ff4581_35fe5f0e","updated":"2025-03-13 23:24:49.000000000","message":"Sure, just didn\u0027t want to have a perm wait incase for some reason the ancdata wasn\u0027t going to come.\n\nWhat if the SO_TIMESTAMP was somehow disabled (not that is something I think you can do). But I see your point.\n\nSo I can either keep it like this, or maybe somehow make waiting at all for the ancdata an option. Just wanted some chance to continue processing the request at the loss of a timestamp.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":164,"context_line":"                                               priority of the process. Work only with"},{"line_number":165,"context_line":"                                               ionice_class."},{"line_number":166,"context_line":"                                               Ignored if IOPRIO_CLASS_IDLE is set."},{"line_number":167,"context_line":"ancdata_wait                   0.01            How long to wait for ancilary data to"},{"line_number":168,"context_line":"                                               be sent from the kernel. Used for SO_TIMESTAMP"},{"line_number":169,"context_line":"\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d  \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d  \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d"},{"line_number":170,"context_line":""}],"source_content_type":"text/x-rst","patch_set":8,"id":"99a7c7f5_740ff987","line":167,"range":{"start_line":167,"start_character":68,"end_line":167,"end_character":76},"updated":"2025-05-01 19:43:11.000000000","message":"\"ancillary\"","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":false,"context_lines":[{"line_number":164,"context_line":"                                               priority of the process. Work only with"},{"line_number":165,"context_line":"                                               ionice_class."},{"line_number":166,"context_line":"                                               Ignored if IOPRIO_CLASS_IDLE is set."},{"line_number":167,"context_line":"ancdata_wait                   0.01            How long to wait for ancilary data to"},{"line_number":168,"context_line":"                                               be sent from the kernel. Used for SO_TIMESTAMP"},{"line_number":169,"context_line":"\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d  \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d  \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d"},{"line_number":170,"context_line":""}],"source_content_type":"text/x-rst","patch_set":8,"id":"5a61b19a_404f2c9c","line":167,"range":{"start_line":167,"start_character":68,"end_line":167,"end_character":76},"in_reply_to":"99a7c7f5_740ff987","updated":"2025-05-02 05:30:59.000000000","message":"Done","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"}],"etc/account-server.conf-sample":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"58b2bdd56a5a1dd6587e491efb5718dfb7eadca6","unresolved":true,"context_lines":[{"line_number":97,"context_line":"# socket\u0027s accept queue. The accepted socket is in non-blocking mode."},{"line_number":98,"context_line":"# So ancdata_wait tells the Swift thread how long it should wait as a maximum"},{"line_number":99,"context_line":"# waiting for this data."},{"line_number":100,"context_line":"# ancdata_wait \u003d 0.1"},{"line_number":101,"context_line":"#"},{"line_number":102,"context_line":"# You can disable REPLICATE handling (default is to allow it). When deploying"},{"line_number":103,"context_line":"# a cluster with a separate replication network, you\u0027ll want multiple"}],"source_content_type":"application/octet-stream","patch_set":2,"id":"ede2975b_eb54dc18","line":100,"range":{"start_line":100,"start_character":2,"end_line":100,"end_character":14},"updated":"2025-03-13 03:02:24.000000000","message":"Not sure I\u0027ll keep this as the name, someone come up with a better name? 😜\n\nancilary_wait?","commit_id":"4bdb7b997c36c5c6cf173cd1106149b3e709e230"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":92,"context_line":"# set log_address \u003d /dev/log"},{"line_number":93,"context_line":"#"},{"line_number":94,"context_line":"# Additional socket conection information is passed from the kernel and into"},{"line_number":95,"context_line":"# userspace via ancilary. One such piece of information is the time the request"},{"line_number":96,"context_line":"# hit the kernel via SO_TIMESTAMP.  We use this track time on spend on the"},{"line_number":97,"context_line":"# socket\u0027s accept queue. The accepted socket is in non-blocking mode."},{"line_number":98,"context_line":"# So ancdata_wait tells the Swift thread how long it should wait as a maximum"}],"source_content_type":"application/octet-stream","patch_set":8,"id":"f21bf7b7_be1b3ee7","line":95,"range":{"start_line":95,"start_character":16,"end_line":95,"end_character":24},"updated":"2025-05-01 19:43:11.000000000","message":"\"ancillary data\"","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":false,"context_lines":[{"line_number":92,"context_line":"# set log_address \u003d /dev/log"},{"line_number":93,"context_line":"#"},{"line_number":94,"context_line":"# Additional socket conection information is passed from the kernel and into"},{"line_number":95,"context_line":"# userspace via ancilary. One such piece of information is the time the request"},{"line_number":96,"context_line":"# hit the kernel via SO_TIMESTAMP.  We use this track time on spend on the"},{"line_number":97,"context_line":"# socket\u0027s accept queue. The accepted socket is in non-blocking mode."},{"line_number":98,"context_line":"# So ancdata_wait tells the Swift thread how long it should wait as a maximum"}],"source_content_type":"application/octet-stream","patch_set":8,"id":"d96047b6_931c1bf2","line":95,"range":{"start_line":95,"start_character":16,"end_line":95,"end_character":24},"in_reply_to":"f21bf7b7_be1b3ee7","updated":"2025-05-02 05:30:59.000000000","message":"Done","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":96,"context_line":"# hit the kernel via SO_TIMESTAMP.  We use this track time on spend on the"},{"line_number":97,"context_line":"# socket\u0027s accept queue. The accepted socket is in non-blocking mode."},{"line_number":98,"context_line":"# So ancdata_wait tells the Swift thread how long it should wait as a maximum"},{"line_number":99,"context_line":"# waiting for this data."},{"line_number":100,"context_line":"# ancdata_wait \u003d 0.01"},{"line_number":101,"context_line":"#"},{"line_number":102,"context_line":"# You can disable REPLICATE handling (default is to allow it). When deploying"}],"source_content_type":"application/octet-stream","patch_set":8,"id":"ddfb0cfd_b8f30f9d","line":99,"updated":"2025-05-01 19:43:11.000000000","message":"We should indicate that this is measured in seconds.","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":false,"context_lines":[{"line_number":96,"context_line":"# hit the kernel via SO_TIMESTAMP.  We use this track time on spend on the"},{"line_number":97,"context_line":"# socket\u0027s accept queue. The accepted socket is in non-blocking mode."},{"line_number":98,"context_line":"# So ancdata_wait tells the Swift thread how long it should wait as a maximum"},{"line_number":99,"context_line":"# waiting for this data."},{"line_number":100,"context_line":"# ancdata_wait \u003d 0.01"},{"line_number":101,"context_line":"#"},{"line_number":102,"context_line":"# You can disable REPLICATE handling (default is to allow it). When deploying"}],"source_content_type":"application/octet-stream","patch_set":8,"id":"6ab9ef82_a660077f","line":99,"in_reply_to":"ddfb0cfd_b8f30f9d","updated":"2025-05-02 05:30:59.000000000","message":"Done","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"}],"swift/common/http_protocol.py":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"222436ed958a6d2049de89634152e9bca7004f87","unresolved":true,"context_lines":[{"line_number":233,"context_line":"        # the timestamp added my SO_TIMESTAMP."},{"line_number":234,"context_line":"        # We don\u0027t want to read any of the data, only the ancdata"},{"line_number":235,"context_line":"        timestamp \u003d None"},{"line_number":236,"context_line":"        ancdata \u003d []"},{"line_number":237,"context_line":"        try:"},{"line_number":238,"context_line":"            _raw_data, ancdata, _flags, _address \u003d self.request.recvmsg("},{"line_number":239,"context_line":"                0, socket.CMSG_LEN(struct.calcsize(\"iiii\")))"}],"source_content_type":"text/x-python","patch_set":1,"id":"d7f1f29a_f68b7c56","line":236,"range":{"start_line":236,"start_character":8,"end_line":236,"end_character":20},"updated":"2025-03-12 22:16:11.000000000","message":"Now that I\u0027ve moved the except clause below, this initialization isn\u0027t needed anymore.","commit_id":"05891bccaaf83c89d548e7d8cd03c5e8542556c8"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e2bca88b73e3508961c3420260799d8fa556018","unresolved":false,"context_lines":[{"line_number":233,"context_line":"        # the timestamp added my SO_TIMESTAMP."},{"line_number":234,"context_line":"        # We don\u0027t want to read any of the data, only the ancdata"},{"line_number":235,"context_line":"        timestamp \u003d None"},{"line_number":236,"context_line":"        ancdata \u003d []"},{"line_number":237,"context_line":"        try:"},{"line_number":238,"context_line":"            _raw_data, ancdata, _flags, _address \u003d self.request.recvmsg("},{"line_number":239,"context_line":"                0, socket.CMSG_LEN(struct.calcsize(\"iiii\")))"}],"source_content_type":"text/x-python","patch_set":1,"id":"3cf9bb3d_46e4d25b","line":236,"range":{"start_line":236,"start_character":8,"end_line":236,"end_character":20},"in_reply_to":"d7f1f29a_f68b7c56","updated":"2025-03-13 03:01:12.000000000","message":"now it is used ;)","commit_id":"05891bccaaf83c89d548e7d8cd03c5e8542556c8"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e2bca88b73e3508961c3420260799d8fa556018","unresolved":true,"context_lines":[{"line_number":256,"context_line":"        except (Exception, Timeout) as ex:"},{"line_number":257,"context_line":"            # If we fail to grab fire off a recvmsg then let\u0027s not break"},{"line_number":258,"context_line":"            # anything"},{"line_number":259,"context_line":"            self.log_message(f\"\u003d\u003d\u003d Exception {str(ex)} \u003d\u003d\u003d\")"},{"line_number":260,"context_line":"        return timestamp"},{"line_number":261,"context_line":""},{"line_number":262,"context_line":"    def handle_one_request(self):"}],"source_content_type":"text/x-python","patch_set":2,"id":"595e2641_7100a833","line":259,"range":{"start_line":259,"start_character":12,"end_line":259,"end_character":60},"updated":"2025-03-13 03:01:12.000000000","message":"This wont be in the mergable version, but helps to see the exceptions in the log, or on the console when running the proxy like:\n\n```\npython3 swift/proxy/server.py /etc/swift/proxy-server/proxy-server.conf.d/ -v\n```","commit_id":"4bdb7b997c36c5c6cf173cd1106149b3e709e230"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":true,"context_lines":[{"line_number":232,"context_line":"    def _try_grab_so_timestamp(self):"},{"line_number":233,"context_line":"        # attempt to grab any ancillary data which might contain"},{"line_number":234,"context_line":"        # the timestamp added my SO_TIMESTAMP."},{"line_number":235,"context_line":"        # We don\u0027t want to read any of the data, only the ancdata"},{"line_number":236,"context_line":"        timestamp \u003d None"},{"line_number":237,"context_line":"        ancdata \u003d []"},{"line_number":238,"context_line":"        try:"}],"source_content_type":"text/x-python","patch_set":4,"id":"23e54a37_79e13e30","line":235,"updated":"2025-03-13 17:02:10.000000000","message":"I would normally expect a multi-line docstring to use the triple-quote method","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":true,"context_lines":[{"line_number":232,"context_line":"    def _try_grab_so_timestamp(self):"},{"line_number":233,"context_line":"        # attempt to grab any ancillary data which might contain"},{"line_number":234,"context_line":"        # the timestamp added my SO_TIMESTAMP."},{"line_number":235,"context_line":"        # We don\u0027t want to read any of the data, only the ancdata"},{"line_number":236,"context_line":"        timestamp \u003d None"},{"line_number":237,"context_line":"        ancdata \u003d []"},{"line_number":238,"context_line":"        try:"}],"source_content_type":"text/x-python","patch_set":4,"id":"05d62a72_266283a2","line":235,"in_reply_to":"23e54a37_79e13e30","updated":"2025-03-13 23:24:49.000000000","message":"Oh yeah, I should do that.. I put it in as a private method (_\u003cname\u003e) but yeah, still better to be a doc string, ta.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":true,"context_lines":[{"line_number":239,"context_line":"            # We don\u0027t want to turn the socket to blocking instead, we\u0027ll"},{"line_number":240,"context_line":"            # just try and get the ancdata for a bit"},{"line_number":241,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":242,"context_line":"                while not ancdata:"},{"line_number":243,"context_line":"                    try:"},{"line_number":244,"context_line":"                        _, ancdata, _, _ \u003d self.request.recvmsg("},{"line_number":245,"context_line":"                            0, socket.CMSG_LEN(struct.calcsize(\"iiii\")),"}],"source_content_type":"text/x-python","patch_set":4,"id":"acae4483_f3137f80","line":242,"updated":"2025-03-13 17:02:10.000000000","message":"I don\u0027t understand the idea here... I assume that recvmsg would pause/trampoline this gt until it returns something... when would recvmsg *return* but then ancdata still be empty?","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":true,"context_lines":[{"line_number":239,"context_line":"            # We don\u0027t want to turn the socket to blocking instead, we\u0027ll"},{"line_number":240,"context_line":"            # just try and get the ancdata for a bit"},{"line_number":241,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":242,"context_line":"                while not ancdata:"},{"line_number":243,"context_line":"                    try:"},{"line_number":244,"context_line":"                        _, ancdata, _, _ \u003d self.request.recvmsg("},{"line_number":245,"context_line":"                            0, socket.CMSG_LEN(struct.calcsize(\"iiii\")),"}],"source_content_type":"text/x-python","patch_set":4,"id":"38ba3e60_56bfce70","line":242,"in_reply_to":"acae4483_f3137f80","updated":"2025-03-13 23:24:49.000000000","message":"Yeah, I thought it would do that too, but it doesn\u0027t. In my simplified test server (that I ended up throwing eventlet into to see if green sockets where the issue, and it wasn\u0027t) I always had it available (the ancdata), but when moving it to swift, it\u0027ll only be available for a subset of the requests.\nIt doesn\u0027t wait, it throws a Errno 11, nonbocking. If I make the socket temp blocking by SAIO requests became dog slow. Throwing a retry here and a timeout worked, and was super quick. I think the 0.1 is probably still way to high, but it\u0027s a max. I assume the recvmsg just needs to be run an extra time or 2 until the anciliary data is available.\n\nI also wonder if the main difference is that wsgi is using a green pool, so maybe something something evenlet is causing a delay in the ancdata.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":true,"context_lines":[{"line_number":241,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":242,"context_line":"                while not ancdata:"},{"line_number":243,"context_line":"                    try:"},{"line_number":244,"context_line":"                        _, ancdata, _, _ \u003d self.request.recvmsg("},{"line_number":245,"context_line":"                            0, socket.CMSG_LEN(struct.calcsize(\"iiii\")),"},{"line_number":246,"context_line":"                            socket.MSG_PEEK)"},{"line_number":247,"context_line":"                    except Exception:"}],"source_content_type":"text/x-python","patch_set":4,"id":"b40508a3_da94ec64","line":244,"updated":"2025-03-13 17:02:10.000000000","message":"FWIW, I can\u0027t find any interface to *just* get the ancillary data:\n\nhttps://docs.python.org/3/library/socket.html\n\n... which is a little surprising.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":241,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":242,"context_line":"                while not ancdata:"},{"line_number":243,"context_line":"                    try:"},{"line_number":244,"context_line":"                        _, ancdata, _, _ \u003d self.request.recvmsg("},{"line_number":245,"context_line":"                            0, socket.CMSG_LEN(struct.calcsize(\"iiii\")),"},{"line_number":246,"context_line":"                            socket.MSG_PEEK)"},{"line_number":247,"context_line":"                    except Exception:"}],"source_content_type":"text/x-python","patch_set":4,"id":"6a2856f0_5d80b8ff","line":244,"in_reply_to":"82fa89c4_65bd4785","updated":"2025-05-01 19:43:11.000000000","message":"I wonder if we might be able to drop the `ancdata_wait` stuff if we did something more like `recvmsg(1, ..., socket.MSG_PEEK)`... I know [eventlet\u0027s got some special handling for `recv(0)`](https://github.com/eventlet/eventlet/blob/0.39.1/eventlet/greenio/base.py#L326-L336)\n\nThough I suppose then we\u0027d get tripped up by someone opening a connection but not sending the request for a while...","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":true,"context_lines":[{"line_number":241,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":242,"context_line":"                while not ancdata:"},{"line_number":243,"context_line":"                    try:"},{"line_number":244,"context_line":"                        _, ancdata, _, _ \u003d self.request.recvmsg("},{"line_number":245,"context_line":"                            0, socket.CMSG_LEN(struct.calcsize(\"iiii\")),"},{"line_number":246,"context_line":"                            socket.MSG_PEEK)"},{"line_number":247,"context_line":"                    except Exception:"}],"source_content_type":"text/x-python","patch_set":4,"id":"82fa89c4_65bd4785","line":244,"in_reply_to":"b40508a3_da94ec64","updated":"2025-03-13 23:24:49.000000000","message":"Yeah I know, I looked hard for that too. The only way is recvmsg.. but notice I threw in a 0 for data length _and_ a MSG_PEEK flag, which says don\u0027t pop any data off the socket, so it wont effect any other reads. So in essence is just a get ancillary data call.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":true,"context_lines":[{"line_number":247,"context_line":"                    except Exception:"},{"line_number":248,"context_line":"                        pass"},{"line_number":249,"context_line":"            for i in ancdata:"},{"line_number":250,"context_line":"                if i[0] !\u003d socket.SOL_SOCKET or i[1] !\u003d s_wsgi.SO_TIMESTAMP:"},{"line_number":251,"context_line":"                    continue"},{"line_number":252,"context_line":"                tmp \u003d struct.unpack(\"iiii\", i[2])"},{"line_number":253,"context_line":"                # tmp[2] is the exponent part of the float, we could probably"}],"source_content_type":"text/x-python","patch_set":4,"id":"f6991a33_c6370573","line":250,"updated":"2025-03-13 17:02:10.000000000","message":"I don\u0027t understand what this is saying; maybe worth a comment.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":true,"context_lines":[{"line_number":247,"context_line":"                    except Exception:"},{"line_number":248,"context_line":"                        pass"},{"line_number":249,"context_line":"            for i in ancdata:"},{"line_number":250,"context_line":"                if i[0] !\u003d socket.SOL_SOCKET or i[1] !\u003d s_wsgi.SO_TIMESTAMP:"},{"line_number":251,"context_line":"                    continue"},{"line_number":252,"context_line":"                tmp \u003d struct.unpack(\"iiii\", i[2])"},{"line_number":253,"context_line":"                # tmp[2] is the exponent part of the float, we could probably"}],"source_content_type":"text/x-python","patch_set":4,"id":"fd4b3a00_61082c60","line":250,"in_reply_to":"f6991a33_c6370573","updated":"2025-03-13 23:24:49.000000000","message":"Just filtering out any other possible ancillary data that this code isn\u0027t interested in. But yeah, can clean it up or add a comment.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5814f3e069b18032abb0aca34d04dd3e094b9d23","unresolved":false,"context_lines":[{"line_number":247,"context_line":"                    except Exception:"},{"line_number":248,"context_line":"                        pass"},{"line_number":249,"context_line":"            for i in ancdata:"},{"line_number":250,"context_line":"                if i[0] !\u003d socket.SOL_SOCKET or i[1] !\u003d s_wsgi.SO_TIMESTAMP:"},{"line_number":251,"context_line":"                    continue"},{"line_number":252,"context_line":"                tmp \u003d struct.unpack(\"iiii\", i[2])"},{"line_number":253,"context_line":"                # tmp[2] is the exponent part of the float, we could probably"}],"source_content_type":"text/x-python","patch_set":4,"id":"53f48d17_30cffd1c","line":250,"in_reply_to":"fd4b3a00_61082c60","updated":"2025-03-14 05:29:27.000000000","message":"Done","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":true,"context_lines":[{"line_number":254,"context_line":"                # just loose this bit."},{"line_number":255,"context_line":"                timestamp \u003d tmp[0] + tmp[2] * 1e-6"},{"line_number":256,"context_line":"        except (Exception, Timeout):"},{"line_number":257,"context_line":"            # If we fail to grab fire off a recvmsg then let\u0027s not break"},{"line_number":258,"context_line":"            # anything"},{"line_number":259,"context_line":"            pass"},{"line_number":260,"context_line":"        return timestamp"}],"source_content_type":"text/x-python","patch_set":4,"id":"a5578ac9_369b28d3","line":257,"updated":"2025-03-13 17:02:10.000000000","message":"this sentence could use a comma, presumably after grab?","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":true,"context_lines":[{"line_number":254,"context_line":"                # just loose this bit."},{"line_number":255,"context_line":"                timestamp \u003d tmp[0] + tmp[2] * 1e-6"},{"line_number":256,"context_line":"        except (Exception, Timeout):"},{"line_number":257,"context_line":"            # If we fail to grab fire off a recvmsg then let\u0027s not break"},{"line_number":258,"context_line":"            # anything"},{"line_number":259,"context_line":"            pass"},{"line_number":260,"context_line":"        return timestamp"}],"source_content_type":"text/x-python","patch_set":4,"id":"da602d4c_f4c27557","line":257,"in_reply_to":"a5578ac9_369b28d3","updated":"2025-03-13 23:24:49.000000000","message":"yup, basically if we don\u0027t have the socket_timestamp, oh well let\u0027s still process the request.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":true,"context_lines":[{"line_number":376,"context_line":"        # ensure the opening line for the connection is a valid PROXY protcol"},{"line_number":377,"context_line":"        # line; this is the only IO we do on this connection before any"},{"line_number":378,"context_line":"        # additional wrapping further pollutes the raw socket."},{"line_number":379,"context_line":"        connection_line \u003d self.rfile.readline(self.server.url_length_limit)"},{"line_number":380,"context_line":""},{"line_number":381,"context_line":"        if not connection_line.startswith(b\u0027PROXY \u0027):"},{"line_number":382,"context_line":"            return self.handle_error(connection_line)"}],"source_content_type":"text/x-python","patch_set":4,"id":"62938039_f97abbfa","line":379,"updated":"2025-03-13 17:02:10.000000000","message":"this is the first data that comes off the socket if you\u0027re doing SSL\n\nmaybe we need a \"read first line and ancdata\" method on our protocol that we ALWAYS do?","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":true,"context_lines":[{"line_number":376,"context_line":"        # ensure the opening line for the connection is a valid PROXY protcol"},{"line_number":377,"context_line":"        # line; this is the only IO we do on this connection before any"},{"line_number":378,"context_line":"        # additional wrapping further pollutes the raw socket."},{"line_number":379,"context_line":"        connection_line \u003d self.rfile.readline(self.server.url_length_limit)"},{"line_number":380,"context_line":""},{"line_number":381,"context_line":"        if not connection_line.startswith(b\u0027PROXY \u0027):"},{"line_number":382,"context_line":"            return self.handle_error(connection_line)"}],"source_content_type":"text/x-python","patch_set":4,"id":"49775fe6_d753356a","line":379,"in_reply_to":"62938039_f97abbfa","updated":"2025-03-13 23:24:49.000000000","message":"oh interesting, maybe.. the real problem I found however is as soon as setup makes the rfile and wfile via socket.makefile, the recvmsg will ALWAYS fail with an errno 11 exception. Which is why I ended up putting the ancillary data pulling up BEFORE the super classes setup.\n\nI confirmed this in the simple server poc, and it too would fail to recvmsg if I\u0027ve already makefile\u0027ed. \n\nI tried calling the `_try_grab_so_timestamp` all over the place.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"f4213970bb0ee458fd96d81d0f17c40372420fd9","unresolved":true,"context_lines":[{"line_number":232,"context_line":"    def _try_grab_so_timestamp(self):"},{"line_number":233,"context_line":"        \"\"\""},{"line_number":234,"context_line":"        Attempt to grab any ancillary data which might contain"},{"line_number":235,"context_line":"        the timestamp added my SO_TIMESTAMP."},{"line_number":236,"context_line":"        \"\"\""},{"line_number":237,"context_line":"        timestamp \u003d None"},{"line_number":238,"context_line":"        ancdata \u003d []"}],"source_content_type":"text/x-python","patch_set":7,"id":"e2af1c28_c81e01a0","line":235,"range":{"start_line":235,"start_character":28,"end_line":235,"end_character":30},"updated":"2025-04-07 16:24:36.000000000","message":"s/my/by/","commit_id":"13b99c6f99b74db3a5dfb9b5f77be0cc1e83347a"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"201bb5b71501d02e68b9f5c72350d7af29f871e1","unresolved":false,"context_lines":[{"line_number":232,"context_line":"    def _try_grab_so_timestamp(self):"},{"line_number":233,"context_line":"        \"\"\""},{"line_number":234,"context_line":"        Attempt to grab any ancillary data which might contain"},{"line_number":235,"context_line":"        the timestamp added my SO_TIMESTAMP."},{"line_number":236,"context_line":"        \"\"\""},{"line_number":237,"context_line":"        timestamp \u003d None"},{"line_number":238,"context_line":"        ancdata \u003d []"}],"source_content_type":"text/x-python","patch_set":7,"id":"d9e10e44_f4db1220","line":235,"range":{"start_line":235,"start_character":28,"end_line":235,"end_character":30},"in_reply_to":"e2af1c28_c81e01a0","updated":"2025-04-08 13:04:23.000000000","message":"Done","commit_id":"13b99c6f99b74db3a5dfb9b5f77be0cc1e83347a"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":171,"context_line":"    def get_environ(self, *args, **kwargs):"},{"line_number":172,"context_line":"        environ \u003d wsgi.HttpProtocol.get_environ(self, *args, **kwargs)"},{"line_number":173,"context_line":"        if self.socket_timestamp:"},{"line_number":174,"context_line":"            environ[\u0027socket_timestamp\u0027] \u003d self.socket_timestamp"},{"line_number":175,"context_line":"        header_payload \u003d self.headers.get_payload()"},{"line_number":176,"context_line":"        if isinstance(header_payload, list) and len(header_payload) \u003d\u003d 1:"},{"line_number":177,"context_line":"            header_payload \u003d header_payload[0].get_payload()"}],"source_content_type":"text/x-python","patch_set":8,"id":"b54b4d4d_913d04f2","line":174,"range":{"start_line":174,"start_character":21,"end_line":174,"end_character":37},"updated":"2025-05-01 19:43:11.000000000","message":"We probably ought to namespace this -- maybe `swift.socket_timestamp`?\n\nWhat happens with pipelined requests? Subrequests?","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":true,"context_lines":[{"line_number":171,"context_line":"    def get_environ(self, *args, **kwargs):"},{"line_number":172,"context_line":"        environ \u003d wsgi.HttpProtocol.get_environ(self, *args, **kwargs)"},{"line_number":173,"context_line":"        if self.socket_timestamp:"},{"line_number":174,"context_line":"            environ[\u0027socket_timestamp\u0027] \u003d self.socket_timestamp"},{"line_number":175,"context_line":"        header_payload \u003d self.headers.get_payload()"},{"line_number":176,"context_line":"        if isinstance(header_payload, list) and len(header_payload) \u003d\u003d 1:"},{"line_number":177,"context_line":"            header_payload \u003d header_payload[0].get_payload()"}],"source_content_type":"text/x-python","patch_set":8,"id":"cdd07263_31ef27f2","line":174,"range":{"start_line":174,"start_character":21,"end_line":174,"end_character":37},"in_reply_to":"b54b4d4d_913d04f2","updated":"2025-05-02 05:30:59.000000000","message":"Good idea, with the swift.socket_timestmap, I\u0027ll make that change.","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"4048022ce0088b5611b99cc982dea3544313cacb","unresolved":false,"context_lines":[{"line_number":171,"context_line":"    def get_environ(self, *args, **kwargs):"},{"line_number":172,"context_line":"        environ \u003d wsgi.HttpProtocol.get_environ(self, *args, **kwargs)"},{"line_number":173,"context_line":"        if self.socket_timestamp:"},{"line_number":174,"context_line":"            environ[\u0027socket_timestamp\u0027] \u003d self.socket_timestamp"},{"line_number":175,"context_line":"        header_payload \u003d self.headers.get_payload()"},{"line_number":176,"context_line":"        if isinstance(header_payload, list) and len(header_payload) \u003d\u003d 1:"},{"line_number":177,"context_line":"            header_payload \u003d header_payload[0].get_payload()"}],"source_content_type":"text/x-python","patch_set":8,"id":"9c3e0af7_9662f305","line":174,"range":{"start_line":174,"start_character":21,"end_line":174,"end_character":37},"in_reply_to":"cdd07263_31ef27f2","updated":"2025-05-07 01:27:54.000000000","message":"Done","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":226,"context_line":"    def setup(self):"},{"line_number":227,"context_line":"        # Need to grab the ancdata before we make socket files. At least"},{"line_number":228,"context_line":"        # I seem to need to in my testing."},{"line_number":229,"context_line":"        self.socket_timestamp \u003d self._try_grab_so_timestamp()"},{"line_number":230,"context_line":"        return super().setup()"},{"line_number":231,"context_line":""},{"line_number":232,"context_line":"    def _try_grab_so_timestamp(self):"}],"source_content_type":"text/x-python","patch_set":8,"id":"209c3234_75871e6e","line":229,"updated":"2025-05-01 19:43:11.000000000","message":"Why here and not in `__init__` (which we already override)?","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":true,"context_lines":[{"line_number":226,"context_line":"    def setup(self):"},{"line_number":227,"context_line":"        # Need to grab the ancdata before we make socket files. At least"},{"line_number":228,"context_line":"        # I seem to need to in my testing."},{"line_number":229,"context_line":"        self.socket_timestamp \u003d self._try_grab_so_timestamp()"},{"line_number":230,"context_line":"        return super().setup()"},{"line_number":231,"context_line":""},{"line_number":232,"context_line":"    def _try_grab_so_timestamp(self):"}],"source_content_type":"text/x-python","patch_set":8,"id":"71e58480_01904a2c","line":229,"in_reply_to":"209c3234_75871e6e","updated":"2025-05-02 05:30:59.000000000","message":"Tried to do it as close as I can to the reading of the request.","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"4048022ce0088b5611b99cc982dea3544313cacb","unresolved":true,"context_lines":[{"line_number":226,"context_line":"    def setup(self):"},{"line_number":227,"context_line":"        # Need to grab the ancdata before we make socket files. At least"},{"line_number":228,"context_line":"        # I seem to need to in my testing."},{"line_number":229,"context_line":"        self.socket_timestamp \u003d self._try_grab_so_timestamp()"},{"line_number":230,"context_line":"        return super().setup()"},{"line_number":231,"context_line":""},{"line_number":232,"context_line":"    def _try_grab_so_timestamp(self):"}],"source_content_type":"text/x-python","patch_set":8,"id":"93726bb9_50b93aec","line":229,"in_reply_to":"71e58480_01904a2c","updated":"2025-05-07 01:27:54.000000000","message":"Close to the reading of the request, or the accepting of the connection?\n\nPart of me wonders if we need to basically implement the backlog in application code -- have some bounded queue for waiting-to-spawn-handler connections and dramatically reduce the kernel-level backlog...","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":240,"context_line":"            # We don\u0027t want to turn the socket to blocking instead, we\u0027ll"},{"line_number":241,"context_line":"            # just try and get the ancdata for a bit"},{"line_number":242,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":243,"context_line":"                while not ancdata:"},{"line_number":244,"context_line":"                    try:"},{"line_number":245,"context_line":"                        # We don\u0027t want to read any of the data, only the"},{"line_number":246,"context_line":"                        # ancdata"}],"source_content_type":"text/x-python","patch_set":8,"id":"1f379e53_64682996","line":243,"updated":"2025-05-01 19:43:11.000000000","message":"If we can go so fast that we find ourselves with no ancdata, do we need to worry about us going so fast as to get only partial ancdata? Maybe not now, but if we ever start using more sockopts...\n\nI feel like we ought to have this be `while not timestamp` and move the `for data in ancdata:` inside the loop.","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":false,"context_lines":[{"line_number":240,"context_line":"            # We don\u0027t want to turn the socket to blocking instead, we\u0027ll"},{"line_number":241,"context_line":"            # just try and get the ancdata for a bit"},{"line_number":242,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":243,"context_line":"                while not ancdata:"},{"line_number":244,"context_line":"                    try:"},{"line_number":245,"context_line":"                        # We don\u0027t want to read any of the data, only the"},{"line_number":246,"context_line":"                        # ancdata"}],"source_content_type":"text/x-python","patch_set":8,"id":"c7e25126_f51f4dc3","line":243,"in_reply_to":"1f379e53_64682996","updated":"2025-05-02 05:30:59.000000000","message":"yeah fair point, that does seem better from a future proofing POV.\n\nDone","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":245,"context_line":"                        # We don\u0027t want to read any of the data, only the"},{"line_number":246,"context_line":"                        # ancdata"},{"line_number":247,"context_line":"                        _, ancdata, _, _ \u003d self.request.recvmsg("},{"line_number":248,"context_line":"                            0, socket.CMSG_LEN(struct.calcsize(\"iiii\")),"},{"line_number":249,"context_line":"                            socket.MSG_PEEK)"},{"line_number":250,"context_line":"                    except Exception:"},{"line_number":251,"context_line":"                        pass"}],"source_content_type":"text/x-python","patch_set":8,"id":"708ce0ef_1609edfd","line":248,"range":{"start_line":248,"start_character":38,"end_line":248,"end_character":46},"updated":"2025-05-01 19:43:11.000000000","message":"`socket.CMSG_LEN`, or `socket.CMSG_SPACE`? I suppose it comes out the same either way:\n```\n\u003e\u003e\u003e socket.CMSG_LEN(struct.calcsize(\u00274i\u0027))\n32\n\u003e\u003e\u003e socket.CMSG_SPACE(struct.calcsize(\u00274i\u0027))\n32\n```","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":251,"context_line":"                        pass"},{"line_number":252,"context_line":"            for data in ancdata:"},{"line_number":253,"context_line":"                if data[0] \u003d\u003d socket.SOL_SOCKET and \\"},{"line_number":254,"context_line":"                        data[1] \u003d\u003d s_wsgi.SO_TIMESTAMP:"},{"line_number":255,"context_line":"                    # Got the SO_TIMESTAMP data from the kernel"},{"line_number":256,"context_line":"                    ts_data \u003d struct.unpack(\"iiii\", data[2])"},{"line_number":257,"context_line":"                    # ts_data[2] is the exponent part of the float, we could"}],"source_content_type":"text/x-python","patch_set":8,"id":"eb3f8f18_2baaa297","line":254,"updated":"2025-05-01 19:43:11.000000000","message":"Should we be checking for whether we got `TX_SOFTWARE` vs `RX_SOFTWARE`?","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":253,"context_line":"                if data[0] \u003d\u003d socket.SOL_SOCKET and \\"},{"line_number":254,"context_line":"                        data[1] \u003d\u003d s_wsgi.SO_TIMESTAMP:"},{"line_number":255,"context_line":"                    # Got the SO_TIMESTAMP data from the kernel"},{"line_number":256,"context_line":"                    ts_data \u003d struct.unpack(\"iiii\", data[2])"},{"line_number":257,"context_line":"                    # ts_data[2] is the exponent part of the float, we could"},{"line_number":258,"context_line":"                    # probably just loose this bit but does give us better"},{"line_number":259,"context_line":"                    # precision."}],"source_content_type":"text/x-python","patch_set":8,"id":"b14c93ad_bdd2c2d0","line":256,"updated":"2025-05-01 19:43:11.000000000","message":"https://www.man7.org/linux/man-pages/man3/timeval.3type.html sure makes it look like 2 fields, not 4 -- I think we want `qq` (or `QQ`?) instead of `iiii`.","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"4048022ce0088b5611b99cc982dea3544313cacb","unresolved":false,"context_lines":[{"line_number":253,"context_line":"                if data[0] \u003d\u003d socket.SOL_SOCKET and \\"},{"line_number":254,"context_line":"                        data[1] \u003d\u003d s_wsgi.SO_TIMESTAMP:"},{"line_number":255,"context_line":"                    # Got the SO_TIMESTAMP data from the kernel"},{"line_number":256,"context_line":"                    ts_data \u003d struct.unpack(\"iiii\", data[2])"},{"line_number":257,"context_line":"                    # ts_data[2] is the exponent part of the float, we could"},{"line_number":258,"context_line":"                    # probably just loose this bit but does give us better"},{"line_number":259,"context_line":"                    # precision."}],"source_content_type":"text/x-python","patch_set":8,"id":"60d8c6de_698b27e6","line":256,"in_reply_to":"b14c93ad_bdd2c2d0","updated":"2025-05-07 01:27:54.000000000","message":"Done","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":254,"context_line":"                        data[1] \u003d\u003d s_wsgi.SO_TIMESTAMP:"},{"line_number":255,"context_line":"                    # Got the SO_TIMESTAMP data from the kernel"},{"line_number":256,"context_line":"                    ts_data \u003d struct.unpack(\"iiii\", data[2])"},{"line_number":257,"context_line":"                    # ts_data[2] is the exponent part of the float, we could"},{"line_number":258,"context_line":"                    # probably just loose this bit but does give us better"},{"line_number":259,"context_line":"                    # precision."},{"line_number":260,"context_line":"                    timestamp \u003d ts_data[0] + ts_data[2] * 1e-6"}],"source_content_type":"text/x-python","patch_set":8,"id":"e3db2e4b_bd783a1e","line":257,"range":{"start_line":257,"start_character":36,"end_line":257,"end_character":66},"updated":"2025-05-01 19:43:11.000000000","message":"Wait, what? Do I need to brush off my knowledge of how IEEE 754 packs data?\n\nI only saw references saying\n\n\u003e It is an unsigned integer type ...","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"4048022ce0088b5611b99cc982dea3544313cacb","unresolved":false,"context_lines":[{"line_number":254,"context_line":"                        data[1] \u003d\u003d s_wsgi.SO_TIMESTAMP:"},{"line_number":255,"context_line":"                    # Got the SO_TIMESTAMP data from the kernel"},{"line_number":256,"context_line":"                    ts_data \u003d struct.unpack(\"iiii\", data[2])"},{"line_number":257,"context_line":"                    # ts_data[2] is the exponent part of the float, we could"},{"line_number":258,"context_line":"                    # probably just loose this bit but does give us better"},{"line_number":259,"context_line":"                    # precision."},{"line_number":260,"context_line":"                    timestamp \u003d ts_data[0] + ts_data[2] * 1e-6"}],"source_content_type":"text/x-python","patch_set":8,"id":"3e32ad66_f3aa8c34","line":257,"range":{"start_line":257,"start_character":36,"end_line":257,"end_character":66},"in_reply_to":"e3db2e4b_bd783a1e","updated":"2025-05-07 01:27:54.000000000","message":"Done","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"98d47a5a57d51db33b96c45ccae9cf90ca9530a8","unresolved":true,"context_lines":[{"line_number":248,"context_line":"                        _, ancdata, _, _ \u003d self.request.recvmsg("},{"line_number":249,"context_line":"                            0, socket.CMSG_LEN(struct.calcsize(\"qq\")),"},{"line_number":250,"context_line":"                            socket.MSG_PEEK)"},{"line_number":251,"context_line":"                    except Exception:"},{"line_number":252,"context_line":"                        pass"},{"line_number":253,"context_line":"                    for data in ancdata:"},{"line_number":254,"context_line":"                        if data[0] \u003d\u003d socket.SOL_SOCKET and \\"},{"line_number":255,"context_line":"                                data[1] \u003d\u003d s_wsgi.SO_TIMESTAMP:"}],"source_content_type":"text/x-python","patch_set":9,"id":"7c0668b0_0f846a63","line":252,"range":{"start_line":251,"start_character":20,"end_line":252,"end_character":28},"updated":"2025-05-07 23:44:15.000000000","message":"We can be more specific here, yeah? Something like\n```\n                except OSError as e:\n                    if e.errno \u003d\u003d errno.EWOULDBLOCK:\n                        continue\n                    raise\n```\nseems about right -- though part of me wonders if we ought to do a `sleep(0)` before trying again.","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"cb4b0297e0280d62a2d370c876b957119451da0b","unresolved":true,"context_lines":[{"line_number":271,"context_line":"        if self.pre_shutdown_bugfix_eventlet:"},{"line_number":272,"context_line":"            if self.conn_state[2] !\u003d wsgi.STATE_CLOSE:"},{"line_number":273,"context_line":"                self.conn_state[2] \u003d wsgi.STATE_IDLE"},{"line_number":274,"context_line":"        return got"},{"line_number":275,"context_line":""},{"line_number":276,"context_line":"    def send_error(self, code, message\u003dNone, explain\u003dNone):"},{"line_number":277,"context_line":"        \"\"\"Send and log an error reply, we are overriding the cpython parent"}],"source_content_type":"text/x-python","patch_set":9,"id":"af2fb559_00e6d9f1","line":274,"updated":"2025-05-02 21:22:30.000000000","message":"Adding\n```\n        # socket timestamp isn\u0027t terribly useful for pipelined requests\n        self.socket_timestamp \u003d None\n```\nhere definitely helped me make sense of my logs. I debated about going for `time.time()` instead, but decided that if we wanted to track time between pipelined requests, we ought to do it as a separate field since a spike in either would likely indicate rather different things.","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"13f4926b99416eac6ead81901ba92139c1dfc5d3","unresolved":true,"context_lines":[{"line_number":255,"context_line":"                                data[1] in (s_wsgi.SO_TIMESTAMPING_NEW,"},{"line_number":256,"context_line":"                                            s_wsgi.SO_TIMESTAMPING_OLD):"},{"line_number":257,"context_line":"                            # Got the SO_TIMESTAMPING data from the kernel"},{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"}],"source_content_type":"text/x-python","patch_set":10,"id":"cad1d865_50aa33e9","line":258,"updated":"2025-05-08 15:52:12.000000000","message":"Looking at [kernel source](https://github.com/torvalds/linux/blob/d76bb1ebb5587f66b0f8b8099bfbb44722bc08b3/net/socket.c#L903-L932) it seems `ts_data[0]` and `ts_data[1]` are the software timestamps and `ts_data[4]` and `ts_data[5]` are the hardware ones -- I wonder what `ts_data[2]` and `ts_data[3]` are supposed to mean...","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"25e48574e995594b87e71739293d985e82ac8abe","unresolved":true,"context_lines":[{"line_number":255,"context_line":"                                data[1] in (s_wsgi.SO_TIMESTAMPING_NEW,"},{"line_number":256,"context_line":"                                            s_wsgi.SO_TIMESTAMPING_OLD):"},{"line_number":257,"context_line":"                            # Got the SO_TIMESTAMPING data from the kernel"},{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"}],"source_content_type":"text/x-python","patch_set":10,"id":"d465f4c1_8510df4e","line":258,"in_reply_to":"cad1d865_50aa33e9","updated":"2025-05-13 02:05:01.000000000","message":"Oh great find.. interesting. I guess we also need to include `SOF_TIMESTAMPING_RAW_HARDWARE` to activate that behaviour.\n\nLooking at more source, here is the enum:\n\n```\n/* SO_TIMESTAMPING flags */                                                                                                     \nenum {                                                                                                                          \n»···SOF_TIMESTAMPING_TX_HARDWARE \u003d (1\u003c\u003c0),                                                                                      \n»···SOF_TIMESTAMPING_TX_SOFTWARE \u003d (1\u003c\u003c1),                                                                                      \n»···SOF_TIMESTAMPING_RX_HARDWARE \u003d (1\u003c\u003c2),                                                                                      \n»···SOF_TIMESTAMPING_RX_SOFTWARE \u003d (1\u003c\u003c3),                                                                                      \n»···SOF_TIMESTAMPING_SOFTWARE \u003d (1\u003c\u003c4),                                                                                         \n»···SOF_TIMESTAMPING_SYS_HARDWARE \u003d (1\u003c\u003c5),                                                                                     \n»···SOF_TIMESTAMPING_RAW_HARDWARE \u003d (1\u003c\u003c6),                                                                                     \n»···SOF_TIMESTAMPING_OPT_ID \u003d (1\u003c\u003c7),                                                                                           \n»···SOF_TIMESTAMPING_TX_SCHED \u003d (1\u003c\u003c8),                                                                                         \n»···SOF_TIMESTAMPING_TX_ACK \u003d (1\u003c\u003c9),                                                                                           \n»···SOF_TIMESTAMPING_OPT_CMSG \u003d (1\u003c\u003c10),                                                                                        \n»···SOF_TIMESTAMPING_OPT_TSONLY \u003d (1\u003c\u003c11),                                                                                      \n»···SOF_TIMESTAMPING_OPT_STATS \u003d (1\u003c\u003c12),                                                                                       \n»···SOF_TIMESTAMPING_OPT_PKTINFO \u003d (1\u003c\u003c13),                                                                                     \n»···SOF_TIMESTAMPING_OPT_TX_SWHW \u003d (1\u003c\u003c14),                                                                                     \n»···SOF_TIMESTAMPING_BIND_PHC \u003d (1 \u003c\u003c 15),                                                                                      \n»···SOF_TIMESTAMPING_OPT_ID_TCP \u003d (1 \u003c\u003c 16),                                                                                    \n»···SOF_TIMESTAMPING_OPT_RX_FILTER \u003d (1 \u003c\u003c 17),                                                                                 \n»···SOF_TIMESTAMPING_TX_COMPLETION \u003d (1 \u003c\u003c 18),                                                                                 \n                                                                                                                                \n»···SOF_TIMESTAMPING_LAST \u003d SOF_TIMESTAMPING_TX_COMPLETION,                                                                     \n»···SOF_TIMESTAMPING_MASK \u003d (SOF_TIMESTAMPING_LAST - 1) |                                                                       \n»···»···»···»··· SOF_TIMESTAMPING_LAST                                                                                          \n};\n```\n\nMaybe SOF_TIMESTAMPING_SOFTWARE is the first, SOF_TIMESTAMPING_SYS_HARDWARE is the second and SOF_TIMESTAMPING_RAW_HARDWARE is the third? And what do we want to prioritise?\n\nFrom timestamping.txt:\n\n```\n1.3.2 Timestamp Reporting\n\nThe other three bits control which timestamps will be reported in a\ngenerated control message. Changes to the bits take immediate\neffect at the timestamp reporting locations in the stack. Timestamps\nare only reported for packets that also have the relevant timestamp\ngeneration request set.\n\nSOF_TIMESTAMPING_SOFTWARE:\n  Report any software timestamps when available.\n\nSOF_TIMESTAMPING_SYS_HARDWARE:\n  This option is deprecated and ignored.\n\nSOF_TIMESTAMPING_RAW_HARDWARE:\n  Report hardware timestamps as generated by\n  SOF_TIMESTAMPING_TX_HARDWARE when available.\n```\n\nFrom that we can ignore SOF_TIMESTAMPING_SYS_HARDWARE, and SOF_TIMESTAMPING_RAW_HARDWARE it sounds like it might only be for TX? or is it saying it uses the same timestamp generator as used for TX?","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"4a8a5279eaf0216aa5b3f45b80cdfbe9323c7b23","unresolved":true,"context_lines":[{"line_number":255,"context_line":"                                data[1] in (s_wsgi.SO_TIMESTAMPING_NEW,"},{"line_number":256,"context_line":"                                            s_wsgi.SO_TIMESTAMPING_OLD):"},{"line_number":257,"context_line":"                            # Got the SO_TIMESTAMPING data from the kernel"},{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"}],"source_content_type":"text/x-python","patch_set":10,"id":"6d88f4ae_6a250cba","line":258,"in_reply_to":"d465f4c1_8510df4e","updated":"2025-05-13 17:48:31.000000000","message":"¯\\\\\\_(ツ)\\_/¯","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"13f4926b99416eac6ead81901ba92139c1dfc5d3","unresolved":true,"context_lines":[{"line_number":256,"context_line":"                                            s_wsgi.SO_TIMESTAMPING_OLD):"},{"line_number":257,"context_line":"                            # Got the SO_TIMESTAMPING data from the kernel"},{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"},{"line_number":262,"context_line":"                            break"}],"source_content_type":"text/x-python","patch_set":10,"id":"308460bd_75a594d7","line":259,"range":{"start_line":259,"start_character":38,"end_line":259,"end_character":39},"updated":"2025-05-08 15:52:12.000000000","message":"1","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"25e48574e995594b87e71739293d985e82ac8abe","unresolved":false,"context_lines":[{"line_number":256,"context_line":"                                            s_wsgi.SO_TIMESTAMPING_OLD):"},{"line_number":257,"context_line":"                            # Got the SO_TIMESTAMPING data from the kernel"},{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"},{"line_number":262,"context_line":"                            break"}],"source_content_type":"text/x-python","patch_set":10,"id":"1ef91d4f_19d77dfb","line":259,"range":{"start_line":259,"start_character":38,"end_line":259,"end_character":39},"in_reply_to":"308460bd_75a594d7","updated":"2025-05-13 02:05:01.000000000","message":"Done","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"13f4926b99416eac6ead81901ba92139c1dfc5d3","unresolved":true,"context_lines":[{"line_number":257,"context_line":"                            # Got the SO_TIMESTAMPING data from the kernel"},{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"},{"line_number":262,"context_line":"                            break"},{"line_number":263,"context_line":"        except (Exception, Timeout):"}],"source_content_type":"text/x-python","patch_set":10,"id":"a01f2b41_214a253f","line":260,"range":{"start_line":260,"start_character":30,"end_line":260,"end_character":42},"updated":"2025-05-08 15:52:12.000000000","message":"nanoseconds","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"25e48574e995594b87e71739293d985e82ac8abe","unresolved":false,"context_lines":[{"line_number":257,"context_line":"                            # Got the SO_TIMESTAMPING data from the kernel"},{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"},{"line_number":262,"context_line":"                            break"},{"line_number":263,"context_line":"        except (Exception, Timeout):"}],"source_content_type":"text/x-python","patch_set":10,"id":"9057564a_2be6ceed","line":260,"range":{"start_line":260,"start_character":30,"end_line":260,"end_character":42},"in_reply_to":"a01f2b41_214a253f","updated":"2025-05-13 02:05:01.000000000","message":"Done","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"13f4926b99416eac6ead81901ba92139c1dfc5d3","unresolved":true,"context_lines":[{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"},{"line_number":262,"context_line":"                            break"},{"line_number":263,"context_line":"        except (Exception, Timeout):"},{"line_number":264,"context_line":"            # If we fail to grab the ancillary data, then let\u0027s not block the"}],"source_content_type":"text/x-python","patch_set":10,"id":"7f6a58ec_54f0b6b0","line":261,"updated":"2025-05-08 15:52:12.000000000","message":"We want this closer to the last patchset, but for nanoseconds instead of microseconds:\n```\ntimestamp \u003d ts_data[0] + ts_data[1] * 1e-9\n```\nAlternatively, we could zero-pad with something like\n```\ntimestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]:09}\u0027)\n```\nbut the `int`s -\u003e `str` -\u003e `float` conversion seems silly when we could just go `int`s -\u003e `float`","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"25e48574e995594b87e71739293d985e82ac8abe","unresolved":false,"context_lines":[{"line_number":258,"context_line":"                            ts_data \u003d struct.unpack(\"QQQQQQ\", data[2])"},{"line_number":259,"context_line":"                            # ts_data[2] is the decimal component float, or"},{"line_number":260,"context_line":"                            # microseconds of the time."},{"line_number":261,"context_line":"                            timestamp \u003d float(f\u0027{ts_data[0]}.{ts_data[1]}\u0027)"},{"line_number":262,"context_line":"                            break"},{"line_number":263,"context_line":"        except (Exception, Timeout):"},{"line_number":264,"context_line":"            # If we fail to grab the ancillary data, then let\u0027s not block the"}],"source_content_type":"text/x-python","patch_set":10,"id":"75067662_1e3f6fde","line":261,"in_reply_to":"7f6a58ec_54f0b6b0","updated":"2025-05-13 02:05:01.000000000","message":"yeah cool. I guess it\u0027s the number of nanoseconds so yeah makes more sense. Don\u0027t know what I was on to change it :P","commit_id":"6d296d925d9b6d7b4530ba6f76c0d62b393478cc"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"5b4854995a33b9a39d4e1d9765941ae1e205330b","unresolved":true,"context_lines":[{"line_number":241,"context_line":"            # We don\u0027t want to turn the socket to blocking instead, we\u0027ll"},{"line_number":242,"context_line":"            # just try and get the ancdata for a bit"},{"line_number":243,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":244,"context_line":"                while not timestamp:"},{"line_number":245,"context_line":"                    try:"},{"line_number":246,"context_line":"                        # We don\u0027t want to read any of the data, only the"},{"line_number":247,"context_line":"                        # ancdata"}],"source_content_type":"text/x-python","patch_set":11,"id":"a40ea396_d86da048","line":244,"updated":"2025-05-12 20:21:34.000000000","message":"If we *don\u0027t* have a sleep in this loop, the timeout might not be able to pop -- I think that\u0027s what\u0027s happening in CI to cause the hang. I can repro locally; `test/unit/common/middleware/crypto/test_encryption.py::TestCryptoPipelineChanges::test_copy_encrypted_to_encrypted` spins here with a stack like\n```\n  File \"/home/tburke/py3/lib/python3.12/site-packages/eventlet/greenthread.py\", line 265, in main\n    result \u003d function(*args, **kwargs)\n  File \"/home/tburke/py3/lib/python3.12/site-packages/eventlet/wsgi.py\", line 905, in process_request\n    proto.__init__(conn_state, self)\n  File \"/home/tburke/code/swift/swift/common/http_protocol.py\", line 37, in __init__\n    super().__init__(*args, **kwargs)\n  File \"/home/tburke/py3/lib/python3.12/site-packages/eventlet/wsgi.py\", line 356, in __init__\n    self.setup()\n  File \"/home/tburke/code/swift/swift/common/http_protocol.py\", line 230, in setup\n    self.socket_timestamp \u003d self._try_grab_so_timestamp()\n  File \"/home/tburke/code/swift/swift/common/http_protocol.py\", line 248, in _try_grab_so_timestamp\n    _, ancdata, _, _ \u003d self.request.recvmsg(\n  File \"\u003cstring\u003e\", line 1, in \u003cmodule\u003e\n  File \"\u003cstring\u003e\", line 85, in \u003cmodule\u003e\n```\n---\nApplying this seems better:\n```\ndiff --git a/swift/common/http_protocol.py b/swift/common/http_protocol.py\nindex 037aa528c..044a1d59b 100644\n--- a/swift/common/http_protocol.py\n+++ b/swift/common/http_protocol.py\n@@ -15,7 +15,7 @@\n \n import socket\n import struct\n-from eventlet import wsgi, websocket, Timeout\n+from eventlet import wsgi, websocket, Timeout, sleep\n \n from swift.common.utils import generate_trans_id\n from swift.common.http import HTTP_NO_CONTENT, HTTP_RESET_CONTENT, \\\n@@ -263,6 +263,7 @@ class SwiftHttpProtocol(wsgi.HttpProtocol):\n                                 secs, nano \u003d ts_data[4:]\n                             timestamp \u003d secs + nano * 1e-9\n                             break\n+                    sleep(0)\n         except (Exception, Timeout):\n             # If we fail to grab the ancillary data, then let\u0027s not block the\n             # request.\n```","commit_id":"0af4128a418ad56b8db74ce6566409f5e215be08"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"4a8a5279eaf0216aa5b3f45b80cdfbe9323c7b23","unresolved":true,"context_lines":[{"line_number":241,"context_line":"            # We don\u0027t want to turn the socket to blocking instead, we\u0027ll"},{"line_number":242,"context_line":"            # just try and get the ancdata for a bit"},{"line_number":243,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":244,"context_line":"                while not timestamp:"},{"line_number":245,"context_line":"                    try:"},{"line_number":246,"context_line":"                        # We don\u0027t want to read any of the data, only the"},{"line_number":247,"context_line":"                        # ancdata"}],"source_content_type":"text/x-python","patch_set":11,"id":"51e214c7_e8944055","line":244,"in_reply_to":"8ad01f70_009abdb4","updated":"2025-05-13 17:48:31.000000000","message":"Even better -- I was thinking the `break` was for the `while not timestamp` rather than looping through ancdata.","commit_id":"0af4128a418ad56b8db74ce6566409f5e215be08"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bb8cadd602bebfbff77d8463584a7ecd495c2ebf","unresolved":true,"context_lines":[{"line_number":241,"context_line":"            # We don\u0027t want to turn the socket to blocking instead, we\u0027ll"},{"line_number":242,"context_line":"            # just try and get the ancdata for a bit"},{"line_number":243,"context_line":"            with Timeout(self.ancdata_wait):"},{"line_number":244,"context_line":"                while not timestamp:"},{"line_number":245,"context_line":"                    try:"},{"line_number":246,"context_line":"                        # We don\u0027t want to read any of the data, only the"},{"line_number":247,"context_line":"                        # ancdata"}],"source_content_type":"text/x-python","patch_set":11,"id":"8ad01f70_009abdb4","line":244,"in_reply_to":"a40ea396_d86da048","updated":"2025-05-13 06:10:27.000000000","message":"oh nice, thanks!\n\nOK so let it check all the possible ancillary data beofre we sleep(0) to let the timeout have a chance of triggering... Although if it got something, the timeout will blat it out.. so I wonder if it makes sense a little further up?\n\nSo we give timeout a chance, but try for ancillary data and return it if we get the chance:\n\n```\ndiff --git a/swift/common/http_protocol.py b/swift/common/http_protocol.py\nindex 037aa528c..438ee6ab1 100644\n--- a/swift/common/http_protocol.py\n+++ b/swift/common/http_protocol.py\n@@ -15,7 +15,7 @@\n \n import socket\n import struct\n-from eventlet import wsgi, websocket, Timeout\n+from eventlet import wsgi, websocket, Timeout, sleep\n \n from swift.common.utils import generate_trans_id\n from swift.common.http import HTTP_NO_CONTENT, HTTP_RESET_CONTENT, \\\n@@ -242,6 +242,7 @@ class SwiftHttpProtocol(wsgi.HttpProtocol):\n             # just try and get the ancdata for a bit\n             with Timeout(self.ancdata_wait):\n                 while not timestamp:\n+                    sleep(0)\n                     try:\n                         # We don\u0027t want to read any of the data, only the\n                         # ancdata\n```","commit_id":"0af4128a418ad56b8db74ce6566409f5e215be08"}],"swift/common/middleware/gatekeeper.py":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e2bca88b73e3508961c3420260799d8fa556018","unresolved":true,"context_lines":[{"line_number":81,"context_line":"    def __call__(self, env, start_response):"},{"line_number":82,"context_line":"        req \u003d Request(env)"},{"line_number":83,"context_line":"        if env.get(\u0027socket_timestamp\u0027):"},{"line_number":84,"context_line":"            print(f\"\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d SOCKET_TIMESTAMP {env.get(\u0027socket_timestamp\u0027)} \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\")"},{"line_number":85,"context_line":"        removed \u003d remove_items(req.headers, self.inbound_condition)"},{"line_number":86,"context_line":"        if removed:"},{"line_number":87,"context_line":"            self.logger.debug(\u0027removed request headers: %s\u0027 % removed)"}],"source_content_type":"text/x-python","patch_set":2,"id":"adbc8032_c88b61e9","line":84,"updated":"2025-03-13 03:01:12.000000000","message":"This also wont be in the final, just here so we can see it working.","commit_id":"4bdb7b997c36c5c6cf173cd1106149b3e709e230"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":false,"context_lines":[{"line_number":81,"context_line":"    def __call__(self, env, start_response):"},{"line_number":82,"context_line":"        req \u003d Request(env)"},{"line_number":83,"context_line":"        if env.get(\u0027socket_timestamp\u0027):"},{"line_number":84,"context_line":"            print(f\"\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d SOCKET_TIMESTAMP {env.get(\u0027socket_timestamp\u0027)} \u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\u003d\")"},{"line_number":85,"context_line":"        removed \u003d remove_items(req.headers, self.inbound_condition)"},{"line_number":86,"context_line":"        if removed:"},{"line_number":87,"context_line":"            self.logger.debug(\u0027removed request headers: %s\u0027 % removed)"}],"source_content_type":"text/x-python","patch_set":2,"id":"30774b4a_073f5148","line":84,"in_reply_to":"adbc8032_c88b61e9","updated":"2025-03-13 23:24:49.000000000","message":"Acknowledged","commit_id":"4bdb7b997c36c5c6cf173cd1106149b3e709e230"},{"author":{"_account_id":1179,"name":"Clay Gerrard","email":"clay.gerrard@gmail.com","username":"clay-gerrard"},"change_message_id":"c69249d2b7867a616d1251015984f8d773a852b4","unresolved":true,"context_lines":[{"line_number":85,"context_line":"            accept_queue_delta \u003d time.time() - env[\u0027socket_timestamp\u0027]"},{"line_number":86,"context_line":"            self.logger.debug(\u0027Accept queue wait: %f\u0027 % accept_queue_delta)"},{"line_number":87,"context_line":"            if accept_queue_delta \u003e self._pipeline_final_app.client_timeout:"},{"line_number":88,"context_line":"                self.logger.increment(\u0027accept_queue.client_timeouts\u0027)"},{"line_number":89,"context_line":"        removed \u003d remove_items(req.headers, self.inbound_condition)"},{"line_number":90,"context_line":"        if removed:"},{"line_number":91,"context_line":"            self.logger.debug(\u0027removed request headers: %s\u0027 % removed)"}],"source_content_type":"text/x-python","patch_set":4,"id":"f0893505_21590c51","line":88,"updated":"2025-03-13 17:02:10.000000000","message":"maybe a little weird name since we\u0027re not really doing a timeout here, but I see what you\u0027re going for.","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"5e9d870dc9b206fe543d173de56482c379c14428","unresolved":true,"context_lines":[{"line_number":85,"context_line":"            accept_queue_delta \u003d time.time() - env[\u0027socket_timestamp\u0027]"},{"line_number":86,"context_line":"            self.logger.debug(\u0027Accept queue wait: %f\u0027 % accept_queue_delta)"},{"line_number":87,"context_line":"            if accept_queue_delta \u003e self._pipeline_final_app.client_timeout:"},{"line_number":88,"context_line":"                self.logger.increment(\u0027accept_queue.client_timeouts\u0027)"},{"line_number":89,"context_line":"        removed \u003d remove_items(req.headers, self.inbound_condition)"},{"line_number":90,"context_line":"        if removed:"},{"line_number":91,"context_line":"            self.logger.debug(\u0027removed request headers: %s\u0027 % removed)"}],"source_content_type":"text/x-python","patch_set":4,"id":"f4b01f22_9df9184e","line":88,"in_reply_to":"f0893505_21590c51","updated":"2025-03-13 23:24:49.000000000","message":"Yeah, I was using gatekeeper as a place to verify that the socket_timestamp was in the env, as it was the closest to it.\n\nBut we could move this anywhere. Returning a timeout here is probably wrong because we probably want to make sure we log it, so needs to get at least to the first proxy_logging middleware :shrug:","commit_id":"0d11f20ce289f6ceb7bc984e7c62648232499f1b"}],"swift/common/middleware/proxy_logging.py":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"b0ddbedf1d099f468aa4704d5feda1a214790bb3","unresolved":true,"context_lines":[{"line_number":24,"context_line":"    client_ip remote_addr end_time.datetime method path protocol"},{"line_number":25,"context_line":"        status_int referer user_agent auth_token bytes_recvd bytes_sent"},{"line_number":26,"context_line":"        client_etag transaction_id headers request_time source log_info"},{"line_number":27,"context_line":"        start_time end_time policy_index connection_start"},{"line_number":28,"context_line":""},{"line_number":29,"context_line":"These values are space-separated, and each is url-encoded, so that they can"},{"line_number":30,"context_line":"be separated with a simple ``.split()``."}],"source_content_type":"text/x-python","patch_set":5,"id":"890b85e4_c0b6e0f4","line":27,"updated":"2025-03-14 05:31:41.000000000","message":"Didn\u0027t add queue_delta here.","commit_id":"1c0c876b59e97495b45e83619f2350df032ea698"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"b0ddbedf1d099f468aa4704d5feda1a214790bb3","unresolved":true,"context_lines":[{"line_number":127,"context_line":"                \u0027{auth_token} {bytes_recvd} {bytes_sent} {client_etag} \u0027"},{"line_number":128,"context_line":"                \u0027{transaction_id} {headers} {request_time} {source} \u0027"},{"line_number":129,"context_line":"                \u0027{log_info} {start_time} {end_time} {policy_index} \u0027"},{"line_number":130,"context_line":"                \u0027{connection_start} {queue_delta}\u0027))"},{"line_number":131,"context_line":"        # The salt is only used in StrAnonymizer. This class requires bytes,"},{"line_number":132,"context_line":"        # convert it now to prevent useless convertion later."},{"line_number":133,"context_line":"        self.anonymization_method \u003d conf.get(\u0027log_anonymization_method\u0027, \u0027md5\u0027)"}],"source_content_type":"text/x-python","patch_set":5,"id":"ce5b7680_06ae2825","line":130,"range":{"start_line":130,"start_character":17,"end_line":130,"end_character":49},"updated":"2025-03-14 05:31:41.000000000","message":"Not sure if these should be in the default set. But easier for testing in my saio","commit_id":"1c0c876b59e97495b45e83619f2350df032ea698"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":289,"context_line":"        acc, cont, obj \u003d self.get_aco_from_path(swift_path)"},{"line_number":290,"context_line":"        connection_start \u003d self.connection_start_from_req(req)"},{"line_number":291,"context_line":"        queue_delta \u003d \u0027-\u0027"},{"line_number":292,"context_line":"        if connection_start and start_time:"},{"line_number":293,"context_line":"            queue_delta \u003d \"%.9f\" % (start_time - connection_start)"},{"line_number":294,"context_line":""},{"line_number":295,"context_line":"        replacements \u003d {"}],"source_content_type":"text/x-python","patch_set":8,"id":"d08947f2_828359f3","line":292,"range":{"start_line":292,"start_character":28,"end_line":292,"end_character":42},"updated":"2025-05-01 19:43:11.000000000","message":"When would we not have a `start_time`?","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":false,"context_lines":[{"line_number":289,"context_line":"        acc, cont, obj \u003d self.get_aco_from_path(swift_path)"},{"line_number":290,"context_line":"        connection_start \u003d self.connection_start_from_req(req)"},{"line_number":291,"context_line":"        queue_delta \u003d \u0027-\u0027"},{"line_number":292,"context_line":"        if connection_start and start_time:"},{"line_number":293,"context_line":"            queue_delta \u003d \"%.9f\" % (start_time - connection_start)"},{"line_number":294,"context_line":""},{"line_number":295,"context_line":"        replacements \u003d {"}],"source_content_type":"text/x-python","patch_set":8,"id":"5ac87618_360955b0","line":292,"range":{"start_line":292,"start_character":28,"end_line":292,"end_character":42},"in_reply_to":"d08947f2_828359f3","updated":"2025-05-02 05:30:59.000000000","message":"Done","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":341,"context_line":"            \u0027ttfb\u0027: ttfb,"},{"line_number":342,"context_line":"            \u0027pid\u0027: self.pid,"},{"line_number":343,"context_line":"            \u0027wire_status_int\u0027: wire_status_int or status_int,"},{"line_number":344,"context_line":"            \u0027queue_delta\u0027: queue_delta,"},{"line_number":345,"context_line":"        }"},{"line_number":346,"context_line":"        self.access_logger.info("},{"line_number":347,"context_line":"            self.log_formatter.format(self.log_msg_template,"}],"source_content_type":"text/x-python","patch_set":8,"id":"c43112a2_b363646e","line":344,"range":{"start_line":344,"start_character":13,"end_line":344,"end_character":24},"updated":"2025-05-01 19:43:11.000000000","message":"Might be better as `queue_time` in keeping with `request_time`","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":false,"context_lines":[{"line_number":341,"context_line":"            \u0027ttfb\u0027: ttfb,"},{"line_number":342,"context_line":"            \u0027pid\u0027: self.pid,"},{"line_number":343,"context_line":"            \u0027wire_status_int\u0027: wire_status_int or status_int,"},{"line_number":344,"context_line":"            \u0027queue_delta\u0027: queue_delta,"},{"line_number":345,"context_line":"        }"},{"line_number":346,"context_line":"        self.access_logger.info("},{"line_number":347,"context_line":"            self.log_formatter.format(self.log_msg_template,"}],"source_content_type":"text/x-python","patch_set":8,"id":"35c496f1_31d7efbf","line":344,"range":{"start_line":344,"start_character":13,"end_line":344,"end_character":24},"in_reply_to":"c43112a2_b363646e","updated":"2025-05-02 05:30:59.000000000","message":"Done","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":418,"context_line":"        start_response_args \u003d [None]"},{"line_number":419,"context_line":"        input_proxy \u003d InputProxy(env[\u0027wsgi.input\u0027])"},{"line_number":420,"context_line":"        env[\u0027wsgi.input\u0027] \u003d input_proxy"},{"line_number":421,"context_line":"        start_time \u003d time.time()"},{"line_number":422,"context_line":""},{"line_number":423,"context_line":"        def my_start_response(status, headers, exc_info\u003dNone):"},{"line_number":424,"context_line":"            start_response_args[0] \u003d (status, list(headers), exc_info)"}],"source_content_type":"text/x-python","patch_set":8,"id":"63e60e5a_a94e18d8","line":421,"updated":"2025-05-01 19:43:11.000000000","message":"I\u0027m starting to wonder if this should get recorded in the environment in `http_protocol`, too... though it\u0027d get funky with subrequests...","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"cb4b0297e0280d62a2d370c876b957119451da0b","unresolved":true,"context_lines":[{"line_number":296,"context_line":"            # Time information"},{"line_number":297,"context_line":"            \u0027end_time\u0027: StrFormatTime(end_time),"},{"line_number":298,"context_line":"            \u0027start_time\u0027: StrFormatTime(start_time),"},{"line_number":299,"context_line":"            \u0027connection_start\u0027: StrFormatTime(connection_start),"},{"line_number":300,"context_line":"            # Information worth to anonymize"},{"line_number":301,"context_line":"            \u0027client_ip\u0027: StrAnonymizer(get_remote_client(req),"},{"line_number":302,"context_line":"                                       self.anonymization_method,"}],"source_content_type":"text/x-python","patch_set":9,"id":"ea1e7beb_4d78bceb","line":299,"updated":"2025-05-02 21:22:30.000000000","message":"Should this be `StrFormatTime(connection_start or start_time)`? Once I started dropping `SwiftHttpProtocol.socket_timestamp` after handling a request, I was surprised to see this field coming out as `0`.\n\nAlternatively, maybe we drop the zero-default from `connection_start_from_req` and update `StrFormatTime` to return `\"-\"` in basically all cases when `self.time is None`...","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"}],"swift/common/utils/logs.py":[{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":52,"context_line":"                          \u0027\"{referer}\" \"{txn_id}\" \"{user_agent}\" \u0027 \\"},{"line_number":53,"context_line":"                          \u0027{trans_time:.4f} \"{additional_info}\" {pid} \u0027 \\"},{"line_number":54,"context_line":"                          \u0027{policy_index} {connection_start:.4f} \u0027\\"},{"line_number":55,"context_line":"                          \u0027{queue_delta}\u0027"},{"line_number":56,"context_line":""},{"line_number":57,"context_line":""},{"line_number":58,"context_line":"def logging_monkey_patch():"}],"source_content_type":"text/x-python","patch_set":8,"id":"b2e60d8c_2b18e135","line":55,"range":{"start_line":55,"start_character":28,"end_line":55,"end_character":39},"updated":"2025-05-01 19:43:11.000000000","message":"Might be better as `queue_time`, in keeping with `trans_time`.\n\nWhy do we throw in `connection_start`, too? Shouldn\u0027t we be able to determine that from `time - trans_time - queue_delta`? Eh, I suppose we do that and more in proxy-logging...","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":true,"context_lines":[{"line_number":52,"context_line":"                          \u0027\"{referer}\" \"{txn_id}\" \"{user_agent}\" \u0027 \\"},{"line_number":53,"context_line":"                          \u0027{trans_time:.4f} \"{additional_info}\" {pid} \u0027 \\"},{"line_number":54,"context_line":"                          \u0027{policy_index} {connection_start:.4f} \u0027\\"},{"line_number":55,"context_line":"                          \u0027{queue_delta}\u0027"},{"line_number":56,"context_line":""},{"line_number":57,"context_line":""},{"line_number":58,"context_line":"def logging_monkey_patch():"}],"source_content_type":"text/x-python","patch_set":8,"id":"22a3d7c7_ed747dde","line":55,"range":{"start_line":55,"start_character":28,"end_line":55,"end_character":39},"in_reply_to":"b2e60d8c_2b18e135","updated":"2025-05-02 05:30:59.000000000","message":"yeah, maybe making these all defaults might be wrong :shrug:","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"}],"swift/common/wsgi.py":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"f4213970bb0ee458fd96d81d0f17c40372420fd9","unresolved":true,"context_lines":[{"line_number":433,"context_line":"                  allow_modify_pipeline\u003dallow_modify_pipeline)"},{"line_number":434,"context_line":"    max_clients \u003d int(conf.get(\u0027max_clients\u0027, \u00271024\u0027))"},{"line_number":435,"context_line":"    pool \u003d RestrictedGreenPool(size\u003dmax_clients)"},{"line_number":436,"context_line":"    ancdata_wait \u003d float(conf.get(\u0027ancdata_wait\u0027, \u00270.1\u0027))"},{"line_number":437,"context_line":""},{"line_number":438,"context_line":"    # Select which protocol class to use (normal or one expecting PROXY"},{"line_number":439,"context_line":"    # protocol)"}],"source_content_type":"text/x-python","patch_set":7,"id":"6bc8a26e_353c9344","line":436,"range":{"start_line":436,"start_character":51,"end_line":436,"end_character":54},"updated":"2025-04-07 16:24:36.000000000","message":"opps this should probably be changed to 0.01 too","commit_id":"13b99c6f99b74db3a5dfb9b5f77be0cc1e83347a"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"201bb5b71501d02e68b9f5c72350d7af29f871e1","unresolved":false,"context_lines":[{"line_number":433,"context_line":"                  allow_modify_pipeline\u003dallow_modify_pipeline)"},{"line_number":434,"context_line":"    max_clients \u003d int(conf.get(\u0027max_clients\u0027, \u00271024\u0027))"},{"line_number":435,"context_line":"    pool \u003d RestrictedGreenPool(size\u003dmax_clients)"},{"line_number":436,"context_line":"    ancdata_wait \u003d float(conf.get(\u0027ancdata_wait\u0027, \u00270.1\u0027))"},{"line_number":437,"context_line":""},{"line_number":438,"context_line":"    # Select which protocol class to use (normal or one expecting PROXY"},{"line_number":439,"context_line":"    # protocol)"}],"source_content_type":"text/x-python","patch_set":7,"id":"cfbf4bfe_efcd41af","line":436,"range":{"start_line":436,"start_character":51,"end_line":436,"end_character":54},"in_reply_to":"6bc8a26e_353c9344","updated":"2025-04-08 13:04:23.000000000","message":"Done","commit_id":"13b99c6f99b74db3a5dfb9b5f77be0cc1e83347a"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"beb4c42d0b413f600cea661df5238e2483a46585","unresolved":true,"context_lines":[{"line_number":215,"context_line":"    #   TX_SOFTWARE 2"},{"line_number":216,"context_line":"    #   RX_HARDWARE 4"},{"line_number":217,"context_line":"    #   RX_SOFTWARE 8"},{"line_number":218,"context_line":"    sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMP, 10)"},{"line_number":219,"context_line":"    if hasattr(socket, \u0027TCP_KEEPIDLE\u0027):"},{"line_number":220,"context_line":"        sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPIDLE, keepidle)"},{"line_number":221,"context_line":"    if warn_ssl:"}],"source_content_type":"text/x-python","patch_set":8,"id":"a97aee76_7afb951a","line":218,"updated":"2025-05-01 19:43:11.000000000","message":"Why tx? Why not hardware? I wonder how much delta we might see between `RX_HARDWARE` and `RX_SOFTWARE`...","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"00eec2fd2fc590bed119b242ea644cbe557bce88","unresolved":true,"context_lines":[{"line_number":215,"context_line":"    #   TX_SOFTWARE 2"},{"line_number":216,"context_line":"    #   RX_HARDWARE 4"},{"line_number":217,"context_line":"    #   RX_SOFTWARE 8"},{"line_number":218,"context_line":"    sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMP, 10)"},{"line_number":219,"context_line":"    if hasattr(socket, \u0027TCP_KEEPIDLE\u0027):"},{"line_number":220,"context_line":"        sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPIDLE, keepidle)"},{"line_number":221,"context_line":"    if warn_ssl:"}],"source_content_type":"text/x-python","patch_set":8,"id":"1419a33e_1d4b2cea","line":218,"in_reply_to":"2641e2b7_c17e5248","updated":"2025-05-07 10:02:21.000000000","message":"Yeah, maybe. Rereading maybe SO_TIMESTAMPING is what I meant when defining differnt timestamps... Man how\u0027d I mix that up :facepalm:\n\nAlso:\n```\nSO_TIMESTAMP\nGenerates a timestamp for each incoming packet...\n```\n\nSo maybe this is why we can get a later timestamp?\n\nI\u0027ll try and use SO_TIMESTAMPING, as there is mention that on byte streams and using software TX it\u0027ll only use one timestamp.. and I hope/wonder if it\u0027s the same for software RX?","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"c7650eae58d60c7248f590040e451b4ede1bb77d","unresolved":true,"context_lines":[{"line_number":215,"context_line":"    #   TX_SOFTWARE 2"},{"line_number":216,"context_line":"    #   RX_HARDWARE 4"},{"line_number":217,"context_line":"    #   RX_SOFTWARE 8"},{"line_number":218,"context_line":"    sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMP, 10)"},{"line_number":219,"context_line":"    if hasattr(socket, \u0027TCP_KEEPIDLE\u0027):"},{"line_number":220,"context_line":"        sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPIDLE, keepidle)"},{"line_number":221,"context_line":"    if warn_ssl:"}],"source_content_type":"text/x-python","patch_set":8,"id":"2641e2b7_c17e5248","line":218,"in_reply_to":"7a4184d7_41e6c7b2","updated":"2025-05-06 23:18:16.000000000","message":"Reading https://www.kernel.org/doc/Documentation/networking/timestamping.txt, `SO_TIMESTAMP` seems more like a boolean -- were you thinking of `SO_TIMESTAMPING`?","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bddfc04026d884b96438d297bcf44c5b19a0c5bd","unresolved":true,"context_lines":[{"line_number":215,"context_line":"    #   TX_SOFTWARE 2"},{"line_number":216,"context_line":"    #   RX_HARDWARE 4"},{"line_number":217,"context_line":"    #   RX_SOFTWARE 8"},{"line_number":218,"context_line":"    sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMP, 10)"},{"line_number":219,"context_line":"    if hasattr(socket, \u0027TCP_KEEPIDLE\u0027):"},{"line_number":220,"context_line":"        sock.setsockopt(socket.IPPROTO_TCP, socket.TCP_KEEPIDLE, keepidle)"},{"line_number":221,"context_line":"    if warn_ssl:"}],"source_content_type":"text/x-python","patch_set":8,"id":"7a4184d7_41e6c7b2","line":218,"in_reply_to":"a97aee76_7afb951a","updated":"2025-05-02 05:30:59.000000000","message":"yeah good question. But really I just wanted a timestamp from before it\u0027s put on the accept queue. And who knows if everyone has hardware support. So just went with software.. yeah tx is probably not required 😊","commit_id":"1b8724a1d683dfd27418be0f8d048cf4f55f5504"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"4048022ce0088b5611b99cc982dea3544313cacb","unresolved":true,"context_lines":[{"line_number":47,"context_line":"                  if n.startswith(\u0027SIG\u0027) and \u0027_\u0027 not in n}"},{"line_number":48,"context_line":"NOTIFY_FD_ENV_KEY \u003d \u0027__SWIFT_SERVER_NOTIFY_FD\u0027"},{"line_number":49,"context_line":"CHILD_STATE_FD_ENV_KEY \u003d \u0027__SWIFT_SERVER_CHILD_STATE_FD\u0027"},{"line_number":50,"context_line":"SO_TIMESTAMP \u003d 29"},{"line_number":51,"context_line":""},{"line_number":52,"context_line":"# Set maximum line size of message headers to be accepted."},{"line_number":53,"context_line":"wsgi.MAX_HEADER_LINE \u003d constraints.MAX_HEADER_SIZE"}],"source_content_type":"text/x-python","patch_set":9,"id":"859a886e_8bf6acf1","line":50,"updated":"2025-05-07 01:27:54.000000000","message":"Note that this is Linux-specific -- on OS X (and [FreeBSD](https://github.com/freebsd/freebsd-src/blob/c15cdaf505849509900b018a44d91eee3647fb13/sys/sys/socket.h#L140)) it\u0027s 1024; on OpenBSD, [it\u0027s 2048](https://github.com/openbsd/src/blob/4c4a6f3e171333cc66aaef510ca70cabf8fee422/sys/sys/socket.h#L97). Though I can\u0027t seem to get the ancdata on my Mac... Should we look at `sys.platform` before we go calling `setsockopt`?\n\nGiven that it\u0027s Linux-specific anyway, do we want `SO_TIMESTAMP`, or `SO_TIMESTAMP_NEW`? From [the docs](https://www.kernel.org/doc/Documentation/networking/timestamping.txt):\n```\nAlways use SO_TIMESTAMP_NEW timestamp to always get timestamp in\nstruct __kernel_sock_timeval format.\n\nSO_TIMESTAMP_OLD returns incorrect timestamps after the year 2038\non 32 bit machines.\n```","commit_id":"6cf149a8b7e26e9342ff8523c9e4df08deaf1e6a"},{"author":{"_account_id":15343,"name":"Tim Burke","email":"tburke@nvidia.com","username":"tburke"},"change_message_id":"5b4854995a33b9a39d4e1d9765941ae1e205330b","unresolved":true,"context_lines":[{"line_number":221,"context_line":"        #   SOF_TIMESTAMPING_RX_HARDWARE 4"},{"line_number":222,"context_line":"        #   SOF_TIMESTAMPING_RX_SOFTWARE 8"},{"line_number":223,"context_line":"        #   SOF_TIMESTAMPING_SOFTWARE 16"},{"line_number":224,"context_line":"        #   SOF_TIMESTAMPING_RAW_HARDWARE 64"},{"line_number":225,"context_line":"        sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMPING_NEW, 92)"},{"line_number":226,"context_line":"    except socket.error:"},{"line_number":227,"context_line":"        sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMPING_OLD, 92)"}],"source_content_type":"text/x-python","patch_set":11,"id":"c85bbe77_7f613e02","line":224,"updated":"2025-05-12 20:21:34.000000000","message":"Checks out:\n```\n#include \u003clinux/net_tstamp.h\u003e\n#include \u003cstdio.h\u003e\n#define p(val) printf(\"%s \u003d %d\\n\", #val, val)\nint main() {\n    p(SOF_TIMESTAMPING_TX_HARDWARE);\n    p(SOF_TIMESTAMPING_TX_SOFTWARE);\n    p(SOF_TIMESTAMPING_RX_HARDWARE);\n    p(SOF_TIMESTAMPING_RX_SOFTWARE);\n    p(SOF_TIMESTAMPING_SOFTWARE);\n    p(SOF_TIMESTAMPING_RAW_HARDWARE);\n    return 0;\n}\n```\nShould we just define these as constants in the file, then say\n```\nopt_val \u003d (SOF_TIMESTAMPING_RX_HARDWARE | SOF_TIMESTAMPING_RX_SOFTWARE |\n           SOF_TIMESTAMPING_SOFTWARE | SOF_TIMESTAMPING_RAW_HARDWARE)\nsock.setsockopt(socket.SOL_SOCKET, ..., opt_val)\n```\n?","commit_id":"0af4128a418ad56b8db74ce6566409f5e215be08"},{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"bb8cadd602bebfbff77d8463584a7ecd495c2ebf","unresolved":true,"context_lines":[{"line_number":221,"context_line":"        #   SOF_TIMESTAMPING_RX_HARDWARE 4"},{"line_number":222,"context_line":"        #   SOF_TIMESTAMPING_RX_SOFTWARE 8"},{"line_number":223,"context_line":"        #   SOF_TIMESTAMPING_SOFTWARE 16"},{"line_number":224,"context_line":"        #   SOF_TIMESTAMPING_RAW_HARDWARE 64"},{"line_number":225,"context_line":"        sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMPING_NEW, 92)"},{"line_number":226,"context_line":"    except socket.error:"},{"line_number":227,"context_line":"        sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMPING_OLD, 92)"}],"source_content_type":"text/x-python","patch_set":11,"id":"c7d71cc0_e526e80c","line":224,"in_reply_to":"c85bbe77_7f613e02","updated":"2025-05-13 06:10:27.000000000","message":"yeah, probably a god idea.. expecially how we have so many mentioned","commit_id":"0af4128a418ad56b8db74ce6566409f5e215be08"}],"test/__init__.py":[{"author":{"_account_id":7233,"name":"Matthew Oliver","email":"matt@oliver.net.au","username":"mattoliverau"},"change_message_id":"89430bab6004da91451acafce11835265e3968b2","unresolved":true,"context_lines":[{"line_number":81,"context_line":"    same port twice. That causes our tests to fail, so open-code it here"},{"line_number":82,"context_line":"    without SO_REUSEPORT."},{"line_number":83,"context_line":"    \"\"\""},{"line_number":84,"context_line":"    SO_TIMESTAMP \u003d 29"},{"line_number":85,"context_line":"    sock \u003d socket.socket(socket.AF_INET, socket.SOCK_STREAM)"},{"line_number":86,"context_line":"    sock.setsockopt(socket.SOL_SOCKET, SO_TIMESTAMP, 10)"},{"line_number":87,"context_line":"    sock.bind((\"127.0.0.1\", 0))"}],"source_content_type":"text/x-python","patch_set":12,"id":"0799af37_ae0cc074","line":84,"updated":"2025-12-04 05:16:30.000000000","message":"This shoulw probably be one of:\n\n```\nSO_TIMESTAMPING_NEW \u003d 65\nSO_TIMESTAMPING_OLD \u003d 37\n```","commit_id":"be725a83244d9b73843786d544fb79938d340e7b"}]}