I have nginx set up to terminate an SSL connection and forward requests to an http backend. The client makes a number of background requests, one of which is failing with 400 Bad Reqest whenever it attempts to negotiate the SSL connection. If it doesn't need to negotiate the connection - e.g. if a different background request just posted successfully, the request succeeds. Examining the Chrome network tab shows no relevant difference between a successful request and a failed request. My journey is posted here in this bug report, but here is what I've been able to distill so far:
The SSL Connection
When the problem request succeeds, I can tell that it doesn't need to negotiate the SSL connection by viewing the Timing tab of the network request (in Chrome): Timing - successful request
On the other hand, whenever the request fails, I see that it has attempted to negotiate the SSL connection, as seen in this image: Timing - failed request
Nginx Handling
By checking the application access logs, I have determined that it is nginx that returns the 400 Bad Request error, and not the HTTP application. When the request fails, all nginx logs is the POST body rather than the HTTP method and URL per usual (I have not customized the nginx log format).
I turned on debugging in the nginx error log (with the line error_log /var/log/nginx/error.log debug;). This allows me to see what is going on during the SSL negotiation (although I don't understand it).
As I mentioned briefly above, there are other background requests that do succeed, although they run less frequently. After any request succeeds, all requests will succeed for a period of time (until they need to negotiate the SSL connection).
Additionally, if I use Copy as cURL functionality from Chrome and run the request as a cURL request, it always succeeds. The only time I have observed it to fail is when the browser makes the request.
Nginx debug logs
Here is the relevant bit from a successful SSL request in the logs:
2021/10/22 20:37:59 [debug] 1858722#1858722: *441 free: 0000562A9F69F340
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 http upstream request: "/api/method/frappe.core.doctype.log_settings.log_settings.has_unseen_error_log?"
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 http upstream process header
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 malloc: 0000562A9F712CB0:131072
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 recv: eof:0, avail:-1
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 recv: fd:9 678 of 131072
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 http proxy status 200 "200 OK"
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 http proxy header: "Server: gunicorn"
... more http proxy headers ...
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 http proxy header done
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 xslt filter header
2021/10/22 20:37:59 [debug] 1858722#1858722: *438 HTTP/1.1 200 OK
Server: nginx/1.18.0 (Ubuntu)
... HTTP response
Here is the failed negotiation:
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 free: 0000562A9F69F340
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 http wait request handler
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 malloc: 0000562A9F69F340:1024
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 SSL_read: 812
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 SSL_read: -1
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 SSL_get_error: 2
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 reusable connection: 0
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 posix_memalign: 0000562A9F70CEB0:4096 @16
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 http process request line
2021/10/22 20:39:00 [info] 1858722#1858722: *446 client sent invalid method while reading client request line, client: 107.185.20.83, server: atlas-dev.ebs.llc, request: "doctype=Error+Log&fields=%5B%22%60tabError+Log%60.%60name%60%22%2C%22%60tabError+Log%60.%60owner%60%22%2C%22%60tabError+Log%60.%60creation%60%22%2C%22%60tabError+Log%60.%60modified%60%22%2C%22%60tabError+Log%60.%60modified_by%60%22%2C%22%60tabError+Log%60.%60_user_tags%60%22%2C%22%60tabError+Log%60.%60_comments%60%22%2C%22%60tabError+Log%60.%60_assign%60%22%2C%22%60tabError+Log%60.%60_liked_by%60%22%2C%22%60tabError+Log%60.%60docstatus%60%22%2C%22%60tabError+Log%60.%60parent%60%22%2C%22%60tabError+Log%60.%60parenttype%60%22%2C%22%60tabError+Log%60.%60parentfield%60%22%2C%22%60tabError+Log%60.%60idx%60%22%2C%22%60tabError+Log%60.%60method%60%22%2C%22%60tabError+Log%60.%60seen%60%22%5D&filters=%5B%5D&order_by=%60tabError+Log%60.%60modified%60+desc&start=0&page_length=20&view=List&with_comment_count=true"
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 http finalize request: 400, "?" a:1, c:1
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 event timer del: 9: 337737968
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 http special response: 400, "?"
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 http set discard body
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 xslt filter header
2021/10/22 20:39:00 [debug] 1858722#1858722: *446 HTTP/1.1 400 Bad Request
Server: nginx/1.18.0 (Ubuntu)
Date: Fri, 22 Oct 2021 20:39:00 GMT
Content-Type: text/html
Content-Length: 166
Connection: close
Based on what little I know about the nginx debug log (i.e., nothing), it looks to me like nginx swaps out the HTTP method and url for the body during the negotiation. When it looks for the HTTP method, it is no longer present, and it chokes.
Nginx SSL Config
Version information: nginx/1.18.0 (Ubuntu), Ubuntu 20.04 LTS
I'm using the default nginx.conf. The SSL portion of the server conf looks like this:
listen 443 ssl;
server_name [HOST];
root /opt/erpnext/bench/sites;
proxy_buffer_size 128k;
proxy_buffers 4 256k;
proxy_busy_buffers_size 256k;
ssl_certificate /etc/letsencrypt/live/[HOST]/fullchain.pem;
ssl_certificate_key /etc/letsencrypt/live/[HOST]/privkey.pem;
ssl_session_timeout 5m;
ssl_session_cache shared:SSL:10m;
ssl_session_tickets off;
ssl_stapling on;
ssl_stapling_verify on;
ssl_protocols TLSv1.2 TLSv1.3;
ssl_ciphers EECDH+AESGCM:EDH+AESGCM;
ssl_ecdh_curve secp384r1;
ssl_prefer_server_ciphers on;
There is an SSL redirect at the bottom of the file, and nginx is set up to server a flat-file based HTTP webserver on port 8080 from another config.
How can I determine what causing the issue? I know that the request is properly formed, because identical requests succeed... up until it needs to negotiate the SSL connection. Help?
