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

[BUG] Blob Storage: Netty HttpClient is slow when downloading via an authenticated proxy server #19415

Closed
sesu-bio opened this issue Feb 24, 2021 · 10 comments · Fixed by #19558
Closed

[BUG] Blob Storage: Netty HttpClient is slow when downloading via an authenticated proxy server #19415

sesu-bio opened this issue Feb 24, 2021 · 10 comments · Fixed by #19558
Assignees
@alzimmermsft
Labels
Azure.Core azure-core Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. HttpClient question The issue doesn't require a change to the product in order to be resolved. Most issues start as that

Comments

@sesu-bio
Copy link

Describe the bug
When downloading a file via an authenticated proxy server, the netty HttpClient is noticably slower than the OkHttp one. It also outputs a warning "Failed to connect to proxy." I suspect that it interpretes the 407 Proxy Authentication Required from the proxy server as an error and waits a while until it retries.

Exception or Stack Trace
[reactor-http-nio-1] WARN reactor.netty.http.client.HttpClientConnect - [id: 0xe9730fb2, L:/169.254.111.2:61622 - R:/169.254.111.2:3128] The connection observed an error io.netty.handler.proxy.ProxyConnectException: Failed to connect to proxy. at com.azure.core.http.netty.implementation.HttpProxyHandler.handleResponse(HttpProxyHandler.java:239) at io.netty.handler.proxy.ProxyHandler.channelRead(ProxyHandler.java:258) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748) [reactor-http-nio-1] WARN reactor.netty.http.client.HttpClientConnect - [id: 0xe9730fb2, L:/169.254.111.2:61622 ! R:/169.254.111.2:3128] The connection observed an error io.netty.handler.proxy.ProxyConnectException: Failed to connect to proxy. at com.azure.core.http.netty.implementation.HttpProxyHandler.handleResponse(HttpProxyHandler.java:239) at io.netty.handler.proxy.ProxyHandler.channelRead(ProxyHandler.java:258) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296) at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:748)

To Reproduce
Run the below code snippet running an authenticated proxy server on port 3128.
Result for a small text file:

  • okhttp took 370ms
  • netty took 4708ms

Code Snippet

		String TEST_URL = "https://xyz.blob.core.windows.net/abc";

		// proxy server accepts only authenticated requests
		String PROXY_HOST = "169.254.111.2";
		final String PROXY_PORT = "3128";
		final String PROXY_USER = "user";
		final String PROXY_PASS = "pass";
		final int PROXY_PORT_INT = Integer.parseInt(PROXY_PORT);

		ProxyOptions authProxyOptions = new ProxyOptions(ProxyOptions.Type.HTTP,
				new InetSocketAddress(PROXY_HOST, PROXY_PORT_INT));
		authProxyOptions.setCredentials(PROXY_USER, PROXY_PASS);
		HttpClient okClient = new OkHttpAsyncHttpClientBuilder().proxy(authProxyOptions).build();
		BlobClient okBlobClient = new BlobClientBuilder().endpoint(TEST_URL).httpClient(okClient).buildClient();
		HttpClient nettyClient = new NettyAsyncHttpClientBuilder().proxy(authProxyOptions).build();
		BlobClient nettyBlobClient = new BlobClientBuilder().endpoint(TEST_URL).httpClient(nettyClient).buildClient();
		
		long start = System.currentTimeMillis();
		okBlobClient.downloadToFile("hello_world2.txt", true);
		long finish = System.currentTimeMillis();
		long timeElapsed = finish - start;
		System.out.println("okhttp took " + timeElapsed + "ms");
		
		start = System.currentTimeMillis();
		nettyBlobClient.downloadToFile("hello_world2.txt", true);
		finish = System.currentTimeMillis();
		timeElapsed = finish - start;
		System.out.println("netty took " + timeElapsed + "ms");

Expected behavior
Netty HttpClient should be about as fast as OkHttp and not log a warning.

Setup (please complete the following information):

  • OS: WIndows, Linux
  • IDE : Eclipse
  • azure-storage-blob 12.11.0-beta.1

Information Checklist
Kindly make sure that you have added all the following information above and checkoff the required fields otherwise we will treat the issuer as an incomplete report

  • [x ] Bug Description Added
  • [x ] Repro Steps Added
  • [x ] Setup information Added
@ghost ghost added needs-triage Workflow: This is a new issue that needs to be triaged to the appropriate team. customer-reported Issues that are reported by GitHub users external to the Azure organization. question The issue doesn't require a change to the product in order to be resolved. Most issues start as that labels Feb 24, 2021
@rickle-msft
Copy link
Contributor

@anuchandy @alzimmermsft Any thoughts on whether this might be the case for the netty client?

@alzimmermsft alzimmermsft self-assigned this Feb 24, 2021
@alzimmermsft alzimmermsft added Azure.Core azure-core Client This issue points to a problem in the data-plane of the library. HttpClient labels Feb 24, 2021
@ghost ghost removed the needs-triage Workflow: This is a new issue that needs to be triaged to the appropriate team. label Feb 24, 2021
@alzimmermsft
Copy link
Member

alzimmermsft commented Feb 24, 2021 •
edited
Loading

Yes, this appears to be a difference between how our Netty and OkHttp HTTP clients wrappers handle authenticated proxying.

@alzimmermsft
Copy link
Member

Additional context on this issue, this should only happen for the first connection using the authenticated proxy while subsequent connections should eagerly apply authentication. The first CONNECT does not as it supports both basic and digest authentication and does not eagerly apply basic even though it is possible. One change here other than more quickly retrying on a 407 exception would be applying a basic authentication eagerly (though guards may be added to only do this on a secure connection).

@sesu-bio
Copy link
Author

Thank you for looking into this. Applying the authentication eagerly for secure connections would not help in our specific use case (but might benefit others). Quickly retrying like OkHttp does would be completely sufficient for us.

@alzimmermsft alzimmermsft mentioned this issue Mar 12, 2021
Merged
@sesu-bio
Copy link
Author

sesu-bio commented Apr 6, 2021

I can still reproduce this with azure-storage-blob 12.11.0-beta.2 and azure-core-http-netty 1.9.1.

@alzimmermsft
Copy link
Member

Hi @sesu-bio, do you have a reproduction of this issue available? I've added testing to ensure when a ProxyConnectionException occurs the overall request doesn't take longer that what a retry delay is.

@sesu-bio
Copy link
Author

sesu-bio commented Apr 7, 2021

I am still using the above code. This is from my pom.xml:

	<dependencies>
		<dependency>
			<groupId>com.azure</groupId>
			<artifactId>azure-storage-blob</artifactId>
			<version>12.11.0-beta.2</version>
		</dependency>
		<dependency>
			<groupId>com.azure</groupId>
			<artifactId>azure-core</artifactId>
			<version>1.15.0</version>
		</dependency>
		<dependency>
			<groupId>com.fasterxml.jackson.core</groupId>
			<artifactId>jackson-core</artifactId>
			<version>2.12.2</version>
		</dependency>
		<dependency>
			<groupId>io.projectreactor</groupId>
			<artifactId>reactor-core</artifactId>
			<version>3.4.3</version>
		</dependency>
		<dependency>
			<groupId>com.azure</groupId>
			<artifactId>azure-core-http-okhttp</artifactId>
			<version>1.6.1</version>
		</dependency>
		<dependency>
			<groupId>com.azure</groupId>
			<artifactId>azure-core-http-netty</artifactId>
			<version>1.9.1</version>
		</dependency>
		<dependency>
			<groupId>org.slf4j</groupId>
			<artifactId>slf4j-simple</artifactId>
			<version>1.7.30</version>
		</dependency>
		<dependency>
			<groupId>com.microsoft.azure.sdk.iot</groupId>
			<artifactId>iot-device-client</artifactId>
			<version>1.29.4</version>
		</dependency>

Looks like the ProxyConnectException now causes an SSLException. This is the stacktrace:

[reactor-http-nio-2] WARN reactor.netty.http.client.HttpClientConnect - [id: 0x700cbbcb, L:/169.254.111.2:50861 - R:/169.254.111.2:3128] The connection observed an error
javax.net.ssl.SSLException: failure when writing TLS control frames
	at io.netty.handler.ssl.SslHandler.setHandshakeFailureTransportFailure(SslHandler.java:1878)
	at io.netty.handler.ssl.SslHandler.access$600(SslHandler.java:168)
	at io.netty.handler.ssl.SslHandler$2.operationComplete(SslHandler.java:986)
	at io.netty.handler.ssl.SslHandler$2.operationComplete(SslHandler.java:981)
	at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:578)
	at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:552)
	at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:491)
	at io.netty.util.concurrent.DefaultPromise.setValue0(DefaultPromise.java:616)
	at io.netty.util.concurrent.DefaultPromise.setFailure0(DefaultPromise.java:609)
	at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:117)
	at io.netty.channel.PendingWriteQueue.safeFail(PendingWriteQueue.java:288)
	at io.netty.channel.PendingWriteQueue.removeAndFailAll(PendingWriteQueue.java:186)
	at io.netty.handler.proxy.ProxyHandler.failPendingWrites(ProxyHandler.java:435)
	at io.netty.handler.proxy.ProxyHandler.failPendingWritesAndClose(ProxyHandler.java:352)
	at io.netty.handler.proxy.ProxyHandler.setConnectFailure(ProxyHandler.java:347)
	at io.netty.handler.proxy.ProxyHandler.channelRead(ProxyHandler.java:267)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
	at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)
Caused by: io.netty.handler.proxy.ProxyConnectException: Failed to connect to proxy.
	at com.azure.core.http.netty.implementation.HttpProxyHandler.handleResponse(HttpProxyHandler.java:239)
	at io.netty.handler.proxy.ProxyHandler.channelRead(ProxyHandler.java:258)
	... 23 more
[reactor-http-nio-2] WARN reactor.netty.http.client.HttpClientConnect - [id: 0x700cbbcb, L:/169.254.111.2:50861 ! R:/169.254.111.2:3128] The connection observed an error
io.netty.handler.proxy.ProxyConnectException: Failed to connect to proxy.
	at com.azure.core.http.netty.implementation.HttpProxyHandler.handleResponse(HttpProxyHandler.java:239)
	at io.netty.handler.proxy.ProxyHandler.channelRead(ProxyHandler.java:258)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
	at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
	at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
	at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
	at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
	at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
	at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:719)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:655)
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:581)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
	at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
	at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
	at java.lang.Thread.run(Thread.java:748)

Netty still takes about 5s longer for the first download:

okhttp took 397ms
netty took 5286ms

Maybe the default retry delay is actually 5s?

@alzimmermsft alzimmermsft reopened this Apr 12, 2021
@alzimmermsft
Copy link
Member

Hi @sesu-bio, took a look into this again.

It appears that exception propagation changed leading to our logic to unwrap SSLExceptions that were actually caused by ProxyConnectExceptions to no longer unwrap and propagate the ProxyConnectException. This had a downstream affect where the fix I put in for eagerly retrying ProxyConnectExceptions to no longer trigger, leading the exception to propagate all the way to the request retrying logic where it was apply a delay retries. Essentially putting this back into the state which you initially called out in this issue.

I've submitted #20675 to better resolve this issue. I did notice during testing though that the initial request through Netty does take longer than OkHttp (likely due to the additional initialization costs it has with connection pooling, etc), so some of the differences you may be seeing in the repro you gave may be due to that.

@alzimmermsft
Copy link
Member

@sesu-bio azure-core 1.16.0 was released containing the last PR. Has this resolved the issue you've been seeing?

@sesu-bio
Copy link
Author

sesu-bio commented Jun 8, 2021

@alzimmermsft Using the latest dependency versions, the Netty http client has gotten a lot faster in the described situation. The remaining difference is most likely caused by the effects you mentioned in your previous comment.

okhttp took 383ms
netty took 1242ms

A warning about the 407 HTTP status is still logged but this is only a minor annoyance. I consider the issue resolved. Thank you very much!

@sesu-bio sesu-bio closed this as completed Jun 8, 2021
azure-sdk pushed a commit to azure-sdk/azure-sdk-for-java that referenced this issue Jun 20, 2022
@dw511214992
CodeGen from PR 19415 in Azure/azure-rest-api-specs
1903eaf 
Fix small logical mistake in automation rules examples (Azure#19415)

* Fix small logical mistake in automation rules examples

* Update readme.md

Co-authored-by: Wei Dong <[email protected]>
@github-actions github-actions bot locked and limited conversation to collaborators Apr 12, 2023
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees

@alzimmermsft alzimmermsft

Labels
Azure.Core azure-core Client This issue points to a problem in the data-plane of the library. customer-reported Issues that are reported by GitHub users external to the Azure organization. HttpClient question The issue doesn't require a change to the product in order to be resolved. Most issues start as that
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Add Retry to ProxyConnectException alzimmermsft/azure-sdk-for-java
3 participants
@rickle-msft @alzimmermsft @sesu-bio