timamsk/sing-box
1
0
Fork 0
mirror of https://github.com/SagerNet/sing-box.git synced 2026-04-11 17:47:20 +10:00
Code Issues Packages Projects Releases Wiki Activity

Add trace logging for lifecycle calls

Browse Source 
Log start/close operations with timing information for debugging.
This commit is contained in:
世界
2025-12-20 18:47:50 +08:00
parent 2fc1b672cc
commit faff3174a3
6 changed files with 156 additions and 35 deletions
Download Patch File Download Diff File Expand all files Collapse all files

22
adapter/endpoint/manager.go
View File

@@ -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 {

22
adapter/inbound/manager.go
View File

@@ -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 {

39
adapter/lifecycle.go
View File

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

37
adapter/outbound/manager.go
View File

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

22
adapter/service/manager.go
View File

@@ -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 {

49
box.go
View File

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