Use slog with proper levels for logging

Author: gauravakto

ebpf/bpfwrapper/deleteProbes.go

@@ -1,7 +1,7 @@
 package bpfwrapper
 
 import (
-	"fmt"
+	"log/slog"
 	"os/exec"
 	"strings"
 )
@@ -12,7 +12,7 @@ func DeleteExistingAktoKernelProbes() {
 
 	listOutput, err := listCmd.Output()
 	if err != nil {
-		fmt.Println("Error listing kprobes:", err)
+		slog.Error("Error listing kprobes", "error", err)
 		return
 	}
 
@@ -37,9 +37,9 @@ func DeleteExistingAktoKernelProbes() {
 
 			// Run the command
 			if err := deleteCmd.Run(); err != nil {
-				fmt.Printf("Error deleting kprobe %s: %v\n", kprobeName, err)
+				slog.Error("Error deleting kprobe", "kprobe", kprobeName, "error", err)
 			} else {
-				fmt.Printf("Deleted kprobe %s\n", kprobeName)
+				slog.Debug("Deleted kprobe", "kprobe", kprobeName)
 			}
 		}
 	}

ebpf/bpfwrapper/eventCallbacks.go

@@ -3,7 +3,7 @@ package bpfwrapper
 import (
 	"bytes"
 	"encoding/binary"
-	"log"
+	"log/slog"
 	"unsafe"
 
 	"github.com/akto-api-security/mirroring-api-logging/ebpf/connections"
@@ -28,11 +28,16 @@ func SocketOpenEventCallback(inputChan chan []byte, connectionFactory *connectio
 
 		var event structs.SocketOpenEvent
 		if err := binary.Read(bytes.NewReader(data), bcc.GetHostByteOrder(), &event); err != nil {
-			log.Printf("Failed to decode received data on socket open: %+v", err)
+			slog.Error("Failed to decode received data on socket open", "error", err)
 			continue
 		}
 		connId := event.ConnId
-		utils.LogIngest("Received open fd: %v id: %v ts: %v ip: %v port: %v\n", connId.Fd, connId.Id, connId.Conn_start_ns, connId.Ip, connId.Port)
+		slog.Debug("Received socket open event", 
+			"fd", connId.Fd,
+			"id", connId.Id,
+			"timestamp", connId.Conn_start_ns,
+			"ip", connId.Ip,
+			"port", connId.Port)
 		connectionFactory.CreateIfNotExists(connId)
 		connectionFactory.SendEvent(connId, &event)
 	}
@@ -45,12 +50,17 @@ func SocketCloseEventCallback(inputChan chan []byte, connectionFactory *connecti
 		}
 		var event structs.SocketCloseEvent
 		if err := binary.Read(bytes.NewReader(data), bcc.GetHostByteOrder(), &event); err != nil {
-			log.Printf("Failed to decode received data on socket close: %+v", err)
+			slog.Error("Failed to decode received data on socket close", "error", err)
 			continue
 		}
 
 		connId := event.ConnId
-		utils.LogIngest("Received close on: fd: %v id: %v ts: %v ip: %v port: %v\n", connId.Fd, connId.Id, connId.Conn_start_ns, connId.Ip, connId.Port)
+		slog.Debug("Received close on", 
+			"fd", connId.Fd,
+			"id", connId.Id,
+			"timestamp", connId.Conn_start_ns,
+			"ip", connId.Ip,
+			"port", connId.Port)
 		connectionFactory.SendEvent(connId, &event)
 	}
 }
@@ -90,7 +100,7 @@ func SocketDataEventCallback(inputChan chan []byte, connectionFactory *connectio
 		}
 
 		if !(connectionFactory.CanBeFilled() && connections.BufferCheck()) {
-			utils.LogIngest("Connections filled")
+			slog.Debug("Connections filled")
 			continue
 		}
 
@@ -100,10 +110,10 @@ func SocketDataEventCallback(inputChan chan []byte, connectionFactory *connectio
 		// Since the Msg field might be mostly empty, binary.read fails.
 		// So we split the loading into the fixed size attribute parts, and copying the message separately.
 
-		// fmt.Printf("data: %v\n", data)
+		// slog.Debug("data", "data", data)
 
 		if err := binary.Read(bytes.NewReader(data[:eventAttributesSize]), bcc.GetHostByteOrder(), &event.Attr); err != nil {
-			utils.LogIngest("Failed to decode received data: %+v", err)
+			slog.Error("Failed to decode received data", "error", err)
 			continue
 		}
 
@@ -120,7 +130,12 @@ func SocketDataEventCallback(inputChan chan []byte, connectionFactory *connectio
 
 		_, ok := ignorePortsMap[connId.Port]
 		if ignorePorts && ok {
-			utils.LogIngest("Ignoring data for ignore port fd: %v id: %v ts: %v rc: %v wc: %v\n", connId.Fd, connId.Id, connId.Conn_start_ns, event.Attr.ReadEventsCount, event.Attr.WriteEventsCount)
+			slog.Debug("Ignoring data for ignore port", 
+				"fd", connId.Fd,
+				"id", connId.Id,
+				"timestamp", connId.Conn_start_ns,
+				"rc", event.Attr.ReadEventsCount,
+				"wc", event.Attr.WriteEventsCount)
 			continue
 		}
 
@@ -134,6 +149,15 @@ func SocketDataEventCallback(inputChan chan []byte, connectionFactory *connectio
 		connectionFactory.SendEvent(connId, &event)
 		connections.UpdateBufferSize(uint64(utils.Abs(bytesSent)))
 
-		utils.LogIngest("Got data fd: %v id: %v ts: %v ip: %v port: %v data: %v rc: %v wc: %v ssl: %v\n", connId.Fd, connId.Id, connId.Conn_start_ns, connId.Ip, connId.Port, dataStr, event.Attr.ReadEventsCount, event.Attr.WriteEventsCount, event.Attr.Ssl)
+		slog.Debug("Got data", 
+			"fd", connId.Fd,
+			"id", connId.Id,
+			"timestamp", connId.Conn_start_ns,
+			"ip", connId.Ip,
+			"port", connId.Port,
+			"data", dataStr,
+			"rc", event.Attr.ReadEventsCount,
+			"wc", event.Attr.WriteEventsCount,
+			"ssl", event.Attr.Ssl)
 	}
 }

ebpf/bpfwrapper/kprobes.go

@@ -1,7 +1,7 @@
 package bpfwrapper
 
 import (
-	"log"
+	"log/slog"
 	"runtime"
 
 	"github.com/iovisor/gobpf/bcc"
@@ -78,25 +78,25 @@ func AttachKprobes(bpfModule *bcc.Module, kprobeList []Kprobe) error {
 
 		probeFD, err := bpfModule.LoadKprobe(probe.HookName)
 		if err != nil {
-			log.Printf("failed to load %q due to: %v, skipping", probe.HookName, err)
+			slog.Error("failed to load kprobe", "hook", probe.HookName, "error", err)
 			continue
 		}
 
 		switch probe.Type {
 		case EntryType:
-			log.Printf("Loading %q for %q as kprobe\n", probe.HookName, functionToHook)
+			slog.Debug("Loading kprobe", "hook", probe.HookName, "as kprobe", functionToHook)
 			if err = bpfModule.AttachKprobe(functionToHook, probeFD, maxActiveConnections); err != nil {
-				log.Printf("failed to attach kprobe %q to %q due to: %v, skipping", probe.HookName, functionToHook, err)
+				slog.Error("failed to attach kprobe", "hook", probe.HookName, "function", functionToHook, "error", err)
 			}
 			continue
 		case ReturnType:
-			log.Printf("Loading %q for %q as kretprobe\n", probe.HookName, functionToHook)
+			slog.Debug("Loading kretprobe", "hook", probe.HookName, "as kretprobe", functionToHook)
 			if err = bpfModule.AttachKretprobe(functionToHook, probeFD, maxActiveConnections); err != nil {
-				log.Printf("failed to attach kretprobe %q to %q due to: %v, skipping", probe.HookName, functionToHook, err)
+				slog.Error("failed to attach kretprobe", "hook", probe.HookName, "function", functionToHook, "error", err)
 			}
 			continue
 		default:
-			log.Printf("unknown Kprobe type %d given for %q, skipping", probe.Type, probe.HookName)
+			slog.Error("unknown Kprobe type given for hook", "type", probe.Type, "hook", probe.HookName)
 			continue
 		}
 	}

ebpf/bpfwrapper/uprobes.go

@@ -2,7 +2,7 @@ package bpfwrapper
 
 import (
 	"fmt"
-	"log"
+	"log/slog"
 	"regexp"
 	"strings"
 
@@ -36,46 +36,46 @@ func AttachUprobes(soPath string, pid int, bpfModule *bcc.Module, uprobeList []U
 
 		switch probe.Type {
 		case EntryType:
-			log.Printf("Loading %q for %q as uprobe\n", probe.HookName, probe.FunctionToHook)
+			slog.Debug("Loading uprobe", "hook", probe.HookName, "as uprobe", functionToHook)
 			if err = bpfModule.AttachUprobe(soPath, functionToHook, probeFD, pid); err != nil {
 				return fmt.Errorf("failed to attach uprobe %q to %q due to: %v", probe.HookName, functionToHook, err)
 			}
 		case ReturnType:
-			log.Printf("Loading %q for %q as uretprobe\n", probe.HookName, probe.FunctionToHook)
+			slog.Debug("Loading uretprobe", "hook", probe.HookName, "as uretprobe", functionToHook)
 			if err = bpfModule.AttachUretprobe(soPath, functionToHook, probeFD, pid); err != nil {
 				return fmt.Errorf("failed to attach uretprobe %q to %q due to: %v", probe.HookName, functionToHook, err)
 			}
 		case EntryType_Matching_Suf:
-			log.Printf("Loading %q for %q as matching uprobe\n", probe.HookName, probe.FunctionToHook)
+			slog.Debug("Loading matching uprobe", "hook", probe.HookName, "as matching uprobe", functionToHook)
 			regex := getSuffixRegex(functionToHook)
 
 			if err = bpfModule.AttachMatchingUprobes(soPath, regex, probeFD, pid); err != nil {
 				return fmt.Errorf("failed to attach matching uprobe %q to %q due to: %v", probe.HookName, functionToHook, err)
 			}
 		case ReturnType_Matching_Suf_Addr:
 			for _, add := range probe.Addresses {
-				log.Printf("Loading %q for %q as matching uretprobe with add %v\n", probe.HookName, probe.FunctionToHook, add)
+				slog.Debug("Loading matching uretprobe", "hook", probe.HookName, "as matching uretprobe", functionToHook, "with add", add)
 				path, addr, err := bcc.ResolveSymbolPath(soPath, functionToHook, 0x0, pid)
 				if err != nil {
-					fmt.Printf("resolv error: %v\n", err)
+					slog.Error("resolv error", "error", err)
 					continue
 				}
 				finalAddr := addr + add
 				evName := fmt.Sprintf("akto_p_%s_0x%x", uprobeRegexp.ReplaceAllString(path, "_"), finalAddr)
 				if err = bpfModule.AttachUProbeInternal(evName, bcc.BPF_PROBE_ENTRY, path, finalAddr, probeFD, pid); err != nil {
-					fmt.Printf("failed to attach matching uretprobe %q to %q due to: %v\n", probe.HookName, functionToHook, err)
+					slog.Error("failed to attach matching uretprobe", "hook", probe.HookName, "as matching uretprobe", functionToHook, "error", err)
 					continue
 				}
 			}
 		case EntryType_Matching_Pre:
-			log.Printf("Loading %q for %q as pre matching uprobe\n", probe.HookName, probe.FunctionToHook)
+			slog.Debug("Loading matching uprobe", "hook", probe.HookName, "as matching uprobe", functionToHook)
 			regex := getPrefixRegex(functionToHook)
 
 			if err = bpfModule.AttachMatchingUprobes(soPath, regex, probeFD, pid); err != nil {
 				return fmt.Errorf("failed to attach pre matching uprobe %q to %q due to: %v", probe.HookName, functionToHook, err)
 			}
 		case ReturnType_Matching_Pre:
-			log.Printf("Loading %q for %q as matching uprobe\n", probe.HookName, probe.FunctionToHook)
+			slog.Debug("Loading matching uretprobe", "hook", probe.HookName, "as matching uretprobe", functionToHook)
 			regex := getPrefixRegex(functionToHook)
 
 			if err = bpfModule.AttachMatchingUretprobes(soPath, regex, probeFD, pid); err != nil {

ebpf/connections/factory.go

@@ -3,7 +3,7 @@ package connections
 import (
 	"encoding/binary"
 	"fmt"
-	"log"
+	"log/slog"
 	"net"
 	"sort"
 
@@ -162,7 +162,7 @@ func UpdateBufferSize(bufferSize uint64) {
 		currentTotalBuffer += int64(bufferSize)
 		if currentTotalBuffer/(1024*1024) > lastPrint {
 			lastPrint = currentTotalBuffer / (1024 * 1024)
-			log.Printf("Current total buffer: %v %v\n", currentTotalBuffer, lastPrint)
+			slog.Debug("Current total buffer", "buffer", currentTotalBuffer, "lastPrint", lastPrint)
 		}
 	}
 }
@@ -249,12 +249,12 @@ func (factory *Factory) DeleteWorker(connectionID structs.ConnID) {
 	if (time.Now().UnixMilli())-lastMemCheck > int64(memCheckInterval) {
 		lastMemCheck = time.Now().UnixMilli()
 		mem := utils.LogMemoryStats()
-		log.Printf("Requests processed : %v %v\n", requestProcessCount, lastMemCheck)
-		log.Printf("connection factory size : %v %v %v\n", len(factory.connections), len(factory.processor), lastMemCheck)
+		slog.Debug("Requests processed", "count", requestProcessCount, "lastMemCheck", lastMemCheck)
+		slog.Debug("connection factory size", "connections", len(factory.connections), "processors", len(factory.processor), "lastMemCheck", lastMemCheck)
 		requestProcessCount = 0
 		if mem >= bufferMemThreshold {
 			trackersToDelete := make(map[structs.ConnID]struct{})
-			metaUtils.LogProcessing("Deleting all trackers at mem: %v \n", mem)
+			slog.Debug("Deleting all trackers at mem", "mem", mem)
 			for k := range factory.connections {
 				trackersToDelete[k] = struct{}{}
 			}

ebpf/main.go

@@ -2,14 +2,14 @@ package main
 
 import (
 	"fmt"
+	"log/slog"
 	"os"
 	"os/signal"
 	"runtime"
 	"runtime/pprof"
 	"strconv"
 	"sync"
 
-	"log"
 	"strings"
 	"syscall"
 	"time"
@@ -59,7 +59,7 @@ func replaceArchType() {
 
 func isArmArch() bool {
 	arch := runtime.GOARCH
-	fmt.Printf("arch type detected: %v\n", arch)
+	slog.Debug("arch type detected", "arch", arch)
 	if strings.Contains(arch, "arm") {
 		return true
 	}
@@ -68,7 +68,7 @@ func isArmArch() bool {
 
 func isAmdArch() bool {
 	arch := runtime.GOARCH
-	fmt.Printf("arch type detected: %v\n", arch)
+	slog.Debug("arch type detected", "arch", arch)
 	if strings.Contains(arch, "amd") {
 		return true
 	}
@@ -86,7 +86,8 @@ func run() {
 
 	byteString, err := os.ReadFile("./kernel/module.cc")
 	if err != nil {
-		log.Panic(err)
+		slog.Error("failed to read kernel module", "error", err)
+		panic(err)
 	}
 	source = string(byteString)
 
@@ -98,7 +99,8 @@ func run() {
 
 	bpfModule := bcc.NewModule(source, []string{})
 	if bpfModule == nil {
-		log.Panic("bpf is nil")
+		slog.Error("failed to create BPF module", "error", "module is nil")
+		panic("bpf module is nil")
 	}
 	defer bpfModule.Close()
 
@@ -140,7 +142,8 @@ func run() {
 	hooks = append(hooks, bpfwrapper.Level4hooks...)
 
 	if err := bpfwrapper.LaunchPerfBufferConsumers(bpfModule, connectionFactory, callbacks); err != nil {
-		log.Panic(err)
+		slog.Error("failed to launch perf buffer consumers", "error", err)
+		panic(err)
 	}
 
 	if err := bpfwrapper.AttachKprobes(bpfModule, hooks); err != nil {
@@ -160,11 +163,11 @@ func run() {
 
 	if captureSsl == "true" || captureAll == "true" {
 		go func() {
-			fmt.Printf("Starting to attach to processes in ticker start\n")
+			slog.Debug("Starting to attach to processes in ticker start")
 			ticker := time.NewTicker(pollInterval) // Create a ticker to trigger every minute
 			defer ticker.Stop()
 			for range ticker.C {
-				fmt.Printf("Starting to attach to processes in ticker\n")
+				slog.Debug("Starting to attach to processes in ticker")
 				if !isRunning_2 {
 					mu_2.Lock()
 					if isRunning_2 {
@@ -174,16 +177,16 @@ func run() {
 					isRunning_2 = true
 					mu_2.Unlock()
 
-					fmt.Printf("Starting to attach to processes\n")
+					slog.Debug("Starting to attach to processes")
 					processFactory.AddNewProcessesToProbe(bpfModule)
-					fmt.Printf("Ended attaching to processes\n")
+					slog.Debug("Ended attaching to processes")
 					mu_2.Lock()
 					isRunning_2 = false
 					mu_2.Unlock()
 				}
-				fmt.Printf("Ended attaching to processes in ticker\n")
+				slog.Debug("Ended attaching to processes in ticker")
 			}
-			fmt.Printf("Ended attaching to processes in ticker end\n")
+			slog.Debug("Ended attaching to processes in ticker end")
 		}()
 	}
 
@@ -208,9 +211,9 @@ func run() {
 
 	sig := make(chan os.Signal, 1)
 	signal.Notify(sig, syscall.SIGHUP, syscall.SIGINT, syscall.SIGQUIT, syscall.SIGTERM)
-	log.Println("Sniffer is ready")
+	slog.Debug("sniffer is ready")
 	<-sig
-	log.Println("Signaled to terminate")
+	slog.Debug("signaled to terminate")
 }
 
 func captureMemoryProfile() {
@@ -232,11 +235,11 @@ func captureCpuProfile() {
 	if err := pprof.StartCPUProfile(f); err != nil {
 		panic("could not start CPU profile: " + err.Error())
 	}
-	fmt.Println("CPU profiling started")
+	slog.Debug("CPU profiling started")
 
 	// Allow profiling for a certain duration or simulate workload
 	time.Sleep(12 * time.Second) // Sleep for 10 seconds to simulate CPU activity
 
 	pprof.StopCPUProfile()
-	fmt.Println("CPU profiling stopped")
+	slog.Debug("CPU profiling stopped")
 }