Superminaren
/
kvm
mirror of https://github.com/jetkvm/kvm.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

refactor: use structured logging

This commit is contained in:
Siyuan Miao 2025-04-10 18:35:31 +02:00
parent 3aa93009d7
commit 621484a33e
32 changed files with 415 additions and 289 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
block_device.go
View File

@ -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()
}

31
cloud.go
View File

@ -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

6
config.go
View File

@ -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
}

28
display.go
View File

@ -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()

2
fuse.go
View File

@ -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()
}

8
hw.go
View File

@ -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
}

28
internal/pion/logging/logger.go
View File

@ -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,

19
internal/pion/logging/scoped.go
View File

@ -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)

28
internal/usbgadget/config.go
View File

@ -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
}

2
internal/usbgadget/hid_keyboard.go
View File

@ -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

2
internal/usbgadget/hid_mouse_absolute.go
View File

@ -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

2
internal/usbgadget/hid_mouse_relative.go
View File

@ -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

6
internal/usbgadget/udc.go
View File

@ -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"
}

13
internal/usbgadget/usbgadget.go
View File

@ -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
}

6
internal/usbgadget/utils.go
View File

@ -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)

4
jiggler.go
View File

@ -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")
}
}
}

46
jsonrpc.go
View File

@ -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)

96
log.go
View File

@ -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
}

16
main.go
View File

@ -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 {

60
native.go
View File

@ -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")
}
}
}

26
network.go
View File

@ -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")
}
}

28
ntp.go
View File

@ -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")
}

27
ota.go
View File

@ -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")
}
}

2
remote_mount.go
View File

@ -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

27
serial.go
View File

@ -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")
}
})

10
terminal.go
View File

@ -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")
}
})

6
usb.go
View File

@ -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()
}

50
usb_mass_storage.go
View File

@ -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
}

2
video.go
View File

@ -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

79
web.go
View File

@ -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")
}
}
}

14
web_tls.go
View File

@ -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{

18
webrtc.go
View File

@ -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