From bfa5c21d2d608ff65887e4068604175f32ef6fe5 Mon Sep 17 00:00:00 2001 From: Viktor Liu <17948409+lixmal@users.noreply.github.com> Date: Mon, 16 Jun 2025 10:12:59 +0200 Subject: [PATCH] [client] Improve icmp conntrack log (#3963) --- client/cmd/trace.go | 2 +- client/firewall/uspfilter/conntrack/common.go | 2 +- client/firewall/uspfilter/conntrack/icmp.go | 121 ++++++++++++++++-- .../firewall/uspfilter/conntrack/icmp_test.go | 4 +- .../firewall/uspfilter/forwarder/endpoint.go | 2 +- client/firewall/uspfilter/forwarder/tcp.go | 4 +- client/firewall/uspfilter/forwarder/udp.go | 4 +- client/firewall/uspfilter/uspfilter.go | 4 +- .../internal/netflow/conntrack/conntrack.go | 2 +- 9 files changed, 125 insertions(+), 20 deletions(-) diff --git a/client/cmd/trace.go b/client/cmd/trace.go index abb73b646..655838260 100644 --- a/client/cmd/trace.go +++ b/client/cmd/trace.go @@ -118,7 +118,7 @@ func tracePacket(cmd *cobra.Command, args []string) error { } func printTrace(cmd *cobra.Command, src, dst, proto string, sport, dport uint16, resp *proto.TracePacketResponse) { - cmd.Printf("Packet trace %s:%d -> %s:%d (%s)\n\n", src, sport, dst, dport, strings.ToUpper(proto)) + cmd.Printf("Packet trace %s:%d → %s:%d (%s)\n\n", src, sport, dst, dport, strings.ToUpper(proto)) for _, stage := range resp.Stages { if stage.ForwardingDetails != nil { diff --git a/client/firewall/uspfilter/conntrack/common.go b/client/firewall/uspfilter/conntrack/common.go index 3de0bb3f4..bcf6d894b 100644 --- a/client/firewall/uspfilter/conntrack/common.go +++ b/client/firewall/uspfilter/conntrack/common.go @@ -62,5 +62,5 @@ type ConnKey struct { } func (c ConnKey) String() string { - return fmt.Sprintf("%s:%d -> %s:%d", c.SrcIP.Unmap(), c.SrcPort, c.DstIP.Unmap(), c.DstPort) + return fmt.Sprintf("%s:%d → %s:%d", c.SrcIP.Unmap(), c.SrcPort, c.DstIP.Unmap(), c.DstPort) } diff --git a/client/firewall/uspfilter/conntrack/icmp.go b/client/firewall/uspfilter/conntrack/icmp.go index c8ea159da..509c1549b 100644 --- a/client/firewall/uspfilter/conntrack/icmp.go +++ b/client/firewall/uspfilter/conntrack/icmp.go @@ -3,6 +3,7 @@ package conntrack import ( "context" "fmt" + "net" "net/netip" "sync" "time" @@ -19,6 +20,10 @@ const ( DefaultICMPTimeout = 30 * time.Second // ICMPCleanupInterval is how often we check for stale ICMP connections ICMPCleanupInterval = 15 * time.Second + + // MaxICMPPayloadLength is the maximum length of ICMP payload we consider for original packet info, + // which includes the IP header (20 bytes) and transport header (8 bytes) + MaxICMPPayloadLength = 28 ) // ICMPConnKey uniquely identifies an ICMP connection @@ -29,7 +34,7 @@ type ICMPConnKey struct { } func (i ICMPConnKey) String() string { - return fmt.Sprintf("%s -> %s (id %d)", i.SrcIP, i.DstIP, i.ID) + return fmt.Sprintf("%s → %s (id %d)", i.SrcIP, i.DstIP, i.ID) } // ICMPConnTrack represents an ICMP connection state @@ -50,6 +55,72 @@ type ICMPTracker struct { flowLogger nftypes.FlowLogger } +// ICMPInfo holds ICMP type, code, and payload for lazy string formatting in logs +type ICMPInfo struct { + TypeCode layers.ICMPv4TypeCode + PayloadData [MaxICMPPayloadLength]byte + // actual length of valid data + PayloadLen int +} + +// String implements fmt.Stringer for lazy evaluation in log messages +func (info ICMPInfo) String() string { + if info.isErrorMessage() && info.PayloadLen >= MaxICMPPayloadLength { + if origInfo := info.parseOriginalPacket(); origInfo != "" { + return fmt.Sprintf("%s (original: %s)", info.TypeCode, origInfo) + } + } + + return info.TypeCode.String() +} + +// isErrorMessage returns true if this ICMP type carries original packet info +func (info ICMPInfo) isErrorMessage() bool { + typ := info.TypeCode.Type() + return typ == 3 || // Destination Unreachable + typ == 5 || // Redirect + typ == 11 || // Time Exceeded + typ == 12 // Parameter Problem +} + +// parseOriginalPacket extracts info about the original packet from ICMP payload +func (info ICMPInfo) parseOriginalPacket() string { + if info.PayloadLen < MaxICMPPayloadLength { + return "" + } + + // TODO: handle IPv6 + if version := (info.PayloadData[0] >> 4) & 0xF; version != 4 { + return "" + } + + protocol := info.PayloadData[9] + srcIP := net.IP(info.PayloadData[12:16]) + dstIP := net.IP(info.PayloadData[16:20]) + + transportData := info.PayloadData[20:] + + switch nftypes.Protocol(protocol) { + case nftypes.TCP: + srcPort := uint16(transportData[0])<<8 | uint16(transportData[1]) + dstPort := uint16(transportData[2])<<8 | uint16(transportData[3]) + return fmt.Sprintf("TCP %s:%d → %s:%d", srcIP, srcPort, dstIP, dstPort) + + case nftypes.UDP: + srcPort := uint16(transportData[0])<<8 | uint16(transportData[1]) + dstPort := uint16(transportData[2])<<8 | uint16(transportData[3]) + return fmt.Sprintf("UDP %s:%d → %s:%d", srcIP, srcPort, dstIP, dstPort) + + case nftypes.ICMP: + icmpType := transportData[0] + icmpCode := transportData[1] + return fmt.Sprintf("ICMP %s → %s (type %d code %d)", srcIP, dstIP, icmpType, icmpCode) + + default: + return fmt.Sprintf("Proto %d %s → %s", protocol, srcIP, dstIP) + } +} + // NewICMPTracker creates a new ICMP connection tracker func NewICMPTracker(timeout time.Duration, logger *nblog.Logger, flowLogger nftypes.FlowLogger) *ICMPTracker { if timeout == 0 { @@ -93,30 +164,64 @@ func (t *ICMPTracker) updateIfExists(srcIP netip.Addr, dstIP netip.Addr, id uint } // TrackOutbound records an outbound ICMP connection -func (t *ICMPTracker) TrackOutbound(srcIP netip.Addr, dstIP netip.Addr, id uint16, typecode layers.ICMPv4TypeCode, size int) { +func (t *ICMPTracker) TrackOutbound( + srcIP netip.Addr, + dstIP netip.Addr, + id uint16, + typecode layers.ICMPv4TypeCode, + payload []byte, + size int, +) { if _, exists := t.updateIfExists(dstIP, srcIP, id, nftypes.Egress, size); !exists { // if (inverted direction) conn is not tracked, track this direction - t.track(srcIP, dstIP, id, typecode, nftypes.Egress, nil, size) + t.track(srcIP, dstIP, id, typecode, nftypes.Egress, nil, payload, size) } } // TrackInbound records an inbound ICMP Echo Request -func (t *ICMPTracker) TrackInbound(srcIP netip.Addr, dstIP netip.Addr, id uint16, typecode layers.ICMPv4TypeCode, ruleId []byte, size int) { - t.track(srcIP, dstIP, id, typecode, nftypes.Ingress, ruleId, size) +func (t *ICMPTracker) TrackInbound( + srcIP netip.Addr, + dstIP netip.Addr, + id uint16, + typecode layers.ICMPv4TypeCode, + ruleId []byte, + payload []byte, + size int, +) { + t.track(srcIP, dstIP, id, typecode, nftypes.Ingress, ruleId, payload, size) } // track is the common implementation for tracking both inbound and outbound ICMP connections -func (t *ICMPTracker) track(srcIP netip.Addr, dstIP netip.Addr, id uint16, typecode layers.ICMPv4TypeCode, direction nftypes.Direction, ruleId []byte, size int) { +func (t *ICMPTracker) track( + srcIP netip.Addr, + dstIP netip.Addr, + id uint16, + typecode layers.ICMPv4TypeCode, + direction nftypes.Direction, + ruleId []byte, + payload []byte, + size int, +) { key, exists := t.updateIfExists(srcIP, dstIP, id, direction, size) if exists { return } typ, code := typecode.Type(), typecode.Code() + icmpInfo := ICMPInfo{ + TypeCode: typecode, + } + if len(payload) > 0 { + icmpInfo.PayloadLen = len(payload) + if icmpInfo.PayloadLen > MaxICMPPayloadLength { + icmpInfo.PayloadLen = MaxICMPPayloadLength + } + copy(icmpInfo.PayloadData[:], payload[:icmpInfo.PayloadLen]) + } // non echo requests don't need tracking if typ != uint8(layers.ICMPv4TypeEchoRequest) { - t.logger.Trace("New %s ICMP connection %s type %d code %d", direction, key, typ, code) + t.logger.Trace("New %s ICMP connection %s - %s", direction, key, icmpInfo) t.sendStartEvent(direction, srcIP, dstIP, typ, code, ruleId, size) return } @@ -138,7 +243,7 @@ func (t *ICMPTracker) track(srcIP netip.Addr, dstIP netip.Addr, id uint16, typec t.connections[key] = conn t.mutex.Unlock() - t.logger.Trace("New %s ICMP connection %s type %d code %d", direction, key, typ, code) + t.logger.Trace("New %s ICMP connection %s - %s", direction, key, icmpInfo) t.sendEvent(nftypes.TypeStart, conn, ruleId) } diff --git a/client/firewall/uspfilter/conntrack/icmp_test.go b/client/firewall/uspfilter/conntrack/icmp_test.go index 5a7b36a36..b15b42cf0 100644 --- a/client/firewall/uspfilter/conntrack/icmp_test.go +++ b/client/firewall/uspfilter/conntrack/icmp_test.go @@ -15,7 +15,7 @@ func BenchmarkICMPTracker(b *testing.B) { b.ResetTimer() for i := 0; i < b.N; i++ { - tracker.TrackOutbound(srcIP, dstIP, uint16(i%65535), 0, 0) + tracker.TrackOutbound(srcIP, dstIP, uint16(i%65535), 0, []byte{}, 0) } }) @@ -28,7 +28,7 @@ func BenchmarkICMPTracker(b *testing.B) { // Pre-populate some connections for i := 0; i < 1000; i++ { - tracker.TrackOutbound(srcIP, dstIP, uint16(i), 0, 0) + tracker.TrackOutbound(srcIP, dstIP, uint16(i), 0, []byte{}, 0) } b.ResetTimer() diff --git a/client/firewall/uspfilter/forwarder/endpoint.go b/client/firewall/uspfilter/forwarder/endpoint.go index 3720eedfa..e18c083b9 100644 --- a/client/firewall/uspfilter/forwarder/endpoint.go +++ b/client/firewall/uspfilter/forwarder/endpoint.go @@ -86,5 +86,5 @@ type epID stack.TransportEndpointID func (i epID) String() string { // src and remote is swapped - return fmt.Sprintf("%s:%d -> %s:%d", i.RemoteAddress, i.RemotePort, i.LocalAddress, i.LocalPort) + return fmt.Sprintf("%s:%d → %s:%d", i.RemoteAddress, i.RemotePort, i.LocalAddress, i.LocalPort) } diff --git a/client/firewall/uspfilter/forwarder/tcp.go b/client/firewall/uspfilter/forwarder/tcp.go index 64e54e293..aa42f811b 100644 --- a/client/firewall/uspfilter/forwarder/tcp.go +++ b/client/firewall/uspfilter/forwarder/tcp.go @@ -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.Error("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.Error("proxyTCP: copy error (out → in) for %s: %v", epID(id), errOutToIn) } } diff --git a/client/firewall/uspfilter/forwarder/udp.go b/client/firewall/uspfilter/forwarder/udp.go index f237a313d..3a761d06b 100644 --- a/client/firewall/uspfilter/forwarder/udp.go +++ b/client/firewall/uspfilter/forwarder/udp.go @@ -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.Error("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.Error("proxyUDP: copy error (inbound→outbound) for %s: %v", epID(id), inboundErr) } var rxPackets, txPackets uint64 diff --git a/client/firewall/uspfilter/uspfilter.go b/client/firewall/uspfilter/uspfilter.go index c216bc302..dcff92c61 100644 --- a/client/firewall/uspfilter/uspfilter.go +++ b/client/firewall/uspfilter/uspfilter.go @@ -671,7 +671,7 @@ func (m *Manager) trackOutbound(d *decoder, srcIP, dstIP netip.Addr, size int) { flags := getTCPFlags(&d.tcp) m.tcpTracker.TrackOutbound(srcIP, dstIP, uint16(d.tcp.SrcPort), uint16(d.tcp.DstPort), flags, size) case layers.LayerTypeICMPv4: - m.icmpTracker.TrackOutbound(srcIP, dstIP, d.icmp4.Id, d.icmp4.TypeCode, size) + m.icmpTracker.TrackOutbound(srcIP, dstIP, d.icmp4.Id, d.icmp4.TypeCode, d.icmp4.Payload, size) } } @@ -684,7 +684,7 @@ func (m *Manager) trackInbound(d *decoder, srcIP, dstIP netip.Addr, ruleID []byt flags := getTCPFlags(&d.tcp) m.tcpTracker.TrackInbound(srcIP, dstIP, uint16(d.tcp.SrcPort), uint16(d.tcp.DstPort), flags, ruleID, size) case layers.LayerTypeICMPv4: - m.icmpTracker.TrackInbound(srcIP, dstIP, d.icmp4.Id, d.icmp4.TypeCode, ruleID, size) + m.icmpTracker.TrackInbound(srcIP, dstIP, d.icmp4.Id, d.icmp4.TypeCode, ruleID, d.icmp4.Payload, size) } } diff --git a/client/internal/netflow/conntrack/conntrack.go b/client/internal/netflow/conntrack/conntrack.go index d01adf135..dbb4747a5 100644 --- a/client/internal/netflow/conntrack/conntrack.go +++ b/client/internal/netflow/conntrack/conntrack.go @@ -204,7 +204,7 @@ func (c *ConnTrack) handleEvent(event nfct.Event) { eventStr = "Ended" } - log.Tracef("%s %s %s connection: %s:%d -> %s:%d", eventStr, direction, proto, srcIP, srcPort, dstIP, dstPort) + log.Tracef("%s %s %s connection: %s:%d → %s:%d", eventStr, direction, proto, srcIP, srcPort, dstIP, dstPort) c.flowLogger.StoreEvent(nftypes.EventFields{ FlowID: flowID,