[client] Improve userspace filter logging performance

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

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

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

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,21 +727,21 @@ 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
 	}
 
 	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
 	}
 

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++

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,15 +72,15 @@ 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
 	}
 
 	response := make([]byte, f.endpoint.mtu)
 	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)

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