refactor: migrate to structured debug logging

2025-11-09 00:00:55 -06:00
parent fd5eb65bc0
commit 636d400f1e
6 changed files with 196 additions and 247 deletions
--- a/pkg/interfaces/interface.go
+++ b/pkg/interfaces/interface.go
@@ -3,12 +3,12 @@ package interfaces
 import (
 	"encoding/binary"
 	"fmt"
-	"log"
 	"net"
 	"sync"
 	"time"

 	"github.com/Sudo-Ivan/reticulum-go/pkg/common"
+	"github.com/Sudo-Ivan/reticulum-go/pkg/debug"
 )

 const (
@@ -26,17 +26,6 @@ const (
 	TYPE_TCP = 0x02

 	PROPAGATION_RATE = 0.02 // 2% of interface bandwidth
-
-	DEBUG_LEVEL = 4 // Default debug level for interface logging
-
-	// Debug levels
-	DEBUG_CRITICAL = 1
-	DEBUG_ERROR    = 2
-	DEBUG_INFO     = 3
-	DEBUG_VERBOSE  = 4
-	DEBUG_TRACE    = 5
-	DEBUG_PACKETS  = 6
-	DEBUG_ALL      = 7
 )

 type Interface interface {
@@ -127,7 +116,7 @@ func (i *BaseInterface) ProcessIncoming(data []byte) {

 func (i *BaseInterface) ProcessOutgoing(data []byte) error {
 	if !i.Online || i.Detached {
-		log.Printf("[DEBUG-1] Interface %s: Cannot process outgoing packet - interface offline or detached", i.Name)
+		debug.Log(debug.DEBUG_CRITICAL, "Interface cannot process outgoing packet - interface offline or detached", "name", i.Name)
 		return fmt.Errorf("interface offline or detached")
 	}

@@ -135,7 +124,7 @@ func (i *BaseInterface) ProcessOutgoing(data []byte) error {
 	i.TxBytes += uint64(len(data))
 	i.mutex.Unlock()

-	log.Printf("[DEBUG-%d] Interface %s: Processed outgoing packet of %d bytes, total TX: %d", DEBUG_LEVEL, i.Name, len(data), i.TxBytes)
+	debug.Log(debug.DEBUG_VERBOSE, "Interface processed outgoing packet", "name", i.Name, "bytes", len(data), "total_tx", i.TxBytes)
 	return nil
 }

@@ -189,7 +178,7 @@ func (i *BaseInterface) Enable() {
 	i.Enabled = true
 	i.Online = true

-	log.Printf("[DEBUG-%d] Interface %s: State changed - Enabled: %v->%v, Online: %v->%v", DEBUG_INFO, i.Name, prevState, i.Enabled, !i.Online, i.Online)
+	debug.Log(debug.DEBUG_INFO, "Interface state changed", "name", i.Name, "enabled_prev", prevState, "enabled", i.Enabled, "online_prev", !i.Online, "online", i.Online)
 }

 func (i *BaseInterface) Disable() {
@@ -197,7 +186,7 @@ func (i *BaseInterface) Disable() {
 	defer i.mutex.Unlock()
 	i.Enabled = false
 	i.Online = false
-	log.Printf("[DEBUG-2] Interface %s: Disabled and offline", i.Name)
+	debug.Log(debug.DEBUG_ERROR, "Interface disabled and offline", "name", i.Name)
 }

 func (i *BaseInterface) GetName() string {
@@ -237,11 +226,11 @@ func (i *BaseInterface) Stop() error {
 }

 func (i *BaseInterface) Send(data []byte, address string) error {
-	log.Printf("[DEBUG-%d] Interface %s: Sending %d bytes to %s", DEBUG_LEVEL, i.Name, len(data), address)
+	debug.Log(debug.DEBUG_VERBOSE, "Interface sending bytes", "name", i.Name, "bytes", len(data), "address", address)

 	err := i.ProcessOutgoing(data)
 	if err != nil {
-		log.Printf("[DEBUG-1] Interface %s: Failed to send data: %v", i.Name, err)
+		debug.Log(debug.DEBUG_CRITICAL, "Interface failed to send data", "name", i.Name, "error", err)
 		return err
 	}

@@ -261,7 +250,7 @@ func (i *BaseInterface) GetBandwidthAvailable() bool {
 	timeSinceLastTx := now.Sub(i.lastTx)

 	if timeSinceLastTx > time.Second {
-		log.Printf("[DEBUG-%d] Interface %s: Bandwidth available (idle for %.2fs)", DEBUG_VERBOSE, i.Name, timeSinceLastTx.Seconds())
+		debug.Log(debug.DEBUG_VERBOSE, "Interface bandwidth available", "name", i.Name, "idle_seconds", timeSinceLastTx.Seconds())
 		return true
 	}

@@ -270,7 +259,7 @@ func (i *BaseInterface) GetBandwidthAvailable() bool {
 	maxUsage := float64(i.Bitrate) * PROPAGATION_RATE

 	available := currentUsage < maxUsage
-	log.Printf("[DEBUG-%d] Interface %s: Bandwidth stats - Current: %.2f bps, Max: %.2f bps, Usage: %.1f%%, Available: %v", DEBUG_VERBOSE, i.Name, currentUsage, maxUsage, (currentUsage/maxUsage)*100, available)
+	debug.Log(debug.DEBUG_VERBOSE, "Interface bandwidth stats", "name", i.Name, "current_bps", currentUsage, "max_bps", maxUsage, "usage_percent", (currentUsage/maxUsage)*100, "available", available)

 	return available
 }
@@ -282,7 +271,7 @@ func (i *BaseInterface) updateBandwidthStats(bytes uint64) {
 	i.TxBytes += bytes
 	i.lastTx = time.Now()

-	log.Printf("[DEBUG-%d] Interface %s: Updated bandwidth stats - TX bytes: %d, Last TX: %v", DEBUG_LEVEL, i.Name, i.TxBytes, i.lastTx)
+	debug.Log(debug.DEBUG_VERBOSE, "Interface updated bandwidth stats", "name", i.Name, "tx_bytes", i.TxBytes, "last_tx", i.lastTx)
 }

 type InterceptedInterface struct {
@@ -305,7 +294,7 @@ func (i *InterceptedInterface) Send(data []byte, addr string) error {
 	// Call interceptor if provided
 	if i.interceptor != nil && len(data) > 0 {
 		if err := i.interceptor(data, i); err != nil {
-			log.Printf("[DEBUG-2] Failed to intercept outgoing packet: %v", err)
+			debug.Log(debug.DEBUG_ERROR, "Failed to intercept outgoing packet", "error", err)
 		}
 	}

--- a/pkg/interfaces/tcp.go
+++ b/pkg/interfaces/tcp.go
@@ -2,13 +2,13 @@ package interfaces

 import (
 	"fmt"
-	"log"
 	"net"
 	"runtime"
 	"sync"
 	"time"

 	"github.com/Sudo-Ivan/reticulum-go/pkg/common"
+	"github.com/Sudo-Ivan/reticulum-go/pkg/debug"
 )

 const (
@@ -106,11 +106,11 @@ func (tc *TCPClientInterface) Start() error {
 	switch runtime.GOOS {
 	case "linux":
 		if err := tc.setTimeoutsLinux(); err != nil {
-			log.Printf("[DEBUG-2] Failed to set Linux TCP timeouts: %v", err)
+			debug.Log(debug.DEBUG_ERROR, "Failed to set Linux TCP timeouts", "error", err)
 		}
 	case "darwin":
 		if err := tc.setTimeoutsOSX(); err != nil {
-			log.Printf("[DEBUG-2] Failed to set OSX TCP timeouts: %v", err)
+			debug.Log(debug.DEBUG_ERROR, "Failed to set OSX TCP timeouts", "error", err)
 		}
 	}

@@ -169,7 +169,7 @@ func (tc *TCPClientInterface) readLoop() {

 func (tc *TCPClientInterface) handlePacket(data []byte) {
 	if len(data) < 1 {
-		log.Printf("[DEBUG-7] Received invalid packet: empty")
+		debug.Log(debug.DEBUG_ALL, "Received invalid packet: empty")
 		return
 	}

@@ -179,20 +179,20 @@ func (tc *TCPClientInterface) handlePacket(data []byte) {
 	tc.lastRx = lastRx
 	tc.mutex.Unlock()

-	log.Printf("[DEBUG-7] Received packet: type=0x%02x, size=%d bytes", data[0], len(data))
+	debug.Log(debug.DEBUG_ALL, "Received packet", "type", fmt.Sprintf("0x%02x", data[0]), "size", len(data))

 	// For RNS packets, call the packet callback directly
 	if callback := tc.GetPacketCallback(); callback != nil {
-		log.Printf("[DEBUG-7] Calling packet callback for RNS packet")
+		debug.Log(debug.DEBUG_ALL, "Calling packet callback for RNS packet")
 		callback(data, tc)
 	} else {
-		log.Printf("[DEBUG-7] No packet callback set for TCP interface")
+		debug.Log(debug.DEBUG_ALL, "No packet callback set for TCP interface")
 	}
 }

 // Send implements the interface Send method for TCP interface
 func (tc *TCPClientInterface) Send(data []byte, address string) error {
-	log.Printf("[DEBUG-7] TCP interface %s: Sending %d bytes", tc.Name, len(data))
+	debug.Log(debug.DEBUG_ALL, "TCP interface sending bytes", "name", tc.Name, "bytes", len(data))
 	
 	if !tc.IsEnabled() || !tc.IsOnline() {
 		return fmt.Errorf("TCP interface %s is not online", tc.Name)
@@ -223,10 +223,10 @@ func (tc *TCPClientInterface) ProcessOutgoing(data []byte) error {
 	// Update TX stats before sending
 	tc.UpdateStats(uint64(len(frame)), false)

-	log.Printf("[DEBUG-7] TCP interface %s: Writing %d bytes to network", tc.Name, len(frame))
+	debug.Log(debug.DEBUG_ALL, "TCP interface writing to network", "name", tc.Name, "bytes", len(frame))
 	_, err := tc.conn.Write(frame)
 	if err != nil {
-		log.Printf("[DEBUG-1] TCP interface %s: Write failed: %v", tc.Name, err)
+		debug.Log(debug.DEBUG_CRITICAL, "TCP interface write failed", "name", tc.Name, "error", err)
 	}
 	return err
 }
@@ -390,7 +390,7 @@ func (tc *TCPClientInterface) GetRTT() time.Duration {
 				if err := info.Control(func(fd uintptr) { // #nosec G104
 					rtt = platformGetRTT(fd)
 				}); err != nil {
-					log.Printf("[DEBUG-2] Error in SyscallConn Control: %v", err)
+					debug.Log(debug.DEBUG_ERROR, "Error in SyscallConn Control", "error", err)
 				}
 			}
 		}
@@ -420,13 +420,11 @@ func (tc *TCPClientInterface) UpdateStats(bytes uint64, isRx bool) {
 	if isRx {
 		tc.RxBytes += bytes
 		tc.lastRx = now
-		log.Printf("[DEBUG-5] Interface %s RX stats: bytes=%d total=%d last=%v",
-			tc.Name, bytes, tc.RxBytes, tc.lastRx)
+		debug.Log(debug.DEBUG_TRACE, "Interface RX stats", "name", tc.Name, "bytes", bytes, "total", tc.RxBytes, "last", tc.lastRx)
 	} else {
 		tc.TxBytes += bytes
 		tc.lastTx = now
-		log.Printf("[DEBUG-5] Interface %s TX stats: bytes=%d total=%d last=%v",
-			tc.Name, bytes, tc.TxBytes, tc.lastTx)
+		debug.Log(debug.DEBUG_TRACE, "Interface TX stats", "name", tc.Name, "bytes", bytes, "total", tc.TxBytes, "last", tc.lastTx)
 	}
 }

@@ -580,7 +578,7 @@ func (ts *TCPServerInterface) Start() error {
 				if !ts.Online {
 					return // Normal shutdown
 				}
-				log.Printf("[DEBUG-2] Error accepting connection: %v", err)
+				debug.Log(debug.DEBUG_ERROR, "Error accepting connection", "error", err)
 				continue
 			}

@@ -663,8 +661,7 @@ func (ts *TCPServerInterface) ProcessOutgoing(data []byte) error {

 	for _, conn := range ts.connections {
 		if _, err := conn.Write(frame); err != nil {
-			log.Printf("[DEBUG-4] Error writing to connection %s: %v",
-				conn.RemoteAddr(), err)
+			debug.Log(debug.DEBUG_VERBOSE, "Error writing to connection", "address", conn.RemoteAddr(), "error", err)
 		}
 	}

--- a/pkg/interfaces/udp.go
+++ b/pkg/interfaces/udp.go
@@ -2,11 +2,11 @@ package interfaces

 import (
 	"fmt"
-	"log"
 	"net"
 	"sync"

 	"github.com/Sudo-Ivan/reticulum-go/pkg/common"
+	"github.com/Sudo-Ivan/reticulum-go/pkg/debug"
 )

 type UDPInterface struct {
@@ -76,7 +76,7 @@ func (ui *UDPInterface) Detach() {
 }

 func (ui *UDPInterface) Send(data []byte, addr string) error {
-	log.Printf("[DEBUG-7] UDP interface %s: Sending %d bytes", ui.Name, len(data))
+	debug.Log(debug.DEBUG_ALL, "UDP interface sending bytes", "name", ui.Name, "bytes", len(data))

 	if !ui.IsEnabled() {
 		return fmt.Errorf("interface not enabled")
@@ -93,9 +93,9 @@ func (ui *UDPInterface) Send(data []byte, addr string) error {

 	_, err := ui.conn.WriteTo(data, ui.targetAddr)
 	if err != nil {
-		log.Printf("[DEBUG-1] UDP interface %s: Write failed: %v", ui.Name, err)
+		debug.Log(debug.DEBUG_CRITICAL, "UDP interface write failed", "name", ui.Name, "error", err)
 	} else {
-		log.Printf("[DEBUG-7] UDP interface %s: Sent %d bytes successfully", ui.Name, len(data))
+		debug.Log(debug.DEBUG_ALL, "UDP interface sent bytes successfully", "name", ui.Name, "bytes", len(data))
 	}
 	return err
 }
@@ -195,14 +195,14 @@ func (ui *UDPInterface) readLoop() {
 		n, remoteAddr, err := ui.conn.ReadFromUDP(buffer)
 		if err != nil {
 			if ui.IsOnline() {
-				log.Printf("Error reading from UDP interface %s: %v", ui.Name, err)
+				debug.Log(debug.DEBUG_ERROR, "Error reading from UDP interface", "name", ui.Name, "error", err)
 			}
 			return
 		}

 		ui.mutex.Lock()
 		if ui.targetAddr == nil {
-			log.Printf("[DEBUG-7] UDP interface %s discovered peer %s", ui.Name, remoteAddr)
+			debug.Log(debug.DEBUG_ALL, "UDP interface discovered peer", "name", ui.Name, "peer", remoteAddr.String())
 			ui.targetAddr = remoteAddr
 		}
 		ui.mutex.Unlock()
@@ -213,25 +213,6 @@ func (ui *UDPInterface) readLoop() {
 	}
 }

-/*
-func (ui *UDPInterface) readLoop() {
-	buffer := make([]byte, ui.MTU)
-	for {
-		n, _, err := ui.conn.ReadFromUDP(buffer)
-		if err != nil {
-			if ui.Online {
-				log.Printf("Error reading from UDP interface %s: %v", ui.Name, err)
-				ui.Stop() // Consider if stopping is the right action or just log and continue
-			}
-			return
-		}
-		if ui.packetCallback != nil {
-			ui.packetCallback(buffer[:n], ui)
-		}
-	}
-}
-*/
-
 func (ui *UDPInterface) IsEnabled() bool {
 	ui.mutex.RLock()
 	defer ui.mutex.RUnlock()