Avoid opening log output before start &

Replace tracing logs with task monitor
This commit is contained in:
世界 2023-12-04 11:47:25 +08:00
parent 25810b50c1
commit 21283b554a
No known key found for this signature in database
GPG Key ID: CD109927C34A63C4
14 changed files with 231 additions and 266 deletions

49
box.go
View File

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

View File

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

View File

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

View File

@ -1,6 +1,7 @@
package main package main
import ( import (
"context"
"os" "os"
"time" "time"
@ -37,7 +38,7 @@ func main() {
func preRun(cmd *cobra.Command, args []string) { func preRun(cmd *cobra.Command, args []string) {
if disableColor { 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 != "" { if workingDir != "" {
_, err := os.Stat(workingDir) _, err := os.Stat(workingDir)

View File

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

View File

@ -11,4 +11,7 @@ const (
UDPTimeout = 5 * time.Minute UDPTimeout = 5 * time.Minute
DefaultURLTestInterval = 3 * time.Minute DefaultURLTestInterval = 3 * time.Minute
DefaultURLTestIdleTimeout = 30 * time.Minute DefaultURLTestIdleTimeout = 30 * time.Minute
DefaultStartTimeout = 10 * time.Second
DefaultStopTimeout = 5 * time.Second
DefaultStopFatalTimeout = 10 * time.Second
) )

View File

@ -8,6 +8,7 @@ import (
"time" "time"
"github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/adapter"
"github.com/sagernet/sing-box/common/taskmonitor"
C "github.com/sagernet/sing-box/constant" C "github.com/sagernet/sing-box/constant"
"github.com/sagernet/sing-box/experimental/libbox/platform" "github.com/sagernet/sing-box/experimental/libbox/platform"
"github.com/sagernet/sing-box/log" "github.com/sagernet/sing-box/log"
@ -142,7 +143,6 @@ func (t *Tun) Tag() string {
func (t *Tun) Start() error { func (t *Tun) Start() error {
if C.IsAndroid && t.platformInterface == nil { if C.IsAndroid && t.platformInterface == nil {
t.logger.Trace("building android rules")
t.tunOptions.BuildAndroidRules(t.router.PackageManager(), t) t.tunOptions.BuildAndroidRules(t.router.PackageManager(), t)
} }
if t.tunOptions.Name == "" { if t.tunOptions.Name == "" {
@ -152,12 +152,14 @@ func (t *Tun) Start() error {
tunInterface tun.Tun tunInterface tun.Tun
err error err error
) )
t.logger.Trace("opening interface") monitor := taskmonitor.New(t.logger, C.DefaultStartTimeout)
monitor.Start("open tun interface")
if t.platformInterface != nil { if t.platformInterface != nil {
tunInterface, err = t.platformInterface.OpenTun(&t.tunOptions, t.platformOptions) tunInterface, err = t.platformInterface.OpenTun(&t.tunOptions, t.platformOptions)
} else { } else {
tunInterface, err = tun.New(t.tunOptions) tunInterface, err = tun.New(t.tunOptions)
} }
monitor.Finish()
if err != nil { if err != nil {
return E.Cause(err, "configure tun interface") return E.Cause(err, "configure tun interface")
} }
@ -180,8 +182,9 @@ func (t *Tun) Start() error {
if err != nil { if err != nil {
return err return err
} }
t.logger.Trace("starting stack") monitor.Start("initiating tun stack")
err = t.tunStack.Start() err = t.tunStack.Start()
monitor.Finish()
if err != nil { if err != nil {
return err return err
} }

View File

@ -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)
}

View File

@ -9,7 +9,14 @@ import (
var std ContextLogger var std ContextLogger
func init() { 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 { func StdLogger() ContextLogger {

View File

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

View File

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

View File

@ -15,6 +15,14 @@ func NewNOPFactory() ObservableFactory {
return (*nopFactory)(nil) return (*nopFactory)(nil)
} }
func (f *nopFactory) Start() error {
return nil
}
func (f *nopFactory) Close() error {
return nil
}
func (f *nopFactory) Level() Level { func (f *nopFactory) Level() Level {
return LevelTrace 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) 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) { func (f *nopFactory) Subscribe() (subscription observable.Subscription[Entry], done <-chan struct{}, err error) {
return nil, nil, os.ErrInvalid return nil, nil, os.ErrInvalid
} }

View File

@ -9,29 +9,44 @@ import (
"github.com/sagernet/sing/common" "github.com/sagernet/sing/common"
F "github.com/sagernet/sing/common/format" F "github.com/sagernet/sing/common/format"
"github.com/sagernet/sing/common/observable" "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 formatter Formatter
platformFormatter Formatter platformFormatter Formatter
writer io.Writer writer io.Writer
file *os.File
filePath string
platformWriter PlatformWriter platformWriter PlatformWriter
needObservable bool
level Level level Level
subscriber *observable.Subscriber[Entry] subscriber *observable.Subscriber[Entry]
observer *observable.Observer[Entry] observer *observable.Observer[Entry]
} }
func NewObservableFactory(formatter Formatter, writer io.Writer, platformWriter PlatformWriter) ObservableFactory { func NewDefaultFactory(
factory := &observableFactory{ ctx context.Context,
formatter Formatter,
writer io.Writer,
filePath string,
platformWriter PlatformWriter,
needObservable bool,
) ObservableFactory {
factory := &defaultFactory{
ctx: ctx,
formatter: formatter, formatter: formatter,
platformFormatter: Formatter{ platformFormatter: Formatter{
BaseTime: formatter.BaseTime, BaseTime: formatter.BaseTime,
DisableLineBreak: true, DisableLineBreak: true,
}, },
writer: writer, writer: writer,
filePath: filePath,
platformWriter: platformWriter, platformWriter: platformWriter,
needObservable: needObservable,
level: LevelTrace, level: LevelTrace,
subscriber: observable.NewSubscriber[Entry](128), subscriber: observable.NewSubscriber[Entry](128),
} }
@ -42,40 +57,53 @@ func NewObservableFactory(formatter Formatter, writer io.Writer, platformWriter
return factory 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 return f.level
} }
func (f *observableFactory) SetLevel(level Level) { func (f *defaultFactory) SetLevel(level Level) {
f.level = level f.level = level
} }
func (f *observableFactory) Logger() ContextLogger { func (f *defaultFactory) Logger() ContextLogger {
return f.NewLogger("") return f.NewLogger("")
} }
func (f *observableFactory) NewLogger(tag string) ContextLogger { func (f *defaultFactory) NewLogger(tag string) ContextLogger {
return &observableLogger{f, tag} 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() return f.observer.Subscribe()
} }
func (f *observableFactory) UnSubscribe(sub observable.Subscription[Entry]) { func (f *defaultFactory) UnSubscribe(sub observable.Subscription[Entry]) {
f.observer.UnSubscribe(sub) f.observer.UnSubscribe(sub)
} }
func (f *observableFactory) Close() error {
return common.Close(
f.observer,
)
}
var _ ContextLogger = (*observableLogger)(nil) var _ ContextLogger = (*observableLogger)(nil)
type observableLogger struct { type observableLogger struct {
*observableFactory *defaultFactory
tag string tag string
} }
@ -85,6 +113,7 @@ func (l *observableLogger) Log(ctx context.Context, level Level, args []any) {
return return
} }
nowTime := time.Now() nowTime := time.Now()
if l.needObservable {
message, messageSimple := l.formatter.FormatWithSimple(ctx, level, l.tag, F.ToString(args...), nowTime) message, messageSimple := l.formatter.FormatWithSimple(ctx, level, l.tag, F.ToString(args...), nowTime)
if level == LevelPanic { if level == LevelPanic {
panic(message) panic(message)
@ -94,6 +123,16 @@ func (l *observableLogger) Log(ctx context.Context, level Level, args []any) {
os.Exit(1) os.Exit(1)
} }
l.subscriber.Emit(Entry{level, messageSimple}) 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)
}
}
if l.platformWriter != nil { if l.platformWriter != nil {
l.platformWriter.WriteMessage(level, l.platformFormatter.Format(ctx, level, l.tag, F.ToString(args...), nowTime)) l.platformWriter.WriteMessage(level, l.platformFormatter.Format(ctx, level, l.tag, F.ToString(args...), nowTime))
} }

View File

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