README.md

Setup

1. Install lnav:

brew install lnav

1. Copy (or link) the contents of the formats directory to ~/.config/lnav/formats/installed/:

cp -a formats/. ~/.config/lnav/formats/installed/

Usage

Use extract_nginx_logs.sh to extract and untar all of the nginx logs from cloud_controller log bundles in your current directory.

Once extracted, run analyze_bundle.sh with the directory as the argument:

./analyze_bundle.sh ~/my_logs/

To analyze errored requests (4xx/5xx/499) from the nginx access logs, pass error-report.lnav as the second argument:

./analyze_bundle.sh ~/my_logs/ error-report.lnav

To dig into specific server errors (5xx and error/fatal log lines) from the Cloud Controller (CCNG) log itself, run analyze_ccng_bundle.sh with the directory as the argument (requires jq, brew install jq):

./analyze_ccng_bundle.sh ~/my_logs/

This report favors listing individual errors (with message, error class, request path, and trace id for correlating back to nginx via vcap_request_id/b3_trace_id) over aggregate counts.

Note: cloud_controller_ng.log is JSON-lines, but lnav's built-in web_robot_log format always wins auto-detection against a custom JSON format with overlapping field names (thread_id, fiber_id, process_id, file, lineno, method), so analyze_ccng_bundle.sh flattens each line to TSV with jq before handing it to lnav, and formats/cloud_controller_log.json matches that flattened line with a regex instead of file-type: json. Because of this, opening a raw cloud_controller_ng.log directly in lnav will not use this format -- always go through analyze_ccng_bundle.sh.

To dig into why clients are cancelling requests (499s), pass 499-report.lnav as the second argument to analyze_bundle.sh:

./analyze_bundle.sh ~/my_logs/ 499-report.lnav

A 499 with a long response_time means the client waited a while before giving up -- likely a slow/expensive backend request. A 499 with a near-zero response_time usually means the client itself bailed almost immediately (closed tab, an automated client with an aggressive timeout, a retry loop) and isn't a backend performance issue. This report buckets 499s by response time, and breaks them down by endpoint, user agent, remote address, and minute, to help tell those cases apart.

To find the slowest requests regardless of status code, pass slowest-requests.lnav as the second argument to analyze_bundle.sh:

./analyze_bundle.sh ~/my_logs/ slowest-requests.lnav

To find problematic API VMs -- i.e. see if errors/slowness are spread evenly across CCNG instances or concentrated on a few -- run analyze_by_instance.sh against the top-level bundle directory (the one containing cloud_controller.<guid>.<timestamp>.tgz.dir/ subdirectories, after extract_nginx_logs.sh has run):

./analyze_by_instance.sh ~/my_logs/ [output.csv]

The other reports above concatenate every instance's logs together, so a bad VM gets averaged out and hidden. analyze_by_instance.sh instead runs the same summary query (request count, error rate, 5xx/499 counts, avg/p95/p99/max response time, CC-side 5xx and error/fatal counts) against each instance's logs separately -- since nginx/CC log content has no field identifying which VM it came from, the file path is the only signal, so instances have to stay split apart rather than combined. It writes one row per instance to a CSV and prints it sorted by error rate, average response time, and p95 response time so outliers surface immediately (a VM with a bad tail but an OK average won't hide behind the avg-only sort). Once you spot a suspect instance, drill into it with the other reports by pointing them at just that instance's directory, e.g. ./analyze_ccng_bundle.sh ~/my_logs/cloud_controller.<guid>.<timestamp>.tgz.dir.

Percentiles (p95/p99) are also available directly in lnav's SQL via percentile_cont(response_time, 0.95) -- performance-report.lnav and slowest-requests.lnav both include p95/p99 columns alongside avg/min/max.