diff --git a/HELP.md b/HELP.md index 5457c85b..62889fb9 100644 --- a/HELP.md +++ b/HELP.md @@ -192,6 +192,14 @@ To reach the Command Monitor on a machine that autoboots, press Esc while the PROM says "Starting up the system" (from the monitor console: `ps2 esc`). `test/tftp/` has a guest-side client and a test script. +To see what the PROM or a client actually does, start iris with +`IRIS_TFTP_TRACE=1`. It writes to stderr, in any build: what BOOTP was asked to +boot, each read request and whether the file was found, and how each transfer +ended (bytes, blocks, retransmits, duplicate ACKs, the slowest ACK, total +time), plus any ACK slower than 500 ms as it happens. A read request sent to +the host's port 69 instead (no `tftp_dir`, or a server address other than the +gateway) is reported too, so silence means no request arrived at all. + ### rsh (files from the host) `rsh_dir = "DIR"` under `[network]` (or `--rsh-dir DIR`) starts a small rsh diff --git a/src/net/nat_udp.rs b/src/net/nat_udp.rs index d58fe786..11254a27 100644 --- a/src/net/nat_udp.rs +++ b/src/net/nat_udp.rs @@ -60,6 +60,14 @@ impl NatEngine { _ if to_gw && self.udp_service_ports.contains_key(&dport) => self.udp_service(src_mac, src_ip, sport, dport, payload), _ => { + // A read request that is not ours: say where it goes, since + // "no TFTP trace" otherwise looks the same as "no request". + if dport == super::services::TFTP_PORT && payload.starts_with(&[0, 1]) && super::tftp::trace_enabled() { + eprintln!("iris: tftp: guest {}:{} -> {}:{} read request {}", + src_ip, sport, dst_ip, dport, + if to_gw { "relayed to the host's port 69: tftp_dir is not set" } + else { "relayed to that address: it is not the gateway" }); + } let (ip, port) = self.gateway_to_host(dst_ip, dport); self.udp_relay(src_mac, src_ip, sport, visible, SocketAddrV4::new(ip, port), payload); } diff --git a/src/net/services.rs b/src/net/services.rs index 1ae53d19..64074f35 100644 --- a/src/net/services.rs +++ b/src/net/services.rs @@ -279,12 +279,26 @@ impl NatEngine { /// file whenever the TFTP root has it. With no TFTP, or no such file, the /// fields stay empty. fn bootp_boot_file(&self, req: &[u8], rep: &mut [u8]) { - let Some(root) = self.config.tftp_dir.as_ref() else { return }; + let trace = super::tftp::trace_enabled(); let file = bootp_str(&req[108..236]); + let Some(root) = self.config.tftp_dir.as_ref() else { + if trace && !file.is_empty() { + eprintln!("iris: tftp BOOTP asks for {:?}: no boot file named, tftp_dir is not set", file); + } + return; + }; if file.is_empty() || !super::tftp::file_exists(root, &file) { dlog_dev!(LogModule::Net, "NAT BOOTP file {:?} not in the TFTP root", file); + if trace { + eprintln!("iris: tftp BOOTP asks for {:?}: no boot file named, {}", file, + if file.is_empty() { "the request names no file".to_string() } + else { format!("it is not a file under {}", root.display()) }); + } return; } + if trace { + eprintln!("iris: tftp BOOTP asks for {:?}: named as the boot file", file); + } // Echo a requested server name (bootp()host:file), else name ourselves. let sname = match bootp_str(&req[44..108]) { s if s.is_empty() => "iris".to_string(), diff --git a/src/net/tftp.rs b/src/net/tftp.rs index c070f2d4..1a39a706 100644 --- a/src/net/tftp.rs +++ b/src/net/tftp.rs @@ -40,6 +40,32 @@ const ERR_UNKNOWN_ID: u16 = 5; /// A client is identified by its address and source port (its TID). pub type ClientId = (Ipv4Addr, u16); +/// With `IRIS_TFTP_TRACE` set, every request and how each transfer ended is +/// written to stderr, in any build (`dlog_dev!` output exists only in +/// `developer` builds): what was asked for, whether it was found, bytes, +/// blocks, retransmits, duplicate ACKs, the slowest ACK and the total time. +/// Lock-step TFTP is as slow as its slowest round trip, so those numbers say +/// where a slow or stalled PROM network boot spends its time. +pub fn trace_enabled() -> bool { + static ON: std::sync::OnceLock = std::sync::OnceLock::new(); + *ON.get_or_init(|| std::env::var_os("IRIS_TFTP_TRACE").is_some()) +} + +macro_rules! ttrace { + ($s:expr, $($a:tt)*) => { + if $s.trace { + eprintln!("iris: tftp {}", format_args!($($a)*)); + } + }; +} + +fn who(c: ClientId) -> String { + format!("{}:{}", c.0, c.1) +} + +/// A reply slower than this is reported as it happens. +const SLOW_ACK: Duration = Duration::from_millis(500); + /// Where a transfer's bytes come from. Octet streams the file; netascii /// changes the length, so it is translated once up front. enum Source { @@ -59,18 +85,25 @@ struct Transfer { final_block: bool, retries: u8, sent_at: Instant, + // For the trace. + name: String, + started: Instant, + retransmits: u32, + dup_acks: u32, + slowest_ack: Duration, } pub struct TftpServer { root: PathBuf, transfers: HashMap, timeout: Duration, + trace: bool, } impl TftpServer { /// Serve read-only out of `root`. Nothing outside it is ever reachable. pub fn new(root: PathBuf) -> Self { - Self { root, transfers: HashMap::new(), timeout: RETRANSMIT_TIMEOUT } + Self { root, transfers: HashMap::new(), timeout: RETRANSMIT_TIMEOUT, trace: trace_enabled() } } pub fn root(&self) -> &Path { @@ -84,13 +117,25 @@ impl TftpServer { } match u16::from_be_bytes([packet[0], packet[1]]) { OP_RRQ => Some(self.start_read(client, &packet[2..], now)), - OP_WRQ => Some(error_packet(ERR_ACCESS_VIOLATION, "server is read-only")), + OP_WRQ => { + ttrace!(self, "{} WRQ refused: the server is read-only", who(client)); + Some(error_packet(ERR_ACCESS_VIOLATION, "server is read-only")) + } OP_ACK => self.handle_ack(client, u16::from_be_bytes([packet[2], packet[3]]), now), OP_ERROR => { - self.transfers.remove(&client); + let code = u16::from_be_bytes([packet[2], packet[3]]); + let msg = String::from_utf8_lossy(packet[4..].split(|&b| b == 0).next().unwrap_or(&[])).into_owned(); + match self.transfers.remove(&client) { + Some(t) => ttrace!(self, "{} aborted {:?} at block {} (error {}: {:?})", + who(client), t.name, t.block, code, msg), + None => ttrace!(self, "{} sent error {}: {:?}", who(client), code, msg), + } None } - _ => Some(error_packet(ERR_ILLEGAL_OP, "only RRQ is supported")), + op => { + ttrace!(self, "{} unsupported opcode {}", who(client), op); + Some(error_packet(ERR_ILLEGAL_OP, "only RRQ is supported")) + } } } @@ -98,16 +143,25 @@ impl TftpServer { /// have exhausted their retries. Returns the packets to send. pub fn tick(&mut self, now: Instant) -> Vec<(ClientId, Vec)> { let timeout = self.timeout; + let trace = self.trace; let mut out = Vec::new(); self.transfers.retain(|client, t| { if now.duration_since(t.sent_at) < timeout { return true; } if t.retries >= MAX_RETRIES { + if trace { + eprintln!("iris: tftp {} gave up on {:?} at block {}: no ACK after {} retransmits ({} ms in)", + who(*client), t.name, t.block, MAX_RETRIES, now.duration_since(t.started).as_millis()); + } return false; } t.retries += 1; + t.retransmits += 1; t.sent_at = now; + if trace { + eprintln!("iris: tftp {} retransmit {:?} block {} (try {})", who(*client), t.name, t.block, t.retries); + } out.push((*client, t.last_packet.clone())); true }); @@ -126,23 +180,31 @@ impl TftpServer { fn start_read(&mut self, client: ClientId, body: &[u8], now: Instant) -> Vec { let Some((name, mode)) = parse_request(body) else { + ttrace!(self, "{} malformed request ({} bytes)", who(client), body.len()); return error_packet(ERR_NOT_DEFINED, "malformed request"); }; + ttrace!(self, "{} RRQ {:?} ({})", who(client), name, mode); // The PROM always asks for octet; command-line clients default to netascii. let netascii = mode.eq_ignore_ascii_case("netascii"); if !netascii && !mode.eq_ignore_ascii_case("octet") { + ttrace!(self, "{} refused: mode {:?} is neither octet nor netascii", who(client), mode); return error_packet(ERR_NOT_DEFINED, "mode must be octet or netascii"); } let Some(path) = self.resolve(&name) else { + ttrace!(self, "{} refused: {:?} is not under {} (or leaves it)", who(client), name, self.root.display()); return error_packet(ERR_FILE_NOT_FOUND, &format!("{}: not found", name)); }; let mut file = match File::open(&path) { Ok(f) => f, - Err(e) => return error_packet(ERR_FILE_NOT_FOUND, &format!("{}: {}", name, e)), + Err(e) => { + ttrace!(self, "{} refused: {:?}: {}", who(client), name, e); + return error_packet(ERR_FILE_NOT_FOUND, &format!("{}: {}", name, e)); + } }; let source = if netascii { let mut raw = Vec::new(); if let Err(e) = file.read_to_end(&mut raw) { + ttrace!(self, "{} refused: {:?}: {}", who(client), name, e); return error_packet(ERR_NOT_DEFINED, &format!("{}: {}", name, e)); } Source::Netascii(to_netascii(&raw)) @@ -150,8 +212,17 @@ impl TftpServer { Source::File(file) }; + let size = match &source { + Source::File(f) => f.metadata().map(|m| m.len()).ok(), + Source::Netascii(d) => Some(d.len() as u64), + }; // A second RRQ from the same TID replaces whatever was in flight. let mut t = Transfer { + name: name.clone(), + started: now, + retransmits: 0, + dup_acks: 0, + slowest_ack: Duration::ZERO, source, block: 0, offset: 0, @@ -162,24 +233,46 @@ impl TftpServer { }; match send_block(&mut t, 1, 0, now) { Ok(pkt) => { - self.transfers.insert(client, t); + if let Some(old) = self.transfers.insert(client, t) { + ttrace!(self, "{} new request replaces {:?} (was at block {})", who(client), old.name, old.block); + } + match size { + Some(n) => ttrace!(self, "{} sending {:?}: {} bytes, {} blocks", who(client), name, n, n / BLOCK_SIZE as u64 + 1), + None => ttrace!(self, "{} sending {:?}", who(client), name), + } pkt } - Err(e) => error_packet(ERR_NOT_DEFINED, &format!("{}: {}", name, e)), + Err(e) => { + ttrace!(self, "{} refused: {:?}: {}", who(client), name, e); + error_packet(ERR_NOT_DEFINED, &format!("{}: {}", name, e)) + } } } fn handle_ack(&mut self, client: ClientId, block: u16, now: Instant) -> Option> { + let trace = self.trace; let Some(t) = self.transfers.get_mut(&client) else { + ttrace!(self, "{} ACK {} with no transfer in progress", who(client), block); return Some(error_packet(ERR_UNKNOWN_ID, "no transfer in progress")); }; // A duplicate ACK (the classic Sorcerer's Apprentice case) must not // advance the transfer — ignore anything that isn't the block in flight. if block != t.block { + t.dup_acks += 1; return None; } + let rtt = now.duration_since(t.sent_at); + t.slowest_ack = t.slowest_ack.max(rtt); + if trace && rtt >= SLOW_ACK { + eprintln!("iris: tftp {} slow ACK for {:?} block {}: {} ms", who(client), t.name, block, rtt.as_millis()); + } if t.final_block { - self.transfers.remove(&client); + if let Some(t) = self.transfers.remove(&client) { + ttrace!(self, "{} complete {:?}: {} bytes, {} blocks, {} retransmits, {} duplicate ACKs, slowest ACK {} ms, {} ms total", + who(client), t.name, t.offset + t.last_packet.len().saturating_sub(4) as u64, + block, t.retransmits, t.dup_acks, t.slowest_ack.as_millis(), + now.duration_since(t.started).as_millis()); + } return None; } let next_offset = t.offset + BLOCK_SIZE as u64; @@ -189,6 +282,7 @@ impl TftpServer { Ok(pkt) => Some(pkt), Err(e) => { self.transfers.remove(&client); + ttrace!(self, "{} read error at block {}: {}", who(client), next_block, e); Some(error_packet(ERR_NOT_DEFINED, &e.to_string())) } } @@ -558,4 +652,46 @@ mod tests { assert_eq!(field(&p), ERR_UNKNOWN_ID); let _ = std::fs::remove_dir_all(&root); } + + /// Tracing only writes to stderr: every path behaves as it does untraced. + #[test] + fn tracing_changes_no_behaviour() { + let root = tmp_root("trace"); + std::fs::write(root.join("f"), vec![7u8; 1100]).unwrap(); + let mut s = TftpServer::new(root.clone()); + s.trace = true; + let now = Instant::now(); + assert_eq!(opcode(&s.handle(CLIENT, &rrq("nope", "octet"), now).unwrap()), OP_ERROR); + assert_eq!(opcode(&s.handle(CLIENT, &rrq("f", "mail"), now).unwrap()), OP_ERROR); + assert_eq!(opcode(&s.handle(CLIENT, &[0, 2, b'x', 0, b'o', 0], now).unwrap()), OP_ERROR); + assert_eq!(opcode(&s.handle(CLIENT, &ack(1), now).unwrap()), OP_ERROR); + let p = s.handle(CLIENT, &rrq("f", "octet"), now).unwrap(); + assert_eq!((opcode(&p), field(&p)), (OP_DATA, 1)); + assert!(s.handle(CLIENT, &ack(9), now).is_none(), "a wrong ACK is a duplicate"); + let p = s.handle(CLIENT, &ack(1), now + Duration::from_millis(700)).unwrap(); + assert_eq!(field(&p), 2); + let p = s.handle(CLIENT, &ack(2), now).unwrap(); + assert_eq!((field(&p), p.len()), (3, 4 + 76)); + assert!(s.handle(CLIENT, &ack(3), now).is_none()); + assert_eq!(s.active_transfers(), 0); + // Retransmits, then giving up. + s.handle(CLIENT, &rrq("f", "octet"), now).unwrap(); + let mut t = now; + let mut sent = 0; + for _ in 0..(MAX_RETRIES as usize + 2) { + t += RETRANSMIT_TIMEOUT; + sent += s.tick(t).len(); + } + assert_eq!(sent, MAX_RETRIES as usize); + assert_eq!(s.active_transfers(), 0); + // A new request replaces one in flight; a client error ends it. + s.handle(CLIENT, &rrq("f", "octet"), now).unwrap(); + s.handle(CLIENT, &rrq("f", "netascii"), now).unwrap(); + assert_eq!(s.active_transfers(), 1); + let mut err = vec![0, 5, 0, 3]; + err.extend_from_slice(b"disk full\0"); + assert!(s.handle(CLIENT, &err, now).is_none()); + assert_eq!(s.active_transfers(), 0); + let _ = std::fs::remove_dir_all(&root); + } }