diff --git a/adapter/endpoint/manager.go b/adapter/endpoint/manager.go index 7d7aa4bc..535c31b4 100644 --- a/adapter/endpoint/manager.go +++ b/adapter/endpoint/manager.go @@ -4,7 +4,6 @@ import ( "context" "os" "sync" - "time" "github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/common/taskmonitor" @@ -48,13 +47,12 @@ func (m *Manager) Start(stage adapter.StartStage) error { } for _, endpoint := range m.endpoints { name := "endpoint/" + endpoint.Type() + "[" + endpoint.Tag() + "]" - m.logger.Trace(stage, " ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, stage, " ", name) err := adapter.LegacyStart(endpoint, stage) + done() if err != nil { return E.Cause(err, stage, " ", name) } - adapter.LogElapsed(m.logger, startTime, stage, " ", name) } return nil } @@ -72,14 +70,13 @@ func (m *Manager) Close() error { var err error for _, endpoint := range endpoints { name := "endpoint/" + endpoint.Type() + "[" + endpoint.Tag() + "]" - m.logger.Trace("close ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, "close ", name) monitor.Start("close ", name) err = E.Append(err, endpoint.Close(), func(err error) error { return E.Cause(err, "close ", name) }) monitor.Finish() - adapter.LogElapsed(m.logger, startTime, "close ", name) + done() } return nil } @@ -130,13 +127,12 @@ func (m *Manager) Create(ctx context.Context, router adapter.Router, logger log. if m.started { name := "endpoint/" + endpoint.Type() + "[" + endpoint.Tag() + "]" for _, stage := range adapter.ListStartStages { - m.logger.Trace(stage, " ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, stage, " ", name) err = adapter.LegacyStart(endpoint, stage) + done() if err != nil { return E.Cause(err, stage, " ", name) } - adapter.LogElapsed(m.logger, startTime, stage, " ", name) } } if existsEndpoint, loaded := m.endpointByTag[tag]; loaded { diff --git a/adapter/inbound/manager.go b/adapter/inbound/manager.go index 2d1b0d2e..d6567cde 100644 --- a/adapter/inbound/manager.go +++ b/adapter/inbound/manager.go @@ -4,7 +4,6 @@ import ( "context" "os" "sync" - "time" "github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/common/taskmonitor" @@ -47,13 +46,12 @@ func (m *Manager) Start(stage adapter.StartStage) error { m.access.Unlock() for _, inbound := range inbounds { name := "inbound/" + inbound.Type() + "[" + inbound.Tag() + "]" - m.logger.Trace(stage, " ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, stage, " ", name) err := adapter.LegacyStart(inbound, stage) + done() if err != nil { return E.Cause(err, stage, " ", name) } - adapter.LogElapsed(m.logger, startTime, stage, " ", name) } return nil } @@ -71,14 +69,13 @@ func (m *Manager) Close() error { var err error for _, inbound := range inbounds { name := "inbound/" + inbound.Type() + "[" + inbound.Tag() + "]" - m.logger.Trace("close ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, "close ", name) monitor.Start("close ", name) err = E.Append(err, inbound.Close(), func(err error) error { return E.Cause(err, "close ", name) }) monitor.Finish() - adapter.LogElapsed(m.logger, startTime, "close ", name) + done() } return nil } @@ -132,13 +129,12 @@ func (m *Manager) Create(ctx context.Context, router adapter.Router, logger log. if m.started { name := "inbound/" + inbound.Type() + "[" + inbound.Tag() + "]" for _, stage := range adapter.ListStartStages { - m.logger.Trace(stage, " ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, stage, " ", name) err = adapter.LegacyStart(inbound, stage) + done() if err != nil { return E.Cause(err, stage, " ", name) } - adapter.LogElapsed(m.logger, startTime, stage, " ", name) } } if existsInbound, loaded := m.inboundByTag[tag]; loaded { diff --git a/adapter/lifecycle.go b/adapter/lifecycle.go index ebc0a303..2a6a8ed7 100644 --- a/adapter/lifecycle.go +++ b/adapter/lifecycle.go @@ -77,33 +77,38 @@ func getServiceName(service any) string { func Start(logger log.ContextLogger, stage StartStage, services ...Lifecycle) error { for _, service := range services { name := getServiceName(service) - logger.Trace(stage, " ", name) - startTime := time.Now() + done := LogElapsed(logger, stage, " ", name) err := service.Start(stage) + done() if err != nil { return err } - LogElapsed(logger, startTime, stage, " ", name) } return nil } func StartNamed(logger log.ContextLogger, stage StartStage, services []LifecycleService) error { for _, service := range services { - logger.Trace(stage, " ", service.Name()) - startTime := time.Now() + done := LogElapsed(logger, stage, " ", service.Name()) err := service.Start(stage) + done() if err != nil { return E.Cause(err, stage.String(), " ", service.Name()) } - LogElapsed(logger, startTime, stage, " ", service.Name()) } return nil } -func LogElapsed(logger log.ContextLogger, startTime time.Time, description ...any) { - duration := time.Since(startTime) - if duration > time.Second { - logger.Trace(append(description, " completed (", F.Seconds(duration.Seconds()), "s)")...) +func LogElapsed(logger log.ContextLogger, description ...any) func() { + prefix := F.ToString(description...) + startTime := time.Now() + timer := time.AfterFunc(time.Second, func() { + logger.Trace(prefix, "...") + }) + return func() { + if timer.Stop() { + return + } + logger.Trace(prefix, " completed (", F.Seconds(time.Since(startTime).Seconds()), "s)") } } diff --git a/adapter/outbound/manager.go b/adapter/outbound/manager.go index 287f1a91..1bbad69e 100644 --- a/adapter/outbound/manager.go +++ b/adapter/outbound/manager.go @@ -6,7 +6,6 @@ import ( "os" "strings" "sync" - "time" "github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/common/taskmonitor" @@ -83,13 +82,12 @@ func (m *Manager) Start(stage adapter.StartStage) error { m.access.Unlock() for _, outbound := range outbounds { name := "outbound/" + outbound.Type() + "[" + outbound.Tag() + "]" - m.logger.Trace(stage, " ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, stage, " ", name) err := adapter.LegacyStart(outbound, stage) + done() if err != nil { return E.Cause(err, stage, " ", name) } - adapter.LogElapsed(m.logger, startTime, stage, " ", name) } } return nil @@ -116,27 +114,25 @@ func (m *Manager) startOutbounds(outbounds []adapter.Outbound) error { canContinue = true name := "outbound/" + outboundToStart.Type() + "[" + outboundTag + "]" if starter, isStarter := outboundToStart.(adapter.Lifecycle); isStarter { - m.logger.Trace("start ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, "start ", name) monitor.Start("start ", name) err := starter.Start(adapter.StartStateStart) monitor.Finish() + done() if err != nil { return E.Cause(err, "start ", name) } - adapter.LogElapsed(m.logger, startTime, "start ", name) } else if starter, isStarter := outboundToStart.(interface { Start() error }); isStarter { - m.logger.Trace("start ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, "start ", name) monitor.Start("start ", name) err := starter.Start() monitor.Finish() + done() if err != nil { return E.Cause(err, "start ", name) } - adapter.LogElapsed(m.logger, startTime, "start ", name) } } if len(started) == len(outbounds) { @@ -184,14 +180,13 @@ func (m *Manager) Close() error { for _, outbound := range outbounds { if closer, isCloser := outbound.(io.Closer); isCloser { name := "outbound/" + outbound.Type() + "[" + outbound.Tag() + "]" - m.logger.Trace("close ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, "close ", name) monitor.Start("close ", name) err = E.Append(err, closer.Close(), func(err error) error { return E.Cause(err, "close ", name) }) monitor.Finish() - adapter.LogElapsed(m.logger, startTime, "close ", name) + done() } } return nil @@ -274,13 +269,12 @@ func (m *Manager) Create(ctx context.Context, router adapter.Router, logger log. if m.started { name := "outbound/" + outbound.Type() + "[" + outbound.Tag() + "]" for _, stage := range adapter.ListStartStages { - m.logger.Trace(stage, " ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, stage, " ", name) err = adapter.LegacyStart(outbound, stage) + done() if err != nil { return E.Cause(err, stage, " ", name) } - adapter.LogElapsed(m.logger, startTime, stage, " ", name) } } m.access.Lock() diff --git a/adapter/service/manager.go b/adapter/service/manager.go index 8ae961de..1a83c503 100644 --- a/adapter/service/manager.go +++ b/adapter/service/manager.go @@ -4,7 +4,6 @@ import ( "context" "os" "sync" - "time" "github.com/sagernet/sing-box/adapter" "github.com/sagernet/sing-box/common/taskmonitor" @@ -45,13 +44,12 @@ func (m *Manager) Start(stage adapter.StartStage) error { m.access.Unlock() for _, service := range services { name := "service/" + service.Type() + "[" + service.Tag() + "]" - m.logger.Trace(stage, " ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, stage, " ", name) err := adapter.LegacyStart(service, stage) + done() if err != nil { return E.Cause(err, stage, " ", name) } - adapter.LogElapsed(m.logger, startTime, stage, " ", name) } return nil } @@ -69,14 +67,13 @@ func (m *Manager) Close() error { var err error for _, service := range services { name := "service/" + service.Type() + "[" + service.Tag() + "]" - m.logger.Trace("close ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, "close ", name) monitor.Start("close ", name) err = E.Append(err, service.Close(), func(err error) error { return E.Cause(err, "close ", name) }) monitor.Finish() - adapter.LogElapsed(m.logger, startTime, "close ", name) + done() } return nil } @@ -127,13 +124,12 @@ func (m *Manager) Create(ctx context.Context, logger log.ContextLogger, tag stri if m.started { name := "service/" + service.Type() + "[" + service.Tag() + "]" for _, stage := range adapter.ListStartStages { - m.logger.Trace(stage, " ", name) - startTime := time.Now() + done := adapter.LogElapsed(m.logger, stage, " ", name) err = adapter.LegacyStart(service, stage) + done() if err != nil { return E.Cause(err, stage, " ", name) } - adapter.LogElapsed(m.logger, startTime, stage, " ", name) } } if existsService, loaded := m.serviceByTag[tag]; loaded { diff --git a/box.go b/box.go index 549f2fe0..c88a9bc9 100644 --- a/box.go +++ b/box.go @@ -515,27 +515,24 @@ func (s *Box) Close() error { {"dns-transport", s.dnsTransport}, {"network", s.network}, } { - s.logger.Trace("close ", closeItem.name) - startTime := time.Now() + done := adapter.LogElapsed(s.logger, "close ", closeItem.name) err = E.Append(err, closeItem.service.Close(), func(err error) error { return E.Cause(err, "close ", closeItem.name) }) - adapter.LogElapsed(s.logger, startTime, "close ", closeItem.name) + done() } for _, lifecycleService := range s.internalService { - s.logger.Trace("close ", lifecycleService.Name()) - startTime := time.Now() + done := adapter.LogElapsed(s.logger, "close ", lifecycleService.Name()) err = E.Append(err, lifecycleService.Close(), func(err error) error { return E.Cause(err, "close ", lifecycleService.Name()) }) - adapter.LogElapsed(s.logger, startTime, "close ", lifecycleService.Name()) + done() } - s.logger.Trace("close logger") - startTime := time.Now() + done := adapter.LogElapsed(s.logger, "close logger") err = E.Append(err, s.logFactory.Close(), func(err error) error { return E.Cause(err, "close logger") }) - adapter.LogElapsed(s.logger, startTime, "close logger") + done() return err }