How to See Full Request URI in FPM Status

Or: How FPM status page can help when some URLS are blocked?

I changed some code in my application, and now the tests suite is failing with many timeout errors. Huh?! 😮 What happened?

Section intitulée the-initial-setupThe initial setup

Before my changes, we had the following application flow:

1. someone create a “project” (POST /projects);
2. the server dispatches a message in rabbitmq;
3. the server saves some data in the database;
4. and finally returns a 201;
5. then a handler processes the message: it fetches the “project” via an API and does its job.

Note: I simplified the algo to make it simpler to understand.

We are using asynit to run our tests. From the README, it’s a:

Asynchronous HTTP Request Testing Library for API and more…

Section intitulée the-next-setupThe next setup

We are using symfony/messenger to handle async tasks. In order to simplify our test suite, I tested to consume messages synchronously instead of relying on a worker. Even if I’m not a big fan of this solution, especially since the test env now differs from the prod env, the code is so much simpler! So what’s going on here?

My first intuition was:

there is a deadlock somewhere!

A deadlock is a situation where a processus A waits for another processus B. And this processus B also waits for A.

Section intitulée finding-the-deadlockFinding the deadlock

Since the platform is build on top of HTTP API, I wanted to use the PHP FPM status page to understand which URLs are blocked.

After quick configuration I’m getting this page:

Oups! As you can see, the “request URI” column does not contain the full request URI. Only the script, and the query string are here. It’s not a bug, it’s a feature, since it’s documented:

request uri The URI of the last served request (after webserver processing, it may always be /index.php if you use a front controller pattern redirect).

Since I’m using Symfony, I’m using the front controller pattern.

Let’s try to fix it!

I’m using nginx, and nginx passes some parameters to FPM. It looks like that:

location ~ ^/index\.php(/|$) {
    fastcgi_pass 127.0.0.1:9000;
    fastcgi_split_path_info ^(.+\.php)(/.*)$;
    include fastcgi_params;
    include environments;
    fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
    fastcgi_param SERVER_NAME $http_host;
}

Section intitulée how-to-see-real-request-url-in-fpm-status-pageHow to See Real Request URL in FPM Status page?

So after some guess and tries, I found that adding the following code make the full URI available:

location ~ ^/index\.php(/|$) {
     fastcgi_pass 127.0.0.1:9000;
     fastcgi_split_path_info ^(.+\.php)(/.*)$;
     include fastcgi_params;
     include environments;
     fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
     fastcgi_param SERVER_NAME $http_host;
+    fastcgi_param SCRIPT_NAME $request_uri;
 }

Here we go! Now we have the full path in the request URI, and it’s much easier to debug.

Section intitulée so-what-s-going-onSo, what’s going on?

While it’s not the most important part of this article, you might be curious and you want to know the fix.

So I was able to detect that an HTTP call was waiting for the result of another HTTP call.

Section intitulée the-bugThe bug

Let’s sum it up, by reusing the flow in the first chapter, a bit more detailed:

1. someone create a “project” (POST /projects);
2. the server dispatches a message in rabbitmq;
3. the handler processes the message: it fetches the "project” via an API and does its job;
4. but the project is not available yet. It retries until it exist;
5. 💥 ;
6. the server saves some data in the database;
7. and finally returns a 201.

Section intitulée the-fixThe fix

The fix is pretty simple, I moved the message dispatch as late as possible:

1. someone create a “project” (POST /projects);
2. but the project is not available yet. It retries until it exist;
3. the server saves some data in the database;
4. the server dispatches a message in rabbitmq;
5. the handler processes the message: it fetches the "project” via an API and does its job;
6. and finally returns a 201.

Section intitulée conclusionConclusion

Monitoring what’s going on during the tests suite from the FPM point of view is really useful! It helps me to find my deadlock very quickly because I could see very clearly what API endpoints were being requested at any time. I also discovered via this status page we were using only 4 FPM workers! It really too low since asynit runs by default 15 requests simultaneously. I increased it to 25, and the tests suite is now almost twice faster. I really like these quick wins!

Finally, you can find the full diff in the pull request and #190