From e15f150bad82480976dee0f4415cf05b8d934de1 Mon Sep 17 00:00:00 2001 From: Qiyue Yao <39061776+qiyueyao@users.noreply.github.com> Date: Wed, 25 Sep 2024 15:08:44 -0700 Subject: [PATCH] Fix L7NP packet logging (#6651) Currently when enableLogging is enabled for an L7NP rule, we enable "tagged" packet logging in the appropriate Suricata reject rule. Unfortunately, this leads to the wrong packet being logged: the RST packet generated by Suricata instead of the original TCP packet containing the HTTP request from the client. This solution modifies the design to remove enableLogging in L7, keep it in L4, and instead configure Suricata to log packet info for all alert events. This is a global configuration, and no longer a per-rule configuration. Experiments revealed that enabling packet logging for all reject rules only had a minor impact (5%) in performance. Therefore, logging is always enabled, unconditionally. Fixes #6636. Signed-off-by: Qiyue Yao --- docs/antrea-l7-network-policy.md | 39 +++++------ .../networkpolicy/l7engine/reconciler.go | 22 ++---- .../networkpolicy/l7engine/reconciler_test.go | 4 +- .../networkpolicy/networkpolicy_controller.go | 6 +- test/e2e/l7networkpolicy_test.go | 67 ++++++++++++++----- 5 files changed, 82 insertions(+), 56 deletions(-) diff --git a/docs/antrea-l7-network-policy.md b/docs/antrea-l7-network-policy.md index 1f917de0152..62fecd80d20 100644 --- a/docs/antrea-l7-network-policy.md +++ b/docs/antrea-l7-network-policy.md @@ -329,20 +329,20 @@ Allow ingress from client (10.10.1.9) to web (10.10.1.10/public/*). } ``` -Deny ingress from client (10.10.1.9) to web (10.10.1.10/admin/*) +Deny ingress from client (10.10.1.4) to web (10.10.1.3/admin/*). ```json { - "timestamp": "2024-08-26T22:38:26.019956+0000", - "flow_id": 642636870504569, + "timestamp": "2024-09-05T22:49:24.788756+0000", + "flow_id": 1131530446896560, "in_iface": "antrea-l7-tap0", "event_type": "alert", "vlan": [ 2 ], - "src_ip": "10.10.1.9", - "src_port": 37892, - "dest_ip": "10.10.1.10", + "src_ip": "10.10.1.4", + "src_port": 45034, + "dest_ip": "10.10.1.3", "dest_port": 80, "proto": "TCP", "pkt_src": "wire/pcap", @@ -362,36 +362,37 @@ Deny ingress from client (10.10.1.9) to web (10.10.1.10/admin/*) "flow": { "pkts_toserver": 3, "pkts_toclient": 1, - "bytes_toserver": 308, + "bytes_toserver": 307, "bytes_toclient": 78, - "start": "2024-08-26T22:38:26.018553+0000", - "src_ip": "10.10.1.9", - "dest_ip": "10.10.1.10", - "src_port": 37892, + "start": "2024-09-05T22:49:24.787742+0000", + "src_ip": "10.10.1.4", + "dest_ip": "10.10.1.3", + "src_port": 45034, "dest_port": 80 } } ``` -Additional packet log when `enableLogging` is set +Additional packet logs are available when `enableLogging` is set, which tracks all +packets in Suricata matching the dst IP address of the packet generating the alert. ```json { - "timestamp": "2024-08-26T22:38:26.025742+0000", - "flow_id": 642636870504569, + "timestamp": "2024-09-05T22:49:24.788756+0000", + "flow_id": 1131530446896560, "in_iface": "antrea-l7-tap0", "event_type": "packet", "vlan": [ 2 ], - "src_ip": "10.10.1.10", - "src_port": 80, - "dest_ip": "10.10.1.9", - "dest_port": 37892, + "src_ip": "10.10.1.4", + "src_port": 45034, + "dest_ip": "10.10.1.3", + "dest_port": 80, "proto": "TCP", "pkt_src": "wire/pcap", "tenant_id": 2, - "packet": "/hYGSsKknh8fnhcggQAAAggARQAAKN7MAABABoXdCgoBCgoKAQkAUJQE0EfjHLfFVXZQFAH7QroAAA==", + "packet": "dtwWezuaHlOhfWpNgQAAAggARQAAjU/0QABABtRcCgoBBAoKAQOv6gBQgOZTvPTauPuAGAH7TZcAAAEBCAouFZzsR8fBM0dFVCAvYWRtaW4vaW5kZXguaHRtbCBIVFRQLzEuMQ0KSG9zdDogMTAuMTAuMS4zDQpVc2VyLUFnZW50OiBjdXJsLzcuNzQuMA0KQWNjZXB0OiAqLyoNCg0K", "packet_info": { "linktype": 1 } diff --git a/pkg/agent/controller/networkpolicy/l7engine/reconciler.go b/pkg/agent/controller/networkpolicy/l7engine/reconciler.go index eb2d24fa289..40ff2ffa854 100644 --- a/pkg/agent/controller/networkpolicy/l7engine/reconciler.go +++ b/pkg/agent/controller/networkpolicy/l7engine/reconciler.go @@ -78,10 +78,9 @@ outputs: enabled: no types: - alert: - tagged-packets: yes + packet: yes - http: extended: yes - tagged-packets: yes - tls: extended: yes - eve-log: @@ -170,19 +169,12 @@ func NewReconciler() *Reconciler { } } -func generateTenantRulesData(policyName string, protoKeywords map[string]sets.Set[string], enableLogging bool) *bytes.Buffer { +func generateTenantRulesData(policyName string, protoKeywords map[string]sets.Set[string]) *bytes.Buffer { rulesData := bytes.NewBuffer(nil) sid := 1 - // Enable logging of packets in the session that set off the rule, the session is tagged for 30 seconds. - // Refer to Suricata detect engine in codebase for detailed tag keyword configuration. - var tagKeyword string - if enableLogging { - tagKeyword = " tag: session, 30, seconds;" - } - // Generate default reject rule. - allKeywords := fmt.Sprintf(`msg: "Reject by %s"; flow: to_server, established;%s sid: %d;`, policyName, tagKeyword, sid) + allKeywords := fmt.Sprintf(`msg: "Reject by %s"; flow: to_server, established; sid: %d;`, policyName, sid) rule := fmt.Sprintf("reject ip any any -> any any (%s)\n", allKeywords) rulesData.WriteString(rule) sid++ @@ -193,9 +185,9 @@ func generateTenantRulesData(policyName string, protoKeywords map[string]sets.Se // It is a convention that the sid is provided as the last keyword (or second-to-last if there is a rev) // of a rule. if keywords != "" { - allKeywords = fmt.Sprintf(`msg: "Allow %s by %s"; %s%s sid: %d;`, proto, policyName, keywords, tagKeyword, sid) + allKeywords = fmt.Sprintf(`msg: "Allow %s by %s"; %s sid: %d;`, proto, policyName, keywords, sid) } else { - allKeywords = fmt.Sprintf(`msg: "Allow %s by %s";%s sid: %d;`, proto, policyName, tagKeyword, sid) + allKeywords = fmt.Sprintf(`msg: "Allow %s by %s"; sid: %d;`, proto, policyName, sid) } rule = fmt.Sprintf("pass %s any any -> any any (%s)\n", proto, allKeywords) rulesData.WriteString(rule) @@ -274,7 +266,7 @@ func (r *Reconciler) StartSuricataOnce() { }) } -func (r *Reconciler) AddRule(ruleID, policyName string, vlanID uint32, l7Protocols []v1beta.L7Protocol, enableLogging bool) error { +func (r *Reconciler) AddRule(ruleID, policyName string, vlanID uint32, l7Protocols []v1beta.L7Protocol) error { start := time.Now() defer func() { klog.V(5).Infof("AddRule took %v", time.Since(start)) @@ -304,7 +296,7 @@ func (r *Reconciler) AddRule(ruleID, policyName string, vlanID uint32, l7Protoco klog.InfoS("Reconciling L7 rule", "RuleID", ruleID, "PolicyName", policyName) // Write the Suricata rules to file. rulesPath := generateTenantRulesPath(vlanID) - rulesData := generateTenantRulesData(policyName, protoKeywords, enableLogging) + rulesData := generateTenantRulesData(policyName, protoKeywords) if err := writeConfigFile(rulesPath, rulesData); err != nil { return fmt.Errorf("failed to write Suricata rules data to file %s for L7 rule %s of %s, err: %w", rulesPath, ruleID, policyName, err) } diff --git a/pkg/agent/controller/networkpolicy/l7engine/reconciler_test.go b/pkg/agent/controller/networkpolicy/l7engine/reconciler_test.go index 340547cfba1..39a1745fd80 100644 --- a/pkg/agent/controller/networkpolicy/l7engine/reconciler_test.go +++ b/pkg/agent/controller/networkpolicy/l7engine/reconciler_test.go @@ -189,7 +189,7 @@ func TestRuleLifecycle(t *testing.T) { fe.startSuricataFn = fs.startSuricataFn // Test add a L7 NetworkPolicy. - assert.NoError(t, fe.AddRule(ruleID, policyName, vlanID, tc.l7Protocols, false)) + assert.NoError(t, fe.AddRule(ruleID, policyName, vlanID, tc.l7Protocols)) rulesPath := generateTenantRulesPath(vlanID) ok, err := afero.FileContainsBytes(defaultFS, rulesPath, []byte(tc.expectedRules)) @@ -206,7 +206,7 @@ func TestRuleLifecycle(t *testing.T) { assert.Equal(t, expectedScCommands, fs.calledScCommands) // Update the added L7 NetworkPolicy. - assert.NoError(t, fe.AddRule(ruleID, policyName, vlanID, tc.updatedL7Protocols, false)) + assert.NoError(t, fe.AddRule(ruleID, policyName, vlanID, tc.updatedL7Protocols)) expectedScCommands.Insert("reload-tenant 1 /etc/suricata/antrea-tenant-1.yaml") assert.Equal(t, expectedScCommands, fs.calledScCommands) diff --git a/pkg/agent/controller/networkpolicy/networkpolicy_controller.go b/pkg/agent/controller/networkpolicy/networkpolicy_controller.go index 05a5ea315e7..ae0afe124c4 100644 --- a/pkg/agent/controller/networkpolicy/networkpolicy_controller.go +++ b/pkg/agent/controller/networkpolicy/networkpolicy_controller.go @@ -72,7 +72,7 @@ const ( ) type L7RuleReconciler interface { - AddRule(ruleID, policyName string, vlanID uint32, l7Protocols []v1beta2.L7Protocol, enableLogging bool) error + AddRule(ruleID, policyName string, vlanID uint32, l7Protocols []v1beta2.L7Protocol) error DeleteRule(ruleID string, vlanID uint32) error } @@ -802,7 +802,7 @@ func (c *Controller) syncRule(key string) error { vlanID := c.l7VlanIDAllocator.allocate(key) rule.L7RuleVlanID = &vlanID - if err := c.l7RuleReconciler.AddRule(key, rule.SourceRef.ToString(), vlanID, rule.L7Protocols, rule.EnableLogging); err != nil { + if err := c.l7RuleReconciler.AddRule(key, rule.SourceRef.ToString(), vlanID, rule.L7Protocols); err != nil { return err } } @@ -857,7 +857,7 @@ func (c *Controller) syncRules(keys []string) error { vlanID := c.l7VlanIDAllocator.allocate(key) rule.L7RuleVlanID = &vlanID - if err := c.l7RuleReconciler.AddRule(key, rule.SourceRef.ToString(), vlanID, rule.L7Protocols, rule.EnableLogging); err != nil { + if err := c.l7RuleReconciler.AddRule(key, rule.SourceRef.ToString(), vlanID, rule.L7Protocols); err != nil { return err } } diff --git a/test/e2e/l7networkpolicy_test.go b/test/e2e/l7networkpolicy_test.go index a2b6090c56f..be0cf549c10 100644 --- a/test/e2e/l7networkpolicy_test.go +++ b/test/e2e/l7networkpolicy_test.go @@ -15,11 +15,13 @@ package e2e import ( + "bytes" "context" "encoding/json" "fmt" "net" "reflect" + "regexp" "slices" "strings" "testing" @@ -396,12 +398,16 @@ func testL7NetworkPolicyLogging(t *testing.T, data *TestData) { var l7LogMatchers []*L7LogEntry for _, ip := range serverIPs { clientMatcher := &L7LogEntry{ - EventType: "alert", - DestIP: ip.String(), - DestPort: 8080, - Protocol: "TCP", - AppProtocol: "http", - Alert: &L7LogAlertEntry{Action: "blocked", Signature: fmt.Sprintf("Reject by AntreaNetworkPolicy:%s/%s", data.testNamespace, policyAllowPathHostname)}, + EventType: "alert", + DestIP: ip.String(), + DestPort: 8080, + Protocol: "TCP", + AppProtocol: "http", + expectedPacketRegex: regexp.MustCompile(fmt.Sprintf("%s|HTTP|GET|%s", ip.String(), "/clientip")), + Alert: &L7LogAlertEntry{ + Action: "blocked", + Signature: fmt.Sprintf("Reject by AntreaNetworkPolicy:%s/%s", data.testNamespace, policyAllowPathHostname), + }, } hostMatcher := &L7LogEntry{ EventType: "http", @@ -429,17 +435,44 @@ type L7LogAlertEntry struct { } type L7LogEntry struct { - EventType string `json:"event_type"` - DestIP string `json:"dest_ip"` - DestPort int32 `json:"dest_port"` - Protocol string `json:"proto"` - AppProtocol string `json:"app_proto,omitempty"` - Http *L7LogHttpEntry `json:"http,omitempty"` - Alert *L7LogAlertEntry `json:"alert,omitempty"` + EventType string `json:"event_type"` + DestIP string `json:"dest_ip"` + DestPort int32 `json:"dest_port"` + Protocol string `json:"proto"` + AppProtocol string `json:"app_proto,omitempty"` + PacketBytes []byte `json:"packet,omitempty"` + Http *L7LogHttpEntry `json:"http,omitempty"` + Alert *L7LogAlertEntry `json:"alert,omitempty"` + expectedPacketRegex *regexp.Regexp } -func (e *L7LogEntry) Equal(x *L7LogEntry) bool { - return reflect.DeepEqual(e, x) +// Matches the 2 L7LogEntries. If an L7LogEntry includes an expectedPacketRegex, the +// PacketBytes field in the other L7LogEntry must match the regex. If none of the +// L7LogEntries include an expectedPacketRegex, the PacketBytes fields must be +// strictly equal for both entries. +func (e *L7LogEntry) Match(x *L7LogEntry) bool { + packetMatch := func(e, x *L7LogEntry) bool { + if e.expectedPacketRegex != nil { + if !e.expectedPacketRegex.Match(x.PacketBytes) { + return false + } + } + if x.expectedPacketRegex != nil { + if !x.expectedPacketRegex.Match(e.PacketBytes) { + return false + } + } + if e.expectedPacketRegex == nil && x.expectedPacketRegex == nil { + if !bytes.Equal(e.PacketBytes, x.PacketBytes) { + return false + } + } + return true + } + + return e.EventType == x.EventType && e.DestIP == x.DestIP && e.DestPort == x.DestPort && + e.Protocol == x.Protocol && e.AppProtocol == x.AppProtocol && packetMatch(e, x) && + reflect.DeepEqual(e.Http, x.Http) && reflect.DeepEqual(e.Alert, x.Alert) } func (e *L7LogEntry) String() string { @@ -469,11 +502,11 @@ func checkL7LoggingResult(t *testing.T, data *TestData, antreaPodName string, l7 return false, err } // ignore unexpected log entries and duplicates - if slices.ContainsFunc(expected, log.Equal) && !slices.ContainsFunc(actual, log.Equal) { + if slices.ContainsFunc(expected, log.Match) && !slices.ContainsFunc(actual, log.Match) { actual = append(actual, log) } } - if !slices.EqualFunc(actual, expected, func(e1, e2 *L7LogEntry) bool { return e1.Equal(e2) }) { + if !slices.EqualFunc(actual, expected, func(e1, e2 *L7LogEntry) bool { return e1.Match(e2) }) { t.Logf("L7NP log mismatch") t.Logf("Expected: %v", expected) t.Logf("Actual: %v", actual)