diff --git a/block_device.go b/block_device.go index 3a44135..4a8769e 100644 --- a/block_device.go +++ b/block_device.go @@ -16,8 +16,8 @@ type remoteImageBackend struct { func (r remoteImageBackend) ReadAt(p []byte, off int64) (n int, err error) { virtualMediaStateMutex.RLock() - logger.Debugf("currentVirtualMediaState is %v", currentVirtualMediaState) - logger.Debugf("read size: %d, off: %d", len(p), off) + logger.Debug().Interface("currentVirtualMediaState", currentVirtualMediaState).Msg("currentVirtualMediaState") + logger.Debug().Int64("read size", int64(len(p))).Int64("off", off).Msg("read size and off") if currentVirtualMediaState == nil { return 0, errors.New("image not mounted") } @@ -93,7 +93,7 @@ func (d *NBDDevice) Start() error { // Remove the socket file if it already exists if _, err := os.Stat(nbdSocketPath); err == nil { if err := os.Remove(nbdSocketPath); err != nil { - logger.Errorf("Failed to remove existing socket file %s: %v", nbdSocketPath, err) + nativeLogger.Warn().Err(err).Str("socket_path", nbdSocketPath).Msg("Failed to remove existing socket file") os.Exit(1) } } @@ -134,7 +134,7 @@ func (d *NBDDevice) runServerConn() { MaximumBlockSize: uint32(16 * 1024), SupportsMultiConn: false, }) - logger.Infof("nbd server exited: %v", err) + nativeLogger.Info().Err(err).Msg("nbd server exited") } func (d *NBDDevice) runClientConn() { @@ -142,14 +142,14 @@ func (d *NBDDevice) runClientConn() { ExportName: "jetkvm", BlockSize: uint32(4 * 1024), }) - logger.Infof("nbd client exited: %v", err) + nativeLogger.Info().Err(err).Msg("nbd client exited") } func (d *NBDDevice) Close() { if d.dev != nil { err := client.Disconnect(d.dev) if err != nil { - logger.Warnf("error disconnecting nbd client: %v", err) + nativeLogger.Warn().Err(err).Msg("error disconnecting nbd client") } _ = d.dev.Close() } diff --git a/cloud.go b/cloud.go index 070db8d..a999fc8 100644 --- a/cloud.go +++ b/cloud.go @@ -253,14 +253,14 @@ func disconnectCloud(reason error) { defer cloudDisconnectLock.Unlock() if cloudDisconnectChan == nil { - cloudLogger.Tracef("cloud disconnect channel is not set, no need to disconnect") + cloudLogger.Trace().Msg("cloud disconnect channel is not set, no need to disconnect") return } // just in case the channel is closed, we don't want to panic defer func() { if r := recover(); r != nil { - cloudLogger.Infof("cloud disconnect channel is closed, no need to disconnect: %v", r) + cloudLogger.Warn().Interface("reason", r).Msg("cloud disconnect channel is closed, no need to disconnect") } }() cloudDisconnectChan <- reason @@ -289,11 +289,16 @@ func runWebsocketClient() error { header.Set("Authorization", "Bearer "+config.CloudToken) dialCtx, cancelDial := context.WithTimeout(context.Background(), CloudWebSocketConnectTimeout) + scopedLogger := websocketLogger.With(). + Str("source", wsURL.Host). + Str("sourceType", "cloud"). + Logger() + defer cancelDial() c, _, err := websocket.Dial(dialCtx, wsURL.String(), &websocket.DialOptions{ HTTPHeader: header, OnPingReceived: func(ctx context.Context, payload []byte) bool { - websocketLogger.Infof("ping frame received: %v, source: %s, sourceType: cloud", payload, wsURL.Host) + scopedLogger.Info().Bytes("payload", payload).Int("length", len(payload)).Msg("ping frame received") metricConnectionTotalPingReceivedCount.WithLabelValues("cloud", wsURL.Host).Inc() metricConnectionLastPingReceivedTimestamp.WithLabelValues("cloud", wsURL.Host).SetToCurrentTime() @@ -304,19 +309,19 @@ func runWebsocketClient() error { // if the context is canceled, we don't want to return an error if err != nil { if errors.Is(err, context.Canceled) { - cloudLogger.Infof("websocket connection canceled") + cloudLogger.Info().Msg("websocket connection canceled") return nil } return err } defer c.CloseNow() //nolint:errcheck - cloudLogger.Infof("websocket connected to %s", wsURL) + cloudLogger.Info().Str("url", wsURL.String()).Msg("websocket connected") // set the metrics when we successfully connect to the cloud. wsResetMetrics(true, "cloud", wsURL.Host) // we don't have a source for the cloud connection - return handleWebRTCSignalWsMessages(c, true, wsURL.Host) + return handleWebRTCSignalWsMessages(c, true, wsURL.Host, &scopedLogger) } func authenticateSession(ctx context.Context, c *websocket.Conn, req WebRTCSessionRequest) error { @@ -327,7 +332,7 @@ func authenticateSession(ctx context.Context, c *websocket.Conn, req WebRTCSessi _ = wsjson.Write(context.Background(), c, gin.H{ "error": fmt.Sprintf("failed to initialize OIDC provider: %v", err), }) - cloudLogger.Errorf("failed to initialize OIDC provider: %v", err) + cloudLogger.Warn().Err(err).Msg("failed to initialize OIDC provider") return err } @@ -396,8 +401,8 @@ func handleSessionRequest(ctx context.Context, c *websocket.Conn, req WebRTCSess }() } - cloudLogger.Info("new session accepted") - cloudLogger.Tracef("new session accepted: %v", session) + cloudLogger.Info().Interface("session", session).Msg("new session accepted") + cloudLogger.Trace().Interface("session", session).Msg("new session accepted") currentSession = session _ = wsjson.Write(context.Background(), c, gin.H{"type": "answer", "data": sd}) return nil @@ -413,21 +418,21 @@ func RunWebsocketClient() { // If the network is not up, well, we can't connect to the cloud. if !networkState.Up { - cloudLogger.Warn("waiting for network to be up, will retry in 3 seconds") + cloudLogger.Warn().Msg("waiting for network to be up, will retry in 3 seconds") time.Sleep(3 * time.Second) continue } // If the system time is not synchronized, the API request will fail anyway because the TLS handshake will fail. if isTimeSyncNeeded() && !timeSyncSuccess { - cloudLogger.Warn("system time is not synced, will retry in 3 seconds") + cloudLogger.Warn().Msg("system time is not synced, will retry in 3 seconds") time.Sleep(3 * time.Second) continue } err := runWebsocketClient() if err != nil { - cloudLogger.Errorf("websocket client error: %v", err) + cloudLogger.Warn().Err(err).Msg("websocket client error") metricCloudConnectionStatus.Set(0) metricCloudConnectionFailureCount.Inc() time.Sleep(5 * time.Second) @@ -479,7 +484,7 @@ func rpcDeregisterDevice() error { return fmt.Errorf("failed to save configuration after deregistering: %w", err) } - cloudLogger.Infof("device deregistered, disconnecting from cloud") + cloudLogger.Info().Msg("device deregistered, disconnecting from cloud") disconnectCloud(fmt.Errorf("device deregistered")) return nil diff --git a/config.go b/config.go index 1c1b98d..c38f1ed 100644 --- a/config.go +++ b/config.go @@ -132,7 +132,7 @@ func LoadConfig() { defer configLock.Unlock() if config != nil { - logger.Info("config already loaded, skipping") + logger.Info().Msg("config already loaded, skipping") return } @@ -141,7 +141,7 @@ func LoadConfig() { file, err := os.Open(configPath) if err != nil { - logger.Debug("default config file doesn't exist, using default") + logger.Debug().Msg("default config file doesn't exist, using default") return } defer file.Close() @@ -149,7 +149,7 @@ func LoadConfig() { // load and merge the default config with the user config loadedConfig := *defaultConfig if err := json.NewDecoder(file).Decode(&loadedConfig); err != nil { - logger.Errorf("config file JSON parsing failed, %v", err) + logger.Warn().Err(err).Msg("config file JSON parsing failed") return } diff --git a/display.go b/display.go index f4e8cf7..a5528a3 100644 --- a/display.go +++ b/display.go @@ -24,7 +24,7 @@ const ( func switchToScreen(screen string) { _, err := CallCtrlAction("lv_scr_load", map[string]interface{}{"obj": screen}) if err != nil { - logger.Warnf("failed to switch to screen %s: %v", screen, err) + displayLogger.Warn().Err(err).Str("screen", screen).Msg("failed to switch to screen") return } currentScreen = screen @@ -40,7 +40,7 @@ func updateLabelIfChanged(objName string, newText string) { } func switchToScreenIfDifferent(screenName string) { - logger.Infof("switching screen from %s to %s", currentScreen, screenName) + displayLogger.Info().Str("from", currentScreen).Str("to", screenName).Msg("switching screen") if currentScreen != screenName { switchToScreen(screenName) } @@ -74,12 +74,12 @@ var displayInited = false func requestDisplayUpdate() { if !displayInited { - logger.Info("display not inited, skipping updates") + displayLogger.Info().Msg("display not inited, skipping updates") return } go func() { wakeDisplay(false) - logger.Info("display updating") + displayLogger.Info().Msg("display updating") //TODO: only run once regardless how many pending updates updateDisplay() }() @@ -118,7 +118,7 @@ func setDisplayBrightness(brightness int) error { return err } - logger.Infof("display: set brightness to %v", brightness) + displayLogger.Info().Int("brightness", brightness).Msg("set brightness") return nil } @@ -127,7 +127,7 @@ func setDisplayBrightness(brightness int) error { func tick_displayDim() { err := setDisplayBrightness(config.DisplayMaxBrightness / 2) if err != nil { - logger.Warnf("display: failed to dim display: %s", err) + displayLogger.Warn().Err(err).Msg("failed to dim display") } dimTicker.Stop() @@ -140,7 +140,7 @@ func tick_displayDim() { func tick_displayOff() { err := setDisplayBrightness(0) if err != nil { - logger.Warnf("display: failed to turn off display: %s", err) + displayLogger.Warn().Err(err).Msg("failed to turn off display") } offTicker.Stop() @@ -163,7 +163,7 @@ func wakeDisplay(force bool) { err := setDisplayBrightness(config.DisplayMaxBrightness) if err != nil { - logger.Warnf("display wake failed, %s", err) + displayLogger.Warn().Err(err).Msg("failed to wake display") } if config.DisplayDimAfterSec != 0 { @@ -183,7 +183,7 @@ func wakeDisplay(force bool) { func watchTsEvents() { ts, err := os.OpenFile(touchscreenDevice, os.O_RDONLY, 0666) if err != nil { - logger.Warnf("display: failed to open touchscreen device: %s", err) + displayLogger.Warn().Err(err).Msg("failed to open touchscreen device") return } @@ -196,7 +196,7 @@ func watchTsEvents() { for { _, err := ts.Read(buf) if err != nil { - logger.Warnf("display: failed to read from touchscreen device: %s", err) + displayLogger.Warn().Err(err).Msg("failed to read from touchscreen device") return } @@ -216,7 +216,7 @@ func startBacklightTickers() { } if dimTicker == nil && config.DisplayDimAfterSec != 0 { - logger.Info("display: dim_ticker has started") + displayLogger.Info().Msg("dim_ticker has started") dimTicker = time.NewTicker(time.Duration(config.DisplayDimAfterSec) * time.Second) defer dimTicker.Stop() @@ -231,7 +231,7 @@ func startBacklightTickers() { } if offTicker == nil && config.DisplayOffAfterSec != 0 { - logger.Info("display: off_ticker has started") + displayLogger.Info().Msg("off_ticker has started") offTicker = time.NewTicker(time.Duration(config.DisplayOffAfterSec) * time.Second) defer offTicker.Stop() @@ -251,11 +251,11 @@ func init() { go func() { waitCtrlClientConnected() - logger.Info("setting initial display contents") + displayLogger.Info().Msg("setting initial display contents") time.Sleep(500 * time.Millisecond) updateStaticContents() displayInited = true - logger.Info("display inited") + displayLogger.Info().Msg("display inited") startBacklightTickers() wakeDisplay(true) requestDisplayUpdate() diff --git a/fuse.go b/fuse.go index 29b11f7..ea50bfd 100644 --- a/fuse.go +++ b/fuse.go @@ -103,7 +103,7 @@ func RunFuseServer() { var err error fuseServer, err = fs.Mount(fuseMountPoint, &FuseRoot{}, opts) if err != nil { - logger.Warnf("failed to mount fuse: %v", err) + logger.Warn().Err(err).Msg("failed to mount fuse") } fuseServer.Wait() } diff --git a/go.mod b/go.mod index fae1cbd..1311a33 100644 --- a/go.mod +++ b/go.mod @@ -1,8 +1,6 @@ module github.com/jetkvm/kvm -go 1.21.0 - -toolchain go1.21.1 +go 1.23.0 require ( github.com/Masterminds/semver/v3 v3.3.0 @@ -10,7 +8,8 @@ require ( github.com/coder/websocket v1.8.13 github.com/coreos/go-oidc/v3 v3.11.0 github.com/creack/pty v1.1.23 - github.com/gin-gonic/gin v1.9.1 + github.com/gin-contrib/logger v1.2.5 + github.com/gin-gonic/gin v1.10.0 github.com/google/uuid v1.6.0 github.com/gwatts/rootcerts v0.0.0-20240401182218-3ab9db955caf github.com/hanwen/go-fuse/v2 v2.5.1 @@ -22,38 +21,39 @@ require ( github.com/prometheus/client_golang v1.21.0 github.com/prometheus/common v0.62.0 github.com/psanford/httpreadat v0.1.0 + github.com/rs/zerolog v1.34.0 github.com/vishvananda/netlink v1.3.0 go.bug.st/serial v1.6.2 - golang.org/x/crypto v0.31.0 - golang.org/x/net v0.33.0 + golang.org/x/crypto v0.36.0 + golang.org/x/net v0.38.0 ) replace github.com/pojntfx/go-nbd v0.3.2 => github.com/chemhack/go-nbd v0.0.0-20241006125820-59e45f5b1e7b require ( github.com/beorn7/perks v1.0.1 // indirect - github.com/bytedance/sonic v1.11.6 // indirect - github.com/bytedance/sonic/loader v0.1.1 // indirect + github.com/bytedance/sonic v1.13.2 // indirect + github.com/bytedance/sonic/loader v0.2.4 // indirect github.com/cespare/xxhash/v2 v2.3.0 // indirect - github.com/cloudwego/base64x v0.1.4 // indirect - github.com/cloudwego/iasm v0.2.0 // indirect + github.com/cloudwego/base64x v0.1.5 // indirect github.com/creack/goselect v0.1.2 // indirect - github.com/gabriel-vasile/mimetype v1.4.3 // indirect - github.com/gin-contrib/sse v0.1.0 // indirect + github.com/gabriel-vasile/mimetype v1.4.8 // indirect + github.com/gin-contrib/sse v1.0.0 // indirect github.com/go-jose/go-jose/v4 v4.0.2 // indirect github.com/go-playground/locales v0.14.1 // indirect github.com/go-playground/universal-translator v0.18.1 // indirect - github.com/go-playground/validator/v10 v10.20.0 // indirect - github.com/goccy/go-json v0.10.2 // indirect + github.com/go-playground/validator/v10 v10.26.0 // indirect + github.com/goccy/go-json v0.10.5 // indirect github.com/json-iterator/go v1.1.12 // indirect github.com/klauspost/compress v1.17.11 // indirect - github.com/klauspost/cpuid/v2 v2.2.7 // indirect + github.com/klauspost/cpuid/v2 v2.2.10 // indirect github.com/leodido/go-urn v1.4.0 // indirect + github.com/mattn/go-colorable v0.1.14 // indirect github.com/mattn/go-isatty v0.0.20 // indirect github.com/modern-go/concurrent v0.0.0-20180306012644-bacd9c7ef1dd // indirect github.com/modern-go/reflect2 v1.0.2 // indirect github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 // indirect - github.com/pelletier/go-toml/v2 v2.2.2 // indirect + github.com/pelletier/go-toml/v2 v2.2.3 // indirect github.com/pilebones/go-udev v0.9.0 // indirect github.com/pion/datachannel v1.5.9 // indirect github.com/pion/dtls/v3 v3.0.3 // indirect @@ -74,10 +74,10 @@ require ( github.com/ugorji/go/codec v1.2.12 // indirect github.com/vishvananda/netns v0.0.4 // indirect github.com/wlynxg/anet v0.0.5 // indirect - golang.org/x/arch v0.8.0 // indirect + golang.org/x/arch v0.15.0 // indirect golang.org/x/oauth2 v0.24.0 // indirect - golang.org/x/sys v0.28.0 // indirect - golang.org/x/text v0.21.0 // indirect - google.golang.org/protobuf v1.36.1 // indirect + golang.org/x/sys v0.32.0 // indirect + golang.org/x/text v0.23.0 // indirect + google.golang.org/protobuf v1.36.6 // indirect gopkg.in/yaml.v3 v3.0.1 // indirect ) diff --git a/go.sum b/go.sum index 1563130..565c0cc 100644 --- a/go.sum +++ b/go.sum @@ -4,24 +4,23 @@ github.com/beevik/ntp v1.3.1 h1:Y/srlT8L1yQr58kyPWFPZIxRL8ttx2SRIpVYJqZIlAM= github.com/beevik/ntp v1.3.1/go.mod h1:fT6PylBq86Tsq23ZMEe47b7QQrZfYBFPnpzt0a9kJxw= github.com/beorn7/perks v1.0.1 h1:VlbKKnNfV8bJzeqoa4cOKqO6bYr3WgKZxO8Z16+hsOM= github.com/beorn7/perks v1.0.1/go.mod h1:G2ZrVWU2WbWT9wwq4/hrbKbnv/1ERSJQ0ibhJ6rlkpw= -github.com/bytedance/sonic v1.11.6 h1:oUp34TzMlL+OY1OUWxHqsdkgC/Zfc85zGqw9siXjrc0= -github.com/bytedance/sonic v1.11.6/go.mod h1:LysEHSvpvDySVdC2f87zGWf6CIKJcAvqab1ZaiQtds4= -github.com/bytedance/sonic/loader v0.1.1 h1:c+e5Pt1k/cy5wMveRDyk2X4B9hF4g7an8N3zCYjJFNM= +github.com/bytedance/sonic v1.13.2 h1:8/H1FempDZqC4VqjptGo14QQlJx8VdZJegxs6wwfqpQ= +github.com/bytedance/sonic v1.13.2/go.mod h1:o68xyaF9u2gvVBuGHPlUVCy+ZfmNNO5ETf1+KgkJhz4= github.com/bytedance/sonic/loader v0.1.1/go.mod h1:ncP89zfokxS5LZrJxl5z0UJcsk4M4yY2JpfqGeCtNLU= +github.com/bytedance/sonic/loader v0.2.4 h1:ZWCw4stuXUsn1/+zQDqeE7JKP+QO47tz7QCNan80NzY= +github.com/bytedance/sonic/loader v0.2.4/go.mod h1:N8A3vUdtUebEY2/VQC0MyhYeKUFosQU6FxH2JmUe6VI= github.com/cespare/xxhash/v2 v2.3.0 h1:UL815xU9SqsFlibzuggzjXhog7bL6oX9BbNZnL2UFvs= github.com/cespare/xxhash/v2 v2.3.0/go.mod h1:VGX0DQ3Q6kWi7AoAeZDth3/j3BFtOZR5XLFGgcrjCOs= github.com/chemhack/go-nbd v0.0.0-20241006125820-59e45f5b1e7b h1:dSbDgy72Y1sjLPWLv7vs0fMFuhMBMViiT9PJZiZWZNs= github.com/chemhack/go-nbd v0.0.0-20241006125820-59e45f5b1e7b/go.mod h1:SehHnbi2e8NiSAKby42Itm8SIoS7b+wAprsfPH3qgYk= -github.com/cloudwego/base64x v0.1.4 h1:jwCgWpFanWmN8xoIUHa2rtzmkd5J2plF/dnLS6Xd/0Y= -github.com/cloudwego/base64x v0.1.4/go.mod h1:0zlkT4Wn5C6NdauXdJRhSKRlJvmclQ1hhJgA0rcu/8w= -github.com/cloudwego/iasm v0.2.0 h1:1KNIy1I1H9hNNFEEH3DVnI4UujN+1zjpuk6gwHLTssg= +github.com/cloudwego/base64x v0.1.5 h1:XPciSp1xaq2VCSt6lF0phncD4koWyULpl5bUxbfCyP4= +github.com/cloudwego/base64x v0.1.5/go.mod h1:0zlkT4Wn5C6NdauXdJRhSKRlJvmclQ1hhJgA0rcu/8w= github.com/cloudwego/iasm v0.2.0/go.mod h1:8rXZaNYT2n95jn+zTI1sDr+IgcD2GVs0nlbbQPiEFhY= -github.com/coder/websocket v1.8.12 h1:5bUXkEPPIbewrnkU8LTCLVaxi4N4J8ahufH2vlo4NAo= -github.com/coder/websocket v1.8.12/go.mod h1:LNVeNrXQZfe5qhS9ALED3uA+l5pPqvwXg3CKoDBB2gs= github.com/coder/websocket v1.8.13 h1:f3QZdXy7uGVz+4uCJy2nTZyM0yTBj8yANEHhqlXZ9FE= github.com/coder/websocket v1.8.13/go.mod h1:LNVeNrXQZfe5qhS9ALED3uA+l5pPqvwXg3CKoDBB2gs= github.com/coreos/go-oidc/v3 v3.11.0 h1:Ia3MxdwpSw702YW0xgfmP1GVCMA9aEFWu12XUZ3/OtI= github.com/coreos/go-oidc/v3 v3.11.0/go.mod h1:gE3LgjOgFoHi9a4ce4/tJczr0Ai2/BoDhf0r5lltWI0= +github.com/coreos/go-systemd/v22 v22.5.0/go.mod h1:Y58oyj3AT4RCenI/lSvhwexgC+NSVTIJ3seZv2GcEnc= github.com/creack/goselect v0.1.2 h1:2DNy14+JPjRBgPzAd1thbQp4BSIihxcBf0IXhQXDRa0= github.com/creack/goselect v0.1.2/go.mod h1:a/NhLweNvqIYMuxcMOuWY516Cimucms3DglDzQP3hKY= github.com/creack/pty v1.1.23 h1:4M6+isWdcStXEf15G/RbrMPOQj1dZ7HPZCGwE4kOeP0= @@ -29,12 +28,14 @@ github.com/creack/pty v1.1.23/go.mod h1:08sCNb52WyoAwi2QDyzUCTgcvVFhUzewun7wtTfv github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= -github.com/gabriel-vasile/mimetype v1.4.3 h1:in2uUcidCuFcDKtdcBxlR0rJ1+fsokWf+uqxgUFjbI0= -github.com/gabriel-vasile/mimetype v1.4.3/go.mod h1:d8uq/6HKRL6CGdk+aubisF/M5GcPfT7nKyLpA0lbSSk= -github.com/gin-contrib/sse v0.1.0 h1:Y/yl/+YNO8GZSjAhjMsSuLt29uWRFHdHYUb5lYOV9qE= -github.com/gin-contrib/sse v0.1.0/go.mod h1:RHrZQHXnP2xjPF+u1gW/2HnVO7nvIa9PG3Gm+fLHvGI= -github.com/gin-gonic/gin v1.9.1 h1:4idEAncQnU5cB7BeOkPtxjfCSye0AAm1R0RVIqJ+Jmg= -github.com/gin-gonic/gin v1.9.1/go.mod h1:hPrL7YrpYKXt5YId3A/Tnip5kqbEAP+KLuI3SUcPTeU= +github.com/gabriel-vasile/mimetype v1.4.8 h1:FfZ3gj38NjllZIeJAmMhr+qKL8Wu+nOoI3GqacKw1NM= +github.com/gabriel-vasile/mimetype v1.4.8/go.mod h1:ByKUIKGjh1ODkGM1asKUbQZOLGrPjydw3hYPU2YU9t8= +github.com/gin-contrib/logger v1.2.5 h1:qVQI4omayQecuN4zX9ZZnsOq7w9J/ZLds3J/FMn8ypM= +github.com/gin-contrib/logger v1.2.5/go.mod h1:/bj+vNMuA2xOEQ1aRHoJ1m9+uyaaXIAxQTvM2llsc6I= +github.com/gin-contrib/sse v1.0.0 h1:y3bT1mUWUxDpW4JLQg/HnTqV4rozuW4tC9eFKTxYI9E= +github.com/gin-contrib/sse v1.0.0/go.mod h1:zNuFdwarAygJBht0NTKiSi3jRf6RbqeILZ9Sp6Slhe0= +github.com/gin-gonic/gin v1.10.0 h1:nTuyha1TYqgedzytsKYqna+DfLos46nTv2ygFy86HFU= +github.com/gin-gonic/gin v1.10.0/go.mod h1:4PMNQiOhvDRa013RKVbsiNwoyezlm2rm0uX/T7kzp5Y= github.com/go-jose/go-jose/v4 v4.0.2 h1:R3l3kkBds16bO7ZFAEEcofK0MkrAJt3jlJznWZG0nvk= github.com/go-jose/go-jose/v4 v4.0.2/go.mod h1:WVf9LFMHh/QVrmqrOfqun0C45tMe3RoiKJMPvgWwLfY= github.com/go-playground/assert/v2 v2.2.0 h1:JvknZsQTYeFEAhQwI4qEt9cyV5ONwRHC+lYKSsYSR8s= @@ -43,10 +44,11 @@ github.com/go-playground/locales v0.14.1 h1:EWaQ/wswjilfKLTECiXz7Rh+3BjFhfDFKv/o github.com/go-playground/locales v0.14.1/go.mod h1:hxrqLVvrK65+Rwrd5Fc6F2O76J/NuW9t0sjnWqG1slY= github.com/go-playground/universal-translator v0.18.1 h1:Bcnm0ZwsGyWbCzImXv+pAJnYK9S473LQFuzCbDbfSFY= github.com/go-playground/universal-translator v0.18.1/go.mod h1:xekY+UJKNuX9WP91TpwSH2VMlDf28Uj24BCp08ZFTUY= -github.com/go-playground/validator/v10 v10.20.0 h1:K9ISHbSaI0lyB2eWMPJo+kOS/FBExVwjEviJTixqxL8= -github.com/go-playground/validator/v10 v10.20.0/go.mod h1:dbuPbCMFw/DrkbEynArYaCwl3amGuJotoKCe95atGMM= -github.com/goccy/go-json v0.10.2 h1:CrxCmQqYDkv1z7lO7Wbh2HN93uovUHgrECaO5ZrCXAU= -github.com/goccy/go-json v0.10.2/go.mod h1:6MelG93GURQebXPDq3khkgXZkazVtN9CRI+MGFi0w8I= +github.com/go-playground/validator/v10 v10.26.0 h1:SP05Nqhjcvz81uJaRfEV0YBSSSGMc/iMaVtFbr3Sw2k= +github.com/go-playground/validator/v10 v10.26.0/go.mod h1:I5QpIEbmr8On7W0TktmJAumgzX4CA1XNl4ZmDuVHKKo= +github.com/goccy/go-json v0.10.5 h1:Fq85nIqj+gXn/S5ahsiTlK3TmC85qgirsdTP/+DeaC4= +github.com/goccy/go-json v0.10.5/go.mod h1:oq7eo15ShAhp70Anwd5lgX2pLfOS3QCiwU/PULtXL6M= +github.com/godbus/dbus/v5 v5.0.4/go.mod h1:xhWf0FNVPg57R7Z0UbKHbJfkEywrmjJnf7w5xrFpKfA= github.com/google/go-cmp v0.6.0 h1:ofyhxvXcZhMsU5ulbFiLKl/XBFqE1GSq7atu8tAmTRI= github.com/google/go-cmp v0.6.0/go.mod h1:17dUlkBOakJ0+DkrSSNjCkIjxS6bF9zb3elmeNGIjoY= github.com/google/gofuzz v1.0.0/go.mod h1:dBl0BpW6vV/+mYPU4Po3pmUjxk6FQPldtuIdl/M65Eg= @@ -63,8 +65,8 @@ github.com/json-iterator/go v1.1.12/go.mod h1:e30LSqwooZae/UwlEbR2852Gd8hjQvJoHm github.com/klauspost/compress v1.17.11 h1:In6xLpyWOi1+C7tXUUWv2ot1QvBjxevKAaI6IXrJmUc= github.com/klauspost/compress v1.17.11/go.mod h1:pMDklpSncoRMuLFrf1W9Ss9KT+0rH90U12bZKk7uwG0= github.com/klauspost/cpuid/v2 v2.0.9/go.mod h1:FInQzS24/EEf25PyTYn52gqo7WaD8xa0213Md/qVLRg= -github.com/klauspost/cpuid/v2 v2.2.7 h1:ZWSB3igEs+d0qvnxR/ZBzXVmxkgt8DdzP6m9pfuVLDM= -github.com/klauspost/cpuid/v2 v2.2.7/go.mod h1:Lcz8mBdAVJIBVzewtcLocK12l3Y+JytZYpaMropDUws= +github.com/klauspost/cpuid/v2 v2.2.10 h1:tBs3QSyvjDyFTq3uoc/9xFpCuOsJQFNPiAhYdw2skhE= +github.com/klauspost/cpuid/v2 v2.2.10/go.mod h1:hqwkgyIinND0mEev00jJYCxPNVRVXFQeu1XKlok6oO0= github.com/knz/go-libedit v1.10.1/go.mod h1:MZTVkCWyz0oBc7JOWP3wNAzd002ZbM/5hgShxwh4x8M= github.com/kr/pretty v0.2.1/go.mod h1:ipq/a2n7PKx3OHsz4KJII5eveXtPO4qwEXGdVfWzfnI= github.com/kr/pretty v0.3.1 h1:flRD4NNwYAUpkphVc1HcthR4KEIFJ65n8Mw5qdRn3LE= @@ -78,6 +80,11 @@ github.com/kylelemons/godebug v1.1.0 h1:RPNrshWIDI6G2gRW9EHilWtl7Z6Sb1BR0xunSBf0 github.com/kylelemons/godebug v1.1.0/go.mod h1:9/0rRGxNHcop5bhtWyNeEfOS8JIWk580+fNqagV/RAw= github.com/leodido/go-urn v1.4.0 h1:WT9HwE9SGECu3lg4d/dIA+jxlljEa1/ffXKmRjqdmIQ= github.com/leodido/go-urn v1.4.0/go.mod h1:bvxc+MVxLKB4z00jd1z+Dvzr47oO32F/QSNjSBOlFxI= +github.com/mattn/go-colorable v0.1.13/go.mod h1:7S9/ev0klgBDR4GtXTXX8a3vIGJpMovkB8vQcUbaXHg= +github.com/mattn/go-colorable v0.1.14 h1:9A9LHSqF/7dyVVX6g0U9cwm9pG3kP9gSzcuIPHPsaIE= +github.com/mattn/go-colorable v0.1.14/go.mod h1:6LmQG8QLFO4G5z1gPvYEzlUgJ2wF+stgPZH1UqBm1s8= +github.com/mattn/go-isatty v0.0.16/go.mod h1:kYGgaQfpe5nmfYZH+SKPsOc2e4SrIfOl2e/yFXSvRLM= +github.com/mattn/go-isatty v0.0.19/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/mattn/go-isatty v0.0.20 h1:xfD0iDuEKnDkl03q4limB+vH+GxLEtL/jb4xVJSWWEY= github.com/mattn/go-isatty v0.0.20/go.mod h1:W+V8PltTTMOvKvAeJH7IuucS94S2C6jfK/D7dTCTo3Y= github.com/moby/sys/mountinfo v0.6.2 h1:BzJjoreD5BMFNmD9Rus6gdd1pLuecOFPt8wC+Vygl78= @@ -89,8 +96,8 @@ github.com/modern-go/reflect2 v1.0.2 h1:xBagoLtFs94CBntxluKeaWgTMpvLxC4ur3nMaC9G github.com/modern-go/reflect2 v1.0.2/go.mod h1:yWuevngMOJpCy52FWWMvUC8ws7m/LJsjYzDa0/r8luk= github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822 h1:C3w9PqII01/Oq1c1nUAm88MOHcQC9l5mIlSMApZMrHA= github.com/munnerz/goautoneg v0.0.0-20191010083416-a7dc8b61c822/go.mod h1:+n7T8mK8HuQTcFwEeznm/DIxMOiR9yIdICNftLE1DvQ= -github.com/pelletier/go-toml/v2 v2.2.2 h1:aYUidT7k73Pcl9nb2gScu7NSrKCSHIDE89b3+6Wq+LM= -github.com/pelletier/go-toml/v2 v2.2.2/go.mod h1:1t835xjRzz80PqgE6HHgN2JOsmgYu/h4qDAS4n929Rs= +github.com/pelletier/go-toml/v2 v2.2.3 h1:YmeHyLY8mFWbdkNWwpr+qIL2bEqT0o95WSdkNHvL12M= +github.com/pelletier/go-toml/v2 v2.2.3/go.mod h1:MfCQTFTvCcUyyvvwm1+G6H/jORL20Xlb6rzQu9GuUkc= github.com/pilebones/go-udev v0.9.0 h1:N1uEO/SxUwtIctc0WLU0t69JeBxIYEYnj8lT/Nabl9Q= github.com/pilebones/go-udev v0.9.0/go.mod h1:T2eI2tUSK0hA2WS5QLjXJUfQkluZQu+18Cqvem3CaXI= github.com/pion/datachannel v1.5.9 h1:LpIWAOYPyDrXtU+BW7X0Yt/vGtYxtXQ8ql7dFfYUVZA= @@ -125,6 +132,7 @@ github.com/pion/turn/v4 v4.0.0 h1:qxplo3Rxa9Yg1xXDxxH8xaqcyGUtbHYw4QSCvmFWvhM= github.com/pion/turn/v4 v4.0.0/go.mod h1:MuPDkm15nYSklKpN8vWJ9W2M0PlyQZqYt1McGuxG7mA= github.com/pion/webrtc/v4 v4.0.0 h1:x8ec7uJQPP3D1iI8ojPAiTOylPI7Fa7QgqZrhpLyqZ8= github.com/pion/webrtc/v4 v4.0.0/go.mod h1:SfNn8CcFxR6OUVjLXVslAQ3a3994JhyE3Hw1jAuqEto= +github.com/pkg/errors v0.9.1/go.mod h1:bwawxfHBFNV+L2hUp1rHADufV3IMtnDRdf1r5NINEl0= github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZbAQM= github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/prometheus/client_golang v1.21.0 h1:DIsaGmiaBkSangBgMtWdNfxbMNdku5IK6iNhrEqWvdA= @@ -139,6 +147,9 @@ github.com/psanford/httpreadat v0.1.0 h1:VleW1HS2zO7/4c7c7zNl33fO6oYACSagjJIyMIw github.com/psanford/httpreadat v0.1.0/go.mod h1:Zg7P+TlBm3bYbyHTKv/EdtSJZn3qwbPwpfZ/I9GKCRE= github.com/rogpeppe/go-internal v1.10.0 h1:TMyTOH3F/DB16zRVcYyreMH6GnZZrwQVAoYjRBZyWFQ= github.com/rogpeppe/go-internal v1.10.0/go.mod h1:UQnix2H7Ngw/k4C5ijL5+65zddjncjaFoBhdsK/akog= +github.com/rs/xid v1.6.0/go.mod h1:7XoLgs4eV+QndskICGsho+ADou8ySMSjJKDIan90Nz0= +github.com/rs/zerolog v1.34.0 h1:k43nTLIwcTVQAncfCw4KZ2VY6ukYoZaBPNOE8txlOeY= +github.com/rs/zerolog v1.34.0/go.mod h1:bJsvje4Z08ROH4Nhs5iH600c3IkWhwp44iRc54W6wYQ= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= github.com/stretchr/objx v0.4.0/go.mod h1:YvHI0jy2hoMjB+UWwv71VJQ9isScKT/TqJzVSSt89Yw= github.com/stretchr/objx v0.5.0/go.mod h1:Yh+to48EsGEfYuaHDzXPcE3xhTkx73EhmCGUpEOglKo= @@ -164,27 +175,27 @@ github.com/wlynxg/anet v0.0.5 h1:J3VJGi1gvo0JwZ/P1/Yc/8p63SoW98B5dHkYDmpgvvU= github.com/wlynxg/anet v0.0.5/go.mod h1:eay5PRQr7fIVAMbTbchTnO9gG65Hg/uYGdc7mguHxoA= go.bug.st/serial v1.6.2 h1:kn9LRX3sdm+WxWKufMlIRndwGfPWsH1/9lCWXQCasq8= go.bug.st/serial v1.6.2/go.mod h1:UABfsluHAiaNI+La2iESysd9Vetq7VRdpxvjx7CmmOE= -golang.org/x/arch v0.0.0-20210923205945-b76863e36670/go.mod h1:5om86z9Hs0C8fWVUuoMHwpExlXzs5Tkyp9hOrfG7pp8= -golang.org/x/arch v0.8.0 h1:3wRIsP3pM4yUptoR96otTUOXI367OS0+c9eeRi9doIc= -golang.org/x/arch v0.8.0/go.mod h1:FEVrYAQjsQXMVJ1nsMoVVXPZg6p2JE2mx8psSWTDQys= -golang.org/x/crypto v0.31.0 h1:ihbySMvVjLAeSH1IbfcRTkD/iNscyz8rGzjF/E5hV6U= -golang.org/x/crypto v0.31.0/go.mod h1:kDsLvtWBEx7MV9tJOj9bnXsPbxwJQ6csT/x4KIN4Ssk= -golang.org/x/net v0.33.0 h1:74SYHlV8BIgHIFC/LrYkOGIwL19eTYXQ5wc6TBuO36I= -golang.org/x/net v0.33.0/go.mod h1:HXLR5J+9DxmrqMwG9qjGCxZ+zKXxBru04zlTvWlWuN4= +golang.org/x/arch v0.15.0 h1:QtOrQd0bTUnhNVNndMpLHNWrDmYzZ2KDqSrEymqInZw= +golang.org/x/arch v0.15.0/go.mod h1:JmwW7aLIoRUKgaTzhkiEFxvcEiQGyOg9BMonBJUS7EE= +golang.org/x/crypto v0.36.0 h1:AnAEvhDddvBdpY+uR+MyHmuZzzNqXSe/GvuDeob5L34= +golang.org/x/crypto v0.36.0/go.mod h1:Y4J0ReaxCR1IMaabaSMugxJES1EpwhBHhv2bDHklZvc= +golang.org/x/net v0.38.0 h1:vRMAPTMaeGqVhG5QyLJHqNDwecKTomGeqbnfZyKlBI8= +golang.org/x/net v0.38.0/go.mod h1:ivrbrMbzFq5J41QOQh0siUuly180yBYtLp+CKbEaFx8= golang.org/x/oauth2 v0.24.0 h1:KTBBxWqUa0ykRPLtV69rRto9TLXcqYkeswu48x/gvNE= golang.org/x/oauth2 v0.24.0/go.mod h1:XYTD2NtWslqkgxebSiOHnXEap4TF09sJSc7H1sXbhtI= golang.org/x/sync v0.0.0-20201207232520-09787c993a3a/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sys v0.0.0-20220520151302-bc2c85ada10a/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.0.0-20220811171246-fbc7d0a398ab/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.2.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.5.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.6.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= golang.org/x/sys v0.10.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= -golang.org/x/sys v0.28.0 h1:Fksou7UEQUWlKvIdsqzJmUmCX3cZuD2+P3XyyzwMhlA= -golang.org/x/sys v0.28.0/go.mod h1:/VUhepiaJMQUp4+oa/7Zr1D23ma6VTLIYjOOTFZPUcA= -golang.org/x/text v0.21.0 h1:zyQAAkrwaneQ066sspRyJaG9VNi/YJ1NfzcGB3hZ/qo= -golang.org/x/text v0.21.0/go.mod h1:4IBbMaMmOPCJ8SecivzSH54+73PCFmPWxNTLm+vZkEQ= -google.golang.org/protobuf v1.36.1 h1:yBPeRvTftaleIgM3PZ/WBIZ7XM/eEYAaEyCwvyjq/gk= -google.golang.org/protobuf v1.36.1/go.mod h1:9fA7Ob0pmnwhb644+1+CVWFRbNajQ6iRojtC/QF5bRE= +golang.org/x/sys v0.12.0/go.mod h1:oPkhp1MJrh7nUepCBck5+mAzfO9JrbApNNgaTdGDITg= +golang.org/x/sys v0.32.0 h1:s77OFDvIQeibCmezSnk/q6iAfkdiQaJi4VzroCFrN20= +golang.org/x/sys v0.32.0/go.mod h1:BJP2sWEmIv4KK5OTEluFJCKSidICx8ciO85XgH3Ak8k= +golang.org/x/text v0.23.0 h1:D71I7dUrlY+VX0gQShAThNGHFxZ13dGLBHQLVl1mJlY= +golang.org/x/text v0.23.0/go.mod h1:/BLNzu4aZCJ1+kcD0DNRotWKage4q2rGVAg4o22unh4= +google.golang.org/protobuf v1.36.6 h1:z1NpPI8ku2WgiWnf+t9wTPsn6eP1L7ksHUlkfLvd9xY= +google.golang.org/protobuf v1.36.6/go.mod h1:jduwjTPXsFjZGTmRluh+L6NjiWu7pchiJ2/5YcXBHnY= gopkg.in/check.v1 v0.0.0-20161208181325-20d25e280405/go.mod h1:Co6ibVJAznAaIkqp8huTwlJQCZ016jof/cbN4VW5Yz0= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c h1:Hei/4ADfdWqJk1ZMxUNpqntNwaWcugrBjAiHlqqRiVk= gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c/go.mod h1:JHkPIbrfpd72SG/EVd6muEfDQjcINNoR0C8j2r3qZ4Q= @@ -192,4 +203,3 @@ gopkg.in/yaml.v3 v3.0.0-20200313102051-9f266ea9e77c/go.mod h1:K4uyk7z7BCEPqu6E+C gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA= gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM= nullprogram.com/x/optparse v1.0.0/go.mod h1:KdyPE+Igbe0jQUrVfMqDMeJQIJZEuyV7pjYmp6pbG50= -rsc.io/pdf v0.1.1/go.mod h1:n8OzWcQ6Sp37PL01nO98y4iUCRdTGarVfzxY20ICaU4= diff --git a/hw.go b/hw.go index 03e9d4b..02e4815 100644 --- a/hw.go +++ b/hw.go @@ -42,7 +42,7 @@ func GetDeviceID() string { deviceIDOnce.Do(func() { serial, err := extractSerialNumber() if err != nil { - logger.Warn("unknown serial number, the program likely not running on RV1106") + logger.Warn().Msg("unknown serial number, the program likely not running on RV1106") deviceID = "unknown_device_id" } else { deviceID = serial @@ -54,7 +54,7 @@ func GetDeviceID() string { func runWatchdog() { file, err := os.OpenFile("/dev/watchdog", os.O_WRONLY, 0) if err != nil { - logger.Warnf("unable to open /dev/watchdog: %v, skipping watchdog reset", err) + logger.Warn().Err(err).Msg("unable to open /dev/watchdog, skipping watchdog reset") return } defer file.Close() @@ -65,13 +65,13 @@ func runWatchdog() { case <-ticker.C: _, err = file.Write([]byte{0}) if err != nil { - logger.Errorf("error writing to /dev/watchdog, system may reboot: %v", err) + logger.Warn().Err(err).Msg("error writing to /dev/watchdog, system may reboot") } case <-appCtx.Done(): //disarm watchdog with magic value _, err := file.Write([]byte("V")) if err != nil { - logger.Errorf("failed to disarm watchdog, system may reboot: %v", err) + logger.Warn().Err(err).Msg("failed to disarm watchdog, system may reboot") } return } diff --git a/internal/usbgadget/config.go b/internal/usbgadget/config.go index 5cc3ed2..b73d392 100644 --- a/internal/usbgadget/config.go +++ b/internal/usbgadget/config.go @@ -84,7 +84,7 @@ func (u *UsbGadget) isGadgetConfigItemEnabled(itemKey string) bool { func (u *UsbGadget) loadGadgetConfig() { if u.customConfig.isEmpty { - u.log.Trace("using default gadget config") + u.log.Trace().Msg("using default gadget config") return } @@ -163,26 +163,26 @@ func (u *UsbGadget) Init() error { udcs := getUdcs() if len(udcs) < 1 { - u.log.Error("no udc found, skipping USB stack init") + u.log.Error().Msg("no udc found, skipping USB stack init") return nil } u.udc = udcs[0] _, err := os.Stat(u.kvmGadgetPath) if err == nil { - u.log.Info("usb gadget already exists") + u.log.Info().Msg("usb gadget already exists") } if err := mountConfigFS(); err != nil { - u.log.Errorf("failed to mount configfs: %v, usb stack might not function properly", err) + u.log.Error().Err(err).Msg("failed to mount configfs, usb stack might not function properly") } if err := os.MkdirAll(u.configC1Path, 0755); err != nil { - u.log.Errorf("failed to create config path: %v", err) + u.log.Error().Err(err).Msg("failed to create config path") } if err := u.writeGadgetConfig(); err != nil { - u.log.Errorf("failed to start gadget: %v", err) + u.log.Error().Err(err).Msg("failed to start gadget") } return nil @@ -195,7 +195,7 @@ func (u *UsbGadget) UpdateGadgetConfig() error { u.loadGadgetConfig() if err := u.writeGadgetConfig(); err != nil { - u.log.Errorf("failed to update gadget: %v", err) + u.log.Error().Err(err).Msg("failed to update gadget") } return nil @@ -221,21 +221,21 @@ func (u *UsbGadget) writeGadgetConfig() error { return err } - u.log.Tracef("writing gadget config") + u.log.Trace().Msg("writing gadget config") for _, val := range u.getOrderedConfigItems() { key := val.key item := val.item // check if the item is enabled in the config if !u.isGadgetConfigItemEnabled(key) { - u.log.Tracef("disabling gadget config: %s", key) + u.log.Trace().Str("key", key).Msg("disabling gadget config") err = u.disableGadgetItemConfig(item) if err != nil { return err } continue } - u.log.Tracef("writing gadget config: %s", key) + u.log.Trace().Str("key", key).Msg("writing gadget config") err = u.writeGadgetItemConfig(item) if err != nil { return err @@ -243,12 +243,12 @@ func (u *UsbGadget) writeGadgetConfig() error { } if err = u.writeUDC(); err != nil { - u.log.Errorf("failed to write UDC: %v", err) + u.log.Error().Err(err).Msg("failed to write UDC") return err } if err = u.rebindUsb(true); err != nil { - u.log.Infof("failed to rebind usb: %v", err) + u.log.Info().Err(err).Msg("failed to rebind usb") } return nil @@ -263,7 +263,7 @@ func (u *UsbGadget) disableGadgetItemConfig(item gadgetConfigItem) error { configPath := joinPath(u.configC1Path, item.configPath) if _, err := os.Lstat(configPath); os.IsNotExist(err) { - u.log.Tracef("symlink %s does not exist", item.configPath) + u.log.Trace().Str("path", configPath).Msg("symlink does not exist") return nil } @@ -315,7 +315,7 @@ func (u *UsbGadget) writeGadgetItemConfig(item gadgetConfigItem) error { // create symlink if configPath is set if item.configPath != nil && item.configAttrs == nil { configPath := joinPath(u.configC1Path, item.configPath) - u.log.Tracef("Creating symlink from %s to %s", configPath, gadgetItemPath) + u.log.Trace().Str("source", configPath).Str("target", gadgetItemPath).Msg("creating symlink") if err := ensureSymlink(configPath, gadgetItemPath); err != nil { return err } diff --git a/internal/usbgadget/hid_keyboard.go b/internal/usbgadget/hid_keyboard.go index 030f7af..de007e4 100644 --- a/internal/usbgadget/hid_keyboard.go +++ b/internal/usbgadget/hid_keyboard.go @@ -65,7 +65,7 @@ func (u *UsbGadget) keyboardWriteHidFile(data []byte) error { _, err := u.keyboardHidFile.Write(data) if err != nil { - u.log.Errorf("failed to write to hidg0: %w", err) + u.log.Error().Err(err).Msg("failed to write to hidg0") u.keyboardHidFile.Close() u.keyboardHidFile = nil return err diff --git a/internal/usbgadget/hid_mouse_absolute.go b/internal/usbgadget/hid_mouse_absolute.go index c59b591..de77b1e 100644 --- a/internal/usbgadget/hid_mouse_absolute.go +++ b/internal/usbgadget/hid_mouse_absolute.go @@ -73,7 +73,7 @@ func (u *UsbGadget) absMouseWriteHidFile(data []byte) error { _, err := u.absMouseHidFile.Write(data) if err != nil { - u.log.Errorf("failed to write to hidg1: %w", err) + u.log.Error().Err(err).Msg("failed to write to hidg1") u.absMouseHidFile.Close() u.absMouseHidFile = nil return err diff --git a/internal/usbgadget/hid_mouse_relative.go b/internal/usbgadget/hid_mouse_relative.go index df844dc..af2d028 100644 --- a/internal/usbgadget/hid_mouse_relative.go +++ b/internal/usbgadget/hid_mouse_relative.go @@ -65,7 +65,7 @@ func (u *UsbGadget) relMouseWriteHidFile(data []byte) error { _, err := u.relMouseHidFile.Write(data) if err != nil { - u.log.Errorf("failed to write to hidg2: %w", err) + u.log.Error().Err(err).Msg("failed to write to hidg2") u.relMouseHidFile.Close() u.relMouseHidFile = nil return err diff --git a/internal/usbgadget/udc.go b/internal/usbgadget/udc.go index 6316b83..84dfbe4 100644 --- a/internal/usbgadget/udc.go +++ b/internal/usbgadget/udc.go @@ -38,7 +38,7 @@ func rebindUsb(udc string, ignoreUnbindError bool) error { } func (u *UsbGadget) rebindUsb(ignoreUnbindError bool) error { - u.log.Infof("rebinding USB gadget to UDC %s", u.udc) + u.log.Info().Str("udc", u.udc).Msg("rebinding USB gadget to UDC") return rebindUsb(u.udc, ignoreUnbindError) } @@ -53,7 +53,7 @@ func (u *UsbGadget) RebindUsb(ignoreUnbindError bool) error { func (u *UsbGadget) writeUDC() error { path := path.Join(u.kvmGadgetPath, "UDC") - u.log.Tracef("writing UDC %s to %s", u.udc, path) + u.log.Trace().Str("udc", u.udc).Str("path", path).Msg("writing UDC") err := u.writeIfDifferent(path, []byte(u.udc), 0644) if err != nil { return fmt.Errorf("failed to write UDC: %w", err) @@ -70,7 +70,7 @@ func (u *UsbGadget) GetUsbState() (state string) { if os.IsNotExist(err) { return "not attached" } else { - u.log.Tracef("failed to read usb state: %v", err) + u.log.Trace().Err(err).Msg("failed to read usb state") } return "unknown" } diff --git a/internal/usbgadget/usbgadget.go b/internal/usbgadget/usbgadget.go index 9fc34d5..1dff2f3 100644 --- a/internal/usbgadget/usbgadget.go +++ b/internal/usbgadget/usbgadget.go @@ -8,7 +8,7 @@ import ( "sync" "time" - "github.com/pion/logging" + "github.com/rs/zerolog" ) // Devices is a struct that represents the USB devices that can be enabled on a USB gadget. @@ -63,16 +63,16 @@ type UsbGadget struct { lastUserInput time.Time - log logging.LeveledLogger + log *zerolog.Logger } const configFSPath = "/sys/kernel/config" const gadgetPath = "/sys/kernel/config/usb_gadget" -var defaultLogger = logging.NewDefaultLoggerFactory().NewLogger("usbgadget") +var defaultLogger = zerolog.New(os.Stdout).Level(zerolog.InfoLevel) // NewUsbGadget creates a new UsbGadget. -func NewUsbGadget(name string, enabledDevices *Devices, config *Config, logger *logging.LeveledLogger) *UsbGadget { +func NewUsbGadget(name string, enabledDevices *Devices, config *Config, logger *zerolog.Logger) *UsbGadget { if logger == nil { logger = &defaultLogger } @@ -97,12 +97,12 @@ func NewUsbGadget(name string, enabledDevices *Devices, config *Config, logger * relMouseLock: sync.Mutex{}, enabledDevices: *enabledDevices, lastUserInput: time.Now(), - log: *logger, + log: logger, absMouseAccumulatedWheelY: 0, } if err := g.Init(); err != nil { - g.log.Errorf("failed to init USB gadget: %v", err) + logger.Error().Err(err).Msg("failed to init USB gadget") return nil } diff --git a/internal/usbgadget/utils.go b/internal/usbgadget/utils.go index 3f0adda..0e796c8 100644 --- a/internal/usbgadget/utils.go +++ b/internal/usbgadget/utils.go @@ -45,18 +45,18 @@ func (u *UsbGadget) writeIfDifferent(filePath string, content []byte, permMode o oldContent, err := os.ReadFile(filePath) if err == nil { if bytes.Equal(oldContent, content) { - u.log.Tracef("skipping writing to %s as it already has the correct content", filePath) + u.log.Trace().Str("path", filePath).Msg("skipping writing to as it already has the correct content") return nil } if len(oldContent) == len(content)+1 && bytes.Equal(oldContent[:len(content)], content) && oldContent[len(content)] == 10 { - u.log.Tracef("skipping writing to %s as it already has the correct content", filePath) + u.log.Trace().Str("path", filePath).Msg("skipping writing to as it already has the correct content") return nil } - u.log.Tracef("writing to %s as it has different content old%v new%v", filePath, oldContent, content) + u.log.Trace().Str("path", filePath).Bytes("old", oldContent).Bytes("new", content).Msg("writing to as it has different content") } } return os.WriteFile(filePath, content, permMode) diff --git a/jiggler.go b/jiggler.go index daec192..94f7d15 100644 --- a/jiggler.go +++ b/jiggler.go @@ -28,11 +28,11 @@ func runJiggler() { //TODO: change to rel mouse err := rpcAbsMouseReport(1, 1, 0) if err != nil { - logger.Warnf("Failed to jiggle mouse: %v", err) + logger.Warn().Err(err).Msg("Failed to jiggle mouse") } err = rpcAbsMouseReport(0, 0, 0) if err != nil { - logger.Warnf("Failed to reset mouse position: %v", err) + logger.Warn().Err(err).Msg("Failed to reset mouse position") } } } diff --git a/jsonrpc.go b/jsonrpc.go index e5deb49..de29e08 100644 --- a/jsonrpc.go +++ b/jsonrpc.go @@ -47,12 +47,12 @@ type BacklightSettings struct { func writeJSONRPCResponse(response JSONRPCResponse, session *Session) { responseBytes, err := json.Marshal(response) if err != nil { - logger.Warnf("Error marshalling JSONRPC response: %v", err) + logger.Warn().Err(err).Msg("Error marshalling JSONRPC response") return } err = session.RPCChannel.SendText(string(responseBytes)) if err != nil { - logger.Warnf("Error sending JSONRPC response: %v", err) + logger.Warn().Err(err).Msg("Error sending JSONRPC response") return } } @@ -65,16 +65,16 @@ func writeJSONRPCEvent(event string, params interface{}, session *Session) { } requestBytes, err := json.Marshal(request) if err != nil { - logger.Warnf("Error marshalling JSONRPC event: %v", err) + logger.Warn().Err(err).Msg("Error marshalling JSONRPC event") return } if session == nil || session.RPCChannel == nil { - logger.Info("RPC channel not available") + logger.Info().Msg("RPC channel not available") return } err = session.RPCChannel.SendText(string(requestBytes)) if err != nil { - logger.Warnf("Error sending JSONRPC event: %v", err) + logger.Warn().Err(err).Msg("Error sending JSONRPC event") return } } @@ -148,7 +148,7 @@ func rpcGetStreamQualityFactor() (float64, error) { } func rpcSetStreamQualityFactor(factor float64) error { - logger.Infof("Setting stream quality factor to: %f", factor) + logger.Info().Float64("factor", factor).Msg("Setting stream quality factor") var _, err = CallCtrlAction("set_video_quality_factor", map[string]interface{}{"quality_factor": factor}) if err != nil { return err @@ -184,10 +184,10 @@ func rpcGetEDID() (string, error) { func rpcSetEDID(edid string) error { if edid == "" { - logger.Info("Restoring EDID to default") + logger.Info().Msg("Restoring EDID to default") edid = "00ffffffffffff0052620188008888881c150103800000780a0dc9a05747982712484c00000001010101010101010101010101010101023a801871382d40582c4500c48e2100001e011d007251d01e206e285500c48e2100001e000000fc00543734392d6648443732300a20000000fd00147801ff1d000a202020202020017b" } else { - logger.Infof("Setting EDID to: %s", edid) + logger.Info().Str("edid", edid).Msg("Setting EDID") } _, err := CallCtrlAction("set_edid", map[string]interface{}{"edid": edid}) if err != nil { @@ -227,7 +227,7 @@ func rpcTryUpdate() error { go func() { err := TryUpdate(context.Background(), GetDeviceID(), includePreRelease) if err != nil { - logger.Warnf("failed to try update: %v", err) + logger.Warn().Err(err).Msg("failed to try update") } }() return nil @@ -257,7 +257,7 @@ func rpcSetBacklightSettings(params BacklightSettings) error { return fmt.Errorf("failed to save config: %w", err) } - logger.Infof("rpc: display: settings applied, max_brightness: %d, dim after: %ds, off after: %ds", config.DisplayMaxBrightness, config.DisplayDimAfterSec, config.DisplayOffAfterSec) + logger.Info().Int("max_brightness", config.DisplayMaxBrightness).Int("dim_after", config.DisplayDimAfterSec).Int("off_after", config.DisplayOffAfterSec).Msg("rpc: display: settings applied") // If the device started up with auto-dim and/or auto-off set to zero, the display init // method will not have started the tickers. So in case that has changed, attempt to start the tickers now. @@ -318,7 +318,7 @@ func rpcSetDevModeState(enabled bool) error { return fmt.Errorf("failed to create devmode file: %w", err) } } else { - logger.Debug("dev mode already enabled") + logger.Debug().Msg("dev mode already enabled") return nil } } else { @@ -327,7 +327,7 @@ func rpcSetDevModeState(enabled bool) error { return fmt.Errorf("failed to remove devmode file: %w", err) } } else if os.IsNotExist(err) { - logger.Debug("dev mode already disabled") + logger.Debug().Msg("dev mode already disabled") return nil } else { return fmt.Errorf("error checking dev mode file: %w", err) @@ -337,7 +337,7 @@ func rpcSetDevModeState(enabled bool) error { cmd := exec.Command("dropbear.sh") output, err := cmd.CombinedOutput() if err != nil { - logger.Warnf("Failed to start/stop SSH: %v, %v", err, output) + logger.Warn().Err(err).Bytes("output", output).Msg("Failed to start/stop SSH") return fmt.Errorf("failed to start/stop SSH, you may need to reboot for changes to take effect") } @@ -478,23 +478,23 @@ type RPCHandler struct { } func rpcSetMassStorageMode(mode string) (string, error) { - logger.Infof("[jsonrpc.go:rpcSetMassStorageMode] Setting mass storage mode to: %s", mode) + logger.Info().Str("mode", mode).Msg("Setting mass storage mode") var cdrom bool if mode == "cdrom" { cdrom = true } else if mode != "file" { - logger.Infof("[jsonrpc.go:rpcSetMassStorageMode] Invalid mode provided: %s", mode) + logger.Info().Str("mode", mode).Msg("Invalid mode provided") return "", fmt.Errorf("invalid mode: %s", mode) } - logger.Infof("[jsonrpc.go:rpcSetMassStorageMode] Setting mass storage mode to: %s", mode) + logger.Info().Str("mode", mode).Msg("Setting mass storage mode") err := setMassStorageMode(cdrom) if err != nil { return "", fmt.Errorf("failed to set mass storage mode: %w", err) } - logger.Infof("[jsonrpc.go:rpcSetMassStorageMode] Mass storage mode set to %s", mode) + logger.Info().Str("mode", mode).Msg("Mass storage mode set") // Get the updated mode after setting return rpcGetMassStorageMode() @@ -563,7 +563,7 @@ func rpcResetConfig() error { return fmt.Errorf("failed to reset config: %w", err) } - logger.Info("Configuration reset to default") + logger.Info().Msg("Configuration reset to default") return nil } @@ -579,7 +579,7 @@ func rpcGetDCPowerState() (DCPowerState, error) { } func rpcSetDCPowerState(enabled bool) error { - logger.Infof("[jsonrpc.go:rpcSetDCPowerState] Setting DC power state to: %v", enabled) + logger.Info().Bool("enabled", enabled).Msg("Setting DC power state") err := setDCPowerState(enabled) if err != nil { return fmt.Errorf("failed to set DC power state: %w", err) @@ -613,16 +613,16 @@ func rpcSetActiveExtension(extensionId string) error { } func rpcSetATXPowerAction(action string) error { - logger.Debugf("[jsonrpc.go:rpcSetATXPowerAction] Executing ATX power action: %s", action) + logger.Debug().Str("action", action).Msg("Executing ATX power action") switch action { case "power-short": - logger.Debug("[jsonrpc.go:rpcSetATXPowerAction] Simulating short power button press") + logger.Debug().Msg("Simulating short power button press") return pressATXPowerButton(200 * time.Millisecond) case "power-long": - logger.Debug("[jsonrpc.go:rpcSetATXPowerAction] Simulating long power button press") + logger.Debug().Msg("Simulating long power button press") return pressATXPowerButton(5 * time.Second) case "reset": - logger.Debug("[jsonrpc.go:rpcSetATXPowerAction] Simulating reset button press") + logger.Debug().Msg("Simulating reset button press") return pressATXResetButton(200 * time.Millisecond) default: return fmt.Errorf("invalid action: %s", action) diff --git a/log.go b/log.go index 0d36c0d..6824a3f 100644 --- a/log.go +++ b/log.go @@ -1,9 +1,169 @@ package kvm -import "github.com/pion/logging" +import ( + "fmt" + "io" + "os" + "strings" + "sync" + "time" -// we use logging framework from pion -// ref: https://github.com/pion/webrtc/wiki/Debugging-WebRTC -var logger = logging.NewDefaultLoggerFactory().NewLogger("jetkvm") -var cloudLogger = logging.NewDefaultLoggerFactory().NewLogger("cloud") -var websocketLogger = logging.NewDefaultLoggerFactory().NewLogger("websocket") + "github.com/pion/logging" + "github.com/rs/zerolog" +) + +var ( + defaultLogOutput io.Writer = zerolog.ConsoleWriter{ + Out: os.Stdout, + TimeFormat: time.RFC3339, + PartsOrder: []string{"time", "level", "scope", "component", "message"}, + FieldsExclude: []string{"scope", "component"}, + FormatPartValueByName: func(value interface{}, name string) string { + val := fmt.Sprintf("%s", value) + if name == "component" { + if value == nil { + return "-" + } + } + return val + }, + } + defaultLogLevel = zerolog.ErrorLevel + rootLogger = zerolog.New(defaultLogOutput).With(). + Str("scope", "jetkvm"). + Timestamp(). + Stack(). + Logger() +) + +var ( + scopeLevels map[string]zerolog.Level + scopeLevelMutex = sync.Mutex{} +) + +var ( + logger = getLogger("jetkvm") + cloudLogger = getLogger("cloud") + websocketLogger = getLogger("websocket") + nativeLogger = getLogger("native") + ntpLogger = getLogger("ntp") + displayLogger = getLogger("display") + usbLogger = getLogger("usb") + ginLogger = getLogger("gin") +) + +func updateLogLevel() { + scopeLevelMutex.Lock() + defer scopeLevelMutex.Unlock() + + logLevels := map[string]zerolog.Level{ + "DISABLE": zerolog.Disabled, + "NOLEVEL": zerolog.NoLevel, + "PANIC": zerolog.PanicLevel, + "FATAL": zerolog.FatalLevel, + "ERROR": zerolog.ErrorLevel, + "WARN": zerolog.WarnLevel, + "INFO": zerolog.InfoLevel, + "DEBUG": zerolog.DebugLevel, + "TRACE": zerolog.TraceLevel, + } + + scopeLevels = make(map[string]zerolog.Level) + + for name, level := range logLevels { + env := os.Getenv(fmt.Sprintf("JETKVM_LOG_%s", name)) + + if env == "" { + env = os.Getenv(fmt.Sprintf("PION_LOG_%s", name)) + } + + if env == "" { + env = os.Getenv(fmt.Sprintf("PIONS_LOG_%s", name)) + } + + if env == "" { + continue + } + + if strings.ToLower(env) == "all" { + if defaultLogLevel > level { + defaultLogLevel = level + } + + continue + } + + scopes := strings.Split(strings.ToLower(env), ",") + for _, scope := range scopes { + scopeLevels[scope] = level + } + } +} + +func getLogger(scope string) zerolog.Logger { + if scopeLevels == nil { + updateLogLevel() + } + + l := rootLogger.With().Str("component", scope).Logger() + + // if the scope is not in the map, use the default level from the root logger + if level, ok := scopeLevels[scope]; ok { + return l.Level(level) + } + + return l.Level(defaultLogLevel) +} + +type pionLogger struct { + logger *zerolog.Logger +} + +// Print all messages except trace. +func (c pionLogger) Trace(msg string) { + c.logger.Trace().Msg(msg) +} +func (c pionLogger) Tracef(format string, args ...interface{}) { + c.logger.Trace().Msgf(format, args...) +} + +func (c pionLogger) Debug(msg string) { + c.logger.Debug().Msg(msg) +} +func (c pionLogger) Debugf(format string, args ...interface{}) { + c.logger.Debug().Msgf(format, args...) +} +func (c pionLogger) Info(msg string) { + c.logger.Info().Msg(msg) +} +func (c pionLogger) Infof(format string, args ...interface{}) { + c.logger.Info().Msgf(format, args...) +} +func (c pionLogger) Warn(msg string) { + c.logger.Warn().Msg(msg) +} +func (c pionLogger) Warnf(format string, args ...interface{}) { + c.logger.Warn().Msgf(format, args...) +} +func (c pionLogger) Error(msg string) { + c.logger.Error().Msg(msg) +} +func (c pionLogger) Errorf(format string, args ...interface{}) { + c.logger.Error().Msgf(format, args...) +} + +// customLoggerFactory satisfies the interface logging.LoggerFactory +// This allows us to create different loggers per subsystem. So we can +// add custom behavior. +type pionLoggerFactory struct{} + +func (c pionLoggerFactory) NewLogger(subsystem string) logging.LeveledLogger { + logger := getLogger(subsystem).With(). + Str("scope", "pion"). + Str("component", subsystem). + Logger() + + return pionLogger{logger: &logger} +} + +var defaultLoggerFactory = &pionLoggerFactory{} diff --git a/main.go b/main.go index aeb3d85..98748c7 100644 --- a/main.go +++ b/main.go @@ -17,17 +17,17 @@ func Main() { var cancel context.CancelFunc appCtx, cancel = context.WithCancel(context.Background()) defer cancel() - logger.Info("Starting JetKvm") + logger.Info().Msg("Starting JetKvm") go runWatchdog() go confirmCurrentSystem() http.DefaultClient.Timeout = 1 * time.Minute LoadConfig() - logger.Debug("config loaded") + logger.Debug().Msg("config loaded") err := rootcerts.UpdateDefaultTransport() if err != nil { - logger.Errorf("failed to load CA certs: %v", err) + logger.Warn().Err(err).Msg("failed to load CA certs") } go TimeSyncLoop() @@ -40,7 +40,7 @@ func Main() { go func() { err = ExtractAndRunNativeBin() if err != nil { - logger.Errorf("failed to extract and run native bin: %v", err) + logger.Warn().Err(err).Msg("failed to extract and run native bin") //TODO: prepare an error message screen buffer to show on kvm screen } }() @@ -50,19 +50,19 @@ func Main() { go func() { time.Sleep(15 * time.Minute) for { - logger.Debugf("UPDATING - Auto update enabled: %v", config.AutoUpdateEnabled) + logger.Debug().Bool("auto_update_enabled", config.AutoUpdateEnabled).Msg("UPDATING") if !config.AutoUpdateEnabled { return } if currentSession != nil { - logger.Debugf("skipping update since a session is active") + logger.Debug().Msg("skipping update since a session is active") time.Sleep(1 * time.Minute) continue } includePreRelease := config.IncludePreRelease err = TryUpdate(context.Background(), GetDeviceID(), includePreRelease) if err != nil { - logger.Errorf("failed to auto update: %v", err) + logger.Warn().Err(err).Msg("failed to auto update") } time.Sleep(1 * time.Hour) } @@ -79,7 +79,7 @@ func Main() { sigs := make(chan os.Signal, 1) signal.Notify(sigs, syscall.SIGINT, syscall.SIGTERM) <-sigs - logger.Info("JetKVM Shutting Down") + logger.Info().Msg("JetKVM Shutting Down") //if fuseServer != nil { // err := setMassStorageImage(" ") // if err != nil { diff --git a/native.go b/native.go index 8960304..630093b 100644 --- a/native.go +++ b/native.go @@ -13,6 +13,7 @@ import ( "time" "github.com/jetkvm/kvm/resource" + "github.com/rs/zerolog" "github.com/pion/webrtc/v4/pkg/media" ) @@ -34,6 +35,19 @@ type CtrlResponse struct { Data json.RawMessage `json:"data,omitempty"` } +type nativeOutput struct { + mu *sync.Mutex + logger *zerolog.Event +} + +func (w *nativeOutput) Write(p []byte) (n int, err error) { + w.mu.Lock() + defer w.mu.Unlock() + + w.logger.Msg(string(p)) + return len(p), nil +} + type EventHandler func(event CtrlResponse) var seq int32 = 1 @@ -61,7 +75,7 @@ func CallCtrlAction(action string, params map[string]interface{}) (*CtrlResponse return nil, fmt.Errorf("error marshaling ctrl action: %w", err) } - logger.Infof("sending ctrl action: %s", string(jsonData)) + nativeLogger.Info().Str("action", ctrlAction.Action).Msg("sending ctrl action") err = WriteCtrlMessage(jsonData) if err != nil { @@ -104,28 +118,28 @@ func StartNativeSocketServer(socketPath string, handleClient func(net.Conn), isC // Remove the socket file if it already exists if _, err := os.Stat(socketPath); err == nil { if err := os.Remove(socketPath); err != nil { - logger.Errorf("Failed to remove existing socket file %s: %v", socketPath, err) + nativeLogger.Warn().Err(err).Str("socket_path", socketPath).Msg("Failed to remove existing socket file") os.Exit(1) } } listener, err := net.Listen("unixpacket", socketPath) if err != nil { - logger.Errorf("Failed to start server on %s: %v", socketPath, err) + nativeLogger.Warn().Err(err).Str("socket_path", socketPath).Msg("Failed to start server") os.Exit(1) } - logger.Infof("Server listening on %s", socketPath) + nativeLogger.Info().Str("socket_path", socketPath).Msg("Server listening") go func() { conn, err := listener.Accept() listener.Close() if err != nil { - logger.Errorf("failed to accept sock: %v", err) + nativeLogger.Warn().Err(err).Str("socket_path", socketPath).Msg("failed to accept sock") } if isCtrl { close(ctrlClientConnected) - logger.Debug("first native ctrl socket client connected") + nativeLogger.Debug().Msg("first native ctrl socket client connected") } handleClient(conn) }() @@ -135,20 +149,20 @@ func StartNativeSocketServer(socketPath string, handleClient func(net.Conn), isC func StartNativeCtrlSocketServer() { nativeCtrlSocketListener = StartNativeSocketServer("/var/run/jetkvm_ctrl.sock", handleCtrlClient, true) - logger.Debug("native app ctrl sock started") + nativeLogger.Debug().Msg("native app ctrl sock started") } func StartNativeVideoSocketServer() { nativeVideoSocketListener = StartNativeSocketServer("/var/run/jetkvm_video.sock", handleVideoClient, false) - logger.Debug("native app video sock started") + nativeLogger.Debug().Msg("native app video sock started") } func handleCtrlClient(conn net.Conn) { defer conn.Close() - logger.Debug("native socket client connected") + nativeLogger.Debug().Msg("native socket client connected") if ctrlSocketConn != nil { - logger.Debugf("closing existing native socket connection") + nativeLogger.Debug().Msg("closing existing native socket connection") ctrlSocketConn.Close() } @@ -161,17 +175,19 @@ func handleCtrlClient(conn net.Conn) { for { n, err := conn.Read(readBuf) if err != nil { - logger.Errorf("error reading from ctrl sock: %v", err) + nativeLogger.Warn().Err(err).Msg("error reading from ctrl sock") break } readMsg := string(readBuf[:n]) - logger.Tracef("ctrl sock msg: %v", readMsg) + ctrlResp := CtrlResponse{} err = json.Unmarshal([]byte(readMsg), &ctrlResp) if err != nil { - logger.Warnf("error parsing ctrl sock msg: %v", err) + nativeLogger.Warn().Err(err).Str("data", readMsg).Msg("error parsing ctrl sock msg") continue } + nativeLogger.Trace().Interface("data", ctrlResp).Msg("ctrl sock msg") + if ctrlResp.Seq != 0 { responseChan, ok := ongoingRequests[ctrlResp.Seq] if ok { @@ -184,20 +200,20 @@ func handleCtrlClient(conn net.Conn) { } } - logger.Debug("ctrl sock disconnected") + nativeLogger.Debug().Msg("ctrl sock disconnected") } func handleVideoClient(conn net.Conn) { defer conn.Close() - logger.Infof("Native video socket client connected: %v", conn.RemoteAddr()) + nativeLogger.Info().Str("addr", conn.RemoteAddr().String()).Msg("Native video socket client connected") inboundPacket := make([]byte, maxFrameSize) lastFrame := time.Now() for { n, err := conn.Read(inboundPacket) if err != nil { - logger.Warnf("error during read: %v", err) + nativeLogger.Warn().Err(err).Msg("error during read") return } now := time.Now() @@ -206,7 +222,7 @@ func handleVideoClient(conn net.Conn) { if currentSession != nil { err := currentSession.VideoTrack.WriteSample(media.Sample{Data: inboundPacket[:n], Duration: sinceLastFrame}) if err != nil { - logger.Warnf("error writing sample: %v", err) + nativeLogger.Warn().Err(err).Msg("error writing sample") } } } @@ -225,9 +241,19 @@ func ExtractAndRunNativeBin() error { // Run the binary in the background cmd := exec.Command(binaryPath) + nativeOutputLock := sync.Mutex{} + nativeStdout := &nativeOutput{ + mu: &nativeOutputLock, + logger: nativeLogger.Info().Str("pipe", "stdout"), + } + nativeStderr := &nativeOutput{ + mu: &nativeOutputLock, + logger: nativeLogger.Info().Str("pipe", "stderr"), + } + // Redirect stdout and stderr to the current process - cmd.Stdout = os.Stdout - cmd.Stderr = os.Stderr + cmd.Stdout = nativeStdout + cmd.Stderr = nativeStderr // Set the process group ID so we can kill the process and its children when this process exits cmd.SysProcAttr = &syscall.SysProcAttr{ @@ -243,28 +269,28 @@ func ExtractAndRunNativeBin() error { //TODO: add auto restart go func() { <-appCtx.Done() - logger.Infof("killing process PID: %d", cmd.Process.Pid) + nativeLogger.Info().Int("pid", cmd.Process.Pid).Msg("killing process") err := cmd.Process.Kill() if err != nil { - logger.Errorf("failed to kill process: %v", err) + nativeLogger.Warn().Err(err).Msg("failed to kill process") return } }() - logger.Infof("Binary started with PID: %d", cmd.Process.Pid) + nativeLogger.Info().Int("pid", cmd.Process.Pid).Msg("Binary started") return nil } func shouldOverwrite(destPath string, srcHash []byte) bool { if srcHash == nil { - logger.Debug("error reading embedded jetkvm_native.sha256, doing overwriting") + nativeLogger.Debug().Msg("error reading embedded jetkvm_native.sha256, doing overwriting") return true } dstHash, err := os.ReadFile(destPath + ".sha256") if err != nil { - logger.Debug("error reading existing jetkvm_native.sha256, doing overwriting") + nativeLogger.Debug().Msg("error reading existing jetkvm_native.sha256, doing overwriting") return true } @@ -280,13 +306,13 @@ func ensureBinaryUpdated(destPath string) error { srcHash, err := resource.ResourceFS.ReadFile("jetkvm_native.sha256") if err != nil { - logger.Debug("error reading embedded jetkvm_native.sha256, proceeding with update") + nativeLogger.Debug().Msg("error reading embedded jetkvm_native.sha256, proceeding with update") srcHash = nil } _, err = os.Stat(destPath) if shouldOverwrite(destPath, srcHash) || err != nil { - logger.Info("writing jetkvm_native") + nativeLogger.Info().Msg("writing jetkvm_native") _ = os.Remove(destPath) destFile, err := os.OpenFile(destPath, os.O_CREATE|os.O_RDWR, 0755) if err != nil { @@ -303,7 +329,7 @@ func ensureBinaryUpdated(destPath string) error { return err } } - logger.Info("jetkvm_native updated") + nativeLogger.Info().Msg("jetkvm_native updated") } return nil @@ -313,10 +339,10 @@ func ensureBinaryUpdated(destPath string) error { // Called after successful connection to jetkvm_native. func restoreHdmiEdid() { if config.EdidString != "" { - logger.Infof("Restoring HDMI EDID to %v", config.EdidString) + nativeLogger.Info().Str("edid", config.EdidString).Msg("Restoring HDMI EDID") _, err := CallCtrlAction("set_edid", map[string]interface{}{"edid": config.EdidString}) if err != nil { - logger.Errorf("Failed to restore HDMI EDID: %v", err) + nativeLogger.Warn().Err(err).Msg("Failed to restore HDMI EDID") } } } diff --git a/network.go b/network.go index 66b8616..4051c06 100644 --- a/network.go +++ b/network.go @@ -56,14 +56,14 @@ func setDhcpClientState(active bool) { cmd := exec.Command("/usr/bin/killall", signal, "udhcpc") if err := cmd.Run(); err != nil { - logger.Warnf("network: setDhcpClientState: failed to change udhcpc state: %s", err) + logger.Warn().Err(err).Msg("network: setDhcpClientState: failed to change udhcpc state") } } func checkNetworkState() { iface, err := netlink.LinkByName(NetIfName) if err != nil { - logger.Warnf("failed to get [%s] interface: %v", NetIfName, err) + logger.Warn().Err(err).Str("interface", NetIfName).Msg("failed to get interface") return } @@ -76,7 +76,7 @@ func checkNetworkState() { addrs, err := netlink.AddrList(iface, nl.FAMILY_ALL) if err != nil { - logger.Warnf("failed to get addresses for [%s]: %v", NetIfName, err) + logger.Warn().Err(err).Str("interface", NetIfName).Msg("failed to get addresses") } // If the link is going down, put udhcpc into idle mode. @@ -89,10 +89,10 @@ func checkNetworkState() { if addr.IP.To4() != nil { if !newState.Up && networkState.Up { // If the network is going down, remove all IPv4 addresses from the interface. - logger.Infof("network: state transitioned to down, removing IPv4 address %s", addr.IP.String()) + logger.Info().Str("address", addr.IP.String()).Msg("network: state transitioned to down, removing IPv4 address") err := netlink.AddrDel(iface, &addr) if err != nil { - logger.Warnf("network: failed to delete %s", addr.IP.String()) + logger.Warn().Err(err).Str("address", addr.IP.String()).Msg("network: failed to delete address") } newState.IPv4 = "..." @@ -105,7 +105,7 @@ func checkNetworkState() { } if newState != networkState { - logger.Info("network state changed") + logger.Info().Msg("network state changed") // restart MDNS _ = startMDNS() networkState = newState @@ -116,15 +116,15 @@ func checkNetworkState() { func startMDNS() error { // If server was previously running, stop it if mDNSConn != nil { - logger.Info("Stopping mDNS server") + logger.Info().Msg("Stopping mDNS server") err := mDNSConn.Close() if err != nil { - logger.Warnf("failed to stop mDNS server: %v", err) + logger.Warn().Err(err).Msg("failed to stop mDNS server") } } // Start a new server - logger.Info("Starting mDNS server on jetkvm.local") + logger.Info().Msg("Starting mDNS server on jetkvm.local") addr4, err := net.ResolveUDPAddr("udp4", mdns.DefaultAddressIPv4) if err != nil { return err @@ -146,7 +146,8 @@ func startMDNS() error { } mDNSConn, err = mdns.Server(ipv4.NewPacketConn(l4), ipv6.NewPacketConn(l6), &mdns.Config{ - LocalNames: []string{"jetkvm.local"}, //TODO: make it configurable + LocalNames: []string{"jetkvm.local"}, //TODO: make it configurable + LoggerFactory: defaultLoggerFactory, }) if err != nil { mDNSConn = nil @@ -181,7 +182,7 @@ func getNTPServersFromDHCPInfo() ([]string, error) { for _, server := range strings.Fields(val) { if net.ParseIP(server) == nil { - logger.Infof("invalid NTP server IP: %s, ignoring", server) + logger.Info().Str("server", server).Msg("invalid NTP server IP, ignoring") } servers = append(servers, server) } @@ -196,7 +197,7 @@ func init() { done := make(chan struct{}) if err := netlink.LinkSubscribe(updates, done); err != nil { - logger.Warnf("failed to subscribe to link updates: %v", err) + logger.Warn().Err(err).Msg("failed to subscribe to link updates") return } @@ -210,7 +211,7 @@ func init() { select { case update := <-updates: if update.Link.Attrs().Name == NetIfName { - logger.Infof("link update: %+v", update) + logger.Info().Interface("update", update).Msg("link update") checkNetworkState() } case <-ticker.C: @@ -222,6 +223,6 @@ func init() { }() err := startMDNS() if err != nil { - logger.Warnf("failed to run mDNS: %v", err) + logger.Warn().Err(err).Msg("failed to run mDNS") } } diff --git a/ntp.go b/ntp.go index 27ec100..aa7d17a 100644 --- a/ntp.go +++ b/ntp.go @@ -32,13 +32,13 @@ var ( func isTimeSyncNeeded() bool { if builtTimestamp == "" { - logger.Warnf("Built timestamp is not set, time sync is needed") + ntpLogger.Warn().Msg("Built timestamp is not set, time sync is needed") return true } ts, err := strconv.Atoi(builtTimestamp) if err != nil { - logger.Warnf("Failed to parse built timestamp: %v", err) + ntpLogger.Warn().Str("error", err.Error()).Msg("Failed to parse built timestamp") return true } @@ -46,10 +46,10 @@ func isTimeSyncNeeded() bool { builtTime := time.Unix(int64(ts), 0) now := time.Now() - logger.Tracef("Built time: %v, now: %v", builtTime, now) + ntpLogger.Debug().Str("built_time", builtTime.Format(time.RFC3339)).Str("now", now.Format(time.RFC3339)).Msg("Built time and now") if now.Sub(builtTime) < 0 { - logger.Warnf("System time is behind the built time, time sync is needed") + ntpLogger.Warn().Msg("System time is behind the built time, time sync is needed") return true } @@ -64,7 +64,7 @@ func TimeSyncLoop() { } if !networkState.Up { - logger.Infof("Waiting for network to come up") + ntpLogger.Info().Msg("Waiting for network to come up") time.Sleep(timeSyncWaitNetUpInt) continue } @@ -72,11 +72,11 @@ func TimeSyncLoop() { // check if time sync is needed, but do nothing for now isTimeSyncNeeded() - logger.Infof("Syncing system time") + ntpLogger.Info().Msg("Syncing system time") start := time.Now() err := SyncSystemTime() if err != nil { - logger.Warnf("Failed to sync system time: %v", err) + ntpLogger.Error().Str("error", err.Error()).Msg("Failed to sync system time") // retry after a delay timeSyncRetryInterval += timeSyncRetryStep @@ -89,7 +89,9 @@ func TimeSyncLoop() { continue } timeSyncSuccess = true - logger.Infof("Time sync successful, now is: %v, time taken: %v", time.Now(), time.Since(start)) + ntpLogger.Info().Str("now", time.Now().Format(time.RFC3339)). + Str("time_taken", time.Since(start).String()). + Msg("Time sync successful") time.Sleep(timeSyncInterval) // after the first sync is done } } @@ -109,20 +111,20 @@ func SyncSystemTime() (err error) { func queryNetworkTime() (*time.Time, error) { ntpServers, err := getNTPServersFromDHCPInfo() if err != nil { - logger.Warnf("failed to get NTP servers from DHCP info: %v\n", err) + ntpLogger.Error().Str("error", err.Error()).Msg("failed to get NTP servers from DHCP info") } if ntpServers == nil { ntpServers = defaultNTPServers - logger.Infof("Using default NTP servers: %v\n", ntpServers) + ntpLogger.Info().Str("ntp_servers", fmt.Sprintf("%v", ntpServers)).Msg("Using default NTP servers") } else { - logger.Infof("Using NTP servers from DHCP: %v\n", ntpServers) + ntpLogger.Info().Str("ntp_servers", fmt.Sprintf("%v", ntpServers)).Msg("Using NTP servers from DHCP") } for _, server := range ntpServers { now, err := queryNtpServer(server, timeSyncTimeout) if err == nil { - logger.Infof("NTP server [%s] returned time: %v\n", server, now) + ntpLogger.Info().Str("ntp_server", server).Str("time", now.Format(time.RFC3339)).Msg("NTP server returned time") return now, nil } } @@ -133,9 +135,11 @@ func queryNetworkTime() (*time.Time, error) { for _, url := range httpUrls { now, err := queryHttpTime(url, timeSyncTimeout) if err == nil { + ntpLogger.Info().Str("http_url", url).Str("time", now.Format(time.RFC3339)).Msg("HTTP server returned time") return now, nil } } + ntpLogger.Error().Msg("failed to query network time") return nil, errors.New("failed to query network time") } diff --git a/ota.go b/ota.go index b28abbb..64d7a26 100644 --- a/ota.go +++ b/ota.go @@ -76,7 +76,7 @@ func fetchUpdateMetadata(ctx context.Context, deviceId string, includePreRelease query.Set("prerelease", fmt.Sprintf("%v", includePreRelease)) updateUrl.RawQuery = query.Encode() - logger.Infof("Checking for updates at: %s", updateUrl) + logger.Info().Str("url", updateUrl.String()).Msg("Checking for updates") req, err := http.NewRequestWithContext(ctx, "GET", updateUrl.String(), nil) if err != nil { @@ -235,7 +235,7 @@ func verifyFile(path string, expectedHash string, verifyProgress *float32) error } hashSum := hash.Sum(nil) - logger.Infof("SHA256 hash of %s: %x", path, hashSum) + logger.Info().Str("path", path).Str("hash", hex.EncodeToString(hashSum)).Msg("SHA256 hash of") if hex.EncodeToString(hashSum) != expectedHash { return fmt.Errorf("hash mismatch: %x != %s", hashSum, expectedHash) @@ -277,7 +277,7 @@ var otaState = OTAState{} func triggerOTAStateUpdate() { go func() { if currentSession == nil { - logger.Info("No active RPC session, skipping update state update") + logger.Info().Msg("No active RPC session, skipping update state update") return } writeJSONRPCEvent("otaState", otaState, currentSession) @@ -285,7 +285,7 @@ func triggerOTAStateUpdate() { } func TryUpdate(ctx context.Context, deviceId string, includePreRelease bool) error { - logger.Info("Trying to update...") + logger.Info().Msg("Trying to update...") if otaState.Updating { return fmt.Errorf("update already in progress") } @@ -320,7 +320,7 @@ func TryUpdate(ctx context.Context, deviceId string, includePreRelease bool) err rebootNeeded := false if appUpdateAvailable { - logger.Infof("App update available: %s -> %s", local.AppVersion, remote.AppVersion) + logger.Info().Str("local", local.AppVersion).Str("remote", remote.AppVersion).Msg("App update available") err := downloadFile(ctx, "/userdata/jetkvm/jetkvm_app.update", remote.AppUrl, &otaState.AppDownloadProgress) if err != nil { @@ -346,14 +346,15 @@ func TryUpdate(ctx context.Context, deviceId string, includePreRelease bool) err otaState.AppUpdateProgress = 1 triggerOTAStateUpdate() - logger.Info("App update downloaded") + logger.Info().Msg("App update downloaded") rebootNeeded = true } else { - logger.Info("App is up to date") + logger.Info().Msg("App is up to date") } if systemUpdateAvailable { - logger.Infof("System update available: %s -> %s", local.SystemVersion, remote.SystemVersion) + logger.Info().Str("local", local.SystemVersion).Str("remote", remote.SystemVersion).Msg("System update available") + err := downloadFile(ctx, "/userdata/jetkvm/update_system.tar", remote.SystemUrl, &otaState.SystemDownloadProgress) if err != nil { otaState.Error = fmt.Sprintf("Error downloading system update: %v", err) @@ -371,7 +372,7 @@ func TryUpdate(ctx context.Context, deviceId string, includePreRelease bool) err triggerOTAStateUpdate() return err } - logger.Info("System update downloaded") + logger.Info().Msg("System update downloaded") verifyFinished := time.Now() otaState.SystemVerifiedAt = &verifyFinished otaState.SystemVerificationProgress = 1 @@ -418,17 +419,17 @@ func TryUpdate(ctx context.Context, deviceId string, includePreRelease bool) err return fmt.Errorf("error executing rk_ota command: %w\nOutput: %s", err, output) } - logger.Infof("rk_ota success, output: %s", output) + logger.Info().Str("output", output).Msg("rk_ota success") otaState.SystemUpdateProgress = 1 otaState.SystemUpdatedAt = &verifyFinished triggerOTAStateUpdate() rebootNeeded = true } else { - logger.Info("System is up to date") + logger.Info().Msg("System is up to date") } if rebootNeeded { - logger.Info("System Rebooting in 10s") + logger.Info().Msg("System Rebooting in 10s") time.Sleep(10 * time.Second) cmd := exec.Command("reboot") err := cmd.Start() @@ -503,6 +504,6 @@ func IsUpdatePending() bool { func confirmCurrentSystem() { output, err := exec.Command("rk_ota", "--misc=now").CombinedOutput() if err != nil { - logger.Warnf("failed to set current partition in A/B setup: %s", string(output)) + logger.Warn().Str("output", string(output)).Msg("failed to set current partition in A/B setup") } } diff --git a/remote_mount.go b/remote_mount.go index 5b10695..befffcb 100644 --- a/remote_mount.go +++ b/remote_mount.go @@ -44,7 +44,7 @@ func (w *WebRTCDiskReader) Read(ctx context.Context, offset int64, size int64) ( return nil, errors.New("not active session") } - logger.Debugf("reading from webrtc %v", string(jsonBytes)) + logger.Debug().Str("request", string(jsonBytes)).Msg("reading from webrtc") err = currentSession.DiskChannel.SendText(string(jsonBytes)) if err != nil { return nil, err diff --git a/serial.go b/serial.go index 31fd553..732c022 100644 --- a/serial.go +++ b/serial.go @@ -39,13 +39,13 @@ func runATXControl() { for { line, err := reader.ReadString('\n') if err != nil { - logger.Errorf("Error reading from serial port: %v", err) + logger.Warn().Err(err).Msg("Error reading from serial port") return } // Each line should be 4 binary digits + newline if len(line) != 5 { - logger.Warnf("Invalid line length: %d", len(line)) + logger.Warn().Int("length", len(line)).Msg("Invalid line length") continue } @@ -66,8 +66,7 @@ func runATXControl() { newLedPWRState != ledPWRState || newBtnRSTState != btnRSTState || newBtnPWRState != btnPWRState { - logger.Debugf("Status changed: HDD LED: %v, PWR LED: %v, RST BTN: %v, PWR BTN: %v", - newLedHDDState, newLedPWRState, newBtnRSTState, newBtnPWRState) + logger.Debug().Bool("hdd", newLedHDDState).Bool("pwr", newLedPWRState).Bool("rst", newBtnRSTState).Bool("pwr", newBtnPWRState).Msg("Status changed") // Update states ledHDDState = newLedHDDState @@ -138,41 +137,41 @@ func runDCControl() { for { line, err := reader.ReadString('\n') if err != nil { - logger.Errorf("Error reading from serial port: %v", err) + logger.Warn().Err(err).Msg("Error reading from serial port") return } // Split the line by semicolon parts := strings.Split(strings.TrimSpace(line), ";") if len(parts) != 4 { - logger.Warnf("Invalid line: %s", line) + logger.Warn().Str("line", line).Msg("Invalid line") continue } // Parse new states powerState, err := strconv.Atoi(parts[0]) if err != nil { - logger.Warnf("Invalid power state: %v", err) + logger.Warn().Err(err).Msg("Invalid power state") continue } dcState.IsOn = powerState == 1 milliVolts, err := strconv.ParseFloat(parts[1], 64) if err != nil { - logger.Warnf("Invalid voltage: %v", err) + logger.Warn().Err(err).Msg("Invalid voltage") continue } volts := milliVolts / 1000 // Convert mV to V milliAmps, err := strconv.ParseFloat(parts[2], 64) if err != nil { - logger.Warnf("Invalid current: %v", err) + logger.Warn().Err(err).Msg("Invalid current") continue } amps := milliAmps / 1000 // Convert mA to A milliWatts, err := strconv.ParseFloat(parts[3], 64) if err != nil { - logger.Warnf("Invalid power: %v", err) + logger.Warn().Err(err).Msg("Invalid power") continue } watts := milliWatts / 1000 // Convert mW to W @@ -226,7 +225,7 @@ func reopenSerialPort() error { var err error port, err = serial.Open(serialPortPath, defaultMode) if err != nil { - logger.Errorf("Error opening serial port: %v", err) + logger.Warn().Err(err).Msg("Error opening serial port") } return nil } @@ -239,13 +238,13 @@ func handleSerialChannel(d *webrtc.DataChannel) { n, err := port.Read(buf) if err != nil { if err != io.EOF { - logger.Errorf("Failed to read from serial port: %v", err) + logger.Warn().Err(err).Msg("Failed to read from serial port") } break } err = d.Send(buf[:n]) if err != nil { - logger.Errorf("Failed to send serial output: %v", err) + logger.Warn().Err(err).Msg("Failed to send serial output") break } } @@ -258,7 +257,7 @@ func handleSerialChannel(d *webrtc.DataChannel) { } _, err := port.Write(msg.Data) if err != nil { - logger.Errorf("Failed to write to serial: %v", err) + logger.Warn().Err(err).Msg("Failed to write to serial") } }) diff --git a/terminal.go b/terminal.go index 3e64020..2200064 100644 --- a/terminal.go +++ b/terminal.go @@ -23,7 +23,7 @@ func handleTerminalChannel(d *webrtc.DataChannel) { var err error ptmx, err = pty.Start(cmd) if err != nil { - logger.Errorf("Failed to start pty: %v", err) + logger.Warn().Err(err).Msg("Failed to start pty") d.Close() return } @@ -34,13 +34,13 @@ func handleTerminalChannel(d *webrtc.DataChannel) { n, err := ptmx.Read(buf) if err != nil { if err != io.EOF { - logger.Errorf("Failed to read from pty: %v", err) + logger.Warn().Err(err).Msg("Failed to read from pty") } break } err = d.Send(buf[:n]) if err != nil { - logger.Errorf("Failed to send pty output: %v", err) + logger.Warn().Err(err).Msg("Failed to send pty output") break } } @@ -63,11 +63,11 @@ func handleTerminalChannel(d *webrtc.DataChannel) { return } } - logger.Errorf("Failed to parse terminal size: %v", err) + logger.Warn().Err(err).Msg("Failed to parse terminal size") } _, err := ptmx.Write(msg.Data) if err != nil { - logger.Errorf("Failed to write to pty: %v", err) + logger.Warn().Err(err).Msg("Failed to write to pty") } }) diff --git a/usb.go b/usb.go index 8a3538b..03ea8a3 100644 --- a/usb.go +++ b/usb.go @@ -15,7 +15,7 @@ func initUsbGadget() { "jetkvm", config.UsbDevices, config.UsbConfig, - &logger, + &usbLogger, ) go func() { @@ -51,7 +51,7 @@ func rpcGetUSBState() (state string) { func triggerUSBStateUpdate() { go func() { if currentSession == nil { - logger.Info("No active RPC session, skipping update state update") + usbLogger.Info().Msg("No active RPC session, skipping update state update") return } writeJSONRPCEvent("usbState", usbState, currentSession) @@ -65,7 +65,7 @@ func checkUSBState() { } usbState = newState - logger.Infof("USB state changed from %s to %s", usbState, newState) + usbLogger.Info().Str("from", usbState).Str("to", newState).Msg("USB state changed") requestDisplayUpdate() triggerUSBStateUpdate() } diff --git a/usb_mass_storage.go b/usb_mass_storage.go index 6578069..e70a353 100644 --- a/usb_mass_storage.go +++ b/usb_mass_storage.go @@ -55,7 +55,7 @@ func setMassStorageMode(cdrom bool) error { } func onDiskMessage(msg webrtc.DataChannelMessage) { - logger.Infof("Disk Message, len: %d", len(msg.Data)) + logger.Info().Int("len", len(msg.Data)).Msg("Disk Message") diskReadChan <- msg.Data } @@ -76,7 +76,7 @@ var nbdDevice *NBDDevice const imagesFolder = "/userdata/jetkvm/images" func rpcMountBuiltInImage(filename string) error { - logger.Infof("Mount Built-In Image: %s", filename) + logger.Info().Str("filename", filename).Msg("Mount Built-In Image") _ = os.MkdirAll(imagesFolder, 0755) imagePath := filepath.Join(imagesFolder, filename) @@ -173,7 +173,7 @@ func rpcUnmountImage() error { defer virtualMediaStateMutex.Unlock() err := setMassStorageImage("\n") if err != nil { - logger.Warnf("Remove Mass Storage Image Error: %v", err) + logger.Warn().Err(err).Msg("Remove Mass Storage Image Error") } //TODO: check if we still need it time.Sleep(500 * time.Millisecond) @@ -199,7 +199,7 @@ func rpcMountWithHTTP(url string, mode VirtualMediaMode) error { virtualMediaStateMutex.Unlock() return fmt.Errorf("failed to use http url: %w", err) } - logger.Infof("using remote url %s with size %d", url, n) + logger.Info().Str("url", url).Int64("size", n).Msg("using remote url") currentVirtualMediaState = &VirtualMediaState{ Source: HTTP, Mode: mode, @@ -208,21 +208,21 @@ func rpcMountWithHTTP(url string, mode VirtualMediaMode) error { } virtualMediaStateMutex.Unlock() - logger.Debug("Starting nbd device") + logger.Debug().Msg("Starting nbd device") nbdDevice = NewNBDDevice() err = nbdDevice.Start() if err != nil { - logger.Errorf("failed to start nbd device: %v", err) + logger.Warn().Err(err).Msg("failed to start nbd device") return err } - logger.Debug("nbd device started") + logger.Debug().Msg("nbd device started") //TODO: replace by polling on block device having right size time.Sleep(1 * time.Second) err = setMassStorageImage("/dev/nbd0") if err != nil { return err } - logger.Info("usb mass storage mounted") + logger.Info().Msg("usb mass storage mounted") return nil } @@ -239,22 +239,22 @@ func rpcMountWithWebRTC(filename string, size int64, mode VirtualMediaMode) erro Size: size, } virtualMediaStateMutex.Unlock() - logger.Debugf("currentVirtualMediaState is %v", currentVirtualMediaState) - logger.Debug("Starting nbd device") + logger.Debug().Interface("currentVirtualMediaState", currentVirtualMediaState).Msg("currentVirtualMediaState") + logger.Debug().Msg("Starting nbd device") nbdDevice = NewNBDDevice() err := nbdDevice.Start() if err != nil { - logger.Errorf("failed to start nbd device: %v", err) + logger.Warn().Err(err).Msg("failed to start nbd device") return err } - logger.Debug("nbd device started") + logger.Debug().Msg("nbd device started") //TODO: replace by polling on block device having right size time.Sleep(1 * time.Second) err = setMassStorageImage("/dev/nbd0") if err != nil { return err } - logger.Info("usb mass storage mounted") + logger.Info().Msg("usb mass storage mounted") return nil } @@ -444,7 +444,7 @@ func handleUploadChannel(d *webrtc.DataChannel) { pendingUpload, ok := pendingUploads[uploadId] pendingUploadsMutex.Unlock() if !ok { - logger.Warnf("upload channel opened for unknown upload: %s", uploadId) + logger.Warn().Str("uploadId", uploadId).Msg("upload channel opened for unknown upload") return } totalBytesWritten := pendingUpload.AlreadyUploadedBytes @@ -454,12 +454,12 @@ func handleUploadChannel(d *webrtc.DataChannel) { newName := strings.TrimSuffix(pendingUpload.File.Name(), ".incomplete") err := os.Rename(pendingUpload.File.Name(), newName) if err != nil { - logger.Errorf("failed to rename uploaded file: %v", err) + logger.Warn().Err(err).Str("uploadId", uploadId).Msg("failed to rename uploaded file") } else { - logger.Debugf("successfully renamed uploaded file to: %s", newName) + logger.Debug().Str("uploadId", uploadId).Str("newName", newName).Msg("successfully renamed uploaded file") } } else { - logger.Warnf("uploaded ended before the complete file received") + logger.Warn().Str("uploadId", uploadId).Msg("uploaded ended before the complete file received") } pendingUploadsMutex.Lock() delete(pendingUploads, uploadId) @@ -470,7 +470,7 @@ func handleUploadChannel(d *webrtc.DataChannel) { d.OnMessage(func(msg webrtc.DataChannelMessage) { bytesWritten, err := pendingUpload.File.Write(msg.Data) if err != nil { - logger.Errorf("failed to write to file: %v", err) + logger.Warn().Err(err).Str("uploadId", uploadId).Msg("failed to write to file") close(uploadComplete) return } @@ -492,11 +492,11 @@ func handleUploadChannel(d *webrtc.DataChannel) { } progressJSON, err := json.Marshal(progress) if err != nil { - logger.Errorf("failed to marshal upload progress: %v", err) + logger.Warn().Err(err).Str("uploadId", uploadId).Msg("failed to marshal upload progress") } else { err = d.SendText(string(progressJSON)) if err != nil { - logger.Errorf("failed to send upload progress: %v", err) + logger.Warn().Err(err).Str("uploadId", uploadId).Msg("failed to send upload progress") } } lastProgressTime = time.Now() @@ -524,12 +524,12 @@ func handleUploadHttp(c *gin.Context) { newName := strings.TrimSuffix(pendingUpload.File.Name(), ".incomplete") err := os.Rename(pendingUpload.File.Name(), newName) if err != nil { - logger.Errorf("failed to rename uploaded file: %v", err) + logger.Warn().Err(err).Str("uploadId", uploadId).Msg("failed to rename uploaded file") } else { - logger.Debugf("successfully renamed uploaded file to: %s", newName) + logger.Debug().Str("uploadId", uploadId).Str("newName", newName).Msg("successfully renamed uploaded file") } } else { - logger.Warnf("uploaded ended before the complete file received") + logger.Warn().Str("uploadId", uploadId).Msg("uploaded ended before the complete file received") } pendingUploadsMutex.Lock() delete(pendingUploads, uploadId) @@ -541,7 +541,7 @@ func handleUploadHttp(c *gin.Context) { for { n, err := reader.Read(buffer) if err != nil && err != io.EOF { - logger.Errorf("failed to read from request body: %v", err) + logger.Warn().Err(err).Str("uploadId", uploadId).Msg("failed to read from request body") c.JSON(http.StatusInternalServerError, gin.H{"error": "Failed to read upload data"}) return } @@ -549,7 +549,7 @@ func handleUploadHttp(c *gin.Context) { if n > 0 { bytesWritten, err := pendingUpload.File.Write(buffer[:n]) if err != nil { - logger.Errorf("failed to write to file: %v", err) + logger.Warn().Err(err).Str("uploadId", uploadId).Msg("failed to write to file") c.JSON(http.StatusInternalServerError, gin.H{"error": "Failed to write upload data"}) return } diff --git a/video.go b/video.go index ade9353..d74add8 100644 --- a/video.go +++ b/video.go @@ -38,7 +38,7 @@ func HandleVideoStateMessage(event CtrlResponse) { videoState := VideoInputState{} err := json.Unmarshal(event.Data, &videoState) if err != nil { - logger.Warnf("Error parsing video state json: %v", err) + logger.Warn().Err(err).Msg("Error parsing video state json") return } lastVideoState = videoState diff --git a/web.go b/web.go index 6c35073..8bf34af 100644 --- a/web.go +++ b/web.go @@ -15,11 +15,13 @@ import ( "github.com/coder/websocket" "github.com/coder/websocket/wsjson" + gin_logger "github.com/gin-contrib/logger" "github.com/gin-gonic/gin" "github.com/google/uuid" "github.com/pion/webrtc/v4" "github.com/prometheus/client_golang/prometheus" "github.com/prometheus/client_golang/prometheus/promhttp" + "github.com/rs/zerolog" "golang.org/x/crypto/bcrypt" ) @@ -65,7 +67,11 @@ func setupRouter() *gin.Engine { gin.SetMode(gin.ReleaseMode) gin.DisableConsoleColor() r := gin.Default() - + r.Use(gin_logger.SetLogger( + gin_logger.WithLogger(func(*gin.Context, zerolog.Logger) zerolog.Logger { + return ginLogger + }), + )) staticFS, _ := fs.Sub(staticFiles, "static") // Add a custom middleware to set cache headers for images @@ -181,16 +187,22 @@ var ( ) func handleLocalWebRTCSignal(c *gin.Context) { - cloudLogger.Infof("new websocket connection established") - // get the source from the request source := c.ClientIP() + scopedLogger := websocketLogger.With(). + Str("component", "websocket"). + Str("source", source). + Str("sourceType", "local"). + Logger() + + scopedLogger.Info().Msg("new websocket connection established") + // Create WebSocket options with InsecureSkipVerify to bypass origin check wsOptions := &websocket.AcceptOptions{ InsecureSkipVerify: true, // Allow connections from any origin OnPingReceived: func(ctx context.Context, payload []byte) bool { - websocketLogger.Infof("ping frame received: %v, source: %s, sourceType: local", payload, source) + scopedLogger.Info().Bytes("payload", payload).Msg("ping frame received") metricConnectionTotalPingReceivedCount.WithLabelValues("local", source).Inc() metricConnectionLastPingReceivedTimestamp.WithLabelValues("local", source).SetToCurrentTime() @@ -214,14 +226,14 @@ func handleLocalWebRTCSignal(c *gin.Context) { return } - err = handleWebRTCSignalWsMessages(wsCon, false, source) + err = handleWebRTCSignalWsMessages(wsCon, false, source, &scopedLogger) if err != nil { c.JSON(http.StatusInternalServerError, gin.H{"error": err.Error()}) return } } -func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, source string) error { +func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, source string, scopedLogger *zerolog.Logger) error { runCtx, cancelRun := context.WithCancel(context.Background()) defer cancelRun() @@ -236,21 +248,13 @@ func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, sourceType = "local" } - // probably we can use a better logging framework here - logInfof := func(format string, args ...interface{}) { - args = append(args, source, sourceType, connectionID) - websocketLogger.Infof(format+", source: %s, sourceType: %s, id: %s", args...) - } - logWarnf := func(format string, args ...interface{}) { - args = append(args, source, sourceType, connectionID) - websocketLogger.Warnf(format+", source: %s, sourceType: %s, id: %s", args...) - } - logTracef := func(format string, args ...interface{}) { - args = append(args, source, sourceType, connectionID) - websocketLogger.Tracef(format+", source: %s, sourceType: %s, id: %s", args...) - } + l := scopedLogger.With(). + Str("source", source). + Str("sourceType", sourceType). + Str("connectionID", connectionID). + Logger() - logInfof("new websocket connection established") + l.Info().Msg("new websocket connection established") go func() { for { @@ -258,9 +262,9 @@ func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, if ctxErr := runCtx.Err(); ctxErr != nil { if !errors.Is(ctxErr, context.Canceled) { - logWarnf("websocket connection closed: %v", ctxErr) + l.Warn().Str("error", ctxErr.Error()).Msg("websocket connection closed") } else { - logTracef("websocket connection closed as the context was canceled: %v") + l.Trace().Str("error", ctxErr.Error()).Msg("websocket connection closed as the context was canceled") } return } @@ -271,11 +275,11 @@ func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, metricConnectionPingDuration.WithLabelValues(sourceType, source).Observe(v) })) - logTracef("sending ping frame") + l.Trace().Msg("sending ping frame") err := wsCon.Ping(runCtx) if err != nil { - logWarnf("websocket ping error: %v", err) + l.Warn().Str("error", err.Error()).Msg("websocket ping error") cancelRun() return } @@ -286,7 +290,7 @@ func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, metricConnectionTotalPingSentCount.WithLabelValues(sourceType, source).Inc() metricConnectionLastPingTimestamp.WithLabelValues(sourceType, source).SetToCurrentTime() - logTracef("received pong frame, duration: %v", duration) + l.Trace().Str("duration", duration.String()).Msg("received pong frame") } }() @@ -302,7 +306,7 @@ func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, if err == nil { continue } - cloudLogger.Infof("disconnecting from cloud due to: %v", err) + cloudLogger.Info().Err(err).Msg("disconnecting from cloud due to") cancelRun() } }() @@ -311,7 +315,7 @@ func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, for { typ, msg, err := wsCon.Read(runCtx) if err != nil { - logWarnf("websocket read error: %v", err) + l.Warn().Str("error", err.Error()).Msg("websocket read error") return err } if typ != websocket.MessageText { @@ -325,10 +329,10 @@ func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, } if bytes.Equal(msg, pingMessage) { - logInfof("ping message received: %s", string(msg)) + l.Info().Str("message", string(msg)).Msg("ping message received") err = wsCon.Write(context.Background(), websocket.MessageText, pongMessage) if err != nil { - logWarnf("unable to write pong message: %v", err) + l.Warn().Str("error", err.Error()).Msg("unable to write pong message") return err } @@ -340,55 +344,55 @@ func handleWebRTCSignalWsMessages(wsCon *websocket.Conn, isCloudConnection bool, err = json.Unmarshal(msg, &message) if err != nil { - logWarnf("unable to parse ws message: %v", err) + l.Warn().Str("error", err.Error()).Msg("unable to parse ws message") continue } if message.Type == "offer" { - logInfof("new session request received") + l.Info().Msg("new session request received") var req WebRTCSessionRequest err = json.Unmarshal(message.Data, &req) if err != nil { - logWarnf("unable to parse session request data: %v", err) + l.Warn().Str("error", err.Error()).Msg("unable to parse session request data") continue } if req.OidcGoogle != "" { - logInfof("new session request with OIDC Google: %v", req.OidcGoogle) + l.Info().Str("oidcGoogle", req.OidcGoogle).Msg("new session request with OIDC Google") } metricConnectionSessionRequestCount.WithLabelValues(sourceType, source).Inc() metricConnectionLastSessionRequestTimestamp.WithLabelValues(sourceType, source).SetToCurrentTime() err = handleSessionRequest(runCtx, wsCon, req, isCloudConnection, source) if err != nil { - logWarnf("error starting new session: %v", err) + l.Warn().Str("error", err.Error()).Msg("error starting new session") continue } } else if message.Type == "new-ice-candidate" { - logInfof("The client sent us a new ICE candidate: %v", string(message.Data)) + l.Info().Str("data", string(message.Data)).Msg("The client sent us a new ICE candidate") var candidate webrtc.ICECandidateInit // Attempt to unmarshal as a ICECandidateInit if err := json.Unmarshal(message.Data, &candidate); err != nil { - logWarnf("unable to parse incoming ICE candidate data: %v", string(message.Data)) + l.Warn().Str("error", err.Error()).Msg("unable to parse incoming ICE candidate data") continue } if candidate.Candidate == "" { - logWarnf("empty incoming ICE candidate, skipping") + l.Warn().Msg("empty incoming ICE candidate, skipping") continue } - logInfof("unmarshalled incoming ICE candidate: %v", candidate) + l.Info().Str("data", fmt.Sprintf("%v", candidate)).Msg("unmarshalled incoming ICE candidate") if currentSession == nil { - logInfof("no current session, skipping incoming ICE candidate") + l.Warn().Msg("no current session, skipping incoming ICE candidate") continue } - logInfof("adding incoming ICE candidate to current session: %v", candidate) + l.Info().Str("data", fmt.Sprintf("%v", candidate)).Msg("adding incoming ICE candidate to current session") if err = currentSession.peerConnection.AddICECandidate(candidate); err != nil { - logWarnf("failed to add incoming ICE candidate to our peer connection: %v", err) + l.Warn().Str("error", err.Error()).Msg("failed to add incoming ICE candidate to our peer connection") } } } diff --git a/web_tls.go b/web_tls.go index 976cff6..1ef4d31 100644 --- a/web_tls.go +++ b/web_tls.go @@ -45,7 +45,7 @@ func RunWebSecureServer() { hostname = strings.Split(info.Conn.LocalAddr().String(), ":")[0] } - logger.Infof("TLS handshake for %s, SupportedProtos: %v", hostname, info.SupportedProtos) + logger.Info().Str("hostname", hostname).Interface("SupportedProtos", info.SupportedProtos).Msg("TLS handshake") cert := createSelfSignedCert(hostname) @@ -53,7 +53,7 @@ func RunWebSecureServer() { }, }, } - logger.Infof("Starting websecure server on %s", RunWebSecureServer) + logger.Info().Str("listen", WebSecureListen).Msg("Starting websecure server") err := server.ListenAndServeTLS("", "") if err != nil { panic(err) @@ -67,11 +67,11 @@ func createSelfSignedCert(hostname string) *tls.Certificate { tlsCertLock.Lock() defer tlsCertLock.Unlock() - logger.Infof("Creating self-signed certificate for %s", hostname) + logger.Info().Str("hostname", hostname).Msg("Creating self-signed certificate") priv, err := ecdsa.GenerateKey(elliptic.P256(), rand.Reader) if err != nil { - logger.Errorf("Failed to generate private key: %v", err) + logger.Warn().Err(err).Msg("Failed to generate private key") os.Exit(1) } keyUsage := x509.KeyUsageDigitalSignature @@ -82,7 +82,7 @@ func createSelfSignedCert(hostname string) *tls.Certificate { serialNumberLimit := new(big.Int).Lsh(big.NewInt(1), 128) serialNumber, err := rand.Int(rand.Reader, serialNumberLimit) if err != nil { - logger.Errorf("Failed to generate serial number: %v", err) + logger.Warn().Err(err).Msg("Failed to generate serial number") } dnsName := hostname @@ -114,12 +114,12 @@ func createSelfSignedCert(hostname string) *tls.Certificate { derBytes, err := x509.CreateCertificate(rand.Reader, &template, &template, &priv.PublicKey, priv) if err != nil { - logger.Errorf("Failed to create certificate: %v", err) + logger.Warn().Err(err).Msg("Failed to create certificate") } cert := pem.EncodeToMemory(&pem.Block{Type: "CERTIFICATE", Bytes: derBytes}) if cert == nil { - logger.Errorf("Failed to encode certificate") + logger.Warn().Msg("Failed to encode certificate") } tlsCert := &tls.Certificate{ diff --git a/webrtc.go b/webrtc.go index a047ecc..d01b4b6 100644 --- a/webrtc.go +++ b/webrtc.go @@ -65,22 +65,24 @@ func (s *Session) ExchangeOffer(offerStr string) (string, error) { } func newSession(config SessionConfig) (*Session, error) { - webrtcSettingEngine := webrtc.SettingEngine{} + webrtcSettingEngine := webrtc.SettingEngine{ + LoggerFactory: defaultLoggerFactory, + } iceServer := webrtc.ICEServer{} if config.IsCloud { if config.ICEServers == nil { - logger.Info("ICE Servers not provided by cloud") + logger.Info().Msg("ICE Servers not provided by cloud") } else { iceServer.URLs = config.ICEServers - logger.Infof("Using ICE Servers provided by cloud: %v", iceServer.URLs) + logger.Info().Interface("iceServers", iceServer.URLs).Msg("Using ICE Servers provided by cloud") } if config.LocalIP == "" || net.ParseIP(config.LocalIP) == nil { - logger.Infof("Local IP address %v not provided or invalid, won't set NAT1To1IPs", config.LocalIP) + logger.Info().Str("localIP", config.LocalIP).Msg("Local IP address not provided or invalid, won't set NAT1To1IPs") } else { webrtcSettingEngine.SetNAT1To1IPs([]string{config.LocalIP}, webrtc.ICECandidateTypeSrflx) - logger.Infof("Setting NAT1To1IPs to %s", config.LocalIP) + logger.Info().Str("localIP", config.LocalIP).Msg("Setting NAT1To1IPs") } } @@ -94,7 +96,7 @@ func newSession(config SessionConfig) (*Session, error) { session := &Session{peerConnection: peerConnection} peerConnection.OnDataChannel(func(d *webrtc.DataChannel) { - logger.Infof("New DataChannel %s %d", d.Label(), d.ID()) + logger.Info().Str("label", d.Label()).Uint16("id", *d.ID()).Msg("New DataChannel") switch d.Label() { case "rpc": session.RPCChannel = d @@ -142,17 +144,17 @@ func newSession(config SessionConfig) (*Session, error) { var isConnected bool peerConnection.OnICECandidate(func(candidate *webrtc.ICECandidate) { - logger.Infof("Our WebRTC peerConnection has a new ICE candidate: %v", candidate) + logger.Info().Interface("candidate", candidate).Msg("Our WebRTC peerConnection has a new ICE candidate") if candidate != nil { err := wsjson.Write(context.Background(), config.ws, gin.H{"type": "new-ice-candidate", "data": candidate.ToJSON()}) if err != nil { - logger.Errorf("failed to write new-ice-candidate to WebRTC signaling channel: %v", err) + logger.Warn().Err(err).Msg("failed to write new-ice-candidate to WebRTC signaling channel") } } }) peerConnection.OnICEConnectionStateChange(func(connectionState webrtc.ICEConnectionState) { - logger.Infof("Connection State has changed %s", connectionState) + logger.Info().Str("connectionState", connectionState.String()).Msg("Connection State has changed") if connectionState == webrtc.ICEConnectionStateConnected { if !isConnected { isConnected = true @@ -173,7 +175,7 @@ func newSession(config SessionConfig) (*Session, error) { } if session.shouldUmountVirtualMedia { err := rpcUnmountImage() - logger.Debugf("unmount image failed on connection close %v", err) + logger.Debug().Err(err).Msg("unmount image failed on connection close") } if isConnected { isConnected = false