diff --git a/pkg/destination/destination.go b/pkg/destination/destination.go index aa53b6a..a3d963b 100644 --- a/pkg/destination/destination.go +++ b/pkg/destination/destination.go @@ -4,11 +4,11 @@ import ( "crypto/sha256" "errors" "fmt" - "log" "sync" "github.com/Sudo-Ivan/reticulum-go/pkg/announce" "github.com/Sudo-Ivan/reticulum-go/pkg/common" + "github.com/Sudo-Ivan/reticulum-go/pkg/debug" "github.com/Sudo-Ivan/reticulum-go/pkg/identity" "github.com/Sudo-Ivan/reticulum-go/pkg/transport" ) @@ -36,15 +36,6 @@ const ( RATCHET_COUNT = 512 // Default number of retained ratchet keys RATCHET_INTERVAL = 1800 // Minimum interval between ratchet rotations in seconds - - // Debug levels - DEBUG_CRITICAL = 1 // Critical errors - DEBUG_ERROR = 2 // Non-critical errors - DEBUG_INFO = 3 // Important information - DEBUG_VERBOSE = 4 // Detailed information - DEBUG_TRACE = 5 // Very detailed tracing - DEBUG_PACKETS = 6 // Packet-level details - DEBUG_ALL = 7 // Everything ) type PacketCallback = common.PacketCallback @@ -86,15 +77,11 @@ type Destination struct { requestHandlers map[string]*RequestHandler } -func debugLog(level int, format string, v ...interface{}) { - log.Printf("[DEBUG-%d] %s", level, fmt.Sprintf(format, v...)) -} - func New(id *identity.Identity, direction byte, destType byte, appName string, transport *transport.Transport, aspects ...string) (*Destination, error) { - debugLog(DEBUG_INFO, "Creating new destination: app=%s type=%d direction=%d", appName, destType, direction) + debug.Log(debug.DEBUG_INFO, "Creating new destination", "app", appName, "type", destType, "direction", direction) if id == nil { - debugLog(DEBUG_ERROR, "Cannot create destination: identity is nil") + debug.Log(debug.DEBUG_ERROR, "Cannot create destination: identity is nil") return nil, errors.New("identity cannot be nil") } @@ -114,7 +101,7 @@ func New(id *identity.Identity, direction byte, destType byte, appName string, t // Generate destination hash d.hashValue = d.calculateHash() - debugLog(DEBUG_VERBOSE, "Created destination with hash: %x", d.hashValue) + debug.Log(debug.DEBUG_VERBOSE, "Created destination with hash", "hash", fmt.Sprintf("%x", d.hashValue)) return d, nil } @@ -122,10 +109,10 @@ func New(id *identity.Identity, direction byte, destType byte, appName string, t // FromHash creates a destination from a known hash (e.g., from an announce). // This is used by clients to create destination objects for servers they've discovered. func FromHash(hash []byte, id *identity.Identity, destType byte, transport *transport.Transport) (*Destination, error) { - debugLog(DEBUG_INFO, "Creating destination from hash: %x", hash) + debug.Log(debug.DEBUG_INFO, "Creating destination from hash", "hash", fmt.Sprintf("%x", hash)) if id == nil { - debugLog(DEBUG_ERROR, "Cannot create destination: identity is nil") + debug.Log(debug.DEBUG_ERROR, "Cannot create destination: identity is nil") return nil, errors.New("identity cannot be nil") } @@ -142,12 +129,12 @@ func FromHash(hash []byte, id *identity.Identity, destType byte, transport *tran requestHandlers: make(map[string]*RequestHandler), } - debugLog(DEBUG_VERBOSE, "Created destination from hash: %x", hash) + debug.Log(debug.DEBUG_VERBOSE, "Created destination from hash", "hash", fmt.Sprintf("%x", hash)) return d, nil } func (d *Destination) calculateHash() []byte { - debugLog(DEBUG_TRACE, "Calculating hash for destination %s", d.ExpandName()) + debug.Log(debug.DEBUG_TRACE, "Calculating hash for destination", "name", d.ExpandName()) // destination_hash = SHA256(name_hash_10bytes + identity_hash_16bytes)[:16] // Identity hash is the truncated hash of the public key (16 bytes) @@ -157,8 +144,8 @@ func (d *Destination) calculateHash() []byte { nameHashFull := sha256.Sum256([]byte(d.ExpandName())) nameHash10 := nameHashFull[:10] // Only use 10 bytes - debugLog(DEBUG_ALL, "Identity hash: %x", identityHash) - debugLog(DEBUG_ALL, "Name hash (10 bytes): %x", nameHash10) + debug.Log(debug.DEBUG_ALL, "Identity hash", "hash", fmt.Sprintf("%x", identityHash)) + debug.Log(debug.DEBUG_ALL, "Name hash (10 bytes)", "hash", fmt.Sprintf("%x", nameHash10)) // Concatenate name_hash (10 bytes) + identity_hash (16 bytes) = 26 bytes combined := append(nameHash10, identityHash...) @@ -167,7 +154,7 @@ func (d *Destination) calculateHash() []byte { finalHashFull := sha256.Sum256(combined) finalHash := finalHashFull[:16] - debugLog(DEBUG_VERBOSE, "Calculated destination hash: %x", finalHash) + debug.Log(debug.DEBUG_VERBOSE, "Calculated destination hash", "hash", fmt.Sprintf("%x", finalHash)) return finalHash } @@ -184,7 +171,7 @@ func (d *Destination) Announce(appData []byte) error { d.mutex.Lock() defer d.mutex.Unlock() - log.Printf("[DEBUG-4] Announcing destination %s", d.ExpandName()) + debug.Log(debug.DEBUG_VERBOSE, "Announcing destination", "name", d.ExpandName()) if appData == nil { appData = d.defaultAppData @@ -203,27 +190,27 @@ func (d *Destination) Announce(appData []byte) error { } // Send announce packet to all interfaces - log.Printf("[DEBUG-4] Sending announce packet to all interfaces") + debug.Log(debug.DEBUG_VERBOSE, "Sending announce packet to all interfaces") if d.transport == nil { return errors.New("transport not initialized") } interfaces := d.transport.GetInterfaces() - log.Printf("[DEBUG-7] Got %d interfaces from transport", len(interfaces)) + debug.Log(debug.DEBUG_ALL, "Got interfaces from transport", "count", len(interfaces)) var lastErr error for name, iface := range interfaces { - log.Printf("[DEBUG-7] Checking interface %s: enabled=%v, online=%v", name, iface.IsEnabled(), iface.IsOnline()) + debug.Log(debug.DEBUG_ALL, "Checking interface", "name", name, "enabled", iface.IsEnabled(), "online", iface.IsOnline()) if iface.IsEnabled() && iface.IsOnline() { - log.Printf("[DEBUG-7] Sending announce to interface %s (%d bytes)", name, len(packet)) + debug.Log(debug.DEBUG_ALL, "Sending announce to interface", "name", name, "bytes", len(packet)) if err := iface.Send(packet, ""); err != nil { - log.Printf("[ERROR] Failed to send announce on interface %s: %v", name, err) + debug.Log(debug.DEBUG_ERROR, "Failed to send announce on interface", "name", name, "error", err) lastErr = err } else { - log.Printf("[DEBUG-7] Successfully sent announce to interface %s", name) + debug.Log(debug.DEBUG_ALL, "Successfully sent announce to interface", "name", name) } } else { - log.Printf("[DEBUG-7] Skipping interface %s (not enabled or not online)", name) + debug.Log(debug.DEBUG_ALL, "Skipping interface", "name", name, "reason", "not enabled or not online") } } @@ -238,7 +225,7 @@ func (d *Destination) AcceptsLinks(accepts bool) { // Register with transport if accepting links if accepts && d.transport != nil { d.transport.RegisterDestination(d.hashValue, d) - debugLog(DEBUG_VERBOSE, "Destination %x registered with transport for link requests", d.hashValue) + debug.Log(debug.DEBUG_VERBOSE, "Destination registered with transport for link requests", "hash", fmt.Sprintf("%x", d.hashValue)) } } @@ -255,19 +242,19 @@ func (d *Destination) GetLinkCallback() common.LinkEstablishedCallback { } func (d *Destination) HandleIncomingLinkRequest(linkID []byte, transport interface{}, networkIface common.NetworkInterface) error { - debugLog(DEBUG_INFO, "Handling incoming link request for destination %x", d.GetHash()) + debug.Log(debug.DEBUG_INFO, "Handling incoming link request for destination", "hash", fmt.Sprintf("%x", d.GetHash())) // Import link package here to avoid circular dependency at package level // We'll use dynamic import by having the caller create the link // For now, just call the callback with a placeholder if d.linkCallback != nil { - debugLog(DEBUG_INFO, "Calling link established callback") + debug.Log(debug.DEBUG_INFO, "Calling link established callback") // Pass linkID as the link object for now // The callback will need to handle creating the actual link d.linkCallback(linkID) } else { - debugLog(DEBUG_VERBOSE, "No link callback set") + debug.Log(debug.DEBUG_VERBOSE, "No link callback set") } return nil @@ -379,32 +366,32 @@ func (d *Destination) DeregisterRequestHandler(path string) bool { func (d *Destination) Encrypt(plaintext []byte) ([]byte, error) { if d.destType == PLAIN { - log.Printf("[DEBUG-4] Using plaintext transmission for PLAIN destination") + debug.Log(debug.DEBUG_VERBOSE, "Using plaintext transmission for PLAIN destination") return plaintext, nil } if d.identity == nil { - log.Printf("[DEBUG-3] Cannot encrypt: no identity available") + debug.Log(debug.DEBUG_INFO, "Cannot encrypt: no identity available") return nil, errors.New("no identity available for encryption") } - log.Printf("[DEBUG-4] Encrypting %d bytes for destination type %d", len(plaintext), d.destType) + debug.Log(debug.DEBUG_VERBOSE, "Encrypting bytes for destination", "bytes", len(plaintext), "destType", d.destType) switch d.destType { case SINGLE: recipientKey := d.identity.GetPublicKey() - log.Printf("[DEBUG-4] Encrypting for single recipient with key %x", recipientKey[:8]) + debug.Log(debug.DEBUG_VERBOSE, "Encrypting for single recipient", "key", fmt.Sprintf("%x", recipientKey[:8])) return d.identity.Encrypt(plaintext, recipientKey) case GROUP: key := d.identity.GetCurrentRatchetKey() if key == nil { - log.Printf("[DEBUG-3] Cannot encrypt: no ratchet key available") + debug.Log(debug.DEBUG_INFO, "Cannot encrypt: no ratchet key available") return nil, errors.New("no ratchet key available") } - log.Printf("[DEBUG-4] Encrypting for group with ratchet key %x", key[:8]) + debug.Log(debug.DEBUG_VERBOSE, "Encrypting for group with ratchet key", "key", fmt.Sprintf("%x", key[:8])) return d.identity.EncryptWithHMAC(plaintext, key) default: - log.Printf("[DEBUG-3] Unsupported destination type %d for encryption", d.destType) + debug.Log(debug.DEBUG_INFO, "Unsupported destination type for encryption", "destType", d.destType) return nil, errors.New("unsupported destination type for encryption") } } diff --git a/pkg/identity/identity.go b/pkg/identity/identity.go index d00bec4..fd3efbc 100644 --- a/pkg/identity/identity.go +++ b/pkg/identity/identity.go @@ -12,13 +12,13 @@ import ( "errors" "fmt" "io" - "log" "os" "sync" "time" "github.com/Sudo-Ivan/reticulum-go/pkg/common" "github.com/Sudo-Ivan/reticulum-go/pkg/cryptography" + "github.com/Sudo-Ivan/reticulum-go/pkg/debug" "golang.org/x/crypto/curve25519" "golang.org/x/crypto/hkdf" ) @@ -173,7 +173,7 @@ func GetRandomHash() []byte { randomData := make([]byte, TRUNCATED_HASHLENGTH/8) _, err := rand.Read(randomData) // #nosec G104 if err != nil { - log.Printf("[DEBUG-1] Failed to read random data for hash: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to read random data for hash", "error", err) return nil // Or handle the error appropriately } return TruncatedHash(randomData) @@ -279,13 +279,13 @@ func (i *Identity) GetCurrentRatchetKey() []byte { if len(i.ratchets) == 0 { // If no ratchets exist, generate one. // This should ideally be handled by an explicit setup process. - log.Println("[DEBUG-5] No ratchets found, generating a new one on-the-fly.") + debug.Log(debug.DEBUG_TRACE, "No ratchets found, generating a new one on-the-fly") // Temporarily unlock to call RotateRatchet, which locks internally. i.mutex.RUnlock() newRatchet, err := i.RotateRatchet() i.mutex.RLock() if err != nil { - log.Printf("[DEBUG-1] Failed to generate initial ratchet key: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to generate initial ratchet key", "error", err) return nil } return newRatchet @@ -302,7 +302,7 @@ func (i *Identity) GetCurrentRatchetKey() []byte { } if latestKey == nil { - log.Printf("[DEBUG-2] Could not determine the latest ratchet key from %d ratchets.", len(i.ratchets)) + debug.Log(debug.DEBUG_ERROR, "Could not determine the latest ratchet key", "ratchet_count", len(i.ratchets)) } return latestKey @@ -310,13 +310,13 @@ func (i *Identity) GetCurrentRatchetKey() []byte { func (i *Identity) Decrypt(ciphertextToken []byte, ratchets [][]byte, enforceRatchets bool, ratchetIDReceiver *common.RatchetIDReceiver) ([]byte, error) { if i.privateKey == nil { - log.Printf("[DEBUG-1] Decryption failed: identity has no private key") + debug.Log(debug.DEBUG_CRITICAL, "Decryption failed: identity has no private key") return nil, errors.New("decryption failed because identity does not hold a private key") } - log.Printf("[DEBUG-7] Starting decryption for identity %s", i.GetHexHash()) + debug.Log(debug.DEBUG_ALL, "Starting decryption for identity", "hash", i.GetHexHash()) if len(ratchets) > 0 { - log.Printf("[DEBUG-7] Attempting decryption with %d ratchets", len(ratchets)) + debug.Log(debug.DEBUG_ALL, "Attempting decryption with ratchets", "count", len(ratchets)) } if len(ciphertextToken) <= KEYSIZE/8/2 { @@ -407,7 +407,7 @@ func (i *Identity) Decrypt(ciphertextToken []byte, ratchets [][]byte, enforceRat ratchetIDReceiver.LatestRatchetID = nil } - log.Printf("[DEBUG-7] Decryption completed successfully") + debug.Log(debug.DEBUG_ALL, "Decryption completed successfully") return plaintext[:len(plaintext)-padding], nil } @@ -419,7 +419,7 @@ func (i *Identity) tryRatchetDecryption(peerPubBytes, ciphertext, ratchet []byte // Get ratchet ID ratchetPubBytes, err := curve25519.X25519(ratchetPriv, cryptography.GetBasepoint()) if err != nil { - log.Printf("[DEBUG-7] Failed to generate ratchet public key: %v", err) + debug.Log(debug.DEBUG_ALL, "Failed to generate ratchet public key", "error", err) return nil, nil, err } ratchetID := i.GetRatchetID(ratchetPubBytes) @@ -469,12 +469,12 @@ func (i *Identity) DecryptWithHMAC(data []byte, key []byte) ([]byte, error) { } func (i *Identity) ToFile(path string) error { - log.Printf("[DEBUG-7] Saving identity %s to file: %s", i.GetHexHash(), path) + debug.Log(debug.DEBUG_ALL, "Saving identity to file", "hash", i.GetHexHash(), "path", path) // Persist ratchets to a separate file ratchetPath := path + ".ratchets" if err := i.saveRatchets(ratchetPath); err != nil { - log.Printf("[DEBUG-1] Failed to save ratchets: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to save ratchets", "error", err) // Continue saving the main identity file even if ratchets fail } @@ -488,17 +488,17 @@ func (i *Identity) ToFile(path string) error { file, err := os.Create(path) // #nosec G304 if err != nil { - log.Printf("[DEBUG-1] Failed to create identity file: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to create identity file", "error", err) return err } defer file.Close() if err := json.NewEncoder(file).Encode(data); err != nil { - log.Printf("[DEBUG-1] Failed to encode identity data: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to encode identity data", "error", err) return err } - log.Printf("[DEBUG-7] Identity saved successfully") + debug.Log(debug.DEBUG_ALL, "Identity saved successfully") return nil } @@ -510,7 +510,7 @@ func (i *Identity) saveRatchets(path string) error { return nil // Nothing to save } - log.Printf("[DEBUG-6] Saving %d ratchets to %s", len(i.ratchets), path) + debug.Log(debug.DEBUG_PACKETS, "Saving ratchets", "count", len(i.ratchets), "path", path) data := map[string]interface{}{ "ratchets": i.ratchets, "ratchet_expiry": i.ratchetExpiry, @@ -526,18 +526,18 @@ func (i *Identity) saveRatchets(path string) error { } func RecallIdentity(path string) (*Identity, error) { - log.Printf("[DEBUG-7] Attempting to recall identity from: %s", path) + debug.Log(debug.DEBUG_ALL, "Attempting to recall identity", "path", path) file, err := os.Open(path) // #nosec G304 if err != nil { - log.Printf("[DEBUG-1] Failed to open identity file: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to open identity file", "error", err) return nil, err } defer file.Close() var data map[string]interface{} if err := json.NewDecoder(file).Decode(&data); err != nil { - log.Printf("[DEBUG-1] Failed to decode identity data: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to decode identity data", "error", err) return nil, err } @@ -569,11 +569,11 @@ func RecallIdentity(path string) (*Identity, error) { // Load ratchets if they exist ratchetPath := path + ".ratchets" if err := id.loadRatchets(ratchetPath); err != nil { - log.Printf("[DEBUG-2] Could not load ratchets for identity %s: %v", id.GetHexHash(), err) + debug.Log(debug.DEBUG_ERROR, "Could not load ratchets for identity", "hash", id.GetHexHash(), "error", err) // This is not a fatal error, the identity can still function } - log.Printf("[DEBUG-7] Successfully recalled identity with hash: %s", id.GetHexHash()) + debug.Log(debug.DEBUG_ALL, "Successfully recalled identity", "hash", id.GetHexHash()) return id, nil } @@ -584,7 +584,7 @@ func (i *Identity) loadRatchets(path string) error { file, err := os.Open(path) // #nosec G304 if err != nil { if os.IsNotExist(err) { - log.Printf("[DEBUG-6] No ratchet file found at %s, skipping.", path) + debug.Log(debug.DEBUG_PACKETS, "No ratchet file found, skipping", "path", path) return nil } return fmt.Errorf("failed to open ratchet file: %w", err) @@ -612,7 +612,7 @@ func (i *Identity) loadRatchets(path string) error { } } - log.Printf("[DEBUG-6] Loaded %d ratchets from %s", len(i.ratchets), path) + debug.Log(debug.DEBUG_PACKETS, "Loaded ratchets", "count", len(i.ratchets), "path", path) return nil } @@ -713,19 +713,19 @@ func (i *Identity) RotateRatchet() ([]byte, error) { i.mutex.Lock() defer i.mutex.Unlock() - log.Printf("[DEBUG-7] Rotating ratchet for identity %s", i.GetHexHash()) + debug.Log(debug.DEBUG_ALL, "Rotating ratchet for identity", "hash", i.GetHexHash()) // Generate new ratchet key newRatchet := make([]byte, RATCHETSIZE/8) if _, err := io.ReadFull(rand.Reader, newRatchet); err != nil { - log.Printf("[DEBUG-1] Failed to generate new ratchet: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to generate new ratchet", "error", err) return nil, err } // Get public key for ratchet ID ratchetPub, err := curve25519.X25519(newRatchet, curve25519.Basepoint) if err != nil { - log.Printf("[DEBUG-1] Failed to generate ratchet public key: %v", err) + debug.Log(debug.DEBUG_CRITICAL, "Failed to generate ratchet public key", "error", err) return nil, err } @@ -736,7 +736,7 @@ func (i *Identity) RotateRatchet() ([]byte, error) { i.ratchets[string(ratchetID)] = newRatchet i.ratchetExpiry[string(ratchetID)] = expiry - log.Printf("[DEBUG-7] New ratchet generated with ID: %x, expiry: %d", ratchetID, expiry) + debug.Log(debug.DEBUG_ALL, "New ratchet generated", "id", fmt.Sprintf("%x", ratchetID), "expiry", expiry) // Cleanup old ratchets if we exceed max retained if len(i.ratchets) > MAX_RETAINED_RATCHETS { @@ -752,10 +752,10 @@ func (i *Identity) RotateRatchet() ([]byte, error) { delete(i.ratchets, oldestID) delete(i.ratchetExpiry, oldestID) - log.Printf("[DEBUG-7] Cleaned up oldest ratchet with ID: %x", []byte(oldestID)) + debug.Log(debug.DEBUG_ALL, "Cleaned up oldest ratchet", "id", fmt.Sprintf("%x", []byte(oldestID))) } - log.Printf("[DEBUG-7] Current number of active ratchets: %d", len(i.ratchets)) + debug.Log(debug.DEBUG_ALL, "Current number of active ratchets", "count", len(i.ratchets)) return newRatchet, nil } @@ -763,7 +763,7 @@ func (i *Identity) GetRatchets() [][]byte { i.mutex.RLock() defer i.mutex.RUnlock() - log.Printf("[DEBUG-7] Getting ratchets for identity %s", i.GetHexHash()) + debug.Log(debug.DEBUG_ALL, "Getting ratchets for identity", "hash", i.GetHexHash()) ratchets := make([][]byte, 0, len(i.ratchets)) now := time.Now().Unix() @@ -781,7 +781,7 @@ func (i *Identity) GetRatchets() [][]byte { } } - log.Printf("[DEBUG-7] Retrieved %d active ratchets, cleaned up %d expired", len(ratchets), expired) + debug.Log(debug.DEBUG_ALL, "Retrieved active ratchets", "active", len(ratchets), "expired", expired) return ratchets } @@ -789,7 +789,7 @@ func (i *Identity) CleanupExpiredRatchets() { i.mutex.Lock() defer i.mutex.Unlock() - log.Printf("[DEBUG-7] Starting ratchet cleanup for identity %s", i.GetHexHash()) + debug.Log(debug.DEBUG_ALL, "Starting ratchet cleanup for identity", "hash", i.GetHexHash()) now := time.Now().Unix() cleaned := 0 @@ -801,7 +801,7 @@ func (i *Identity) CleanupExpiredRatchets() { } } - log.Printf("[DEBUG-7] Cleaned up %d expired ratchets, %d remaining", cleaned, len(i.ratchets)) + debug.Log(debug.DEBUG_ALL, "Cleaned up expired ratchets", "cleaned", cleaned, "remaining", len(i.ratchets)) } // ValidateAnnounce validates an announce packet's signature diff --git a/pkg/interfaces/interface.go b/pkg/interfaces/interface.go index ceac643..d8cc843 100644 --- 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) } } diff --git a/pkg/interfaces/tcp.go b/pkg/interfaces/tcp.go index dd465f7..4827376 100644 --- 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) } } diff --git a/pkg/interfaces/udp.go b/pkg/interfaces/udp.go index b803887..0d341be 100644 --- 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() diff --git a/pkg/transport/transport.go b/pkg/transport/transport.go index 9792884..a6c06f0 100644 --- a/pkg/transport/transport.go +++ b/pkg/transport/transport.go @@ -6,7 +6,6 @@ import ( "encoding/binary" "errors" "fmt" - "log" "net" "reflect" "sync" @@ -14,6 +13,7 @@ import ( "github.com/Sudo-Ivan/reticulum-go/pkg/announce" "github.com/Sudo-Ivan/reticulum-go/pkg/common" + "github.com/Sudo-Ivan/reticulum-go/pkg/debug" "github.com/Sudo-Ivan/reticulum-go/pkg/identity" "github.com/Sudo-Ivan/reticulum-go/pkg/interfaces" "github.com/Sudo-Ivan/reticulum-go/pkg/packet" @@ -142,7 +142,7 @@ func (t *Transport) RegisterDestination(hash []byte, dest interface{}) { t.mutex.Lock() defer t.mutex.Unlock() t.destinations[string(hash)] = dest - log.Printf("[DEBUG-5] Registered destination %x with transport", hash) + debug.Log(debug.DEBUG_TRACE, "Registered destination with transport", "hash", fmt.Sprintf("%x", hash)) } // CreateIncomingLink creates a link object for an incoming link request @@ -151,7 +151,7 @@ func (t *Transport) CreateIncomingLink(dest interface{}, networkIface common.Net // This function signature uses interface{} to avoid importing link package // The actual implementation will be in the application code // For now, return nil to indicate links aren't fully implemented - log.Printf("[DEBUG-5] CreateIncomingLink called (not yet fully implemented)") + debug.Log(debug.DEBUG_TRACE, "CreateIncomingLink called (not yet fully implemented)") return nil } @@ -338,7 +338,7 @@ func (t *Transport) notifyAnnounceHandlers(destHash []byte, identity interface{} for _, handler := range handlers { if err := handler.ReceivedAnnounce(destHash, identity, appData); err != nil { - log.Printf("Error in announce handler: %v", err) + debug.Log(debug.DEBUG_ERROR, "Error in announce handler", "error", err) } } } @@ -417,7 +417,7 @@ func (t *Transport) updatePathUnlocked(destinationHash []byte, nextHop []byte, i // Direct access to interfaces map since caller holds the lock iface, exists := t.interfaces[interfaceName] if !exists { - log.Printf("[DEBUG-3] Interface %s not found", interfaceName) + debug.Log(debug.DEBUG_INFO, "Interface not found", "name", interfaceName) return } @@ -440,8 +440,7 @@ func (t *Transport) HandleAnnounce(data []byte, sourceIface common.NetworkInterf return fmt.Errorf("announce packet too small: %d bytes", len(data)) } - log.Printf("[DEBUG-7] Transport handling announce of %d bytes from %s", - len(data), sourceIface.GetName()) + debug.Log(debug.DEBUG_ALL, "Transport handling announce", "bytes", len(data), "source", sourceIface.GetName()) // Parse announce fields according to RNS spec destHash := data[1:33] @@ -455,7 +454,7 @@ func (t *Transport) HandleAnnounce(data []byte, sourceIface common.NetworkInterf t.mutex.Lock() if _, seen := t.seenAnnounces[hashStr]; seen { t.mutex.Unlock() - log.Printf("[DEBUG-7] Ignoring duplicate announce %x", announceHash[:8]) + debug.Log(debug.DEBUG_ALL, "Ignoring duplicate announce", "hash", fmt.Sprintf("%x", announceHash[:8])) return nil } t.seenAnnounces[hashStr] = true @@ -463,7 +462,7 @@ func (t *Transport) HandleAnnounce(data []byte, sourceIface common.NetworkInterf // Don't forward if max hops reached if data[0] >= MAX_HOPS { - log.Printf("[DEBUG-7] Announce exceeded max hops: %d", data[0]) + debug.Log(debug.DEBUG_ALL, "Announce exceeded max hops", "hops", data[0]) return nil } @@ -472,7 +471,7 @@ func (t *Transport) HandleAnnounce(data []byte, sourceIface common.NetworkInterf b := make([]byte, 8) _, err := rand.Read(b) if err != nil { - log.Printf("[DEBUG-7] Failed to generate random delay: %v", err) + debug.Log(debug.DEBUG_ALL, "Failed to generate random delay", "error", err) delay = time.Duration(0) // Default to no delay on error } else { delay = time.Duration(binary.BigEndian.Uint64(b)%2000) * time.Millisecond // #nosec G115 @@ -481,7 +480,7 @@ func (t *Transport) HandleAnnounce(data []byte, sourceIface common.NetworkInterf // Check bandwidth allocation for announces if !t.announceRate.Allow() { - log.Printf("[DEBUG-7] Announce rate limit exceeded, queuing...") + debug.Log(debug.DEBUG_ALL, "Announce rate limit exceeded, queuing") return nil } @@ -495,9 +494,9 @@ func (t *Transport) HandleAnnounce(data []byte, sourceIface common.NetworkInterf continue } - log.Printf("[DEBUG-7] Forwarding announce on interface %s", name) + debug.Log(debug.DEBUG_ALL, "Forwarding announce on interface", "name", name) if err := iface.Send(data, ""); err != nil { - log.Printf("[DEBUG-7] Failed to forward announce on %s: %v", name, err) + debug.Log(debug.DEBUG_ALL, "Failed to forward announce", "name", name, "error", err) lastErr = err } } @@ -649,7 +648,7 @@ func SendAnnounce(packet []byte) error { func (t *Transport) HandlePacket(data []byte, iface common.NetworkInterface) { if len(data) < 2 { - log.Printf("[DEBUG-3] Dropping packet: insufficient length (%d bytes)", len(data)) + debug.Log(debug.DEBUG_INFO, "Dropping packet: insufficient length", "bytes", len(data)) return } @@ -660,37 +659,36 @@ func (t *Transport) HandlePacket(data []byte, iface common.NetworkInterface) { propType := (headerByte & 0x10) >> 4 destType := (headerByte & 0x0C) >> 2 - log.Printf("[DEBUG-3] TRANSPORT: Packet received - Type: 0x%02x, Header: %d, Context: %d, PropType: %d, DestType: %d, Size: %d bytes", - packetType, headerType, contextFlag, propType, destType, len(data)) - log.Printf("[DEBUG-5] Interface: %s, Raw header: 0x%02x", iface.GetName(), headerByte) + debug.Log(debug.DEBUG_INFO, "TRANSPORT: Packet received", "type", fmt.Sprintf("0x%02x", packetType), "header", headerType, "context", contextFlag, "propType", propType, "destType", destType, "size", len(data)) + debug.Log(debug.DEBUG_TRACE, "Interface and raw header", "name", iface.GetName(), "header", fmt.Sprintf("0x%02x", headerByte)) if tcpIface, ok := iface.(*interfaces.TCPClientInterface); ok { tcpIface.UpdateStats(uint64(len(data)), true) - log.Printf("[DEBUG-6] Updated TCP interface stats - RX bytes: %d", len(data)) + debug.Log(debug.DEBUG_PACKETS, "Updated TCP interface stats", "rx_bytes", len(data)) } switch packetType { case PACKET_TYPE_ANNOUNCE: - log.Printf("[DEBUG-4] Processing announce packet") + debug.Log(debug.DEBUG_VERBOSE, "Processing announce packet") if err := t.handleAnnouncePacket(data, iface); err != nil { - log.Printf("[DEBUG-3] Announce handling failed: %v", err) + debug.Log(debug.DEBUG_INFO, "Announce handling failed", "error", err) } case PACKET_TYPE_LINK: - log.Printf("[DEBUG-4] Processing link packet") + debug.Log(debug.DEBUG_VERBOSE, "Processing link packet") t.handleLinkPacket(data[1:], iface) case 0x03: - log.Printf("[DEBUG-4] Processing path response") + debug.Log(debug.DEBUG_VERBOSE, "Processing path response") t.handlePathResponse(data[1:], iface) case 0x00: - log.Printf("[DEBUG-4] Processing transport packet") + debug.Log(debug.DEBUG_VERBOSE, "Processing transport packet") t.handleTransportPacket(data[1:], iface) default: - log.Printf("[DEBUG-3] Unknown packet type 0x%02x from %s", packetType, iface.GetName()) + debug.Log(debug.DEBUG_INFO, "Unknown packet type", "type", fmt.Sprintf("0x%02x", packetType), "source", iface.GetName()) } } func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterface) error { - log.Printf("[DEBUG-3] Processing announce packet, length: %d bytes", len(data)) + debug.Log(debug.DEBUG_INFO, "Processing announce packet", "length", len(data)) if len(data) < 2 { return fmt.Errorf("packet too small for header") } @@ -707,8 +705,7 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf destType := (headerByte1 & 0x0C) >> 2 // Destination type in next 2 bits packetType := headerByte1 & 0x03 // Packet type in lowest 2 bits - log.Printf("[DEBUG-5] Announce header: IFAC=%d, headerType=%d, context=%d, propType=%d, destType=%d, packetType=%d", - ifacFlag, headerType, contextFlag, propType, destType, packetType) + debug.Log(debug.DEBUG_TRACE, "Announce header", "ifac", ifacFlag, "headerType", headerType, "context", contextFlag, "propType", propType, "destType", destType, "packetType", packetType) // Skip IFAC code if present startIdx := 2 @@ -733,9 +730,9 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf context := data[startIdx+addrSize] payload := data[startIdx+addrSize+1:] - log.Printf("[DEBUG-3] Addresses: %x (len=%d)", addresses, len(addresses)) - log.Printf("[DEBUG-3] Context: %02x, Payload length: %d", context, len(payload)) - log.Printf("[DEBUG-3] Packet total length: %d", len(data)) + debug.Log(debug.DEBUG_INFO, "Addresses", "addresses", fmt.Sprintf("%x", addresses), "len", len(addresses)) + debug.Log(debug.DEBUG_INFO, "Context and payload", "context", fmt.Sprintf("%02x", context), "payload_len", len(payload)) + debug.Log(debug.DEBUG_INFO, "Packet total length", "length", len(data)) // Parse announce packet according to RNS specification // All announce packets have the same format: @@ -747,7 +744,7 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf minAnnounceSize := 64 + 10 + 10 + 64 // pubKey + nameHash + randomHash + signature if len(payload) < minAnnounceSize { - log.Printf("[DEBUG-3] Payload too small for announce: %d bytes, minimum %d", len(payload), minAnnounceSize) + debug.Log(debug.DEBUG_INFO, "Payload too small for announce", "bytes", len(payload), "minimum", minAnnounceSize) return fmt.Errorf("payload too small for announce") } @@ -782,16 +779,15 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf } else { ratchetHex = "(empty)" } - log.Printf("[DEBUG-3] Parsed announce: pubKey=%x, nameHash=%x, randomHash=%x, ratchet=%s, appData len=%d", - pubKey[:8], nameHash, randomHash, ratchetHex, len(appData)) + debug.Log(debug.DEBUG_INFO, "Parsed announce", "pubKey", fmt.Sprintf("%x", pubKey[:8]), "nameHash", fmt.Sprintf("%x", nameHash), "randomHash", fmt.Sprintf("%x", randomHash), "ratchet", ratchetHex, "appData_len", len(appData)) // Create identity from public key id = identity.FromPublicKey(pubKey) if id == nil { - log.Printf("[DEBUG-3] Failed to create identity from public key") + debug.Log(debug.DEBUG_INFO, "Failed to create identity from public key") return fmt.Errorf("invalid identity") } - log.Printf("[DEBUG-3] Successfully created identity") + debug.Log(debug.DEBUG_INFO, "Successfully created identity") // For announce packets, use destination hash from packet header (first 16 bytes of addresses) // This matches the RNS validate_announce logic @@ -807,7 +803,7 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf } signData = append(signData, appData...) - log.Printf("[DEBUG-3] Verifying signature with data len: %d", len(signData)) + debug.Log(debug.DEBUG_INFO, "Verifying signature", "data_len", len(signData)) // Check if this passes full RNS validation (signature + destination hash check) hashMaterial := make([]byte, 0) @@ -816,38 +812,38 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf expectedHashFull := sha256.Sum256(hashMaterial) expectedHash := expectedHashFull[:16] - log.Printf("[DEBUG-3] Destination hash from packet: %x", destinationHash) - log.Printf("[DEBUG-3] Expected destination hash: %x", expectedHash) - log.Printf("[DEBUG-3] Hash match: %t", string(destinationHash) == string(expectedHash)) + debug.Log(debug.DEBUG_INFO, "Destination hash from packet", "hash", fmt.Sprintf("%x", destinationHash)) + debug.Log(debug.DEBUG_INFO, "Expected destination hash", "hash", fmt.Sprintf("%x", expectedHash)) + debug.Log(debug.DEBUG_INFO, "Hash match", "match", string(destinationHash) == string(expectedHash)) hasAppData := len(appData) > 0 if !id.Verify(signData, signature) { if hasAppData { - log.Printf("[DEBUG-3] Announce packet has app_data, signature failed but accepting") + debug.Log(debug.DEBUG_INFO, "Announce packet has app_data, signature failed but accepting") } else { - log.Printf("[DEBUG-3] Signature verification failed - announce rejected") + debug.Log(debug.DEBUG_INFO, "Signature verification failed - announce rejected") return fmt.Errorf("invalid announce signature") } } else { - log.Printf("[DEBUG-3] Signature verification successful") + debug.Log(debug.DEBUG_INFO, "Signature verification successful") } if string(destinationHash) != string(expectedHash) { if hasAppData { - log.Printf("[DEBUG-3] Announce packet has app_data, destination hash mismatch but accepting") + debug.Log(debug.DEBUG_INFO, "Announce packet has app_data, destination hash mismatch but accepting") } else { - log.Printf("[DEBUG-3] Destination hash mismatch - announce rejected") + debug.Log(debug.DEBUG_INFO, "Destination hash mismatch - announce rejected") return fmt.Errorf("destination hash mismatch") } } else { - log.Printf("[DEBUG-3] Destination hash validation successful") + debug.Log(debug.DEBUG_INFO, "Destination hash validation successful") } - log.Printf("[DEBUG-3] Signature and destination hash verified successfully") + debug.Log(debug.DEBUG_INFO, "Signature and destination hash verified successfully") // Log app_data content for accepted announces if len(appData) > 0 { - log.Printf("[DEBUG-3] Accepted announce app_data: %x (%q)", appData, string(appData)) + debug.Log(debug.DEBUG_INFO, "Accepted announce app_data", "data", fmt.Sprintf("%x", appData), "string", string(appData)) } // Store the identity for later recall @@ -857,18 +853,18 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf announceHash := sha256.Sum256(data) hashStr := string(announceHash[:]) - log.Printf("[DEBUG-3] Announce hash: %x", announceHash[:8]) + debug.Log(debug.DEBUG_INFO, "Announce hash", "hash", fmt.Sprintf("%x", announceHash[:8])) t.mutex.Lock() if _, seen := t.seenAnnounces[hashStr]; seen { t.mutex.Unlock() - log.Printf("[DEBUG-3] Ignoring duplicate announce %x", announceHash[:8]) + debug.Log(debug.DEBUG_INFO, "Ignoring duplicate announce", "hash", fmt.Sprintf("%x", announceHash[:8])) return nil } t.seenAnnounces[hashStr] = true t.mutex.Unlock() - log.Printf("[DEBUG-3] Processing new announce") + debug.Log(debug.DEBUG_INFO, "Processing new announce") // Register the path from this announce // The destination is reachable via the interface that received this announce @@ -877,34 +873,34 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf t.mutex.Lock() t.updatePathUnlocked(destinationHash, nil, iface.GetName(), hopCount) t.mutex.Unlock() - log.Printf("[DEBUG-3] Registered path to %x via %s (%d hops)", destinationHash, iface.GetName(), hopCount) + debug.Log(debug.DEBUG_INFO, "Registered path", "hash", fmt.Sprintf("%x", destinationHash), "interface", iface.GetName(), "hops", hopCount) } // Notify handlers first, regardless of forwarding limits - log.Printf("[DEBUG-3] Notifying announce handlers: destHash=%x, appDataLen=%d", addresses[:16], len(appData)) + debug.Log(debug.DEBUG_INFO, "Notifying announce handlers", "destHash", fmt.Sprintf("%x", addresses[:16]), "appDataLen", len(appData)) t.notifyAnnounceHandlers(addresses[:16], id, appData) - log.Printf("[DEBUG-3] Announce handlers notified") + debug.Log(debug.DEBUG_INFO, "Announce handlers notified") // Don't forward if max hops reached if hopCount >= MAX_HOPS { - log.Printf("[DEBUG-3] Announce exceeded max hops: %d", hopCount) + debug.Log(debug.DEBUG_INFO, "Announce exceeded max hops", "hops", hopCount) return nil } - log.Printf("[DEBUG-3] Hop count OK: %d", hopCount) + debug.Log(debug.DEBUG_INFO, "Hop count OK", "hops", hopCount) // Check bandwidth allocation for announces if !t.announceRate.Allow() { - log.Printf("[DEBUG-3] Announce rate limit exceeded, not forwarding...") + debug.Log(debug.DEBUG_INFO, "Announce rate limit exceeded, not forwarding") return nil } - log.Printf("[DEBUG-3] Bandwidth check passed") + debug.Log(debug.DEBUG_INFO, "Bandwidth check passed") // Add random delay before retransmission (0-2 seconds) var delay time.Duration b := make([]byte, 8) _, err := rand.Read(b) if err != nil { - log.Printf("[DEBUG-7] Failed to generate random delay: %v", err) + debug.Log(debug.DEBUG_ALL, "Failed to generate random delay", "error", err) delay = time.Duration(0) // Default to no delay on error } else { delay = time.Duration(binary.BigEndian.Uint64(b)%2000) * time.Millisecond // #nosec G115 @@ -921,9 +917,9 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf continue } - log.Printf("[DEBUG-7] Forwarding announce on interface %s", name) + debug.Log(debug.DEBUG_ALL, "Forwarding announce on interface", "name", name) if err := outIface.Send(data, ""); err != nil { - log.Printf("[DEBUG-7] Failed to forward announce on %s: %v", name, err) + debug.Log(debug.DEBUG_ALL, "Failed to forward announce", "name", name, "error", err) lastErr = err } } @@ -932,13 +928,13 @@ func (t *Transport) handleAnnouncePacket(data []byte, iface common.NetworkInterf } func (t *Transport) handleLinkPacket(data []byte, iface common.NetworkInterface) { - log.Printf("[DEBUG-5] Handling link packet (%d bytes)", len(data)) + debug.Log(debug.DEBUG_TRACE, "Handling link packet", "bytes", len(data)) // Parse the packet - need to prepend the packet type byte that was stripped fullData := append([]byte{PACKET_TYPE_LINK}, data...) pkt := &packet.Packet{Raw: fullData} if err := pkt.Unpack(); err != nil { - log.Printf("[DEBUG-3] Failed to unpack link packet: %v", err) + debug.Log(debug.DEBUG_INFO, "Failed to unpack link packet", "error", err) return } @@ -947,11 +943,11 @@ func (t *Transport) handleLinkPacket(data []byte, iface common.NetworkInterface) destHash = destHash[:16] } - log.Printf("[DEBUG-5] Link packet for destination: %x, context: 0x%02x", destHash, pkt.Context) + debug.Log(debug.DEBUG_TRACE, "Link packet for destination", "hash", fmt.Sprintf("%x", destHash), "context", fmt.Sprintf("0x%02x", pkt.Context)) // Check if this is a link request (initial link establishment) if pkt.Context == packet.ContextLinkIdentify { - log.Printf("[DEBUG-4] Received link request for destination %x", destHash) + debug.Log(debug.DEBUG_VERBOSE, "Received link request for destination", "hash", fmt.Sprintf("%x", destHash)) // Look up the destination t.mutex.RLock() @@ -959,11 +955,11 @@ func (t *Transport) handleLinkPacket(data []byte, iface common.NetworkInterface) t.mutex.RUnlock() if !exists { - log.Printf("[DEBUG-3] No destination registered for hash %x", destHash) + debug.Log(debug.DEBUG_INFO, "No destination registered for hash", "hash", fmt.Sprintf("%x", destHash)) return } - log.Printf("[DEBUG-5] Found registered destination for %x", destHash) + debug.Log(debug.DEBUG_TRACE, "Found registered destination", "hash", fmt.Sprintf("%x", destHash)) // Handle the incoming link request t.handleIncomingLinkRequest(pkt, destIface, iface) @@ -972,27 +968,27 @@ func (t *Transport) handleLinkPacket(data []byte, iface common.NetworkInterface) // Handle regular link packets (for established links) if link := t.findLink(destHash); link != nil { - log.Printf("[DEBUG-6] Routing packet to established link") + debug.Log(debug.DEBUG_PACKETS, "Routing packet to established link") if link.packetCb != nil { - log.Printf("[DEBUG-7] Executing packet callback with %d bytes", len(pkt.Data)) + debug.Log(debug.DEBUG_ALL, "Executing packet callback", "bytes", len(pkt.Data)) link.packetCb(pkt.Data, pkt) } } else { - log.Printf("[DEBUG-5] No established link found for destination %x", destHash) + debug.Log(debug.DEBUG_TRACE, "No established link found for destination", "hash", fmt.Sprintf("%x", destHash)) } } func (t *Transport) handleIncomingLinkRequest(pkt *packet.Packet, destIface interface{}, networkIface common.NetworkInterface) { - log.Printf("[DEBUG-5] Handling incoming link request") + debug.Log(debug.DEBUG_TRACE, "Handling incoming link request") // The link ID is in the packet data linkID := pkt.Data if len(linkID) == 0 { - log.Printf("[DEBUG-3] No link ID in link request packet") + debug.Log(debug.DEBUG_INFO, "No link ID in link request packet") return } - log.Printf("[DEBUG-5] Link request with ID %x", linkID[:8]) + debug.Log(debug.DEBUG_TRACE, "Link request with ID", "id", fmt.Sprintf("%x", linkID[:8])) // Call the destination's link established callback directly // Use reflection to call the method if it exists @@ -1005,19 +1001,19 @@ func (t *Transport) handleIncomingLinkRequest(pkt *packet.Packet, destIface inte if len(results) > 0 && !results[0].IsNil() { // The callback is of type common.LinkEstablishedCallback which is func(interface{}) callback := results[0].Interface().(common.LinkEstablishedCallback) - log.Printf("[DEBUG-4] Calling destination's link established callback") + debug.Log(debug.DEBUG_VERBOSE, "Calling destination's link established callback") callback(linkID) } else { - log.Printf("[DEBUG-5] No link established callback set on destination") + debug.Log(debug.DEBUG_TRACE, "No link established callback set on destination") } } else { - log.Printf("[DEBUG-3] Destination does not have GetLinkCallback method") + debug.Log(debug.DEBUG_INFO, "Destination does not have GetLinkCallback method") } } else { - log.Printf("[DEBUG-3] Invalid destination object") + debug.Log(debug.DEBUG_INFO, "Invalid destination object") } - log.Printf("[DEBUG-4] Link request handled successfully") + debug.Log(debug.DEBUG_VERBOSE, "Link request handled successfully") } func (t *Transport) handlePathResponse(data []byte, iface common.NetworkInterface) { @@ -1058,37 +1054,36 @@ func (t *Transport) SendPacket(p *packet.Packet) error { t.mutex.RLock() defer t.mutex.RUnlock() - log.Printf("[DEBUG-4] Sending packet - Type: 0x%02x, Header: %d", p.PacketType, p.HeaderType) + debug.Log(debug.DEBUG_VERBOSE, "Sending packet", "type", fmt.Sprintf("0x%02x", p.PacketType), "header", p.HeaderType) data, err := p.Serialize() if err != nil { - log.Printf("[DEBUG-3] Packet serialization failed: %v", err) + debug.Log(debug.DEBUG_INFO, "Packet serialization failed", "error", err) return fmt.Errorf("failed to serialize packet: %w", err) } - log.Printf("[DEBUG-5] Serialized packet size: %d bytes", len(data)) + debug.Log(debug.DEBUG_TRACE, "Serialized packet size", "bytes", len(data)) // Use the DestinationHash field directly for path lookup destHash := p.DestinationHash if len(destHash) > 16 { destHash = destHash[:16] } - log.Printf("[DEBUG-6] Destination hash: %x", destHash) + debug.Log(debug.DEBUG_PACKETS, "Destination hash", "hash", fmt.Sprintf("%x", destHash)) path, exists := t.paths[string(destHash)] if !exists { - log.Printf("[DEBUG-3] No path found for destination %x", destHash) + debug.Log(debug.DEBUG_INFO, "No path found for destination", "hash", fmt.Sprintf("%x", destHash)) return errors.New("no path to destination") } - log.Printf("[DEBUG-5] Using path - Interface: %s, Next hop: %x, Hops: %d", - path.Interface.GetName(), path.NextHop, path.HopCount) + debug.Log(debug.DEBUG_TRACE, "Using path", "interface", path.Interface.GetName(), "nextHop", fmt.Sprintf("%x", path.NextHop), "hops", path.HopCount) if err := path.Interface.Send(data, ""); err != nil { - log.Printf("[DEBUG-3] Failed to send packet: %v", err) + debug.Log(debug.DEBUG_INFO, "Failed to send packet", "error", err) return fmt.Errorf("failed to send packet: %w", err) } - log.Printf("[DEBUG-7] Packet sent successfully") + debug.Log(debug.DEBUG_ALL, "Packet sent successfully") return nil } @@ -1257,8 +1252,8 @@ func (l *Link) GetStatus() int { } func CreateAnnouncePacket(destHash []byte, identity *identity.Identity, appData []byte, destName string, hops byte, config *common.ReticulumConfig) []byte { - log.Printf("[DEBUG-3] Creating announce packet for %s", destName) - log.Printf("[DEBUG-3] Input: destHash=%x, appData=%s, hops=%d", destHash[:8], string(appData), hops) + debug.Log(debug.DEBUG_INFO, "Creating announce packet", "destName", destName) + debug.Log(debug.DEBUG_INFO, "Input", "destHash", fmt.Sprintf("%x", destHash[:8]), "appData", string(appData), "hops", hops) // Create header (2 bytes) headerByte := byte( @@ -1270,53 +1265,53 @@ func CreateAnnouncePacket(destHash []byte, identity *identity.Identity, appData PACKET_TYPE_ANNOUNCE, // Packet type (0x01) ) - log.Printf("[DEBUG-7] Created header byte: 0x%02x, hops: %d", headerByte, hops) + debug.Log(debug.DEBUG_ALL, "Created header byte", "header", fmt.Sprintf("0x%02x", headerByte), "hops", hops) packet := []byte{headerByte, hops} - log.Printf("[DEBUG-7] Initial packet size: %d bytes", len(packet)) + debug.Log(debug.DEBUG_ALL, "Initial packet size", "bytes", len(packet)) // Add destination hash (16 bytes) if len(destHash) > 16 { destHash = destHash[:16] } - log.Printf("[DEBUG-7] Adding destination hash (16 bytes): %x", destHash) + debug.Log(debug.DEBUG_ALL, "Adding destination hash (16 bytes)", "hash", fmt.Sprintf("%x", destHash)) packet = append(packet, destHash...) - log.Printf("[DEBUG-7] Packet size after adding destination hash: %d bytes", len(packet)) + debug.Log(debug.DEBUG_ALL, "Packet size after adding destination hash", "bytes", len(packet)) // Get full public key and split into encryption and signing keys pubKey := identity.GetPublicKey() encKey := pubKey[:32] // x25519 public key for encryption signKey := pubKey[32:] // Ed25519 public key for signing - log.Printf("[DEBUG-7] Full public key: %x", pubKey) + debug.Log(debug.DEBUG_ALL, "Full public key", "key", fmt.Sprintf("%x", pubKey)) // Add encryption key (32 bytes) - log.Printf("[DEBUG-7] Adding encryption key (32 bytes): %x", encKey) + debug.Log(debug.DEBUG_ALL, "Adding encryption key (32 bytes)", "key", fmt.Sprintf("%x", encKey)) packet = append(packet, encKey...) - log.Printf("[DEBUG-7] Packet size after adding encryption key: %d bytes", len(packet)) + debug.Log(debug.DEBUG_ALL, "Packet size after adding encryption key", "bytes", len(packet)) // Add signing key (32 bytes) - log.Printf("[DEBUG-7] Adding signing key (32 bytes): %x", signKey) + debug.Log(debug.DEBUG_ALL, "Adding signing key (32 bytes)", "key", fmt.Sprintf("%x", signKey)) packet = append(packet, signKey...) - log.Printf("[DEBUG-7] Packet size after adding signing key: %d bytes", len(packet)) + debug.Log(debug.DEBUG_ALL, "Packet size after adding signing key", "bytes", len(packet)) // Add name hash (10 bytes) nameHash := sha256.Sum256([]byte(destName)) - log.Printf("[DEBUG-7] Adding name hash (10 bytes) for %s: %x", destName, nameHash[:10]) + debug.Log(debug.DEBUG_ALL, "Adding name hash (10 bytes)", "destName", destName, "hash", fmt.Sprintf("%x", nameHash[:10])) packet = append(packet, nameHash[:10]...) - log.Printf("[DEBUG-7] Packet size after adding name hash: %d bytes", len(packet)) + debug.Log(debug.DEBUG_ALL, "Packet size after adding name hash", "bytes", len(packet)) // Add random hash (10 bytes) randomBytes := make([]byte, 5) _, err := rand.Read(randomBytes) // #nosec G104 if err != nil { - log.Printf("[DEBUG-7] Failed to read random bytes: %v", err) + debug.Log(debug.DEBUG_ALL, "Failed to read random bytes", "error", err) return nil // Or handle the error appropriately } timeBytes := make([]byte, 8) binary.BigEndian.PutUint64(timeBytes, uint64(time.Now().Unix())) // #nosec G115 - log.Printf("[DEBUG-7] Adding random hash (10 bytes): %x%x", randomBytes, timeBytes[:5]) + debug.Log(debug.DEBUG_ALL, "Adding random hash (10 bytes)", "random", fmt.Sprintf("%x", randomBytes), "time", fmt.Sprintf("%x", timeBytes[:5])) packet = append(packet, randomBytes...) packet = append(packet, timeBytes[:5]...) - log.Printf("[DEBUG-7] Packet size after adding random hash: %d bytes", len(packet)) + debug.Log(debug.DEBUG_ALL, "Packet size after adding random hash", "bytes", len(packet)) // Create msgpack array for app data nameBytes := []byte(destName) @@ -1335,14 +1330,14 @@ func CreateAnnouncePacket(destHash []byte, identity *identity.Identity, appData // Create signature over destination hash and app data signData := append(destHash, appDataMsg...) signature := identity.Sign(signData) - log.Printf("[DEBUG-7] Adding signature (64 bytes): %x", signature) + debug.Log(debug.DEBUG_ALL, "Adding signature (64 bytes)", "signature", fmt.Sprintf("%x", signature)) packet = append(packet, signature...) - log.Printf("[DEBUG-7] Packet size after adding signature: %d bytes", len(packet)) + debug.Log(debug.DEBUG_ALL, "Packet size after adding signature", "bytes", len(packet)) // Finally add the app data message packet = append(packet, appDataMsg...) - log.Printf("[DEBUG-3] Final packet size: %d bytes", len(packet)) - log.Printf("[DEBUG-3] appDataMsg: %x (len=%d)", appDataMsg, len(appDataMsg)) + debug.Log(debug.DEBUG_INFO, "Final packet size", "bytes", len(packet)) + debug.Log(debug.DEBUG_INFO, "appDataMsg", "data", fmt.Sprintf("%x", appDataMsg), "len", len(appDataMsg)) return packet }