2

I'm getting sporadic 502s returned by a proxy server. When inspecting the packet flow I see nginx sending a POST request to a socket that the origin server already sent a [FIN,ACK]. I want to understand how is this possible and any potential solutions. Is it the issue with the origin (it sends the FIN,ACK only after 5 seconds after sending the response) or on the proxy?

Here is the screenshot of the PCAP that is illustrative of the problem: enter image description here

My understanding:

  • the response from the origin is a [PSH, ACK];
  • proxy sends an [ACK] for the data received with that [P.] (wireshark confirms that the next [ACK] is for the [PSH-ACK] received before);
  • 7 seconds passed (take note of the timestamp btw/ the [FIN, ACK] and our POST ([PSH, ACK]));
  • origin sends a [FIN, ACK]. When the first [FIN, ACK] is sent the origin TCP state machine should be in FIN_WAIT_1 state.
  • then we send another POST causing a [RST] in return since the origin was not expecting a [PSH, ACK].

Question:

  • What is the possible explanation for this case?
  • Why is the proxy (nginx) sending another request if it already received a FIN and is actually acknowledging it! (the ack number in the POST [PSH, ACK] packet is actually SEQ_NUMBER + 1 of the [FIN,ACK] - so it's acknowledging the phantom bit FIN.
  • What are the possible reasons for the origin returning a [FIN,ACK] only after 5 seconds and not immediatelly? Read-timeout / idle-timeout?

I do not own the origin - so can not capture there.

Additional details:

The error log on the proxy (nginx error log):

2017/04/17 06:51:07 [error] 123091#0: *225010841 upstream prematurely closed connection while reading response header from upstream, client: X.90.10, server: www.example.com, request: "POST /web/?a=b HTTP/1.1", upstream: "http://X.32.238:80/web/?a=b", host: "www.example.com"

The SEQ and ACK numbers are shown for the last requests in this screenshot:

enter image description here

  • Is this a theoretical question, or do you have a concrete problem you're trying to solve? If it's an actual problem please include logs, configuration, and demonstrate the problem. – Tim Apr 18 '17 at 22:15
  • Yes, this is an actual recurring 502 source. I do not own the origin, so I can't add configurations from that end. I can add it from the proxy, but I have no idea what configuration option could potentially lead to this situation either from systctl or from nginx config. Which configuration should I start with? – Mindaugas Bernatavičius Apr 18 '17 at 22:19
  • Please edit your question to more precisely describe the problem you're having, and your desired end state. Please include whatever logs or configuration you have access to. If its not your server then this might include a curl showing headers (curl -i), to show the high level response. – Tim Apr 18 '17 at 22:26
  • Added nginx error log on the proxy level, added some clarifications on what I'm trying to achieve. – Mindaugas Bernatavičius Apr 18 '17 at 22:38
3

What is the possible explanation for this case?

A race condition between a ~5 seconds idle counter on the origin and variably client-side activity. The third involved variable is of course the network latency.

There seems to be a ~5 seconds idle timer on the origin, while your client is taking ~5 seconds to make a second request (POST) through the Nginx proxy. If the former is longer than the latter (including network latency) you have no problems. If it takes just a teeny bit more for the client request to be sent then you have a problem.

You can see how both the POST and the FIN,ACK from the Nginx are sent pretty much together: 2.4ms and 2.6ms after the origin's FIN,ACK respectively. This could've put you off track here, because I don't think the POST is a response to the origin's FIN,ACK at all. As it is sent 2.4ms after the origin's FIN,ACK

Why is the proxy (nginx) sending another request if it already received a FIN and is actually acknowledging it! (the ack number in the POST [PSH, ACK] packet is actually SEQ_NUMBER + 1 of the [FIN,ACK] - so it's acknowledging the phantom bit FIN.

The ACK number on the POST packet is for the "200 OK" packet most probably. There's no extra data coming from the server side after that HTTP response, so any ACK from the client will be ACKing the same number.

Update: We now know that the POST packet has the ACK number increased in 1, so Nginx knew about the [FIN,ACK]. Further investigation shows this is fine: A machine might send a request and end with a [FIN,ACK] if it's not planning to continue the connection after it receives the response from the remote side, who was to send the requested data back and end with continuing the [FIN,ACK] process.

This doesn't change the fact that there's a race condition where the origin decided to close the connection after 5 seconds idle, thus ignoring the POST packet that comes shortly after (and even sending a RST back - although it's not clear if this RST would've been sent regardless).

What are the possible reasons for the origin returning a [FIN,ACK] only after 5 seconds and not immediatelly? Read-timeout / idle-timeout?

You don't have to return a FIN,ACK immediately, especially since HTTP 1.1 and the introduction of persistent connections. These ~5 seconds seem to be an idle timer on the origin.

Both things are confirmed here: https://en.wikipedia.org/wiki/HTTP_persistent_connection - including a default 5 seconds idle timeout in Apache 2.2 or newer.

Suggested solutions

I can't really suggest a solution without knowing more about your infrastructure, but in rough terms you have a few options:

  • Investigate why the client takes 5 seconds to send a second request. Drawbacks: Time consuming and probably implies application changes.
  • Increase origin's (Apache?) timeout to maybe 10 seconds. Drawbacks: Problems to scale as you're keeping more resources idle. Might need application changes to dispose of the connections as soon as possible.
  • Don't reuse the TCP connection for a second HTTP request, by issuing the "Connection: Close" header. Drawbacks: Higher cost per request as you have to establish a new TCP session. Might entail application changes to issue the header on all requests or changes on Nginx, thus deviating from your default configuration (increased admin costs).
  • Use the "keepalive" option on Nginx inside your upstream configuration to set a keepalive lower than 5 seconds. Drawback: Lots of extra traffic/noise.

Hope this helps :)

  • 1
    Thanks for the comment, it's awesome to see that someone can confirm some of the ideas I had. I also thought about this race condition and that it might be the cause. However this would be true only if the the POST would have the same ACK number of 78958, not 78959 . Since the ACK for the POST and the next [FIN,ACK] sent by the server hosting the proxy (nginx) - it means when the POST was send the TCP stack was aware of the [FIN,ACK] returned by the origin. I added the screenshot with the ACK and SEQ numbers for everyones reference in the question. Would appreciate your opinion on this. – Mindaugas Bernatavičius Apr 19 '17 at 11:23
  • 1
    You are right, the [FIN,ACK] is known by the POST if the ACK# has been increased in 1. Regardless, it decides to still send the data. I have been looking at this and I think it's not wrong - one side might send a request and end with a [FIN,ACK], then wait for the remote side to reply with all the data and continue the connection closing process. It doesn't go against RFC. However in this case the origin does not want to take any more data and resets the connection due to the unexpected non-[FIN,ACK] packet. So the root cause seems to be still the same race condition. – Pedro Perez Apr 19 '17 at 14:43
  • 1
    Thanks Pedro. I do believe that it is now more fruitful to turn to connection states rather than packets. When the responder sends the [FIN,ACK] it switches to the FIN_WAIT_1 state. When the receiver receives it, it switches to the CLOSE_WAIT state. In the CLOSE_WAIT state it waits for the application (nginx in the case of my proxy) to close the connection. However nginx sends some more data and TCP stack can't do anything, but accept it (increasing the ACK number). Please peer review this, I think it's correct but would appreciate someone providing confirmation. – Mindaugas Bernatavičius Apr 19 '17 at 20:10
  • 1
    The key point is in the explanation of the CLOSE-WAIT: The device has received a close request (FIN) from the other device. It must now wait for the application on the local device to acknowledge this request and generate a matching request. – Pedro Perez Apr 19 '17 at 23:13
  • 1
    Thanks, I agree on all the points and seem like our understanding is the same... I learned a lot from this as well. Now my problem is this - can I tweak the TCP stack or nginx configuration to avoid this from the proxy side? Do you think I should create another question or do you have any suggestions... My initial hypothesis is that there is nothing from the proxy side to prevent nginx deciding to send data to CLOSE_WAIT. WDYT ? – Mindaugas Bernatavičius Apr 20 '17 at 10:11
0

I think this caused by the upstream server socket keep alive timeout, and socket will be closed,default socket.setsolinger will not open.

I think we can let nginx upstream servers keepalive timeout。Here another author solve it,please see this

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Not the answer you're looking for? Browse other questions tagged or ask your own question.