Introducing mizu logs dump & Log prints alignment in API server using rlog (#165)

agent/pkg/api/socket_routes.go

@@ -2,9 +2,9 @@ package api
 
 import (
 	"errors"
-	"fmt"
 	"github.com/gin-gonic/gin"
 	"github.com/gorilla/websocket"
+	"github.com/romana/rlog"
 	"github.com/up9inc/mizu/shared/debounce"
 	"net/http"
 	"sync"
@@ -50,7 +50,7 @@ func WebSocketRoutes(app *gin.Engine, eventHandlers EventHandlers) {
 func websocketHandler(w http.ResponseWriter, r *http.Request, eventHandlers EventHandlers, isTapper bool) {
 	conn, err := websocketUpgrader.Upgrade(w, r, nil)
 	if err != nil {
-		fmt.Println("Failed to set websocket upgrade: %+v", err)
+		rlog.Errorf("Failed to set websocket upgrade: %v", err)
 		return
 	}
 
@@ -71,7 +71,7 @@ func websocketHandler(w http.ResponseWriter, r *http.Request, eventHandlers Even
 	for {
 		_, msg, err := conn.ReadMessage()
 		if err != nil {
-			fmt.Printf("Conn err: %v\n", err)
+			rlog.Errorf("Error reading message, socket id: %d, error: %v", socketId, err)
 			break
 		}
 		eventHandlers.WebSocketMessage(socketId, msg)
@@ -81,7 +81,7 @@ func websocketHandler(w http.ResponseWriter, r *http.Request, eventHandlers Even
 func socketCleanup(socketId int, socketConnection *SocketConnection) {
 	err := socketConnection.connection.Close()
 	if err != nil {
-		fmt.Printf("Error closing socket connection for socket id %d: %v\n", socketId, err)
+		rlog.Errorf("Error closing socket connection for socket id %d: %v\n", socketId, err)
 	}
 
 	websocketIdsLock.Lock()
@@ -92,7 +92,7 @@ func socketCleanup(socketId int, socketConnection *SocketConnection) {
 }
 
 var db = debounce.NewDebouncer(time.Second*5, func() {
-	fmt.Println("Successfully sent to socket")
+	rlog.Error("Successfully sent to socket")
 })
 
 func SendToSocket(socketId int, message []byte) error {
@@ -104,7 +104,7 @@ func SendToSocket(socketId int, message []byte) error {
 	var sent = false
 	time.AfterFunc(time.Second*5, func() {
 		if !sent {
-			fmt.Println("Socket timed out")
+			rlog.Error("Socket timed out")
 			socketCleanup(socketId, socketObj)
 		}
 	})

agent/pkg/api/socket_server_handlers.go

@@ -52,7 +52,7 @@ func BroadcastToBrowserClients(message []byte) {
 		go func(socketId int) {
 			err := SendToSocket(socketId, message)
 			if err != nil {
-				fmt.Printf("error sending message to socket ID %d: %v", socketId, err)
+				rlog.Errorf("error sending message to socket ID %d: %v", socketId, err)
 			}
 		}(socketId)
 	}
@@ -114,7 +114,7 @@ func handleTLSLink(outboundLinkMessage models.WebsocketOutboundLinkMessage) {
 	if err != nil {
 		rlog.Errorf("Error marshaling outbound link message for broadcasting: %v", err)
 	} else {
-		fmt.Printf("Broadcasting outboundlink message %s\n", string(marshaledMessage))
+		rlog.Errorf("Broadcasting outboundlink message %s", string(marshaledMessage))
 		BroadcastToBrowserClients(marshaledMessage)
 	}
 }

agent/pkg/database/size_enforcer.go

@@ -1,8 +1,8 @@
 package database
 
 import (
-	"fmt"
 	"github.com/fsnotify/fsnotify"
+	"github.com/romana/rlog"
 	"github.com/up9inc/mizu/shared"
 	"github.com/up9inc/mizu/shared/debounce"
 	"github.com/up9inc/mizu/shared/units"
@@ -47,7 +47,7 @@ func StartEnforcingDatabaseSize() {
 				if !ok {
 					return // closed channel
 				}
-				fmt.Printf("filesystem watcher encountered error:%v\n", err)
+				rlog.Errorf("filesystem watcher encountered error:%v", err)
 			}
 		}
 	}()
@@ -72,7 +72,7 @@ func getMaxEntriesDBByteSize() (int64, error) {
 func checkFileSize(maxSizeBytes int64) {
 	fileStat, err := os.Stat(DBPath)
 	if err != nil {
-		fmt.Printf("Error checking %s file size: %v\n", DBPath, err)
+		rlog.Errorf("Error checking %s file size: %v", DBPath, err)
 	} else {
 		if fileStat.Size() > maxSizeBytes {
 			pruneOldEntries(fileStat.Size())
@@ -83,13 +83,13 @@ func checkFileSize(maxSizeBytes int64) {
 func pruneOldEntries(currentFileSize int64) {
 	// sqlite locks the database while delete or VACUUM are running and sqlite is terrible at handling its own db lock while a lot of inserts are attempted, we prevent a significant bottleneck by handling the db lock ourselves here
 	IsDBLocked = true
-	defer func() {IsDBLocked = false}()
+	defer func() { IsDBLocked = false }()
 
 	amountOfBytesToTrim := currentFileSize / (100 / percentageOfMaxSizeBytesToPrune)
 
 	rows, err := GetEntriesTable().Limit(10000).Order("id").Rows()
 	if err != nil {
-		fmt.Printf("Error getting 10000 first db rows: %v\n", err)
+		rlog.Errorf("Error getting 10000 first db rows: %v", err)
 		return
 	}
 
@@ -102,7 +102,7 @@ func pruneOldEntries(currentFileSize int64) {
 		var entry models.MizuEntry
 		err = DB.ScanRows(rows, &entry)
 		if err != nil {
-			fmt.Printf("Error scanning db row: %v\n", err)
+			rlog.Errorf("Error scanning db row: %v", err)
 			continue
 		}
 
@@ -114,8 +114,8 @@ func pruneOldEntries(currentFileSize int64) {
 		GetEntriesTable().Where(entryIdsToRemove).Delete(models.MizuEntry{})
 		// VACUUM causes sqlite to shrink the db file after rows have been deleted, the db file will not shrink without this
 		DB.Exec("VACUUM")
-		fmt.Printf("Removed %d rows and cleared %s\n", len(entryIdsToRemove), units.BytesToHumanReadable(bytesToBeRemoved))
+		rlog.Errorf("Removed %d rows and cleared %s", len(entryIdsToRemove), units.BytesToHumanReadable(bytesToBeRemoved))
 	} else {
-		fmt.Println("Found no rows to remove when pruning")
+		rlog.Error("Found no rows to remove when pruning")
 	}
 }

agent/pkg/resolver/README.md

@@ -32,7 +32,7 @@ Now you will be able to import `github.com/up9inc/mizu/resolver` in any `.go` fi
 errOut := make(chan error, 100)
 k8sResolver, err := resolver.NewFromOutOfCluster("", errOut)
 if err != nil {
-    fmt.Printf("error creating k8s resolver %s", err)
+    rlog.Errorf("error creating k8s resolver %s", err)
 }
 
 ctx, cancel := context.WithCancel(context.Background())
@@ -40,15 +40,15 @@ k8sResolver.Start(ctx)
 
 resolvedName := k8sResolver.Resolve("10.107.251.91") // will always return `nil` in real scenarios as the internal map takes a moment to populate after `Start` is called
 if resolvedName != nil {
-    fmt.Printf("resolved 10.107.251.91=%s", *resolvedName)
+    rlog.Errorf("resolved 10.107.251.91=%s", *resolvedName)
 } else {
-    fmt.Printf("Could not find a resolved name for 10.107.251.91")
+    rlog.Error("Could not find a resolved name for 10.107.251.91")
 }
 
 for {
     select {
         case err := <- errOut:
-            fmt.Printf("name resolving error %s", err)
+            rlog.Errorf("name resolving error %s", err)
     }
 }
 ```

agent/pkg/utils/truncating_logger.go

@@ -3,6 +3,7 @@ package utils
 import (
 	"context"
 	"fmt"
+	"github.com/romana/rlog"
 	"gorm.io/gorm/logger"
 	"gorm.io/gorm/utils"
 	"time"
@@ -10,7 +11,7 @@ import (
 
 // TruncatingLogger implements the gorm logger.Interface interface. Its purpose is to act as gorm's logger while truncating logs to a max of 50 characters to minimise the performance impact
 type TruncatingLogger struct {
-	LogLevel logger.LogLevel
+	LogLevel      logger.LogLevel
 	SlowThreshold time.Duration
 }
 
@@ -23,21 +24,21 @@ func (truncatingLogger *TruncatingLogger) Info(_ context.Context, message string
 	if truncatingLogger.LogLevel < logger.Info {
 		return
 	}
-	fmt.Printf("gorm info: %.150s\n", message)
+	rlog.Errorf("gorm info: %.150s", message)
 }
 
 func (truncatingLogger *TruncatingLogger) Warn(_ context.Context, message string, __ ...interface{}) {
 	if truncatingLogger.LogLevel < logger.Warn {
 		return
 	}
-	fmt.Printf("gorm warning: %.150s\n", message)
+	rlog.Errorf("gorm warning: %.150s", message)
 }
 
 func (truncatingLogger *TruncatingLogger) Error(_ context.Context, message string, __ ...interface{}) {
 	if truncatingLogger.LogLevel < logger.Error {
 		return
 	}
-	fmt.Printf("gorm error: %.150s\n", message)
+	rlog.Errorf("gorm error: %.150s", message)
 }
 
 func (truncatingLogger *TruncatingLogger) Trace(ctx context.Context, begin time.Time, fc func() (string, int64), err error) {