写这篇文章的起因,是同一周里三个不同岗位的人问了我三个问题。
做设备接入的同事问:"那条属性设置指令,到底是在哪个进程、哪一秒被处理的?"运维问:"昨天下午四点那阵子卡,是数据库慢还是我自己的 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.HostNameKey | getHostIP()结果 | 标准语义键,兼容通用查询面板 |
attribute "hostname" | 同上 | 自定义键,方便按主机筛选 |
HostNameKey里填的其实是 IP 而不是主机名。这在容器化部署里是个很实用的选择:主机名常常是随机串,两台机器重名也不稀奇,而 IP 在故障时刻是最短的那条线索——拿到 IP 就能直接登上去看。
四、一个进程只允许有一个 Provider
otel.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 里的 scheme |
127.0.0.1:4318 | 正则拆 host:port | WithInsecure(),明文 HTTP |
127.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.Logger | customWriter实现io.Writer | 同上 |
log/slog(MQTT Broker) | SlogAdapter实现slog.Handler | 同上 |
| SQL 日志 | gf ORM 内建 | resource/log/sql |
先是标准库这一路。核心就是让io.Writer的Write把字节转手给 gf:
type 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.Logger:
func (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恒返回true:
func (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.path | resource/log/server | 业务日志目录 |
logger.file | {Y-m-d}.log | 一天一个文件 |
logger.rotateExpire | 1d | 按天回滚 |
logger.rotateBackupLimit | 7 | 只留最近 7 天 |
logger.stdout | true | 同时打到终端,便于前台调试 |
database.logger.path | resource/log/sql | SQL 日志单独目录 |
database.logger.level | error | 只记错误级 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 组织页查看,两版在可观测性这一层的设计思路一致。