Debugging slow Livewire requests with Grafana
For an application I’m working on, we were confronted with occasional 504 responses. These were tricky to debug because nothing showed up in our error tracker Flare.
That makes sense when you think about it. The load balancer stops waiting and returns the 504 itself. PHP never throws an exception, so Flare has nothing to report.
I wanted to know which requests were causing these timeouts, so I started sending our Nginx access logs to Grafana Loki.
Logging requests as JSON
Nginx uses a plain-text access log by default. That works fine when reading the file directly, but structured JSON is much easier to query in Grafana.
I added a custom log format containing the fields I was interested in:
map $request_uri $application_request_path {
~^([^?]*) $1;
}
log_format application_json escape=json
'{'
'"timestamp":"$time_iso8601",'
'"request_id":"$request_id",'
'"host":"$host",'
'"method":"$request_method",'
'"path":"$application_request_path",'
'"status":$status,'
'"request_time":$request_time,'
'"upstream_status":"$upstream_status",'
'"upstream_response_time":"$upstream_response_time"'
'}';
The map strips query parameters from the URI. I don’t want tokens, search terms, or other potentially sensitive values ending up in Grafana.
You can enable the format using the access_log directive:
access_log /var/log/nginx/application-access.log application_json;
After sending this file to Loki, the logs can be queried using LogQL:
{job="nginx", app="application"} | json
Why the timeouts appeared as 499
I initially searched for status code 504, but the requests I was looking for appeared as 499 instead.
A 499 means the client closed the connection before Nginx could return its response. In this case, that client is the load balancer. It gives up waiting, returns a 504 to the browser, and closes its connection to Nginx.
Our load-balancer timeout is ten seconds, so I could find likely timeouts by looking for 499 responses around that duration:
{job="nginx", app="application"}
| json
| status="499"
| request_time >= 9.8
| request_time <= 10.2
You’ll need to adjust that range to match your own timeout configuration.
All Livewire requests look the same
The logs now showed which requests were slow, but many of them looked like this:
{ "method": "POST", "path": "/livewire-42074e47/update", "status": 499, "request_time": 10.001 }
That path tells me it was a Livewire request, but not which page the user was viewing. An interaction on a billing page and one on a large table both use the same update endpoint.
Luckily, Livewire requests normally include the current page in the HTTP referrer.
Adding the originating page
I didn’t want to log the complete referrer because it can also contain query parameters. Instead, I added another map that extracts only its path:
map $http_referer $application_referer_path {
default "-";
~^https?://[^/]+(?<captured_referer_path>[^?]*) $captured_referer_path;
}
That value can be added to the JSON log:
'"referer_path":"$application_referer_path",'
The same Livewire request now contains the missing context:
{ "host": "customer.example.com", "path": "/livewire-42124e17/update", "referer_path": "/email-lists/example/subscribers", "status": 499, "request_time": 10.001 }
The hostname tells me which tenant was affected, while referer_path tells me which page triggered the Livewire request. That is usually enough to narrow the problem down to a specific table, form, or component.
Don’t forget log rotation
Access logs can grow quickly, so make sure the new file is covered by logrotate:
cat /etc/logrotate.d/nginx
If it isn’t, move the log into the configured Nginx log directory or add a dedicated rotation rule. You can safely validate that rule using:
sudo logrotate --debug /etc/logrotate.d/application-nginx-access
Now, when a Livewire request times out, I have an actual page to investigate instead of one generic update endpoint. Pretty neat!