写这篇文章的起因是同一周里三个不同岗位的人问了我三个问题。做设备接入的同事问那条属性设置指令到底是在哪个进程、哪一秒被处理的运维问昨天下午四点那阵子卡是数据库慢还是我自己的 SQL 慢负责部署的同事问我新加一个进程要接几处才能让它出现在监控里三个问题其实指向同一件事一套系统好不好排障不取决于它有没有日志而取决于观测的入口是不是只有一个。入口多了每个进程自己接一套问题就变成这次该看哪一份。SagooIoT 在这一块的做法比较克制启动链上留一个统一入口然后向三个方向出口——链路trace、日志log、运行时剖面pprof。这篇文章就按这个顺序把三个出口分别拆开看。一、入口在AllSystemInit里排在环境检查之前所有走标准启动流程的进程都会先经过command.AllSystemInit。它在里面按固定顺序铺开几件事解析启动参数、设置运行模式、锁定时区、初始化链路追踪然后才去检查数据库、Redis、时序库能不能连上。func AllSystemInit(ctx context.Context) { //运行参数处理 FlagInit(ctx) // 设置gf运行模式 SetGFMode(ctx) // 默认上海时区 if err : gtime.SetTimeZone(Asia/Shanghai); err ! nil { _ gtime.SetTimeZone(Local) g.Log().Debugf(ctx, 时区设置异常系统时区设置为Local 。err%v, err) } // 初始化链路追踪 InitTrace(ctx) // 检查环境 if err : CheckEnvironment(ctx); err ! nil { fmt.Println(系统启动失败环境检查未通过, err.Error()) os.Exit(1) } // ...缓存适配器、系统参数、规则引擎数据 }顺序是有讲究的。InitTrace放在环境检查前面意味着启动失败这件事本身也能被观测到。如果反过来时序库连不上、进程直接退出追踪还没起来这条最关键的起不来记录就只能靠翻终端输出。时区也放在前面是因为日志时间戳、gtime的默认时区、以及后面所有 span 的时间都受它影响。默认上海时区取不到就退回Local并且这条降级本身也打一条 Debug 日志——降级要留下痕迹但不该升级成 Error 把人半夜叫起来。进程入口本身很短短到几乎没有可观测性的痕迹。这正是设计意图main里不该出现初始化 Jaeger这种字眼。func main() { version.ShowLogo(BuildVersion, BuildTime, CommitID) ctx : gctx.GetInitCtx() command.AllSystemInit(ctx) app : command.GetServer(ctx) cmd : command.NewMainCommand(app.Server) cmd.Run(ctx) }二、一个 bool 开关决定这个进程要不要长出链路链路追踪默认是关的。InitTrace的第一件事就是读配置读不到就直接返回一行都不往下走。func InitTrace(ctx context.Context) { if !g.Cfg().MustGet(ctx, jaeger.switch).Bool() { return } tp, err : otlptrace.Init(helper.AppName(ctx), g.Cfg().MustGet(ctx, jaeger.endpoint).String()) if err ! nil { g.Log().Fatal(ctx, err) } helper.Event().Register(consts.EventServerClose, func(ctx context.Context, args ...interface{}) { _ tp.Shutdown(ctx) g.Log().Debug(ctx, jaeger closed ..) }) }配置里对应两行jaeger: endpoint: http://127.0.0.1:4318 # Jaeger服务地址这里有个取舍值得说开关用的是独立的jaeger.switch而不是endpoint 为空就不启用。后者看起来很省事但语义会变得很滑——地址写错一个字符系统就静默地不采数据了而你以为它在采。独立开关把要不要采和采到哪里分成两个问题排查时先看开关、再看地址不会互相干扰。开发环境不配这个键默认关闭本地跑起来不会有任何多余的网络请求生产打开一次配置全进程生效。三、进程身份名字来自配置地址来自网卡链路数据发到后端第一件事是回答这是谁发来的。otlptrace.Init接两个参数服务名和端点。服务名不是写死的常量而是从配置读// AppName 应用名称 func AppName(ctx context.Context) string { return g.Cfg().MustGet(ctx, system.name, sagooiot).String() }默认值兜底成sagooiot。多进程部署时各进程的配置文件里把system.name写成不同的值后端就能直接按服务名分组——不用在代码里判断我是 core 还是 admin。机器地址则来自网卡枚举而且有三级兜底func getHostIP() (string, error) { // 先尝试获取内网 IP intranetIPArray, err : gipv4.GetIntranetIpArray() if err ! nil { return , err } // 如果内网 IP 为空尝试获取所有 IP if len(intranetIPArray) 0 { intranetIPArray, err gipv4.GetIpArray() if err ! nil { return , err } } // 如果有可用 IP返回第一个 if len(intranetIPArray) 0 { return intranetIPArray[0], nil } return defaultHostIP, nil }优先内网 IP是因为物联网系统基本都部署在内网拿不到内网再退到全部网卡实在一个都没有返回常量NoHostIpFound而不是空字符串。这个常量的价值在于可查询后端里看到一堆NoHostIpFound说明是容器网络异常而不是数据缺字段。拿到的地址会被写进 Resource 的三个属性里Resource 属性取值来源用途semconv.ServiceNameKey配置system.name后端按服务名分组、区分进程semconv.HostNameKeygetHostIP()结果标准语义键兼容通用查询面板attribute hostname同上自定义键方便按主机筛选HostNameKey里填的其实是 IP 而不是主机名。这在容器化部署里是个很实用的选择主机名常常是随机串两台机器重名也不稀奇而 IP 在故障时刻是最短的那条线索——拿到 IP 就能直接登上去看。四、一个进程只允许有一个 Providerotel.SetTracerProvider设置的是全局变量。这件事带来一个容易被忽略的后果如果初始化被调用两次第二次会把第一次的 provider 覆盖掉而第一次那个 provider 的批处理队列里攒着的 span就再也没人负责导出了。otlptrace用sync.Once把这件事彻底封住var ( // 使用 sync.Once 确保只初始化一次 initOnce sync.Once // 缓存 TracerProvider 实例 globalTP *trace.TracerProvider ) func Init(serviceName, endpoint string) (*trace.TracerProvider, error) { var initErr error // 使用 sync.Once 确保只初始化一次避免重复初始化 initOnce.Do(func() { globalTP, initErr initTracer(serviceName, endpoint) }) if initErr ! nil { return nil, initErr } return globalTP, nil }Init被设计成可以随便调多处调用拿到的是同一个*trace.TracerProvider指针Shutdown也只需要执行一次。对使用方来说最省心的写法是我需要追踪就在启动时调一次不需要自己维护单例。导出器用的是 HTTP 版 OTLP带批处理tp : trace.NewTracerProvider( // 使用批处理器提高性能 trace.WithBatcher(exp), // 记录应用信息到 Resource trace.WithResource(resource.NewWithAttributes( semconv.SchemaURL, semconv.ServiceNameKey.String(serviceName), semconv.HostNameKey.String(hostIP), attribute.String(tracerHostnameTagKey, hostIP), )), ) // 设置全局 TracerProvider otel.SetTracerProvider(tp)批处理在这里不是性能优化而是隔离span 结束时只是把数据塞进队列真正发网络请求是后台协程做的事。业务代码的耗时不会被追踪后端的抖动带偏后端挂了也不会把请求链路拖慢。五、端点两种写法超时只有一个值配置里的人写地址的习惯不一样有人写127.0.0.1:4318有人写完整的http://127.0.0.1:4318。getEndpointOption把两种都接住了// 设置超时时间 opts append(opts, otlptracehttp.WithTimeout(defaultTimeout)) // 如果endpoint是http开头的完整URL if strings.HasPrefix(endpoint, http) { opts append(opts, otlptracehttp.WithEndpoint(endpoint)) return opts, nil } // 解析 endpoint 格式 match, err : gregex.MatchString((.):(\d), endpoint) if err ! nil { return nil, err } if len(match) 3 { return nil, gerror.NewCodef( gcode.CodeInvalidParameter, invalid endpoint %s, endpoint, ) } // 构造完整的 HTTP endpoint httpEndpoint : match[1] : match[2] opts append(opts, otlptracehttp.WithEndpoint(httpEndpoint)) // 默认使用 HTTP opts append(opts, otlptracehttp.WithInsecure())配置写法走的分支传输http://127.0.0.1:4318前缀判断命中按 URL 里的 scheme127.0.0.1:4318正则拆 host:portWithInsecure()明文 HTTP127.0.0.1无端口正则不匹配返回CodeInvalidParameter并回显原文第三行的处理方式是这段代码里我最喜欢的一处参数不合法时不是返回一个含糊的errors.New(bad config)而是带上gcode.CodeInvalidParameter错误码并且把原始字符串回显出来。运维看到的是invalid endpoint 127.0.0.1一眼知道少了个端口而不是去翻文档猜格式。超时统一 5 秒defaultTimeout 5 * time.Second这个值调得不激进。导出是后台批量做的5 秒足够一次正常的 OTLP/HTTP 往返真超时了Shutdown的调用方也不会被无限期挂住。六、批处理队列要有人收尾批处理有代价进程退出时队列里可能还有没发出去的 span。所以InitTrace在拿到tp之后立刻把它挂到进程关闭事件上helper.Event().Register(consts.EventServerClose, func(ctx context.Context, args ...interface{}) { _ tp.Shutdown(ctx) g.Log().Debug(ctx, jaeger closed ..) })Shutdown会先把队列刷干净再关连接这正是退出前需要的那一下。承接这个动作的是一个很小的进程内事件总线按分组存回调type sEvent struct { sync.Mutex list map[string][]EventFunc // 所有事件的列表 } func (e *sEvent) Register(group string, callback EventFunc) { e.Lock() defer e.Unlock() e.list[group] append(e.list[group], callback) } func (e *sEvent) Call(group string, ctx context.Context, args ...interface{}) { if events, ok : e.list[group]; ok { for _, f : range events { f(ctx, args...) } } }它的好处是把收尾动作从main里挪走了。谁申请了资源谁自己登记释放关闭流程只负责Call(server.close)不需要知道一共有几个组件要收尾。以后再加一个需要优雅退出的组件改的是组件自己不是启动代码。分组用字符串常量consts.EventServerClose的值是server.close。常量集中在一处避免 A 写server.close、B 写server-close这种拼写漂移。七、日志三种来源落同一个文件链路只覆盖请求怎么走日志覆盖发生了什么。SagooIoT 的日志有两个原生来源和两个外来的来源logadapter就是那道闸门。日志来源适配方式最终落点业务代码g.Log()gf 原生resource/log/server标准库log.LoggercustomWriter实现io.Writer同上log/slogMQTT BrokerSlogAdapter实现slog.Handler同上SQL 日志gf ORM 内建resource/log/sql先是标准库这一路。核心就是让io.Writer的Write把字节转手给 gftype customWriter struct { ctx context.Context prefix string } func (w *customWriter) Write(p []byte) (n int, err error) { // 使用 gf 的日志功能记录日志 g.Log().Debugf(w.ctx, %s: %s, w.prefix, string(p)) return len(p), nil } // GetLogAdapter 返回标准库logger实例 func GetLogAdapter(ctx context.Context, prefix string) *log.Logger { writer : customWriter{ ctx: ctx, prefix: prefix, } // 使用 log.New 创建新的 Logger 实例 return log.New(writer, , log.LstdFlags) }关键在于return len(p), nil。io.Writer的约定是没有报错就必须返回完整的长度很多适配器在这里返回0或者部分长度后果是调用方认为写失败、反复重试最后日志重复。这里老老实实返回len(p)语义是正确的。再进一步是LoggerWrapper它把 writer 留了个引用出来func (l *LoggerWrapper) SetContext(ctx context.Context) { l.writer.ctx ctx } func (l *LoggerWrapper) SetPrefix(prefix string) { l.writer.prefix prefix }有了这两个方法一个长期存在的 logger 可以在不同请求之间切换 ctx——日志里的RequestId跟着变而不用为每个请求都新建一个 logger。八、slog 那一桥把 Broker 的日志并进来MQTT Broker 用的是 mochi-mqtt v2它的Options.Logger类型是*slog.Logger。如果不管它Broker 的日志会走到 stderr和业务日志分家排障时要开两个窗口。SlogAdapter做的就是把slog.Handler实现一遍转发到*glog.Loggerfunc (a *SlogAdapter) Handle(ctx context.Context, r slog.Record) error { // 构建日志内容 attrs : make(map[string]interface{}) r.Attrs(func(attr slog.Attr) bool { attrs[attr.Key] attr.Value.Any() return true }) // 根据不同级别调用对应的日志方法 switch r.Level { case slog.LevelDebug: a.logger.Debug(ctx, r.Message, attrs) case slog.LevelInfo: a.logger.Info(ctx, r.Message, attrs) case slog.LevelWarn: a.logger.Warning(ctx, r.Message, attrs) case slog.LevelError: a.logger.Error(ctx, r.Message, attrs) } return nil }两个细节值得注意。第一slog.Record里的属性是链式的用Attrs回调收集成map再作为 gf 的结构化字段传进去。这样 Broker 输出的{id: tcp, protocol: http, address: :1883}这类键值在日志文件里会是可读的键值对而不是被压成一行字符串。第二Enabled恒返回truefunc (a *SlogAdapter) Enabled(ctx context.Context, level slog.Level) bool { return true }这不是偷懒而是把过滤权收归一处。gf 的日志级别在config.yaml的logger.level里配默认all如果这里再用slog自己的 level 过滤一遍就会出现两个地方都能关日志的局面——调了一个发现没生效因为另一个也在拦。恒 true 表示我不拦交给下面的 gf 决定。接线只有两行adapter : logadapter.NewSlogAdapter(ctx, g.Log()) server : mqtt.New(mqtt.Options{ // ... InlineClient: true, Logger: slog.New(adapter), })InlineClient: true让 Broker 自带一个内联客户端配合前面提到的$SYS主题Broker 自己的状态和业务日志就都在同一个进程、同一份文件里了。九、RequestId是把一次请求串成一条线的钩子一次 HTTP 请求会碰十几张表、调几个服务日志会散成几十行。把它们重新串起来靠的是 ctx 里的请求 ID——gf 的 logger 支持ctxKeys配置了哪些键就把 ctx 里对应的值自动打进每行日志的头部。# 日志配置 logger: ctxKeys: [] # 业务日志这一路留空# 数据库连接配置 database: logger: path: resource/log/sql level: error stdout: false ctxKeys: [ RequestId ]数据库这一路已经开了RequestId所以慢 SQL 能和业务日志对上业务日志这一路留了空位是因为它在不同部署形态下取值不同留给现场按需填。要串起来把同一行写成ctxKeys: [ RequestId ]即可。这是一个我很喜欢的配置设计留空而不是写死。写死了某个环境不产生这个键日志头部就会多出一对空的[];留空则是在需要的时候填一行不填也没有噪音。十、日志分目录业务一份SQL 一份日志落盘的位置和轮转策略都在配置里两个目录分开配置项值作用logger.pathresource/log/server业务日志目录logger.file{Y-m-d}.log一天一个文件logger.rotateExpire1d按天回滚logger.rotateBackupLimit7只留最近 7 天logger.stdouttrue同时打到终端便于前台调试database.logger.pathresource/log/sqlSQL 日志单独目录database.logger.levelerror只记错误级 SQL按天切、留 7 天是在够查和别把磁盘写满之间取的一个中间值——大部分线上问题当天就发现隔周再翻的概率很低。SQL 日志单独一路并且只记error是为了避免它淹掉业务日志ORM 的 SQL 日志在all级别下会把每次查询都打出来一个页面几十条业务日志夹在中间根本看不见。只留错误级等于把它定位成出问题时才需要看的那份。十一、运行时剖面只在打开开关时才有成本第三个出口是运行时的自我剖面。InitPProf也是先看开关func InitPProf(signalChannel chan os.Signal, defaultPprofPort string) { //开启系统性能分析 enablePProf : g.Cfg().MustGet(context.Background(), system.enablePProf).Bool() if enablePProf { pprofPort : g.Cfg().MustGet(context.Background(), system.pprofPort).String() if pprofPort { pprofPort defaultPprofPort } RunSystemAnalysis(signalChannel, pprofPort) // 运行系统分析 } }端口可以从配置读读不到才用调用方传进来的默认值。这个配置优先、默认兜底的写法让多进程部署时不必改代码——各进程在自己的配置里写system.pprofPort即可。真正启动的部分做了三件事func RunSystemAnalysis(stopSignal chan os.Signal, pprofPort string) { // 开启性能分析 runtime.SetMutexProfileFraction(1) // (非必需)开启对锁调用的跟踪 runtime.SetBlockProfileRate(1) // (非必需)开启对阻塞操作的跟踪 // 将Go程序运行时的各种内部数据进行可视化的展示如可以展示堆、对象、协程、GC等信息 err : statsviz.RegisterDefault() if err nil { g.Log().Infof(context.Background(), System performance analysis browser to http://localhost:%s/debug/statsviz/, pprofPort) go func() { defer func() { if err : recover(); err ! nil { g.Log().Debug(context.Background(), RunSystemAnalysis panic: %v, err) } }() s : http.Server{ Addr: : pprofPort, ReadTimeout: 30 * time.Second, WriteTimeout: 30 * time.Second, IdleTimeout: 30 * time.Second, } if err : s.ListenAndServe(); err ! nil { fmt.Println(err) } stopSignal - syscall.SIGQUIT }() } }SetMutexProfileFraction(1)和SetBlockProfileRate(1)是采样的开关1表示全量采集。全量会带来一点开销所以它们被包在enablePProf里面——默认关闭时这两行根本不会执行运行时零成本。statsviz.RegisterDefault()提供的是浏览器里的实时视图堆、对象、协程、GC刷新页面就能看到曲线不需要先在终端敲go tool pprof再去读火焰图。对一个需要长时间观察协程数量变化的物联网服务来说这个视角比一次性的快照有用得多。剖面服务跑在独立端口上和业务端口分开http.Server三个超时都设成 30 秒避免慢连接占着 goroutine 不放。监听失败时把SIGQUIT送回停止信号通道让进程按正常路径退出而不是留一个半死的服务。多进程部署时各进程端口不同比如 core 用58088、admin 用58089配置里各写各的不冲突。十二、三个出口的边界回头看这三个出口各自回答一个不同层次的问题边界划得比较清楚出口回答的问题数据形态开关链路 trace这次调用经过了哪些环节、各花多久结构化 span发往 OTLP 后端jaeger.switch日志 log那一刻系统认为发生了什么文本 结构化字段落盘logger.level剖面 pprof进程内部的资源在怎么用运行时快照与实时曲线system.enablePProf三者不重叠也不互相替代。链路能告出慢在哪一环但说不出这一环里的锁等了多久日志能说清做了什么决定但说不出决定完花了多久剖面能指出协程在涨但不知道是哪个请求带来的。把三者接在同一个启动入口上好处是加进程的时候成本很低新进程只要走标准的AllSystemInit链路和剖面的开关就自动生效日志因为走的是 gf 的全局配置也是自动生效只有在用到第三方库比如 Broker时才需要额外接一个slog桥而那也只有两行。结语可观测性这件事难点很少在要不要做而在接在哪里。接在每个进程的main里十个进程就是十份重复代码接在一个统一入口上加进程只需要复制一段main。SagooIoT 的选择是后者AllSystemInit里一行InitTrace配置里一个jaeger.switch日志靠 gf 的全局配置剖面靠system.enablePProf。三个开关、一个入口剩下的都是适配器的事——把标准库的、slog的、Broker 的日志统统导进同一份文件。代码量不大pkg/otlptrace一百多行、pkg/logadapter一百来行但把起不来时也能看见、退出前把队列刷干净、两种地址写法都能接、两个地方都能关日志这些容易漏的边角都照顾到了。这类基础组件写得好不好平时看不出来出问题时差别很大。项目地址开源仓库https://github.com/sagoo-cloud在线文档https://iotdoc.sagoo.cn本文代码基于本地部署的 SagooIoT 专业版涉及pkg/otlptrace、pkg/logadapter、pkg/utility/helper、command/global.go、command/pprof.go、mqttserver/mqtt.go与manifest/config/config.yaml。社区版源码可在 GitHub 组织页查看两版在可观测性这一层的设计思路一致。