Skip to content

Commit 71bb09d

Browse files
lixmallixmal
authored
[client] Improve userspace filter logging performance (#4221)
1 parent 5de61f3 commit 71bb09d

File tree

11 files changed

+237
-103
lines changed

11 files changed

+237
-103
lines changed

‎client/firewall/uspfilter/conntrack/icmp.go‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -221,7 +221,7 @@ func (t *ICMPTracker) track(
221221

222222
// non echo requests don't need tracking
223223
if typ != uint8(layers.ICMPv4TypeEchoRequest) {
224-
t.logger.Trace("New %s ICMP connection %s - %s", direction, key, icmpInfo)
224+
t.logger.Trace3("New %s ICMP connection %s - %s", direction, key, icmpInfo)
225225
t.sendStartEvent(direction, srcIP, dstIP, typ, code, ruleId, size)
226226
return
227227
}
@@ -243,7 +243,7 @@ func (t *ICMPTracker) track(
243243
t.connections[key] = conn
244244
t.mutex.Unlock()
245245

246-
t.logger.Trace("New %s ICMP connection %s - %s", direction, key, icmpInfo)
246+
t.logger.Trace3("New %s ICMP connection %s - %s", direction, key, icmpInfo)
247247
t.sendEvent(nftypes.TypeStart, conn, ruleId)
248248
}
249249

@@ -294,7 +294,7 @@ func (t *ICMPTracker) cleanup() {
294294
if conn.timeoutExceeded(t.timeout) {
295295
delete(t.connections, key)
296296

297-
t.logger.Trace("Removed ICMP connection %s (timeout) [in: %d Pkts/%d B out: %d Pkts/%d B]",
297+
t.logger.Trace5("Removed ICMP connection %s (timeout) [in: %d Pkts/%d B out: %d Pkts/%d B]",
298298
key, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load())
299299
t.sendEvent(nftypes.TypeEnd, conn, nil)
300300
}

‎client/firewall/uspfilter/conntrack/tcp.go‎

Lines changed: 7 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -211,7 +211,7 @@ func (t *TCPTracker) track(srcIP, dstIP netip.Addr, srcPort, dstPort uint16, fla
211211
conn.tombstone.Store(false)
212212
conn.state.Store(int32(TCPStateNew))
213213

214-
t.logger.Trace("New %s TCP connection: %s", direction, key)
214+
t.logger.Trace2("New %s TCP connection: %s", direction, key)
215215
t.updateState(key, conn, flags, direction, size)
216216

217217
t.mutex.Lock()
@@ -240,7 +240,7 @@ func (t *TCPTracker) IsValidInbound(srcIP, dstIP netip.Addr, srcPort, dstPort ui
240240

241241
currentState := conn.GetState()
242242
if !t.isValidStateForFlags(currentState, flags) {
243-
t.logger.Warn("TCP state %s is not valid with flags %x for connection %s", currentState, flags, key)
243+
t.logger.Warn3("TCP state %s is not valid with flags %x for connection %s", currentState, flags, key)
244244
// allow all flags for established for now
245245
if currentState == TCPStateEstablished {
246246
return true
@@ -262,7 +262,7 @@ func (t *TCPTracker) updateState(key ConnKey, conn *TCPConnTrack, flags uint8, p
262262
if flags&TCPRst != 0 {
263263
if conn.CompareAndSwapState(currentState, TCPStateClosed) {
264264
conn.SetTombstone()
265-
t.logger.Trace("TCP connection reset: %s (dir: %s) [in: %d Pkts/%d B, out: %d Pkts/%d B]",
265+
t.logger.Trace6("TCP connection reset: %s (dir: %s) [in: %d Pkts/%d B, out: %d Pkts/%d B]",
266266
key, packetDir, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load())
267267
t.sendEvent(nftypes.TypeEnd, conn, nil)
268268
}
@@ -340,17 +340,17 @@ func (t *TCPTracker) updateState(key ConnKey, conn *TCPConnTrack, flags uint8, p
340340
}
341341

342342
if newState != 0 && conn.CompareAndSwapState(currentState, newState) {
343-
t.logger.Trace("TCP connection %s transitioned from %s to %s (dir: %s)", key, currentState, newState, packetDir)
343+
t.logger.Trace4("TCP connection %s transitioned from %s to %s (dir: %s)", key, currentState, newState, packetDir)
344344

345345
switch newState {
346346
case TCPStateTimeWait:
347-
t.logger.Trace("TCP connection %s completed [in: %d Pkts/%d B, out: %d Pkts/%d B]",
347+
t.logger.Trace5("TCP connection %s completed [in: %d Pkts/%d B, out: %d Pkts/%d B]",
348348
key, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load())
349349
t.sendEvent(nftypes.TypeEnd, conn, nil)
350350

351351
case TCPStateClosed:
352352
conn.SetTombstone()
353-
t.logger.Trace("TCP connection %s closed gracefully [in: %d Pkts/%d, B out: %d Pkts/%d B]",
353+
t.logger.Trace5("TCP connection %s closed gracefully [in: %d Pkts/%d, B out: %d Pkts/%d B]",
354354
key, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load())
355355
t.sendEvent(nftypes.TypeEnd, conn, nil)
356356
}
@@ -438,7 +438,7 @@ func (t *TCPTracker) cleanup() {
438438
if conn.timeoutExceeded(timeout) {
439439
delete(t.connections, key)
440440

441-
t.logger.Trace("Cleaned up timed-out TCP connection %s (%s) [in: %d Pkts/%d, B out: %d Pkts/%d B]",
441+
t.logger.Trace6("Cleaned up timed-out TCP connection %s (%s) [in: %d Pkts/%d, B out: %d Pkts/%d B]",
442442
key, conn.GetState(), conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load())
443443

444444
// event already handled by state change

‎client/firewall/uspfilter/conntrack/udp.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -116,7 +116,7 @@ func (t *UDPTracker) track(srcIP netip.Addr, dstIP netip.Addr, srcPort uint16, d
116116
t.connections[key] = conn
117117
t.mutex.Unlock()
118118

119-
t.logger.Trace("New %s UDP connection: %s", direction, key)
119+
t.logger.Trace2("New %s UDP connection: %s", direction, key)
120120
t.sendEvent(nftypes.TypeStart, conn, ruleID)
121121
}
122122

@@ -165,7 +165,7 @@ func (t *UDPTracker) cleanup() {
165165
if conn.timeoutExceeded(t.timeout) {
166166
delete(t.connections, key)
167167

168-
t.logger.Trace("Removed UDP connection %s (timeout) [in: %d Pkts/%d B, out: %d Pkts/%d B]",
168+
t.logger.Trace5("Removed UDP connection %s (timeout) [in: %d Pkts/%d B, out: %d Pkts/%d B]",
169169
key, conn.PacketsRx.Load(), conn.BytesRx.Load(), conn.PacketsTx.Load(), conn.BytesTx.Load())
170170
t.sendEvent(nftypes.TypeEnd, conn, nil)
171171
}

‎client/firewall/uspfilter/filter.go‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -601,7 +601,7 @@ func (m *Manager) filterOutbound(packetData []byte, size int) bool {
601601

602602
srcIP, dstIP := m.extractIPs(d)
603603
if !srcIP.IsValid() {
604-
m.logger.Error("Unknown network layer: %v", d.decoded[0])
604+
m.logger.Error1("Unknown network layer: %v", d.decoded[0])
605605
return false
606606
}
607607

@@ -727,21 +727,21 @@ func (m *Manager) filterInbound(packetData []byte, size int) bool {
727727

728728
srcIP, dstIP := m.extractIPs(d)
729729
if !srcIP.IsValid() {
730-
m.logger.Error("Unknown network layer: %v", d.decoded[0])
730+
m.logger.Error1("Unknown network layer: %v", d.decoded[0])
731731
return true
732732
}
733733

734734
// TODO: pass fragments of routed packets to forwarder
735735
if fragment {
736-
m.logger.Trace("packet is a fragment: src=%v dst=%v id=%v flags=%v",
736+
m.logger.Trace4("packet is a fragment: src=%v dst=%v id=%v flags=%v",
737737
srcIP, dstIP, d.ip4.Id, d.ip4.Flags)
738738
return false
739739
}
740740

741741
if translated := m.translateInboundReverse(packetData, d); translated {
742742
// Re-decode after translation to get original addresses
743743
if err := d.parser.DecodeLayers(packetData, &d.decoded); err != nil {
744-
m.logger.Error("Failed to re-decode packet after reverse DNAT: %v", err)
744+
m.logger.Error1("Failed to re-decode packet after reverse DNAT: %v", err)
745745
return true
746746
}
747747
srcIP, dstIP = m.extractIPs(d)
@@ -766,7 +766,7 @@ func (m *Manager) handleLocalTraffic(d *decoder, srcIP, dstIP netip.Addr, packet
766766
_, pnum := getProtocolFromPacket(d)
767767
srcPort, dstPort := getPortsFromPacket(d)
768768

769-
m.logger.Trace("Dropping local packet (ACL denied): rule_id=%s proto=%v src=%s:%d dst=%s:%d",
769+
m.logger.Trace6("Dropping local packet (ACL denied): rule_id=%s proto=%v src=%s:%d dst=%s:%d",
770770
ruleID, pnum, srcIP, srcPort, dstIP, dstPort)
771771

772772
m.flowLogger.StoreEvent(nftypes.EventFields{
@@ -807,7 +807,7 @@ func (m *Manager) handleForwardedLocalTraffic(packetData []byte) bool {
807807
}
808808

809809
if err := fwd.InjectIncomingPacket(packetData); err != nil {
810-
m.logger.Error("Failed to inject local packet: %v", err)
810+
m.logger.Error1("Failed to inject local packet: %v", err)
811811
}
812812

813813
// don't process this packet further
@@ -819,7 +819,7 @@ func (m *Manager) handleForwardedLocalTraffic(packetData []byte) bool {
819819
func (m *Manager) handleRoutedTraffic(d *decoder, srcIP, dstIP netip.Addr, packetData []byte, size int) bool {
820820
// Drop if routing is disabled
821821
if !m.routingEnabled.Load() {
822-
m.logger.Trace("Dropping routed packet (routing disabled): src=%s dst=%s",
822+
m.logger.Trace2("Dropping routed packet (routing disabled): src=%s dst=%s",
823823
srcIP, dstIP)
824824
return true
825825
}
@@ -835,7 +835,7 @@ func (m *Manager) handleRoutedTraffic(d *decoder, srcIP, dstIP netip.Addr, packe
835835

836836
ruleID, pass := m.routeACLsPass(srcIP, dstIP, proto, srcPort, dstPort)
837837
if !pass {
838-
m.logger.Trace("Dropping routed packet (ACL denied): rule_id=%s proto=%v src=%s:%d dst=%s:%d",
838+
m.logger.Trace6("Dropping routed packet (ACL denied): rule_id=%s proto=%v src=%s:%d dst=%s:%d",
839839
ruleID, pnum, srcIP, srcPort, dstIP, dstPort)
840840

841841
m.flowLogger.StoreEvent(nftypes.EventFields{
@@ -863,7 +863,7 @@ func (m *Manager) handleRoutedTraffic(d *decoder, srcIP, dstIP netip.Addr, packe
863863
fwd.RegisterRuleID(srcIP, dstIP, srcPort, dstPort, ruleID)
864864

865865
if err := fwd.InjectIncomingPacket(packetData); err != nil {
866-
m.logger.Error("Failed to inject routed packet: %v", err)
866+
m.logger.Error1("Failed to inject routed packet: %v", err)
867867
fwd.DeleteRuleID(srcIP, dstIP, srcPort, dstPort)
868868
}
869869
}
@@ -901,7 +901,7 @@ func getPortsFromPacket(d *decoder) (srcPort, dstPort uint16) {
901901
// It returns true, true if the packet is a fragment and valid.
902902
func (m *Manager) isValidPacket(d *decoder, packetData []byte) (bool, bool) {
903903
if err := d.parser.DecodeLayers(packetData, &d.decoded); err != nil {
904-
m.logger.Trace("couldn't decode packet, err: %s", err)
904+
m.logger.Trace1("couldn't decode packet, err: %s", err)
905905
return false, false
906906
}
907907

‎client/firewall/uspfilter/forwarder/endpoint.go‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -57,7 +57,7 @@ func (e *endpoint) WritePackets(pkts stack.PacketBufferList) (int, tcpip.Error)
5757
address := netHeader.DestinationAddress()
5858
err := e.device.CreateOutboundPacket(data.AsSlice(), address.AsSlice())
5959
if err != nil {
60-
e.logger.Error("CreateOutboundPacket: %v", err)
60+
e.logger.Error1("CreateOutboundPacket: %v", err)
6161
continue
6262
}
6363
written++

‎client/firewall/uspfilter/forwarder/icmp.go‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -34,14 +34,14 @@ func (f *Forwarder) handleICMP(id stack.TransportEndpointID, pkt stack.PacketBuf
3434
// TODO: support non-root
3535
conn, err := lc.ListenPacket(ctx, "ip4:icmp", "0.0.0.0")
3636
if err != nil {
37-
f.logger.Error("forwarder: Failed to create ICMP socket for %v: %v", epID(id), err)
37+
f.logger.Error2("forwarder: Failed to create ICMP socket for %v: %v", epID(id), err)
3838

3939
// This will make netstack reply on behalf of the original destination, that's ok for now
4040
return false
4141
}
4242
defer func() {
4343
if err := conn.Close(); err != nil {
44-
f.logger.Debug("forwarder: Failed to close ICMP socket: %v", err)
44+
f.logger.Debug1("forwarder: Failed to close ICMP socket: %v", err)
4545
}
4646
}()
4747

@@ -52,11 +52,11 @@ func (f *Forwarder) handleICMP(id stack.TransportEndpointID, pkt stack.PacketBuf
5252
payload := fullPacket.AsSlice()
5353

5454
if _, err = conn.WriteTo(payload, dst); err != nil {
55-
f.logger.Error("forwarder: Failed to write ICMP packet for %v: %v", epID(id), err)
55+
f.logger.Error2("forwarder: Failed to write ICMP packet for %v: %v", epID(id), err)
5656
return true
5757
}
5858

59-
f.logger.Trace("forwarder: Forwarded ICMP packet %v type %v code %v",
59+
f.logger.Trace3("forwarder: Forwarded ICMP packet %v type %v code %v",
6060
epID(id), icmpHdr.Type(), icmpHdr.Code())
6161

6262
// For Echo Requests, send and handle response
@@ -72,15 +72,15 @@ func (f *Forwarder) handleICMP(id stack.TransportEndpointID, pkt stack.PacketBuf
7272

7373
func (f *Forwarder) handleEchoResponse(icmpHdr header.ICMPv4, conn net.PacketConn, id stack.TransportEndpointID) int {
7474
if err := conn.SetReadDeadline(time.Now().Add(5 * time.Second)); err != nil {
75-
f.logger.Error("forwarder: Failed to set read deadline for ICMP response: %v", err)
75+
f.logger.Error1("forwarder: Failed to set read deadline for ICMP response: %v", err)
7676
return 0
7777
}
7878

7979
response := make([]byte, f.endpoint.mtu)
8080
n, _, err := conn.ReadFrom(response)
8181
if err != nil {
8282
if !isTimeout(err) {
83-
f.logger.Error("forwarder: Failed to read ICMP response: %v", err)
83+
f.logger.Error1("forwarder: Failed to read ICMP response: %v", err)
8484
}
8585
return 0
8686
}
@@ -101,12 +101,12 @@ func (f *Forwarder) handleEchoResponse(icmpHdr header.ICMPv4, conn net.PacketCon
101101
fullPacket = append(fullPacket, response[:n]...)
102102

103103
if err := f.InjectIncomingPacket(fullPacket); err != nil {
104-
f.logger.Error("forwarder: Failed to inject ICMP response: %v", err)
104+
f.logger.Error1("forwarder: Failed to inject ICMP response: %v", err)
105105

106106
return 0
107107
}
108108

109-
f.logger.Trace("forwarder: Forwarded ICMP echo reply for %v type %v code %v",
109+
f.logger.Trace3("forwarder: Forwarded ICMP echo reply for %v type %v code %v",
110110
epID(id), icmpHdr.Type(), icmpHdr.Code())
111111

112112
return len(fullPacket)

‎client/firewall/uspfilter/forwarder/tcp.go‎

Lines changed: 9 additions & 9 deletions
Original file line numberDiff line numberDiff line change
@@ -38,7 +38,7 @@ func (f *Forwarder) handleTCP(r *tcp.ForwarderRequest) {
3838
outConn, err := (&net.Dialer{}).DialContext(f.ctx, "tcp", dialAddr)
3939
if err != nil {
4040
r.Complete(true)
41-
f.logger.Trace("forwarder: dial error for %v: %v", epID(id), err)
41+
f.logger.Trace2("forwarder: dial error for %v: %v", epID(id), err)
4242
return
4343
}
4444

@@ -47,9 +47,9 @@ func (f *Forwarder) handleTCP(r *tcp.ForwarderRequest) {
4747

4848
ep, epErr := r.CreateEndpoint(&wq)
4949
if epErr != nil {
50-
f.logger.Error("forwarder: failed to create TCP endpoint: %v", epErr)
50+
f.logger.Error1("forwarder: failed to create TCP endpoint: %v", epErr)
5151
if err := outConn.Close(); err != nil {
52-
f.logger.Debug("forwarder: outConn close error: %v", err)
52+
f.logger.Debug1("forwarder: outConn close error: %v", err)
5353
}
5454
r.Complete(true)
5555
return
@@ -61,7 +61,7 @@ func (f *Forwarder) handleTCP(r *tcp.ForwarderRequest) {
6161
inConn := gonet.NewTCPConn(&wq, ep)
6262

6363
success = true
64-
f.logger.Trace("forwarder: established TCP connection %v", epID(id))
64+
f.logger.Trace1("forwarder: established TCP connection %v", epID(id))
6565

6666
go f.proxyTCP(id, inConn, outConn, ep, flowID)
6767
}
@@ -75,10 +75,10 @@ func (f *Forwarder) proxyTCP(id stack.TransportEndpointID, inConn *gonet.TCPConn
7575
<-ctx.Done()
7676
// Close connections and endpoint.
7777
if err := inConn.Close(); err != nil && !isClosedError(err) {
78-
f.logger.Debug("forwarder: inConn close error: %v", err)
78+
f.logger.Debug1("forwarder: inConn close error: %v", err)
7979
}
8080
if err := outConn.Close(); err != nil && !isClosedError(err) {
81-
f.logger.Debug("forwarder: outConn close error: %v", err)
81+
f.logger.Debug1("forwarder: outConn close error: %v", err)
8282
}
8383

8484
ep.Close()
@@ -111,12 +111,12 @@ func (f *Forwarder) proxyTCP(id stack.TransportEndpointID, inConn *gonet.TCPConn
111111

112112
if errInToOut != nil {
113113
if !isClosedError(errInToOut) {
114-
f.logger.Error("proxyTCP: copy error (in → out) for %s: %v", epID(id), errInToOut)
114+
f.logger.Error2("proxyTCP: copy error (in → out) for %s: %v", epID(id), errInToOut)
115115
}
116116
}
117117
if errOutToIn != nil {
118118
if !isClosedError(errOutToIn) {
119-
f.logger.Error("proxyTCP: copy error (out → in) for %s: %v", epID(id), errOutToIn)
119+
f.logger.Error2("proxyTCP: copy error (out → in) for %s: %v", epID(id), errOutToIn)
120120
}
121121
}
122122

@@ -127,7 +127,7 @@ func (f *Forwarder) proxyTCP(id stack.TransportEndpointID, inConn *gonet.TCPConn
127127
txPackets = tcpStats.SegmentsReceived.Value()
128128
}
129129

130-
f.logger.Trace("forwarder: Removed TCP connection %s [in: %d Pkts/%d B, out: %d Pkts/%d B]", epID(id), rxPackets, bytesFromOutToIn, txPackets, bytesFromInToOut)
130+
f.logger.Trace5("forwarder: Removed TCP connection %s [in: %d Pkts/%d B, out: %d Pkts/%d B]", epID(id), rxPackets, bytesFromOutToIn, txPackets, bytesFromInToOut)
131131

132132
f.sendTCPEvent(nftypes.TypeEnd, flowID, id, uint64(bytesFromOutToIn), uint64(bytesFromInToOut), rxPackets, txPackets)
133133
}

0 commit comments

Comments
 (0)