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.

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

[BUG] [azure-storage-blob] Timeout when uploading large files to a block blob #5221

Closed
cdraeger opened this issue Sep 3, 2019 · 13 comments · Fixed by #5401
Closed

[BUG] [azure-storage-blob] Timeout when uploading large files to a block blob #5221

cdraeger opened this issue Sep 3, 2019 · 13 comments · Fixed by #5401
Assignees
Labels
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. Storage Storage Service (Queues, Blobs, Files)

Comments

@cdraeger
Copy link

cdraeger commented Sep 3, 2019

Describe the bug
I am currently trying to utilize the Storage SDK 12 (azure-storage-blob) to upload very large files to the Blob Storage with a BlockBlobClient instance. But I am running into timeouts quickly.

File size when testing: ~ 1Gb, but file size can easily be ~ 10-16Gb which may take quite some time to upload. Downloading files of the same size should of course also work, but I didn't get to try this out yet because the upload already fails.

I uploaded using BlockBlobClient#uploadFromFile(filePath). I also tried setting a high timeout via this method.

I also tried writing to the outputstream of a blob directly via BlockBlobClient#getBlobOutputStream(), but for some reason this was very slow and the resulting blob size was totally off when I tried with much smaller files of just a few megabytes.

Exception or Stack Trace
I'm seeing first a couple of these:

2019-09-03 14:46:52,010 WARN  [reactor-http-kqueue-1] [] [HttpClientConnect.warn:299] [id: 0x8d937e75, L:/10.111.8.206:54858 - R:mystorage.blob.core.windows.net/XXXXXXXX:443] The connection observed an error
io.netty.channel.unix.Errors$NativeIoException: readAddress(..) failed: Operation timed out
	at io.netty.channel.unix.Errors.newIOException(Errors.java:122) ~[netty-transport-native-unix-common-4.1.36.Final.jar:4.1.36.Final]
	at io.netty.channel.unix.Errors.ioResult(Errors.java:146) ~[netty-transport-native-unix-common-4.1.36.Final.jar:4.1.36.Final]
	at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:177) ~[netty-transport-native-unix-common-4.1.36.Final.jar:4.1.36.Final]
	at io.netty.channel.kqueue.AbstractKQueueChannel.doReadBytes(AbstractKQueueChannel.java:253) ~[netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.AbstractKQueueStreamChannel$KQueueStreamUnsafe.readReady(AbstractKQueueStreamChannel.java:530) [netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.AbstractKQueueChannel$AbstractKQueueUnsafe.readEOF(AbstractKQueueChannel.java:468) [netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.KQueueEventLoop.processReady(KQueueEventLoop.java:183) [netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.KQueueEventLoop.run(KQueueEventLoop.java:259) [netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:906) [netty-common-4.1.36.Final.jar:4.1.36.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [netty-common-4.1.36.Final.jar:4.1.36.Final]
	at java.lang.Thread.run(Thread.java:834) [?:?]

And in the end this:

Caused by: reactor.core.Exceptions$ReactiveException: java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.Exceptions.propagate(Exceptions.java:326) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:131) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
Caused by: reactor.core.Exceptions$ReactiveException: java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)

	at reactor.core.publisher.Mono.block(Mono.java:1518) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at com.azure.storage.blob.Utility.blockWithOptionalTimeout(Utility.java:391) ~[azure-storage-blob-12.0.0-preview.2.jar:?]
	at com.azure.storage.blob.BlockBlobClient.uploadFromFile(BlockBlobClient.java:198) ~[azure-storage-blob-12.0.0-preview.2.jar:?]
	at com.company.my.cloud.storage.AzureBlobStorageClient.uploadFromFile(AzureBlobStorageClient.java:78) ~[main/:?]
  at com.company.my.rest.service.impl.ServiceRestImpl.upload(ServiceRestImpl.java:372) ~[main/:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
	at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
	at org.springframework.security.access.intercept.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:69) ~[spring-security-core-5.1.5.RELEASE.jar:5.1.5.RELEASE]
	at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
	at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
	at com.sun.proxy.$Proxy131.getAllSdCardFileTransfers(Unknown Source) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
	at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
	at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
	at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
	at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[cxf-core-3.3.2.jar:3.3.2]
	at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[cxf-core-3.3.2.jar:3.3.2]
	... 77 more
	Suppressed: java.lang.Exception: #block terminated with an error
		at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:133) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
		at reactor.core.publisher.Mono.block(Mono.java:1518) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
		at com.azure.storage.blob.Utility.blockWithOptionalTimeout(Utility.java:391) ~[azure-storage-blob-12.0.0-preview.2.jar:?]
		at com.azure.storage.blob.BlockBlobClient.uploadFromFile(BlockBlobClient.java:198) ~[azure-storage-blob-12.0.0-preview.2.jar:?]
		at com.company.my.cloud.storage.AzureBlobStorageClient.uploadFromFile(AzureBlobStorageClient.java:78) ~[main/:?]
    at com.company.my.rest.service.impl.ServiceRestImpl.upload(ServiceRestImpl.java:372) ~[main/:?]
		at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
		at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
		at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
		at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
		at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:343) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at org.springframework.security.access.intercept.aopalliance.MethodSecurityInterceptor.invoke(MethodSecurityInterceptor.java:69) ~[spring-security-core-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:186) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:212) ~[spring-aop-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at com.sun.proxy.$Proxy131.getAllSdCardFileTransfers(Unknown Source) ~[?:?]
		at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
		at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
		at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
		at java.lang.reflect.Method.invoke(Method.java:566) ~[?:?]
		at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[cxf-core-3.3.2.jar:3.3.2]
		at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[cxf-core-3.3.2.jar:3.3.2]
		at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:201) ~[cxf-rt-frontend-jaxrs-3.3.2.jar:3.3.2]
		at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:104) ~[cxf-rt-frontend-jaxrs-3.3.2.jar:3.3.2]
		at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[cxf-core-3.3.2.jar:3.3.2]
		at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) ~[cxf-core-3.3.2.jar:3.3.2]
		at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:308) ~[cxf-core-3.3.2.jar:3.3.2]
		at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[cxf-core-3.3.2.jar:3.3.2]
		at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:267) ~[cxf-rt-transports-http-3.3.2.jar:3.3.2]
		at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[cxf-rt-transports-http-3.3.2.jar:3.3.2]
		at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[cxf-rt-transports-http-3.3.2.jar:3.3.2]
		at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[cxf-rt-transports-http-3.3.2.jar:3.3.2]
		at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:216) ~[cxf-rt-transports-http-3.3.2.jar:3.3.2]
		at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:301) ~[cxf-rt-transports-http-3.3.2.jar:3.3.2]
		at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doGet(AbstractHTTPServlet.java:225) ~[cxf-rt-transports-http-3.3.2.jar:3.3.2]
		at javax.servlet.http.HttpServlet.service(HttpServlet.java:645) ~[javax.servlet-api-4.0.1.jar:4.0.1]
		at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:276) ~[cxf-rt-transports-http-3.3.2.jar:3.3.2]
		at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:876) ~[jetty-servlet-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1623) ~[jetty-servlet-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:320) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.invoke(FilterSecurityInterceptor.java:127) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.access.intercept.FilterSecurityInterceptor.doFilter(FilterSecurityInterceptor.java:91) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.access.ExceptionTranslationFilter.doFilter(ExceptionTranslationFilter.java:119) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.session.SessionManagementFilter.doFilter(SessionManagementFilter.java:137) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.authentication.AnonymousAuthenticationFilter.doFilter(AnonymousAuthenticationFilter.java:111) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.authentication.rememberme.RememberMeAuthenticationFilter.doFilter(RememberMeAuthenticationFilter.java:158) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.servletapi.SecurityContextHolderAwareRequestFilter.doFilter(SecurityContextHolderAwareRequestFilter.java:170) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.savedrequest.RequestCacheAwareFilter.doFilter(RequestCacheAwareFilter.java:63) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.authentication.logout.LogoutFilter.doFilter(LogoutFilter.java:116) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.header.HeaderWriterFilter.doFilterInternal(HeaderWriterFilter.java:74) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:109) ~[spring-web-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.context.SecurityContextPersistenceFilter.doFilter(SecurityContextPersistenceFilter.java:105) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.context.request.async.WebAsyncManagerIntegrationFilter.doFilterInternal(WebAsyncManagerIntegrationFilter.java:56) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:109) ~[spring-web-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at org.springframework.security.web.FilterChainProxy$VirtualFilterChain.doFilter(FilterChainProxy.java:334) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:215) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:178) ~[spring-security-web-5.1.5.RELEASE.jar:5.1.5.RELEASE]
		at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:357) ~[spring-web-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:270) ~[spring-web-5.1.8.RELEASE.jar:5.1.8.RELEASE]
		at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1610) ~[jetty-servlet-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:540) ~[jetty-servlet-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1711) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1347) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:480) ~[jetty-servlet-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1678) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1249) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at com.tomtom.jetty.DcsServletRequestLogHandler.handle(DcsServletRequestLogHandler.java:60) ~[main/:?]
		at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:220) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:152) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.Server.handle(Server.java:505) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:370) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:267) ~[jetty-server-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:305) ~[jetty-io-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) ~[jetty-io-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) ~[jetty-io-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333) ~[jetty-util-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310) ~[jetty-util-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168) ~[jetty-util-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:132) ~[jetty-util-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:781) [jetty-util-9.4.19.v20190610.jar:9.4.19.v20190610]
		at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:917) [jetty-util-9.4.19.v20190610.jar:9.4.19.v20190610]
		at java.lang.Thread.run(Thread.java:834) [?:?]
Caused by: java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
Caused by: java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)

	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) ~[?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[?:?]
	... 1 more

I also saw when I played around:

reactor.core.Exceptions$ReactiveException: io.netty.channel.AbstractChannel$AnnotatedConnectException: finishConnect(..) failed: Operation timed out: mystorage.blob.core.windows.net/XXXXXXX:443

(...)
Caused by: java.net.ConnectException: finishConnect(..) failed: Operation timed out

	at io.netty.channel.unix.Socket.finishConnect(Socket.java:269) ~[netty-transport-native-unix-common-4.1.36.Final.jar:4.1.36.Final]
	at io.netty.channel.kqueue.AbstractKQueueChannel$AbstractKQueueUnsafe.doFinishConnect(AbstractKQueueChannel.java:640) ~[netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.AbstractKQueueChannel$AbstractKQueueUnsafe.finishConnect(AbstractKQueueChannel.java:620) ~[netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.AbstractKQueueChannel$AbstractKQueueUnsafe.shutdownInput(AbstractKQueueChannel.java:434) ~[netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.AbstractKQueueChannel$AbstractKQueueUnsafe.readEOF(AbstractKQueueChannel.java:471) ~[netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.KQueueEventLoop.processReady(KQueueEventLoop.java:183) ~[netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.channel.kqueue.KQueueEventLoop.run(KQueueEventLoop.java:259) ~[netty-transport-native-kqueue-4.1.36.Final-osx-x86_64.jar:4.1.36.Final]
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:906) ~[netty-common-4.1.36.Final.jar:4.1.36.Final]
	at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) ~[netty-common-4.1.36.Final.jar:4.1.36.Final]
	... 1 more
2019-09-03 13:04:03,652 WARN  [reactor-http-kqueue-8] [] [HttpClientConnect.warn:299] [id: 0xc81100c2, L:/10.111.8.206:53405 - R:mystorage.blob.core.windows.net/XXXXXXXXX:443] The connection observed an error
javax.net.ssl.SSLException: handshake timed out
	at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.36.Final.jar:4.1.36.Final]
2019-09-03 13:04:03,652 WARN  [reactor-http-kqueue-1] [] [HttpClientConnect.warn:299] [id: 0xf5876558, L:/10.111.8.206:53393 - R:mystorage.blob.core.windows.net/XXXXXXX:443] The connection observed an error

To Reproduce

  • Setup a Spring 5 / CXF environment
  • setup a REST method triggering a file upload of at least ~1Gb of size (can be hardcoded)
  • upload via BlockBlobClient#uploadFromFile(filePath) or BlockBlobClient#getBlobOutputStream()

Code Snippet

final Path largeFile = Paths.get("/Users/username/large-file.zip");
try
{
    containerClient.getBlockBlobClient("basefolder/large-file.zip").uploadFromFile(largeFile.toString());
}
catch (final CloudStorageException e)
{
    Log.error("Test failed", e);
}

Also this is not working, resulting in very slow upload activity or completely wrong resulting file size:

try(final InputStream inputStream = Files.newInputStream(largeFile); final OutputStream outputStream = containerClient.getBlockBlobClient("large-file.zip").getBlobOutputStream())
{
    StreamUtils.copy(inputStream, outputStream);
}
catch (final IOException | StorageException e)
{
    throw new CloudStorageException("Could not upload zip stream to blob storage", e);
}

Expected behavior
I expect the upload of large files to complete successfully, even if this means upload times of one hour or more.

I would also expect writing to the OutputStream of a block blob to work as fast as regular file upload, resulting in the correct blob size depending on the final length of the input stream.

Screenshots
If applicable, add screenshots to help explain your problem.

Setup (please complete the following information):

  • OS: Linux / MacOS
  • IDE : IntelliJ
  • 12.0.0-preview.2

I'd appreciate any help or comments, thanks!

@rickle-msft rickle-msft added 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. Storage Storage Service (Queues, Blobs, Files) labels Sep 4, 2019
@rickle-msft
Copy link
Contributor

@cdraeger Thank you for reporting this. Can you provide a bit more information to help us get started debugging? Are you able to see network traffic at all with something like Fiddler or is it stalling before it hits the network (I'm seeing a proxy buried in the middle of your stack trace that could be interfering)? Also, are you able to upload small files at all and this only manifests past a certain size or does it always trigger this exception? Is there any way you can test this outside of Spring as well to make sure nothing there is interfering?

I'm able to upload a 1GB file in about 18s over here, which if nothing else is better than timing out after 60s.

@cdraeger
Copy link
Author

cdraeger commented Sep 4, 2019

@rickle-msft Thanks for responding quickly. I indeed see network activity:

  • There is no proxy configured: I'm assuming what you see is internal mapping of the Spring framework, I'm not sure exactly.
  • Generally the network connection is fine and stable (RJ45 cable connected) and capable of both uploading and downloading large files of e.g. ~15Gb e.g. to OneDrive.
  • Uploading a ~250Mb file I tried before via the SDK worked fine and the upload completed.
  • The upload from file for larger files via SDK starts and speed is about 6-7 Mb/s. This went on for about 2m50s until the above reactor exception regarding 'peek' pops up.

I just tried again with a RandomAccessFile I created with a 2Gb length:

  • Upload also starts fine with 7Mb/s
  • In between I got frequent and repeating SSL handshake timeout warnings I also already posted above. This started only after 1m15s but doesn't break the upload (if at all I see some drops to 0Kb/s sometimes but upload then quickly resumes).
  • Upload in the end also failed with the same stacktrace, this time after about 3m15s after ~ 1,2Gb have been uploaded.

Handshake warning in between that I sometimes see, but this didn't yet fail the upload:

2019-09-04 08:32:29,199 WARN  [reactor-http-kqueue-7] [] [HttpClientConnect.warn:299] [id: 0xe6325b95, L:/10.111.8.206:57501 - R:mystorage.blob.core.windows.net/XXXXXXX:443] The connection observed an error
javax.net.ssl.SSLException: handshake timed out
	at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.36.Final.jar:4.1.36.Final]

I tried this once more: upload also failed after ~3 minutes, but this time the SSL handshake timeout was the actual cause:

Caused by: reactor.core.Exceptions$ReactiveException: javax.net.ssl.SSLException: handshake timed out
	at reactor.core.Exceptions.propagate(Exceptions.java:326) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.BlockingSingleSubscriber.blockingGet(BlockingSingleSubscriber.java:131) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
Caused by: reactor.core.Exceptions$ReactiveException: javax.net.ssl.SSLException: handshake timed out

	at reactor.core.publisher.Mono.block(Mono.java:1518) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at com.azure.storage.blob.Utility.blockWithOptionalTimeout(Utility.java:391) ~[azure-storage-blob-12.0.0-preview.2.jar:?]
	at com.azure.storage.blob.BlockBlobClient.uploadFromFile(BlockBlobClient.java:198) ~[azure-storage-blob-12.0.0-preview.2.jar:?]
(...)

So I'm really not sure what I can do, it looks like something is wrong in the underlying network stack of the SDK, but I don't know how to tackle or configure it properly.

I also tried uploading an InputStream with a specified length via the BlockBlockClient: this fails after the block size of 100Mb is reached, I'm not sure why since I expected the SDK to abstract this away like with a file upload.

Also as said, I don't see much of network activity when writing to the outputstream of a blob directly via the BlockBlockClient, which would have been preferred as the cleanest solution (also I could channel streams directly without buffer files). I think I saw only something around ~100kb/s. When I tried with a small file the resulting file size was completely off, so this also didn't suffice as a workaround.

Thanks!

@cdraeger
Copy link
Author

cdraeger commented Sep 4, 2019

@rickle-msft I now tried isolating my code from Spring, set up a bare Gradle test project (see sample code below).

With this setup, uploading a 1Mb file works fine. Uploading a 250Mb file or even more reproducibly freezes and literally crashes my Mac. My terminal cached some of the stacktrace though, I enabled debug logging. What I see is possibly similar: some errors and handshake timeouts in between. I don't get to any final exception because the Mac freezes before (with or without uploading in a separate thread).

Stacktrace

2019-09-04 11:26:24,601 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:230] [id: 0x18db035c, L:/10.111.8.206:49736 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,601 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0x18db035c, L:/10.111.8.206:49736 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 83 active connections and 38 inactive connections
2019-09-04 11:26:24,601 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:230] [id: 0x76d181a2, L:/10.111.8.206:49737 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,601 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0x76d181a2, L:/10.111.8.206:49737 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 84 active connections and 37 inactive connections
2019-09-04 11:26:24,601 DEBUG [reactor-http-nio-7] [ChannelOperationsHandler.debug:235] [id: 0xb6a08fc6, L:/10.111.8.206:49703 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:24,602 DEBUG [reactor-http-nio-3] [PooledConnectionProvider.debug:230] [id: 0x8980818d, L:/10.111.8.206:49729 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,602 DEBUG [reactor-http-nio-3] [PooledConnectionProvider.debug:235] [id: 0x8980818d, L:/10.111.8.206:49729 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 85 active connections and 36 inactive connections
2019-09-04 11:26:24,602 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:24,603 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:230] [id: 0xb6505ee9, L:/10.111.8.206:49731 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,603 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0xb6505ee9, L:/10.111.8.206:49731 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 86 active connections and 35 inactive connections
2019-09-04 11:26:24,603 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:230] [id: 0xa3e1b3ca, L:/10.111.8.206:49738 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,603 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xa3e1b3ca, L:/10.111.8.206:49738 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 87 active connections and 34 inactive connections
2019-09-04 11:26:24,604 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:230] [id: 0xd0d64f7a, L:/10.111.8.206:49739 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,604 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xd0d64f7a, L:/10.111.8.206:49739 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 88 active connections and 33 inactive connections
2019-09-04 11:26:24,606 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:230] [id: 0xbf47a49f, L:/10.111.8.206:49740 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,606 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xbf47a49f, L:/10.111.8.206:49740 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 90 active connections and 31 inactive connections
2019-09-04 11:26:24,606 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:230] [id: 0xf9facd2a, L:/10.111.8.206:49723 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,606 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0xf9facd2a, L:/10.111.8.206:49723 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 90 active connections and 31 inactive connections
2019-09-04 11:26:24,606 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:230] [id: 0x163fe9a8, L:/10.111.8.206:49734 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,606 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0x163fe9a8, L:/10.111.8.206:49734 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 91 active connections and 30 inactive connections
2019-09-04 11:26:24,607 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:230] [id: 0x8d39cf27, L:/10.111.8.206:49744 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,607 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x8d39cf27, L:/10.111.8.206:49744 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 92 active connections and 29 inactive connections
2019-09-04 11:26:24,608 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:230] [id: 0xfb15cb4a, L:/10.111.8.206:49742 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,608 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xfb15cb4a, L:/10.111.8.206:49742 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 93 active connections and 28 inactive connections
2019-09-04 11:26:24,613 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:230] [id: 0x47090159, L:/10.111.8.206:49749 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,613 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x47090159, L:/10.111.8.206:49749 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 94 active connections and 27 inactive connections
2019-09-04 11:26:24,613 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:230] [id: 0x97b0acc6, L:/10.111.8.206:49751 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,613 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x97b0acc6, L:/10.111.8.206:49751 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 95 active connections and 26 inactive connections
2019-09-04 11:26:24,613 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:24,613 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:24,617 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:230] [id: 0xefb73afd, L:/10.111.8.206:49741 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,617 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0xefb73afd, L:/10.111.8.206:49741 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 96 active connections and 25 inactive connections
2019-09-04 11:26:24,617 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:230] [id: 0x0047f831, L:/10.111.8.206:49743 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,617 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x0047f831, L:/10.111.8.206:49743 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 97 active connections and 24 inactive connections
2019-09-04 11:26:24,618 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:230] [id: 0x3b0d2b0e, L:/10.111.8.206:49745 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,618 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x3b0d2b0e, L:/10.111.8.206:49745 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 98 active connections and 23 inactive connections
2019-09-04 11:26:24,618 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:230] [id: 0x1262d36d, L:/10.111.8.206:49748 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,618 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x1262d36d, L:/10.111.8.206:49748 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 99 active connections and 22 inactive connections
2019-09-04 11:26:24,618 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:230] [id: 0x439a316f, L:/10.111.8.206:49747 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,618 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x439a316f, L:/10.111.8.206:49747 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 100 active connections and 21 inactive connections
2019-09-04 11:26:24,618 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:230] [id: 0x666c4432, L:/10.111.8.206:49750 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:24,618 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x666c4432, L:/10.111.8.206:49750 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 101 active connections and 20 inactive connections
2019-09-04 11:26:24,629 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:24,629 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:24,629 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:24,749 DEBUG [reactor-http-nio-11] [SslHandler.setHandshakeSuccess:1535] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:24,749 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:24,749 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:24,749 DEBUG [reactor-http-nio-11] [HttpClientConnect.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Handler is being applied: {uri=https://mystorage.blob.core.windows.net/test/random-large.zip?blockid=MTFhYWIzNDYtOGFmOC00ZTVkLTgzMTgtYzYyOTJiNTQxMmRi&comp=block, method=PUT}
2019-09-04 11:26:24,749 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
PUT /test/random-large.zip?blockid=MTFhYWIzNDYtOGFmOC00ZTVkLTgzMTgtYzYyOTJiNTQxMmRi&comp=block HTTP/1.1
host: mystorage.blob.core.windows.net
accept: */*
Date: Wed, 04 Sep 2019 09:25:19 GMT
Authorization: Bearer XXXXXX
Content-Length: 4194304
x-ms-version: 2018-11-09
Content-Type: application/octet-stream
x-ms-client-request-id: 60eaceea-85bb-4e48-a500-88b11cee37a7
User-Agent: azsdk-java-azure-storage-blob/12.0.0-preview.2 11.0.3; Mac OS X 10.14.6
2019-09-04 11:26:34,513 ERROR [reactor-http-nio-5] [PooledConnectionProvider.error:300] [id: 0x939245db, L:/10.111.8.206:49709 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,514 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0x939245db, L:/10.111.8.206:49709 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 100 active connections and 21 inactive connections
2019-09-04 11:26:34,514 ERROR [reactor-http-nio-5] [PooledConnectionProvider.error:300] [id: 0xb3dc9ad1, L:/10.111.8.206:49710 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,515 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xb3dc9ad1, L:/10.111.8.206:49710 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 99 active connections and 22 inactive connections
2019-09-04 11:26:34,515 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0x939245db, L:/10.111.8.206:49709 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x939245db, L:/10.111.8.206:49709 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,515 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xb3dc9ad1, L:/10.111.8.206:49710 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xb3dc9ad1, L:/10.111.8.206:49710 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,597 ERROR [reactor-http-nio-12] [PooledConnectionProvider.error:300] [id: 0xef4b3806, L:/10.111.8.206:49717 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,598 DEBUG [reactor-http-nio-12] [PooledConnectionProvider.debug:235] [id: 0xef4b3806, L:/10.111.8.206:49717 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 98 active connections and 23 inactive connections
2019-09-04 11:26:34,599 ERROR [reactor-http-nio-12] [PooledConnectionProvider.error:300] [id: 0xf977106c, L:/10.111.8.206:49718 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,599 DEBUG [reactor-http-nio-12] [PooledConnectionProvider.debug:235] [id: 0xf977106c, L:/10.111.8.206:49718 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 97 active connections and 24 inactive connections
2019-09-04 11:26:34,599 DEBUG [reactor-http-nio-12] [PooledConnectionProvider.debug:235] [id: 0xef4b3806, L:/10.111.8.206:49717 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xef4b3806, L:/10.111.8.206:49717 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,600 DEBUG [reactor-http-nio-12] [PooledConnectionProvider.debug:235] [id: 0xf977106c, L:/10.111.8.206:49718 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xf977106c, L:/10.111.8.206:49718 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,600 ERROR [reactor-http-nio-3] [PooledConnectionProvider.error:300] [id: 0x584b85e5, L:/10.111.8.206:49727 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,601 DEBUG [reactor-http-nio-3] [PooledConnectionProvider.debug:235] [id: 0x584b85e5, L:/10.111.8.206:49727 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 96 active connections and 25 inactive connections
2019-09-04 11:26:34,601 DEBUG [reactor-http-nio-3] [PooledConnectionProvider.debug:235] [id: 0x584b85e5, L:/10.111.8.206:49727 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x584b85e5, L:/10.111.8.206:49727 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,601 ERROR [reactor-http-nio-3] [PooledConnectionProvider.error:300] [id: 0x8980818d, L:/10.111.8.206:49729 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,602 DEBUG [reactor-http-nio-3] [PooledConnectionProvider.debug:235] [id: 0x8980818d, L:/10.111.8.206:49729 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 95 active connections and 26 inactive connections
2019-09-04 11:26:34,602 DEBUG [reactor-http-nio-3] [PooledConnectionProvider.debug:235] [id: 0x8980818d, L:/10.111.8.206:49729 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x8980818d, L:/10.111.8.206:49729 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,602 ERROR [reactor-http-nio-3] [PooledConnectionProvider.error:300] [id: 0x3d28c8ac, L:/10.111.8.206:49732 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,603 DEBUG [reactor-http-nio-3] [PooledConnectionProvider.debug:235] [id: 0x3d28c8ac, L:/10.111.8.206:49732 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x3d28c8ac, L:/10.111.8.206:49732 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,604 ERROR [reactor-http-nio-5] [PooledConnectionProvider.error:300] [id: 0x76d181a2, L:/10.111.8.206:49737 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,605 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0x76d181a2, L:/10.111.8.206:49737 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 94 active connections and 27 inactive connections
2019-09-04 11:26:34,605 ERROR [reactor-http-nio-5] [PooledConnectionProvider.error:300] [id: 0xa3e1b3ca, L:/10.111.8.206:49738 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,605 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xa3e1b3ca, L:/10.111.8.206:49738 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 93 active connections and 28 inactive connections
2019-09-04 11:26:34,606 ERROR [reactor-http-nio-5] [PooledConnectionProvider.error:300] [id: 0xd0d64f7a, L:/10.111.8.206:49739 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,606 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xd0d64f7a, L:/10.111.8.206:49739 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 92 active connections and 29 inactive connections
2019-09-04 11:26:34,606 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0x76d181a2, L:/10.111.8.206:49737 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x76d181a2, L:/10.111.8.206:49737 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,606 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xa3e1b3ca, L:/10.111.8.206:49738 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xa3e1b3ca, L:/10.111.8.206:49738 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,606 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xd0d64f7a, L:/10.111.8.206:49739 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xd0d64f7a, L:/10.111.8.206:49739 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,607 ERROR [reactor-http-nio-5] [PooledConnectionProvider.error:300] [id: 0xbf47a49f, L:/10.111.8.206:49740 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,607 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xbf47a49f, L:/10.111.8.206:49740 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 91 active connections and 30 inactive connections
2019-09-04 11:26:34,607 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xbf47a49f, L:/10.111.8.206:49740 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xbf47a49f, L:/10.111.8.206:49740 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:34,608 ERROR [reactor-http-nio-5] [PooledConnectionProvider.error:300] [id: 0xfb15cb4a, L:/10.111.8.206:49742 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:34,609 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xfb15cb4a, L:/10.111.8.206:49742 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 90 active connections and 31 inactive connections
2019-09-04 11:26:34,609 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0xfb15cb4a, L:/10.111.8.206:49742 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xfb15cb4a, L:/10.111.8.206:49742 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,281 ERROR [reactor-http-nio-12] [PooledConnectionProvider.error:300] [id: 0x4dc44234, L:/10.111.8.206:49647 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
java.io.IOException: Operation timed out
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
        at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288) ~[netty-buffer-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[netty-buffer-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) [netty-common-4.1.33.Final.jar:4.1.33.Final]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2019-09-04 11:26:37,282 DEBUG [reactor-http-nio-12] [PooledConnectionProvider.debug:235] [id: 0x4dc44234, L:/10.111.8.206:49647 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 89 active connections and 32 inactive connections
2019-09-04 11:26:37,284 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object
2019-09-04 11:26:37,284 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,284 ERROR [reactor-http-nio-8] [PooledConnectionProvider.error:300] [id: 0xc9c47d58, L:/10.111.8.206:49721 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,285 ERROR [reactor-http-nio-6] [PooledConnectionProvider.error:300] [id: 0x6c0098dc, L:/10.111.8.206:49716 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,285 ERROR [reactor-http-nio-11] [PooledConnectionProvider.error:300] [id: 0xb6505ee9, L:/10.111.8.206:49731 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,285 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,285 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,286 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0xc9c47d58, L:/10.111.8.206:49721 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 88 active connections and 33 inactive connections
2019-09-04 11:26:37,286 DEBUG [reactor-http-nio-6] [PooledConnectionProvider.debug:235] [id: 0x6c0098dc, L:/10.111.8.206:49716 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 87 active connections and 34 inactive connections
2019-09-04 11:26:37,286 ERROR [reactor-http-nio-8] [PooledConnectionProvider.error:300] [id: 0x18db035c, L:/10.111.8.206:49736 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,286 ERROR [reactor-http-nio-6] [PooledConnectionProvider.error:300] [id: 0x01f4d1ea, L:/10.111.8.206:49714 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,286 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0xb6505ee9, L:/10.111.8.206:49731 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 86 active connections and 35 inactive connections
2019-09-04 11:26:37,286 ERROR [reactor-http-nio-2] [PooledConnectionProvider.error:300] [id: 0x9145a684, L:/10.111.8.206:49720 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,286 ERROR [reactor-http-nio-11] [PooledConnectionProvider.error:300] [id: 0x8d39cf27, L:/10.111.8.206:49744 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,286 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,286 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:230] [id: 0x14a987d3, L:/10.111.8.206:49752 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-6] [PooledConnectionProvider.debug:235] [id: 0x01f4d1ea, L:/10.111.8.206:49714 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 86 active connections and 35 inactive connections
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x14a987d3, L:/10.111.8.206:49752 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 86 active connections and 35 inactive connections
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-2] [PooledConnectionProvider.debug:235] [id: 0x9145a684, L:/10.111.8.206:49720 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 85 active connections and 36 inactive connections
2019-09-04 11:26:37,286 ERROR [reactor-http-nio-10] [PooledConnectionProvider.error:300] [id: 0x64da8198, L:/10.111.8.206:49711 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,287 ERROR [reactor-http-nio-7] [PooledConnectionProvider.error:300] [id: 0xefb73afd, L:/10.111.8.206:49741 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-6] [PooledConnectionProvider.debug:235] [id: 0x6c0098dc, L:/10.111.8.206:49716 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x6c0098dc, L:/10.111.8.206:49716 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,287 ERROR [reactor-http-nio-2] [PooledConnectionProvider.error:300] [id: 0xcc207825, L:/10.111.8.206:49722 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-6] [PooledConnectionProvider.debug:235] [id: 0x01f4d1ea, L:/10.111.8.206:49714 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x01f4d1ea, L:/10.111.8.206:49714 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,288 DEBUG [reactor-http-nio-10] [PooledConnectionProvider.debug:235] [id: 0x64da8198, L:/10.111.8.206:49711 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 82 active connections and 39 inactive connections
2019-09-04 11:26:37,288 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,288 DEBUG [reactor-http-nio-2] [PooledConnectionProvider.debug:235] [id: 0xcc207825, L:/10.111.8.206:49722 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 81 active connections and 40 inactive connections
2019-09-04 11:26:37,288 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,288 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0xefb73afd, L:/10.111.8.206:49741 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 80 active connections and 41 inactive connections
2019-09-04 11:26:37,288 ERROR [reactor-http-nio-2] [PooledConnectionProvider.error:300] [id: 0xfa42a37b, L:/10.111.8.206:49724 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,288 ERROR [reactor-http-nio-10] [PooledConnectionProvider.error:300] [id: 0x9be0ea5b, L:/10.111.8.206:49712 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,288 ERROR [reactor-http-nio-7] [PooledConnectionProvider.error:300] [id: 0x0047f831, L:/10.111.8.206:49743 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,288 ERROR [reactor-http-nio-6] [PooledConnectionProvider.error:300] [id: 0xedc8b7fa, L:/10.111.8.206:49691 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
java.io.IOException: Operation timed out
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
        at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288) ~[netty-buffer-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[netty-buffer-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) [netty-common-4.1.33.Final.jar:4.1.33.Final]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0x18db035c, L:/10.111.8.206:49736 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 83 active connections and 38 inactive connections
2019-09-04 11:26:37,288 DEBUG [reactor-http-nio-6] [PooledConnectionProvider.debug:235] [id: 0xedc8b7fa, L:/10.111.8.206:49691 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 79 active connections and 42 inactive connections
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-10] [PooledConnectionProvider.debug:235] [id: 0x9be0ea5b, L:/10.111.8.206:49712 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 77 active connections and 44 inactive connections
2019-09-04 11:26:37,289 ERROR [reactor-http-nio-8] [PooledConnectionProvider.error:300] [id: 0xf9facd2a, L:/10.111.8.206:49723 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-2] [PooledConnectionProvider.debug:235] [id: 0xfa42a37b, L:/10.111.8.206:49724 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 77 active connections and 44 inactive connections
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,287 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x8d39cf27, L:/10.111.8.206:49744 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 83 active connections and 38 inactive connections
2019-09-04 11:26:37,289 ERROR [reactor-http-nio-10] [PooledConnectionProvider.error:300] [id: 0x97cf9a04, L:/10.111.8.206:49719 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x0047f831, L:/10.111.8.206:49743 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 76 active connections and 45 inactive connections
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-2] [PooledConnectionProvider.debug:235] [id: 0x9145a684, L:/10.111.8.206:49720 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x9145a684, L:/10.111.8.206:49720 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,289 ERROR [reactor-http-nio-11] [PooledConnectionProvider.error:300] [id: 0x0c95ab57, L:/10.111.8.206:49746 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,289 ERROR [reactor-http-nio-7] [PooledConnectionProvider.error:300] [id: 0x3b0d2b0e, L:/10.111.8.206:49745 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,288 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-2] [PooledConnectionProvider.debug:235] [id: 0xcc207825, L:/10.111.8.206:49722 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xcc207825, L:/10.111.8.206:49722 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0xf9facd2a, L:/10.111.8.206:49723 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 75 active connections and 46 inactive connections
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-10] [PooledConnectionProvider.debug:235] [id: 0x97cf9a04, L:/10.111.8.206:49719 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 74 active connections and 47 inactive connections
2019-09-04 11:26:37,289 ERROR [reactor-http-nio-11] [PooledConnectionProvider.error:300] [id: 0x47090159, L:/10.111.8.206:49749 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-2] [PooledConnectionProvider.debug:235] [id: 0xfa42a37b, L:/10.111.8.206:49724 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xfa42a37b, L:/10.111.8.206:49724 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,289 ERROR [reactor-http-nio-8] [PooledConnectionProvider.error:300] [id: 0x163fe9a8, L:/10.111.8.206:49734 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-10] [PooledConnectionProvider.debug:235] [id: 0x64da8198, L:/10.111.8.206:49711 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x64da8198, L:/10.111.8.206:49711 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,289 DEBUG [reactor-http-nio-6] [ChannelOperations.debug:240] [id: 0xedc8b7fa, L:/10.111.8.206:49691 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] An outbound error could not be processed
java.nio.channels.ClosedChannelException: null
        at io.netty.channel.AbstractChannel$AbstractUnsafe.close(...)(Unknown Source) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-10] [PooledConnectionProvider.debug:235] [id: 0x9be0ea5b, L:/10.111.8.206:49712 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x9be0ea5b, L:/10.111.8.206:49712 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x3b0d2b0e, L:/10.111.8.206:49745 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 73 active connections and 48 inactive connections
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-6] [ChannelOperationsHandler.debug:235] [id: 0xedc8b7fa, L:/10.111.8.206:49691 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Terminated ChannelOperation. Dropping Pending Write: [Pending Writes on Completion]
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-10] [PooledConnectionProvider.debug:235] [id: 0x97cf9a04, L:/10.111.8.206:49719 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x97cf9a04, L:/10.111.8.206:49719 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,290 ERROR [reactor-http-nio-7] [PooledConnectionProvider.error:300] [id: 0x1262d36d, L:/10.111.8.206:49748 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0x163fe9a8, L:/10.111.8.206:49734 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 72 active connections and 49 inactive connections
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x47090159, L:/10.111.8.206:49749 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 71 active connections and 50 inactive connections
2019-09-04 11:26:37,290 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0xc9c47d58, L:/10.111.8.206:49721 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xc9c47d58, L:/10.111.8.206:49721 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,290 ERROR [reactor-http-nio-11] [PooledConnectionProvider.error:300] [id: 0x97b0acc6, L:/10.111.8.206:49751 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,291 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0x18db035c, L:/10.111.8.206:49736 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x18db035c, L:/10.111.8.206:49736 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,291 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,291 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0xf9facd2a, L:/10.111.8.206:49723 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xf9facd2a, L:/10.111.8.206:49723 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,291 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x1262d36d, L:/10.111.8.206:49748 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 70 active connections and 51 inactive connections
2019-09-04 11:26:37,291 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x97b0acc6, L:/10.111.8.206:49751 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 69 active connections and 52 inactive connections
2019-09-04 11:26:37,291 DEBUG [reactor-http-nio-8] [PooledConnectionProvider.debug:235] [id: 0x163fe9a8, L:/10.111.8.206:49734 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x163fe9a8, L:/10.111.8.206:49734 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,291 ERROR [reactor-http-nio-7] [PooledConnectionProvider.error:300] [id: 0x439a316f, L:/10.111.8.206:49747 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,291 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0xb6505ee9, L:/10.111.8.206:49731 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xb6505ee9, L:/10.111.8.206:49731 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,292 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,292 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,292 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,292 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,292 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,292 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x439a316f, L:/10.111.8.206:49747 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 68 active connections and 53 inactive connections
2019-09-04 11:26:37,292 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,292 ERROR [reactor-http-nio-7] [PooledConnectionProvider.error:300] [id: 0x666c4432, L:/10.111.8.206:49750 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,293 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x8d39cf27, L:/10.111.8.206:49744 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x8d39cf27, L:/10.111.8.206:49744 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,293 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,293 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x0c95ab57, L:/10.111.8.206:49746 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x0c95ab57, L:/10.111.8.206:49746 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,293 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:230] [id: 0x0c95ab57, L:/10.111.8.206:49746 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Immediately aborted pooled channel, re-acquiring new channel
2019-09-04 11:26:37,293 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x666c4432, L:/10.111.8.206:49750 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 67 active connections and 54 inactive connections
2019-09-04 11:26:37,293 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0xefb73afd, L:/10.111.8.206:49741 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xefb73afd, L:/10.111.8.206:49741 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,293 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x0047f831, L:/10.111.8.206:49743 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x0047f831, L:/10.111.8.206:49743 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x47090159, L:/10.111.8.206:49749 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x47090159, L:/10.111.8.206:49749 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0xa9b49aaf] Created new pooled channel, now 67 active connections and 55 inactive connections
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x3b0d2b0e, L:/10.111.8.206:49745 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x3b0d2b0e, L:/10.111.8.206:49745 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x1262d36d, L:/10.111.8.206:49748 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x1262d36d, L:/10.111.8.206:49748 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-4] [SslProvider.debug:235] [id: 0xa9b49aaf] SSL enabled using engine SSLEngineImpl and SNI mystorage.blob.core.windows.net:443
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x439a316f, L:/10.111.8.206:49747 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x439a316f, L:/10.111.8.206:49747 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-4] [BootstrapHandlers.debug:235] [id: 0xa9b49aaf] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (SimpleChannelPool$1#0 = io.netty.channel.pool.SimpleChannelPool$1), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2019-09-04 11:26:37,294 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x666c4432, L:/10.111.8.206:49750 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x666c4432, L:/10.111.8.206:49750 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,295 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,295 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:230] [id: 0x3d28c8ac, L:/10.111.8.206:49732 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Immediately aborted pooled channel, re-acquiring new channel
2019-09-04 11:26:37,295 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,295 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,295 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:235] [id: 0xd7cbdaa2] Created new pooled channel, now 67 active connections and 56 inactive connections
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-1] [SslProvider.debug:235] [id: 0xd7cbdaa2] SSL enabled using engine SSLEngineImpl and SNI mystorage.blob.core.windows.net:443
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0xb8101b56, L:/10.111.8.206:49704 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-1] [BootstrapHandlers.debug:235] [id: 0xd7cbdaa2] Initialized pipeline DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.sslReader = reactor.netty.tcp.SslProvider$SslReadHandler), (BootstrapHandlers$BootstrapInitializerHandler#0 = reactor.netty.channel.BootstrapHandlers$BootstrapInitializerHandler), (SimpleChannelPool$1#0 = io.netty.channel.pool.SimpleChannelPool$1), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,296 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,297 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,297 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,297 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,297 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,297 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,298 DEBUG [reactor-http-nio-1] [ChannelOperationsHandler.debug:235] [id: 0xf3634d6c, L:/10.111.8.206:49706 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,298 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,298 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,298 DEBUG [reactor-http-nio-11] [PooledConnectionProvider.debug:235] [id: 0x97b0acc6, L:/10.111.8.206:49751 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x97b0acc6, L:/10.111.8.206:49751 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,299 ERROR [reactor-http-nio-1] [PooledConnectionProvider.error:300] [id: 0x907155f8, L:/10.111.8.206:49715 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,299 DEBUG [reactor-http-nio-9] [ChannelOperationsHandler.debug:235] [id: 0x73ea78ab, L:/10.111.8.206:49707 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,300 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:235] [id: 0x907155f8, L:/10.111.8.206:49715 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 66 active connections and 57 inactive connections
2019-09-04 11:26:37,300 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,300 ERROR [reactor-http-nio-1] [PooledConnectionProvider.error:300] [id: 0x3e0166f6, L:/10.111.8.206:49713 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
javax.net.ssl.SSLException: handshake timed out
        at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source) ~[netty-handler-4.1.33.Final.jar:4.1.33.Final]
2019-09-04 11:26:37,301 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:235] [id: 0x3e0166f6, L:/10.111.8.206:49713 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 65 active connections and 58 inactive connections
2019-09-04 11:26:37,301 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:235] [id: 0x907155f8, L:/10.111.8.206:49715 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x907155f8, L:/10.111.8.206:49715 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,301 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:235] [id: 0x3e0166f6, L:/10.111.8.206:49713 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x3e0166f6, L:/10.111.8.206:49713 ! R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [disconnecting])
2019-09-04 11:26:37,303 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,303 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,304 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,304 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:230] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 66 active connections and 57 inactive connections
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:230] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 67 active connections and 56 inactive connections
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:230] [id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 68 active connections and 55 inactive connections
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:230] [id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 69 active connections and 54 inactive connections
2019-09-04 11:26:37,305 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,306 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:230] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,306 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 70 active connections and 53 inactive connections
2019-09-04 11:26:37,306 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:230] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,306 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 71 active connections and 52 inactive connections
2019-09-04 11:26:37,306 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,307 DEBUG [reactor-http-nio-11] [ChannelOperationsHandler.debug:235] [id: 0x2d89c53c, L:/10.111.8.206:49708 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,308 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:230] [id: 0x991478dc, L:/10.111.8.206:49753 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,308 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:235] [id: 0x991478dc, L:/10.111.8.206:49753 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 72 active connections and 51 inactive connections
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:230] [id: 0x69abaa5e, L:/10.111.8.206:49759 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:235] [id: 0x69abaa5e, L:/10.111.8.206:49759 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 73 active connections and 50 inactive connections
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:230] [id: 0x188a1f8f, L:/10.111.8.206:49754 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:235] [id: 0x188a1f8f, L:/10.111.8.206:49754 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 74 active connections and 49 inactive connections
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:230] [id: 0xc041a522, L:/10.111.8.206:49757 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:235] [id: 0xc041a522, L:/10.111.8.206:49757 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 75 active connections and 48 inactive connections
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:230] [id: 0x2a8082ad, L:/10.111.8.206:49756 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:235] [id: 0x2a8082ad, L:/10.111.8.206:49756 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 76 active connections and 47 inactive connections
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:230] [id: 0x44d2512c, L:/10.111.8.206:49755 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:235] [id: 0x44d2512c, L:/10.111.8.206:49755 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 77 active connections and 46 inactive connections
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:230] [id: 0x5e2a736c, L:/10.111.8.206:49758 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Registering pool release on close event for channel
2019-09-04 11:26:37,309 DEBUG [reactor-http-nio-9] [PooledConnectionProvider.debug:235] [id: 0x5e2a736c, L:/10.111.8.206:49758 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel connected, now 78 active connections and 45 inactive connections
2019-09-04 11:26:37,397 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:235] [id: 0xd7cbdaa2, L:/10.111.8.206:49761 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 76 active connections and 47 inactive connections
2019-09-04 11:26:37,397 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0xa9b49aaf, L:/10.111.8.206:49760 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 76 active connections and 47 inactive connections
2019-09-04 11:26:37,519 DEBUG [reactor-http-nio-4] [SslHandler.setHandshakeSuccess:1535] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:37,519 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:37,519 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:37,519 DEBUG [reactor-http-nio-4] [HttpClientConnect.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Handler is being applied: {uri=https://mystorage.blob.core.windows.net/test/random-large.zip?blockid=ZWY0MGRlYWItZDJhYy00NjhkLTg4ZTUtOGJjMWQ2NGE5ZTg4&comp=block, method=PUT}
2019-09-04 11:26:37,520 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
PUT /test/random-large.zip?blockid=ZWY0MGRlYWItZDJhYy00NjhkLTg4ZTUtOGJjMWQ2NGE5ZTg4&comp=block HTTP/1.1
host: mystorage.blob.core.windows.net
accept: */*
Date: Wed, 04 Sep 2019 09:25:19 GMT
Authorization: Bearer XXXXXX
Content-Length: 4194304
x-ms-version: 2018-11-09
Content-Type: application/octet-stream
x-ms-client-request-id: f4296dc2-9c42-4326-82d8-08a6b7ef3218
User-Agent: azsdk-java-azure-storage-blob/12.0.0-preview.2 11.0.3; Mac OS X 10.14.6
2019-09-04 11:26:37,520 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object
2019-09-04 11:26:37,520 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,520 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,521 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,521 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,521 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,522 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,522 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,522 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,523 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,523 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,523 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,524 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,528 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,529 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,530 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,530 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,530 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,531 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,531 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x7190eed8, L:/10.111.8.206:49730 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,860 DEBUG [reactor-http-nio-3] [ChannelOperationsHandler.debug:235] [id: 0xa0946cde, L:/10.111.8.206:49659 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,865 DEBUG [reactor-http-nio-4] [SslHandler.setHandshakeSuccess:1535] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:37,866 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:37,866 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:37,866 DEBUG [reactor-http-nio-4] [HttpClientConnect.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Handler is being applied: {uri=https://mystorage.blob.core.windows.net/test/random-large.zip?blockid=NjRhZWVhNjYtYzAzNy00ZTg0LTkwNDYtNjY0ZjRhZTZhYTUz&comp=block, method=PUT}
2019-09-04 11:26:37,866 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
PUT /test/random-large.zip?blockid=NjRhZWVhNjYtYzAzNy00ZTg0LTkwNDYtNjY0ZjRhZTZhYTUz&comp=block HTTP/1.1
host: mystorage.blob.core.windows.net
accept: */*
Date: Wed, 04 Sep 2019 09:25:19 GMT
Authorization: Bearer XXXXXX
Content-Length: 4194304
x-ms-version: 2018-11-09
Content-Type: application/octet-stream
x-ms-client-request-id: 0dfb7f43-4067-4055-bde5-34780c06c905
User-Agent: azsdk-java-azure-storage-blob/12.0.0-preview.2 11.0.3; Mac OS X 10.14.6
2019-09-04 11:26:37,866 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object
2019-09-04 11:26:37,867 DEBUG [reactor-http-nio-4] [SslHandler.setHandshakeSuccess:1535] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:37,867 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:37,867 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:37,867 DEBUG [reactor-http-nio-4] [HttpClientConnect.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Handler is being applied: {uri=https://mystorage.blob.core.windows.net/test/random-large.zip?blockid=ZTVmY2VlZDMtYmI1Mi00NDZiLWFmZDUtODRlYzYyMDEwZWU3&comp=block, method=PUT}
2019-09-04 11:26:37,867 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
PUT /test/random-large.zip?blockid=ZTVmY2VlZDMtYmI1Mi00NDZiLWFmZDUtODRlYzYyMDEwZWU3&comp=block HTTP/1.1
host: mystorage.blob.core.windows.net
accept: */*
Date: Wed, 04 Sep 2019 09:25:19 GMT
Authorization: Bearer XXXXXX
Content-Length: 4194304
x-ms-version: 2018-11-09
Content-Type: application/octet-stream
x-ms-client-request-id: 1949d793-f5b9-475a-be05-b8be15cfcba8
User-Agent: azsdk-java-azure-storage-blob/12.0.0-preview.2 11.0.3; Mac OS X 10.14.6
2019-09-04 11:26:37,868 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object
2019-09-04 11:26:37,868 DEBUG [reactor-http-nio-4] [SslHandler.setHandshakeSuccess:1535] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:37,868 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:37,869 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:37,869 DEBUG [reactor-http-nio-4] [HttpClientConnect.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Handler is being applied: {uri=https://mystorage.blob.core.windows.net/test/random-large.zip?blockid=ODkxODc3YTYtZDViYy00NjAwLTgyN2QtNzlhODRjMDhiNTJj&comp=block, method=PUT}
2019-09-04 11:26:37,869 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
PUT /test/random-large.zip?blockid=ODkxODc3YTYtZDViYy00NjAwLTgyN2QtNzlhODRjMDhiNTJj&comp=block HTTP/1.1
host: mystorage.blob.core.windows.net
accept: */*
Date: Wed, 04 Sep 2019 09:25:19 GMT
Authorization: Bearer XXXXXX
Content-Length: 4194304
x-ms-version: 2018-11-09
Content-Type: application/octet-stream
x-ms-client-request-id: 8e6e8da7-33ff-4ffa-8340-f4f07d35f990
User-Agent: azsdk-java-azure-storage-blob/12.0.0-preview.2 11.0.3; Mac OS X 10.14.6
2019-09-04 11:26:37,869 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object
2019-09-04 11:26:37,870 DEBUG [reactor-http-nio-4] [SslHandler.setHandshakeSuccess:1535] [id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:37,870 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:37,870 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:37,870 DEBUG [reactor-http-nio-4] [HttpClientConnect.debug:235] [id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Handler is being applied: {uri=https://mystorage.blob.core.windows.net/test/random-large.zip?blockid=YzYwOTQ2NGMtMjA4ZC00ZjI1LWEzOGQtNDIxYzNhOTZjNDMy&comp=block, method=PUT}
2019-09-04 11:26:37,871 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
PUT /test/random-large.zip?blockid=YzYwOTQ2NGMtMjA4ZC00ZjI1LWEzOGQtNDIxYzNhOTZjNDMy&comp=block HTTP/1.1
host: mystorage.blob.core.windows.net
accept: */*
Date: Wed, 04 Sep 2019 09:25:19 GMT
Authorization: Bearer XXXXXX
Content-Length: 4194304
x-ms-version: 2018-11-09
Content-Type: application/octet-stream
x-ms-client-request-id: 05088291-05f9-4402-9d0a-402a9073758e
User-Agent: azsdk-java-azure-storage-blob/12.0.0-preview.2 11.0.3; Mac OS X 10.14.6
2019-09-04 11:26:37,871 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x90e67a25, L:/10.111.8.206:49726 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object
2019-09-04 11:26:37,872 DEBUG [reactor-http-nio-4] [SslHandler.setHandshakeSuccess:1535] [id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:37,872 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:37,872 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:37,872 DEBUG [reactor-http-nio-4] [HttpClientConnect.debug:235] [id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Handler is being applied: {uri=https://mystorage.blob.core.windows.net/test/random-large.zip?blockid=YzJlNTg1OTYtNWVlMC00NTEzLTg5NzItYjEzMTg1YmI3NDI2&comp=block, method=PUT}
2019-09-04 11:26:37,872 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object DefaultHttpRequest(decodeResult: success, version: HTTP/1.1)
PUT /test/random-large.zip?blockid=YzJlNTg1OTYtNWVlMC00NTEzLTg5NzItYjEzMTg1YmI3NDI2&comp=block HTTP/1.1
host: mystorage.blob.core.windows.net
accept: */*
Date: Wed, 04 Sep 2019 09:25:19 GMT
Authorization: Bearer XXXXXX
Content-Length: 4194304
x-ms-version: 2018-11-09
Content-Type: application/octet-stream
x-ms-client-request-id: 35e2a0eb-f7b9-4048-a362-9cd2ace1e26f
User-Agent: azsdk-java-azure-storage-blob/12.0.0-preview.2 11.0.3; Mac OS X 10.14.6
2019-09-04 11:26:37,873 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x60587ca6, L:/10.111.8.206:49728 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Writing object
2019-09-04 11:26:37,873 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,873 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:37,873 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:37,877 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,449 ERROR [reactor-http-nio-5] [PooledConnectionProvider.error:300] [id: 0x4afffb8b, L:/10.111.8.206:49699 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
java.io.IOException: Operation timed out
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
        at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288) ~[netty-buffer-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[netty-buffer-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) [netty-common-4.1.33.Final.jar:4.1.33.Final]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2019-09-04 11:26:40,450 DEBUG [reactor-http-nio-5] [PooledConnectionProvider.debug:235] [id: 0x4afffb8b, L:/10.111.8.206:49699 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 75 active connections and 48 inactive connections
2019-09-04 11:26:40,452 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,453 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,453 DEBUG [reactor-http-nio-1] [SslHandler.setHandshakeSuccess:1535] [id: 0xd7cbdaa2, L:/10.111.8.206:49761 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:40,454 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,454 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:235] [id: 0xd7cbdaa2, L:/10.111.8.206:49761 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xd7cbdaa2, L:/10.111.8.206:49761 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:40,454 DEBUG [reactor-http-nio-1] [PooledConnectionProvider.debug:235] [id: 0xd7cbdaa2, L:/10.111.8.206:49761 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xd7cbdaa2, L:/10.111.8.206:49761 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:40,454 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,455 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,456 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x91ed48e4, L:/10.111.8.206:49733 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,459 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:40,459 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:40,459 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,461 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,462 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,462 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,465 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:40,467 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:43,448 ERROR [reactor-http-nio-7] [PooledConnectionProvider.error:300] [id: 0x673b4ad5, L:/10.111.8.206:49653 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Pooled connection observed an error
java.io.IOException: Operation timed out
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
        at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
        at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288) ~[netty-buffer-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1132) ~[netty-buffer-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:677) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:612) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:529) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:491) [netty-transport-4.1.33.Final.jar:4.1.33.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:905) [netty-common-4.1.33.Final.jar:4.1.33.Final]
        at java.lang.Thread.run(Thread.java:834) [?:?]
2019-09-04 11:26:43,449 DEBUG [reactor-http-nio-7] [PooledConnectionProvider.debug:235] [id: 0x673b4ad5, L:/10.111.8.206:49653 ! R:mystorage.blob.core.windows.net/XXXXXXX:443] Channel cleaned, now 74 active connections and 49 inactive connections
2019-09-04 11:26:43,451 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:43,452 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x63e276e8, L:/10.111.8.206:49735 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true
2019-09-04 11:26:43,456 DEBUG [reactor-http-nio-4] [SslHandler.setHandshakeSuccess:1535] [id: 0xa9b49aaf, L:/10.111.8.206:49760 - R:mystorage.blob.core.windows.net/XXXXXXX:443] HANDSHAKEN: TLS_ECDHE_RSA_WITH_AES_128_GCM_SHA256
2019-09-04 11:26:43,456 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0xa9b49aaf, L:/10.111.8.206:49760 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(PooledConnection{channel=[id: 0xa9b49aaf, L:/10.111.8.206:49760 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}, [connected])
2019-09-04 11:26:43,457 DEBUG [reactor-http-nio-4] [PooledConnectionProvider.debug:235] [id: 0xa9b49aaf, L:/10.111.8.206:49760 - R:mystorage.blob.core.windows.net/XXXXXXX:443] onStateChange(GET{uri=/, connection=PooledConnection{channel=[id: 0xa9b49aaf, L:/10.111.8.206:49760 - R:mystorage.blob.core.windows.net/XXXXXXX:443]}}, [configured])
2019-09-04 11:26:43,457 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:43,457 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change false
2019-09-04 11:26:43,458 DEBUG [reactor-http-nio-4] [ChannelOperationsHandler.debug:235] [id: 0x42f8dfe9, L:/10.111.8.206:49725 - R:mystorage.blob.core.windows.net/XXXXXXX:443] Write state change true

Code snippet

public class AzureTest
{
    private static final Logger LOG = LoggerFactory.getLogger(AzureTest.class);

    private final ExecutorService executorService = Executors.newSingleThreadExecutor();

    public static void main(final String[] args)
    {
        final AzureTest instance = new AzureTest();
        instance.testAzure();
    }

    private void testAzure()
    {
        final ClientSecretCredential tokenCredential = new ClientSecretCredentialBuilder()
            .clientId("XXX")
            .tenantId("XXX")
            .clientSecret("XXX")
            .build();

        final BlobServiceClient blobServiceClient =
            new BlobServiceClientBuilder().endpoint("https://mystorage.blob.core.windows.net/").credential(tokenCredential).buildClient();
        final ContainerClient containerClient = blobServiceClient.getContainerClient("test");
        upload(containerClient);
    }

    private void upload(final ContainerClient containerClient)
    {
        executorService.execute(new AzureRunnable(containerClient));
    }

    private static class AzureRunnable implements Runnable
    {
        private final ContainerClient containerClient;

        private AzureRunnable(final ContainerClient containerClient)
        {
            this.containerClient = containerClient;
        }

        @Override
        public void run()
        {
            final Path file = Paths.get("~/random-large.zip");
            try(final RandomAccessFile raf = new RandomAccessFile("~/random-large.zip", "rw");)
            {
                // raf.setLength(1024 * 1024L); -> 1Mb works
                raf.setLength(1024 * 1024 * 250L); // 250Mb: starts uploading, but crashes the whole machine (see stracktrace)
                containerClient.getBlockBlobClient("random-large.zip").uploadFromFile(file.toString());
            }
            catch (final IOException e)
            {
                LOG.error("Error", e);
            }
            finally
            {
                try
                {
                    Files.deleteIfExists(file);
                }
                catch (final IOException e)
                {
                    LOG.error("Error", e);
                }
            }
        }
    }
}

@cdraeger
Copy link
Author

cdraeger commented Sep 4, 2019

@rickle-msft
More information: I played around and tried the following:
blockBlobAsyncClient.uploadFromFile(filePath, 100 * 1024 * 1024, null, null, null).block();

Basically using the async client directly and setting the block size to the max of 100MB (the regular client does not give this possibility). Same error, but this results in a much cleaner stacktrace without SSL handshake errors/warnings. Also the exception comes a bit later after 4m15s as you can see in below stracktrace. Overall unfortunately the SDK seems barely usable to me currently. :(

2019-09-04 12:07:44,787 INFO  [qtp1387210478-17] [] [App.uploadToCloudStorage:336] Uploading random large file [path=/Users/username/random-large.zip; size=2147483648].
2019-09-04 12:12:29,448 ERROR [parallel-2] [] [Operators.error:319] Operator called default onErrorDropped
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,448 ERROR [parallel-11] [] [Operators.error:319] Operator called default onErrorDropped
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,448 ERROR [parallel-12] [] [Operators.error:319] Operator called default onErrorDropped
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,448 ERROR [parallel-3] [] [Operators.error:319] Operator called default onErrorDropped
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,448 ERROR [parallel-1] [] [Operators.error:319] Operator called default onErrorDropped
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,448 ERROR [parallel-8] [] [Operators.error:319] Operator called default onErrorDropped
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,448 ERROR [parallel-10] [] [Operators.error:319] Operator called default onErrorDropped
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,454 ERROR [parallel-10] [] [Schedulers.error:319] Scheduler worker in group main failed with an uncaught exception
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,454 ERROR [parallel-3] [] [Schedulers.error:319] Scheduler worker in group main failed with an uncaught exception
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,454 ERROR [parallel-11] [] [Schedulers.error:319] Scheduler worker in group main failed with an uncaught exception
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,454 ERROR [parallel-2] [] [Schedulers.error:319] Scheduler worker in group main failed with an uncaught exception
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,454 ERROR [parallel-1] [] [Schedulers.error:319] Scheduler worker in group main failed with an uncaught exception
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,454 ERROR [parallel-12] [] [Schedulers.error:319] Scheduler worker in group main failed with an uncaught exception
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]
2019-09-04 12:12:29,454 ERROR [parallel-8] [] [Schedulers.error:319] Scheduler worker in group main failed with an uncaught exception
java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 60000ms in 'peek' (and no fallback has been configured)
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:288) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:273) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:390) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.StrictSubscriber.onNext(StrictSubscriber.java:89) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.FluxOnErrorResume$ResumeSubscriber.onNext(FluxOnErrorResume.java:73) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:117) ~[reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:50) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:27) [reactor-core-3.2.10.RELEASE.jar:3.2.10.RELEASE]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_212]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_212]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_212]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_212]

@rickle-msft
Copy link
Contributor

Thank you for the follow up and thank you for your thorough investigation. I'm sure this information will prove helpful in our efforts to diagnose the problem. @jianghaolu can you ake a look at what might be causing these timeouts?

As a side note, the sync client should let you configure the block size. I have created #5234 to track

@rickle-msft
Copy link
Contributor

@cdraeger while we continue to investigate this over here, can you please try setting the retryOptions on your client (through the builder) and set an arbitrarily large tryTimeout value to see what happens in the network stack if we get the java.util.concurrent.TimeoutException out of the way?

@cdraeger
Copy link
Author

cdraeger commented Sep 6, 2019

Hi @rickle-msft thanks, this advise seems to have actually solved it entirely. I was now able to upload 2Gb and 4GB without errors, assuming that with the right value I will also be able to upload 16Gb or more (not yet tried). Reading the JavaDoc of the retry options class it becomes clear, unfortunately I was not aware of this at all. So in the end maybe just a documentation issue? Since I assume many people will upload large files, this just needs to be prominent then in the first basic examples I think.

I also tried again with a default block size (I believe 4MB) when uploading a 1Gb file. With the tryTimout increase, this is also ok.

Just one more general question: our upload sizes will vary between just a couple of megabytes to ~16Gb. Is it fine to set the block size to the max for all uploads, or should I say e.g. max block size for large files only, and default block size for all files smaller than the max block size?

I am still having issues uploading via streams, but I will open a separate ticket for this. Thanks again!

@rickle-msft
Copy link
Contributor

@cdraeger Happy to hear it! I think our path forward on this will actually be to remove the default timeout. We didn't have it in the past, and we were experimenting with adding it as a safeguard against hanging, but it seems that that environments and workflows are too variable to effectively provide a default, not to mention it's not easy for customers to figure out what went wrong when they do get this error and don't realize there's a default timeout. I'll leave this issue open as the tracking item to remove the default (though it will definitely still be possible to set a timeout if desired).

Thank you for opening a different issue for the streams. I'll respond over there now.

@kurtzeborn
Copy link
Member

@alzimmermsft, you were thinking this would require the removal of a default timeout parameter that wasn't there in v11.

@rickle-msft
Copy link
Contributor

@kurtzeborn @alzimmermsft Confirming that it looks like removing that default should fix this based on the customer's experience

@harisingh-highq
Copy link

harisingh-highq commented Mar 1, 2021

@cdraeger @rickle-msft

We are also facing same timeout issue for large file upload >500MB file size in blob storage version 12.10.0

image

@cdraeger As per your below comment

Hi @rickle-msft thanks, this advise seems to have actually solved it entirely. I was now able to upload 2Gb and 4GB without errors, assuming that with the right value I will also be able to upload 16Gb or more (not yet tried). Reading the JavaDoc of the retry options class it becomes clear, unfortunately I was not aware of this at all. So in the end maybe just a documentation issue? Since I assume many people will upload large files, this just needs to be prominent then in the first basic examples I think.

I also tried tryTimeout default value(which is Integer.MAX_VALUE) and customized value as per below code but none of this worked and still throwing Channel response timed out error and large file upload getting failed

image
image

Correct me if anything is missing in above code snippet. Please help us to sort out this issue?
Thanks

@rickle-msft
Copy link
Contributor

@harisingh-highq Are you using https? If so, can you try with http just as an experiment to see what you get?

@duynk3
Copy link

duynk3 commented Jun 24, 2021

Hi @harisingh-highq
have you resolved that issue ?

@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.
Labels
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. Storage Storage Service (Queues, Blobs, Files)
Projects
None yet
Development

Successfully merging a pull request may close this issue.

7 participants