Hide lifecycle logs for fast operations

2026-05-14 00:51:12 +03:00 · 2026-04-21 17:15:16 +08:00
parent 71f6a2ab4e
commit 83d3a6d4e1
6 changed files with 49 additions and 65 deletions
--- 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 {
--- 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 {
--- 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)")
 	}
 }
--- 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()
--- 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 {
--- 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
 }