fix(wireguard): add xray-style timestamps to streamed logs

x0sina · x0sina · commit 216b1f3c093f · 2026-04-04T22:58:00.000+03:30
diff --git a/backend/wireguard/jobs.go b/backend/wireguard/jobs.go
@@ -107,6 +107,7 @@ func (wg *WireGuard) logStatsDeviceReadError(err error) {
 	wg.mu.Unlock()
 
 	log.Printf("wireguard stats update skipped: failed to read device: %v", err)
+	wg.emitWarningLogf("wireguard stats update skipped: failed to read device: %v", err)
 }
 
 // cleanupOfflineUsers removes deleted stats entries once their traffic has been reported.
diff --git a/backend/wireguard/log.go b/backend/wireguard/log.go
@@ -0,0 +1,56 @@
+package wireguard
+
+import (
+	"fmt"
+	"time"
+)
+
+type logSeverity string
+
+const (
+	wireGuardLogTimestampFormat = "2006/01/02 15:04:05.000000"
+
+	logSeverityInfo    logSeverity = "Info"
+	logSeverityWarning logSeverity = "Warning"
+	logSeverityError   logSeverity = "Error"
+)
+
+func formatWireGuardLogLine(severity logSeverity, message string) string {
+	timestamp := time.Now().Format(wireGuardLogTimestampFormat)
+	return fmt.Sprintf("%s [%s] wireguard: %s", timestamp, severity, message)
+}
+
+func (wg *WireGuard) emitInfoLogf(format string, args ...any) {
+	wg.emitLogf(logSeverityInfo, format, args...)
+}
+
+func (wg *WireGuard) emitWarningLogf(format string, args ...any) {
+	wg.emitLogf(logSeverityWarning, format, args...)
+}
+
+func (wg *WireGuard) emitErrorLogf(format string, args ...any) {
+	wg.emitLogf(logSeverityError, format, args...)
+}
+
+func (wg *WireGuard) emitLogf(severity logSeverity, format string, args ...any) {
+	wg.emitLog(severity, fmt.Sprintf(format, args...))
+}
+
+func (wg *WireGuard) emitLog(severity logSeverity, message string) {
+	wg.mu.RLock()
+	defer wg.mu.RUnlock()
+
+	wg.emitLogLocked(severity, message)
+}
+
+// emitLogLocked sends to the backend log channel while the caller already holds wg.mu.
+func (wg *WireGuard) emitLogLocked(severity logSeverity, message string) {
+	if wg.logChan == nil {
+		return
+	}
+
+	select {
+	case wg.logChan <- formatWireGuardLogLine(severity, message):
+	default:
+	}
+}
diff --git a/backend/wireguard/wireguard.go b/backend/wireguard/wireguard.go
@@ -195,7 +195,7 @@ func newWithManagerFactory(cfg *config.Config, wgConfig *Config, users []*common
 	wg.mu.Unlock()
 
 	log.Println("wireguard started, Version:", wg.Version())
-	wg.logChan <- fmt.Sprintf("WireGuard interface %s initialized successfully", wgConfig.InterfaceName)
+	wg.emitInfoLogf("WireGuard interface %s initialized successfully", wgConfig.InterfaceName)
 
 	return wg, nil
 }
@@ -266,6 +266,7 @@ func (wg *WireGuard) restartLocked() error {
 	wg.mu.Unlock()
 
 	log.Println("dynamically reconfiguring wireguard interface")
+	wg.emitInfoLogf("dynamically reconfiguring wireguard interface")
 
 	config := wgtypes.Config{
 		PrivateKey:   &privateKey,
@@ -279,6 +280,7 @@ func (wg *WireGuard) restartLocked() error {
 	}
 
 	log.Println("wireguard interface reconfigured successfully without downtime")
+	wg.emitInfoLogf("wireguard interface reconfigured successfully without downtime")
 	return nil
 }
 
@@ -327,12 +329,14 @@ func (wg *WireGuard) shutdownLocked() {
 	if wg.manager != nil {
 		if err := wg.manager.Close(); err != nil {
 			log.Printf("error closing manager: %v", err)
+			wg.emitLogLocked(logSeverityError, fmt.Sprintf("error closing manager: %v", err))
 		}
 		wg.manager = nil
 	}
 
 	wg.state = lifecycleStopped
 	wg.version = ""
+	wg.emitLogLocked(logSeverityInfo, "wireguard shutdown complete")
 	if wg.logChan != nil {
 		close(wg.logChan)
 		wg.logChan = nil
diff --git a/backend/wireguard/wireguard_lifecycle_test.go b/backend/wireguard/wireguard_lifecycle_test.go
@@ -5,6 +5,7 @@ import (
 	"errors"
 	"fmt"
 	"net"
+	"regexp"
 	"slices"
 	"strings"
 	"testing"
@@ -160,6 +161,16 @@ func TestWireGuardNewInitializesWithSingleConfigureCallIncludingPeers(t *testing
 		t.Fatalf("expected one peer in startup configure call, got %d", len(configured.Peers))
 	}
 
+	select {
+	case startupLog := <-wg.Logs():
+		pattern := regexp.MustCompile(`^\d{4}/\d{2}/\d{2} \d{2}:\d{2}:\d{2}\.\d{6} \[Info\] wireguard: WireGuard interface wg-test initialized successfully$`)
+		if !pattern.MatchString(startupLog) {
+			t.Fatalf("expected startup log with timestamp prefix, got %q", startupLog)
+		}
+	case <-time.After(time.Second):
+		t.Fatal("expected startup log to be emitted")
+	}
+
 	parsedPublicKey, err := wgtypes.ParseKey(publicKey)
 	if err != nil {
 		t.Fatalf("failed to parse public key: %v", err)

Original file line number	Diff line number	Diff line change
`@@ -107,6 +107,7 @@ func (wg *WireGuard) logStatsDeviceReadError(err error) {`
`107`	`107`	`wg.mu.Unlock()`
`108`	`108`
`109`	`109`	`log.Printf("wireguard stats update skipped: failed to read device: %v", err)`
	`110`	`+ wg.emitWarningLogf("wireguard stats update skipped: failed to read device: %v", err)`
`110`	`111`	`}`
`111`	`112`
`112`	`113`	`// cleanupOfflineUsers removes deleted stats entries once their traffic has been reported.`