Add trace logging for lifecycle calls

Log start/close operations with timing information for debugging.

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 {

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 {

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
 }

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

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 {

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
 }