How To Debug Nginx Reverse Proxy Issues

I love Nginx for its revery proxy capabilities and ease of configuration. A simple proxy_pass can allow you to connect to any of the backends GoLang, php-fpm, NodeJS, another nginx, tomcat, apache, gunicorn, uwsgi, flask, django, a external CDN and many more

When proxying a request to another server, you may or may not have access to log of the server. So it is important to be able to debug, where the problem lies when an issue occurs. Common problems that you may face when proxying request are below

502 Bad Gateway
504 Gateway Timeout
404 Page Not Found
403 Access Denied
400 Bad Request request header or cookie too large
Wrong Redirect
upstream sent too big header while reading response header from upstream
“Primary script unknown” while reading response header from upstream

Few of these issues can because of below possible reasons

Error in the your server code
Error in Nginx config
Error in the information server recieves
Fine tuning of timeouts

In this article I will explain few techniques to debug Nginx + PHP-FPM. These techniques will be applicable to other servers like Gunicorn, uwsgi, or other sites as well

Sample PHP Backend with Error

Consider the below Nginx config with a PHP config

events {
    worker_connections 1024;
}
http {
    server {

        listen 80;
        root /var/www/html;

        index index.php index.html;

        location / {
            deny all;
        }

        location ~ \.php$ {
            #try_files $uri =444;
            fastcgi_split_path_info ^(.+\.php)(/.+)$;
            include fastcgi_params;
            fastcgi_index index.php;
            fastcgi_pass 127.0.0.1:9000;
            fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
        }
    }
}

The above config passes all php scripts to the running php-fpm server listening on 127.0.0.1:9000. And anything other than php is denied.

Now let’s create a php file error.php in /var/www/html/

/var/www/html/error.php


<?php

function random_str($length, $keyspace = '0123456789abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ')
{
    $str = '';
    $max = strlen($keyspace) - 1;
    for ($i = 0; $i < $length; ++$i) {
        $str .= $keyspace[random_int(0, $max)];
    }
    return $str;
}

$body = random_str(65336);
$header =  random_str(65);

header("X-MY-Header: $body");

echo ($body);

Now when we call the above script through curl

$ curl localhost/error.php
<html>
<head><title>502 Bad Gateway</title></head>
<body bgcolor="white">
<center><h1>502 Bad Gateway</h1></center>
<hr><center>nginx/1.13.3</center>
</body>
</html>

If we look at nginx error log, it would show below error

2017/08/31 16:18:05 [error] 5#5: *3 upstream sent too big header while reading response header from upstream, client: 192.168.33.1, server: , request: "GET /error.php HTTP/1.1", upstream: "fastcgi://127.0.0.1:9000", host: "192.168.33.100"

Now this error does indicate that there is an issue with the headers that were sent back. In our demo case there is just one file to check, but in a real project there would be multiple files and it becomes hard to say where the error might be coming from. So what we need is to be able to see the interaction between Nginx and our backend used in proxy_pass

Logging the traffic between source and target

Socat is a command line based utility that establishes two bidirectional byte streams and transfers data between them. Install socat based on the package manager you have on your OS. One of the below commands should do

$ yum install -y socat
$ apt install -y socat
$ apk add socat

Once installed we need to run socat to listen on a port different than 9000 and pass the data to 9000 port.

So we will run a socat in a new terminal or screen or tmux. The communication transfer between the two ports will only happen till socat is running

socat -v TCP-LISTEN:9001,fork TCP:127.0.0.1:9000

The command is self explanatory. It is to listen on 9001 and pass traffic bidirectionaly between the two 127.0.0.1:9000. The -v is for verbose output, it helps us print the traffic

My app is not listening on a port but a unix socket?

No problems. You can adapt your socat command to something like below

socat -v TCP-LISTEN:9001,fork UNIX-CONNECT:/run/php/php7.0-fpm.sock

Note: You will need to make sure the user has access to the socket. Some sockets run with 600 permissions and the owners are different than root or your current user. For example /run/php/php7.0-fpm.sock by default is owned by www-data. So you would need to change the owner of these socket or chmod them to 777 for your testing

Now let us get back to our testing the curl localhost/error.php. When we run

$ curl localhost/error.php

The call fail as usual. Let’s look at the socat terminal

> 2017/09/02 10:09:13.028692  length=520 from=0 to=519
.....\b..................\f.QUERY_STRING..REQUEST_METHODGET\f.CONTENT_TYPE..CONTENT_LENGTH\v
SCRIPT_NAME/error.php\v
REQUEST_URI/error.php\f
DOCUMENT_URI/error.php\r\rDOCUMENT_ROOT/var/www/html.\bSERVER_PROTOCOLHTTP/1.1..REQUEST_SCHEMEhttp.\aGATEWAY_INTERFACECGI/1.1.\fSERVER_SOFTWAREnginx/1.10.3\v	REMOTE_ADDR127.0.0.1\v.REMOTE_PORT33152\v	SERVER_ADDR127.0.0.1\v.SERVER_PORT80\v.SERVER_NAME..REDIRECT_STATUS200..SCRIPT_FILENAME/var/www/html/error.php		HTTP_HOSTlocalhost.\vHTTP_USER_AGENTcurl/7.47.0\v.HTTP_ACCEPT*/*.....................< 2017/09/02 10:09:13.093658  length=8 from=0 to=7
.....@..< 2017/09/02 10:09:13.094167  length=8192 from=8 to=8199
X-MY-Header: d38e4MZW1yeVqrjEVcvZEudbhQzIU6GjorJN1Q6LvL8BRUI4OawlZU4jKOcdcMmHeJ9gqmDTunAl2l5HTFYZXTV1MIJflnsVAo45E80XeVCgVAjHqSG58IfTauTPkTqNCSVbHQrzM1obtMFkuJKh8Aw7723UJL82I3Pu9gOjYrrNKLYDbvkwuSwnCBu....
PCqr9O2YZ71fXyp4kG6LIoOG3xMMr64LwNPGxpbR2Xq7AYzOReFimxnJ8RTjPtwKgAxqNXEcqGJDAlhXEkK7e9CYfAYbIEPIUYa92V0yGBBhzDru6IoUPwayqAJAgbpj60TeQ0ifkBRhd2UKO5mE2Oa9lINtLwd1bhEpmgkqN6N36VJAaLD1eeYfcvSEUiUh< 2017/09/02 10:09:13.111569  length=8192 from=8200 to=16391
Yh0oedDFdi3LS0UZ7zaBzqzzD5VzFeyFU6NdIQiM87MFcbBVnk9cPhPcYoiQxIS3iOOORviYOpCoMzcuVp7V9uEIo48XRlZvptcDy3d5hV7tuax4vtREh0RIDJFDDVMyB9MCa1gYvdsu88dacBwti1EZOdse7ZDwSnkXcIonnmVu4XbSdCE53qQnfSkIukvuV57DFSt8....
rnc0AIxYcnj52MLJIMOKz8C8EEa5q37Dh9VdCsXwxmS0uEV0ndJH0wxmJzWPCDbDdOAOW8XLk1EqDE6kV1QORZHoI84x2017/09/02 10:09:13 socat[14573] E write(6, 0x225c530, 8192): Broken pipe

From this we can easily see that X-MY-Header is coming with large data and after reading 8192 bytes that is 8KB of headers, nginx just leaves it and fails the request.

Now let us execute another curl statement this time

$ curl localhost/test/not_exists.php
File not found.

This time the output on the socat window will be

> 2017/09/02 10:18:48.834880  length=560 from=0 to=559
.....\b..................\f.QUERY_STRING..REQUEST_METHODGET\f.CONTENT_TYPE..CONTENT_LENGTH\v.SCRIPT_NAME/test/not_exists.php\v.REQUEST_URI/test/not_exists.php\f.DOCUMENT_URI/test/not_exists.php\r\rDOCUMENT_ROOT/var/www/html.\bSERVER_PROTOCOLHTTP/1.1..REQUEST_SCHEMEhttp.\aGATEWAY_INTERFACECGI/1.1.\fSERVER_SOFTWAREnginx/1.10.3\v	REMOTE_ADDR127.0.0.1\v.REMOTE_PORT33192\v	SERVER_ADDR127.0.0.1\v.SERVER_PORT80\v.SERVER_NAME..REDIRECT_STATUS200.!SCRIPT_FILENAME/var/www/html/test/not_exists.php		HTTP_HOSTlocalhost.\vHTTP_USER_AGENTcurl/7.47.0\v.HTTP_ACCEPT*/*.....................< 2017/09/02 10:18:48.840436  length=144 from=0 to=143
.\a......Primary script unknown
......Q\a.Status: 404 Not Found\r
Content-type: text/html; charset=UTF-8\r
\r
File not found.
............\b......./ht

We can see that SCRIPT_FILENAME is getting a value /var/www/html/test/not_exists.php. And now we know this doesn’t exists in our code. So it becomes easy to understand what values the backend is getting and why it is not working.

Now let use test another scenario with proxy_pass to another site. So we want to load images from http://tarunlalwani.in/images/ from our localhost. So we update our config to

events {
    worker_connections 1024;
}
http {
    server {

        listen 80;
        root /var/www/html;

        index index.php index.html;

        location / {
            deny all;
        }
         
        location /images/ { 
            proxy_pass http://tarunlalwani.in/;
        }

        location ~ \.php$ {
            #try_files $uri =444;
            fastcgi_split_path_info ^(.+\.php)(/.+)$;
            include fastcgi_params;
            fastcgi_index index.php;
            fastcgi_pass 127.0.0.1:9001;
            fastcgi_param SCRIPT_FILENAME $document_root$fastcgi_script_name;
        }
    }
}

Now if we curl a image from the site http://tarunlalwani.in/images/docker_swarm_security_group.png as http://localhost/images/docker_swarm_security_group.png

$ curl localhost/images/docker_swarm_security_group.png
<!DOCTYPE html>
<html>
  <head>
    <meta http-equiv="Content-type" content="text/html; charset=utf-8">
    <meta http-equiv="Content-Security-Policy" content="default-src 'none'; style-src 'unsafe-inline'; img-src data:; connect-src 'self'">
    <title>Page not found &middot; GitHub Pages</title>
    <style type="text/css" media="screen">
      body {
        background-color: #f1f1f1;
        </style></head></html>

This is weird, we requested a image and got an html. Let us open another socat session

$ socat -v TCP-LISTEN:8080,fork TCP:tarunlalwani.in:80

And change our proxy_pass in nginx from tarunlalwani.in to 127.0.0.1:8080

In the window we can see the request as below

> 2017/09/02 12:38:14.139893  length=128 from=0 to=127
GET /docker_swarm_security_group.png HTTP/1.0\r
Host: 127.0.0.1:8080\r
Connection: close\r
User-Agent: curl/7.47.0\r
Accept: */*\r
\r
< 2017/09/02 12:38:14.446328  length=1378 from=0 to=1377
HTTP/1.1 404 Not Found\r
Server: GitHub.com\r
Date: Sat, 02 Sep 2017 12:38:14 GMT\r
Content-Type: text/html; charset=utf-8\r
Content-Length: 9116\r
Connection: close\r
ETag: "590b8af1-239c"\r
Content-Security-Policy: default-src 'none'; style-src 'unsafe-inline'; img-src data:; connect-src 'self'\r
X-GitHub-Request-Id: 68BC:21B9:C23049:10D47B1:59AAA636\r
\r
<!DOCTYPE html>
<html>

You can see that we are requesting /docker_swarm_security_group.png instead of /images/docker_swarm_security_group.png. If we check our proxy_pass, it is

location /images/ {
   proxy_pass http://127.0.0.1:8080/;
}

When we add a trailing / to proxy_pass address then original uri is not sent to the server. So we need to modify our proxy_pass to

location /images/ {
   proxy_pass http://127.0.0.1:8080;
}

Now let us re-run our curl statement. The logs in socat will be

> 2017/09/02 13:59:14.183562  length=135 from=0 to=134
GET /images/docker_swarm_security_group.png HTTP/1.0\r
Host: 127.0.0.1:8080\r
Connection: close\r
User-Agent: curl/7.47.0\r
Accept: */*\r
\r
< 2017/09/02 13:59:14.492039  length=1378 from=0 to=1377
HTTP/1.1 404 Not Found\r
Server: GitHub.com\r
Date: Sat, 02 Sep 2017 13:59:14 GMT\r
Content-Type: text/html; charset=utf-8\r
Content-Length: 9116\r
Connection: close\r
ETag: "590a28b8-239c"\r
Content-Security-Policy: default-src 'none'; style-src 'unsafe-inline'; img-src data:; connect-src 'self'\r

As we can see the url is now corrected. But we still have a 404. This could be because of Host: 127.0.0.1:8080. So we should set the host name also with our request

location /images/ {
   proxy_pass http://127.0.0.1:8080;
   proxy_set_header Host tarunlalwani.in;
}

Note: This is only needed because we are sending the proxy to socat listener on localhost. If we had use http://tarunlalwani.in as the proxy_pass address, this was not needed

Now our curl command will work. So the final proxy_pass that we need is

location /images/ {
   proxy_pass http://tarunlalwani.in;
   #proxy_set_header Host tarunlalwani.in;
}

I would be soon posting same approach using Docker for docker container communication debugging.

If you have any quesitons, feel free to comment

TARUN LALWANI

Sample PHP Backend with Error

/var/www/html/error.php

Logging the traffic between source and target

My app is not listening on a port but a unix socket?