sensors: reduce the logs when {,un}loading policies

Currently, we emit a log line for every program and map loaded/unloaded in a policy. As policies, becomes more complicated, this makes logs very verbose. This commit addresses this by moving the logging of the messages into Debug, and adding the information of what maps/programs are loaded in a single line that relates to the sensor. An example using the base sensor can be found below. Before: Loading: | time="2024-11-29T14:34:24+01:00" level=info msg="Loading sensor" name=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="Loading kernel version 6.8.12" | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=execve_map max="{0 false}" path=/sys/fs/bpf/tetragon/execve_map sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=tg_execve_joined_info_map max="{0 false}" path=/sys/fs/bpf/tetragon/tg_execve_joined_info_map sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=execve_map_stats max="{0 false}" path=/sys/fs/bpf/tetragon/execve_map_stats sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=tg_execve_joined_info_map_stats max="{0 false}" path=/sys/fs/bpf/tetragon/tg_execve_joined_info_map_stats sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=execve_calls max="{0 false}" path=/sys/fs/bpf/tetragon/__base__/event_execve/execve_calls sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=tcpmon_map max="{0 false}" path=/sys/fs/bpf/tetragon/tcpmon_map sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=tg_conf_map max="{0 false}" path=/sys/fs/bpf/tetragon/tg_conf_map sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=tg_stats_map max="{0 false}" path=/sys/fs/bpf/tetragon/tg_stats_map sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="tetragon, map loaded." map=tg_mbset_map max="{0 false}" path=/sys/fs/bpf/tetragon/tg_mbset_map sensor=__base__ | time="2024-11-29T14:34:24+01:00" level=info msg="Loading BPF program" Attach=acct_process Program=bpf/objs/bpf_exit.o Type=kprobe | time="2024-11-29T14:34:24+01:00" level=info msg="Loading BPF program" Attach=wake_up_new_task Program=bpf/objs/bpf_fork.o Type=kprobe | time="2024-11-29T14:34:24+01:00" level=info msg="Loading registered BPF probe" Attach=sched/sched_process_exec Program=bpf/objs/bpf_execve_event_v61.o Type=execve | time="2024-11-29T14:34:24+01:00" level=info msg="Loading BPF program" Attach=security_bprm_committing_creds Program=bpf/objs/bpf_execve_bprm_commit_creds.o Type=kprobe | time="2024-11-29T14:34:25+01:00" level=info msg="Loaded BPF maps and events for sensor successfully" sensor=__base__ Unloading: | time="2024-11-29T14:35:32+01:00" level=info msg="BPF prog was unloaded" label=kprobe/acct_process pin=__base__/event_exit | time="2024-11-29T14:35:32+01:00" level=info msg="BPF prog was unloaded" label=kprobe/wake_up_new_task pin=__base__/kprobe_pid_clear | time="2024-11-29T14:35:32+01:00" level=info msg="BPF prog was unloaded" label=tracepoint/sys_execve pin=__base__/event_execve | time="2024-11-29T14:35:32+01:00" level=info msg="BPF prog was unloaded" label=kprobe/security_bprm_committing_creds pin=__base__/tg_kp_bprm_committing_creds | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=execve_map pin=execve_map | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=tg_execve_joined_info_map pin=tg_execve_joined_info_map | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=execve_map_stats pin=execve_map_stats | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=tg_execve_joined_info_map_stats pin=tg_execve_joined_info_map_stats | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=execve_calls pin=__base__/event_execve/execve_calls | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=tcpmon_map pin=tcpmon_map | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=tg_conf_map pin=tg_conf_map | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=tg_stats_map pin=tg_stats_map | time="2024-11-29T14:35:32+01:00" level=info msg="map was unloaded" map=tg_mbset_map pin=tg_mbset_map Now: Loading: | time="2024-11-29T14:36:44+01:00" level=info msg="Loading sensor" name=__base__ | time="2024-11-29T14:36:44+01:00" level=info msg="Loading kernel version 6.8.12" | time="2024-11-29T14:36:44+01:00" level=info msg="Loaded BPF maps and events for sensor successfully" maps="[Map{Name:execve_map PinPath:execve_map} Map{Name:tg_execve_joined_info_map PinPath:tg_execve_joined_info_map} Map{Name:execve_map_stats PinPath:execve_map_stats} Map{Name:tg_execve_joined_info_map_stats PinPath:tg_execve_joined_info_map_stats} Map{Name:execve_calls PinPath:__base__/event_execve/execve_calls} Map{Name:tcpmon_map PinPath:tcpmon_map} Map{Name:tg_conf_map PinPath:tg_conf_map} Map{Name:tg_stats_map PinPath:tg_stats_map} Map{Name:tg_mbset_map PinPath:tg_mbset_map}]" progs="[Program{Name:bpf/objs/bpf_exit.o Attach:acct_process Label:kprobe/acct_process PinPath:__base__/event_exit} Program{Name:bpf/objs/bpf_fork.o Attach:wake_up_new_task Label:kprobe/wake_up_new_task PinPath:__base__/kprobe_pid_clear} Program{Name:bpf/objs/bpf_execve_event_v61.o Attach:sched/sched_process_exec Label:tracepoint/sys_execve PinPath:__base__/event_execve} Program{Name:bpf/objs/bpf_execve_bprm_commit_creds.o Attach:security_bprm_committing_creds Label:kprobe/security_bprm_committing_creds PinPath:__base__/tg_kp_bprm_committing_creds}]" sensor=__base__ Unloading: | time="2024-11-29T14:37:48+01:00" level=info msg="Unloading sensor __base__" | time="2024-11-29T14:37:48+01:00" level=info msg="Sensor unloaded" maps="[Map{Name:execve_map PinPath:execve_map} Map{Name:tg_execve_joined_info_map PinPath:tg_execve_joined_info_map} Map{Name:execve_map_stats PinPath:execve_map_stats} Map{Name:tg_execve_joined_info_map_stats PinPath:tg_execve_joined_info_map_stats} Map{Name:execve_calls PinPath:__base__/event_execve/execve_calls} Map{Name:tcpmon_map PinPath:tcpmon_map} Map{Name:tg_conf_map PinPath:tg_conf_map} Map{Name:tg_stats_map PinPath:tg_stats_map} Map{Name:tg_mbset_map PinPath:tg_mbset_map}]" maps-error="[]" progs="[Program{Name:bpf/objs/bpf_exit.o Attach:acct_process Label:kprobe/acct_process PinPath:__base__/event_exit} Program{Name:bpf/objs/bpf_fork.o Attach:wake_up_new_task Label:kprobe/wake_up_new_task PinPath:__base__/kprobe_pid_clear} Program{Name:bpf/objs/bpf_execve_event_v61.o Attach:sched/sched_process_exec Label:tracepoint/sys_execve PinPath:__base__/event_execve} Program{Name:bpf/objs/bpf_execve_bprm_commit_creds.o Attach:security_bprm_committing_creds Label:kprobe/security_bprm_committing_creds PinPath:__base__/tg_kp_bprm_committing_creds}]" Signed-off-by: Kornilios Kourtis <[email protected]>
cilium · Dec 2, 2024 · 04a1c6f · 04a1c6f
1 parent e1a1faf
commit 04a1c6f
Show file tree

Hide file tree

Showing 3 changed files with 29 additions and 6 deletions.
diff --git a/pkg/sensors/load.go b/pkg/sensors/load.go
@@ -185,7 +185,11 @@ func (s *Sensor) Load(bpfDir string) (err error) {
 	// cleanup the BTF once we have loaded all sensor's program
 	btf.FlushKernelSpec()
 
-	l.WithField("sensor", s.Name).Infof("Loaded BPF maps and events for sensor successfully")
+	l.WithFields(logrus.Fields{
+		"sensor": s.Name,
+		"maps":   loadedMaps,
+		"progs":  loadedProgs,
+	}).Infof("Loaded BPF maps and events for sensor successfully")
 	s.Loaded = true
 	return nil
 }
@@ -202,13 +206,19 @@ func (s *Sensor) Unload(unpin bool) error {
 		}
 	}
 
+	var progs []string
 	for _, p := range s.Progs {
 		unloadProgram(p, unpin)
+		progs = append(progs, p.String())
 	}
 
+	var mapsOk, mapsErr []string
 	for _, m := range s.Maps {
 		if err := m.Unload(unpin); err != nil {
 			logger.GetLogger().WithError(err).WithField("map", s.Name).Warn("Failed to unload map")
+			mapsErr = append(mapsErr, m.String())
+		} else {
+			mapsOk = append(mapsOk, m.String())
 		}
 	}
 
@@ -225,6 +235,11 @@ func (s *Sensor) Unload(unpin bool) error {
 	}
 
 	progsCleanup()
+	logger.GetLogger().WithFields(logrus.Fields{
+		"maps":       mapsOk,
+		"maps-error": mapsErr,
+		"progs":      progs,
+	}).Infof("Sensor unloaded")
 	return nil
 }
 
@@ -367,7 +382,7 @@ func (s *Sensor) loadMap(bpfDir string, m *program.Map) error {
 		"map":    m.Name,
 		"path":   pinPath,
 		"max":    m.Entries,
-	}).Info("tetragon, map loaded.")
+	}).Debug("tetragon, map loaded.")
 
 	return nil
 }
@@ -441,7 +456,7 @@ func loadInstance(bpfDir string, load *program.Program, version, verbose int) er
 		logger.GetLogger().WithField("Program", load.Name).
 			WithField("Type", load.Type).
 			WithField("Attach", load.Attach).
-			Info("Loading BPF program")
+			Debug("Loading BPF program")
 		return loadFn(bpfDir, load, verbose)
 	}
 	// Otherwise, check for a registered probe type. If one exists, use that.
@@ -450,7 +465,7 @@ func loadInstance(bpfDir string, load *program.Program, version, verbose int) er
 		logger.GetLogger().WithField("Program", load.Name).
 			WithField("Type", load.Type).
 			WithField("Attach", load.Attach).
-			Info("Loading registered BPF probe")
+			Debug("Loading registered BPF probe")
 		// Registered probes need extra setup
 		version = kernels.FixKernelVersion(version)
 		return probe.LoadProbe(LoadProbeArgs{
@@ -488,7 +503,7 @@ func unloadProgram(prog *program.Program, unpin bool) {
 		logger.GetLogger().WithField("name", prog.Name).WithError(err).Warn("Failed to unload program")
 	}
 
-	log.Info("BPF prog was unloaded")
+	log.Debug("BPF prog was unloaded")
 }
 
 func UnloadSensors(sens []SensorIface) {

diff --git a/pkg/sensors/program/map.go b/pkg/sensors/program/map.go
@@ -104,6 +104,10 @@ type Map struct {
 	Owner        bool
 }
 
+func (m *Map) String() string {
+	return fmt.Sprintf("Map{Name:%s PinPath:%s}", m.Name, m.PinPath)
+}
+
 // globalMaps keeps a record of all global maps to exclude them from per policy
 // memory map accounting.
 var globalMaps = struct {
@@ -220,7 +224,7 @@ func (m *Map) Unload(unpin bool) error {
 		log.WithField("count", count).Debug("Reference exists, not unloading map yet")
 		return nil
 	}
-	log.Info("map was unloaded")
+	log.Debug("map was unloaded")
 	if m.MapHandle != nil {
 		if m.IsOwner() && unpin {
 			m.MapHandle.Unpin()

diff --git a/pkg/sensors/program/program.go b/pkg/sensors/program/program.go
@@ -163,6 +163,10 @@ type Program struct {
 	LoadedMapsInfo map[int]bpf.ExtendedMapInfo
 }
 
+func (p *Program) String() string {
+	return fmt.Sprintf("Program{Name:%s Attach:%s Label:%s PinPath:%s}", p.Name, p.Attach, p.Label, p.PinPath)
+}
+
 func (p *Program) SetRetProbe(ret bool) *Program {
 	p.RetProbe = ret
 	return p