redirector-host: reproduce the oracle's connection lifecycle, not just its bytes

Two live gate attempts failed with "An error occurred downloading the FUT
Squad Update" while the redirect response was verified byte-identical to the
Python oracle. Rolling back to the Python redirector fixed it, so the response
bytes were never the whole contract.

Log archaeology found the discriminator: the client polls
/fifa17/fut/rosterupdate.xml ~4x/min in every successful FUT session, and the
only gap in 300 recorded fetches is 03:47-03:58 -- exactly the two
Rust-redirector sessions. The Blaze RPC sequence over those sessions is
identical (msgNum 0-53), so the divergence is entirely outside Blaze.

A differential lifecycle probe against both redirectors found the two
behaviours this host never reproduced:

  * the oracle drains the request body per Content-Length; this host stopped
    at the header terminator, leaving unread data in the receive queue, which
    makes Linux close with RST rather than FIN
  * the oracle holds the connection open ~300ms before closing
    (time.sleep(0.3)); this host closed at 0ms

Both are now reproduced. The dwell is a named constant, ORACLE_CLOSE_DWELL,
overridable only so the causal experiment -- set it to 0, confirm the failure
returns -- can be run without a rebuild.

The suite could not have caught either: it sent Content-Length: 0, so there
was never a body to drain. It now POSTs a body, and asserts a split-write body
is fully consumed.

Testing the drain via client-visible symptoms does NOT work -- verified by
mutation: with the drain removed the client still reads the buffered response
and sees close_notify before any reset. So the host records a per-connection
ConnOutcome and the test asserts on that. Both mutations (no-dwell, no-drain)
are now each caught by exactly one test.

This does not yet prove causation for the FUT Squad Update failure; it removes
the only two measured divergences. Gate 6 is the test.

openfut-redirector-host/src/config.rs

@@ -5,11 +5,23 @@
 //! the same construction path. Only the transport settings — listener, cert,
 //! key, TLS knobs — are parsed here, and none of them are client-visible.
 
+use std::time::Duration;
+
 use openfut_adapter_fifa17::blaze::AdapterConfig;
 use openfut_host_config::{self as hostcfg, ConfigError};
 
 use crate::tls::TlsConfig;
 
+/// How long the oracle holds a redirector connection open after responding
+/// (`time.sleep(0.3)` in `blaze_responder_v3b.redir_handle`).
+///
+/// Measured, not guessed: a differential lifecycle probe records the Python
+/// redirector holding the socket ~300ms and the first version of this host
+/// closing at 0ms. FIFA 17 was proven against the former, so it is the default
+/// here. Not a tuning knob — changing it changes what this host is a
+/// reimplementation OF.
+pub const ORACLE_CLOSE_DWELL: Duration = Duration::from_millis(300);
+
 #[derive(Debug, Clone)]
 pub struct RedirectorConfig {
     /// BIND: where this listener binds. Never client-visible.
@@ -20,6 +32,10 @@ pub struct RedirectorConfig {
     pub tls: TlsConfig,
     /// ADVERTISE and everything derived from it.
     pub adapter: AdapterConfig,
+    /// Dwell before closing an answered connection. Overridable ONLY so the
+    /// causal experiment — set it to 0 and confirm the failure returns — can be
+    /// run without rebuilding.
+    pub close_dwell: Duration,
 }
 
 impl RedirectorConfig {
@@ -51,11 +67,21 @@ impl RedirectorConfig {
             tls.security_level = level.trim().parse().ok();
         }
 
+        let close_dwell = match hostcfg::optional_opt("OPENFUT_REDIRECTOR_CLOSE_DWELL_MS") {
+            None => ORACLE_CLOSE_DWELL,
+            Some(v) => Duration::from_millis(v.trim().parse().map_err(|_| {
+                ConfigError(format!(
+                    "OPENFUT_REDIRECTOR_CLOSE_DWELL_MS is not a number of milliseconds: {v:?}"
+                ))
+            })?),
+        };
+
         Ok(RedirectorConfig {
             listen_addr,
             listen_port,
             tls,
             adapter,
+            close_dwell,
         })
     }
 
@@ -76,6 +102,7 @@ impl RedirectorConfig {
                 format!("{base}/redir_key.pem"),
             ),
             adapter: AdapterConfig::advertising(advertise),
+            close_dwell: ORACLE_CLOSE_DWELL,
         }
     }
 }

openfut-redirector-host/src/lib.rs

@@ -113,21 +113,57 @@ pub struct Server {
     listener: TcpListener,
     acceptor: Arc<SslAcceptor>,
     cfg: Arc<RedirectorConfig>,
+    outcomes: Outcomes,
 }
 
+/// What the host did on a connection, beyond the bytes it sent.
+///
+/// Recorded because the failure that cost two live gate attempts — a request
+/// body left unread — is invisible to any comparison of the response. The log
+/// line carries the same facts for a live run; this makes them assertable.
+#[derive(Debug, Clone)]
+pub struct ConnOutcome {
+    pub id: u64,
+    pub request_bytes: usize,
+    pub body: BodyRead,
+    pub response_bytes: usize,
+}
+
+pub type Outcomes = Arc<std::sync::Mutex<Vec<ConnOutcome>>>;
+
+/// Keep the record bounded: a long-running redirector must not accumulate one
+/// entry per connection forever.
+const OUTCOME_HISTORY: usize = 64;
+
 impl Server {
+    /// A handle to the connection record, obtainable before [`Server::run`]
+    /// consumes the server.
+    pub fn outcomes(&self) -> Outcomes {
+        self.outcomes.clone()
+    }
+
     pub fn run(self) -> std::io::Result<()> {
         let counter = AtomicU64::new(0);
         for incoming in self.listener.incoming() {
             let Ok(stream) = incoming else { continue };
             let id = counter.fetch_add(1, Ordering::Relaxed) + 1;
             let (acceptor, cfg) = (self.acceptor.clone(), self.cfg.clone());
-            std::thread::spawn(move || handle(stream, id, &acceptor, &cfg));
+            let outcomes = self.outcomes.clone();
+            std::thread::spawn(move || handle(stream, id, &acceptor, &cfg, &outcomes));
         }
         Ok(())
     }
 }
 
+fn record(outcomes: &Outcomes, o: ConnOutcome) {
+    if let Ok(mut v) = outcomes.lock() {
+        if v.len() >= OUTCOME_HISTORY {
+            v.remove(0);
+        }
+        v.push(o);
+    }
+}
+
 /// Build TLS, rehearse the retail handshake, and bind.
 pub fn bind(cfg: RedirectorConfig) -> std::io::Result<Server> {
     let acceptor = tls::build_acceptor(&cfg.tls)
@@ -154,6 +190,7 @@ pub fn bind(cfg: RedirectorConfig) -> std::io::Result<Server> {
         listener,
         acceptor: Arc::new(acceptor),
         cfg: Arc::new(cfg),
+        outcomes: Outcomes::default(),
     })
 }
 
@@ -162,7 +199,13 @@ pub fn serve(cfg: RedirectorConfig) -> std::io::Result<()> {
     bind(cfg)?.run()
 }
 
-fn handle(stream: TcpStream, id: u64, acceptor: &SslAcceptor, cfg: &RedirectorConfig) {
+fn handle(
+    stream: TcpStream,
+    id: u64,
+    acceptor: &SslAcceptor,
+    cfg: &RedirectorConfig,
+    outcomes: &Outcomes,
+) {
     let peer = stream
         .peer_addr()
         .map(|a| a.to_string())
@@ -215,9 +258,25 @@ fn handle(stream: TcpStream, id: u64, acceptor: &SslAcceptor, cfg: &RedirectorCo
         }
     }
 
+    // Drain the request body, exactly as the oracle does. This is NOT cosmetic:
+    // answering and closing while the client is still sending leaves unread data
+    // in the receive queue, and Linux turns that close into an RST rather than a
+    // FIN. The oracle has always drained; the first version of this host stopped
+    // at the header terminator, which is a behaviour difference invisible to any
+    // byte-comparison of the response.
+    let body_read = drain_body(&mut tls, &mut buf);
+
     let head = String::from_utf8_lossy(&buf);
     let line0 = head.lines().next().unwrap_or("").to_string();
-    log(&format!("conn-{id:04} {peer} REQ {line0}"));
+    log(&format!(
+        "conn-{id:04} {peer} REQ {line0} req_bytes={} body={}",
+        buf.len(),
+        match body_read {
+            BodyRead::None => "none".to_string(),
+            BodyRead::Complete(n) => format!("{n}B complete"),
+            BodyRead::Short { got, want } => format!("{got}B of {want}B SHORT"),
+        }
+    ));
     if !line0.is_empty() && !redirector::is_get_server_instance(&line0) {
         log(&format!(
             "conn-{id:04} {peer} NOTE: unexpected request line; answering anyway (oracle behaviour)"
@@ -237,10 +296,67 @@ fn handle(stream: TcpStream, id: u64, acceptor: &SslAcceptor, cfg: &RedirectorCo
         cfg.adapter.endpoints.blaze_port
     ));
 
-    // The oracle closes after responding; the redirector is a one-shot hop.
+    // The oracle holds the connection open before closing. That dwell is the
+    // only other measured difference between the two implementations, and a
+    // redirector that closes at 0ms is not the behaviour FIFA 17 was proven
+    // against — so it is reproduced rather than assumed harmless.
+    record(
+        outcomes,
+        ConnOutcome {
+            id,
+            request_bytes: buf.len(),
+            body: body_read,
+            response_bytes: response.len(),
+        },
+    );
+
+    std::thread::sleep(cfg.close_dwell);
     let _ = tls.shutdown();
 }
 
+/// What happened when the request body was drained. Reported per connection
+/// because "the client sent a body we never read" is exactly the class of
+/// divergence a response-bytes comparison cannot see.
+#[derive(Debug, Clone, Copy, PartialEq, Eq)]
+pub enum BodyRead {
+    /// No `Content-Length` header — nothing to drain.
+    None,
+    Complete(usize),
+    Short { got: usize, want: usize },
+}
+
+/// Parse `Content-Length` and read the remainder of the body into `buf`.
+///
+/// Mirrors the oracle: header lookup is case-insensitive, and a client that
+/// stops early ends the read rather than hanging until the timeout.
+fn drain_body<S: Read>(stream: &mut S, buf: &mut Vec<u8>) -> BodyRead {
+    let Some(sep) = buf.windows(4).position(|w| w == b"\r\n\r\n") else {
+        return BodyRead::None;
+    };
+    let head = String::from_utf8_lossy(&buf[..sep]).to_string();
+    let Some(want) = head
+        .lines()
+        .find(|l| l.to_ascii_lowercase().starts_with("content-length"))
+        .and_then(|l| l.split(':').nth(1))
+        .and_then(|v| v.trim().parse::<usize>().ok())
+    else {
+        return BodyRead::None;
+    };
+
+    let mut got = buf.len() - (sep + 4);
+    let mut chunk = [0u8; 4096];
+    while got < want {
+        match stream.read(&mut chunk) {
+            Ok(0) | Err(_) => return BodyRead::Short { got, want },
+            Ok(n) => {
+                buf.extend_from_slice(&chunk[..n]);
+                got += n;
+            }
+        }
+    }
+    BodyRead::Complete(got)
+}
+
 #[cfg(test)]
 mod tests {
     use super::*;

openfut-redirector-host/tests/oracle_parity.rs

@@ -9,7 +9,7 @@
 use std::io::{Read, Write};
 use std::net::TcpStream;
 
-use openfut_redirector_host::{bind, tls, RedirectorConfig};
+use openfut_redirector_host::{bind, tls, BodyRead, RedirectorConfig};
 use openssl::ssl::{SslConnector, SslMethod, SslVerifyMode};
 
 /// Start the real host on an ephemeral port.
@@ -24,6 +24,14 @@ fn start(advertise: &str) -> String {
     addr
 }
 
+/// A request body, because a retail client POSTs one.
+///
+/// The first version of this suite sent `Content-Length: 0`. That is why it
+/// passed against a host that never drained the body — the blind spot was in
+/// the measurement, not the assertion.
+const REQUEST_BODY: &[u8] = b"<?xml version=\"1.0\" encoding=\"UTF-8\"?>\
+<serverinstancerequest><name>fifa-2017-pc</name></serverinstancerequest>";
+
 /// A client that behaves like the captured FIFA 17 ClientHello.
 fn fifa_like_request(addr: &str) -> (String, Vec<u8>) {
     let mut b = SslConnector::builder(SslMethod::tls()).expect("connector");
@@ -54,14 +62,16 @@ fn fifa_like_request(addr: &str) -> (String, Vec<u8>) {
             .unwrap_or("?")
     );
 
-    stream
+    let mut req = format!(
-        .write_all(
+        "POST /redirector/getServerInstance HTTP/1.1\r\n\
-            b"POST /redirector/getServerInstance HTTP/1.1\r\n\
          Host: winter15.gosredirector.ea.com\r\n\
          Content-Type: application/xml\r\n\
-              Content-Length: 0\r\n\r\n",
+         Content-Length: {}\r\n\r\n",
+        REQUEST_BODY.len()
     )
-        .expect("write request");
+    .into_bytes();
+    req.extend_from_slice(REQUEST_BODY);
+    stream.write_all(&req).expect("write request");
     stream.flush().ok();
 
     let mut out = Vec::new();
@@ -136,6 +146,127 @@ fn the_advertised_address_reaches_the_wire() {
     assert!(!text.contains("198.51.100.7"));
 }
 
+/// The body must be DRAINED, not left in the receive queue.
+///
+/// A server that answers and closes with unread data makes the kernel send RST
+/// instead of FIN. Sending the body in a second write, after a pause, is what
+/// makes this observable: a host that stops at the header terminator has
+/// already responded by the time the body arrives.
+#[test]
+fn the_request_body_is_drained_before_closing() {
+    let mut cfg = RedirectorConfig::for_test("198.51.100.7");
+    cfg.listen_port = 0;
+    let server = bind(cfg).expect("host binds");
+    let addr = server.local_addr.to_string();
+    let outcomes = server.outcomes();
+    std::thread::spawn(move || {
+        let _ = server.run();
+    });
+
+    let mut b = SslConnector::builder(SslMethod::tls()).expect("connector");
+    b.set_cipher_list(tls::OBSERVED_CLIENT_SUITES).expect("list");
+    b.set_verify(SslVerifyMode::NONE);
+    let sock = TcpStream::connect(&addr).expect("connect");
+    let ssl = b
+        .build()
+        .configure()
+        .expect("configure")
+        .verify_hostname(false)
+        .into_ssl("winter15.gosredirector.ea.com")
+        .expect("ssl");
+    let mut stream = openssl::ssl::SslStream::new(ssl, sock).expect("stream");
+    stream.connect().expect("handshake");
+
+    stream
+        .write_all(
+            format!(
+                "POST /redirector/getServerInstance HTTP/1.1\r\n\
+                 Content-Length: {}\r\n\r\n",
+                REQUEST_BODY.len()
+            )
+            .as_bytes(),
+        )
+        .expect("write head");
+    stream.flush().ok();
+    std::thread::sleep(std::time::Duration::from_millis(150));
+
+    // If the host had already answered and closed, this write — or the read
+    // that follows it — is where the reset surfaces.
+    stream.write_all(REQUEST_BODY).expect("body must be accepted");
+    stream.flush().ok();
+
+    let mut out = Vec::new();
+    let mut chunk = [0u8; 4096];
+    loop {
+        match stream.read(&mut chunk) {
+            Ok(0) => break,
+            Ok(n) => out.extend_from_slice(&chunk[..n]),
+            Err(e) => panic!("connection broke instead of closing cleanly: {e}"),
+        }
+    }
+    assert!(
+        String::from_utf8_lossy(&out).contains("<serverinstanceinfo>"),
+        "expected the full response after a split-write body, got {} bytes",
+        out.len()
+    );
+
+    // The assertion that carries the weight. Checking only that the client got
+    // its response does NOT detect an undrained body — verified by mutation:
+    // with the drain removed, the client still reads the buffered response and
+    // sees close_notify before any reset. Only the host's own record shows
+    // whether it consumed what the client sent.
+    let rec = outcomes.lock().expect("outcomes");
+    let last = rec.last().expect("one connection was recorded");
+    assert_eq!(
+        last.body,
+        BodyRead::Complete(REQUEST_BODY.len()),
+        "the host did not drain the request body: {last:?}"
+    );
+}
+
+/// The oracle holds the connection open after responding; so must this host.
+///
+/// Asserted as a floor rather than an exact figure — this measures scheduling,
+/// so the guarantee is "at least the oracle's dwell", not "exactly 300ms".
+#[test]
+fn the_connection_is_held_open_for_the_oracle_dwell() {
+    use openfut_redirector_host::config::ORACLE_CLOSE_DWELL;
+
+    let addr = start("198.51.100.7");
+    let t0 = std::time::Instant::now();
+    let (_, body) = fifa_like_request(&addr);
+    let held = t0.elapsed();
+
+    assert!(!body.is_empty(), "no response");
+    assert!(
+        held >= ORACLE_CLOSE_DWELL,
+        "closed after {held:?}, before the oracle's {ORACLE_CLOSE_DWELL:?} dwell"
+    );
+}
+
+/// The dwell is configurable so the causal experiment can be run, and a bad
+/// value is refused rather than silently ignored.
+#[test]
+fn the_dwell_is_overridable_for_the_causal_experiment() {
+    let mut cfg = RedirectorConfig::for_test("198.51.100.7");
+    cfg.listen_port = 0;
+    cfg.close_dwell = std::time::Duration::ZERO;
+    let server = bind(cfg).expect("binds");
+    let addr = server.local_addr.to_string();
+    std::thread::spawn(move || {
+        let _ = server.run();
+    });
+
+    let t0 = std::time::Instant::now();
+    let (_, body) = fifa_like_request(&addr);
+    assert!(!body.is_empty(), "no response");
+    assert!(
+        t0.elapsed() < std::time::Duration::from_millis(250),
+        "a zero dwell should close promptly, took {:?}",
+        t0.elapsed()
+    );
+}
+
 /// A client that offers only forward-secret suites — i.e. anything modern —
 /// must fail, confirming this listener really is the legacy island it claims
 /// to be and has not silently acquired a modern policy.