Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

flush during send_prelude #8

Closed
wants to merge 1 commit into from

Conversation

@FauxFaux
Copy link
Contributor

commented Sep 8, 2019

I'm seeing requests fail with BadStatus. A lot. I'm using the Agent API.

I believe it's only after periods of inactivity. I can reproduce it on multiple machines, but am yet to reproduce it with sufficient logging to be certain as to what is happening.

My best guess is that:

  • some time after the first request, but before the second, the server is closing the connection (very reasonable)
  • the second request comes along, through send_prelude, which is filling up the TLS buffer, but not actually trying to use the socket, so not seeing an (IO) error
  • do_from_read is doing the first actual IO operation on the connection
  • this is getting the UnexpectedEOF (which read_next_line calls ConnectionAborted)
  • ..which is reported as a BadStatus

The code already copes with the underlying socket dying... so long as send_prelude notices. I suspect that it is not. We can fix this by trying to force some IO inside send_prelude, by flushing here.

--

The server this happens most with is https://api.twitter.com, which seems happy for you to reuse a connection ten times, or to leave it data-idle (maybe there are tcp keepalives?) for 25 minutes sometimes, but sometimes will just kill it after five minutes. I'm unclear on how it is killing it, maybe it's confusing rustls?

I'm on modern amd64 ubuntu, stable/nightly rust from today, home/datacentre internet.

@FauxFaux

This comment has been minimized.

Copy link
Contributor Author

commented Sep 8, 2019

I waited like three hours, you utter sock wrangling piece of software.

With this patch:

diff --git a/src/response.rs b/src/response.rs
index c93d756..8f6f11c 100644
--- a/src/response.rs
+++ b/src/response.rs
@@ -412,7 +412,10 @@ impl Response {
     fn do_from_read(mut reader: impl Read) -> Result<Response, Error> {
         //
         // HTTP/1.1 200 OK\r\n
-        let status_line = read_next_line(&mut reader).map_err(|_| Error::BadStatus)?;
+        let status_line = read_next_line(&mut reader).map_err(|e| {
+            log::warn!("bad status: {:?}", e);
+            Error::BadStatus
+        })?;
 
         let (index, status) = parse_status_line(status_line.as_str())?;

..I just saw:
WARN ureq::response > bad status: Custom { kind: ConnectionAborted, error: "CloseNotify alert received" }

Which is not a denial of my suggestion; the connection is being closed (at the TCP level) and we're not noticing until we try and read. Maybe this is a rustls bug?

@FauxFaux

This comment has been minimized.

Copy link
Contributor Author

commented Sep 8, 2019

I thought this was familiar. I've just found the time someone (cough it was me) fixed this in a different http client.

I think I'm slowly losing it. It's the socks. I swear I'm still sane, it's the socks.

jayjamesjay/http_req@6887f12#diff-5bcc8caa34cc400be17a2bd1a01a41ebR72

@FauxFaux

This comment has been minimized.

Copy link
Contributor Author

commented Sep 9, 2019

This doesn't work. See #10.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
1 participant
You can’t perform that action at this time.