From d6fa7c1eade6f2df601290c4d0fdd7c6c9e01de5 Mon Sep 17 00:00:00 2001 From: sam80180 Date: Sun, 28 Jan 2024 01:02:05 +0800 Subject: [PATCH] fix: log with context data --- cmd/app/launch.go | 8 ++++---- src/util/common.go | 27 ++++++++++++++++++++++++-- src/util/log.go | 46 +++++++++++++++++++++++++++++++++++++-------- src/util/usbmux.go | 47 ++++++++++++++++++++++++++++++++-------------- 4 files changed, 100 insertions(+), 28 deletions(-) diff --git a/cmd/app/launch.go b/cmd/app/launch.go index 9ba76f4..dc544cd 100644 --- a/cmd/app/launch.go +++ b/cmd/app/launch.go @@ -66,11 +66,11 @@ var launchCmd = &cobra.Command{ func myHelpFunc(cmd *cobra.Command, args []string) { fmt.Printf(`%s - Usage: - %s -- [arguments [arguments ...]] +Usage: + %s -- [arguments [arguments ...]] - Flags: - %s`, cmd.Long, cmd.UseLine(), cmd.Flags().FlagUsages()) +Flags: +%s`, cmd.Long, cmd.UseLine(), cmd.Flags().FlagUsages()) } func initAppLaunch() { diff --git a/src/util/common.go b/src/util/common.go index 0cd26c0..8fd4822 100644 --- a/src/util/common.go +++ b/src/util/common.go @@ -20,6 +20,7 @@ package util import ( "archive/zip" "bufio" + "bytes" "encoding/json" "errors" "fmt" @@ -31,12 +32,15 @@ import ( "os" "path" "path/filepath" + "runtime" + "strconv" "strings" "sync" "time" giDevice "github.com/SonicCloudOrg/sonic-gidevice" "github.com/SonicCloudOrg/sonic-ios-bridge/src/entity" + "github.com/sirupsen/logrus" ) const ( @@ -83,11 +87,11 @@ func GetDeviceByUdId(udId string) (device giDevice.Device) { device = list[0] } if device == nil || device.Properties().SerialNumber == "" { - fmt.Println("device not found") + //fmt.Println("device not found") return nil } } else { - fmt.Println("no device connected") + logrus.Debug("No device connected") return nil } return @@ -338,3 +342,22 @@ func StartProxy() func(listener net.Listener, port int, device giDevice.Device) } } } + +func GoRoutineID() int { // https://stackoverflow.com/a/75362272/12857692 + buf := make([]byte, 32) + n := runtime.Stack(buf, false) + buf = buf[:n] + _, buf, ok := bytes.Cut(buf, []byte("goroutine ")) + if !ok { + return 0 + } + i := bytes.IndexByte(buf, ' ') + if i < 0 { + return 0 + } + if id, e := strconv.Atoi(string(buf[:i])); e == nil { + return id + } else { + return 0 + } +} diff --git a/src/util/log.go b/src/util/log.go index a1f8a59..1f548aa 100644 --- a/src/util/log.go +++ b/src/util/log.go @@ -1,6 +1,7 @@ package util import ( + "encoding/json" "fmt" stdlog "log" "os" @@ -11,12 +12,41 @@ import ( easy "github.com/t-tomalak/logrus-easy-formatter" ) +type MyLogrusFormatter struct { + Fmt easy.Formatter +} + +func (f *MyLogrusFormatter) Format(entry *logrus.Entry) ([]byte, error) { + b, e := f.Fmt.Format(entry) + if len(entry.Data) > 0 { + offset := 0 + strB := string(b) + if strings.HasSuffix(strB, "\n") { + offset = 1 + } else if strings.HasSuffix(strB, "\r\n") { + offset = 2 + } + jb, _ := json.Marshal(entry.Data) + b = append(b[:len(b)-offset], []byte("\t")...) + b = append(b, jb...) + if offset == 1 { + b = append(b, []byte("\n")...) + } else if offset == 2 { + b = append(b, []byte("\r\n")...) + } + } + return b, e +} + func InitLogger(strIntLevel string) { logrus.SetOutput(os.Stderr) - logrus.SetFormatter(&easy.Formatter{ - TimestampFormat: "2006-01-02 15:04:05", - LogFormat: "[%lvl%]: %time% - %msg%\n", - }) + fmtr := MyLogrusFormatter{ + Fmt: easy.Formatter{ + TimestampFormat: "2006-01-02 15:04:05", + LogFormat: "[%lvl%]: %time% - %msg%\n", // '%xxx%' is custom placeholder of 'logrus-easy-formatter' + }, + } + logrus.SetFormatter(&fmtr) SetLogLevel(strIntLevel) stdlog.SetOutput(new(LogrusWriter)) } @@ -56,10 +86,10 @@ func (LogrusWriter) Write(data []byte) (int, error) { if strings.HasSuffix(logmessage, "\n") { logmessage = logmessage[:len(logmessage)-1] } - if logmessage == "handle_events: error: libusb: interrupted [code -10]" { // this annoying message - logrus.Debugf("[gousb] %s", logmessage) - } else { // other standard log module output - fmt.Print(string(data)) + if logmessage == "handle_events: error: libusb: interrupted [code -10]" { // handle this annoying message + logrus.Debug(logmessage) + } else { + fmt.Printf("%s", string(data)) } return len(logmessage), nil } diff --git a/src/util/usbmux.go b/src/util/usbmux.go index 57a91ab..accf7ff 100644 --- a/src/util/usbmux.go +++ b/src/util/usbmux.go @@ -26,12 +26,18 @@ func UsbmuxListen(cbOnData func(gidevice *giDevice.Device, device *entity.Device mylatch := latch.NewCountDownLatch() mylatch.Add(2) go (func() { + goroutineId := GoRoutineID() + logger := logrus.WithFields(logrus.Fields{ + "goroutine": goroutineId, + "goroutineName": "healthCheck", + }) backoffAlgorithm := backoff.NewConstantBackOff(30 * time.Second) bIsOk := true backoff.RetryNotify(func() error { if mylatch.Counter() <= 0 { return nil } + logger.Debug("Connecting to usbmux...") usbMuxClient, err := giDevice.NewUsbmux() if err != nil { return NewErrorPrint(ErrConnect, "usbMux", err) @@ -44,27 +50,34 @@ func UsbmuxListen(cbOnData func(gidevice *giDevice.Device, device *entity.Device if _, errBuid := usbMuxClient.ReadBUID(); errBuid != nil { return errBuid } - logrus.Debug("usbmux health check success") + logger.Debug("usbmux health check success") if !bIsOk { // transition from not OK to OK - logrus.Trace("Reset health check backoff algorithm") + logger.Trace("Reset health check backoff algorithm") backoffAlgorithm.Reset() bIsOk = true } } }, backoffAlgorithm, func(err error, d time.Duration) { bIsOk = false - logrus.Warnf("usbmux health check error: %+v", err) + logger.Warnf("usbmux health check error: %+v", err) healthCheck <- false + logger.Debugf("next retry health check in %s", d.String()) }) - logrus.Trace("end health check") + logger.Trace("end health check") })() go (func(funcStop *context.CancelFunc) { + goroutineId := GoRoutineID() + logger := logrus.WithFields(logrus.Fields{ + "goroutine": goroutineId, + "goroutineName": "usbmuxListen", + }) backoffAlgorithm := backoff.NewConstantBackOff(30 * time.Second) bIsOk := true backoff.RetryNotify(func() error { if mylatch.Counter() <= 1 { // 'read channel input' go routine is stopped return nil } + logger.Debug("Connecting to usbmux...") usbMuxClient, err := giDevice.NewUsbmux() if err != nil { return NewErrorPrint(ErrConnect, "usbMux", err) @@ -74,34 +87,40 @@ func UsbmuxListen(cbOnData func(gidevice *giDevice.Device, device *entity.Device if errListen != nil { return NewErrorPrint(ErrSendCommand, string(libimobiledevice.MessageTypeListen), errListen) } - logrus.Info("Start listening...") + logger.Info("Start listening...") <-healthCheck // empty out the channel if !bIsOk { // transition from not OK to OK - logrus.Trace("Reset usbmux listen backoff algorithm") + logger.Trace("Reset usbmux listen backoff algorithm") backoffAlgorithm.Reset() bIsOk = true } for range healthCheck { - logrus.Info("Cancel listening") + logger.Info("Cancel listening") (*funcStop) = nil return fmt.Errorf("usbmux listening is cancelled") } return nil }, backoffAlgorithm, func(err error, d time.Duration) { bIsOk = false - logrus.Warnf("usbmux listening error: %+v", err) + logger.Warnf("usbmux listening error: %+v", err) + logger.Debugf("next retry listening in %s", d.String()) }) mylatch.Done() - logrus.Trace("end usbmux listen") + logger.Trace("end usbmux listen") })(&funcCancelListen) go (func(funcStop *context.CancelFunc) { + goroutineId := GoRoutineID() + logger := logrus.WithFields(logrus.Fields{ + "goroutine": goroutineId, + "goroutineName": "loopRead", + }) numOnlineDevices := 0 loopRead: for { select { case d, ok := <-usbmuxInput: if !ok { // channel is closed - logrus.Info("usbmux input channel is closed") + logger.Info("usbmux input channel is closed") break loopRead } if d == nil { @@ -128,12 +147,12 @@ func UsbmuxListen(cbOnData func(gidevice *giDevice.Device, device *entity.Device if cbOnData != nil { cbOnData(&d, ptrEntityDevice, errDec, _fStop) } - logrus.Debugf("Number of online devices= %d", numOnlineDevices) + logger.Debugf("Number of online devices= %d", numOnlineDevices) if numOnlineDevices <= 0 { - logrus.Info("No devices are online") + logger.Info("No devices are online") } case <-sigTerm: - logrus.Info("Stop listening") + logger.Info("Stop listening") if funcStop != nil { (*funcStop)() } @@ -142,7 +161,7 @@ func UsbmuxListen(cbOnData func(gidevice *giDevice.Device, device *entity.Device } } mylatch.Done() - logrus.Trace("end reading channel input") + logger.Trace("end reading channel input") })(&funcCancelListen) return funcCancelListen }