chore: update logging

This commit is contained in:
Siyuan Miao 2025-04-11 12:55:36 +02:00
parent 924b55059f
commit 0ba7902f82
13 changed files with 246 additions and 105 deletions

View File

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

View File

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

View File

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

223
log.go
View File

@ -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 getLogger(scope string) zerolog.Logger {
if scopeLevels == nil {
updateLogLevel()
func (l *Logger) getScopeLoggerLevel(scope string) zerolog.Level {
if l.scopeLevels == nil {
l.updateLogLevel()
}
l := rootLogger.With().Str("component", scope).Logger()
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 := scopeLevels[scope]; ok {
return l.Level(level)
if level, ok := l.scopeLevels[scope]; ok {
scopeLevel = level
}
return l.Level(defaultLogLevel)
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 ErrorfL(l *zerolog.Logger, format string, err error, args ...interface{}) error {
if l == nil {
l = rootLogger.getLogger("jetkvm")
}
l.Error().Err(err).Msgf(format, args...)
err_msg := err.Error() + ": %v"
err_args := append(args, err)
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()

10
main.go
View File

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

View File

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

View File

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

2
ota.go
View File

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

2
usb.go
View File

@ -15,7 +15,7 @@ func initUsbGadget() {
"jetkvm",
config.UsbDevices,
config.UsbConfig,
&usbLogger,
usbLogger,
)
go func() {

2
web.go
View File

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

View File

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

View File

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

6
wol.go
View File

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