Nginx server is loved by many people for its proxy capabilities and ease of configuration. A simple proxy_pass can allow you to connect to any of the backends such as GoLang, php-fpm, NodeJS, another Nginx, Tomcat, Apache, Gunicorn, uwsgi, Flask, Django, an external CDN and many more.
When proxying a request to another server, you may or may not have access to a log of the server. So it is important to be able to debug the problem if 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
- upstream prematurely closed connection while reading response header from upstream
Few of these issues can occur because of below possible reasons
- Error in the your server code
- Error in Nginx config
- Error in the information server receives
- 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
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 |
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
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 |
<!--?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); </code></pre> <p>Now when we call the above script through curl</p> <pre><code class="language-html">$ curl localhost/error.php <html> <head><title>502 Bad Gateway</title></head> <body bgcolor="white"> <center></p> <h1>502 Bad Gateway</h1> <p></center> </p> <hr> <p><center>nginx/1.13.3</center> </body> </html> </code></pre> <p>If we look at nginx error log, it would show the error below</p> <pre><code class="language-bash">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" </code></pre> <p>Now this error indicates 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</p> <h2 id="logging-the-traffic-between-source-and-target">Logging traffic with socat</h2> <p><strong>Socat</strong> 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</p> <pre><code class="language-bash">$ yum install -y socat $ apt install -y socat $ apk add socat </code></pre> <p>Once installed we need to run socat to listen on a port different than 9000 and pass the data to 9000 port.</p> <p>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</p> <pre><code class="language-bash">socat -v TCP-LISTEN:9001,fork TCP:127.0.0.1:9000 </code></pre> <p>The command is self explanatory. It is to listen on <code>9001</code> and pass traffic bidirectionaly between the two <code>127.0.0.1:9000</code>. The <code>-v</code> is for verbose output, it helps us print the traffic</p> <h4 id="my-app-is-not-listening-on-a-port-but-a-unix-socket">How to set up socat if application runs on unix socket?</h4> <p>No problems. You can adapt your socat command to something like below</p> <pre><code class="language-bash">socat -v TCP-LISTEN:9001,fork UNIX-CONNECT:/run/php/php7.0-fpm.sock </code></pre> <blockquote><p><span style="font-size: 12pt;">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 <code>/run/php/php7.0-fpm.sock</code> by default is owned by <code>www-data</code>. So you would need to change the owner of these socket or chmod them to 777 for your testing</span></p></blockquote> <p>Now let us get back to our testing the <code>curl localhost/error.php</code>. When we run</p> <pre><code class="language-bash">$ curl localhost/error.php </code></pre> <p>The call fail as usual. Let’s look at the socat terminal</p> <pre><code class="language-bash">> 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 </code></pre> <p>From this we can easily see that <code>X-MY-Header</code> is coming with large data and after reading <code>8192</code> bytes that is <code>8KB</code> of headers, nginx just leaves it and fails the request.</p> <p>Now let us execute another curl statement this time</p> <pre><code class="language-bash">$ curl localhost/test/not_exists.php File not found. </code></pre> <p>This time the output on the socat window will be</p> <pre><code class="language-sh">> 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 </code></pre> <p>We can see that <code>SCRIPT_FILENAME</code> is getting a value <code>/var/www/html/test/not_exists.php</code>. 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.</p> <p>Now let use test another scenario with proxy_pass to another site. So we want to load images from <code>http://itgala.xyz/images/</code> from our localhost. So we update our config to</p> <pre><code class="language-nginx">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.com/; } 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; } } } </code></pre> <p>Now if we curl a image from the site <code>http://itgala.xyz/images/docker_swarm_security_group.png</code> as <code>http://localhost/images/docker_swarm_security_group.png</code></p> <pre><code class="language-html">$ 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 &amp;middot; GitHub Pages</title> </p> <img src="data:image/gif;base64,R0lGODlhAQABAIAAAAAAAP///yH5BAEAAAAALAAAAAABAAEAAAIBRAA7" data-wp-preserve="%3Cstyle%20type%3D%22text%2Fcss%22%20media%3D%22screen%22%3E%0A%20%20%20%20%20%20body%20%7B%0A%20%20%20%20%20%20%20%20background-color%3A%20%23f1f1f1%3B%0A%20%20%20%20%20%20%20%20%3C%2Fstyle%3E" data-mce-resize="false" data-mce-placeholder="1" class="mce-object" width="20" height="20" alt="&lt;style&gt;" title="&lt;style&gt;" ?--> |
|
1 |
This is weird, we requested a image and got an html. Let us open another socat session
|
1 2 |
$ socat -v TCP-LISTEN:8080,fork TCP:itgala.xyz:80 |
And change our proxy_pass in nginx from itgala.xyz to 127.0.0.1:8080
In the window we can see the request as below
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 |
> 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 |
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
|
1 2 3 4 |
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
|
1 2 3 4 |
location /images/ { proxy_pass http://127.0.0.1:8080; } |
Now let us re-run our curl statement. The logs in socat will be
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 |
> 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
|
1 2 3 4 5 |
location /images/ { proxy_pass http://127.0.0.1:8080; proxy_set_header Host itgala.xyz; } |
Note: This is only needed because we are sending the proxy to socat listener on localhost. If we had use https://itgala.xyz as the proxy_pass address, this was not needed
Now our curl command will work. So the final proxy_pass that we need is
|
1 2 3 4 5 |
location /images/ { proxy_pass http://itgala.xyz; #proxy_set_header Host itgala.xyz; } |
