可观测

OpenTelemetry 的 Baggage 是与上下文关联的一组字符串键值，可以让请求入口已经知道的信息继续到达下游，例如部署区域或发布分组。它与跨度属性不同，主要用途是传播；它也与链路上下文不同，承载的是应用选择的信息，而不是连接跨度的身份标识和标志。这些机制可以一起出现在一个请求里，但不能因此把它们理解为同一份数据，也不能假定它们具有相同的存储和信任语义。 跨进程传播必须落实到具体边界。发送客户端把上下文注入 HTTP 请求头等载体，接收端再从载体中提取成本地上下文。配置正确的插桩库可以自动执行这些动作，手工插桩时则要明确调用。仅在一个进程中创建行李字段，并不会把信息自动送到另一个进程、任意后台任务或外部服务。判断传播是否成功，应检查真实客户端与接收端，而不是只检查入口是否调用过设置函数。 决定哪些信息可以传播、哪些需要记录 行李字段不会自动成为跨度、日志或指标的属性。下游必须显式读取并复制，或者使用配置好的处理器执行这一映射策略。团队如果只打开传播，就期待在查询后台找到对应属性，通常会遇到数据看似消失的问题。反过来，把所有入站字段无差别复制进遥测，也可能造成语义不清、数据过大或指标基数增长。传播和记录是两个独立决定，应当分别明确目的与范围。 上下文操作返回新的上下文，不会把所有既有引用同时修改。调用者需要保留返回值，并在预期的位置传递或附加它。为某个出站请求删除不合适的行李字段时，也应保留该请求仍然需要的链路上下文。出站字段允许列表和遥测属性允许列表都应当是明确策略：某个接收者需要的值，不一定适合随后经过的全部目的地，更不一定适合永久写入所有观测记录。 坏掉的样子 行李上下文本身没有内置机制，能够证明某个值确实由可信组件签发。调用方完全可以提交请求头，自称属于昂贵账户等级或拥有特权角色。解析成功只能说明数据表示可被读取，不能说明其声明具有授权效力。认证与权限判断必须依赖各自可信的输入。即使字段很短、内容看起来合理，也不能跳过信任来源判断；本地解析器接受字符串，不等于业务系统应该接受其中的身份声明。 不受限制的行李字段会增加请求头大小，也可能把敏感信息传播给原本不该接收它的对象，包括自动插桩所覆盖的第三方接口。需要限制键名与值的范围，检查实际传播目的地，并由传播器负责线上编码。两个相同 SDK 实例之间往返成功，也不等于所有语言实现和代理组合都能够互操作。真正跨服务使用时，应验证实际途经的边界，而不是把一个进程内的演示扩大成对整个部署的保证。 快速验证 建立 Python 虚拟环境，安装 opentelemetry-sdk==1.35.0，把脚本保存为 baggage.py，并使用该环境的解释器运行。本次实际使用 Python 3.14.4。实验调用真实的 W3C 链路上下文传播器和行李传播器，并把跨度导出到内存；没有启动 HTTP 服务，字典代表客户端接下来将发送的请求头载体。因此结果直接证明编解码与上下文行为，不把尚未执行的跨服务通信写成已完成验证。 import json from opentelemetry import baggage, trace from opentelemetry.context import Context from opentelemetry.baggage.propagation import W3CBaggagePropagator from opentelemetry.propagators.composite import CompositePropagator from opentelemetry.sdk.trace import TracerProvider from opentelemetry.sdk.trace.export import SimpleSpanProcessor from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter from opentelemetry.trace.propagation.tracecontext import TraceContextTextMapPropagator base = Context() raw = baggage.set_baggage("region", "eu-west", context=base) raw = baggage.set_baggage("release", "canary/2", context=raw) raw = baggage.set_baggage("internal_note", "synthetic-only", context=raw) assert not baggage.get_all(base) propagator = CompositePropagator([TraceContextTextMapPropagator(), W3CBaggagePropagator()]) provider = TracerProvider() exporter = InMemorySpanExporter() provider.add_span_processor(SimpleSpanProcessor(exporter)) tracer = provider.get_tracer("baggage-lab") with tracer.start_as_current_span("parent", context=Context()) as parent: outgoing = trace.set_span_in_context(parent, baggage.clear(context=raw)) for key in ("region", "release"): outgoing = baggage.set_baggage(key, baggage.get_baggage(key, raw), context=outgoing) carrier = {} propagator.inject(carrier, context=outgoing) received = propagator.extract(carrier, context=Context()) assert set(baggage.get_all(received)) == {"region", "release"} assert baggage.get_baggage("region", received) == "eu-west" assert baggage.get_baggage("internal_note", raw) == "synthetic-only" assert trace.get_current_span(received).get_span_context().trace_id == parent.get_span_context().trace_id with tracer.start_as_current_span("inherited", context=received): pass with tracer.start_as_current_span("copied", context=received) as span: span.set_attribute("deployment.region", baggage.get_baggage("region", received)) assert provider.force_flush() spans = {span.name: span for span in exporter.get_finished_spans()} assert not spans["inherited"].attributes assert spans["copied"].attributes == {"deployment.region": "eu-west"} independent = propagator.extract({"traceparent": "invalid", "baggage": "region=eu-west"}, context=Context()) assert not trace.get_current_span(independent).get_span_context().is_valid assert baggage.get_baggage("region", independent) == "eu-west" untrusted = propagator.extract({"baggage": "tier=gold"}, context=Context()) assert baggage.get_baggage("tier", untrusted) == "gold" print(json.dumps({"wire_fields": sorted(carrier), "wire_baggage": carrier["baggage"], "automatic_span_attributes": dict(spans["inherited"].attributes), "explicit_span_attributes": dict(spans["copied"].attributes), "baggage_survives_invalid_traceparent": True, "caller_supplied_tier_was_parsed": True}, indent=2)) provider.shutdown() 原始上下文包含区域、发布分组和一条完全虚构的内部备注。出站上下文只保留前两个字段，同时携带原父跨度。接收后区域应为 eu-west，发布值 canary/2 经过请求头编码后还原一致。断言还检查了筛选过程没有删除原上下文中的备注，也没有改变最初的空上下文。这说明清理出站载体与修改其他引用不是同一件事，后续代码必须使用正确的上下文对象。 ...

告警标签标识正在跟踪哪一个条件，并提供路由与分组字段；注解则解释这个条件，例如当前值、简短摘要或操作手册链接。把变化中的说明文字放进标签，可能把同一个持续问题拆成多个身份；反过来，如果责任归属字段只存在于注解中，依赖标签的路由又可能无法识别应该由谁处理。两类字段都重要，但承担不同职责。 区分身份与当前说明 队列告警可以保持 alertname、service 与 instance 标签稳定，同时把摘要从等待六项更新为等待八项。Alertmanager 可以在相同告警指纹下更新注解，而不是新增一条告警。指纹来自身份标签，不是通知渲染文本的哈希，所以文字改变不应该被直接理解为发生了另一个独立事件。这个边界也方便操作人员跟踪问题的持续变化。 该区别在进入 Alertmanager 之前也有影响。Prometheus 按告警标签集跟踪等待时长，如果标签中包含不断变化的当前值，就可能持续创建新身份，导致预期等待过程无法完成。除非数值确实定义另一种告警条件，否则应把它放在注解中。遇到反复等待却不触发的问题，应同时审阅规则标签和模板内容，而不是只调整等待参数。 一组告警未必拥有共同摘要 通知模板能访问多个层级的数据。GroupLabels 包含分组选择的标签，CommonLabels 包含通知中所有告警都具有的相同标签对，CommonAnnotations 同样只包含组内共有的注解。Alerts 列表则保留各成员自己的标签和注解，因此可以逐条解释不同实例的现场情况。共同字段与全部字段不是同一概念，字段存在于某条告警中也不保证它存在于组级对象中。 两个副本的摘要描述不同队列长度时，CommonAnnotations 就没有一个共同摘要。只打印该字段的模板，可能恰好省掉响应人员最需要的信息。更合理的方式是用共同上下文组织标题，再遍历每条告警输出变化中的说明。即使当前值不同，两条告警仍可能共享同一份操作手册链接，这个链接就可以继续作为共同注解使用。 也不能假定每一组都具有实例这样的分组标签。按服务与告警名分组，本来就是为了合并不同实例。模板应对应真实分组契约，并主动处理缺少共同字段的情况。代表性输入需要覆盖多条告警、不同注解，以及相关触发或恢复状态，不能只用一条理想告警验证，因为单条输入很容易让所有字段都碰巧成为共同字段。 坏掉的样子 动态标签会让每次数值变化产生新指纹，增加告警变化量，并可能重新开始等待。匹配 team 的路由不能用同名注解代替标签；分组策略与模板假设不一致时，通知标题也可能只描述一台实例，正文却混入不同服务的告警。应把身份、分组与展示作为一条真实调用链检查，避免各部分单独看起来合理，组合后却误导读者。 模板语法通过，并不保证真实分组数据能渲染出完整且准确的消息。应核对渲染内容，而不是只检查解析成功。反过来，渲染成功也不能证明通知集成接受该消息，或消息已经送达。凭据与敏感请求详情不应放在注解中，因为这些文字可能被复制到路由选择的所有接收器，也可能进入后续通知记录。 快速验证 把程序保存为 annotations.py，在 Docker 可用时运行 python3 annotations.py。使用 Alertmanager 0.28.1，必要时下载镜像。隔离服务器的接收器没有实际发送集成；程序通过真实接口提交两条合成告警，然后在标签完全不变的情况下更新其中一条注解。操作只发生在本次临时服务器中，不会修改已有告警状态。 import http.client import io import json import subprocess import time import uuid name = "xbcatm-monitoring-" + uuid.uuid4().hex[:12] class ResponseSocket: def __init__(self, data): self.data = data def makefile(self, mode): return io.BytesIO(self.data) def request(method, path, body="", content_type="application/json"): body = body.encode() headers = (f"{method} {path} HTTP/1.1\r\nHost: 127.0.0.1:{port}\r\n" f"Connection: close\r\nContent-Type: {content_type}\r\n" f"Content-Length: {len(body)}\r\n\r\n").encode() result = subprocess.run( ["docker", "exec", "-i", name, "/bin/nc", "-w", "3", "127.0.0.1", str(port)], input=headers + body, capture_output=True, timeout=5, ) if result.returncode: raise RuntimeError(result.stderr.decode()) response = http.client.HTTPResponse(ResponseSocket(result.stdout)) response.begin() return response.status, response.read().decode() def get_json(path): status, body = request("GET", path) assert status == 200, (status, body) return json.loads(body) def eventually(check): for attempt in range(150): try: value = check() if value: return value except (RuntimeError, AssertionError, http.client.HTTPException): pass time.sleep(0.1) raise AssertionError("Expected local server state did not appear") port = 9093 script = r"""set -eu cat > /tmp/alertmanager.yml <<'ALERT_CONFIG' route: receiver: preview group_by: [alertname, service] group_wait: 1h group_interval: 5m repeat_interval: 4h receivers: - name: preview ALERT_CONFIG exec /bin/alertmanager --config.file=/tmp/alertmanager.yml --storage.path=/tmp/data \ --web.listen-address=127.0.0.1:9093 --cluster.listen-address= """ try: subprocess.run( ["docker", "run", "-d", "--rm", "--name", name, "--network", "none", "--entrypoint", "/bin/sh", "prom/alertmanager:v0.28.1", "-c", script], check=True, capture_output=True, text=True, timeout=20, ) eventually(lambda: request("GET", "/-/ready")[0] == 200) alerts = [{"labels": {"alertname": "QueueHigh", "service": "checkout", "instance": instance}, "annotations": {"summary": "queue=" + str(depth), "runbook": "https://example.invalid/queue"}} for instance, depth in [("api-a", 6), ("api-b", 9)]] assert request("POST", "/api/v2/alerts", json.dumps(alerts))[0] == 200 before = eventually(lambda: (a if len(a := get_json("/api/v2/alerts")) == 2 else False)) fingerprints = {a["labels"]["instance"]: a["fingerprint"] for a in before} alerts[0]["annotations"]["summary"] = "queue=8" assert request("POST", "/api/v2/alerts", json.dumps([alerts[0]]))[0] == 200 def updated_annotations(): items = get_json("/api/v2/alerts") changed = any(x["labels"]["instance"] == "api-a" and x["annotations"]["summary"] == "queue=8" for x in items) return items if changed else None updated = eventually(updated_annotations) assert len(updated) == 2 assert {a["labels"]["instance"]: a["fingerprint"] for a in updated} == fingerprints # Supply the documented notification Data shape to the real template renderer. data = {"receiver": "preview", "status": "firing", "groupLabels": {"alertname": "QueueHigh", "service": "checkout"}, "commonLabels": {"alertname": "QueueHigh", "service": "checkout"}, "commonAnnotations": {"runbook": "https://example.invalid/queue"}, "alerts": [{"status": "firing", "labels": a["labels"], "annotations": a["annotations"]} for a in sorted(updated, key=lambda a: a["labels"]["instance"])]} template = '{{define "preview"}}{{.GroupLabels.service}}|common-summary={{with .CommonAnnotations.summary}}{{.}}{{else}}none{{end}}{{range .Alerts}}\n{{.Labels.instance}}:{{.Annotations.summary}}{{end}}{{end}}' for path, content in [("/tmp/preview.tmpl", template), ("/tmp/data.json", json.dumps(data))]: subprocess.run(["docker", "exec", "-i", name, "/bin/sh", "-c", "cat > " + path], input=content, text=True, capture_output=True, check=True, timeout=5) rendered = subprocess.run(["docker", "exec", name, "/bin/amtool", "template", "render", "--template.glob=/tmp/preview.tmpl", "--template.data=/tmp/data.json", '--template.text={{ template "preview" . }}'], text=True, capture_output=True, check=True, timeout=5).stdout.strip() assert rendered == "checkout|common-summary=none\napi-a:queue=8\napi-b:queue=9", rendered print(json.dumps({"alert_count": 2, "fingerprints_unchanged": True, "rendered": rendered}, indent=2)) finally: subprocess.run(["docker", "rm", "-f", name], stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL) 结果确认更新后仍只有两条告警，指纹也保持不变。程序随后向真实 amtool 模板渲染器提供文档规定的数据结构：共同注解故意只保留共享手册链接，不放入彼此不同的摘要。这里明确提供的输入验证渲染行为，不代表已验证服务器如何组装实际通知，更不能替代发送链路测试。 ...

Linux procfs 通过文件系统接口暴露进程和内核信息。许多入口在读取时生成内容，而不是保存普通磁盘文件字节；每个入口都有具体含义、权限模型和格式。连续读取多个入口，不会冻结进程，也不会得到事务一致快照。因此，有用的观察必须对应正确进程实例和正确解释，不能因为内容都来自 proc，就假定它们是同一时刻的完整状态。 坏掉的样子 普通文件假设可能立刻失效。proc 条目报告大小为零，却仍然返回有用内容；逐进程目录可能随着进程退出消失，数字 PID 之后也可能指向另一个实例。读取失败不一定表示系统安装损坏，某个编号也不会永久代表同一工作负载。生命周期变化本来就是观测需要处理的条件，应避免把正常退出当成异常环境。 不同入口需要按各自格式解析。status 包含有标签字段，stat 则使用固定字段顺序，其中括号包住的命令名可以包含空格和右括号。直接把整行按空白拆分，会让预期字段错位。cmdline 与 environ 使用空字符分隔，普通按行或空格切分，会破坏参数和值的边界。解析方式必须来自接口文档，而不是文件看起来像文本这一点。 视图本身也有语义边界。environ 描述程序执行时建立的环境区域，不保证是所有后续环境修改的实时字典；命令行内容也可以被进程修改。描述符链接以 deleted 结尾，不表示打开对象已经消失。这些入口提供具体状态证据，却不是可以互相替代的身份凭据或访问保证，需要先明确每项观察到底回答什么问题。 快速验证 把脚本保存为 procview.py，在一次性 Linux 环境中运行 python3 procview.py。实测使用 Linux 6.12.76 和 Python 3.11.2。脚本启动一个受控子进程，显式提供少量环境值，只读取自己及该子进程的 proc 条目，不写入内核调节接口： from pathlib import Path from tempfile import TemporaryDirectory import json,os,subprocess,sys worker=r''' from pathlib import Path import ctypes,json,os,sys assert ctypes.CDLL(None).prctl(15,b'worker ) sample',0,0,0)==0 os.environ['XB_PROC_TEST']='changed-after-start' path=Path(sys.argv[1]);path.write_bytes(b'fixture-data') with path.open('rb') as handle: info=os.fstat(handle.fileno());path.unlink() print(json.dumps({'fd':handle.fileno(),'device':info.st_dev,'inode':info.st_ino,'current_environment':os.environ['XB_PROC_TEST']}),flush=True) assert sys.stdin.readline()=='done\n' ''' with TemporaryDirectory(prefix='xbcatm-proc-') as directory: path=Path(directory)/'data' process=subprocess.Popen([sys.executable,'-c',worker,str(path),'argument with spaces'],stdin=subprocess.PIPE,stdout=subprocess.PIPE,stderr=subprocess.PIPE,text=True,env={'PATH':'/usr/bin:/bin','XB_PROC_TEST':'fixture-value'}) try: metadata=json.loads(process.stdout.readline());root=Path('/proc')/str(process.pid) status_path=root/'status';status_text=status_path.read_text() assert status_path.stat().st_size==0 and len(status_text)>0 status=dict(line.split(':',1) for line in status_text.splitlines() if ':' in line) assert int(status['Pid'])==process.pid and int(status['PPid'])==os.getpid() raw=(root/'stat').read_text();pid_text,rest=raw.split(' (',1);comm,fields=rest.rsplit(') ',1) fields=fields.split();assert int(pid_text)==process.pid and comm=='worker ) sample' assert int(fields[1])==os.getpid() and int(fields[19])>0 assert raw.split()[2] not in ('R','S','D','T','Z') print('proc files can have size zero but readable data; stat comm can contain spaces and a closing parenthesis') args=(root/'cmdline').read_bytes().rstrip(b'\0').split(b'\0') environment=(root/'environ').read_bytes().rstrip(b'\0').split(b'\0') assert args[-1]==b'argument with spaces' and b'XB_PROC_TEST=fixture-value' in environment assert metadata['current_environment']=='changed-after-start' assert os.readlink('/proc/self')==str(os.getpid()) print('cmdline and environ use NUL separators; environ retains the initial value here; self resolves for the reader') entry=root/'fd'/str(metadata['fd']);target=os.readlink(entry);actual=entry.stat() assert target==str(path)+' (deleted)' and not path.exists() assert (actual.st_dev,actual.st_ino)==(metadata['device'],metadata['inode']) assert entry.read_bytes()==b'fixture-data' print('a deleted pathname remains inspectable through an open descriptor subject to access checks') output,error=process.communicate('done\n',timeout=5) assert process.returncode==0,error assert not root.exists() print('after the controlled child exits and is reaped, its proc directory disappears') finally: if process.poll() is None:process.kill();process.wait() 子进程把短名称设为带空格和右括号的 worker ) sample，打开临时文件，再删除路径但保持描述符打开。随后它仅报告样本元数据并等待，让控制进程拥有一份已知存活对象。这个名称刻意触发 stat 格式边界，使解析验证不依赖“进程名碰巧没有空格”的理想情况。 ...

一张有用的看板，应该帮助读者决定接下来检查什么。它把大量观测归纳成少数几个问题：用户操作是否成功，影响发生在哪里，资源是否正在逼近限制。但归纳不能抹掉重要区别。全局成功率仍然很好看时，一个区域可能已经严重失败；面板空白也可能是遥测缺失，而不是服务处于安静且健康的状态。看板的价值在于减少重新推理的负担，同时保留做判断必需的上下文。 给页面安排清楚的阅读顺序 先展示服务结果和观测覆盖，再给出流量、延迟、错误以及有关资源的饱和信息。如果区域、操作类型或依赖的差异会改变下一步行动，就提供对应下钻入口。变更标记和诊断资料链接也应放在相关视图附近。曲线同时变化可以帮助选择调查方向，但仅凭发生时间接近，还不能证明某次部署或某个依赖导致了事故，仍需进一步验证真实链路。 每个面板应该回答明确的问题，但不要求只放一个指标。队列长度与配置上限使用相同单位，并列比较就很有意义；把不同单位放进复杂双轴图，则容易制造没有根据的视觉关系。应直接说明单位、聚合窗口、统计总体以及阈值含义，让读者不必凭记忆猜测坐标表示毫秒、秒、零到一比例还是百分数。含义清楚通常比增加面板数量更重要。 保留请求权重和观测覆盖 计算服务错误比例时，应使用相同窗口中的全部不良事件数除以全部符合条件的事件数。直接平均区域百分比，会让很安静的区域与繁忙区域获得相同权重，这已经换成另一种统计量，不是无关紧要的显示方式。即使全局值按请求正确加权，当小范围用户仍属于服务承诺的一部分时，也需要展示能定位影响的区域或操作细分。 新鲜度同样决定统计范围。应展示最近一次成功观测的时间，或者明确的覆盖信号，并约定何时把陈旧数据视为未知。业务看板选择的新鲜度阈值，与存储系统处理时序失效的机制是不同概念。把缺口一律补零，可能让已经不可用的采集器表现成完美错误率或空队列。缺失状态应被保留下来，并提供下一步排查采集链路或服务本身的方向。 坏掉的样子 自动缩放的纵轴可能把微小变化放大成重大事故，过宽的固定范围又可能掩盖真正越过阈值的变化。应根据运维问题选择刻度，让需要比较的面板保持一致。平均延迟还会藏起慢请求群体，需要合适的分布与观测数量作为补充；不能直接平均不同实例已经计算出的高分位数，再把它当成整个服务的尾部延迟。 外观漂亮的页面也可能只是一些互不相关的快照。时区、过滤条件、刷新频率和聚合窗口不同，会妨碍连贯比较。共享变量应有明确默认值和可见范围，尤其要让读者知道当前是否查看生产环境以及哪些区域。应拿区域故障、低流量和观测缺失来检查看板，如果三种场景都表现为绿色，就说明页面在压缩信息时丢掉了做决策所需的关键事实。 快速验证 将代码保存为 dashboard.py 并用 Python 3 执行。它基于一个完整六十秒窗口中的模拟计数，计算可以用于面板展示的值。两个区域有新鲜观测，另一个区域既缺少数值，最近观测时间也较旧。九十秒阈值是示例看板的业务规则，并不是 Prometheus 默认行为；验证这部分聚合逻辑不需要安装 Grafana，也不会操作任何现有仪表盘。 import json from fractions import Fraction # Counts cover the same completed 60-second interval. rows = [ {"region": "west", "requests": 9800, "errors": 0, "age_seconds": 10}, {"region": "east", "requests": 200, "errors": 100, "age_seconds": 10}, {"region": "south", "requests": None, "errors": None, "age_seconds": 240}, ] fresh = [r for r in rows if r["age_seconds"] <= 90 and r["requests"] is not None and r["errors"] is not None] missing = [r["region"] for r in rows if r not in fresh] requests = sum(r["requests"] for r in fresh) errors = sum(r["errors"] for r in fresh) regional = {r["region"]: Fraction(r["errors"], r["requests"]) for r in fresh} known_ratio = Fraction(errors, requests) unweighted = sum(regional.values()) / len(regional) assert known_ratio == Fraction(1, 100) assert regional["east"] == Fraction(1, 2) and unweighted == Fraction(1, 4) assert missing == ["south"] print(json.dumps({ "coverage": "incomplete", "fresh_requests_per_second": round(requests / 60, 3), "fresh_error_percent": float(known_ratio * 100), "regional_error_percent": {k: float(v * 100) for k, v in regional.items()}, "wrong_unweighted_percent": float(unweighted * 100), "unknown_regions": missing, }, indent=2)) 新鲜观测合计一万次请求、一百次错误，对应每秒约一百六十六点六六七次请求，以及按请求加权后的百分之一错误率。然而流量较小的东部区域有一半请求失败。若直接平均两个区域的百分比，会错误地把合并请求错误比例写成百分之二十五。正确方式是让百分之一的总体值与区域细分共同出现，而不是挑选某一个数字来遮住另一个事实。 ...

nginx 访问日志在请求处理末尾执行记录。选择合适字段，可以区分客户端请求了什么、最终由哪个 URI 处理、发送了什么响应，以及上游尝试期间发生了什么。这些是不同观察。有用格式会保留区别，而不是假定一个状态、耗时或路径就能独立解释整个请求。字段越准确地对应事件，事故期间越容易沿实际处理链定位问题。 坏掉的样子 最终客户端状态可以隐藏较早上游失败。如果 nginx 成功重试其他服务器，客户端可能得到 200，但尝试列表仍记录第一次连接失败。反过来，本地生成的响应没有上游操作可计时。把每个请求都当成恰好一次后端响应，会丢失解释重试和本地处理所需的信息，也可能把成功率与上游健康情况混在一起。 内部跳转后，原始和当前 URI 字段也不同。$request 保留请求行，$request_uri 保留原 URI 和查询，$uri 则可能反映后来的规范化或重写路径。只记录最终 URI，调查者可能不知道哪个公共地址触发它；只记录原始路径，又可能看不到最终处理器上下文。两类字段需要按各自含义使用。 时间字段不是总能直接相减并得到精确诊断的独立延迟组件。请求时间覆盖到 nginx 日志采用的客户端侧完成点，上游时间字段则描述自己的阶段，还可能包含多次尝试。分辨率、缺失值和边界都重要；毫秒显示看起来为零，不证明没有执行工作。粗粒度测量与真实无耗时不能混为一谈。 快速验证 使用宿主 Python、Docker，以及固定 nginx 和 Python 镜像运行脚本。实测为 Linux arm64 上的 nginx 1.28.0、Python 3.11.16、Docker 29.3.1。它配置真实后端，以及代理容器内一个没有监听者的端口，检查 nginx 配置，只发布宿主回环代理端口，读取日志后清理自身资源，不向外部未知服务发送探测： from contextlib import contextmanager from pathlib import Path from tempfile import TemporaryDirectory import http.client,json,socket,subprocess,time,uuid NGINX='nginx@sha256:552e7481ca93ffccd046aa658dbbed22caefbc09c66fa7cd247cbb90b8a5c609' PYTHON='python@sha256:528257d48c1da0dcecc2e725d1ae34498d60c965f1241e39cd6a85a8859bdf84' def docker(*args,check=True): result=subprocess.run(['docker',*args],capture_output=True,text=True,timeout=120) if check:assert result.returncode==0,result.stderr return result def wait(predicate): deadline=time.monotonic()+15 while time.monotonic()<deadline: try: if predicate():return except OSError:pass time.sleep(.1) raise AssertionError('fixture did not become ready') @contextmanager def lab(configuration,files=None,backend=None): name='xbcatm-nginx-'+uuid.uuid4().hex[:10];tags=[name+':proxy',name+':backend'];containers=[name+'-proxy',name+'-backend'] try: with TemporaryDirectory(prefix=name+'-') as directory: root=Path(directory);(root/'files').mkdir();(root/'nginx.conf').write_text(configuration) for path,content in (files or {}).items(): target=root/'files'/path;target.parent.mkdir(parents=True,exist_ok=True);target.write_text(content) docker('network','create',name) if backend is not None: (root/'backend.py').write_text(backend) (root/'backend.Dockerfile').write_text(f'FROM {PYTHON}\nCOPY backend.py /backend.py\nCMD ["python", "/backend.py"]\n') docker('build','--network','none','-f',str(root/'backend.Dockerfile'),'-t',tags[1],str(root)) docker('run','-d','--name',containers[1],'--network',name,'--network-alias','backend',tags[1]) wait(lambda:docker('exec',containers[1],'python','-c','import socket;s=socket.create_connection(("127.0.0.1",8081),timeout=.5);s.close()',check=False).returncode==0) (root/'Dockerfile').write_text(f'FROM {NGINX}\nCOPY nginx.conf /etc/nginx/nginx.conf\nCOPY files /srv\n') docker('build','--network','none','-t',tags[0],str(root)) docker('run','--rm','--network',name,tags[0],'nginx','-t') docker('run','-d','--name',containers[0],'--network',name,'-p','127.0.0.1::8080',tags[0]) details=json.loads(docker('inspect',containers[0]).stdout)[0] binding=details['NetworkSettings']['Ports']['8080/tcp'][0];assert binding['HostIp']=='127.0.0.1';port=int(binding['HostPort']) def ready(): connection=socket.create_connection(('127.0.0.1',port),timeout=.5);connection.close();return True wait(ready) def request(path,method='GET',headers=None,body=None): connection=http.client.HTTPConnection('127.0.0.1',port,timeout=5) try: connection.request(method,path,body=body,headers=headers or {}) response=connection.getresponse();return response.status,{k.lower():v for k,v in response.getheaders()},response.read() finally:connection.close() yield containers[0],request finally: docker('rm','-f',*containers,check=False);docker('image','rm',*tags,check=False);docker('network','rm',name,check=False) def config(locations,extra=''): return 'worker_processes 1;\nerror_log /tmp/error.log notice;\nevents {}\nhttp {\naccess_log off;\n'+extra+'\nserver { listen 8080; root /srv;\n'+locations+'\n}\n}\n' backend=r'''from http.server import BaseHTTPRequestHandler,HTTPServer import json class Handler(BaseHTTPRequestHandler): def do_GET(self): body=self.rfile.read(int(self.headers.get('Content-Length','0'))) document={'path':self.path,'method':self.command,'body':body.decode(),'headers':{key:self.headers.get(key) for key in ['Host','X-Forwarded-For','X-Real-IP','X-Forwarded-Proto','X-Forwarded-Host']}} data=json.dumps(document).encode() self.send_response(200);self.send_header('Content-Type','application/json');self.send_header('Content-Length',str(len(data)));self.send_header('X-Backend-Info','fixture-node');self.end_headers();self.wfile.write(data) do_POST=do_GET def log_message(self,*args):pass HTTPServer(('0.0.0.0',8081),Handler).serve_forever() ''' fields={'request':'$request','request_uri':'$request_uri','uri':'$uri','status':'$status','upstream_status':'$upstream_status','upstream_addr':'$upstream_addr','request_time':'$request_time','upstream_connect_time':'$upstream_connect_time','upstream_header_time':'$upstream_header_time','upstream_response_time':'$upstream_response_time','body_bytes_sent':'$body_bytes_sent','bytes_sent':'$bytes_sent'} extra="log_format details escape=json '"+json.dumps(fields,separators=(',',':'))+"';\nupstream service_pool { server 127.0.0.1:1 max_fails=1; server backend:8081 backup; }" locations=r''' access_log /tmp/access.json details; location = /local { return 204; } location = /rewrite { rewrite ^ /normalized last; } location = /normalized { return 200 "normalized"; } location /proxy { proxy_next_upstream error timeout; proxy_next_upstream_tries 2; proxy_pass http://service_pool; } ''' with lab(config(locations,extra),backend=backend) as (container,request): assert request('/local')[0]==204 assert request('/rewrite?x=1')[2]==b'normalized' status,headers,body=request('/proxy?x=1');assert status==200 def lines():return docker('exec',container,'cat','/tmp/access.json').stdout.splitlines() wait(lambda:len(lines())>=3) records={record['request_uri']:record for record in map(json.loads,lines())} print(json.dumps(records,indent=2),flush=True) local=records['/local'];assert local['status']=='204' and local['upstream_status']=='' and local['upstream_response_time']=='' assert local['body_bytes_sent']=='0' and int(local['bytes_sent'])>0 changed=records['/rewrite?x=1'];assert changed['request']=='GET /rewrite?x=1 HTTP/1.1' and changed['uri']=='/normalized' proxy=records['/proxy?x=1'];assert proxy['status']=='200' and proxy['upstream_status']=='502, 200' assert len(proxy['upstream_addr'].split(', '))==2 and int(proxy['body_bytes_sent'])==len(body) assert float(proxy['request_time'])>=0 and len(proxy['upstream_response_time'].split(', '))==2 print('a local 204 has no upstream and no body bytes, but still sends response-header bytes') print('the final uri reflects the internal redirect while request and request_uri retain the original request') print('one client-visible 200 records upstream attempts 502, 200 and separate attempt-address/timing lists') /local 不访问上游，直接返回 204。日志正文计数为零，bytes_sent 却为正，因为发送了响应头。在本例 JSON 转义格式中，缺失上游字段是空字符串。这不同于实际测得零秒的上游操作，也不同于实测版本默认转义路径使用的短横线。正确解析需要知道字段是否有测量，而不是仅看它能否转成数字。 ...