diff --git a/client/firewall/uspfilter/conntrack/icmp.go b/client/firewall/uspfilter/conntrack/icmp.go index 509c1549bce..50b663642c5 100644 --- a/client/firewall/uspfilter/conntrack/icmp.go +++ b/client/firewall/uspfilter/conntrack/icmp.go @@ -221,7 +221,7 @@ func (t *ICMPTracker) track( // non echo requests don't need tracking if typ != uint8(layers.ICMPv4TypeEchoRequest) { - t.logger.Trace("New %s ICMP connection %s - %s", direction, key, icmpInfo) + t.logger.Trace3("New %s ICMP connection %s - %s", direction, key, icmpInfo) t.sendStartEvent(direction, srcIP, dstIP, typ, code, ruleId, size) return } @@ -243,7 +243,7 @@ func (t *ICMPTracker) track( t.connections[key] = conn t.mutex.Unlock() - t.logger.Trace("New %s ICMP connection %s - %s", direction, key, icmpInfo) + t.logger.Trace3("New %s ICMP connection %s - %s", direction, key, icmpInfo) t.sendEvent(nftypes.TypeStart, conn, ruleId) } @@ -294,7 +294,7 @@ func (t *ICMPTracker) cleanup() { if conn.timeoutExceeded(t.timeout) { delete(t.connections, key) - t.logger.Trace("Removed ICMP connection %s (timeout) [in: %d Pkts/%d B out: %d Pkts/%d B]", + t.logger.Trace5("Removed ICMP connection %s (timeout) [in: %d Pkts/%d B out: %d Pkts/%d B]", key, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load()) t.sendEvent(nftypes.TypeEnd, conn, nil) } diff --git a/client/firewall/uspfilter/conntrack/tcp.go b/client/firewall/uspfilter/conntrack/tcp.go index 2d42ea32eca..a2355e5c718 100644 --- a/client/firewall/uspfilter/conntrack/tcp.go +++ b/client/firewall/uspfilter/conntrack/tcp.go @@ -211,7 +211,7 @@ func (t *TCPTracker) track(srcIP, dstIP netip.Addr, srcPort, dstPort uint16, fla conn.tombstone.Store(false) conn.state.Store(int32(TCPStateNew)) - t.logger.Trace("New %s TCP connection: %s", direction, key) + t.logger.Trace2("New %s TCP connection: %s", direction, key) t.updateState(key, conn, flags, direction, size) t.mutex.Lock() @@ -240,7 +240,7 @@ func (t *TCPTracker) IsValidInbound(srcIP, dstIP netip.Addr, srcPort, dstPort ui currentState := conn.GetState() if !t.isValidStateForFlags(currentState, flags) { - t.logger.Warn("TCP state %s is not valid with flags %x for connection %s", currentState, flags, key) + t.logger.Warn3("TCP state %s is not valid with flags %x for connection %s", currentState, flags, key) // allow all flags for established for now if currentState == TCPStateEstablished { return true @@ -262,7 +262,7 @@ func (t *TCPTracker) updateState(key ConnKey, conn *TCPConnTrack, flags uint8, p if flags&TCPRst != 0 { if conn.CompareAndSwapState(currentState, TCPStateClosed) { conn.SetTombstone() - t.logger.Trace("TCP connection reset: %s (dir: %s) [in: %d Pkts/%d B, out: %d Pkts/%d B]", + t.logger.Trace6("TCP connection reset: %s (dir: %s) [in: %d Pkts/%d B, out: %d Pkts/%d B]", key, packetDir, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load()) t.sendEvent(nftypes.TypeEnd, conn, nil) } @@ -340,17 +340,17 @@ func (t *TCPTracker) updateState(key ConnKey, conn *TCPConnTrack, flags uint8, p } if newState != 0 && conn.CompareAndSwapState(currentState, newState) { - t.logger.Trace("TCP connection %s transitioned from %s to %s (dir: %s)", key, currentState, newState, packetDir) + t.logger.Trace4("TCP connection %s transitioned from %s to %s (dir: %s)", key, currentState, newState, packetDir) switch newState { case TCPStateTimeWait: - t.logger.Trace("TCP connection %s completed [in: %d Pkts/%d B, out: %d Pkts/%d B]", + t.logger.Trace5("TCP connection %s completed [in: %d Pkts/%d B, out: %d Pkts/%d B]", key, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load()) t.sendEvent(nftypes.TypeEnd, conn, nil) case TCPStateClosed: conn.SetTombstone() - t.logger.Trace("TCP connection %s closed gracefully [in: %d Pkts/%d, B out: %d Pkts/%d B]", + t.logger.Trace5("TCP connection %s closed gracefully [in: %d Pkts/%d, B out: %d Pkts/%d B]", key, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load()) t.sendEvent(nftypes.TypeEnd, conn, nil) } @@ -438,7 +438,7 @@ func (t *TCPTracker) cleanup() { if conn.timeoutExceeded(timeout) { delete(t.connections, key) - t.logger.Trace("Cleaned up timed-out TCP connection %s (%s) [in: %d Pkts/%d, B out: %d Pkts/%d B]", + t.logger.Trace6("Cleaned up timed-out TCP connection %s (%s) [in: %d Pkts/%d, B out: %d Pkts/%d B]", key, conn.GetState(), conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load()) // event already handled by state change diff --git a/client/firewall/uspfilter/conntrack/udp.go b/client/firewall/uspfilter/conntrack/udp.go index 000eaa1b663..e7f49c46f92 100644 --- a/client/firewall/uspfilter/conntrack/udp.go +++ b/client/firewall/uspfilter/conntrack/udp.go @@ -116,7 +116,7 @@ func (t *UDPTracker) track(srcIP netip.Addr, dstIP netip.Addr, srcPort uint16, d t.connections[key] = conn t.mutex.Unlock() - t.logger.Trace("New %s UDP connection: %s", direction, key) + t.logger.Trace2("New %s UDP connection: %s", direction, key) t.sendEvent(nftypes.TypeStart, conn, ruleID) } @@ -165,7 +165,7 @@ func (t *UDPTracker) cleanup() { if conn.timeoutExceeded(t.timeout) { delete(t.connections, key) - t.logger.Trace("Removed UDP connection %s (timeout) [in: %d Pkts/%d B, out: %d Pkts/%d B]", + t.logger.Trace5("Removed UDP connection %s (timeout) [in: %d Pkts/%d B, out: %d Pkts/%d B]", key, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load()) t.sendEvent(nftypes.TypeEnd, conn, nil) } diff --git a/client/firewall/uspfilter/filter.go b/client/firewall/uspfilter/filter.go index 7120d7d645b..fdc026b8883 100644 --- a/client/firewall/uspfilter/filter.go +++ b/client/firewall/uspfilter/filter.go @@ -601,7 +601,7 @@ func (m *Manager) filterOutbound(packetData []byte, size int) bool { srcIP, dstIP := m.extractIPs(d) if !srcIP.IsValid() { - m.logger.Error("Unknown network layer: %v", d.decoded[0]) + m.logger.Error1("Unknown network layer: %v", d.decoded[0]) return false } @@ -727,13 +727,13 @@ func (m *Manager) filterInbound(packetData []byte, size int) bool { srcIP, dstIP := m.extractIPs(d) if !srcIP.IsValid() { - m.logger.Error("Unknown network layer: %v", d.decoded[0]) + m.logger.Error1("Unknown network layer: %v", d.decoded[0]) return true } // TODO: pass fragments of routed packets to forwarder if fragment { - m.logger.Trace("packet is a fragment: src=%v dst=%v id=%v flags=%v", + m.logger.Trace4("packet is a fragment: src=%v dst=%v id=%v flags=%v", srcIP, dstIP, d.ip4.Id, d.ip4.Flags) return false } @@ -741,7 +741,7 @@ func (m *Manager) filterInbound(packetData []byte, size int) bool { if translated := m.translateInboundReverse(packetData, d); translated { // Re-decode after translation to get original addresses if err := d.parser.DecodeLayers(packetData, &d.decoded); err != nil { - m.logger.Error("Failed to re-decode packet after reverse DNAT: %v", err) + m.logger.Error1("Failed to re-decode packet after reverse DNAT: %v", err) return true } srcIP, dstIP = m.extractIPs(d) @@ -766,7 +766,7 @@ func (m *Manager) handleLocalTraffic(d *decoder, srcIP, dstIP netip.Addr, packet _, pnum := getProtocolFromPacket(d) srcPort, dstPort := getPortsFromPacket(d) - m.logger.Trace("Dropping local packet (ACL denied): rule_id=%s proto=%v src=%s:%d dst=%s:%d", + m.logger.Trace6("Dropping local packet (ACL denied): rule_id=%s proto=%v src=%s:%d dst=%s:%d", ruleID, pnum, srcIP, srcPort, dstIP, dstPort) m.flowLogger.StoreEvent(nftypes.EventFields{ @@ -807,7 +807,7 @@ func (m *Manager) handleForwardedLocalTraffic(packetData []byte) bool { } if err := fwd.InjectIncomingPacket(packetData); err != nil { - m.logger.Error("Failed to inject local packet: %v", err) + m.logger.Error1("Failed to inject local packet: %v", err) } // don't process this packet further @@ -819,7 +819,7 @@ func (m *Manager) handleForwardedLocalTraffic(packetData []byte) bool { func (m *Manager) handleRoutedTraffic(d *decoder, srcIP, dstIP netip.Addr, packetData []byte, size int) bool { // Drop if routing is disabled if !m.routingEnabled.Load() { - m.logger.Trace("Dropping routed packet (routing disabled): src=%s dst=%s", + m.logger.Trace2("Dropping routed packet (routing disabled): src=%s dst=%s", srcIP, dstIP) return true } @@ -835,7 +835,7 @@ func (m *Manager) handleRoutedTraffic(d *decoder, srcIP, dstIP netip.Addr, packe ruleID, pass := m.routeACLsPass(srcIP, dstIP, proto, srcPort, dstPort) if !pass { - m.logger.Trace("Dropping routed packet (ACL denied): rule_id=%s proto=%v src=%s:%d dst=%s:%d", + m.logger.Trace6("Dropping routed packet (ACL denied): rule_id=%s proto=%v src=%s:%d dst=%s:%d", ruleID, pnum, srcIP, srcPort, dstIP, dstPort) m.flowLogger.StoreEvent(nftypes.EventFields{ @@ -863,7 +863,7 @@ func (m *Manager) handleRoutedTraffic(d *decoder, srcIP, dstIP netip.Addr, packe fwd.RegisterRuleID(srcIP, dstIP, srcPort, dstPort, ruleID) if err := fwd.InjectIncomingPacket(packetData); err != nil { - m.logger.Error("Failed to inject routed packet: %v", err) + m.logger.Error1("Failed to inject routed packet: %v", err) fwd.DeleteRuleID(srcIP, dstIP, srcPort, dstPort) } } @@ -901,7 +901,7 @@ func getPortsFromPacket(d *decoder) (srcPort, dstPort uint16) { // It returns true, true if the packet is a fragment and valid. func (m *Manager) isValidPacket(d *decoder, packetData []byte) (bool, bool) { if err := d.parser.DecodeLayers(packetData, &d.decoded); err != nil { - m.logger.Trace("couldn't decode packet, err: %s", err) + m.logger.Trace1("couldn't decode packet, err: %s", err) return false, false } diff --git a/client/firewall/uspfilter/forwarder/endpoint.go b/client/firewall/uspfilter/forwarder/endpoint.go index e18c083b959..f91291ea866 100644 --- a/client/firewall/uspfilter/forwarder/endpoint.go +++ b/client/firewall/uspfilter/forwarder/endpoint.go @@ -57,7 +57,7 @@ func (e *endpoint) WritePackets(pkts stack.PacketBufferList) (int, tcpip.Error) address := netHeader.DestinationAddress() err := e.device.CreateOutboundPacket(data.AsSlice(), address.AsSlice()) if err != nil { - e.logger.Error("CreateOutboundPacket: %v", err) + e.logger.Error1("CreateOutboundPacket: %v", err) continue } written++ diff --git a/client/firewall/uspfilter/forwarder/icmp.go b/client/firewall/uspfilter/forwarder/icmp.go index 08d77ed0532..939c0478967 100644 --- a/client/firewall/uspfilter/forwarder/icmp.go +++ b/client/firewall/uspfilter/forwarder/icmp.go @@ -34,14 +34,14 @@ func (f *Forwarder) handleICMP(id stack.TransportEndpointID, pkt stack.PacketBuf // TODO: support non-root conn, err := lc.ListenPacket(ctx, "ip4:icmp", "0.0.0.0") if err != nil { - f.logger.Error("forwarder: Failed to create ICMP socket for %v: %v", epID(id), err) + f.logger.Error2("forwarder: Failed to create ICMP socket for %v: %v", epID(id), err) // This will make netstack reply on behalf of the original destination, that's ok for now return false } defer func() { if err := conn.Close(); err != nil { - f.logger.Debug("forwarder: Failed to close ICMP socket: %v", err) + f.logger.Debug1("forwarder: Failed to close ICMP socket: %v", err) } }() @@ -52,11 +52,11 @@ func (f *Forwarder) handleICMP(id stack.TransportEndpointID, pkt stack.PacketBuf payload := fullPacket.AsSlice() if _, err = conn.WriteTo(payload, dst); err != nil { - f.logger.Error("forwarder: Failed to write ICMP packet for %v: %v", epID(id), err) + f.logger.Error2("forwarder: Failed to write ICMP packet for %v: %v", epID(id), err) return true } - f.logger.Trace("forwarder: Forwarded ICMP packet %v type %v code %v", + f.logger.Trace3("forwarder: Forwarded ICMP packet %v type %v code %v", epID(id), icmpHdr.Type(), icmpHdr.Code()) // For Echo Requests, send and handle response @@ -72,7 +72,7 @@ func (f *Forwarder) handleICMP(id stack.TransportEndpointID, pkt stack.PacketBuf func (f *Forwarder) handleEchoResponse(icmpHdr header.ICMPv4, conn net.PacketConn, id stack.TransportEndpointID) int { if err := conn.SetReadDeadline(time.Now().Add(5 * time.Second)); err != nil { - f.logger.Error("forwarder: Failed to set read deadline for ICMP response: %v", err) + f.logger.Error1("forwarder: Failed to set read deadline for ICMP response: %v", err) return 0 } @@ -80,7 +80,7 @@ func (f *Forwarder) handleEchoResponse(icmpHdr header.ICMPv4, conn net.PacketCon n, _, err := conn.ReadFrom(response) if err != nil { if !isTimeout(err) { - f.logger.Error("forwarder: Failed to read ICMP response: %v", err) + f.logger.Error1("forwarder: Failed to read ICMP response: %v", err) } return 0 } @@ -101,12 +101,12 @@ func (f *Forwarder) handleEchoResponse(icmpHdr header.ICMPv4, conn net.PacketCon fullPacket = append(fullPacket, response[:n]...) if err := f.InjectIncomingPacket(fullPacket); err != nil { - f.logger.Error("forwarder: Failed to inject ICMP response: %v", err) + f.logger.Error1("forwarder: Failed to inject ICMP response: %v", err) return 0 } - f.logger.Trace("forwarder: Forwarded ICMP echo reply for %v type %v code %v", + f.logger.Trace3("forwarder: Forwarded ICMP echo reply for %v type %v code %v", epID(id), icmpHdr.Type(), icmpHdr.Code()) return len(fullPacket) diff --git a/client/firewall/uspfilter/forwarder/tcp.go b/client/firewall/uspfilter/forwarder/tcp.go index aa42f811b9d..aef420061ee 100644 --- a/client/firewall/uspfilter/forwarder/tcp.go +++ b/client/firewall/uspfilter/forwarder/tcp.go @@ -38,7 +38,7 @@ func (f *Forwarder) handleTCP(r *tcp.ForwarderRequest) { outConn, err := (&net.Dialer{}).DialContext(f.ctx, "tcp", dialAddr) if err != nil { r.Complete(true) - f.logger.Trace("forwarder: dial error for %v: %v", epID(id), err) + f.logger.Trace2("forwarder: dial error for %v: %v", epID(id), err) return } @@ -47,9 +47,9 @@ func (f *Forwarder) handleTCP(r *tcp.ForwarderRequest) { ep, epErr := r.CreateEndpoint(&wq) if epErr != nil { - f.logger.Error("forwarder: failed to create TCP endpoint: %v", epErr) + f.logger.Error1("forwarder: failed to create TCP endpoint: %v", epErr) if err := outConn.Close(); err != nil { - f.logger.Debug("forwarder: outConn close error: %v", err) + f.logger.Debug1("forwarder: outConn close error: %v", err) } r.Complete(true) return @@ -61,7 +61,7 @@ func (f *Forwarder) handleTCP(r *tcp.ForwarderRequest) { inConn := gonet.NewTCPConn(&wq, ep) success = true - f.logger.Trace("forwarder: established TCP connection %v", epID(id)) + f.logger.Trace1("forwarder: established TCP connection %v", epID(id)) go f.proxyTCP(id, inConn, outConn, ep, flowID) } @@ -75,10 +75,10 @@ func (f *Forwarder) proxyTCP(id stack.TransportEndpointID, inConn *gonet.TCPConn <-ctx.Done() // Close connections and endpoint. if err := inConn.Close(); err != nil && !isClosedError(err) { - f.logger.Debug("forwarder: inConn close error: %v", err) + f.logger.Debug1("forwarder: inConn close error: %v", err) } if err := outConn.Close(); err != nil && !isClosedError(err) { - f.logger.Debug("forwarder: outConn close error: %v", err) + f.logger.Debug1("forwarder: outConn close error: %v", err) } ep.Close() @@ -111,12 +111,12 @@ func (f *Forwarder) proxyTCP(id stack.TransportEndpointID, inConn *gonet.TCPConn if errInToOut != nil { if !isClosedError(errInToOut) { - f.logger.Error("proxyTCP: copy error (in → out) for %s: %v", epID(id), errInToOut) + f.logger.Error2("proxyTCP: copy error (in → out) for %s: %v", epID(id), errInToOut) } } if errOutToIn != nil { if !isClosedError(errOutToIn) { - f.logger.Error("proxyTCP: copy error (out → in) for %s: %v", epID(id), errOutToIn) + f.logger.Error2("proxyTCP: copy error (out → in) for %s: %v", epID(id), errOutToIn) } } @@ -127,7 +127,7 @@ func (f *Forwarder) proxyTCP(id stack.TransportEndpointID, inConn *gonet.TCPConn txPackets = tcpStats.SegmentsReceived.Value() } - f.logger.Trace("forwarder: Removed TCP connection %s [in: %d Pkts/%d B, out: %d Pkts/%d B]", epID(id), rxPackets, bytesFromOutToIn, txPackets, bytesFromInToOut) + f.logger.Trace5("forwarder: Removed TCP connection %s [in: %d Pkts/%d B, out: %d Pkts/%d B]", epID(id), rxPackets, bytesFromOutToIn, txPackets, bytesFromInToOut) f.sendTCPEvent(nftypes.TypeEnd, flowID, id, uint64(bytesFromOutToIn), uint64(bytesFromInToOut), rxPackets, txPackets) } diff --git a/client/firewall/uspfilter/forwarder/udp.go b/client/firewall/uspfilter/forwarder/udp.go index 3a761d06b73..d146de5e444 100644 --- a/client/firewall/uspfilter/forwarder/udp.go +++ b/client/firewall/uspfilter/forwarder/udp.go @@ -78,10 +78,10 @@ func (f *udpForwarder) Stop() { for id, conn := range f.conns { conn.cancel() if err := conn.conn.Close(); err != nil { - f.logger.Debug("forwarder: UDP conn close error for %v: %v", epID(id), err) + f.logger.Debug2("forwarder: UDP conn close error for %v: %v", epID(id), err) } if err := conn.outConn.Close(); err != nil { - f.logger.Debug("forwarder: UDP outConn close error for %v: %v", epID(id), err) + f.logger.Debug2("forwarder: UDP outConn close error for %v: %v", epID(id), err) } conn.ep.Close() @@ -112,10 +112,10 @@ func (f *udpForwarder) cleanup() { for _, idle := range idleConns { idle.conn.cancel() if err := idle.conn.conn.Close(); err != nil { - f.logger.Debug("forwarder: UDP conn close error for %v: %v", epID(idle.id), err) + f.logger.Debug2("forwarder: UDP conn close error for %v: %v", epID(idle.id), err) } if err := idle.conn.outConn.Close(); err != nil { - f.logger.Debug("forwarder: UDP outConn close error for %v: %v", epID(idle.id), err) + f.logger.Debug2("forwarder: UDP outConn close error for %v: %v", epID(idle.id), err) } idle.conn.ep.Close() @@ -124,7 +124,7 @@ func (f *udpForwarder) cleanup() { delete(f.conns, idle.id) f.Unlock() - f.logger.Trace("forwarder: cleaned up idle UDP connection %v", epID(idle.id)) + f.logger.Trace1("forwarder: cleaned up idle UDP connection %v", epID(idle.id)) } } } @@ -143,7 +143,7 @@ func (f *Forwarder) handleUDP(r *udp.ForwarderRequest) { _, exists := f.udpForwarder.conns[id] f.udpForwarder.RUnlock() if exists { - f.logger.Trace("forwarder: existing UDP connection for %v", epID(id)) + f.logger.Trace1("forwarder: existing UDP connection for %v", epID(id)) return } @@ -160,7 +160,7 @@ func (f *Forwarder) handleUDP(r *udp.ForwarderRequest) { dstAddr := fmt.Sprintf("%s:%d", f.determineDialAddr(id.LocalAddress), id.LocalPort) outConn, err := (&net.Dialer{}).DialContext(f.ctx, "udp", dstAddr) if err != nil { - f.logger.Debug("forwarder: UDP dial error for %v: %v", epID(id), err) + f.logger.Debug2("forwarder: UDP dial error for %v: %v", epID(id), err) // TODO: Send ICMP error message return } @@ -169,9 +169,9 @@ func (f *Forwarder) handleUDP(r *udp.ForwarderRequest) { wq := waiter.Queue{} ep, epErr := r.CreateEndpoint(&wq) if epErr != nil { - f.logger.Debug("forwarder: failed to create UDP endpoint: %v", epErr) + f.logger.Debug1("forwarder: failed to create UDP endpoint: %v", epErr) if err := outConn.Close(); err != nil { - f.logger.Debug("forwarder: UDP outConn close error for %v: %v", epID(id), err) + f.logger.Debug2("forwarder: UDP outConn close error for %v: %v", epID(id), err) } return } @@ -194,10 +194,10 @@ func (f *Forwarder) handleUDP(r *udp.ForwarderRequest) { f.udpForwarder.Unlock() pConn.cancel() if err := inConn.Close(); err != nil { - f.logger.Debug("forwarder: UDP inConn close error for %v: %v", epID(id), err) + f.logger.Debug2("forwarder: UDP inConn close error for %v: %v", epID(id), err) } if err := outConn.Close(); err != nil { - f.logger.Debug("forwarder: UDP outConn close error for %v: %v", epID(id), err) + f.logger.Debug2("forwarder: UDP outConn close error for %v: %v", epID(id), err) } return } @@ -205,7 +205,7 @@ func (f *Forwarder) handleUDP(r *udp.ForwarderRequest) { f.udpForwarder.Unlock() success = true - f.logger.Trace("forwarder: established UDP connection %v", epID(id)) + f.logger.Trace1("forwarder: established UDP connection %v", epID(id)) go f.proxyUDP(connCtx, pConn, id, ep) } @@ -220,10 +220,10 @@ func (f *Forwarder) proxyUDP(ctx context.Context, pConn *udpPacketConn, id stack pConn.cancel() if err := pConn.conn.Close(); err != nil && !isClosedError(err) { - f.logger.Debug("forwarder: UDP inConn close error for %v: %v", epID(id), err) + f.logger.Debug2("forwarder: UDP inConn close error for %v: %v", epID(id), err) } if err := pConn.outConn.Close(); err != nil && !isClosedError(err) { - f.logger.Debug("forwarder: UDP outConn close error for %v: %v", epID(id), err) + f.logger.Debug2("forwarder: UDP outConn close error for %v: %v", epID(id), err) } ep.Close() @@ -250,10 +250,10 @@ func (f *Forwarder) proxyUDP(ctx context.Context, pConn *udpPacketConn, id stack wg.Wait() if outboundErr != nil && !isClosedError(outboundErr) { - f.logger.Error("proxyUDP: copy error (outbound→inbound) for %s: %v", epID(id), outboundErr) + f.logger.Error2("proxyUDP: copy error (outbound→inbound) for %s: %v", epID(id), outboundErr) } if inboundErr != nil && !isClosedError(inboundErr) { - f.logger.Error("proxyUDP: copy error (inbound→outbound) for %s: %v", epID(id), inboundErr) + f.logger.Error2("proxyUDP: copy error (inbound→outbound) for %s: %v", epID(id), inboundErr) } var rxPackets, txPackets uint64 @@ -263,7 +263,7 @@ func (f *Forwarder) proxyUDP(ctx context.Context, pConn *udpPacketConn, id stack txPackets = udpStats.PacketsReceived.Value() } - f.logger.Trace("forwarder: Removed UDP connection %s [in: %d Pkts/%d B, out: %d Pkts/%d B]", epID(id), rxPackets, rxBytes, txPackets, txBytes) + f.logger.Trace5("forwarder: Removed UDP connection %s [in: %d Pkts/%d B, out: %d Pkts/%d B]", epID(id), rxPackets, rxBytes, txPackets, txBytes) f.udpForwarder.Lock() delete(f.udpForwarder.conns, id) diff --git a/client/firewall/uspfilter/log/log.go b/client/firewall/uspfilter/log/log.go index d22421e2dd0..5614e2ec301 100644 --- a/client/firewall/uspfilter/log/log.go +++ b/client/firewall/uspfilter/log/log.go @@ -44,7 +44,12 @@ var levelStrings = map[Level]string{ type logMessage struct { level Level format string - args []any + arg1 any + arg2 any + arg3 any + arg4 any + arg5 any + arg6 any } // Logger is a high-performance, non-blocking logger @@ -89,62 +94,198 @@ func (l *Logger) SetLevel(level Level) { log.Debugf("Set uspfilter logger loglevel to %v", levelStrings[level]) } -func (l *Logger) log(level Level, format string, args ...any) { - select { - case l.msgChannel <- logMessage{level: level, format: format, args: args}: - default: + +func (l *Logger) Error(format string) { + if l.level.Load() >= uint32(LevelError) { + select { + case l.msgChannel <- logMessage{level: LevelError, format: format}: + default: + } + } +} + +func (l *Logger) Warn(format string) { + if l.level.Load() >= uint32(LevelWarn) { + select { + case l.msgChannel <- logMessage{level: LevelWarn, format: format}: + default: + } } } -// Error logs a message at error level -func (l *Logger) Error(format string, args ...any) { +func (l *Logger) Info(format string) { + if l.level.Load() >= uint32(LevelInfo) { + select { + case l.msgChannel <- logMessage{level: LevelInfo, format: format}: + default: + } + } +} + +func (l *Logger) Debug(format string) { + if l.level.Load() >= uint32(LevelDebug) { + select { + case l.msgChannel <- logMessage{level: LevelDebug, format: format}: + default: + } + } +} + +func (l *Logger) Trace(format string) { + if l.level.Load() >= uint32(LevelTrace) { + select { + case l.msgChannel <- logMessage{level: LevelTrace, format: format}: + default: + } + } +} + +func (l *Logger) Error1(format string, arg1 any) { + if l.level.Load() >= uint32(LevelError) { + select { + case l.msgChannel <- logMessage{level: LevelError, format: format, arg1: arg1}: + default: + } + } +} + +func (l *Logger) Error2(format string, arg1, arg2 any) { if l.level.Load() >= uint32(LevelError) { - l.log(LevelError, format, args...) + select { + case l.msgChannel <- logMessage{level: LevelError, format: format, arg1: arg1, arg2: arg2}: + default: + } } } -// Warn logs a message at warning level -func (l *Logger) Warn(format string, args ...any) { +func (l *Logger) Warn3(format string, arg1, arg2, arg3 any) { if l.level.Load() >= uint32(LevelWarn) { - l.log(LevelWarn, format, args...) + select { + case l.msgChannel <- logMessage{level: LevelWarn, format: format, arg1: arg1, arg2: arg2, arg3: arg3}: + default: + } } } -// Info logs a message at info level -func (l *Logger) Info(format string, args ...any) { - if l.level.Load() >= uint32(LevelInfo) { - l.log(LevelInfo, format, args...) +func (l *Logger) Debug1(format string, arg1 any) { + if l.level.Load() >= uint32(LevelDebug) { + select { + case l.msgChannel <- logMessage{level: LevelDebug, format: format, arg1: arg1}: + default: + } } } -// Debug logs a message at debug level -func (l *Logger) Debug(format string, args ...any) { +func (l *Logger) Debug2(format string, arg1, arg2 any) { if l.level.Load() >= uint32(LevelDebug) { - l.log(LevelDebug, format, args...) + select { + case l.msgChannel <- logMessage{level: LevelDebug, format: format, arg1: arg1, arg2: arg2}: + default: + } } } -// Trace logs a message at trace level -func (l *Logger) Trace(format string, args ...any) { +func (l *Logger) Trace1(format string, arg1 any) { if l.level.Load() >= uint32(LevelTrace) { - l.log(LevelTrace, format, args...) + select { + case l.msgChannel <- logMessage{level: LevelTrace, format: format, arg1: arg1}: + default: + } } } -func (l *Logger) formatMessage(buf *[]byte, level Level, format string, args ...any) { +func (l *Logger) Trace2(format string, arg1, arg2 any) { + if l.level.Load() >= uint32(LevelTrace) { + select { + case l.msgChannel <- logMessage{level: LevelTrace, format: format, arg1: arg1, arg2: arg2}: + default: + } + } +} + +func (l *Logger) Trace3(format string, arg1, arg2, arg3 any) { + if l.level.Load() >= uint32(LevelTrace) { + select { + case l.msgChannel <- logMessage{level: LevelTrace, format: format, arg1: arg1, arg2: arg2, arg3: arg3}: + default: + } + } +} + +func (l *Logger) Trace4(format string, arg1, arg2, arg3, arg4 any) { + if l.level.Load() >= uint32(LevelTrace) { + select { + case l.msgChannel <- logMessage{level: LevelTrace, format: format, arg1: arg1, arg2: arg2, arg3: arg3, arg4: arg4}: + default: + } + } +} + +func (l *Logger) Trace5(format string, arg1, arg2, arg3, arg4, arg5 any) { + if l.level.Load() >= uint32(LevelTrace) { + select { + case l.msgChannel <- logMessage{level: LevelTrace, format: format, arg1: arg1, arg2: arg2, arg3: arg3, arg4: arg4, arg5: arg5}: + default: + } + } +} + +func (l *Logger) Trace6(format string, arg1, arg2, arg3, arg4, arg5, arg6 any) { + if l.level.Load() >= uint32(LevelTrace) { + select { + case l.msgChannel <- logMessage{level: LevelTrace, format: format, arg1: arg1, arg2: arg2, arg3: arg3, arg4: arg4, arg5: arg5, arg6: arg6}: + default: + } + } +} + +func (l *Logger) formatMessage(buf *[]byte, msg logMessage) { *buf = (*buf)[:0] *buf = time.Now().AppendFormat(*buf, "2006-01-02T15:04:05-07:00") *buf = append(*buf, ' ') - *buf = append(*buf, levelStrings[level]...) + *buf = append(*buf, levelStrings[msg.level]...) *buf = append(*buf, ' ') - var msg string - if len(args) > 0 { - msg = fmt.Sprintf(format, args...) - } else { - msg = format + // Count non-nil arguments for switch + argCount := 0 + if msg.arg1 != nil { + argCount++ + if msg.arg2 != nil { + argCount++ + if msg.arg3 != nil { + argCount++ + if msg.arg4 != nil { + argCount++ + if msg.arg5 != nil { + argCount++ + if msg.arg6 != nil { + argCount++ + } + } + } + } + } + } + + var formatted string + switch argCount { + case 0: + formatted = msg.format + case 1: + formatted = fmt.Sprintf(msg.format, msg.arg1) + case 2: + formatted = fmt.Sprintf(msg.format, msg.arg1, msg.arg2) + case 3: + formatted = fmt.Sprintf(msg.format, msg.arg1, msg.arg2, msg.arg3) + case 4: + formatted = fmt.Sprintf(msg.format, msg.arg1, msg.arg2, msg.arg3, msg.arg4) + case 5: + formatted = fmt.Sprintf(msg.format, msg.arg1, msg.arg2, msg.arg3, msg.arg4, msg.arg5) + case 6: + formatted = fmt.Sprintf(msg.format, msg.arg1, msg.arg2, msg.arg3, msg.arg4, msg.arg5, msg.arg6) } - *buf = append(*buf, msg...) + + *buf = append(*buf, formatted...) *buf = append(*buf, '\n') if len(*buf) > maxMessageSize { @@ -157,7 +298,7 @@ func (l *Logger) processMessage(msg logMessage, buffer *[]byte) { bufp := l.bufPool.Get().(*[]byte) defer l.bufPool.Put(bufp) - l.formatMessage(bufp, msg.level, msg.format, msg.args...) + l.formatMessage(bufp, msg) if len(*buffer)+len(*bufp) > maxBatchSize { _, _ = l.output.Write(*buffer) @@ -249,4 +390,4 @@ func (l *Logger) Stop(ctx context.Context) error { case <-done: return nil } -} +} \ No newline at end of file diff --git a/client/firewall/uspfilter/log/log_test.go b/client/firewall/uspfilter/log/log_test.go index e7da9a8e96a..0c221c2623b 100644 --- a/client/firewall/uspfilter/log/log_test.go +++ b/client/firewall/uspfilter/log/log_test.go @@ -19,22 +19,17 @@ func (d *discard) Write(p []byte) (n int, err error) { func BenchmarkLogger(b *testing.B) { simpleMessage := "Connection established" - conntrackMessage := "TCP connection %s:%d -> %s:%d state changed to %d" srcIP := "192.168.1.1" srcPort := uint16(12345) dstIP := "10.0.0.1" dstPort := uint16(443) state := 4 // TCPStateEstablished - complexMessage := "Packet inspection result: protocol=%s, direction=%s, flags=0x%x, sequence=%d, acknowledged=%d, payload_size=%d, fragmented=%v, connection_id=%s" protocol := "TCP" direction := "outbound" flags := uint16(0x18) // ACK + PSH sequence := uint32(123456789) acknowledged := uint32(987654321) - payloadSize := 1460 - fragmented := false - connID := "f7a12b3e-c456-7890-d123-456789abcdef" b.Run("SimpleMessage", func(b *testing.B) { logger := createTestLogger() @@ -52,7 +47,7 @@ func BenchmarkLogger(b *testing.B) { b.ResetTimer() for i := 0; i < b.N; i++ { - logger.Trace(conntrackMessage, srcIP, srcPort, dstIP, dstPort, state) + logger.Trace5("TCP connection %s:%d → %s:%d state %d", srcIP, srcPort, dstIP, dstPort, state) } }) @@ -62,7 +57,7 @@ func BenchmarkLogger(b *testing.B) { b.ResetTimer() for i := 0; i < b.N; i++ { - logger.Trace(complexMessage, protocol, direction, flags, sequence, acknowledged, payloadSize, fragmented, connID) + logger.Trace6("Complex trace: proto=%s dir=%s flags=%d seq=%d ack=%d size=%d", protocol, direction, flags, sequence, acknowledged, 1460) } }) } @@ -72,7 +67,6 @@ func BenchmarkLoggerParallel(b *testing.B) { logger := createTestLogger() defer cleanupLogger(logger) - conntrackMessage := "TCP connection %s:%d -> %s:%d state changed to %d" srcIP := "192.168.1.1" srcPort := uint16(12345) dstIP := "10.0.0.1" @@ -82,7 +76,7 @@ func BenchmarkLoggerParallel(b *testing.B) { b.ResetTimer() b.RunParallel(func(pb *testing.PB) { for pb.Next() { - logger.Trace(conntrackMessage, srcIP, srcPort, dstIP, dstPort, state) + logger.Trace5("TCP connection %s:%d → %s:%d state %d", srcIP, srcPort, dstIP, dstPort, state) } }) } @@ -92,7 +86,6 @@ func BenchmarkLoggerBurst(b *testing.B) { logger := createTestLogger() defer cleanupLogger(logger) - conntrackMessage := "TCP connection %s:%d -> %s:%d state changed to %d" srcIP := "192.168.1.1" srcPort := uint16(12345) dstIP := "10.0.0.1" @@ -102,7 +95,7 @@ func BenchmarkLoggerBurst(b *testing.B) { b.ResetTimer() for i := 0; i < b.N; i++ { for j := 0; j < 100; j++ { - logger.Trace(conntrackMessage, srcIP, srcPort, dstIP, dstPort, state) + logger.Trace5("TCP connection %s:%d → %s:%d state %d", srcIP, srcPort, dstIP, dstPort, state) } } } diff --git a/client/firewall/uspfilter/nat.go b/client/firewall/uspfilter/nat.go index 4539f7da5ef..27b7525315d 100644 --- a/client/firewall/uspfilter/nat.go +++ b/client/firewall/uspfilter/nat.go @@ -211,11 +211,11 @@ func (m *Manager) translateOutboundDNAT(packetData []byte, d *decoder) bool { } if err := m.rewritePacketDestination(packetData, d, translatedIP); err != nil { - m.logger.Error("Failed to rewrite packet destination: %v", err) + m.logger.Error1("Failed to rewrite packet destination: %v", err) return false } - m.logger.Trace("DNAT: %s -> %s", dstIP, translatedIP) + m.logger.Trace2("DNAT: %s -> %s", dstIP, translatedIP) return true } @@ -237,11 +237,11 @@ func (m *Manager) translateInboundReverse(packetData []byte, d *decoder) bool { } if err := m.rewritePacketSource(packetData, d, originalIP); err != nil { - m.logger.Error("Failed to rewrite packet source: %v", err) + m.logger.Error1("Failed to rewrite packet source: %v", err) return false } - m.logger.Trace("Reverse DNAT: %s -> %s", srcIP, originalIP) + m.logger.Trace2("Reverse DNAT: %s -> %s", srcIP, originalIP) return true }