fix: log with context data

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

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

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
 }

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
 }