From 621484a33efa910a0d1396969f7af3227e0ee97e Mon Sep 17 00:00:00 2001 From: Siyuan Miao Date: Thu, 10 Apr 2025 18:35:31 +0200 Subject: [PATCH] refactor: use structured logging --- block_device.go | 12 +-- cloud.go | 31 ++++---- config.go | 6 +- display.go | 28 +++---- fuse.go | 2 +- hw.go | 8 +- internal/pion/logging/logger.go | 28 ++++--- internal/pion/logging/scoped.go | 19 +++++ internal/usbgadget/config.go | 28 +++---- internal/usbgadget/hid_keyboard.go | 2 +- internal/usbgadget/hid_mouse_absolute.go | 2 +- internal/usbgadget/hid_mouse_relative.go | 2 +- internal/usbgadget/udc.go | 6 +- internal/usbgadget/usbgadget.go | 13 ++-- internal/usbgadget/utils.go | 6 +- jiggler.go | 4 +- jsonrpc.go | 46 ++++++------ log.go | 96 ++++++++++++++++++++++-- main.go | 16 ++-- native.go | 60 ++++++++------- network.go | 26 +++---- ntp.go | 28 ++++--- ota.go | 27 +++---- remote_mount.go | 2 +- serial.go | 27 ++++--- terminal.go | 10 +-- usb.go | 6 +- usb_mass_storage.go | 50 ++++++------ video.go | 2 +- web.go | 79 ++++++++++--------- web_tls.go | 14 ++-- webrtc.go | 18 ++--- 32 files changed, 415 insertions(+), 289 deletions(-) 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..7b3ef34 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.String()). + 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/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/pion/logging/logger.go b/internal/pion/logging/logger.go index f38ed1e..7ed6503 100644 --- a/internal/pion/logging/logger.go +++ b/internal/pion/logging/logger.go @@ -6,6 +6,7 @@ import ( "fmt" "io" "os" + "runtime" "strings" "sync" "time" @@ -16,16 +17,13 @@ import ( var defaultOutput io.Writer = zerolog.ConsoleWriter{ Out: os.Stdout, TimeFormat: time.RFC3339, - PartsOrder: []string{"time", "level", "scope", "message"}, - FieldsExclude: []string{"scope"}, + 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 == "scope" { - if strings.HasPrefix(val, "jetkvm/") { - return val[7:] - } else { - // scope without prefix, we assume it's from the pion library - return fmt.Sprintf("pion/%s", val) + if name == "component" { + if value == nil { + return "-" } } return val @@ -182,7 +180,19 @@ func NewDefaultLeveledLoggerForScope(scope string, level LogLevel, writer io.Wri if writer == nil { writer = defaultOutput } - zerologWriter := zerolog.New(writer).With().Timestamp().Str("scope", scope).Logger() + + z := zerolog.New(writer).Level(toZerologLevel(level)).With().Timestamp() + + // scope will be changed to the component name if it's from the pion library + _, file, _, _ := runtime.Caller(2) + if strings.Contains(file, "github.com/pion/") { + z = z.Str("scope", "pion").Str("component", scope) + } else { + z = z.Str("scope", scope) + } + + zerologWriter := z.Logger() + logger := &DefaultLeveledLogger{ writer: &zerologWriter, level: level, diff --git a/internal/pion/logging/scoped.go b/internal/pion/logging/scoped.go index 7f90192..4fdd653 100644 --- a/internal/pion/logging/scoped.go +++ b/internal/pion/logging/scoped.go @@ -57,6 +57,25 @@ const ( LogLevelTrace ) +func toZerologLevel(level LogLevel) zerolog.Level { + switch level { + case LogLevelDisabled: + return zerolog.Disabled + case LogLevelError: + return zerolog.ErrorLevel + case LogLevelWarn: + return zerolog.WarnLevel + case LogLevelInfo: + return zerolog.InfoLevel + case LogLevelDebug: + return zerolog.DebugLevel + case LogLevelTrace: + return zerolog.TraceLevel + default: + return zerolog.NoLevel + } +} + // LeveledLogger is the basic pion Logger interface. type LeveledLogger interface { Trace(msg string) 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..6c09584 100644 --- a/internal/usbgadget/usbgadget.go +++ b/internal/usbgadget/usbgadget.go @@ -9,6 +9,7 @@ import ( "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,18 +64,18 @@ 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 = logging.NewDefaultLoggerFactory().NewLogger("usbgadget").GetLogger() // 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 + logger = defaultLogger } if enabledDevices == nil { @@ -97,12 +98,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 3441b03..5c383ab 100644 --- a/log.go +++ b/log.go @@ -1,10 +1,96 @@ package kvm -import "github.com/pion/logging" +import ( + "fmt" + "os" + "strings" + "sync" + + "github.com/pion/logging" + "github.com/rs/zerolog" +) + +const defaultLogLevel = zerolog.ErrorLevel // we use logging framework from pion // ref: https://github.com/pion/webrtc/wiki/Debugging-WebRTC -var logger = logging.NewDefaultLoggerFactory().NewLogger("jetkvm/jetkvm") -var cloudLogger = logging.NewDefaultLoggerFactory().NewLogger("jetkvm/cloud") -var websocketLogger = logging.NewDefaultLoggerFactory().NewLogger("jetkvm/websocket") -var nativeLogger = logging.NewDefaultLoggerFactory().NewLogger("jetkvm/native") +var rootLogger = logging.NewDefaultLoggerFactory().NewLogger("jetkvm").GetLogger() + +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") +) + +func updateLogLevel() { + scopeLevelMutex.Lock() + defer scopeLevelMutex.Unlock() + + defaultLevel := defaultLogLevel + 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 defaultLevel < level { + defaultLevel = 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 +} 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 36589be..630093b 100644 --- a/native.go +++ b/native.go @@ -75,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 { @@ -118,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) }() @@ -149,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() } @@ -175,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 { @@ -198,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() @@ -220,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") } } } @@ -242,11 +244,11 @@ func ExtractAndRunNativeBin() error { nativeOutputLock := sync.Mutex{} nativeStdout := &nativeOutput{ mu: &nativeOutputLock, - logger: nativeLogger.GetLogger().Info().Str("pipe", "stdout"), + logger: nativeLogger.Info().Str("pipe", "stdout"), } nativeStderr := &nativeOutput{ mu: &nativeOutputLock, - logger: nativeLogger.GetLogger().Info().Str("pipe", "stderr"), + logger: nativeLogger.Info().Str("pipe", "stderr"), } // Redirect stdout and stderr to the current process @@ -267,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 } @@ -304,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 { @@ -327,7 +329,7 @@ func ensureBinaryUpdated(destPath string) error { return err } } - logger.Info("jetkvm_native updated") + nativeLogger.Info().Msg("jetkvm_native updated") } return nil @@ -337,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..e7653d0 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 @@ -181,7 +181,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 +196,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 +210,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 +222,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..1d5859d 100644 --- a/web.go +++ b/web.go @@ -20,6 +20,7 @@ import ( "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" ) @@ -181,16 +182,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 +221,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 +243,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 +257,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 +270,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 +285,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 +301,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 +310,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 +324,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 +339,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..d2e8142 100644 --- a/webrtc.go +++ b/webrtc.go @@ -70,17 +70,17 @@ func newSession(config SessionConfig) (*Session, error) { 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 +94,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 +142,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 +173,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