Debugging Nginx Configurations

A couple of weeks ago, I saw a tweet that peaked my interest.

Statamic is a slick flat-file PHP CMS written by a couple of very smart friends: Jack McDade and Mubashar Iqbal (a.k.a. Mubs). I messed with Statamic a bit during the beta period, though not as much as I would have liked, as I was typically otherwise occupied. Even though I’ve only briefly used Statamic, I like to keep up with the goings on with their venture, and help out or provide support whenever I can. So when I saw the tweet about someone having an issue using Statamic on a Nginx setup, I thought from my escapades configuring Nginx, I might be able to help out.

Pretty Straightforward

Foolishly I though that I knew exactly what the issue was, the user couldn’t access the admin panel, so obviously routing to admin.php wasn’t working!

Off the top of my head, I suspect that the index declaration is what’s screwing you up. Since you have:

index index.html index.php;

It will automatically try to process index.php/admin.php, so maybe try making the line:

index index.html index.php admin.php;

and see what happens. I’ll try to confirm when I can get access to my VPS in a couple of hours.

For some weird reason I assumed that since you declare index and fastcgi_index as index.php, Nginx would try to route everything through index.php. Silly, I know that now. After refreshing my memory on how Nginx handles requests, I realized that it should be able to access admin.php just fine.

# First attempt to serve request as file, then
# as directory, then fall back to displaying a 404.
try_files $uri $uri/ /index.php;
fp

You can’t always be right

That comment made it obvious Nginx should be able to access the admin app just fine when requesting something like http://www.example.com/admin.php by matching on the file, then passing it to the PHP-FPM declaration section which will execute the script. Well that was all well and good in theory, but I was still getting a 404 attempting to navigate to to the admin app.

Taking The Gloves Off

I wasn’t getting anywhere screwing with the Nginx config at this point, so I decided to work through the Statamic code to see what is happening with the in-app routing. The routing code seemed simple enough, and to be doing what it was supposed to, but I wanted to see exactly what was going on during the requests. Since I am an “echo debugger” I hacked in some awful “logging” to quickly see what was going on.

function myLogger($text) {
    $logfile = fopen("/home/webroot/statamic/logs/statamic_log.log", "a");
    fwrite($logfile, date('Y-M-d H:i:s') . " $text\n");
    fclose($logfile);
}

With this, I was able to see what was going on at various stages of the routing within the PHP code. I soon discovered that admin.php was actually being executed, at least long enough for it to verify I was not authenticated, and sending me to log in. The redirect call was sending me over to admin.php/login, and that’s where you end up at the 404. Some more debugging showed that the app was actually getting bounced back to the core app, and index.php was trying to route admin.php/login, as opposed to admin.php routing /admin. At this point I was back on to my Nginx config being the culprit, but I was at a loss as to how to further debug the configuration issues.

Log Trolling

After some exploring on Google, I was happy to discover I was going to be golden with the HttpEchoModule enabling my “echo debugging” ways. At least until:

This module is not distributed with the Nginx source. See the installation instructions.

no_ideas

Shit.

Thankfully I was not left in the dark for long. Researching the way Nginx handles logging, I realized that (herp-derp) you can specify the error_log directive to print out very verbose debugging logs! It’s as easy as adding “debug” to the end of the directive:

error_log  /home/webroots/default/logs/error.log debug;

With that, we end the easy part. Now you have to stare at the debug logs and try to figure out what the hell is going on. “Try” being the key word here.

2012/12/12 00:34:09 [debug] 1529#0: post event 0873B690
2012/12/12 00:34:09 [debug] 1529#0: delete posted event 0873B690
2012/12/12 00:34:09 [debug] 1529#0: accept on 0.0.0.0:80, ready: 0
2012/12/12 00:34:09 [debug] 1529#0: posix_memalign: 08720550:256 @16
2012/12/12 00:34:09 [debug] 1529#0: *23 accept: 10.0.0.20 fd:11
2012/12/12 00:34:09 [debug] 1529#0: *23 event timer add: 11: 60000:2375811513
2012/12/12 00:34:09 [debug] 1529#0: *23 epoll add event: fd:11 op:1 ev:80000001
2012/12/12 00:34:09 [debug] 1529#0: *23 post event 0873B6F8
2012/12/12 00:34:09 [debug] 1529#0: *23 delete posted event 0873B6F8
2012/12/12 00:34:09 [debug] 1529#0: *23 malloc: 08728928:680
2012/12/12 00:34:09 [debug] 1529#0: *23 malloc: 08728BD8:1024
2012/12/12 00:34:09 [debug] 1529#0: *23 posix_memalign: 087452B0:4096 @16
2012/12/12 00:34:09 [debug] 1529#0: *23 http process request line
overwhelmed

What have I gotten myself into?!

Looking Into The Void

Okay so I am probably being a little dramatic here, but goodness there is a lot to sift through in the logs. With that in mind, it’s probably a good time to mention that it is imperative you do not leave debug on for an extended period of time! That will be a good way to run your server out of storage quickly.

Back to the matter at hand. It took me a while to understand, but Nginx debug logs can be “easy” to understand if you just look for some keywords and kind of…ignore everything else. Since this issue centered around admin.php, I started by looking through the log for that first, and look what I found:

2012/12/12 00:34:09 [debug] 1529#0: *23 http request line: "GET /admin.php HTTP/1.1"
2012/12/12 00:34:09 [debug] 1529#0: *23 http uri: "/admin.php"
2012/12/12 00:34:09 [debug] 1529#0: *23 http args: ""
2012/12/12 00:34:09 [debug] 1529#0: *23 http exten: "php"
2012/12/12 00:34:09 [debug] 1529#0: *23 http process request header line

Jackpot. Then after some scrolling I noticed some more lines that seemed relevant to my interests (highlighted for clarity’s sake):

2012/12/12 00:34:09 [debug] 1529#0: *23 test location: ~ "\.php$"
2012/12/12 00:34:09 [debug] 1529#0: *23 using configuration "\.php$"
2012/12/12 00:34:09 [debug] 1529#0: *23 http cl:-1 max:1048576
2012/12/12 00:34:09 [debug] 1529#0: *23 rewrite phase: 3
2012/12/12 00:34:09 [debug] 1529#0: *23 post rewrite phase: 4
2012/12/12 00:34:09 [debug] 1529#0: *23 generic phase: 5
2012/12/12 00:34:09 [debug] 1529#0: *23 generic phase: 6
2012/12/12 00:34:09 [debug] 1529#0: *23 generic phase: 7
2012/12/12 00:34:09 [debug] 1529#0: *23 access phase: 8
2012/12/12 00:34:09 [debug] 1529#0: *23 access phase: 9
2012/12/12 00:34:09 [debug] 1529#0: *23 access phase: 10
2012/12/12 00:34:09 [debug] 1529#0: *23 post access phase: 11
2012/12/12 00:34:09 [debug] 1529#0: *23 try files phase: 12
2012/12/12 00:34:09 [debug] 1529#0: *23 http script var: "/admin.php"
2012/12/12 00:34:09 [debug] 1529#0: *23 trying to use file: "/admin.php" "/home/webroots/default/public_html/admin.php"
2012/12/12 00:34:09 [debug] 1529#0: *23 try file uri: "/admin.php"

Hopefully without having to paste the whole log into this post, you can get the idea of what to look for. Lines with test location, using configuration, trying to use file, and redirect will be the most helpful in tracing what is going on under the hood. After following the path of the app trying to redirect from admin.php to admin.php/login to authenticate, I found that Nginx was indeed not matching the url with the PHP location, even with the rewrite rule that should have allowed admin.php to be processed, regardless of what followed it in the URL. This explained why we ended at a 404, as the fallback was on index.php which had no clue what to do with admin.php/login.

Accursed Regex

As anticlimactic as it may be, the issue all came down to a bad regular expression. A situation commonly referred to by developers as “the bane of my existence.” The problem was resolved by tweaking the rewrite regex until I saw that Nginx was processing the admin URL correctly, and the issue was closed, what more can you ask for?

Maybe a complete Nginx config to use on a Statmic site? Well ask and you receive! I posted the configuration I ended up using as a gist on Github. It should not only allow for full functionality, but also secures all of the sensitive files and directories in your Statamic install.

%d bloggers like this: