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