Avoid opening log output before start &

Replace tracing logs with task monitor

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,7 +300,6 @@ 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)
@@ -300,14 +307,12 @@ func (s *Box) postStart() error {
 	}
 	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

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, "]")
 				}

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

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)

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

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
 )

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
 	}

log/default.go

@@ -1,137 +0,0 @@
-package log
-
-import (
-	"context"
-	"io"
-	"os"
-	"time"
-
-	C "github.com/sagernet/sing-box/constant"
-	F "github.com/sagernet/sing/common/format"
-)
-
-var _ Factory = (*simpleFactory)(nil)
-
-type simpleFactory struct {
-	formatter         Formatter
-	platformFormatter Formatter
-	writer            io.Writer
-	platformWriter    PlatformWriter
-	level             Level
-}
-
-func NewFactory(formatter Formatter, writer io.Writer, platformWriter PlatformWriter) Factory {
-	return &simpleFactory{
-		formatter: formatter,
-		platformFormatter: Formatter{
-			BaseTime:         formatter.BaseTime,
-			DisableColors:    C.IsDarwin || C.IsIos,
-			DisableLineBreak: true,
-		},
-		writer:         writer,
-		platformWriter: platformWriter,
-		level:          LevelTrace,
-	}
-}
-
-func (f *simpleFactory) Level() Level {
-	return f.level
-}
-
-func (f *simpleFactory) SetLevel(level Level) {
-	f.level = level
-}
-
-func (f *simpleFactory) Logger() ContextLogger {
-	return f.NewLogger("")
-}
-
-func (f *simpleFactory) NewLogger(tag string) ContextLogger {
-	return &simpleLogger{f, tag}
-}
-
-func (f *simpleFactory) Close() error {
-	return nil
-}
-
-var _ ContextLogger = (*simpleLogger)(nil)
-
-type simpleLogger struct {
-	*simpleFactory
-	tag string
-}
-
-func (l *simpleLogger) Log(ctx context.Context, level Level, args []any) {
-	level = OverrideLevelFromContext(level, ctx)
-	if level > l.level {
-		return
-	}
-	nowTime := time.Now()
-	message := l.formatter.Format(ctx, level, l.tag, F.ToString(args...), nowTime)
-	if level == LevelPanic {
-		panic(message)
-	}
-	l.writer.Write([]byte(message))
-	if level == LevelFatal {
-		os.Exit(1)
-	}
-	if l.platformWriter != nil {
-		l.platformWriter.WriteMessage(level, l.platformFormatter.Format(ctx, level, l.tag, F.ToString(args...), nowTime))
-	}
-}
-
-func (l *simpleLogger) Trace(args ...any) {
-	l.TraceContext(context.Background(), args...)
-}
-
-func (l *simpleLogger) Debug(args ...any) {
-	l.DebugContext(context.Background(), args...)
-}
-
-func (l *simpleLogger) Info(args ...any) {
-	l.InfoContext(context.Background(), args...)
-}
-
-func (l *simpleLogger) Warn(args ...any) {
-	l.WarnContext(context.Background(), args...)
-}
-
-func (l *simpleLogger) Error(args ...any) {
-	l.ErrorContext(context.Background(), args...)
-}
-
-func (l *simpleLogger) Fatal(args ...any) {
-	l.FatalContext(context.Background(), args...)
-}
-
-func (l *simpleLogger) Panic(args ...any) {
-	l.PanicContext(context.Background(), args...)
-}
-
-func (l *simpleLogger) TraceContext(ctx context.Context, args ...any) {
-	l.Log(ctx, LevelTrace, args)
-}
-
-func (l *simpleLogger) DebugContext(ctx context.Context, args ...any) {
-	l.Log(ctx, LevelDebug, args)
-}
-
-func (l *simpleLogger) InfoContext(ctx context.Context, args ...any) {
-	l.Log(ctx, LevelInfo, args)
-}
-
-func (l *simpleLogger) WarnContext(ctx context.Context, args ...any) {
-	l.Log(ctx, LevelWarn, args)
-}
-
-func (l *simpleLogger) ErrorContext(ctx context.Context, args ...any) {
-	l.Log(ctx, LevelError, args)
-}
-
-func (l *simpleLogger) FatalContext(ctx context.Context, args ...any) {
-	l.Log(ctx, LevelFatal, args)
-}
-
-func (l *simpleLogger) PanicContext(ctx context.Context, args ...any) {
-	l.Log(ctx, LevelPanic, args)
-}

log/export.go

@@ -9,7 +9,14 @@ import (
 var std ContextLogger
 
 func init() {
-	std = NewFactory(Formatter{BaseTime: time.Now()}, os.Stderr, nil).Logger()
+	std = NewDefaultFactory(
+		context.Background(),
+		Formatter{BaseTime: time.Now()},
+		os.Stderr,
+		"",
+		nil,
+		false,
+	).Logger()
 }
 
 func StdLogger() ContextLogger {

log/factory.go

@@ -11,11 +11,12 @@ type (
 )
 
 type Factory interface {
+	Start() error
+	Close() error
 	Level() Level
 	SetLevel(level Level)
 	Logger() ContextLogger
 	NewLogger(tag string) ContextLogger
-	Close() error
 }
 
 type ObservableFactory interface {

log/log.go

@@ -7,35 +7,9 @@ import (
 	"time"
 
 	"github.com/sagernet/sing-box/option"
-	"github.com/sagernet/sing/common"
 	E "github.com/sagernet/sing/common/exceptions"
-	"github.com/sagernet/sing/service/filemanager"
 )
 
-type factoryWithFile struct {
-	Factory
-	file *os.File
-}
-
-func (f *factoryWithFile) Close() error {
-	return common.Close(
-		f.Factory,
-		common.PtrOrNil(f.file),
-	)
-}
-
-type observableFactoryWithFile struct {
-	ObservableFactory
-	file *os.File
-}
-
-func (f *observableFactoryWithFile) Close() error {
-	return common.Close(
-		f.ObservableFactory,
-		common.PtrOrNil(f.file),
-	)
-}
-
 type Options struct {
 	Context        context.Context
 	Options        option.LogOptions
@@ -52,8 +26,8 @@ func New(options Options) (Factory, error) {
 		return NewNOPFactory(), nil
 	}
 
-	var logFile *os.File
 	var logWriter io.Writer
+	var logFilePath string
 
 	switch logOptions.Output {
 	case "":
@@ -66,26 +40,23 @@ func New(options Options) (Factory, error) {
 	case "stdout":
 		logWriter = os.Stdout
 	default:
-		var err error
-		logFile, err = filemanager.OpenFile(options.Context, logOptions.Output, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644)
-		if err != nil {
-			return nil, err
-		}
-		logWriter = logFile
+		logFilePath = logOptions.Output
 	}
 	logFormatter := Formatter{
 		BaseTime:         options.BaseTime,
-		DisableColors:    logOptions.DisableColor || logFile != nil,
-		DisableTimestamp: !logOptions.Timestamp && logFile != nil,
+		DisableColors:    logOptions.DisableColor || logFilePath != "",
+		DisableTimestamp: !logOptions.Timestamp && logFilePath != "",
 		FullTimestamp:    logOptions.Timestamp,
 		TimestampFormat:  "-0700 2006-01-02 15:04:05",
 	}
-	var factory Factory
-	if options.Observable {
-		factory = NewObservableFactory(logFormatter, logWriter, options.PlatformWriter)
-	} else {
-		factory = NewFactory(logFormatter, logWriter, options.PlatformWriter)
-	}
+	factory := NewDefaultFactory(
+		options.Context,
+		logFormatter,
+		logWriter,
+		logFilePath,
+		options.PlatformWriter,
+		options.Observable,
+	)
 	if logOptions.Level != "" {
 		logLevel, err := ParseLevel(logOptions.Level)
 		if err != nil {
@@ -95,18 +66,5 @@ func New(options Options) (Factory, error) {
 	} else {
 		factory.SetLevel(LevelTrace)
 	}
-	if logFile != nil {
-		if options.Observable {
-			factory = &observableFactoryWithFile{
-				ObservableFactory: factory.(ObservableFactory),
-				file:              logFile,
-			}
-		} else {
-			factory = &factoryWithFile{
-				Factory: factory,
-				file:    logFile,
-			}
-		}
-	}
 	return factory, nil
 }

log/nop.go

@@ -15,6 +15,14 @@ func NewNOPFactory() ObservableFactory {
 	return (*nopFactory)(nil)
 }
 
+func (f *nopFactory) Start() error {
+	return nil
+}
+
+func (f *nopFactory) Close() error {
+	return nil
+}
+
 func (f *nopFactory) Level() Level {
 	return LevelTrace
 }
@@ -72,10 +80,6 @@ func (f *nopFactory) FatalContext(ctx context.Context, args ...any) {
 func (f *nopFactory) PanicContext(ctx context.Context, args ...any) {
 }
 
-func (f *nopFactory) Close() error {
-	return nil
-}
-
 func (f *nopFactory) Subscribe() (subscription observable.Subscription[Entry], done <-chan struct{}, err error) {
 	return nil, nil, os.ErrInvalid
 }

log/observable.go

@@ -9,29 +9,44 @@ import (
 	"github.com/sagernet/sing/common"
 	F "github.com/sagernet/sing/common/format"
 	"github.com/sagernet/sing/common/observable"
+	"github.com/sagernet/sing/service/filemanager"
 )
 
-var _ Factory = (*observableFactory)(nil)
+var _ Factory = (*defaultFactory)(nil)
 
-type observableFactory struct {
+type defaultFactory struct {
+	ctx               context.Context
 	formatter         Formatter
 	platformFormatter Formatter
 	writer            io.Writer
+	file              *os.File
+	filePath          string
 	platformWriter    PlatformWriter
+	needObservable    bool
 	level             Level
 	subscriber        *observable.Subscriber[Entry]
 	observer          *observable.Observer[Entry]
 }
 
-func NewObservableFactory(formatter Formatter, writer io.Writer, platformWriter PlatformWriter) ObservableFactory {
-	factory := &observableFactory{
+func NewDefaultFactory(
+	ctx context.Context,
+	formatter Formatter,
+	writer io.Writer,
+	filePath string,
+	platformWriter PlatformWriter,
+	needObservable bool,
+) ObservableFactory {
+	factory := &defaultFactory{
+		ctx:       ctx,
 		formatter: formatter,
 		platformFormatter: Formatter{
 			BaseTime:         formatter.BaseTime,
 			DisableLineBreak: true,
 		},
 		writer:         writer,
+		filePath:       filePath,
 		platformWriter: platformWriter,
+		needObservable: needObservable,
 		level:          LevelTrace,
 		subscriber:     observable.NewSubscriber[Entry](128),
 	}
@@ -42,40 +57,53 @@ func NewObservableFactory(formatter Formatter, writer io.Writer, platformWriter
 	return factory
 }
 
-func (f *observableFactory) Level() Level {
+func (f *defaultFactory) Start() error {
+	if f.filePath != "" {
+		logFile, err := filemanager.OpenFile(f.ctx, f.filePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644)
+		if err != nil {
+			return err
+		}
+		f.writer = logFile
+		f.file = logFile
+	}
+	return nil
+}
+
+func (f *defaultFactory) Close() error {
+	return common.Close(
+		common.PtrOrNil(f.file),
+		f.observer,
+	)
+}
+
+func (f *defaultFactory) Level() Level {
 	return f.level
 }
 
-func (f *observableFactory) SetLevel(level Level) {
+func (f *defaultFactory) SetLevel(level Level) {
 	f.level = level
 }
 
-func (f *observableFactory) Logger() ContextLogger {
+func (f *defaultFactory) Logger() ContextLogger {
 	return f.NewLogger("")
 }
 
-func (f *observableFactory) NewLogger(tag string) ContextLogger {
+func (f *defaultFactory) NewLogger(tag string) ContextLogger {
 	return &observableLogger{f, tag}
 }
 
-func (f *observableFactory) Subscribe() (subscription observable.Subscription[Entry], done <-chan struct{}, err error) {
+func (f *defaultFactory) Subscribe() (subscription observable.Subscription[Entry], done <-chan struct{}, err error) {
 	return f.observer.Subscribe()
 }
 
-func (f *observableFactory) UnSubscribe(sub observable.Subscription[Entry]) {
+func (f *defaultFactory) UnSubscribe(sub observable.Subscription[Entry]) {
 	f.observer.UnSubscribe(sub)
 }
 
-func (f *observableFactory) Close() error {
-	return common.Close(
-		f.observer,
-	)
-}
-
 var _ ContextLogger = (*observableLogger)(nil)
 
 type observableLogger struct {
-	*observableFactory
+	*defaultFactory
 	tag string
 }
 
@@ -85,15 +113,26 @@ func (l *observableLogger) Log(ctx context.Context, level Level, args []any) {
 		return
 	}
 	nowTime := time.Now()
-	message, messageSimple := l.formatter.FormatWithSimple(ctx, level, l.tag, F.ToString(args...), nowTime)
-	if level == LevelPanic {
-		panic(message)
+	if l.needObservable {
+		message, messageSimple := l.formatter.FormatWithSimple(ctx, level, l.tag, F.ToString(args...), nowTime)
+		if level == LevelPanic {
+			panic(message)
+		}
+		l.writer.Write([]byte(message))
+		if level == LevelFatal {
+			os.Exit(1)
+		}
+		l.subscriber.Emit(Entry{level, messageSimple})
+	} else {
+		message := l.formatter.Format(ctx, level, l.tag, F.ToString(args...), nowTime)
+		if level == LevelPanic {
+			panic(message)
+		}
+		l.writer.Write([]byte(message))
+		if level == LevelFatal {
+			os.Exit(1)
+		}
 	}
-	l.writer.Write([]byte(message))
-	if level == LevelFatal {
-		os.Exit(1)
-	}
-	l.subscriber.Emit(Entry{level, messageSimple})
 	if l.platformWriter != nil {
 		l.platformWriter.WriteMessage(level, l.platformFormatter.Format(ctx, level, l.tag, F.ToString(args...), nowTime))
 	}

route/router.go

@@ -18,6 +18,7 @@ import (
 	"github.com/sagernet/sing-box/common/geosite"
 	"github.com/sagernet/sing-box/common/process"
 	"github.com/sagernet/sing-box/common/sniff"
+	"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"
@@ -91,6 +92,7 @@ type Router struct {
 	v2rayServer                        adapter.V2RayServer
 	platformInterface                  platform.Interface
 	needWIFIState                      bool
+	needPackageManager                 bool
 	wifiState                          adapter.WIFIState
 	started                            bool
 }
@@ -126,6 +128,9 @@ func NewRouter(
 		pauseManager:          pause.ManagerFromContext(ctx),
 		platformInterface:     platformInterface,
 		needWIFIState:         hasRule(options.Rules, isWIFIRule) || hasDNSRule(dnsOptions.Rules, isWIFIDNSRule),
+		needPackageManager: C.IsAndroid && platformInterface == nil && common.Any(inbounds, func(inbound option.Inbound) bool {
+			return len(inbound.TunOptions.IncludePackage) > 0 || len(inbound.TunOptions.ExcludePackage) > 0
+		}),
 	}
 	router.dnsClient = dns.NewClient(dns.ClientOptions{
 		DisableCache:     dnsOptions.DNSClientOptions.DisableCache,
@@ -414,26 +419,35 @@ func (r *Router) Outbounds() []adapter.Outbound {
 }
 
 func (r *Router) Start() error {
+	monitor := taskmonitor.New(r.logger, C.DefaultStartTimeout)
 	if r.needGeoIPDatabase {
+		monitor.Start("initialize geoip database")
 		err := r.prepareGeoIPDatabase()
+		monitor.Finish()
 		if err != nil {
 			return err
 		}
 	}
 	if r.needGeositeDatabase {
+		monitor.Start("initialize geosite database")
 		err := r.prepareGeositeDatabase()
+		monitor.Finish()
 		if err != nil {
 			return err
 		}
 	}
 	if r.interfaceMonitor != nil {
+		monitor.Start("initialize interface monitor")
 		err := r.interfaceMonitor.Start()
+		monitor.Finish()
 		if err != nil {
 			return err
 		}
 	}
 	if r.networkMonitor != nil {
+		monitor.Start("initialize network monitor")
 		err := r.networkMonitor.Start()
+		monitor.Finish()
 		if err != nil {
 			return err
 		}
@@ -459,12 +473,15 @@ func (r *Router) Start() error {
 		r.geositeReader = nil
 	}
 	if r.fakeIPStore != nil {
+		monitor.Start("initialize fakeip store")
 		err := r.fakeIPStore.Start()
+		monitor.Finish()
 		if err != nil {
 			return err
 		}
 	}
 	if len(r.ruleSets) > 0 {
+		monitor.Start("initialize rule-set")
 		ruleSetStartContext := NewRuleSetStartContext()
 		var ruleSetStartGroup task.Group
 		for i, ruleSet := range r.ruleSets {
@@ -480,12 +497,12 @@ func (r *Router) Start() error {
 		ruleSetStartGroup.Concurrency(5)
 		ruleSetStartGroup.FastFail()
 		err := ruleSetStartGroup.Run(r.ctx)
+		monitor.Finish()
 		if err != nil {
 			return err
 		}
 		ruleSetStartContext.Close()
 	}
-
 	var (
 		needProcessFromRuleSet   bool
 		needWIFIStateFromRuleSet bool
@@ -499,19 +516,19 @@ func (r *Router) Start() error {
 			needWIFIStateFromRuleSet = true
 		}
 	}
-	if needProcessFromRuleSet || r.needFindProcess {
-		needPackageManager := C.IsAndroid && r.platformInterface == nil
-
-		if needPackageManager {
+	if needProcessFromRuleSet || r.needFindProcess || r.needPackageManager {
+		if C.IsAndroid && r.platformInterface == nil {
+			monitor.Start("initialize package manager")
 			packageManager, err := tun.NewPackageManager(r)
+			monitor.Finish()
 			if err != nil {
 				return E.Cause(err, "create package manager")
 			}
-			if packageManager != nil {
-				err = packageManager.Start()
-				if err != nil {
-					return err
-				}
+			monitor.Start("start package manager")
+			err = packageManager.Start()
+			monitor.Finish()
+			if err != nil {
+				return E.Cause(err, "start package manager")
 			}
 			r.packageManager = packageManager
 		}
@@ -519,10 +536,12 @@ func (r *Router) Start() error {
 		if r.platformInterface != nil {
 			r.processSearcher = r.platformInterface
 		} else {
+			monitor.Start("initialize process searcher")
 			searcher, err := process.NewSearcher(process.Config{
 				Logger:         r.logger,
 				PackageManager: r.packageManager,
 			})
+			monitor.Finish()
 			if err != nil {
 				if err != os.ErrInvalid {
 					r.logger.Warn(E.Cause(err, "create process searcher"))
@@ -533,34 +552,44 @@ func (r *Router) Start() error {
 		}
 	}
 	if needWIFIStateFromRuleSet || r.needWIFIState {
+		monitor.Start("initialize WIFI state")
 		if r.platformInterface != nil && r.interfaceMonitor != nil {
 			r.interfaceMonitor.RegisterCallback(func(_ int) {
 				r.updateWIFIState()
 			})
 		}
 		r.updateWIFIState()
+		monitor.Finish()
 	}
 
 	for i, rule := range r.rules {
+		monitor.Start("initialize rule[", i, "]")
 		err := rule.Start()
+		monitor.Finish()
 		if err != nil {
 			return E.Cause(err, "initialize rule[", i, "]")
 		}
 	}
 	for i, rule := range r.dnsRules {
+		monitor.Start("initialize DNS rule[", i, "]")
 		err := rule.Start()
+		monitor.Finish()
 		if err != nil {
 			return E.Cause(err, "initialize DNS rule[", i, "]")
 		}
 	}
 	for i, transport := range r.transports {
+		monitor.Start("initialize DNS transport[", i, "]")
 		err := transport.Start()
+		monitor.Finish()
 		if err != nil {
 			return E.Cause(err, "initialize DNS server[", i, "]")
 		}
 	}
 	if r.timeService != nil {
+		monitor.Start("initialize time service")
 		err := r.timeService.Start()
+		monitor.Finish()
 		if err != nil {
 			return E.Cause(err, "initialize time service")
 		}
@@ -569,60 +598,70 @@ func (r *Router) Start() error {
 }
 
 func (r *Router) Close() error {
+	monitor := taskmonitor.New(r.logger, C.DefaultStopTimeout)
 	var err error
 	for i, rule := range r.rules {
-		r.logger.Trace("closing rule[", i, "]")
+		monitor.Start("close rule[", i, "]")
 		err = E.Append(err, rule.Close(), func(err error) error {
 			return E.Cause(err, "close rule[", i, "]")
 		})
+		monitor.Finish()
 	}
 	for i, rule := range r.dnsRules {
-		r.logger.Trace("closing dns rule[", i, "]")
+		monitor.Start("close dns rule[", i, "]")
 		err = E.Append(err, rule.Close(), func(err error) error {
 			return E.Cause(err, "close dns rule[", i, "]")
 		})
+		monitor.Finish()
 	}
 	for i, transport := range r.transports {
-		r.logger.Trace("closing transport[", i, "] ")
+		monitor.Start("close dns transport[", i, "]")
 		err = E.Append(err, transport.Close(), func(err error) error {
 			return E.Cause(err, "close dns transport[", i, "]")
 		})
+		monitor.Finish()
 	}
 	if r.geoIPReader != nil {
-		r.logger.Trace("closing geoip reader")
+		monitor.Start("close geoip reader")
 		err = E.Append(err, common.Close(r.geoIPReader), func(err error) error {
 			return E.Cause(err, "close geoip reader")
 		})
+		monitor.Finish()
 	}
 	if r.interfaceMonitor != nil {
-		r.logger.Trace("closing interface monitor")
+		monitor.Start("close interface monitor")
 		err = E.Append(err, r.interfaceMonitor.Close(), func(err error) error {
 			return E.Cause(err, "close interface monitor")
 		})
+		monitor.Finish()
 	}
 	if r.networkMonitor != nil {
-		r.logger.Trace("closing network monitor")
+		monitor.Start("close network monitor")
 		err = E.Append(err, r.networkMonitor.Close(), func(err error) error {
 			return E.Cause(err, "close network monitor")
 		})
+		monitor.Finish()
 	}
 	if r.packageManager != nil {
-		r.logger.Trace("closing package manager")
+		monitor.Start("close package manager")
 		err = E.Append(err, r.packageManager.Close(), func(err error) error {
 			return E.Cause(err, "close package manager")
 		})
+		monitor.Finish()
 	}
 	if r.timeService != nil {
-		r.logger.Trace("closing time service")
+		monitor.Start("close time service")
 		err = E.Append(err, r.timeService.Close(), func(err error) error {
 			return E.Cause(err, "close time service")
 		})
+		monitor.Finish()
 	}
 	if r.fakeIPStore != nil {
-		r.logger.Trace("closing fakeip store")
+		monitor.Start("close fakeip store")
 		err = E.Append(err, r.fakeIPStore.Close(), func(err error) error {
 			return E.Cause(err, "close fakeip store")
 		})
+		monitor.Finish()
 	}
 	return err
 }