Avoid opening log output before start &

Replace tracing logs with task monitor
SagerNet · Dec 5, 2023 · 5077a87 · 5077a87
1 parent 7772ba9
commit 5077a87
Show file tree

Hide file tree

Showing 14 changed files with 222 additions and 257 deletions.
diff --git a/box.go b/box.go
@@ -9,6 +9,8 @@ import (
 	"time"
 
 	"github.com/sagernet/sing-box/adapter"
+	"github.com/sagernet/sing-box/common/taskmonitor"
+	C "github.com/sagernet/sing-box/constant"
 	"github.com/sagernet/sing-box/experimental"
 	"github.com/sagernet/sing-box/experimental/cachefile"
 	"github.com/sagernet/sing-box/experimental/libbox/platform"
@@ -230,25 +232,34 @@ func (s *Box) Start() error {
 }
 
 func (s *Box) preStart() error {
+	monitor := taskmonitor.New(s.logger, C.DefaultStartTimeout)
+	monitor.Start("start logger")
+	err := s.logFactory.Start()
+	monitor.Finish()
+	if err != nil {
+		return E.Cause(err, "start logger")
+	}
 	for serviceName, service := range s.preServices1 {
 		if preService, isPreService := service.(adapter.PreStarter); isPreService {
-			s.logger.Trace("pre-start ", serviceName)
+			monitor.Start("pre-start ", serviceName)
 			err := preService.PreStart()
+			monitor.Finish()
 			if err != nil {
-				return E.Cause(err, "pre-starting ", serviceName)
+				return E.Cause(err, "pre-start ", serviceName)
 			}
 		}
 	}
 	for serviceName, service := range s.preServices2 {
 		if preService, isPreService := service.(adapter.PreStarter); isPreService {
-			s.logger.Trace("pre-start ", serviceName)
+			monitor.Start("pre-start ", serviceName)
 			err := preService.PreStart()
+			monitor.Finish()
 			if err != nil {
-				return E.Cause(err, "pre-starting ", serviceName)
+				return E.Cause(err, "pre-start ", serviceName)
 			}
 		}
 	}
-	err := s.startOutbounds()
+	err = s.startOutbounds()
 	if err != nil {
 		return err
 	}
@@ -261,14 +272,12 @@ func (s *Box) start() error {
 		return err
 	}
 	for serviceName, service := range s.preServices1 {
-		s.logger.Trace("starting ", serviceName)
 		err = service.Start()
 		if err != nil {
 			return E.Cause(err, "start ", serviceName)
 		}
 	}
 	for serviceName, service := range s.preServices2 {
-		s.logger.Trace("starting ", serviceName)
 		err = service.Start()
 		if err != nil {
 			return E.Cause(err, "start ", serviceName)
@@ -281,7 +290,6 @@ func (s *Box) start() error {
 		} else {
 			tag = in.Tag()
 		}
-		s.logger.Trace("initializing inbound/", in.Type(), "[", tag, "]")
 		err = in.Start()
 		if err != nil {
 			return E.Cause(err, "initialize inbound/", in.Type(), "[", tag, "]")
@@ -292,22 +300,19 @@ func (s *Box) start() error {
 
 func (s *Box) postStart() error {
 	for serviceName, service := range s.postServices {
-		s.logger.Trace("starting ", service)
 		err := service.Start()
 		if err != nil {
 			return E.Cause(err, "start ", serviceName)
 		}
 	}
 	for _, outbound := range s.outbounds {
 		if lateOutbound, isLateOutbound := outbound.(adapter.PostStarter); isLateOutbound {
-			s.logger.Trace("post-starting outbound/", outbound.Tag())
 			err := lateOutbound.PostStart()
 			if err != nil {
 				return E.Cause(err, "post-start outbound/", outbound.Tag())
 			}
 		}
 	}
-	s.logger.Trace("post-starting router")
 	err := s.router.PostStart()
 	if err != nil {
 		return E.Cause(err, "post-start router")
@@ -322,47 +327,53 @@ func (s *Box) Close() error {
 	default:
 		close(s.done)
 	}
+	monitor := taskmonitor.New(s.logger, C.DefaultStopTimeout)
 	var errors error
 	for serviceName, service := range s.postServices {
-		s.logger.Trace("closing ", serviceName)
+		monitor.Start("close ", serviceName)
 		errors = E.Append(errors, service.Close(), func(err error) error {
 			return E.Cause(err, "close ", serviceName)
 		})
+		monitor.Finish()
 	}
 	for i, in := range s.inbounds {
-		s.logger.Trace("closing inbound/", in.Type(), "[", i, "]")
+		monitor.Start("close inbound/", in.Type(), "[", i, "]")
 		errors = E.Append(errors, in.Close(), func(err error) error {
 			return E.Cause(err, "close inbound/", in.Type(), "[", i, "]")
 		})
+		monitor.Finish()
 	}
 	for i, out := range s.outbounds {
-		s.logger.Trace("closing outbound/", out.Type(), "[", i, "]")
+		monitor.Start("close outbound/", out.Type(), "[", i, "]")
 		errors = E.Append(errors, common.Close(out), func(err error) error {
 			return E.Cause(err, "close outbound/", out.Type(), "[", i, "]")
 		})
+		monitor.Finish()
 	}
-	s.logger.Trace("closing router")
+	monitor.Start("close router")
 	if err := common.Close(s.router); err != nil {
 		errors = E.Append(errors, err, func(err error) error {
 			return E.Cause(err, "close router")
 		})
 	}
+	monitor.Finish()
 	for serviceName, service := range s.preServices1 {
-		s.logger.Trace("closing ", serviceName)
+		monitor.Start("close ", serviceName)
 		errors = E.Append(errors, service.Close(), func(err error) error {
 			return E.Cause(err, "close ", serviceName)
 		})
+		monitor.Finish()
 	}
 	for serviceName, service := range s.preServices2 {
-		s.logger.Trace("closing ", serviceName)
+		monitor.Start("close ", serviceName)
 		errors = E.Append(errors, service.Close(), func(err error) error {
 			return E.Cause(err, "close ", serviceName)
 		})
+		monitor.Finish()
 	}
-	s.logger.Trace("closing log factory")
 	if err := common.Close(s.logFactory); err != nil {
 		errors = E.Append(errors, err, func(err error) error {
-			return E.Cause(err, "close log factory")
+			return E.Cause(err, "close logger")
 		})
 	}
 	return errors

diff --git a/box_outbound.go b/box_outbound.go
@@ -4,12 +4,15 @@ import (
 	"strings"
 
 	"github.com/sagernet/sing-box/adapter"
+	"github.com/sagernet/sing-box/common/taskmonitor"
+	C "github.com/sagernet/sing-box/constant"
 	"github.com/sagernet/sing/common"
 	E "github.com/sagernet/sing/common/exceptions"
 	F "github.com/sagernet/sing/common/format"
 )
 
 func (s *Box) startOutbounds() error {
+	monitor := taskmonitor.New(s.logger, C.DefaultStartTimeout)
 	outboundTags := make(map[adapter.Outbound]string)
 	outbounds := make(map[string]adapter.Outbound)
 	for i, outboundToStart := range s.outbounds {
@@ -43,8 +46,9 @@ func (s *Box) startOutbounds() error {
 			started[outboundTag] = true
 			canContinue = true
 			if starter, isStarter := outboundToStart.(common.Starter); isStarter {
-				s.logger.Trace("initializing outbound/", outboundToStart.Type(), "[", outboundTag, "]")
+				monitor.Start("initialize outbound/", outboundToStart.Type(), "[", outboundTag, "]")
 				err := starter.Start()
+				monitor.Finish()
 				if err != nil {
 					return E.Cause(err, "initialize outbound/", outboundToStart.Type(), "[", outboundTag, "]")
 				}

diff --git a/cmd/sing-box/cmd_run.go b/cmd/sing-box/cmd_run.go
@@ -13,6 +13,7 @@ import (
 	"time"
 
 	"github.com/sagernet/sing-box"
+	C "github.com/sagernet/sing-box/constant"
 	"github.com/sagernet/sing-box/log"
 	"github.com/sagernet/sing-box/option"
 	E "github.com/sagernet/sing/common/exceptions"
@@ -193,7 +194,7 @@ func run() error {
 }
 
 func closeMonitor(ctx context.Context) {
-	time.Sleep(3 * time.Second)
+	time.Sleep(C.DefaultStopFatalTimeout)
 	select {
 	case <-ctx.Done():
 		return

diff --git a/cmd/sing-box/main.go b/cmd/sing-box/main.go
@@ -1,6 +1,7 @@
 package main
 
 import (
+	"context"
 	"os"
 	"time"
 
@@ -37,7 +38,7 @@ func main() {
 
 func preRun(cmd *cobra.Command, args []string) {
 	if disableColor {
-		log.SetStdLogger(log.NewFactory(log.Formatter{BaseTime: time.Now(), DisableColors: true}, os.Stderr, nil).Logger())
+		log.SetStdLogger(log.NewDefaultFactory(context.Background(), log.Formatter{BaseTime: time.Now(), DisableColors: true}, os.Stderr, "", nil, false).Logger())
 	}
 	if workingDir != "" {
 		_, err := os.Stat(workingDir)

diff --git a/common/taskmonitor/monitor.go b/common/taskmonitor/monitor.go
@@ -0,0 +1,31 @@
+package taskmonitor
+
+import (
+	"time"
+
+	F "github.com/sagernet/sing/common/format"
+	"github.com/sagernet/sing/common/logger"
+)
+
+type Monitor struct {
+	logger  logger.Logger
+	timeout time.Duration
+	timer   *time.Timer
+}
+
+func New(logger logger.Logger, timeout time.Duration) *Monitor {
+	return &Monitor{
+		logger:  logger,
+		timeout: timeout,
+	}
+}
+
+func (m *Monitor) Start(taskName ...any) {
+	m.timer = time.AfterFunc(m.timeout, func() {
+		m.logger.Warn(F.ToString(taskName...), " take too much time to finish!")
+	})
+}
+
+func (m *Monitor) Finish() {
+	m.timer.Stop()
+}
diff --git a/constant/timeout.go b/constant/timeout.go
@@ -11,4 +11,7 @@ const (
 	UDPTimeout                = 5 * time.Minute
 	DefaultURLTestInterval    = 3 * time.Minute
 	DefaultURLTestIdleTimeout = 30 * time.Minute
+	DefaultStartTimeout       = 10 * time.Second
+	DefaultStopTimeout        = 5 * time.Second
+	DefaultStopFatalTimeout   = 10 * time.Second
 )
diff --git a/inbound/tun.go b/inbound/tun.go
@@ -7,6 +7,7 @@ import (
 	"strings"
 
 	"github.com/sagernet/sing-box/adapter"
+	"github.com/sagernet/sing-box/common/taskmonitor"
 	C "github.com/sagernet/sing-box/constant"
 	"github.com/sagernet/sing-box/experimental/libbox/platform"
 	"github.com/sagernet/sing-box/log"
@@ -141,7 +142,6 @@ func (t *Tun) Tag() string {
 
 func (t *Tun) Start() error {
 	if C.IsAndroid && t.platformInterface == nil {
-		t.logger.Trace("building android rules")
 		t.tunOptions.BuildAndroidRules(t.router.PackageManager(), t)
 	}
 	if t.tunOptions.Name == "" {
@@ -151,12 +151,14 @@ func (t *Tun) Start() error {
 		tunInterface tun.Tun
 		err          error
 	)
-	t.logger.Trace("opening interface")
+	monitor := taskmonitor.New(t.logger, C.DefaultStartTimeout)
+	monitor.Start("open tun interface")
 	if t.platformInterface != nil {
 		tunInterface, err = t.platformInterface.OpenTun(&t.tunOptions, t.platformOptions)
 	} else {
 		tunInterface, err = tun.New(t.tunOptions)
 	}
+	monitor.Finish()
 	if err != nil {
 		return E.Cause(err, "configure tun interface")
 	}
@@ -179,8 +181,9 @@ func (t *Tun) Start() error {
 	if err != nil {
 		return err
 	}
-	t.logger.Trace("starting stack")
+	monitor.Start("initiating tun stack")
 	err = t.tunStack.Start()
+	monitor.Finish()
 	if err != nil {
 		return err
 	}