ADDITIONAL SYSTEM INFORMATION :
Reproduced on Windows 7
but also occurs on linux servers
Reproduced with :
- Oracle JDK 1.8.0_172
- OpenJDK 10.0.2
A DESCRIPTION OF THE PROBLEM :
As described here : https://bugs.java.com/bugdatabase/view_bug.do?bug_id=6382788, the JDK is able to retry http/https requests when the server doesn't respond with a correct HTTP response.
When it occurs on a POST request : the body of the POST is lost during the retry process. Only the request headers are sent, leaving the remote server waiting for the body.
This bug is linked to this former bug, when it was the request header that was lost :
https://bugs.java.com/bugdatabase/view_bug.do?bug_id=8025710
Please note that the JDK handles this kind of retries in a least two places :
- sun.net.www.http.HttpClient#parseHTTP
- sun.net.www.http.HttpClient#parseHTTPHeader
In my case, the cause of the retry is a very specific timeout behaviour on a cached TLS connection :
I described it in another bug report : internal review ID : 9056455
STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
The testcase I described in the bug report "internal review ID : 9056455" is able to reproduced the behaviour reliably.
But I guess it is possible to simulate the problem more easily
( I don't know if the problem is specific to HTTPS, but ssl debug are valuable to observe the problem )
- set up an HTTPS server responding to POST requests but which close abrutly the connection without any response one out of two times
- Set up a forward proxy usable for calling the previous server
- make a HTTPS POST call (with a body) with HttpsURLConnection to the previous server through the proxy (at the moment where the request will first be closed abrutly by the server)
EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
Transparent retry of the POST will work and the server will correctly received the body on the second try
JDK logs on sun.net.www. and ssl debug logs shows that two TLS connection was made and that the body was sent in each case.
ACTUAL -
The JDK tries to make a transparent retry of the POST but only send the headers and not the body on this retry :
The server wait for the body (as the requet contains a non-null Content-Length) and the client call eventually fail with a read timeout
JDK logs on sun.net.www. and ssl debug logs shows that two TLS connection was made but that the body was not sent on the second call
During the retry we have :
(...)
main, WRITE: TLSv1.2 Alert, length = 26
[Raw write]: length = 31
0000: 15 03 03 00 1A 00 00 00 00 00 00 00 05 AE EA C8 ................
0010: 41 BB E8 1A 3A 64 08 8D 57 4A 3D 63 0A 34 A9 A...:d..WJ=c.4.
main, called closeSocket(false)
main, called close()
main, called closeInternal(true)
août 03, 2018 7:49:47 PM sun.net.www.protocol.http.HttpURLConnection sendCONNECTRequest
PRÃCIS: sun.net.www.MessageHeader@14fc5f045 pairs: {CONNECT xxxxxxxx.com:443 HTTP/1.1: null}{User-Agent: Java/1.8.0_172}{Host: api.orange.com}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Proxy-Connection: keep-alive}
août 03, 2018 7:49:47 PM sun.net.www.protocol.http.HttpURLConnection doTunneling
PRÃCIS: sun.net.www.MessageHeader@6e2829c71 pairs: {null: HTTP/1.1 200 Connection established}
Allow unsafe renegotiation: false
Allow legacy hello messages: true
(...)
Here the stack from the timeout :
(...)
Padded plaintext before ENCRYPTION: len = 399
0000: 50 4F 53 54 20 2F 6F 70 65 6E 69 64 63 6F 6E 6E POST /openidconn
0010: 65 63 74 2F 66 72 2F 76 31 2F 74 6F 6B 65 6E 20 ect/fr/v1/token
0020: 48 54 54 50 2F 31 2E 31 0D 0A 43 6F 6E 74 65 6E HTTP/1.1..Conten
0030: 74 2D 54 79 70 65 3A 20 61 70 70 6C 69 63 61 74 t-Type: applicat
0040: 69 6F 6E 2F 78 2D 77 77 77 2D 66 6F 72 6D 2D 75 ion/x-www-form-u
0050: 72 6C 65 6E 63 6F 64 65 64 0D 0A 63 68 61 72 73 rlencoded..chars
0060: 65 74 3A 20 75 74 66 2D 38 0D 0A 41 75 74 68 6F et: utf-8..Autho
0070: 72 69 7A 61 74 69 6F 6E 3A 20 42 61 73 69 63 20 rization: Basic
(deleted)
00C0: 53 77 3D 3D 0D 0A 43 61 63 68 65 2D 43 6F 6E 74 xxxx..Cache-Cont
00D0: 72 6F 6C 3A 20 6E 6F 2D 63 61 63 68 65 0D 0A 50 rol: no-cache..P
00E0: 72 61 67 6D 61 3A 20 6E 6F 2D 63 61 63 68 65 0D ragma: no-cache.
00F0: 0A 55 73 65 72 2D 41 67 65 6E 74 3A 20 4A 61 76 .User-Agent: Jav
0100: 61 2F 31 2E 38 2E 30 5F 31 37 32 0D 0A 48 6F 73 a/1.8.0_172..Hos
0110: 74 3A (deleted) 63 6F t: api.xxxxxx.co
0120: 6D 0D 0A 41 63 63 65 70 74 3A 20 74 65 78 74 2F m..Accept: text/
0130: 68 74 6D 6C 2C 20 69 6D 61 67 65 2F 67 69 66 2C html, image/gif,
0140: 20 69 6D 61 67 65 2F 6A 70 65 67 2C 20 2A 3B 20 image/jpeg, *;
0150: 71 3D 2E 32 2C 20 2A 2F 2A 3B 20 71 3D 2E 32 0D q=.2, */*; q=.2.
0160: 0A 43 6F 6E 6E 65 63 74 69 6F 6E 3A 20 6B 65 65 .Connection: kee
0170: 70 2D 61 6C 69 76 65 0D 0A 43 6F 6E 74 65 6E 74 p-alive..Content
0180: 2D 4C 65 6E 67 74 68 3A 20 36 35 0D 0A 0D 0A -Length: 65....
main, WRITE: TLSv1.2 Application Data, length = 423
[Raw write]: length = 428
0000: 17 03 03 01 A7 00 00 00 00 00 00 00 01 54 A3 9B .............T..
0010: 86 64 95 19 C0 EA 32 A4 6E DA 58 DA C8 5C 3C 35 .d....2.n.X..\<5
0020: D3 4E FC D8 D4 60 9E 9F A7 BC B4 10 74 9F A4 12 .N...`......t...
0030: 10 EF 3F C4 C9 5C 3B 82 A1 AA E4 FC D7 11 72 59 ..?..\;.......rY
0040: 35 91 17 5C D5 A9 6A FC 88 DA C7 18 51 F9 82 0A 5..\..j.....Q...
0050: 50 26 EC 57 E0 B1 6B 4B BA FB DC 25 CA 30 35 8C P&.W..kK...%.05.
0060: FC 5D 4B 6B 62 7A 74 86 20 97 D6 74 7D 1A DC 17 .]Kkbzt. ..t....
0070: A9 F2 DE B7 3D 3C 07 93 A8 8F CB 85 03 2F 5F 3C ....=<......./_<
0080: 31 1A 74 82 9E D0 52 81 2E FB 90 AD 36 B1 DC 66 1.t...R.....6..f
0090: EA 4E 83 B5 B8 93 2F D6 4E A1 42 81 40 65 72 BD .N..../.N.B.@er.
00A0: 5B 30 27 CB 3B C8 33 9A 00 84 A5 68 A6 13 32 C3 [0'.;.3....h..2.
00B0: 21 F5 72 2B EB B2 B2 CB 5D 17 DD 08 49 8A C1 FD !.r+....]...I...
00C0: 0E 09 70 D0 26 F8 8C 9A 45 CF 55 99 7A 92 F3 A3 ..p.&...E.U.z...
00D0: DB CC E9 80 F8 A6 76 46 C8 DA 33 A9 3E A3 6B A9 ......vF..3.>.k.
00E0: 65 18 BA D9 DD 25 BC AE 21 F2 2B 6A 9F CE 68 45 e....%..!.+j..hE
00F0: 61 D1 04 6B 77 10 BE 40 55 31 7D D1 6E E1 02 E2 a..kw..@U1..n...
0100: EF 61 61 02 FF 8D A3 CB 72 E1 18 98 0F A9 81 57 .aa.....r......W
0110: 7F 61 AC 5B A1 71 BC B0 D8 D7 39 78 D4 AF 98 C1 .a.[.q....9x....
0120: 39 CE D0 7B FE 75 E6 6F 3C 64 E1 13 19 89 01 1E 9....u.o<d......
0130: 08 B8 A9 E7 79 54 EA BB 32 88 EB 2D 9E B3 3E 4D ....yT..2..-..>M
0140: FA 2C 0B 00 84 7D 3C 04 6A CB 91 4E 43 C3 A5 83 .,....<.j..NC...
0150: 81 8F D6 AC 45 6F BB 53 91 A7 D5 AF 80 FB 65 0E ....Eo.S......e.
0160: 5C 4D DB BF 95 FA C4 98 9F 95 6B 4C D6 3E 8A E1 \M........kL.>..
0170: F5 72 23 FC 15 36 39 E1 DF EF A2 7C E5 58 71 80 .r#..69......Xq.
0180: 84 26 39 93 C9 5B A7 FF 80 9F 4B 64 3C A0 60 48 .&9..[....Kd<.`H
0190: 8D 4C 29 A1 9B 33 29 7F 78 58 B0 46 A3 2D 47 DC .L)..3).xX.F.-G.
01A0: 4A F7 74 4C C5 28 CD 5A F7 3C 96 4F J.tL.(.Z.<.O
main, handling exception: java.net.SocketTimeoutException: Read timed out
main, called close()
main, called closeInternal(true)
main, SEND TLSv1.2 ALERT: warning, description = close_notify
Padded plaintext before ENCRYPTION: len = 2
0000: 01 00 ..
main, WRITE: TLSv1.2 Alert, length = 26
[Raw write]: length = 31
0000: 15 03 03 00 1A 00 00 00 00 00 00 00 02 8A 6C 98 ..............l.
0010: 8F 35 34 06 0F 52 77 F6 08 9B 36 DF 46 B4 F3 .54..Rw...6.F..
main, called closeSocket(true)
main, called close()
main, called closeInternal(true)
java.net.SocketTimeoutException: Read timed out
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
at java.net.SocketInputStream.read(SocketInputStream.java:171)
at java.net.SocketInputStream.read(SocketInputStream.java:141)
at sun.security.ssl.InputRecord.readFully(InputRecord.java:465)
at sun.security.ssl.InputRecord.read(InputRecord.java:503)
at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:983)
at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:940)
at sun.security.ssl.AppInputStream.read(AppInputStream.java:105)
at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:286)
at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:735)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:678)
at sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:848)
at sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:678)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1587)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1492)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)
at sun.net.www.protocol.https.HttpsURLConnectionImpl.getResponseCode(HttpsURLConnectionImpl.java:347)
at TestCase.testCaseMethod
---------- BEGIN SOURCE ----------
Here the test case from bug report "internal review ID : 9056455"
It make two request, but depending on the test setup, one request may be sufficient to reproduce (cf Steps to Reproduce)
package testcase;
import org.apache.commons.io.IOUtils;
import org.junit.Test;
import javax.net.ssl.HttpsURLConnection;
import java.io.InputStream;
import java.io.OutputStream;
import java.net.InetSocketAddress;
import java.net.Proxy;
import java.net.SocketAddress;
import java.net.URL;
import java.nio.charset.StandardCharsets;
public class TestCaseHttpsURLConnection {
@Test
public void testCaseMethod() throws Exception {
URL url = new URL( "https://some.tls.server/xxx/yyy");
SocketAddress sa = new InetSocketAddress("some.corporate.proxy",8080);
Proxy proxy = new Proxy(Proxy.Type.HTTP,sa);
int nb = 0;
while(++nb <= 2) {
try {
System.out.println("*********** REQUEST n° " + nb + " ******************");
HttpsURLConnection urlConnection = (HttpsURLConnection) url.openConnection(proxy);
urlConnection.setConnectTimeout(1000);
urlConnection.setReadTimeout(15000);
urlConnection.setDoInput(true);
urlConnection.setDoOutput(true);
urlConnection.setRequestMethod("POST");
urlConnection.setUseCaches(false);
urlConnection.setRequestProperty( "Content-Type", "application/x-www-form-urlencoded");
urlConnection.setRequestProperty( "charset", "utf-8");
urlConnection.setRequestProperty("Authorization", "Basic xxxxxxxxxx==");
urlConnection.setRequestProperty("Connection", "keep-alive");
String urlParameters = "param1=a¶m2=b¶m3=c";
byte[] postData = urlParameters.getBytes( StandardCharsets.UTF_8 );
OutputStream outputStream = urlConnection.getOutputStream();
outputStream.write(postData);
outputStream.close();
int responseCode = urlConnection.getResponseCode();
System.out.printf("UrlConnection - ResponseCode : %s%n",responseCode);
String output;
InputStream inputStream;
if(responseCode < 400) {
inputStream = urlConnection.getInputStream();
} else {
inputStream = urlConnection.getErrorStream();
}
output = IOUtils.toString(inputStream); // consumint the inputstream is also important to make the httpsclient cacheable
inputStream.close(); // Important to make the client httpscacheable
// urlConnection.disconnect(); // NO ...
System.out.printf("Response body : %s%n",output);
} finally {
try {
Thread.sleep(35000);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}
}
}
---------- END SOURCE ----------
CUSTOMER SUBMITTED WORKAROUND :
In my case : disable keepalive connection which triggered the retry condition too often
Other workaround : disable retries on POST with proprety sun.net.http.retryPost to have a fail fast behaviour (but losing retries capability)
FREQUENCY : always