diff --git a/Kernel/Net/NetworkTask.cpp b/Kernel/Net/NetworkTask.cpp index 89d2ad1d18..868997cc7f 100644 --- a/Kernel/Net/NetworkTask.cpp +++ b/Kernel/Net/NetworkTask.cpp @@ -1,5 +1,5 @@ /* - * Copyright (c) 2018-2020, Andreas Kling + * Copyright (c) 2018-2021, Andreas Kling * All rights reserved. * * Redistribution and use in source and binary forms, with or without @@ -73,7 +73,12 @@ void NetworkTask_main(void*) adapter.set_ipv4_gateway({ 10, 0, 2, 2 }); } - klog() << "NetworkTask: " << adapter.class_name() << " network adapter found: hw=" << adapter.mac_address().to_string().characters() << " address=" << adapter.ipv4_address().to_string().characters() << " netmask=" << adapter.ipv4_netmask().to_string().characters() << " gateway=" << adapter.ipv4_gateway().to_string().characters(); + dmesgln("NetworkTask: {} network adapter found: hw={}, ipv4_address={}, ipv4_netmask={}, ipv4_gateway={}", + adapter.class_name(), + adapter.mac_address().to_string(), + adapter.ipv4_address(), + adapter.ipv4_netmask(), + adapter.ipv4_gateway()); adapter.on_receive = [&]() { pending_packets++; @@ -90,9 +95,7 @@ void NetworkTask_main(void*) return; packet_size = adapter.dequeue_packet(buffer, buffer_size, packet_timestamp); pending_packets--; -#if NETWORK_TASK_DEBUG - klog() << "NetworkTask: Dequeued packet from " << adapter.name().characters() << " (" << packet_size << " bytes)"; -#endif + dbgln_if(NETWORK_TASK_DEBUG, "NetworkTask: Dequeued packet from {} ({} bytes)", adapter.name(), packet_size); }); return packet_size; }; @@ -102,7 +105,6 @@ void NetworkTask_main(void*) auto buffer = (u8*)buffer_region->vaddr().get(); Time packet_timestamp; - klog() << "NetworkTask: Enter main loop."; for (;;) { size_t packet_size = dequeue_packet(buffer, buffer_size, packet_timestamp); if (!packet_size) { @@ -110,33 +112,11 @@ void NetworkTask_main(void*) continue; } if (packet_size < sizeof(EthernetFrameHeader)) { - klog() << "NetworkTask: Packet is too small to be an Ethernet packet! (" << packet_size << ")"; + dbgln("NetworkTask: Packet is too small to be an Ethernet packet! ({})", packet_size); continue; } auto& eth = *(const EthernetFrameHeader*)buffer; -#if ETHERNET_DEBUG - dbgln("NetworkTask: From {} to {}, ether_type={:#04x}, packet_size={}", eth.source().to_string(), eth.destination().to_string(), eth.ether_type(), packet_size); -#endif - -#if ETHERNET_VERY_DEBUG - for (size_t i = 0; i < packet_size; i++) { - klog() << String::format("%#02x", buffer[i]); - - switch (i % 16) { - case 7: - klog() << " "; - break; - case 15: - klog() << ""; - break; - default: - klog() << " "; - break; - } - } - - klog() << ""; -#endif + dbgln_if(ETHERNET_DEBUG, "NetworkTask: From {} to {}, ether_type={:#04x}, packet_size={}", eth.source().to_string(), eth.destination().to_string(), eth.ether_type(), packet_size); switch (eth.ether_type()) { case EtherType::ARP: @@ -149,7 +129,7 @@ void NetworkTask_main(void*) // ignore break; default: - klog() << "NetworkTask: Unknown ethernet type 0x" << String::format("%x", eth.ether_type()); + dbgln("NetworkTask: Unknown ethernet type {:#04x}", eth.ether_type()); } } } @@ -158,7 +138,7 @@ void handle_arp(const EthernetFrameHeader& eth, size_t frame_size) { constexpr size_t minimum_arp_frame_size = sizeof(EthernetFrameHeader) + sizeof(ARPPacket); if (frame_size < minimum_arp_frame_size) { - klog() << "handle_arp: Frame too small (" << frame_size << ", need " << minimum_arp_frame_size << ")"; + dbgln("handle_arp: Frame too small ({}, need {})", frame_size, minimum_arp_frame_size); return; } auto& packet = *static_cast(eth.payload()); @@ -171,14 +151,12 @@ void handle_arp(const EthernetFrameHeader& eth, size_t frame_size) return; } -#if ARP_DEBUG - dbgln("handle_arp: operation={:#04x}, sender={}/{}, target={}/{}", + dbgln_if(ARP_DEBUG, "handle_arp: operation={:#04x}, sender={}/{}, target={}/{}", packet.operation(), packet.sender_hardware_address().to_string(), packet.sender_protocol_address().to_string(), packet.target_hardware_address().to_string(), packet.target_protocol_address().to_string()); -#endif if (!packet.sender_hardware_address().is_zero() && !packet.sender_protocol_address().is_zero()) { // Someone has this IPv4 address. I guess we can try to remember that. @@ -191,7 +169,7 @@ void handle_arp(const EthernetFrameHeader& eth, size_t frame_size) // Who has this IP address? if (auto adapter = NetworkAdapter::from_ipv4_address(packet.target_protocol_address())) { // We do! - klog() << "handle_arp: Responding to ARP request for my IPv4 address (" << adapter->ipv4_address().to_string().characters() << ")"; + dbgln("handle_arp: Responding to ARP request for my IPv4 address ({})", adapter->ipv4_address()); ARPPacket response; response.set_operation(ARPOperation::Response); response.set_target_hardware_address(packet.sender_hardware_address()); @@ -209,25 +187,23 @@ void handle_ipv4(const EthernetFrameHeader& eth, size_t frame_size, const Time& { constexpr size_t minimum_ipv4_frame_size = sizeof(EthernetFrameHeader) + sizeof(IPv4Packet); if (frame_size < minimum_ipv4_frame_size) { - klog() << "handle_ipv4: Frame too small (" << frame_size << ", need " << minimum_ipv4_frame_size << ")"; + dbgln("handle_ipv4: Frame too small ({}, need {})", frame_size, minimum_ipv4_frame_size); return; } auto& packet = *static_cast(eth.payload()); if (packet.length() < sizeof(IPv4Packet)) { - klog() << "handle_ipv4: IPv4 packet too short (" << packet.length() << ", need " << sizeof(IPv4Packet) << ")"; + dbgln("handle_ipv4: IPv4 packet too short ({}, need {})", packet.length(), sizeof(IPv4Packet)); return; } size_t actual_ipv4_packet_length = frame_size - sizeof(EthernetFrameHeader); if (packet.length() > actual_ipv4_packet_length) { - klog() << "handle_ipv4: IPv4 packet claims to be longer than it is (" << packet.length() << ", actually " << actual_ipv4_packet_length << ")"; + dbgln("handle_ipv4: IPv4 packet claims to be longer than it is ({}, actually {})", packet.length(), actual_ipv4_packet_length); return; } -#if IPV4_DEBUG - klog() << "handle_ipv4: source=" << packet.source().to_string().characters() << ", target=" << packet.destination().to_string().characters(); -#endif + dbgln_if(IPV4_DEBUG, "handle_ipv4: source={}, destination={}", packet.source(), packet.destination()); switch ((IPv4Protocol)packet.protocol()) { case IPv4Protocol::ICMP: @@ -237,7 +213,7 @@ void handle_ipv4(const EthernetFrameHeader& eth, size_t frame_size, const Time& case IPv4Protocol::TCP: return handle_tcp(packet, packet_timestamp); default: - klog() << "handle_ipv4: Unhandled protocol " << packet.protocol(); + dbgln("handle_ipv4: Unhandled protocol {:#02x}", packet.protocol()); break; } } @@ -245,9 +221,7 @@ void handle_ipv4(const EthernetFrameHeader& eth, size_t frame_size, const Time& void handle_icmp(const EthernetFrameHeader& eth, const IPv4Packet& ipv4_packet, const Time& packet_timestamp) { auto& icmp_header = *static_cast(ipv4_packet.payload()); -#if ICMP_DEBUG - dbgln("handle_icmp: source={}, destination={}, type={:#02x}, code={:#02x}", ipv4_packet.source().to_string(), ipv4_packet.destination().to_string(), icmp_header.type(), icmp_header.code()); -#endif + dbgln_if(ICMP_DEBUG, "handle_icmp: source={}, destination={}, type={:#02x}, code={:#02x}", ipv4_packet.source().to_string(), ipv4_packet.destination().to_string(), icmp_header.type(), icmp_header.code()); { NonnullRefPtrVector icmp_sockets; @@ -269,10 +243,10 @@ void handle_icmp(const EthernetFrameHeader& eth, const IPv4Packet& ipv4_packet, if (icmp_header.type() == ICMPType::EchoRequest) { auto& request = reinterpret_cast(icmp_header); - klog() << "handle_icmp: EchoRequest from " << ipv4_packet.source().to_string().characters() << ": id=" << (u16)request.identifier << ", seq=" << (u16)request.sequence_number; + dbgln("handle_icmp: EchoRequest from {}: id={}, seq={}", ipv4_packet.source(), (u16)request.identifier, (u16)request.sequence_number); size_t icmp_packet_size = ipv4_packet.payload_size(); if (icmp_packet_size < sizeof(ICMPEchoPacket)) { - klog() << "handle_icmp: EchoRequest packet is too small, ignoring."; + dbgln("handle_icmp: EchoRequest packet is too small, ignoring."); return; } auto buffer = ByteBuffer::create_zeroed(icmp_packet_size); @@ -293,24 +267,25 @@ void handle_icmp(const EthernetFrameHeader& eth, const IPv4Packet& ipv4_packet, void handle_udp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) { if (ipv4_packet.payload_size() < sizeof(UDPPacket)) { - klog() << "handle_udp: Packet too small (" << ipv4_packet.payload_size() << ", need " << sizeof(UDPPacket) << ")"; + dbgln("handle_udp: Packet too small ({}, need {})", ipv4_packet.payload_size(), sizeof(UDPPacket)); return; } auto adapter = NetworkAdapter::from_ipv4_address(ipv4_packet.destination()); if (!adapter && ipv4_packet.destination() != IPv4Address(255, 255, 255, 255)) { - klog() << "handle_udp: this packet is not for me, it's for " << ipv4_packet.destination().to_string().characters(); + dbgln("handle_udp: this packet is not for me, it's for {}", ipv4_packet.destination()); return; } auto& udp_packet = *static_cast(ipv4_packet.payload()); -#if UDP_DEBUG - klog() << "handle_udp: source=" << ipv4_packet.source().to_string().characters() << ":" << udp_packet.source_port() << ", destination=" << ipv4_packet.destination().to_string().characters() << ":" << udp_packet.destination_port() << " length=" << udp_packet.length(); -#endif + dbgln_if(UDP_DEBUG, "handle_udp: source={}:{}, destination={}:{}, length={}", + ipv4_packet.source(), udp_packet.source_port(), + ipv4_packet.destination(), udp_packet.destination_port(), + udp_packet.length()); auto socket = UDPSocket::from_port(udp_packet.destination_port()); if (!socket) { - klog() << "handle_udp: No UDP socket for port " << udp_packet.destination_port(); + dbgln("handle_udp: No local UDP socket for {}:{}", ipv4_packet.destination(), udp_packet.destination_port()); return; } @@ -322,7 +297,7 @@ void handle_udp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) { if (ipv4_packet.payload_size() < sizeof(TCPPacket)) { - klog() << "handle_tcp: IPv4 payload is too small to be a TCP packet (" << ipv4_packet.payload_size() << ", need " << sizeof(TCPPacket) << ")"; + dbgln("handle_tcp: IPv4 payload is too small to be a TCP packet ({}, need {})", ipv4_packet.payload_size(), sizeof(TCPPacket)); return; } @@ -331,18 +306,17 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) size_t minimum_tcp_header_size = 5 * sizeof(u32); size_t maximum_tcp_header_size = 15 * sizeof(u32); if (tcp_packet.header_size() < minimum_tcp_header_size || tcp_packet.header_size() > maximum_tcp_header_size) { - klog() << "handle_tcp: TCP packet header has invalid size " << tcp_packet.header_size(); + dbgln("handle_tcp: TCP packet header has invalid size {}", tcp_packet.header_size()); } if (ipv4_packet.payload_size() < tcp_packet.header_size()) { - klog() << "handle_tcp: IPv4 payload is smaller than TCP header claims (" << ipv4_packet.payload_size() << ", supposedly " << tcp_packet.header_size() << ")"; + dbgln("handle_tcp: IPv4 payload is smaller than TCP header claims ({}, supposedly {})", ipv4_packet.payload_size(), tcp_packet.header_size()); return; } size_t payload_size = ipv4_packet.payload_size() - tcp_packet.header_size(); -#if TCP_DEBUG - dbgln("handle_tcp: source={}:{}, destination={}:{}, seq_no={}, ack_no={}, flags={:#04x} ({}{}{}{}), window_size={}, payload_size={}", + dbgln_if(TCP_DEBUG, "handle_tcp: source={}:{}, destination={}:{}, seq_no={}, ack_no={}, flags={:#04x} ({}{}{}{}), window_size={}, payload_size={}", ipv4_packet.source().to_string(), tcp_packet.source_port(), ipv4_packet.destination().to_string(), @@ -356,19 +330,16 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) tcp_packet.has_rst() ? "RST " : "", tcp_packet.window_size(), payload_size); -#endif auto adapter = NetworkAdapter::from_ipv4_address(ipv4_packet.destination()); if (!adapter) { - klog() << "handle_tcp: this packet is not for me, it's for " << ipv4_packet.destination().to_string().characters(); + dbgln("handle_tcp: this packet is not for me, it's for {}", ipv4_packet.destination()); return; } IPv4SocketTuple tuple(ipv4_packet.destination(), tcp_packet.destination_port(), ipv4_packet.source(), tcp_packet.source_port()); -#if TCP_DEBUG - klog() << "handle_tcp: looking for socket; tuple=" << tuple.to_string().characters(); -#endif + dbgln_if(TCP_DEBUG, "handle_tcp: looking for socket; tuple={}", tuple.to_string()); auto socket = TCPSocket::from_tuple(tuple); if (!socket) { @@ -394,40 +365,34 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) VERIFY(socket->type() == SOCK_STREAM); VERIFY(socket->local_port() == tcp_packet.destination_port()); -#if TCP_DEBUG - klog() << "handle_tcp: got socket; state=" << socket->tuple().to_string().characters() << " " << TCPSocket::to_string(socket->state()); -#endif + dbgln_if(TCP_DEBUG, "handle_tcp: got socket {}; state={}", socket->tuple().to_string(), TCPSocket::to_string(socket->state())); socket->receive_tcp_packet(tcp_packet, ipv4_packet.payload_size()); [[maybe_unused]] int unused_rc {}; switch (socket->state()) { case TCPSocket::State::Closed: - klog() << "handle_tcp: unexpected flags in Closed state"; + dbgln("handle_tcp: unexpected flags in Closed state"); // TODO: we may want to send an RST here, maybe as a configurable option return; case TCPSocket::State::TimeWait: - klog() << "handle_tcp: unexpected flags in TimeWait state"; + dbgln("handle_tcp: unexpected flags in TimeWait state"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; case TCPSocket::State::Listen: switch (tcp_packet.flags()) { case TCPFlags::SYN: { -#if TCP_DEBUG - klog() << "handle_tcp: incoming connection"; -#endif + dbgln_if(TCP_DEBUG, "handle_tcp: incoming connection"); auto& local_address = ipv4_packet.destination(); auto& peer_address = ipv4_packet.source(); auto client = socket->create_client(local_address, tcp_packet.destination_port(), peer_address, tcp_packet.source_port()); if (!client) { - klog() << "handle_tcp: couldn't create client socket"; + dmesgln("handle_tcp: couldn't create client socket"); return; } LOCKER(client->lock()); -#if TCP_DEBUG - klog() << "handle_tcp: created new client socket with tuple " << client->tuple().to_string().characters(); -#endif + dbgln_if(TCP_DEBUG, "handle_tcp: created new client socket with tuple {}", client->tuple().to_string()); client->set_sequence_number(1000); client->set_ack_number(tcp_packet.sequence_number() + payload_size + 1); [[maybe_unused]] auto rc2 = client->send_tcp_packet(TCPFlags::SYN | TCPFlags::ACK); @@ -435,7 +400,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) return; } default: - klog() << "handle_tcp: unexpected flags in Listen state"; + dbgln("handle_tcp: unexpected flags in Listen state"); // socket->send_tcp_packet(TCPFlags::RST); return; } @@ -468,7 +433,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) socket->set_setup_state(Socket::SetupState::Completed); return; default: - klog() << "handle_tcp: unexpected flags in SynSent state"; + dbgln("handle_tcp: unexpected flags in SynSent state"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); socket->set_error(TCPSocket::Error::UnexpectedFlagsDuringConnect); @@ -483,7 +448,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) switch (socket->direction()) { case TCPSocket::Direction::Incoming: if (!socket->has_originator()) { - klog() << "handle_tcp: connection doesn't have an originating socket; maybe it went away?"; + dbgln("handle_tcp: connection doesn't have an originating socket; maybe it went away?"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -499,7 +464,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) socket->set_connected(true); return; default: - klog() << "handle_tcp: got ACK in SynReceived state but direction is invalid (" << TCPSocket::to_string(socket->direction()) << ")"; + dbgln("handle_tcp: got ACK in SynReceived state but direction is invalid ({})", TCPSocket::to_string(socket->direction())); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -507,7 +472,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) return; default: - klog() << "handle_tcp: unexpected flags in SynReceived state"; + dbgln("handle_tcp: unexpected flags in SynReceived state"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -515,7 +480,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) case TCPSocket::State::CloseWait: switch (tcp_packet.flags()) { default: - klog() << "handle_tcp: unexpected flags in CloseWait state"; + dbgln("handle_tcp: unexpected flags in CloseWait state"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -527,7 +492,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) socket->set_state(TCPSocket::State::Closed); return; default: - klog() << "handle_tcp: unexpected flags in LastAck state"; + dbgln("handle_tcp: unexpected flags in LastAck state"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -543,7 +508,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) socket->set_state(TCPSocket::State::Closing); return; default: - klog() << "handle_tcp: unexpected flags in FinWait1 state"; + dbgln("handle_tcp: unexpected flags in FinWait1 state"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -558,7 +523,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) socket->set_state(TCPSocket::State::Closed); return; default: - klog() << "handle_tcp: unexpected flags in FinWait2 state"; + dbgln("handle_tcp: unexpected flags in FinWait2 state"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -570,7 +535,7 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) socket->set_state(TCPSocket::State::TimeWait); return; default: - klog() << "handle_tcp: unexpected flags in Closing state"; + dbgln("handle_tcp: unexpected flags in Closing state"); unused_rc = socket->send_tcp_packet(TCPFlags::RST); socket->set_state(TCPSocket::State::Closed); return; @@ -589,9 +554,8 @@ void handle_tcp(const IPv4Packet& ipv4_packet, const Time& packet_timestamp) socket->set_ack_number(tcp_packet.sequence_number() + payload_size); -#if TCP_DEBUG - klog() << "Got packet with ack_no=" << tcp_packet.ack_number() << ", seq_no=" << tcp_packet.sequence_number() << ", payload_size=" << payload_size << ", acking it with new ack_no=" << socket->ack_number() << ", seq_no=" << socket->sequence_number(); -#endif + dbgln_if(TCP_DEBUG, "Got packet with ack_no={}, seq_no={}, payload_size={}, acking it with new ack_no={}, seq_no={}", + tcp_packet.ack_number(), tcp_packet.sequence_number(), payload_size, socket->ack_number(), socket->sequence_number()); if (payload_size) { if (socket->did_receive(ipv4_packet.source(), tcp_packet.source_port(), KBuffer::copy(&ipv4_packet, sizeof(IPv4Packet) + ipv4_packet.payload_size()), packet_timestamp))