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 转义格式中，缺失上游字段是空字符串。这不同于实际测得零秒的上游操作，也不同于实测版本默认转义路径使用的短横线。正确解析需要知道字段是否有测量，而不是仅看它能否转成数字。

/rewrite?x=1 内部变成 /normalized。日志请求行仍为 GET /rewrite?x=1 HTTP/1.1，原 URI 仍带查询，而 uri 字段记录 /normalized。这在真实日志写入点验证了区别，不是只根据 rewrite 声明或响应正文推测。最终字段值能够帮助判断处理过程中是否发生了内部路由变化。

代理请求先尝试回环端口一，实验代理容器中该端口没有监听者。nginx 把失败尝试记录为 502，再请求配置的备用服务器。客户端最终收到 200，上游状态字符串却为 502, 200。第一项是 nginx 记录的失败结果，不证明某个后端真的发送过 HTTP 502 响应；连接根本未建立时，状态也可能由代理生成。

同一事件包含两个上游地址和两个响应耗时。对于没有进入连接完成或响应头阶段的尝试，相应时间列表可能含短横线，即使整个变量确实存在。这与完全不存在的上游变量不同。解析时应保留这些关系，不能把每个异常形状都替换成无法区分的数值零，否则失败阶段和尝试次数都会丢失。

在这个未压缩实验中，日志正文计数等于客户端实际读取的响应正文长度。bytes_sent 包含更多 HTTP 响应字节，但两者都不是对以太网、TCP 或 TLS 开销的完整统计。这里用计数器区分内容与响应头流量，不把它们冒充物理网络计费测量。指标用途应与其真实计数边界一致。

脚本等到三条事件出现后才解析。日志位于请求处理之后，配置写入缓冲还可能继续延迟可见性。HTTP 成功响应不保证远程日志采集器已经收到或保留对应事件。排查日志延迟时，需要继续检查缓冲、轮转和采集链路，不能只因为请求完成就认定记录应该立即出现在中央查询系统。

在模式中保留诊断含义

按具体运维问题选择字段：原始目标、最终路由、客户端状态、上游尝试结果和相关耗时。在遵循文档语法的解析器处理之前，保留尝试列表原貌。多上游组或内部转换还可能引入比这里两次尝试更复杂的结构，不能把本例逗号拆分直接扩展成所有部署通用解析器。

不要把客户端可控制的转发头当成已经验证的调用者身份。保留查询或其他请求字段前，也要考虑其中是否存在敏感值。更丰富的日志只有在信息用途清楚、访问和保留控制合适时才有价值；收集越多不自动意味着诊断越可靠，反而可能增加隐私和容量负担。

修改格式时，生成有代表性的本地响应、重试、重写和失败，再解析真实记录。轮转与采集另行验证。可靠访问日志把每个字段连接到它测量的事件，并保留缺失或多次尝试信息，而不是压缩成误导性的单一摘要。这样，日志才能支持根因分析，而不只是证明曾经有请求经过。

来源