From abd4d8b367375d457ffeadb9b60d4c55fcd4b5e9 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E4=B8=96=E7=95=8C?= Date: Mon, 4 Dec 2023 11:47:25 +0800 Subject: [PATCH] Avoid opening log output before start & Replace tracing logs with task monitor --- box.go | 49 +++++++----- box_outbound.go | 6 +- cmd/sing-box/cmd_run.go | 3 +- cmd/sing-box/main.go | 3 +- common/taskmonitor/monitor.go | 31 ++++++++ constant/timeout.go | 3 + inbound/tun.go | 9 ++- log/default.go | 137 ---------------------------------- log/export.go | 9 ++- log/factory.go | 3 +- log/log.go | 66 +++------------- log/nop.go | 12 ++- log/observable.go | 89 +++++++++++++++------- route/router.go | 77 ++++++++++++++----- 14 files changed, 231 insertions(+), 266 deletions(-) create mode 100644 common/taskmonitor/monitor.go delete mode 100644 log/default.go diff --git a/box.go b/box.go index 8c1e3d4b..72189d94 100644 --- 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,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 diff --git a/box_outbound.go b/box_outbound.go index 676ae7af..95ba950a 100644 --- 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 index 9c54d61e..d76d3b9c 100644 --- 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 index f7974d2c..1880d1cb 100644 --- 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 new file mode 100644 index 00000000..a23990fa --- /dev/null +++ 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 index 756028ca..8d9ffbba 100644 --- 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 index 7d1f5199..f37e0825 100644 --- 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 } diff --git a/log/default.go b/log/default.go deleted file mode 100644 index c2e1c745..00000000 --- a/log/default.go +++ /dev/null @@ -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) -} diff --git a/log/export.go b/log/export.go index 743fce93..60a0abbb 100644 --- a/log/export.go +++ b/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 { diff --git a/log/factory.go b/log/factory.go index 739aa0f2..54a88228 100644 --- a/log/factory.go +++ b/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 { diff --git a/log/log.go b/log/log.go index 19dbbbd9..7b8f2843 100644 --- a/log/log.go +++ b/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 } diff --git a/log/nop.go b/log/nop.go index 06f0b872..6369e99b 100644 --- a/log/nop.go +++ b/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 } diff --git a/log/observable.go b/log/observable.go index c12cbbbe..859d45b4 100644 --- a/log/observable.go +++ b/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)) } diff --git a/route/router.go b/route/router.go index 98942d44..0e863a24 100644 --- a/route/router.go +++ b/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 }