Search code examples
javahttpurlconnection

HttpURLConnection failing on POST with HTTP 400

HttpURLConnection sometimes fails on POST operations to a http URL. In my case the following fails about one of a hundred times:

byte[] formData = ("mgnlUserId=" + user + "&mgnlUserPSWD=" + user).getBytes(StandardCharsets.UTF_8);
URL url = new URL("http://localhost:8080/magnoliaAuthor/.magnolia/admincentral");
HttpURLConnection connection = (HttpURLConnection) url.openConnection();
connection.setDoOutput(true);
connection.setRequestProperty("Content-Type", "application/x-www-form-urlencoded");
connection.setRequestMethod("POST");
connection.setRequestProperty("charset", "utf-8");
connection.setRequestProperty("Content-Length", Integer.toString(formData.length));
connection.getOutputStream().write(formData);
connection.connect();

// Sometimes fails with response code being 400
assertEquals(200, connection.getResponseCode());

The server complains about the bad request too:

HTTP Status 400 – Bad Request
Invalid character found in method name [User-Agent:]. HTTP method names must be tokens
The server cannot or will not process the request due to something that is perceived to be a client error (e.g., malformed request syntax, invalid request message framing, or deceptive request routing).
java.lang.IllegalArgumentException: Invalid character found in method name [User-Agent:]. HTTP method names must be tokens

Here's some example code for reproducing the problem.

For now this looks like a bug to me but I couldn't find anything related in the Java bug tracker.

Anyone experiencing similar issues and has a workaround?

Solution

  • This is indeed a bug of HttpURLConnection.

    Looking at the HTTP request going over the wire I can see the HTTP method is set to User-Agent: instead of GET:

    enter image description here

    And the log output show the same faulty request being sent:

    Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: ProxySelector Request for http://localhost:8080/magnoliaAuthor/.magnolia/admincentral
Nov 03, 2021 8:37:01 PM sun.net.www.http.HttpClient logFinest
FINEST: KeepAlive stream retrieved from the cache, sun.net.www.http.HttpClient(http://localhost:8080/magnoliaAuthor/.magnolia/admincentral;jsessionid=44DEE0C8C535782A6B4932E9F0D455ED)
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: Proxy used: DIRECT
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@15b170d89 pairs: {POST /magnoliaAuthor/.magnolia/admincentral HTTP/1.1: null}{Content-Type: application/x-www-form-urlencoded}{Cookie: csrf=ZOxgq4P_WMgLjCm3J4mWPEFFNhmIUiHlq9of5JhtKys}{charset: utf-8}{User-Agent: Java/1.8.0_181}{Host: localhost:8080}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}{Content-Length: 92}
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@15b170d89 pairs: {POST /magnoliaAuthor/.magnolia/admincentral HTTP/1.1: null}{Content-Type: application/x-www-form-urlencoded}{Cookie: csrf=ZOxgq4P_WMgLjCm3J4mWPEFFNhmIUiHlq9of5JhtKys}{charset: utf-8}{User-Agent: Java/1.8.0_181}{Host: localhost:8080}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: keep-alive}{Content-Length: 92}
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection getInputStream0
FINE: sun.net.www.MessageHeader@52ae5ad55 pairs: {null: HTTP/1.1 302}{Set-Cookie: JSESSIONID=88DCCC46C9E70CBA8262CF8060A033C0; Path=/magnoliaAuthor; HttpOnly}{Location: /magnoliaAuthor/.magnolia/admincentral;jsessionid=88DCCC46C9E70CBA8262CF8060A033C0}{Content-Length: 0}{Date: Wed, 03 Nov 2021 19:37:01 GMT}
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection followRedirect0
FINE: Redirected from http://localhost:8080/magnoliaAuthor/.magnolia/admincentral to http://localhost:8080/magnoliaAuthor/.magnolia/admincentral;jsessionid=88DCCC46C9E70CBA8262CF8060A033C0
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: ProxySelector Request for http://localhost:8080/magnoliaAuthor/.magnolia/admincentral;jsessionid=88DCCC46C9E70CBA8262CF8060A033C0
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection plainConnect0
FINEST: Proxy used: DIRECT
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection writeRequests
FINE: sun.net.www.MessageHeader@774fca3c4 pairs: {User-Agent: Java/1.8.0_181}{Host: localhost:8080}{Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2}{Connection: close}
Nov 03, 2021 8:37:01 PM sun.net.www.protocol.http.HttpURLConnection getInputStream0
FINE: sun.net.www.MessageHeader@57256a0d6 pairs: {null: HTTP/1.1 400}{Content-Type: text/html;charset=utf-8}{Content-Language: en}{Content-Length: 2244}{Date: Wed, 03 Nov 2021 19:37:01 GMT}{Connection: close}

    Digging deeper I found out that, when HttpURLConnection initiates a POST on a reused connection but finds the socket closed, it will internally recover and open a new connection. If this POST succeeds and the server sends a redirect status (302) it will attempt to follow the redirect. However, internally it fails to correctly initialise the request headers: after creating a new set of headers, it will not set the HTTP method because failedOnce is true at this point from the first POST on the closed socket

    Update: this is now tracked as a bug.

    Update 2: this has now been fixed