Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

When Request Method is "HEAD" and setFollowRedirect is set to true. The method of the second redirect request is GET. #1728

Closed
lakxtxue opened this issue Jun 20, 2020 · 11 comments · Fixed by #1736
Closed

When Request Method is "HEAD" and setFollowRedirect is set to true. The method of the second redirect request is GET. #1728

lakxtxue opened this issue Jun 20, 2020 · 11 comments · Fixed by #1736
Assignees
@TomGranot
Milestone
2.12.3

Comments

@lakxtxue
Copy link

When Request Method is "HEAD" and setFollowRedirect is set to true. The method of the second redirect request is GET.
When I download a large file, it will time out here, in fact it has been downloading

Caused by: java.util.concurrent.TimeoutException: Request timeout to 127.0.0.1/127.0.0.1:8888 after 60000 ms at org.asynchttpclient.netty.timeout.TimeoutTimerTask.expire(TimeoutTimerTask.java:43) at org.asynchttpclient.netty.timeout.RequestTimeoutTimerTask.run(RequestTimeoutTimerTask.java:50) at io.netty.util.HashedWheelTimer$HashedWheelTimeout.expire(HashedWheelTimer.java:672) at io.netty.util.HashedWheelTimer$HashedWheelBucket.expireTimeouts(HashedWheelTimer.java:747) at io.netty.util.HashedWheelTimer$Worker.run(HashedWheelTimer.java:472) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.base/java.lang.Thread.run(Thread.java:834)
@TomGranot
Copy link
Contributor

@lakxtxue hi - I've applied to maintain this library, so I'm taking a look at open issues to see whether I can maybe help out.

As a general note, a paste of the code tends to help in these issues - if not for better comprehension then at least to save a few lines of reproduction:)

Just to make sure I follow: you've got a large resource located at urlA. When dispatching a HEAD request to urlA, you're getting back a 301 that points to urlB, which is followed because setFollowRedirect is set to true. The request to urlB is not a HEAD but a GET.

Since the resource hiding behind urlA (and in effect, urlB) is quite large, you're getting a timeout instead of getting a response back from urlB.

What I assume you'd like to happen is for the same request type that was originally dispatched to be used in the followup requests as well.

Is this a correct assessment?

@lakxtxue
Copy link
Author

@Tomgs hi, yes, that's what I mean, because I use http to download large files, I need to get the size of the file first. When accessing this file resource, there will be a redirection to the real address. I use the HEAD request method to get the file size. AsyncHttpClient encounters a 301 When it was directed, it did not continue to access with a HEAD request but used a GET request to access the redirected address. Now I use HttpURLConnection instead, and I get the result I want correctly.
This is my code using HttpURLConnection

URL u = new URL(url);
HttpURLConnection httpConnection = (HttpURLConnection) u.openConnection();
httpConnection.setRequestMethod("HEAD");
httpConnection.connect();
this.dataSize = httpConnection.getContentLengthLong();

I used AsyncHttpClient to do the same thing. I also set the HEAD request method and configured setFollowRedirect to true. The result was a timeout. I found through packet capture that AsyncHttpClient used GET request when redirecting and started to download files. I hope it will behave like HttpURLConnection.

I don’t know if the expression is clear or not, because my English is not very good. I have found a lot of http libraries. AsyncHttpClient is the only one that can provide me with the greatest flexibility. I really hope it will get better and better.

@TomGranot
Copy link
Contributor

TomGranot commented Aug 24, 2020 •
edited

@lakxtxue I see what you're saying, and it's perfectly clear. Your English is much better than many of the non-native English speakers I've met (I'm also not a native speaker, btw!).

I actually wasn't sure what the HTTP protocol specification says about method handling in redirects.

I didn't go to the spec itself, but MDN says that when a user-agent (like AsyncHttpClient) sends a request and encounters a 301, only GET requests remain unchanged, an the rest of the HTTP methods "may or may not be changed".

I am still familiarising myself with the library, but an initial search seems to show that it's related to the underlying Netty provider this library is using.

I'd say that it's reasonable for the method to persist between redirects, but would have to dig deeper later tonight to see how it can be actually implemented and open a PR. If I forget to follow up please ping me in a few days!

@TomGranot
Copy link
Contributor

TomGranot commented Aug 24, 2020 •
edited

Alright, so I think I found the culprit (not sure why it's not embedding the code lines properly):

https://github.com/TomGranot/async-http-client/blob/master/client/src/main/java/org/asynchttpclient/netty/handler/intercept/Redirect30xInterceptor.java#L88-L91

It basically switches to GET if the original method was not GET and a redirect was encountered. The logic there is too intricate to be added as an afterthought - but looking at the original history here doesn't give much of a clue as the original file was in a different location (client/src/main/java/org/asynchttpclient/netty/handler/Redirect30xHandler.java).

Will dig a little further and get to the root of this - @slandelle this was before your time, but if there's any chance you remember why there's a default to GET for requests I would appreciate a lead (although this is very old).

@TomGranot
Copy link
Contributor

TomGranot commented Aug 24, 2020 •
edited

So I asked around and received other use cases where it makes sense to have a the next request in the cycle be a GET instead. I think this can be easily solved by adding another config option for the RequestBuilder called persistMethodBetweenRedirects that will basically allow you to do HEAD all the way if you wanted to.

I'll write a PR in a bit tomorrow, made the change but need to modify tests (and maybe write a couple more).

@slandelle
Copy link
Contributor

Here’s what I do in Gatling: gatling/gatling@a87729b

@TomGranot
Copy link
Contributor

Ah, that makes sense, this way you allow it for HEAD and OPTIONS but disallow it for POST that can pass too much information away. Thanks @slandelle!

@TomGranot
Copy link
Contributor

Still need to open a PR, just not getting to it. Will do so sometime this week (need to re-write the tests so Maven won't be angry).

@TomGranot
Copy link
Contributor

TomGranot commented Sep 28, 2020 •
edited

Out of the two failing tests, one of them - AsyncStreamHandlerTest.asyncOptionsTest() - is flaky (see #1735).

That leaves us with one problematic test, Head302Test.testHEAD302(), which hits this:

java.util.concurrent.ExecutionException: org.asynchttpclient.handler.MaxRedirectException: Maximum redirect reached: 5

Looking now. Full test dump shows that fixing the interceptor with @slandelle's fix works fine - each following request is a HEAD:

2020-09-28 15:01:45,288 [main] DEBUG io.netty.util.internal.logging.InternalLoggerFactory - Using SLF4J as the default logging framework
2020-09-28 15:01:45,290 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.level: simple
2020-09-28 15:01:45,290 [main] DEBUG io.netty.util.ResourceLeakDetector - -Dio.netty.leakDetection.targetRecords: 4
2020-09-28 15:01:45,293 [main] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@708f5957
2020-09-28 15:01:45,304 [main] DEBUG io.netty.util.internal.PlatformDependent - Platform: MacOS
2020-09-28 15:01:45,305 [main] DEBUG io.netty.util.internal.PlatformDependent0 - -Dio.netty.noUnsafe: false
2020-09-28 15:01:45,305 [main] DEBUG io.netty.util.internal.PlatformDependent0 - Java version: 8
2020-09-28 15:01:45,306 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.theUnsafe: available
2020-09-28 15:01:45,306 [main] DEBUG io.netty.util.internal.PlatformDependent0 - sun.misc.Unsafe.copyMemory: available
2020-09-28 15:01:45,306 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Buffer.address: available
2020-09-28 15:01:45,306 [main] DEBUG io.netty.util.internal.PlatformDependent0 - direct buffer constructor: available
2020-09-28 15:01:45,307 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.Bits.unaligned: available, true
2020-09-28 15:01:45,307 [main] DEBUG io.netty.util.internal.PlatformDependent0 - jdk.internal.misc.Unsafe.allocateUninitializedArray(int): unavailable prior to Java9
2020-09-28 15:01:45,307 [main] DEBUG io.netty.util.internal.PlatformDependent0 - java.nio.DirectByteBuffer.<init>(long, int): available
2020-09-28 15:01:45,307 [main] DEBUG io.netty.util.internal.PlatformDependent - sun.misc.Unsafe: available
2020-09-28 15:01:45,307 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.tmpdir: /var/folders/yj/5yjqs2jd0b92698_fqsbs3_40000gn/T (java.io.tmpdir)
2020-09-28 15:01:45,307 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.bitMode: 64 (sun.arch.data.model)
2020-09-28 15:01:45,308 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.maxDirectMemory: 3817865216 bytes
2020-09-28 15:01:45,308 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.uninitializedArrayAllocationThreshold: -1
2020-09-28 15:01:45,309 [main] DEBUG io.netty.util.internal.CleanerJava6 - java.nio.ByteBuffer.cleaner(): available
2020-09-28 15:01:45,309 [main] DEBUG io.netty.util.internal.PlatformDependent - -Dio.netty.noPreferDirect: false
2020-09-28 15:01:45,315 [main] DEBUG io.netty.util.internal.PlatformDependent - org.jctools-core.MpscChunkedArrayQueue: available
2020-09-28 15:01:45,410 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default protocols (JDK): [TLSv1.2, TLSv1.1, TLSv1] 
2020-09-28 15:01:45,410 [main] DEBUG io.netty.handler.ssl.JdkSslContext - Default cipher suites (JDK): [TLS_ECDHE_ECDSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_ECDSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256, TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384, TLS_ECDHE_RSA_WITH_AES_128_CBC_SHA, TLS_ECDHE_RSA_WITH_AES_256_CBC_SHA, TLS_RSA_WITH_AES_128_GCM_SHA256, TLS_RSA_WITH_AES_128_CBC_SHA, TLS_RSA_WITH_AES_256_CBC_SHA]
2020-09-28 15:01:45,424 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.initialSize: 1024
2020-09-28 15:01:45,424 [main] DEBUG io.netty.util.internal.InternalThreadLocalMap - -Dio.netty.threadLocalMap.stringBuilder.maxSize: 4096
2020-09-28 15:01:45,428 [main] DEBUG io.netty.channel.MultithreadEventLoopGroup - -Dio.netty.eventLoopThreads: 32
2020-09-28 15:01:45,432 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.noKeySetOptimization: false
2020-09-28 15:01:45,432 [main] DEBUG io.netty.channel.nio.NioEventLoop - -Dio.netty.selectorAutoRebuildThreshold: 512
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numHeapArenas: 32
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.numDirectArenas: 32
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.pageSize: 8192
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxOrder: 11
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.chunkSize: 16777216
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.tinyCacheSize: 512
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.smallCacheSize: 256
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.normalCacheSize: 64
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedBufferCapacity: 32768
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimInterval: 8192
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.cacheTrimIntervalMillis: 0
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.useCacheForAllThreads: true
2020-09-28 15:01:45,447 [main] DEBUG io.netty.buffer.PooledByteBufAllocator - -Dio.netty.allocator.maxCachedByteBuffersPerChunk: 1023
2020-09-28 15:01:45,453 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.allocator.type: pooled
2020-09-28 15:01:45,453 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.threadLocalDirectBufferSize: 0
2020-09-28 15:01:45,453 [main] DEBUG io.netty.buffer.ByteBufUtil - -Dio.netty.maxThreadLocalCharBufferSize: 16384
2020-09-28 15:01:45,676 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.processId: 56861 (auto-detected)
2020-09-28 15:01:45,677 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv4Stack: false
2020-09-28 15:01:45,677 [main] DEBUG io.netty.util.NetUtil - -Djava.net.preferIPv6Addresses: false
2020-09-28 15:01:45,679 [main] DEBUG io.netty.util.NetUtil - Loopback interface: lo0 (lo0, 0:0:0:0:0:0:0:1%lo0)
2020-09-28 15:01:45,679 [main] DEBUG io.netty.util.NetUtil - Failed to get SOMAXCONN from sysctl and file /proc/sys/net/core/somaxconn. Default: 128
2020-09-28 15:01:45,682 [main] DEBUG io.netty.channel.DefaultChannelId - -Dio.netty.machineId: ac:de:48:ff:fe:00:11:22 (auto-detected)
2020-09-28 15:01:45,717 [AsyncHttpClient-3-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkAccessible: true
2020-09-28 15:01:45,717 [AsyncHttpClient-3-1] DEBUG io.netty.buffer.AbstractByteBuf - -Dio.netty.buffer.checkBounds: true
2020-09-28 15:01:45,717 [AsyncHttpClient-3-1] DEBUG io.netty.util.ResourceLeakDetectorFactory - Loaded default ResourceLeakDetector: io.netty.util.ResourceLeakDetector@1394a12a
2020-09-28 15:01:45,728 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.channel.NettyConnectListener - Using new Channel '[id: 0x10f3cdd8, L:/127.0.0.1:53379 - R:localhost/127.0.0.1:53377]' for 'HEAD' to '/Test'
2020-09-28 15:01:45,747 [AsyncHttpClient-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxCapacityPerThread: 4096
2020-09-28 15:01:45,747 [AsyncHttpClient-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.maxSharedCapacityFactor: 2
2020-09-28 15:01:45,747 [AsyncHttpClient-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.linkCapacity: 16
2020-09-28 15:01:45,747 [AsyncHttpClient-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.ratio: 8
2020-09-28 15:01:45,747 [AsyncHttpClient-3-1] DEBUG io.netty.util.Recycler - -Dio.netty.recycler.delayedQueue.ratio: 8
2020-09-28 15:01:45,812 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.HttpHandler - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE)
HEAD /Test HTTP/1.1
host: localhost:53377
accept: */*
user-agent: AHC/2.1

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 302 Found
Date: Mon, 28 Sep 2020 12:01:45 GMT
Location: /Test_moved
Content-Length: 0
Server: Jetty(9.4.18.v20190429)

2020-09-28 15:01:45,813 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.intercept.Redirect30xInterceptor - Redirecting to http://localhost:53377/Test_moved
2020-09-28 15:01:45,813 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.intercept.Redirect30xInterceptor - Sending redirect to http://localhost:53377/Test_moved
2020-09-28 15:01:45,814 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Using open Channel [id: 0x10f3cdd8, L:/127.0.0.1:53379 - R:localhost/127.0.0.1:53377] for HEAD '/Test_moved'
2020-09-28 15:01:45,816 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.HttpHandler - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE)
HEAD /Test_moved HTTP/1.1
host: localhost:53377
accept: */*
user-agent: AHC/2.1

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 302 Found
Date: Mon, 28 Sep 2020 12:01:45 GMT
Location: /Test_moved_moved
Content-Length: 0
Server: Jetty(9.4.18.v20190429)

2020-09-28 15:01:45,816 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.intercept.Redirect30xInterceptor - Redirecting to http://localhost:53377/Test_moved_moved
2020-09-28 15:01:45,816 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.intercept.Redirect30xInterceptor - Sending redirect to http://localhost:53377/Test_moved_moved
2020-09-28 15:01:45,816 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Using open Channel [id: 0x10f3cdd8, L:/127.0.0.1:53379 - R:localhost/127.0.0.1:53377] for HEAD '/Test_moved_moved'
2020-09-28 15:01:45,817 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.HttpHandler - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE)
HEAD /Test_moved_moved HTTP/1.1
host: localhost:53377
accept: */*
user-agent: AHC/2.1

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 302 Found
Date: Mon, 28 Sep 2020 12:01:45 GMT
Location: /Test_moved_moved_moved
Content-Length: 0
Server: Jetty(9.4.18.v20190429)

2020-09-28 15:01:45,817 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.intercept.Redirect30xInterceptor - Redirecting to http://localhost:53377/Test_moved_moved_moved
2020-09-28 15:01:45,817 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.intercept.Redirect30xInterceptor - Sending redirect to http://localhost:53377/Test_moved_moved_moved
2020-09-28 15:01:45,818 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Using open Channel [id: 0x10f3cdd8, L:/127.0.0.1:53379 - R:localhost/127.0.0.1:53377] for HEAD '/Test_moved_moved_moved'
2020-09-28 15:01:45,819 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.HttpHandler - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE)
HEAD /Test_moved_moved_moved HTTP/1.1
host: localhost:53377
accept: */*
user-agent: AHC/2.1

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 302 Found
Date: Mon, 28 Sep 2020 12:01:45 GMT
Location: /Test_moved_moved_moved_moved
Content-Length: 0
Server: Jetty(9.4.18.v20190429)

2020-09-28 15:01:45,819 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.intercept.Redirect30xInterceptor - Redirecting to http://localhost:53377/Test_moved_moved_moved_moved
2020-09-28 15:01:45,819 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.intercept.Redirect30xInterceptor - Sending redirect to http://localhost:53377/Test_moved_moved_moved_moved
2020-09-28 15:01:45,819 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Using open Channel [id: 0x10f3cdd8, L:/127.0.0.1:53379 - R:localhost/127.0.0.1:53377] for HEAD '/Test_moved_moved_moved_moved'
2020-09-28 15:01:45,820 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.HttpHandler - 

Request DefaultFullHttpRequest(decodeResult: success, version: HTTP/1.1, content: EmptyByteBufBE)
HEAD /Test_moved_moved_moved_moved HTTP/1.1
host: localhost:53377
accept: */*
user-agent: AHC/2.1

Response DefaultHttpResponse(decodeResult: success, version: HTTP/1.1)
HTTP/1.1 302 Found
Date: Mon, 28 Sep 2020 12:01:45 GMT
Location: /Test_moved_moved_moved_moved_moved
Content-Length: 0
Server: Jetty(9.4.18.v20190429)

2020-09-28 15:01:45,820 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.channel.ChannelManager - Closing Channel [id: 0x10f3cdd8, L:/127.0.0.1:53379 - R:localhost/127.0.0.1:53377] 
2020-09-28 15:01:45,822 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Aborting Future NettyResponseFuture{currentRetry=0,
	isDone=0,
	isCancelled=0,
	asyncHandler=org.asynchttpclient.Head302Test$1@5abf39d2,
	nettyRequest=org.asynchttpclient.netty.request.NettyRequest@59e14ed9,
	future=java.util.concurrent.CompletableFuture@34db6bb0[Not completed, 1 dependents],
	uri=http://localhost:53377/Test_moved_moved_moved_moved,
	keepAlive=true,
	redirectCount=5,
	timeoutsHolder=org.asynchttpclient.netty.timeout.TimeoutsHolder@3d17d3b2,
	inAuth=0,
	touch=1601294505820}

2020-09-28 15:01:45,823 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.request.NettyRequestSender - Maximum redirect reached: 5
org.asynchttpclient.handler.MaxRedirectException: Maximum redirect reached: 5
2020-09-28 15:01:45,824 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.AsyncCompletionHandler - Maximum redirect reached: 5
org.asynchttpclient.handler.MaxRedirectException: Maximum redirect reached: 5
2020-09-28 15:01:45,824 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.channel.ChannelManager - Closing Channel [id: 0x10f3cdd8, L:/127.0.0.1:53379 ! R:localhost/127.0.0.1:53377] 
2020-09-28 15:01:45,824 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.handler.HttpHandler - Unexpected I/O exception on channel [id: 0x10f3cdd8, L:/127.0.0.1:53379 ! R:localhost/127.0.0.1:53377]
org.asynchttpclient.handler.MaxRedirectException: Maximum redirect reached: 5
2020-09-28 15:01:45,824 [AsyncHttpClient-3-1] DEBUG org.asynchttpclient.netty.channel.ChannelManager - Closing Channel [id: 0x10f3cdd8, L:/127.0.0.1:53379 ! R:localhost/127.0.0.1:53377] 



java.util.concurrent.ExecutionException: org.asynchttpclient.handler.MaxRedirectException: Maximum redirect reached: 5

@TomGranot TomGranot mentioned this issue Sep 28, 2020
Closed
@TomGranot
Copy link
Contributor

TomGranot commented Sep 28, 2020 •
edited

One of the really fun things about long-standing repos is that each piece of code has a rich history behind it, with various people facing the same(-ish) problem at different points in time, adding fixes and thought-nuggets into the code over the years. This seems to be exactly one of those cases - looking at https://github.com/TomGranot/async-http-client/commits/master/client/src/test/java/org/asynchttpclient/Head302Test.java reveals that this test actually has been fixed in the past.

Specifically in our case, it seems that TomGranot@3c25a42#diff-64fc1f6f6a5d572c250342b4cdfda122 made this very test added the behaviour that causes this endless loop we're looking at right now - the Head302Hander is specifically written to keep on appending _moved to the URI and send back 302 after every 302 response.

In plain terms, this means that the test expects a HEAD to be followed with a GET and then terminate successfully. Since we now send followup HEADs upon a HEAD where setFollowRedirect is true, we should probably fix it in the handler - decide on a number of redirects following which a GET is sent instead of a HEAD in this redirect chain, which is less than the maximum number of allowed redirects (defaults to 5, as the test dump above shows).

And.... PR done. See below.

TomGranot added a commit to TomGranot/async-http-client that referenced this issue Sep 28, 2020
@TomGranot
Account for recurring HEADs in Head302Test
51da4d5 
Originally, when setFollowRedirect is set to true (like in Head302Test), the expected flow is HEAD --> GET (based on the behaviour of Redirect30xInterceptor - see AsyncHttpClient@3c25a42 for the reasoning).

Following a change to the interceptor (to fix AsyncHttpClient#1728), Head302Test started going on an infinite loop caused by the way the handler in the test was set up (to account for the original HEAD --> GET flow and not the new HEAD --> HEAD --> HEAD.... flow).

This PR does 3 things:

* Changes Redirect30xInterceptor to set all redirects of a HEAD request to be HEADs as well
* Change Head302Test to account for the new flow
* Notes a flaky test in AsyncStreamHandlerTest that was found during work on the PR
@TomGranot TomGranot mentioned this issue Sep 28, 2020
Merged
@TomGranot TomGranot mentioned this issue Dec 1, 2020
Open
TomGranot added a commit that referenced this issue Jan 5, 2021
@TomGranot
Use original method in redirects for HEAD / OPTIONS requests (#1736)
bd7b5bd 
Originally, when setFollowRedirect is set to true (like in Head302Test), the expected flow is HEAD --> GET (based on the behavior of Redirect30xInterceptor - see 3c25a42 for the reasoning).

Following a change to the interceptor (to fix #1728), Head302Test started going on an infinite loop caused by the way the handler in the tent was set up (to account for the original HEAD --> GET flow and not the new HEAD --> HEAD --> HEAD.... flow).

This commit does 3 things:

* Changes Redirect30xInterceptor to set all redirects of a HEAD request to be HEADs as well
* Change Head302Test to account for the new flow
* Notes a flaky test in AsyncStreamHandlerTest that was found during work on the PR
@TomGranot TomGranot self-assigned this Jan 5, 2021
@TomGranot TomGranot added this to the 2.12.3 milestone Jan 5, 2021
@TomGranot
Copy link
Contributor

@lakxtxue Merged to master, should be deployed in 2.12.3.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@TomGranot TomGranot

Labels
None yet
Projects
None yet
Milestone
2.12.3
Development

Successfully merging a pull request may close this issue.

Use original method in redirects for HEAD / OPTIONS requests TomGranot/async-http-client
3 participants
@slandelle @lakxtxue @TomGranot