From 51fd4b7e1a72942be0860e101ce9d9625c6b4a79 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=E4=B8=96=E7=95=8C?= Date: Sat, 20 Dec 2025 18:47:50 +0800 Subject: [PATCH] Add trace logging for lifecycle calls Log start/close operations with timing information for debugging. --- adapter/endpoint/manager.go | 22 ++++++++++++++--- adapter/inbound/manager.go | 22 ++++++++++++++--- adapter/lifecycle.go | 39 ++++++++++++++++++++++++++--- adapter/outbound/manager.go | 37 ++++++++++++++++++++++------ adapter/service/manager.go | 22 ++++++++++++++--- box.go | 49 ++++++++++++++++++++++++++++--------- 6 files changed, 156 insertions(+), 35 deletions(-) diff --git a/adapter/endpoint/manager.go b/adapter/endpoint/manager.go index 5a633beed..8b7c287f3 100644 --- a/adapter/endpoint/manager.go +++ b/adapter/endpoint/manager.go @@ -4,6 +4,7 @@ import ( "context" "os" "sync" + "time" "github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/common/taskmonitor" @@ -11,6 +12,7 @@ import ( "github.com/sagernet/sing-box/log" "github.com/sagernet/sing/common" E "github.com/sagernet/sing/common/exceptions" + F "github.com/sagernet/sing/common/format" ) var _ adapter.EndpointManager = (*Manager)(nil) @@ -46,10 +48,14 @@ func (m *Manager) Start(stage adapter.StartStage) error { return nil } for _, endpoint := range m.endpoints { + name := "endpoint/" + endpoint.Type() + "[" + endpoint.Tag() + "]" + m.logger.Trace(stage, " ", name) + startTime := time.Now() err := adapter.LegacyStart(endpoint, stage) if err != nil { - return E.Cause(err, stage, " endpoint/", endpoint.Type(), "[", endpoint.Tag(), "]") + return E.Cause(err, stage, " ", name) } + m.logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } return nil } @@ -66,11 +72,15 @@ func (m *Manager) Close() error { monitor := taskmonitor.New(m.logger, C.StopTimeout) var err error for _, endpoint := range endpoints { - monitor.Start("close endpoint/", endpoint.Type(), "[", endpoint.Tag(), "]") + name := "endpoint/" + endpoint.Type() + "[" + endpoint.Tag() + "]" + m.logger.Trace("close ", name) + startTime := time.Now() + monitor.Start("close ", name) err = E.Append(err, endpoint.Close(), func(err error) error { - return E.Cause(err, "close endpoint/", endpoint.Type(), "[", endpoint.Tag(), "]") + return E.Cause(err, "close ", name) }) monitor.Finish() + m.logger.Trace("close ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } return nil } @@ -119,11 +129,15 @@ func (m *Manager) Create(ctx context.Context, router adapter.Router, logger log. m.access.Lock() defer m.access.Unlock() if m.started { + name := "endpoint/" + endpoint.Type() + "[" + endpoint.Tag() + "]" for _, stage := range adapter.ListStartStages { + m.logger.Trace(stage, " ", name) + startTime := time.Now() err = adapter.LegacyStart(endpoint, stage) if err != nil { - return E.Cause(err, stage, " endpoint/", endpoint.Type(), "[", endpoint.Tag(), "]") + return E.Cause(err, stage, " ", name) } + m.logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } } if existsEndpoint, loaded := m.endpointByTag[tag]; loaded { diff --git a/adapter/inbound/manager.go b/adapter/inbound/manager.go index 89e424ac9..438c20f4b 100644 --- a/adapter/inbound/manager.go +++ b/adapter/inbound/manager.go @@ -4,6 +4,7 @@ import ( "context" "os" "sync" + "time" "github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/common/taskmonitor" @@ -11,6 +12,7 @@ import ( "github.com/sagernet/sing-box/log" "github.com/sagernet/sing/common" E "github.com/sagernet/sing/common/exceptions" + F "github.com/sagernet/sing/common/format" ) var _ adapter.InboundManager = (*Manager)(nil) @@ -45,10 +47,14 @@ func (m *Manager) Start(stage adapter.StartStage) error { inbounds := m.inbounds m.access.Unlock() for _, inbound := range inbounds { + name := "inbound/" + inbound.Type() + "[" + inbound.Tag() + "]" + m.logger.Trace(stage, " ", name) + startTime := time.Now() err := adapter.LegacyStart(inbound, stage) if err != nil { - return E.Cause(err, stage, " inbound/", inbound.Type(), "[", inbound.Tag(), "]") + return E.Cause(err, stage, " ", name) } + m.logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } return nil } @@ -65,11 +71,15 @@ func (m *Manager) Close() error { monitor := taskmonitor.New(m.logger, C.StopTimeout) var err error for _, inbound := range inbounds { - monitor.Start("close inbound/", inbound.Type(), "[", inbound.Tag(), "]") + name := "inbound/" + inbound.Type() + "[" + inbound.Tag() + "]" + m.logger.Trace("close ", name) + startTime := time.Now() + monitor.Start("close ", name) err = E.Append(err, inbound.Close(), func(err error) error { - return E.Cause(err, "close inbound/", inbound.Type(), "[", inbound.Tag(), "]") + return E.Cause(err, "close ", name) }) monitor.Finish() + m.logger.Trace("close ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } return nil } @@ -121,11 +131,15 @@ func (m *Manager) Create(ctx context.Context, router adapter.Router, logger log. m.access.Lock() defer m.access.Unlock() if m.started { + name := "inbound/" + inbound.Type() + "[" + inbound.Tag() + "]" for _, stage := range adapter.ListStartStages { + m.logger.Trace(stage, " ", name) + startTime := time.Now() err = adapter.LegacyStart(inbound, stage) if err != nil { - return E.Cause(err, stage, " inbound/", inbound.Type(), "[", inbound.Tag(), "]") + return E.Cause(err, stage, " ", name) } + m.logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } } if existsInbound, loaded := m.inboundByTag[tag]; loaded { diff --git a/adapter/lifecycle.go b/adapter/lifecycle.go index face00b76..b969c98ac 100644 --- a/adapter/lifecycle.go +++ b/adapter/lifecycle.go @@ -1,6 +1,14 @@ package adapter -import E "github.com/sagernet/sing/common/exceptions" +import ( + "reflect" + "strings" + "time" + + "github.com/sagernet/sing-box/log" + E "github.com/sagernet/sing/common/exceptions" + F "github.com/sagernet/sing/common/format" +) type SimpleLifecycle interface { Start() error @@ -48,22 +56,47 @@ type LifecycleService interface { Lifecycle } -func Start(stage StartStage, services ...Lifecycle) error { +func getServiceName(service any) string { + if named, ok := service.(interface { + Type() string + Tag() string + }); ok { + tag := named.Tag() + if tag != "" { + return named.Type() + "[" + tag + "]" + } + return named.Type() + } + t := reflect.TypeOf(service) + if t.Kind() == reflect.Ptr { + t = t.Elem() + } + return strings.ToLower(t.Name()) +} + +func Start(logger log.ContextLogger, stage StartStage, services ...Lifecycle) error { for _, service := range services { + name := getServiceName(service) + logger.Trace(stage, " ", name) + startTime := time.Now() err := service.Start(stage) if err != nil { return err } + logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } return nil } -func StartNamed(stage StartStage, services []LifecycleService) error { +func StartNamed(logger log.ContextLogger, stage StartStage, services []LifecycleService) error { for _, service := range services { + logger.Trace(stage, " ", service.Name()) + startTime := time.Now() err := service.Start(stage) if err != nil { return E.Cause(err, stage.String(), " ", service.Name()) } + logger.Trace(stage, " ", service.Name(), " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } return nil } diff --git a/adapter/outbound/manager.go b/adapter/outbound/manager.go index 0fdeb390c..5c1b5d990 100644 --- a/adapter/outbound/manager.go +++ b/adapter/outbound/manager.go @@ -6,6 +6,7 @@ import ( "os" "strings" "sync" + "time" "github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/common/taskmonitor" @@ -13,6 +14,7 @@ import ( "github.com/sagernet/sing-box/log" "github.com/sagernet/sing/common" E "github.com/sagernet/sing/common/exceptions" + F "github.com/sagernet/sing/common/format" "github.com/sagernet/sing/common/logger" ) @@ -81,10 +83,14 @@ func (m *Manager) Start(stage adapter.StartStage) error { outbounds := m.outbounds m.access.Unlock() for _, outbound := range outbounds { + name := "outbound/" + outbound.Type() + "[" + outbound.Tag() + "]" + m.logger.Trace(stage, " ", name) + startTime := time.Now() err := adapter.LegacyStart(outbound, stage) if err != nil { - return E.Cause(err, stage, " outbound/", outbound.Type(), "[", outbound.Tag(), "]") + return E.Cause(err, stage, " ", name) } + m.logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } } return nil @@ -109,22 +115,29 @@ func (m *Manager) startOutbounds(outbounds []adapter.Outbound) error { } started[outboundTag] = true canContinue = true + name := "outbound/" + outboundToStart.Type() + "[" + outboundTag + "]" if starter, isStarter := outboundToStart.(adapter.Lifecycle); isStarter { - monitor.Start("start outbound/", outboundToStart.Type(), "[", outboundTag, "]") + m.logger.Trace("start ", name) + startTime := time.Now() + monitor.Start("start ", name) err := starter.Start(adapter.StartStateStart) monitor.Finish() if err != nil { - return E.Cause(err, "start outbound/", outboundToStart.Type(), "[", outboundTag, "]") + return E.Cause(err, "start ", name) } + m.logger.Trace("start ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } else if starter, isStarter := outboundToStart.(interface { Start() error }); isStarter { - monitor.Start("start outbound/", outboundToStart.Type(), "[", outboundTag, "]") + m.logger.Trace("start ", name) + startTime := time.Now() + monitor.Start("start ", name) err := starter.Start() monitor.Finish() if err != nil { - return E.Cause(err, "start outbound/", outboundToStart.Type(), "[", outboundTag, "]") + return E.Cause(err, "start ", name) } + m.logger.Trace("start ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } } if len(started) == len(outbounds) { @@ -171,11 +184,15 @@ func (m *Manager) Close() error { var err error for _, outbound := range outbounds { if closer, isCloser := outbound.(io.Closer); isCloser { - monitor.Start("close outbound/", outbound.Type(), "[", outbound.Tag(), "]") + name := "outbound/" + outbound.Type() + "[" + outbound.Tag() + "]" + m.logger.Trace("close ", name) + startTime := time.Now() + monitor.Start("close ", name) err = E.Append(err, closer.Close(), func(err error) error { - return E.Cause(err, "close outbound/", outbound.Type(), "[", outbound.Tag(), "]") + return E.Cause(err, "close ", name) }) monitor.Finish() + m.logger.Trace("close ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } } return nil @@ -256,11 +273,15 @@ func (m *Manager) Create(ctx context.Context, router adapter.Router, logger log. return err } if m.started { + name := "outbound/" + outbound.Type() + "[" + outbound.Tag() + "]" for _, stage := range adapter.ListStartStages { + m.logger.Trace(stage, " ", name) + startTime := time.Now() err = adapter.LegacyStart(outbound, stage) if err != nil { - return E.Cause(err, stage, " outbound/", outbound.Type(), "[", outbound.Tag(), "]") + return E.Cause(err, stage, " ", name) } + m.logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } } m.access.Lock() diff --git a/adapter/service/manager.go b/adapter/service/manager.go index d58b1a777..f17aa07ef 100644 --- a/adapter/service/manager.go +++ b/adapter/service/manager.go @@ -4,6 +4,7 @@ import ( "context" "os" "sync" + "time" "github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/common/taskmonitor" @@ -11,6 +12,7 @@ import ( "github.com/sagernet/sing-box/log" "github.com/sagernet/sing/common" E "github.com/sagernet/sing/common/exceptions" + F "github.com/sagernet/sing/common/format" ) var _ adapter.ServiceManager = (*Manager)(nil) @@ -43,10 +45,14 @@ func (m *Manager) Start(stage adapter.StartStage) error { services := m.services m.access.Unlock() for _, service := range services { + name := "service/" + service.Type() + "[" + service.Tag() + "]" + m.logger.Trace(stage, " ", name) + startTime := time.Now() err := adapter.LegacyStart(service, stage) if err != nil { - return E.Cause(err, stage, " service/", service.Type(), "[", service.Tag(), "]") + return E.Cause(err, stage, " ", name) } + m.logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } return nil } @@ -63,11 +69,15 @@ func (m *Manager) Close() error { monitor := taskmonitor.New(m.logger, C.StopTimeout) var err error for _, service := range services { - monitor.Start("close service/", service.Type(), "[", service.Tag(), "]") + name := "service/" + service.Type() + "[" + service.Tag() + "]" + m.logger.Trace("close ", name) + startTime := time.Now() + monitor.Start("close ", name) err = E.Append(err, service.Close(), func(err error) error { - return E.Cause(err, "close service/", service.Type(), "[", service.Tag(), "]") + return E.Cause(err, "close ", name) }) monitor.Finish() + m.logger.Trace("close ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } return nil } @@ -116,11 +126,15 @@ func (m *Manager) Create(ctx context.Context, logger log.ContextLogger, tag stri m.access.Lock() defer m.access.Unlock() if m.started { + name := "service/" + service.Type() + "[" + service.Tag() + "]" for _, stage := range adapter.ListStartStages { + m.logger.Trace(stage, " ", name) + startTime := time.Now() err = adapter.LegacyStart(service, stage) if err != nil { - return E.Cause(err, stage, " service/", service.Type(), "[", service.Tag(), "]") + return E.Cause(err, stage, " ", name) } + m.logger.Trace(stage, " ", name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } } if existsService, loaded := m.serviceByTag[tag]; loaded { diff --git a/box.go b/box.go index 1c168820c..7885b0d41 100644 --- a/box.go +++ b/box.go @@ -443,15 +443,15 @@ func (s *Box) preStart() error { if err != nil { return E.Cause(err, "start logger") } - err = adapter.StartNamed(adapter.StartStateInitialize, s.internalService) // cache-file clash-api v2ray-api + err = adapter.StartNamed(s.logger, adapter.StartStateInitialize, s.internalService) // cache-file clash-api v2ray-api if err != nil { return err } - err = adapter.Start(adapter.StartStateInitialize, s.network, s.dnsTransport, s.dnsRouter, s.connection, s.router, s.outbound, s.inbound, s.endpoint, s.service) + err = adapter.Start(s.logger, adapter.StartStateInitialize, s.network, s.dnsTransport, s.dnsRouter, s.connection, s.router, s.outbound, s.inbound, s.endpoint, s.service) if err != nil { return err } - err = adapter.Start(adapter.StartStateStart, s.outbound, s.dnsTransport, s.dnsRouter, s.network, s.connection, s.router) + err = adapter.Start(s.logger, adapter.StartStateStart, s.outbound, s.dnsTransport, s.dnsRouter, s.network, s.connection, s.router) if err != nil { return err } @@ -463,27 +463,27 @@ func (s *Box) start() error { if err != nil { return err } - err = adapter.StartNamed(adapter.StartStateStart, s.internalService) + err = adapter.StartNamed(s.logger, adapter.StartStateStart, s.internalService) if err != nil { return err } - err = adapter.Start(adapter.StartStateStart, s.inbound, s.endpoint, s.service) + err = adapter.Start(s.logger, adapter.StartStateStart, s.inbound, s.endpoint, s.service) if err != nil { return err } - err = adapter.Start(adapter.StartStatePostStart, s.outbound, s.network, s.dnsTransport, s.dnsRouter, s.connection, s.router, s.inbound, s.endpoint, s.service) + err = adapter.Start(s.logger, adapter.StartStatePostStart, s.outbound, s.network, s.dnsTransport, s.dnsRouter, s.connection, s.router, s.inbound, s.endpoint, s.service) if err != nil { return err } - err = adapter.StartNamed(adapter.StartStatePostStart, s.internalService) + err = adapter.StartNamed(s.logger, adapter.StartStatePostStart, s.internalService) if err != nil { return err } - err = adapter.Start(adapter.StartStateStarted, s.network, s.dnsTransport, s.dnsRouter, s.connection, s.router, s.outbound, s.inbound, s.endpoint, s.service) + err = adapter.Start(s.logger, adapter.StartStateStarted, s.network, s.dnsTransport, s.dnsRouter, s.connection, s.router, s.outbound, s.inbound, s.endpoint, s.service) if err != nil { return err } - err = adapter.StartNamed(adapter.StartStateStarted, s.internalService) + err = adapter.StartNamed(s.logger, adapter.StartStateStarted, s.internalService) if err != nil { return err } @@ -497,17 +497,42 @@ func (s *Box) Close() error { default: close(s.done) } - err := common.Close( - s.service, s.endpoint, s.inbound, s.outbound, s.router, s.connection, s.dnsRouter, s.dnsTransport, s.network, - ) + var err error + for _, closeItem := range []struct { + name string + service adapter.Lifecycle + }{ + {"service", s.service}, + {"endpoint", s.endpoint}, + {"inbound", s.inbound}, + {"outbound", s.outbound}, + {"router", s.router}, + {"connection", s.connection}, + {"dns-router", s.dnsRouter}, + {"dns-transport", s.dnsTransport}, + {"network", s.network}, + } { + s.logger.Trace("close ", closeItem.name) + startTime := time.Now() + err = E.Append(err, closeItem.service.Close(), func(err error) error { + return E.Cause(err, "close ", closeItem.name) + }) + s.logger.Trace("close ", closeItem.name, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") + } for _, lifecycleService := range s.internalService { + s.logger.Trace("close ", lifecycleService.Name()) + startTime := time.Now() err = E.Append(err, lifecycleService.Close(), func(err error) error { return E.Cause(err, "close ", lifecycleService.Name()) }) + s.logger.Trace("close ", lifecycleService.Name(), " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } + s.logger.Trace("close logger") + startTime := time.Now() err = E.Append(err, s.logFactory.Close(), func(err error) error { return E.Cause(err, "close logger") }) + s.logger.Trace("close logger completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") return err }