An nginx access log records request information when logging runs at the end of processing. The selected fields can distinguish what the client requested, which URI ultimately handled it, what response was sent, and what happened during upstream attempts. These are different observations. A useful format keeps them separate instead of assuming that one status, duration, or path explains the whole request by itself.

When it breaks

The final client status can conceal an earlier upstream failure. If nginx retries another server successfully, the client may receive 200 while an attempt list records a failed connection first. Conversely, a locally generated response has no upstream operation to time. Treating every request as exactly one backend response loses the information needed to explain retries and local handling.

Original and current URI fields also differ after internal redirects. $request retains the request line, and $request_uri retains the original URI and query. $uri can reflect a later normalized or rewritten path. An investigator who logs only the final URI may not know which public address triggered it, while logging only the original path can hide the final handler’s context.

Timing fields are not interchangeable latency components that can always be subtracted into a precise diagnosis. Request time includes processing through the client-facing completion point used by nginx logging. Upstream timing fields describe their own phases and can contain several attempt values. Their resolution, missing values, and boundaries matter; a zero-looking millisecond value does not establish that no work occurred.

Check it quickly

Run the script with host Python, Docker, and the pinned nginx and Python images. The recorded environment used nginx 1.28.0 and Python 3.11.16 on Linux arm64 with Docker 29.3.1. It configures a real backend plus an unreachable port inside the proxy container, validates nginx configuration, publishes only a host-loopback proxy port, and removes its own resources after inspecting the logs:

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')

The /local request returns 204 without contacting an upstream. Its log has zero body bytes but a positive bytes_sent value because response headers were sent. In this JSON-escaped format, absent upstream fields are empty strings. This is different from a measured zero-second upstream operation and from the dash used by the tested version’s default escaping path.

The request /rewrite?x=1 internally becomes /normalized. The log retains GET /rewrite?x=1 HTTP/1.1 as the request line and the original URI with its query, while uri records /normalized. This verifies the difference at the actual log-write point, rather than inferring it only from the rewrite declaration or the response body.

The proxy request first tries loopback port one, where the disposable proxy container has no listener. nginx records that failed attempt with status 502 and then reaches the configured backup server. The final client response is 200, while upstream_status is the string 502, 200. The first value is nginx’s recorded failure outcome, not evidence that a backend actually returned an HTTP 502 response.

The same event contains two upstream addresses and two response-time entries. Connect and header timings can contain a dash for an attempt that never reached those phases, even though the overall variable exists. That differs from an entirely absent upstream variable. Preserve these relationships when parsing instead of replacing every unusual value with an indistinguishable numeric zero.

The logged body byte count equals the actual response-body length read by the client in this uncompressed fixture. bytes_sent includes more HTTP response bytes, but neither field is presented as a complete accounting of Ethernet, TCP, or TLS overhead. The example uses the counters to distinguish body content from header traffic, not to claim a physical-network billing measurement.

The script waits until the three events are present before parsing them. Logging occurs after request handling, and configured buffering can delay visibility further. A successful HTTP response does not guarantee that a remote log collector has already received or retained the corresponding event.

Keep diagnostic meaning in the schema

Choose fields that answer concrete operational questions: original target, final route, client status, upstream attempt outcomes, and relevant durations. Keep attempt lists intact until a parser with the documented grammar separates them. Multiple upstream groups or internal transitions can introduce additional structure beyond the simple two-attempt case shown here.

Avoid treating client-controlled forwarding headers as verified caller identity. Also consider whether query strings or other request fields contain sensitive values before retaining them. Richer logs are useful only when the information has a clear purpose and appropriate access and retention controls.

Test format changes by producing representative local responses, retries, rewrites, and failures, then parsing actual records. Validate rotation and collection separately. A trustworthy access log connects each field to its measured event and preserves missing or multi-attempt information instead of flattening it into a misleading summary.

Sources