diff --git a/services/net/src/api.rs b/services/net/src/api.rs index 1e1461bc4..76d764d5c 100644 --- a/services/net/src/api.rs +++ b/services/net/src/api.rs @@ -34,7 +34,7 @@ pub const MIN_EC_REV: SemVer = SemVer { }; /// Dispatch opcodes to the Net crate main loop. -#[derive(num_derive::FromPrimitive, num_derive::ToPrimitive, Debug)] +#[derive(num_derive::FromPrimitive, num_derive::ToPrimitive, Debug, PartialEq, Eq)] #[repr(C)] pub(crate) enum Opcode { SetupMpsc = 0, diff --git a/services/net/src/device.rs b/services/net/src/device.rs index c33b68fbf..c3d732535 100644 --- a/services/net/src/device.rs +++ b/services/net/src/device.rs @@ -1,12 +1,14 @@ use com::Com; use com::api::NET_MTU; -use smoltcp::phy::{self, DeviceCapabilities, Medium}; -use smoltcp::wire::{ArpPacket, ArpRepr, ArpOperation, Ipv4Address, EthernetAddress, EthernetFrame, EthernetProtocol}; +use smoltcp::phy::{self, DeviceCapabilities, Medium, ChecksumCapabilities}; +use smoltcp::wire::{ArpPacket, ArpRepr, ArpOperation, Ipv4Address, + EthernetAddress, EthernetFrame, EthernetProtocol, Ipv4Packet, + Ipv4Repr, /* IpProtocol, TcpPacket, TcpRepr, IpAddress, UdpPacket, UdpRepr */}; use num_traits::*; use std::convert::TryInto; -use crate::{MAC_ADDRESS_LSB, MAC_ADDRESS_MSB}; +use crate::{MAC_ADDRESS_LSB, MAC_ADDRESS_MSB, IPV4_ADDRESS}; use core::sync::atomic::Ordering; use std::collections::VecDeque; use std::sync::{Arc, Mutex}; @@ -49,26 +51,50 @@ impl phy::Device for NetPhy { type TxToken<'a> = NetPhyTxToken<'a>; fn receive(&mut self, _instant: smoltcp::time::Instant) -> Option<(Self::RxToken<'_>, Self::TxToken<'_>)> { + let csum_copy = self.capabilities().checksum.clone(); if let Some(rx_len) = self.loopback_pending.lock().unwrap().pop_front() { + log::debug!("loopback injected {} bytes", rx_len); // loopback takes precedence self.com.wlan_fetch_loopback_packet(&mut self.rx_buffer[..rx_len as usize]).expect("Couldn't call wlan_fetch_packet in device adapter"); Some((NetPhyRxToken{buf: &mut self.rx_buffer[..rx_len as usize]}, - NetPhyTxToken{buf: &mut self.tx_buffer[..], com: & self.com, loopback_conn: self.loopback_conn, loopback_count: self.loopback_pending.clone()})) + NetPhyTxToken{ + buf: &mut self.tx_buffer[..], + com: & self.com, + loopback_conn: self.loopback_conn, + loopback_count: self.loopback_pending.clone(), + caps: csum_copy + })) } else { if let Some(rx_len) = self.rx_avail.take() { + log::debug!("device rx of {} bytes", rx_len); self.com.wlan_fetch_packet(&mut self.rx_buffer[..rx_len as usize]).expect("Couldn't call wlan_fetch_packet in device adapter"); Some((NetPhyRxToken{buf: &mut self.rx_buffer[..rx_len as usize]}, - NetPhyTxToken{buf: &mut self.tx_buffer[..], com: & self.com, loopback_conn: self.loopback_conn, loopback_count: self.loopback_pending.clone()})) + NetPhyTxToken{ + buf: &mut self.tx_buffer[..], + com: & self.com, + loopback_conn: self.loopback_conn, + loopback_count: self.loopback_pending.clone(), + caps: csum_copy + })) } else { + log::trace!("nothing to rx"); None } } } fn transmit(&mut self, _instant: smoltcp::time::Instant) -> Option> { - Some(NetPhyTxToken{buf: &mut self.tx_buffer[..], com: &self.com, loopback_conn: self.loopback_conn, loopback_count: self.loopback_pending.clone()}) + let csum_copy = self.capabilities().checksum.clone(); + log::debug!("device tx"); + Some(NetPhyTxToken{ + buf: &mut self.tx_buffer[..], + com: &self.com, + loopback_conn: self.loopback_conn, + loopback_count: self.loopback_pending.clone(), + caps: csum_copy + }) } fn capabilities(&self) -> DeviceCapabilities { @@ -99,10 +125,13 @@ pub struct NetPhyTxToken<'a> { com: &'a Com, loopback_conn: xous::CID, loopback_count: Arc::>>, + caps: ChecksumCapabilities, } impl <'a> NetPhyTxToken<'a> { /// Initiates the Rx side of things to read out the loopback packet that was queued fn loopback_rx(&self, rxlen: usize) { + // this will initiate a target trace + // log::set_max_level(log::LevelFilter::Trace); self.loopback_count.lock().unwrap().push_back(rxlen as u16); xous::try_send_message(self.loopback_conn, xous::Message::new_scalar(crate::Opcode::LoopbackRx.to_usize().unwrap(), rxlen, 0, 0, 0) @@ -147,85 +176,197 @@ impl <'a> NetPhyTxToken<'a> { } impl<'a> phy::TxToken for NetPhyTxToken<'a> { - fn consume(mut self, len: usize, f: F) -> R + fn consume(self, len: usize, f: F) -> R where F: FnOnce(&mut [u8]) -> R { let result = f(&mut self.buf[..len]); - //log::info!("txlen: {}", len); + log::debug!("txlen: {}", len); { // this is a hack to make loopbacks work on smoltcp. Work-around taken from Redox, but tracking this issue as well: // https://github.com/smoltcp-rs/smoltcp/issues/50 and https://github.com/smoltcp-rs/smoltcp/issues/55 // detect an outbound loopback packet, and shove it back in - let mut loopback = false; - if let Ok(mut frame) = smoltcp::wire::EthernetFrame::new_checked(&mut self.buf) { + if let Ok(mut eth_frame) = EthernetFrame::new_checked(&mut self.buf[..len]) { let mut local_hwaddr = [0u8; 6]; local_hwaddr[2..6].copy_from_slice(&MAC_ADDRESS_LSB.load(Ordering::SeqCst).to_be_bytes()); local_hwaddr[0..2].copy_from_slice(&MAC_ADDRESS_MSB.load(Ordering::SeqCst).to_be_bytes()); - if frame.dst_addr() == EthernetAddress::default() { + if eth_frame.dst_addr() == EthernetAddress::default() { log::debug!("loopback packet redirect"); // override the destination address to be our own address - frame.set_dst_addr(smoltcp::wire::EthernetAddress(local_hwaddr)); - loopback = true; - } else if frame.dst_addr().as_bytes() == local_hwaddr { + eth_frame.set_dst_addr(smoltcp::wire::EthernetAddress(local_hwaddr)); + self.com.wlan_queue_loopback(&self.buf[..len]); + self.loopback_rx(len); + return result; + } else if eth_frame.dst_addr().as_bytes() == local_hwaddr { log::debug!("loopback return packet redirect"); - loopback = true; + self.com.wlan_queue_loopback(&self.buf[..len]); + self.loopback_rx(len); + return result; } - } - // NOTE: was protected by if result.is_ok(), but looking at smoltcp, the calling routines - // *always* return OK, or nothing. So we are removing the protecting .is_ok()... - if loopback { - self.com.wlan_queue_loopback(&self.buf[..len]); - self.loopback_rx(len); - } else { - { - // this is a hack to make loopbacks work on smoltcp. Work-around taken from Redox, but tracking this issue as well: - // https://github.com/smoltcp-rs/smoltcp/issues/50 and https://github.com/smoltcp-rs/smoltcp/issues/55 - // this part of the hack finds ARP packets to and from the local device, and responds to them with packet injections - let pkt = &self.buf[..len]; - if let Ok(frame) = EthernetFrame::new_checked(pkt) { - if frame.ethertype() == EthernetProtocol::Arp { - // we're parsing packets that came from our own stack -- they better be OK! - let arp_packet = ArpPacket::new_checked(frame.payload()).unwrap(); - let arp_repr = ArpRepr::parse(&arp_packet).unwrap(); - match arp_repr { - ArpRepr::EthernetIpv4 { - operation, source_hardware_addr, source_protocol_addr, target_protocol_addr, .. - } => { - log::trace!("outgoing arp: {:?} {:?} {:?}", source_hardware_addr, source_protocol_addr, target_protocol_addr); - if target_protocol_addr.as_bytes() == [127, 0, 0, 1] && operation == ArpOperation::Request { - log::trace!("intercepted outgoing arp for 127.0.0.1: {:?}", pkt); - self.wlan_queue_localhost_arp( - source_hardware_addr.as_bytes().try_into().unwrap(), - source_protocol_addr, - EthernetAddress([0, 0, 0, 0, 0, 0,]), - Ipv4Address([127, 0, 0, 1]), - ); - return result; - } else if source_protocol_addr.as_bytes() == [127, 0, 0, 1] && operation == ArpOperation::Request { - // reverse lookup case - log::trace!("intercepted outgoing arp for own IP: {:?} {:?}", target_protocol_addr, pkt); - self.wlan_queue_localhost_arp( - source_hardware_addr.as_bytes().try_into().unwrap(), - source_protocol_addr, - source_hardware_addr, - target_protocol_addr, - ); - return result; - } else { - // don't do anything, pass it on + // make a copy of the packet so we can meet mutability requirements of the routines below... + let mut packet_clone = [0u8; NET_MTU]; + let payload_len = eth_frame.payload_mut().len(); + packet_clone[..payload_len].copy_from_slice(ð_frame.payload_mut()[..payload_len]); + match eth_frame.ethertype() { + EthernetProtocol::Ipv4 => { + if let Ok(packet) = Ipv4Packet::new_checked(&packet_clone[..payload_len]) { + log::debug!("IPV4 packet checksum: {:x} ({:?})", packet.checksum(), packet.verify_checksum()); + if let Ok(ipv4_parsed) = Ipv4Repr::parse(&packet, &self.caps) { + log::debug!("IPV4 parsed: {:?}", ipv4_parsed); + if ipv4_parsed.dst_addr.as_bytes() == [127, 0, 0, 1] { + log::debug!("patching destination 127.0.0.1"); + // patch the destination MAC address + let mut local_hwaddr = [0u8; 6]; + local_hwaddr[2..6].copy_from_slice(&MAC_ADDRESS_LSB.load(Ordering::SeqCst).to_be_bytes()); + local_hwaddr[0..2].copy_from_slice(&MAC_ADDRESS_MSB.load(Ordering::SeqCst).to_be_bytes()); + eth_frame.set_dst_addr(smoltcp::wire::EthernetAddress(local_hwaddr)); + + /* this is no longer necessary in smoltcp 0.9 or later - an interface can bind to multiple sockets, one of which being 127.0.0.1 + // patch the destination IP address + let orig_dst_addr = ipv4_parsed.dst_addr; + ipv4_parsed.dst_addr = smoltcp::wire::Ipv4Address::from_bytes(&IPV4_ADDRESS.load(Ordering::SeqCst).to_be_bytes()); + + // extract the buffer region from the original frame and overwrite it + let payload_buf = eth_frame.payload_mut(); + let mut mut_pkt = Ipv4Packet::new_unchecked(payload_buf); + // recompute inner-checksums for TCP and UDP cases... + match ipv4_parsed.next_header { + IpProtocol::Tcp => { + let tcp_packet = TcpPacket::new_unchecked(packet.payload()); + if let Ok(tcp_repr) = TcpRepr::parse( + &tcp_packet, + &IpAddress::Ipv4(ipv4_parsed.src_addr), + &IpAddress::Ipv4(orig_dst_addr), + &self.caps + ) { + log::trace!("tcp checksum: {:x}", tcp_packet.checksum()); + let mut mut_tcp_packet = TcpPacket::new_unchecked(mut_pkt.payload_mut()); + tcp_repr.emit( + &mut mut_tcp_packet, + &IpAddress::Ipv4(ipv4_parsed.src_addr), + &IpAddress::Ipv4(ipv4_parsed.dst_addr), + &self.caps + ); + log::trace!("tcp new checksum: {:x}", tcp_packet.checksum()); + } else { + log::error!("Transmitted TCP packet did not unpack correctly! checksum: {:?}", tcp_packet.verify_checksum( + &IpAddress::Ipv4(ipv4_parsed.src_addr), &IpAddress::Ipv4(orig_dst_addr))); + } + } + IpProtocol::Udp => { + let udp_packet = UdpPacket::new_unchecked(packet.payload()); + if let Ok(udp_repr) = UdpRepr::parse( + &udp_packet, + &IpAddress::Ipv4(ipv4_parsed.src_addr), + &IpAddress::Ipv4(orig_dst_addr), + &self.caps + ) { + log::debug!("udp checksum: {:x}", udp_packet.checksum()); + let mut mut_udp_packet = UdpPacket::new_unchecked(mut_pkt.payload_mut()); + udp_repr.emit( + &mut mut_udp_packet, + &IpAddress::Ipv4(ipv4_parsed.src_addr), + &IpAddress::Ipv4(ipv4_parsed.dst_addr), + udp_packet.len() as usize, + |buf| buf.copy_from_slice(packet.payload()), + &self.caps + ); + log::debug!("udp new checksum: {:x}", udp_packet.checksum()); + } else { + log::error!("Transmitted UDP packet did not unpack correctly! checksum: {:?}", udp_packet.verify_checksum( + &IpAddress::Ipv4(ipv4_parsed.src_addr), &IpAddress::Ipv4(orig_dst_addr))); + } + } + _ => { + log::warn!("Unhandled packet type in loopback! Checksum will be incorrect."); + } } + + log::trace!("checksum: {:x}", mut_pkt.checksum()); + ipv4_parsed.emit(&mut mut_pkt, &self.caps); + log::trace!("new checksum: {:x}", mut_pkt.checksum()); + */ + + let buf_to_send = eth_frame.into_inner(); + self.com.wlan_queue_loopback(buf_to_send); + /* // for double-checking the RX packet + if let Ok(check_frame) = EthernetFrame::new_checked(&buf_to_send) { + if let Ok(check_pkt) = Ipv4Packet::new_checked(&check_frame.payload()) { + if let Ok(check_parsed) = Ipv4Repr::parse(&check_pkt, &self.caps) { + log::debug!("CHECK: checksum: {:x}, valid: {:?}, patched packet: {:?}", + check_pkt.checksum(), + check_pkt.verify_checksum(), + check_parsed); + } else { + log::debug!("CHECK: FAILED - invalid IPv4 packet"); + } + } else { + log::debug!("CHECK: FAILED - invalid payload"); + } + } else { + log::debug!("CHECK: FAILED - invalid ethernet frame"); + } + */ + self.loopback_rx(len); + // exit here without sending the packet on, because it went to Rx + return result; } - _ => {}, // pass it on } } } + EthernetProtocol::Arp => { + // this is a hack to make loopbacks work on smoltcp. Work-around taken from Redox, but tracking this issue as well: + // https://github.com/smoltcp-rs/smoltcp/issues/50 and https://github.com/smoltcp-rs/smoltcp/issues/55 + // this part of the hack finds ARP packets to and from the local device, and responds to them with packet injections + // we're parsing packets that came from our own stack -- they better be OK! + let arp_packet = ArpPacket::new_checked(eth_frame.payload_mut()).unwrap(); + let arp_repr = ArpRepr::parse(&arp_packet).unwrap(); + match arp_repr { + ArpRepr::EthernetIpv4 { + operation, source_hardware_addr, source_protocol_addr, target_protocol_addr, .. + } => { + log::debug!("outgoing arp: {:?} {:?} {:?}", source_hardware_addr, source_protocol_addr, target_protocol_addr); + let local_addr = IPV4_ADDRESS.load(Ordering::SeqCst).to_be_bytes(); + if (target_protocol_addr.as_bytes() == [127, 0, 0, 1] + || target_protocol_addr.as_bytes() == local_addr) + && operation == ArpOperation::Request { + log::debug!("intercepted outgoing arp for localhost: {:?}", arp_repr); + let mut local_hwaddr = [0u8; 6]; + local_hwaddr[2..6].copy_from_slice(&MAC_ADDRESS_LSB.load(Ordering::SeqCst).to_be_bytes()); + local_hwaddr[0..2].copy_from_slice(&MAC_ADDRESS_MSB.load(Ordering::SeqCst).to_be_bytes()); + self.wlan_queue_localhost_arp( + source_hardware_addr.as_bytes().try_into().unwrap(), + source_protocol_addr, + EthernetAddress(local_hwaddr), + Ipv4Address(target_protocol_addr.as_bytes().try_into().unwrap()), + ); + return result; + } /* else if (source_protocol_addr.as_bytes() == [127, 0, 0, 1] + || source_protocol_addr.as_bytes() == local_addr) + && operation == ArpOperation::Request { + // reverse lookup case + log::debug!("intercepted outgoing arp for own IP: {:?} {:?}", target_protocol_addr, arp_repr); + self.wlan_queue_localhost_arp( + source_hardware_addr.as_bytes().try_into().unwrap(), + source_protocol_addr, + source_hardware_addr, + target_protocol_addr, + ); + return result; + } else { + // don't do anything, pass it on + } */ + } + _ => {}, // pass it on + } + } + _ => {} } - - // normally this would be the only line! - self.com.wlan_send_packet(&self.buf[..len]).expect("driver error sending WLAN packet"); } } + // forward the packet on if it's not a loopback (loopback will call return early and exit before getting to this line) + self.com.wlan_send_packet(&self.buf[..len]).expect("driver error sending WLAN packet"); + result } } \ No newline at end of file diff --git a/services/net/src/main.rs b/services/net/src/main.rs index 2d4d5aa25..e7b85e283 100644 --- a/services/net/src/main.rs +++ b/services/net/src/main.rs @@ -56,7 +56,7 @@ const PING_IDENT: u16 = 0x22b; /// Anything smaller than 1 ms is rounded up to 1ms; increasing this /// number saves power. In general, most network events create an interrupt /// so the poll interval should be OK to be set quite high. -const NET_DEFAULT_POLL_MS: u64 = 500; +const NET_DEFAULT_POLL_MS: u64 = 900; #[derive(num_derive::FromPrimitive, num_derive::ToPrimitive, Debug)] enum WaitOp { @@ -145,7 +145,7 @@ fn set_com_ints(com_int_list: &mut Vec) { fn main() -> ! { log_server::init_wait().unwrap(); - log::set_max_level(log::LevelFilter::Debug); + log::set_max_level(log::LevelFilter::Info); log::info!("my PID is {}", xous::process::id()); let xns = xous_names::XousNames::new().unwrap(); @@ -207,49 +207,14 @@ fn main() -> ! { log::trace!("{}", _printer); }); let device_caps = device.capabilities(); - let mut iface = Interface::new(config, &mut device, Instant::now()); + let mut iface = Interface::new(config, &mut device, Instant::from_millis(timer.elapsed_ms() as i64)); // Create sockets - /* - let udp_rx_buffer = udp::PacketBuffer::new( - vec![udp::PacketMetadata::EMPTY, udp::PacketMetadata::EMPTY], - vec![0; 65535], - ); - let udp_tx_buffer = udp::PacketBuffer::new( - vec![udp::PacketMetadata::EMPTY, udp::PacketMetadata::EMPTY], - vec![0; 65535], - ); - let udp_socket = udp::Socket::new(udp_rx_buffer, udp_tx_buffer); - - let tcp1_rx_buffer = tcp::SocketBuffer::new(vec![0; 65535]); - let tcp1_tx_buffer = tcp::SocketBuffer::new(vec![0; 65535]); - let tcp1_socket = tcp::Socket::new(tcp1_rx_buffer, tcp1_tx_buffer); - - let tcp2_rx_buffer = tcp::SocketBuffer::new(vec![0; 65535]); - let tcp2_tx_buffer = tcp::SocketBuffer::new(vec![0; 65535]); - let tcp2_socket = tcp::Socket::new(tcp2_rx_buffer, tcp2_tx_buffer); - - let tcp3_rx_buffer = tcp::SocketBuffer::new(vec![0; 65535]); - let tcp3_tx_buffer = tcp::SocketBuffer::new(vec![0; 65535]); - let tcp3_socket = tcp::Socket::new(tcp3_rx_buffer, tcp3_tx_buffer); - - let tcp4_rx_buffer = tcp::SocketBuffer::new(vec![0; 65535]); - let tcp4_tx_buffer = tcp::SocketBuffer::new(vec![0; 65535]); - let tcp4_socket = tcp::Socket::new(tcp4_rx_buffer, tcp4_tx_buffer); - */ - let icmp_rx_buffer = icmp::PacketBuffer::new(vec![icmp::PacketMetadata::EMPTY], vec![0; 256]); let icmp_tx_buffer = icmp::PacketBuffer::new(vec![icmp::PacketMetadata::EMPTY], vec![0; 256]); let icmp_socket = icmp::Socket::new(icmp_rx_buffer, icmp_tx_buffer); let mut sockets = SocketSet::new(vec![]); - /* - let udp_handle = sockets.add(udp_socket); - let tcp1_handle = sockets.add(tcp1_socket); - let tcp2_handle = sockets.add(tcp2_socket); - let tcp3_handle = sockets.add(tcp3_socket); - let tcp4_handle = sockets.add(tcp4_socket); - */ let icmp_handle = sockets.add(icmp_socket); { // put in a block to retire the icmp_socket variable in this scope let icmp_socket = sockets.get_mut::(icmp_handle); @@ -363,18 +328,19 @@ fn main() -> ! { }); let mut self_sender: Option:: = None; loop { - let timestamp = Instant::now(); + let now = timer.elapsed_ms(); + let timestamp = Instant::from_millis(now as i64); let deadline = match iface.poll_at(timestamp, &sockets) { Some(poll_at) if timestamp < poll_at => poll_at - timestamp, _ => Duration::from_millis(NET_DEFAULT_POLL_MS), }; - let msg_or_timeout = core_rx.recv_timeout( std::time::Duration::from_millis(deadline.millis()) ); let mut msg = match msg_or_timeout { Ok(m) => m, Err(std::sync::mpsc::RecvTimeoutError::Timeout) => { + log::trace!("poll timeout; issuing NetPump"); // originate a Pump call when a timeout is reached xous::envelope::Envelope { // self_sender should be safe to unwrap because it is the first thing @@ -410,7 +376,11 @@ fn main() -> ! { } let op = FromPrimitive::from_usize(msg.body.id() & 0x7fff); let nonblocking = (msg.body.id() & NONBLOCKING_FLAG) != 0; - log::debug!("{:?}", op); + if op != Some(Opcode::NetPump) { + log::debug!("{:?}", op); + } else { + log::trace!("{:?}", op); + } match op { Some(Opcode::SetupMpsc) => { self_sender = Some(msg.sender.to_usize()); @@ -422,10 +392,10 @@ fn main() -> ! { }; let mut pkt = buf.to_original::().unwrap(); - let timestamp = Instant::now(); + let timestamp = Instant::from_millis(timer.elapsed_ms() as i64); iface.poll(timestamp, &mut device, &mut sockets); - let timestamp = Instant::now(); + let timestamp = Instant::from_millis(timer.elapsed_ms() as i64); let socket = sockets.get_mut::(icmp_handle); if !socket.is_open() { socket.bind(icmp::Endpoint::Ident(PING_IDENT)).unwrap(); @@ -1031,7 +1001,6 @@ fn main() -> ! { let socket = sockets.get_mut::(*connection); let args = msg.body.scalar_message().unwrap(); let no_delay = args.arg1 != 0; - log::warn!("Setting nagle to {}, see issue #210 about readback!", !no_delay); socket.set_nagle_enabled(!no_delay); xous::return_scalar(msg.sender, 0).ok(); } else { @@ -1169,6 +1138,7 @@ fn main() -> ! { if config.addr != [127, 0, 0, 1] { // note: ARP cache is stale. Maybe that's ok? iface.update_ip_addrs(|ip_addrs| { + ip_addrs.clear(); ip_addrs .push(IpCidr::new(IpAddress::v4( config.addr[0], @@ -1177,9 +1147,15 @@ fn main() -> ! { config.addr[3], ), 24)) .unwrap(); + // ...and the loopback interface + ip_addrs + .push(IpCidr::new(IpAddress::v4( + 127, 0, 0, 1 + ), 8)) + .unwrap(); }); } else { - log::info!("not updating loopback address"); + log::warn!("Attempt to update the loopback interface! Ignoring."); } // reset the default route, in case it has changed iface.routes_mut().remove_default_ipv4_route(); @@ -1310,12 +1286,15 @@ fn main() -> ! { let timestamp = Instant::from_millis(now as i64); if !iface.poll(timestamp, &mut device, &mut sockets) { // nothing to do, continue on. + log::debug!("No change to socket readiness"); continue + } else { + log::debug!("Socket readiness changed"); } // Connect calls take time to establish. This block checks to see if connections // have been made and issues callbacks as necessary. - log::trace!("pump: tcpconnect"); + // log::trace!("pump: tcpconnect"); for connection in tcp_connect_waiting.iter_mut() { let socket; let (env, _handle, fd, local_port, remote_port) = { @@ -1345,7 +1324,7 @@ fn main() -> ! { } // This block handles TCP Rx for libstd callers - log::trace!("pump: tcp rx"); + // log::trace!("pump: tcp rx"); for connection in tcp_rx_waiting.iter_mut() { let socket; let WaitingSocket { @@ -1418,7 +1397,7 @@ fn main() -> ! { } // This block handles TCP Peek for libstd callers - log::trace!("pump: tcp peek"); + // log::trace!("pump: tcp peek"); for connection in tcp_peek_waiting.iter_mut() { let socket; let WaitingSocket { @@ -1491,7 +1470,7 @@ fn main() -> ! { } // This block handles TCP Tx for libstd callers - log::trace!("pump: tcp tx"); + // log::trace!("pump: tcp tx"); for connection in tcp_tx_waiting.iter_mut() { let socket; let WaitingSocket { @@ -1559,7 +1538,7 @@ fn main() -> ! { } // this handles TCP std listeners - log::trace!("pump: tcp listen"); + // log::trace!("pump: tcp listen"); for connection in tcp_accept_waiting.iter_mut() { let ep: IpEndpoint; let AcceptingSocket { @@ -1586,7 +1565,7 @@ fn main() -> ! { } // this block handles StdUdp - log::trace!("pump: udp"); + // log::trace!("pump: udp"); for connection in udp_rx_waiting.iter_mut() { let socket; let UdpStdState { @@ -1657,7 +1636,7 @@ fn main() -> ! { } } - log::trace!("pump: tcp close"); + // log::trace!("pump: tcp close"); tcp_tx_closing.retain(|(handle, sender)| { if std_tcp_can_close(&tcp_tx_waiting, *handle) { let socket = sockets.get_mut::(*handle); @@ -1726,7 +1705,7 @@ fn main() -> ! { }); // this block contains the ICMP Rx handler. Tx is initiated by an incoming message to the Net crate. - log::trace!("pump: icmp"); + // log::trace!("pump: icmp"); { let socket = sockets.get_mut::(icmp_handle); if !socket.is_open() { @@ -1905,7 +1884,7 @@ fn main() -> ! { } } // this block handles ICMP retirement; it runs everytime we pump the block - log::trace!("pump: icmp retirement"); + // log::trace!("pump: icmp retirement"); { // notify the callback to drop its connection, because the queue is now empty // do this before we clear the queue, because we want the Drop message to come on the iteration @@ -1946,6 +1925,8 @@ fn main() -> ! { } ); } + // use this to revert targeted tracing + // log::set_max_level(log::LevelFilter::Info); }), Some(Opcode::GetIpv4Config) => { let mut buffer = unsafe { diff --git a/services/shellchat/Cargo.toml b/services/shellchat/Cargo.toml index 671557f04..679f35ec9 100644 --- a/services/shellchat/Cargo.toml +++ b/services/shellchat/Cargo.toml @@ -132,4 +132,4 @@ websocket = ["tls", "tungstenite", "url"] shellperf = ["ring", "perflib", "xous/v2p", "random-pick"] # this also needs the project-wide "perfcounter" feature to be selected. shellchat is the exclusive manager of the performance counter, do not use with e.g. "vaultperf" feature extra-tests = [] mass-storage = [] -default = [] # "debugprint" +default = ["nettest"] # "debugprint" diff --git a/services/shellchat/src/nettests.rs b/services/shellchat/src/nettests.rs index a45c16531..08ed982e9 100644 --- a/services/shellchat/src/nettests.rs +++ b/services/shellchat/src/nettests.rs @@ -10,9 +10,9 @@ use std::sync::atomic::{AtomicUsize, Ordering}; pub(crate) fn start_batch_tests() { let _ = thread::spawn({ move || { - let run_passing = true; + let run_passing = false; let tt = ticktimer_server::Ticktimer::new().unwrap(); - const PRINT_DELAY: usize = 3000; + const PRINT_DELAY: usize = 2000; if run_passing { log::info!("################################################## bind_error"); tt.sleep_ms(PRINT_DELAY).ok(); @@ -32,6 +32,18 @@ pub(crate) fn start_batch_tests() { log::info!("################################################## read_eof"); tt.sleep_ms(PRINT_DELAY).ok(); read_eof(); + + // This test can fail if there is a ticktimer scheduling error: + /* + INFO:shellchat::nettests: ################################################## write_close (services\shellchat\src\nettests.rs:35) + INFO:shellchat::nettests: ++++++++++++++++++++++++++create server (services\shellchat\src\nettests.rs:252) + INFO:shellchat::nettests: ++++++++++++++++++++++++++try to establish connection (services\shellchat\src\nettests.rs:265) + INFO:shellchat::nettests: ++++++++++++++++++++++++++established (services\shellchat\src\nettests.rs:267) + INFO:shellchat::nettests: ----------------------------create and drop connection to server (services\shellchat\src\nettests.rs:257) + INFO:shellchat::nettests: ----------------------------signal that we should proceed to send the data to the closed server (services\shellchat\src\nettests.rs:262) + ERR :xous_ticktimer: requested to wake 1 entries, which is more than the current 2 waiting entries (services\xous-ticktimer\src\main.rs:429) + -- hangs here forever. + */ log::info!("################################################## write_close"); tt.sleep_ms(PRINT_DELAY).ok(); write_close(); @@ -49,9 +61,9 @@ pub(crate) fn start_batch_tests() { tt.sleep_ms(PRINT_DELAY).ok(); write_vectored(); - // This test cannot be run until issue #210 is fixed see https://github.com/betrusted-io/xous-core/issues/210 - //log::info!("################################################## nodelay"); - //nodelay(); + log::info!("################################################## nodelay"); + nodelay(); + tt.sleep_ms(PRINT_DELAY).ok(); log::info!("################################################## ttl"); tt.sleep_ms(PRINT_DELAY).ok(); ttl(); @@ -90,14 +102,15 @@ pub(crate) fn start_batch_tests() { log::info!("################################################## clone_while_reading"); tt.sleep_ms(PRINT_DELAY).ok(); clone_while_reading(); - log::info!("################################################## clone_accept_smoke"); - tt.sleep_ms(PRINT_DELAY).ok(); - clone_accept_smoke(); - log::info!("################################################## clone_accept_concurrent"); - tt.sleep_ms(PRINT_DELAY).ok(); - clone_accept_concurrent(); } + log::info!("################################################## clone_accept_smoke"); + tt.sleep_ms(PRINT_DELAY).ok(); + clone_accept_smoke(); + log::info!("################################################## clone_accept_concurrent"); + tt.sleep_ms(PRINT_DELAY).ok(); + clone_accept_concurrent(); + log::info!("################################################## multiple_connect_serial"); tt.sleep_ms(PRINT_DELAY).ok(); multiple_connect_serial();