[HTTPCORE-392] Initial request headers not added after following 307 redirect

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Duplicate
• Affects Version/s: 4.4-beta1
• Component/s: HttpCore NIO
• Assignee: Unassigned
• Reporter: Kevin Fongson
• Created: 22/Nov/14 03:00
• Updated: 24/Nov/14 18:42
• Resolved: 24/Nov/14 12:22

Description

When HttpAsyncClient receives a 307 Temporary Redirect response from a server the subsequent request to the redirect Location does not have the initial request's headers. This behavior is different from the synchronous HttpClient, which keeps the initial request's headers. Is this intentional or a bug?

I've attached the code I used to test and the debug logs for the synchronous case. The logs for the async request are below.

Thanks and please let me know if you need any more information!

DEBUG logs:

2014-11-22 02:29:19,950 DEBUG [main] (MainClientExec.java:133)  - [exchange: 1] start execution
2014-11-22 02:29:19,958 DEBUG [main] (RequestAddCookies.java:122)  - CookieSpec selected: best-match
2014-11-22 02:29:19,974 DEBUG [main] (RequestAuthCache.java:75)  - Auth cache not set in the context
2014-11-22 02:29:19,974 DEBUG [main] (DefaultClientExchangeHandlerImpl.java:338)  - [exchange: 1] Request connection for {}->http://xxx.yyy.zzz.com:80
2014-11-22 02:29:19,976 DEBUG [main] (PoolingNHttpClientConnectionManager.java:245)  - Connection request: [route: {}->http://xxx.yyy.zzz.com:80][total kept alive: 0; route allocated: 0 of 2; total allocated: 0 of 20]
2014-11-22 02:29:20,148 DEBUG [I/O dispatcher 1] (PoolingNHttpClientConnectionManager.java:462)  - Connection leased: [id: http-outgoing-0][route: {}->http://xxx.yyy.zzz.com:80][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]
2014-11-22 02:29:20,154 DEBUG [I/O dispatcher 1] (DefaultClientExchangeHandlerImpl.java:293)  - [exchange: 1] Connection allocated: http-outgoing-0 [ACTIVE]
2014-11-22 02:29:20,155 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:164)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][r:]: Set attribute http.nio.exchange-handler
2014-11-22 02:29:20,155 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:102)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][rw:]: Event set [w]
2014-11-22 02:29:20,156 DEBUG [I/O dispatcher 1] (LoggingAsyncRequestExecutor.java:58)  - http-outgoing-0 [ACTIVE]: Connected
2014-11-22 02:29:20,156 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:164)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][rw:]: Set attribute http.nio.http-exchange-state
2014-11-22 02:29:20,157 DEBUG [I/O dispatcher 1] (LoggingAsyncRequestExecutor.java:75)  - http-outgoing-0 [ACTIVE] Request ready
2014-11-22 02:29:20,157 DEBUG [I/O dispatcher 1] (MainClientExec.java:168)  - Start connection routing
2014-11-22 02:29:20,159 DEBUG [I/O dispatcher 1] (MainClientExec.java:212)  - Connection route established
2014-11-22 02:29:20,159 DEBUG [I/O dispatcher 1] (MainClientExec.java:238)  - [exchange: 1] Attempt 1 to execute request
2014-11-22 02:29:20,159 DEBUG [I/O dispatcher 1] (MainClientExec.java:245)  - Target auth state: UNCHALLENGED
2014-11-22 02:29:20,160 DEBUG [I/O dispatcher 1] (MainClientExec.java:252)  - Proxy auth state: UNCHALLENGED
2014-11-22 02:29:20,160 DEBUG [I/O dispatcher 1] (ManagedNHttpClientConnectionImpl.java:133)  - http-outgoing-0 >> GET /admin/redirect HTTP/1.1
2014-11-22 02:29:20,161 DEBUG [I/O dispatcher 1] (ManagedNHttpClientConnectionImpl.java:136)  - http-outgoing-0 >> Test-Header: 12345
2014-11-22 02:29:20,161 DEBUG [I/O dispatcher 1] (ManagedNHttpClientConnectionImpl.java:136)  - http-outgoing-0 >> Host: xxx.yyy.zzz.com
2014-11-22 02:29:20,161 DEBUG [I/O dispatcher 1] (ManagedNHttpClientConnectionImpl.java:136)  - http-outgoing-0 >> Connection: Keep-Alive
2014-11-22 02:29:20,161 DEBUG [I/O dispatcher 1] (ManagedNHttpClientConnectionImpl.java:136)  - http-outgoing-0 >> User-Agent: Apache-HttpAsyncClient/4.0.1 (java 1.5)
2014-11-22 02:29:20,162 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:102)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][rw:]: Event set [w]
2014-11-22 02:29:20,162 DEBUG [I/O dispatcher 1] (MainClientExec.java:291)  - [exchange: 1] Request completed
2014-11-22 02:29:20,162 DEBUG [I/O dispatcher 1] (LoggingAsyncRequestExecutor.java:75)  - http-outgoing-0 [ACTIVE] Request ready
2014-11-22 02:29:20,164 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:201)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][rw:w]: 196 bytes written
2014-11-22 02:29:20,164 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 >> "GET /admin/redirect HTTP/1.1[\r][\n]"
2014-11-22 02:29:20,164 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 >> "Test-Header: 12345[\r][\n]"
2014-11-22 02:29:20,165 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 >> "Host: xxx.yyy.zzz.com[\r][\n]"
2014-11-22 02:29:20,165 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 >> "Connection: Keep-Alive[\r][\n]"
2014-11-22 02:29:20,165 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 >> "User-Agent: Apache-HttpAsyncClient/4.0.1 (java 1.5)[\r][\n]"
2014-11-22 02:29:20,165 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 >> "[\r][\n]"
2014-11-22 02:29:20,165 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:109)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][r:w]: Event cleared [w]
2014-11-22 02:29:20,242 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:186)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][r:r]: 147 bytes read
2014-11-22 02:29:20,242 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 << "HTTP/1.1 307 Temporary Redirect[\r][\n]"
2014-11-22 02:29:20,242 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 << "Location: http://aaa.bbb.ccc.com/admin/redirect[\r][\n]"
2014-11-22 02:29:20,243 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 << "Content-Length: 0[\r][\n]"
2014-11-22 02:29:20,243 DEBUG [I/O dispatcher 1] (Wire.java:54)  - http-outgoing-0 << "[\r][\n]"
2014-11-22 02:29:20,248 DEBUG [I/O dispatcher 1] (ManagedNHttpClientConnectionImpl.java:122)  - http-outgoing-0 << HTTP/1.1 307 Temporary Redirect
2014-11-22 02:29:20,248 DEBUG [I/O dispatcher 1] (ManagedNHttpClientConnectionImpl.java:125)  - http-outgoing-0 << Location: http://aaa.bbb.ccc.com/admin/redirect
2014-11-22 02:29:20,248 DEBUG [I/O dispatcher 1] (ManagedNHttpClientConnectionImpl.java:125)  - http-outgoing-0 << Content-Length: 0
2014-11-22 02:29:20,248 DEBUG [I/O dispatcher 1] (LoggingAsyncRequestExecutor.java:110)  - http-outgoing-0 [ACTIVE] Response received
2014-11-22 02:29:20,248 DEBUG [I/O dispatcher 1] (MainClientExec.java:302)  - [exchange: 1] Response received HTTP/1.1 307 Temporary Redirect
2014-11-22 02:29:20,249 DEBUG [I/O dispatcher 1] (DefaultRedirectStrategy.java:140)  - Redirect requested to location 'http://aaa.bbb.ccc.com/admin/redirect'
2014-11-22 02:29:20,253 DEBUG [I/O dispatcher 1] (LoggingAsyncRequestExecutor.java:85)  - http-outgoing-0 [ACTIVE] Input ready
2014-11-22 02:29:20,253 DEBUG [I/O dispatcher 1] (MainClientExec.java:341)  - [exchange: 1] Consume content
2014-11-22 02:29:20,253 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:186)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][r:r]: 0 bytes read
2014-11-22 02:29:20,256 DEBUG [I/O dispatcher 1] (MainClientExec.java:378)  - [exchange: 1] Connection can be kept alive indefinitely
2014-11-22 02:29:20,257 DEBUG [I/O dispatcher 1] (MainClientExec.java:428)  - [exchange: 1] Redirecting to 'http://aaa.bbb.ccc.com/admin/redirect'
2014-11-22 02:29:20,258 DEBUG [I/O dispatcher 1] (MainClientExec.java:442)  - [exchange: 1] Resetting target auth state
2014-11-22 02:29:20,266 DEBUG [I/O dispatcher 1] (DefaultClientExchangeHandlerImpl.java:206)  - [exchange: 1] releasing connection
2014-11-22 02:29:20,267 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:171)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][r:r]: Remove attribute http.nio.exchange-handler
2014-11-22 02:29:20,267 DEBUG [I/O dispatcher 1] (PoolingNHttpClientConnectionManager.java:279)  - Releasing connection: [id: http-outgoing-0][route: {}->http://xxx.yyy.zzz.com:80][total kept alive: 0; route allocated: 1 of 2; total allocated: 1 of 20]
2014-11-22 02:29:20,267 DEBUG [I/O dispatcher 1] (PoolingNHttpClientConnectionManager.java:293)  - Connection [id: http-outgoing-0][route: {}->http://xxx.yyy.zzz.com:80] can be kept alive indefinitely
2014-11-22 02:29:20,267 DEBUG [I/O dispatcher 1] (PoolingNHttpClientConnectionManager.java:299)  - Connection released: [id: http-outgoing-0][route: {}->http://xxx.yyy.zzz.com:80][total kept alive: 1; route allocated: 1 of 2; total allocated: 1 of 20]
2014-11-22 02:29:20,268 DEBUG [I/O dispatcher 1] (RequestAddCookies.java:122)  - CookieSpec selected: best-match
2014-11-22 02:29:20,276 DEBUG [I/O dispatcher 1] (RequestAuthCache.java:75)  - Auth cache not set in the context
2014-11-22 02:29:20,277 DEBUG [I/O dispatcher 1] (DefaultClientExchangeHandlerImpl.java:338)  - [exchange: 1] Request connection for {}->http://aaa.bbb.ccc.com:80
2014-11-22 02:29:20,277 DEBUG [I/O dispatcher 1] (PoolingNHttpClientConnectionManager.java:245)  - Connection request: [route: {}->http://aaa.bbb.ccc.com:80][total kept alive: 1; route allocated: 0 of 2; total allocated: 1 of 20]
2014-11-22 02:29:20,278 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:102)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][rw:r]: Event set [w]
2014-11-22 02:29:20,278 DEBUG [I/O dispatcher 1] (LoggingAsyncRequestExecutor.java:89)  - http-outgoing-0 [ACTIVE] [content length: 0; pos: 0; completed: true]
2014-11-22 02:29:20,278 DEBUG [I/O dispatcher 1] (LoggingAsyncRequestExecutor.java:75)  - http-outgoing-0 [ACTIVE] Request ready
2014-11-22 02:29:20,279 DEBUG [I/O dispatcher 1] (LoggingIOSession.java:109)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][r:w]: Event cleared [w]
2014-11-22 02:29:20,354 DEBUG [I/O dispatcher 2] (PoolingNHttpClientConnectionManager.java:462)  - Connection leased: [id: http-outgoing-1][route: {}->http://aaa.bbb.ccc.com:80][total kept alive: 1; route allocated: 1 of 2; total allocated: 2 of 20]
2014-11-22 02:29:20,354 DEBUG [I/O dispatcher 2] (DefaultClientExchangeHandlerImpl.java:293)  - [exchange: 1] Connection allocated: http-outgoing-1 [ACTIVE]
2014-11-22 02:29:20,355 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:164)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][r:]: Set attribute http.nio.exchange-handler
2014-11-22 02:29:20,355 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:102)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][rw:]: Event set [w]
2014-11-22 02:29:20,355 DEBUG [I/O dispatcher 2] (LoggingAsyncRequestExecutor.java:58)  - http-outgoing-1 [ACTIVE]: Connected
2014-11-22 02:29:20,355 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:164)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][rw:]: Set attribute http.nio.http-exchange-state
2014-11-22 02:29:20,355 DEBUG [I/O dispatcher 2] (LoggingAsyncRequestExecutor.java:75)  - http-outgoing-1 [ACTIVE] Request ready
2014-11-22 02:29:20,355 DEBUG [I/O dispatcher 2] (MainClientExec.java:168)  - Start connection routing
2014-11-22 02:29:20,355 DEBUG [I/O dispatcher 2] (MainClientExec.java:212)  - Connection route established
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (MainClientExec.java:238)  - [exchange: 1] Attempt 2 to execute request
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (MainClientExec.java:245)  - Target auth state: UNCHALLENGED
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (MainClientExec.java:252)  - Proxy auth state: UNCHALLENGED
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (ManagedNHttpClientConnectionImpl.java:133)  - http-outgoing-1 >> GET /admin/redirect HTTP/1.1
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (ManagedNHttpClientConnectionImpl.java:136)  - http-outgoing-1 >> Host: aaa.bbb.ccc.com
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (ManagedNHttpClientConnectionImpl.java:136)  - http-outgoing-1 >> Connection: Keep-Alive
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (ManagedNHttpClientConnectionImpl.java:136)  - http-outgoing-1 >> User-Agent: Apache-HttpAsyncClient/4.0.1 (java 1.5)
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:102)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][rw:]: Event set [w]
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (MainClientExec.java:291)  - [exchange: 1] Request completed
2014-11-22 02:29:20,356 DEBUG [I/O dispatcher 2] (LoggingAsyncRequestExecutor.java:75)  - http-outgoing-1 [ACTIVE] Request ready
2014-11-22 02:29:20,357 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:201)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][rw:w]: 176 bytes written
2014-11-22 02:29:20,357 DEBUG [I/O dispatcher 2] (Wire.java:54)  - http-outgoing-1 >> "GET /admin/redirect HTTP/1.1[\r][\n]"
2014-11-22 02:29:20,358 DEBUG [I/O dispatcher 2] (Wire.java:54)  - http-outgoing-1 >> "Host: aaa.bbb.ccc.com[\r][\n]"
2014-11-22 02:29:20,359 DEBUG [I/O dispatcher 2] (Wire.java:54)  - http-outgoing-1 >> "Connection: Keep-Alive[\r][\n]"
2014-11-22 02:29:20,359 DEBUG [I/O dispatcher 2] (Wire.java:54)  - http-outgoing-1 >> "User-Agent: Apache-HttpAsyncClient/4.0.1 (java 1.5)[\r][\n]"
2014-11-22 02:29:20,359 DEBUG [I/O dispatcher 2] (Wire.java:54)  - http-outgoing-1 >> "[\r][\n]"
2014-11-22 02:29:20,359 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:109)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][r:w]: Event cleared [w]
2014-11-22 02:29:20,443 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:186)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][r:r]: 38 bytes read
2014-11-22 02:29:20,443 DEBUG [I/O dispatcher 2] (Wire.java:54)  - http-outgoing-1 << "HTTP/1.1 200 OK[\r][\n]"
2014-11-22 02:29:20,443 DEBUG [I/O dispatcher 2] (Wire.java:54)  - http-outgoing-1 << "Content-Length: 0[\r][\n]"
2014-11-22 02:29:20,444 DEBUG [I/O dispatcher 2] (Wire.java:54)  - http-outgoing-1 << "[\r][\n]"
2014-11-22 02:29:20,444 DEBUG [I/O dispatcher 2] (ManagedNHttpClientConnectionImpl.java:122)  - http-outgoing-1 << HTTP/1.1 200 OK
2014-11-22 02:29:20,444 DEBUG [I/O dispatcher 2] (ManagedNHttpClientConnectionImpl.java:125)  - http-outgoing-1 << Content-Length: 0
2014-11-22 02:29:20,444 DEBUG [I/O dispatcher 2] (LoggingAsyncRequestExecutor.java:110)  - http-outgoing-1 [ACTIVE] Response received
2014-11-22 02:29:20,444 DEBUG [I/O dispatcher 2] (MainClientExec.java:302)  - [exchange: 1] Response received HTTP/1.1 200 OK
2014-11-22 02:29:20,447 DEBUG [I/O dispatcher 2] (LoggingAsyncRequestExecutor.java:85)  - http-outgoing-1 [ACTIVE] Input ready
2014-11-22 02:29:20,447 DEBUG [I/O dispatcher 2] (MainClientExec.java:341)  - [exchange: 1] Consume content
2014-11-22 02:29:20,447 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:186)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][r:r]: 0 bytes read
2014-11-22 02:29:20,448 DEBUG [I/O dispatcher 2] (MainClientExec.java:378)  - [exchange: 1] Connection can be kept alive indefinitely
2014-11-22 02:29:20,448 DEBUG [I/O dispatcher 2] (MainClientExec.java:420)  - [exchange: 1] Response processed
2014-11-22 02:29:20,448 DEBUG [I/O dispatcher 2] (DefaultClientExchangeHandlerImpl.java:206)  - [exchange: 1] releasing connection
2014-11-22 02:29:20,448 DEBUG [I/O dispatcher 2] (LoggingIOSession.java:171)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][r:r]: Remove attribute http.nio.exchange-handler
2014-11-22 02:29:20,448 DEBUG [I/O dispatcher 2] (PoolingNHttpClientConnectionManager.java:279)  - Releasing connection: [id: http-outgoing-1][route: {}->http://aaa.bbb.ccc.com:80][total kept alive: 1; route allocated: 1 of 2; total allocated: 2 of 20]
2014-11-22 02:29:20,448 DEBUG [I/O dispatcher 2] (PoolingNHttpClientConnectionManager.java:293)  - Connection [id: http-outgoing-1][route: {}->http://aaa.bbb.ccc.com:80] can be kept alive indefinitely
2014-11-22 02:29:20,448 DEBUG [I/O dispatcher 2] (PoolingNHttpClientConnectionManager.java:299)  - Connection released: [id: http-outgoing-1][route: {}->http://aaa.bbb.ccc.com:80][total kept alive: 2; route allocated: 1 of 2; total allocated: 2 of 20]
2014-11-22 02:29:20,449 DEBUG [I/O dispatcher 2] (LoggingAsyncRequestExecutor.java:89)  - http-outgoing-1 [ACTIVE] [content length: 0; pos: 0; completed: true]

2014-11-22 02:29:20,450 DEBUG [main] (PoolingNHttpClientConnectionManager.java:199)  - Connection manager is shutting down
2014-11-22 02:29:20,450 DEBUG [main] (LoggingIOSession.java:115)  - http-outgoing-1 1.1.1.1:55425<->3.3.3.3:80[ACTIVE][r:r]: Close
2014-11-22 02:29:20,451 DEBUG [main] (LoggingIOSession.java:115)  - http-outgoing-0 1.1.1.1:37002<->2.2.2.2:80[ACTIVE][r:w]: Close
2014-11-22 02:29:20,451 DEBUG [I/O dispatcher 2] (LoggingAsyncRequestExecutor.java:66)  - http-outgoing-1 [CLOSED]: Disconnected
2014-11-22 02:29:20,456 DEBUG [I/O dispatcher 1] (LoggingAsyncRequestExecutor.java:66)  - http-outgoing-0 [CLOSED]: Disconnected
2014-11-22 02:29:20,458 DEBUG [main] (PoolingNHttpClientConnectionManager.java:201)  - Connection manager shut down

Issue Links

• duplicates: HTTPASYNC-73 Request headers are not copied upon redirect