net/tftp: IRIS_TFTP_TRACE request and transfer log

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

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);
             }

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(),

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<bool> = 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<ClientId, Transfer>,
     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,30 +117,51 @@ 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"))
+            }
         }
     }
 
     /// Retransmit any DATA that has gone unanswered, and drop transfers that
     /// have exhausted their retries. Returns the packets to send.
     pub fn tick(&mut self, now: Instant) -> Vec<(ClientId, Vec<u8>)> {
         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,32 +180,49 @@ impl TftpServer {
 
     fn start_read(&mut self, client: ClientId, body: &[u8], now: Instant) -> Vec<u8> {
         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))
         } else {
             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<Vec<u8>> {
+        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);
+    }
 }