diff --git a/config.go b/config.go index f19b6e0..cf096a7 100644 --- a/config.go +++ b/config.go @@ -93,6 +93,7 @@ type Config struct { TLSMode string `json:"tls_mode"` // options: "self-signed", "user-defined", "" UsbConfig *usbgadget.Config `json:"usb_config"` UsbDevices *usbgadget.Devices `json:"usb_devices"` + DefaultLogLevel string `json:"default_log_level"` } const configPath = "/userdata/kvm_config.json" @@ -120,6 +121,7 @@ var defaultConfig = &Config{ Keyboard: true, MassStorage: true, }, + DefaultLogLevel: "INFO", } var ( @@ -163,6 +165,8 @@ func LoadConfig() { } config = &loadedConfig + + rootLogger.UpdateLogLevel() } func SaveConfig() error { diff --git a/display.go b/display.go index a5528a3..38e12b1 100644 --- a/display.go +++ b/display.go @@ -5,6 +5,7 @@ import ( "fmt" "os" "strconv" + "sync" "time" ) @@ -70,9 +71,15 @@ func updateDisplay() { } } -var displayInited = false +var ( + displayInited = false + displayUpdateLock = sync.Mutex{} +) func requestDisplayUpdate() { + displayUpdateLock.Lock() + defer displayUpdateLock.Unlock() + if !displayInited { displayLogger.Info().Msg("display not inited, skipping updates") return diff --git a/jsonrpc.go b/jsonrpc.go index d788e86..0c7d7fd 100644 --- a/jsonrpc.go +++ b/jsonrpc.go @@ -74,11 +74,15 @@ func writeJSONRPCEvent(event string, params interface{}, session *Session) { } requestString := string(requestBytes) - jsonRpcLogger.Info().Str("data", requestString).Msg("Sending JSONRPC event") + scopedLogger := jsonRpcLogger.With(). + Str("data", requestString). + Logger() + + scopedLogger.Info().Msg("sending JSONRPC event") err = session.RPCChannel.SendText(requestString) if err != nil { - jsonRpcLogger.Warn().Err(err).Str("data", requestString).Msg("Error sending JSONRPC event") + scopedLogger.Warn().Err(err).Msg("error sending JSONRPC event") return } } diff --git a/log.go b/log.go index 3ee8473..b97a473 100644 --- a/log.go +++ b/log.go @@ -12,8 +12,36 @@ import ( "github.com/rs/zerolog" ) +type Logger struct { + l *zerolog.Logger + scopeLoggers map[string]*zerolog.Logger + scopeLevels map[string]zerolog.Level + scopeLevelMutex sync.Mutex + + defaultLogLevelFromEnv zerolog.Level + defaultLogLevelFromConfig zerolog.Level + defaultLogLevel zerolog.Level +} + +const ( + defaultLogLevel = zerolog.ErrorLevel +) + +type logOutput struct { + mu *sync.Mutex +} + +func (w *logOutput) Write(p []byte) (n int, err error) { + w.mu.Lock() + defer w.mu.Unlock() + + // TODO: write to file or syslog + + return len(p), nil +} + var ( - defaultLogOutput io.Writer = zerolog.ConsoleWriter{ + consoleLogOutput io.Writer = zerolog.ConsoleWriter{ Out: os.Stdout, TimeFormat: time.RFC3339, PartsOrder: []string{"time", "level", "scope", "component", "message"}, @@ -28,57 +56,10 @@ var ( return val }, } - defaultLogLevel = zerolog.ErrorLevel - rootLogger = zerolog.New(defaultLogOutput).With(). - Str("scope", "jetkvm"). - Timestamp(). - Stack(). - Logger() -) + fileLogOutput io.Writer = &logOutput{mu: &sync.Mutex{}} + defaultLogOutput = zerolog.MultiLevelWriter(consoleLogOutput, fileLogOutput) -var ( - scopeLevels map[string]zerolog.Level - scopeLevelMutex = sync.Mutex{} -) - -var ( - logger = getLogger("jetkvm") - cloudLogger = getLogger("cloud") - websocketLogger = getLogger("websocket") - webrtcLogger = getLogger("webrtc") - nativeLogger = getLogger("native") - ntpLogger = getLogger("ntp") - jsonRpcLogger = getLogger("jsonrpc") - watchdogLogger = getLogger("watchdog") - websecureLogger = getLogger("websecure") - otaLogger = getLogger("ota") - serialLogger = getLogger("serial") - terminalLogger = getLogger("terminal") - displayLogger = getLogger("display") - wolLogger = getLogger("wol") - usbLogger = getLogger("usb") - // external components - ginLogger = getLogger("gin") -) - -func ErrorfL(l *zerolog.Logger, format string, err error, args ...interface{}) error { - if l == nil { - l = &logger - } - - l.Error().Err(err).Msgf(format, args...) - - err_msg := err.Error() + ": %v" - err_args := append(args, err) - - return fmt.Errorf(err_msg, err_args...) -} - -func updateLogLevel() { - scopeLevelMutex.Lock() - defer scopeLevelMutex.Unlock() - - logLevels := map[string]zerolog.Level{ + zerologLevels = map[string]zerolog.Level{ "DISABLE": zerolog.Disabled, "NOLEVEL": zerolog.NoLevel, "PANIC": zerolog.PanicLevel, @@ -90,9 +71,35 @@ func updateLogLevel() { "TRACE": zerolog.TraceLevel, } - scopeLevels = make(map[string]zerolog.Level) + rootZerologLogger = zerolog.New(defaultLogOutput).With(). + Str("scope", "jetkvm"). + Timestamp(). + Stack(). + Logger() + rootLogger = NewLogger(rootZerologLogger) +) - for name, level := range logLevels { +func NewLogger(zerologLogger zerolog.Logger) *Logger { + return &Logger{ + l: &zerologLogger, + scopeLoggers: make(map[string]*zerolog.Logger), + scopeLevels: make(map[string]zerolog.Level), + scopeLevelMutex: sync.Mutex{}, + defaultLogLevelFromEnv: -2, + defaultLogLevelFromConfig: -2, + defaultLogLevel: defaultLogLevel, + } +} + +func (l *Logger) updateLogLevel() { + l.scopeLevelMutex.Lock() + defer l.scopeLevelMutex.Unlock() + + l.scopeLevels = make(map[string]zerolog.Level) + + finalDefaultLogLevel := l.defaultLogLevel + + for name, level := range zerologLevels { env := os.Getenv(fmt.Sprintf("JETKVM_LOG_%s", name)) if env == "" { @@ -108,8 +115,10 @@ func updateLogLevel() { } if strings.ToLower(env) == "all" { - if defaultLogLevel > level { - defaultLogLevel = level + l.defaultLogLevelFromEnv = level + + if finalDefaultLogLevel > level { + finalDefaultLogLevel = level } continue @@ -117,26 +126,112 @@ func updateLogLevel() { scopes := strings.Split(strings.ToLower(env), ",") for _, scope := range scopes { - scopeLevels[scope] = level + l.scopeLevels[scope] = level + } + } + + l.defaultLogLevel = finalDefaultLogLevel +} + +func (l *Logger) getScopeLoggerLevel(scope string) zerolog.Level { + if l.scopeLevels == nil { + l.updateLogLevel() + } + + var scopeLevel zerolog.Level + if l.defaultLogLevelFromConfig != -2 { + scopeLevel = l.defaultLogLevelFromConfig + } + if l.defaultLogLevelFromEnv != -2 { + scopeLevel = l.defaultLogLevelFromEnv + } + + // if the scope is not in the map, use the default level from the root logger + if level, ok := l.scopeLevels[scope]; ok { + scopeLevel = level + } + + return scopeLevel +} + +func (l *Logger) newScopeLogger(scope string) zerolog.Logger { + scopeLevel := l.getScopeLoggerLevel(scope) + logger := l.l.Level(scopeLevel).With().Str("component", scope).Logger() + + return logger +} + +func (l *Logger) getLogger(scope string) *zerolog.Logger { + logger, ok := l.scopeLoggers[scope] + if !ok || logger == nil { + scopeLogger := l.newScopeLogger(scope) + l.scopeLoggers[scope] = &scopeLogger + } + + return l.scopeLoggers[scope] +} + +func (l *Logger) UpdateLogLevel() { + needUpdate := false + + if config != nil && config.DefaultLogLevel != "" { + if logLevel, ok := zerologLevels[config.DefaultLogLevel]; ok { + l.defaultLogLevelFromConfig = logLevel + } else { + l.l.Warn().Str("logLevel", config.DefaultLogLevel).Msg("invalid defaultLogLevel from config, using ERROR") + } + + if l.defaultLogLevelFromConfig != l.defaultLogLevel { + needUpdate = true + } + } + + l.updateLogLevel() + + if needUpdate { + for scope, logger := range l.scopeLoggers { + currentLevel := logger.GetLevel() + targetLevel := l.getScopeLoggerLevel(scope) + if currentLevel != targetLevel { + *logger = l.newScopeLogger(scope) + } } } } -func getLogger(scope string) zerolog.Logger { - if scopeLevels == nil { - updateLogLevel() +func ErrorfL(l *zerolog.Logger, format string, err error, args ...interface{}) error { + if l == nil { + l = rootLogger.getLogger("jetkvm") } - l := rootLogger.With().Str("component", scope).Logger() + l.Error().Err(err).Msgf(format, args...) - // 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) - } + err_msg := err.Error() + ": %v" + err_args := append(args, err) - return l.Level(defaultLogLevel) + return fmt.Errorf(err_msg, err_args...) } +var ( + logger = rootLogger.getLogger("jetkvm") + cloudLogger = rootLogger.getLogger("cloud") + websocketLogger = rootLogger.getLogger("websocket") + webrtcLogger = rootLogger.getLogger("webrtc") + nativeLogger = rootLogger.getLogger("native") + ntpLogger = rootLogger.getLogger("ntp") + jsonRpcLogger = rootLogger.getLogger("jsonrpc") + watchdogLogger = rootLogger.getLogger("watchdog") + websecureLogger = rootLogger.getLogger("websecure") + otaLogger = rootLogger.getLogger("ota") + serialLogger = rootLogger.getLogger("serial") + terminalLogger = rootLogger.getLogger("terminal") + displayLogger = rootLogger.getLogger("display") + wolLogger = rootLogger.getLogger("wol") + usbLogger = rootLogger.getLogger("usb") + // external components + ginLogger = rootLogger.getLogger("gin") +) + type pionLogger struct { logger *zerolog.Logger } @@ -180,7 +275,7 @@ func (c pionLogger) Errorf(format string, args ...interface{}) { type pionLoggerFactory struct{} func (c pionLoggerFactory) NewLogger(subsystem string) logging.LeveledLogger { - logger := getLogger(subsystem).With(). + logger := rootLogger.getLogger(subsystem).With(). Str("scope", "pion"). Str("component", subsystem). Logger() diff --git a/main.go b/main.go index d74b1ef..9eab708 100644 --- a/main.go +++ b/main.go @@ -14,22 +14,26 @@ import ( var appCtx context.Context func Main() { + LoadConfig() + logger.Debug().Msg("config loaded") + var cancel context.CancelFunc appCtx, cancel = context.WithCancel(context.Background()) defer cancel() - logger.Info().Msg("Starting JetKvm") + logger.Info().Msg("starting JetKvm") + go runWatchdog() go confirmCurrentSystem() http.DefaultClient.Timeout = 1 * time.Minute - LoadConfig() - logger.Debug().Msg("config loaded") err := rootcerts.UpdateDefaultTransport() if err != nil { logger.Warn().Err(err).Msg("failed to load CA certs") } + initNetwork() + go TimeSyncLoop() StartNativeCtrlSocketServer() diff --git a/native.go b/native.go index 630093b..ded7dc4 100644 --- a/native.go +++ b/native.go @@ -75,25 +75,29 @@ func CallCtrlAction(action string, params map[string]interface{}) (*CtrlResponse return nil, fmt.Errorf("error marshaling ctrl action: %w", err) } - nativeLogger.Info().Str("action", ctrlAction.Action).Msg("sending ctrl action") + scopedLogger := nativeLogger.With(). + Str("action", ctrlAction.Action). + Interface("params", ctrlAction.Params).Logger() + + scopedLogger.Debug().Msg("sending ctrl action") err = WriteCtrlMessage(jsonData) if err != nil { delete(ongoingRequests, ctrlAction.Seq) - return nil, fmt.Errorf("error writing ctrl message: %w", err) + return nil, ErrorfL(&scopedLogger, "error writing ctrl message", err) } select { case response := <-responseChan: delete(ongoingRequests, seq) if response.Error != "" { - return nil, fmt.Errorf("error native response: %s", response.Error) + return nil, ErrorfL(&scopedLogger, "error native response: %s", fmt.Errorf(response.Error)) } return response, nil case <-time.After(5 * time.Second): close(responseChan) delete(ongoingRequests, seq) - return nil, fmt.Errorf("timeout waiting for response") + return nil, ErrorfL(&scopedLogger, "timeout waiting for response", nil) } } @@ -115,31 +119,35 @@ func waitCtrlClientConnected() { } func StartNativeSocketServer(socketPath string, handleClient func(net.Conn), isCtrl bool) net.Listener { + scopedLogger := nativeLogger.With(). + Str("socket_path", socketPath). + Logger() + // Remove the socket file if it already exists if _, err := os.Stat(socketPath); err == nil { if err := os.Remove(socketPath); err != nil { - nativeLogger.Warn().Err(err).Str("socket_path", socketPath).Msg("Failed to remove existing socket file") + scopedLogger.Warn().Err(err).Msg("failed to remove existing socket file") os.Exit(1) } } listener, err := net.Listen("unixpacket", socketPath) if err != nil { - nativeLogger.Warn().Err(err).Str("socket_path", socketPath).Msg("Failed to start server") + scopedLogger.Warn().Err(err).Msg("failed to start server") os.Exit(1) } - nativeLogger.Info().Str("socket_path", socketPath).Msg("Server listening") + scopedLogger.Info().Msg("server listening") go func() { conn, err := listener.Accept() listener.Close() if err != nil { - nativeLogger.Warn().Err(err).Str("socket_path", socketPath).Msg("failed to accept sock") + scopedLogger.Warn().Err(err).Msg("failed to accept socket") } if isCtrl { close(ctrlClientConnected) - nativeLogger.Debug().Msg("first native ctrl socket client connected") + scopedLogger.Debug().Msg("first native ctrl socket client connected") } handleClient(conn) }() @@ -160,9 +168,14 @@ func StartNativeVideoSocketServer() { func handleCtrlClient(conn net.Conn) { defer conn.Close() - nativeLogger.Debug().Msg("native socket client connected") + scopedLogger := nativeLogger.With(). + Str("addr", conn.RemoteAddr().String()). + Str("type", "ctrl"). + Logger() + + scopedLogger.Info().Msg("native ctrl socket client connected") if ctrlSocketConn != nil { - nativeLogger.Debug().Msg("closing existing native socket connection") + scopedLogger.Debug().Msg("closing existing native socket connection") ctrlSocketConn.Close() } @@ -175,7 +188,7 @@ func handleCtrlClient(conn net.Conn) { for { n, err := conn.Read(readBuf) if err != nil { - nativeLogger.Warn().Err(err).Msg("error reading from ctrl sock") + scopedLogger.Warn().Err(err).Msg("error reading from ctrl sock") break } readMsg := string(readBuf[:n]) @@ -183,10 +196,10 @@ func handleCtrlClient(conn net.Conn) { ctrlResp := CtrlResponse{} err = json.Unmarshal([]byte(readMsg), &ctrlResp) if err != nil { - nativeLogger.Warn().Err(err).Str("data", readMsg).Msg("error parsing ctrl sock msg") + scopedLogger.Warn().Err(err).Str("data", readMsg).Msg("error parsing ctrl sock msg") continue } - nativeLogger.Trace().Interface("data", ctrlResp).Msg("ctrl sock msg") + scopedLogger.Trace().Interface("data", ctrlResp).Msg("ctrl sock msg") if ctrlResp.Seq != 0 { responseChan, ok := ongoingRequests[ctrlResp.Seq] @@ -200,20 +213,25 @@ func handleCtrlClient(conn net.Conn) { } } - nativeLogger.Debug().Msg("ctrl sock disconnected") + scopedLogger.Debug().Msg("ctrl sock disconnected") } func handleVideoClient(conn net.Conn) { defer conn.Close() - nativeLogger.Info().Str("addr", conn.RemoteAddr().String()).Msg("Native video socket client connected") + scopedLogger := nativeLogger.With(). + Str("addr", conn.RemoteAddr().String()). + Str("type", "video"). + Logger() + + scopedLogger.Info().Msg("native video socket client connected") inboundPacket := make([]byte, maxFrameSize) lastFrame := time.Now() for { n, err := conn.Read(inboundPacket) if err != nil { - nativeLogger.Warn().Err(err).Msg("error during read") + scopedLogger.Warn().Err(err).Msg("error during read") return } now := time.Now() @@ -222,7 +240,7 @@ func handleVideoClient(conn net.Conn) { if currentSession != nil { err := currentSession.VideoTrack.WriteSample(media.Sample{Data: inboundPacket[:n], Duration: sinceLastFrame}) if err != nil { - nativeLogger.Warn().Err(err).Msg("error writing sample") + scopedLogger.Warn().Err(err).Msg("error writing sample") } } } @@ -277,7 +295,7 @@ func ExtractAndRunNativeBin() error { } }() - nativeLogger.Info().Int("pid", cmd.Process.Pid).Msg("Binary started") + nativeLogger.Info().Int("pid", cmd.Process.Pid).Msg("jetkvm_native binary started") return nil } diff --git a/network.go b/network.go index 4051c06..6948d9a 100644 --- a/network.go +++ b/network.go @@ -105,7 +105,11 @@ func checkNetworkState() { } if newState != networkState { - logger.Info().Msg("network state changed") + logger.Info(). + Interface("newState", newState). + Interface("oldState", networkState). + Msg("network state changed") + // restart MDNS _ = startMDNS() networkState = newState @@ -116,7 +120,7 @@ func checkNetworkState() { func startMDNS() error { // If server was previously running, stop it if mDNSConn != nil { - logger.Info().Msg("Stopping mDNS server") + logger.Info().Msg("stopping mDNS server") err := mDNSConn.Close() if err != nil { logger.Warn().Err(err).Msg("failed to stop mDNS server") @@ -124,7 +128,11 @@ func startMDNS() error { } // Start a new server - logger.Info().Msg("Starting mDNS server on jetkvm.local") + hostname := "jetkvm.local" + + scopedLogger := logger.With().Str("hostname", hostname).Logger() + scopedLogger.Info().Msg("starting mDNS server") + addr4, err := net.ResolveUDPAddr("udp4", mdns.DefaultAddressIPv4) if err != nil { return err @@ -146,10 +154,11 @@ func startMDNS() error { } mDNSConn, err = mdns.Server(ipv4.NewPacketConn(l4), ipv6.NewPacketConn(l6), &mdns.Config{ - LocalNames: []string{"jetkvm.local"}, //TODO: make it configurable + LocalNames: []string{hostname}, //TODO: make it configurable LoggerFactory: defaultLoggerFactory, }) if err != nil { + scopedLogger.Warn().Err(err).Msg("failed to start mDNS server") mDNSConn = nil return err } @@ -190,7 +199,7 @@ func getNTPServersFromDHCPInfo() ([]string, error) { return servers, nil } -func init() { +func initNetwork() { ensureConfigLoaded() updates := make(chan netlink.LinkUpdate) diff --git a/ota.go b/ota.go index ded1353..a5da772 100644 --- a/ota.go +++ b/ota.go @@ -194,7 +194,7 @@ func downloadFile(ctx context.Context, path string, url string, downloadProgress func verifyFile(path string, expectedHash string, verifyProgress *float32, scopedLogger *zerolog.Logger) error { if scopedLogger == nil { - scopedLogger = &otaLogger + scopedLogger = otaLogger } unverifiedPath := path + ".unverified" diff --git a/usb.go b/usb.go index 03ea8a3..3395db4 100644 --- a/usb.go +++ b/usb.go @@ -15,7 +15,7 @@ func initUsbGadget() { "jetkvm", config.UsbDevices, config.UsbConfig, - &usbLogger, + usbLogger, ) go func() { diff --git a/web.go b/web.go index b696637..8ff5929 100644 --- a/web.go +++ b/web.go @@ -69,7 +69,7 @@ func setupRouter() *gin.Engine { r := gin.Default() r.Use(gin_logger.SetLogger( gin_logger.WithLogger(func(*gin.Context, zerolog.Logger) zerolog.Logger { - return ginLogger + return *ginLogger }), )) staticFS, _ := fs.Sub(staticFiles, "static") diff --git a/web_tls.go b/web_tls.go index 048e9fa..2989957 100644 --- a/web_tls.go +++ b/web_tls.go @@ -38,12 +38,12 @@ func initCertStore() { websecureLogger.Warn().Msg("TLS store already initialized, it should not be initialized again") return } - certStore = websecure.NewCertStore(tlsStorePath, &websecureLogger) + certStore = websecure.NewCertStore(tlsStorePath, websecureLogger) certStore.LoadCertificates() certSigner = websecure.NewSelfSigner( certStore, - &websecureLogger, + websecureLogger, webSecureSelfSignedDefaultDomain, webSecureSelfSignedOrganization, webSecureSelfSignedOU, diff --git a/webrtc.go b/webrtc.go index 5bc6623..1e093e2 100644 --- a/webrtc.go +++ b/webrtc.go @@ -77,7 +77,7 @@ func newSession(config SessionConfig) (*Session, error) { l := config.Logger.With().Str("component", "webrtc").Logger() scopedLogger = &l } else { - scopedLogger = &webrtcLogger + scopedLogger = webrtcLogger } if config.IsCloud { diff --git a/wol.go b/wol.go index d6fc8bc..47f921a 100644 --- a/wol.go +++ b/wol.go @@ -11,7 +11,7 @@ func rpcSendWOLMagicPacket(macAddress string) error { // Parse the MAC address mac, err := net.ParseMAC(macAddress) if err != nil { - return ErrorfL(&wolLogger, "invalid MAC address", err) + return ErrorfL(wolLogger, "invalid MAC address", err) } // Create the magic packet @@ -20,14 +20,14 @@ func rpcSendWOLMagicPacket(macAddress string) error { // Set up UDP connection conn, err := net.Dial("udp", "255.255.255.255:9") if err != nil { - return ErrorfL(&wolLogger, "failed to establish UDP connection", err) + return ErrorfL(wolLogger, "failed to establish UDP connection", err) } defer conn.Close() // Send the packet _, err = conn.Write(packet) if err != nil { - return ErrorfL(&wolLogger, "failed to send WOL packet", err) + return ErrorfL(wolLogger, "failed to send WOL packet", err) } wolLogger.Info().Str("mac", macAddress).Msg("WOL packet sent")