[BUG] Jackson-Dependency upgrade causes EventHub communication to fail without any visible reason

[quandor]

Describe the bug
After adding dependency com.fasterxml.jackson.dataformat:jackson-dataformat-xml:2.12.0 to our project we are no longer able to successfully register a EventHubProcessorClient.
Turning on tracing logs did not give any insight about the cause of the problem.

To Reproduce
https://github.com/quandor/azure-dependency-problems contains code and instructions

Expected behavior
Clear message in logs about error condition.

** Setup information **

• OS: Linux (5.10.11-arch1-1)

[conniey]

Hey,

Thanks for reporting this issue. If you execute mvn dependency:tree -Dincludes="*fasterxml*" -Dverbose, there is a dependency conflict with Jackson: "com.fasterxml.jackson.dataformat:jackson-dataformat-xml:jar:2.11.3:compile - omitted for conflict with 2.12.0)".

Since you explicitly referenced 2.12.0, maven picks it up first as part of its dependency resolution. If you use 2.11.3, it should work.

[INFO] --- maven-dependency-plugin:2.8:tree (default-cli) @ azure-dependency-problems ---
[INFO] azure-dependency-problems:azure-dependency-problems:jar:1.0-SNAPSHOT
[INFO] +- com.azure:azure-messaging-eventhubs:jar:5.4.0:compile
[INFO] |  \- com.azure:azure-core:jar:1.12.0:compile
[INFO] |     +- com.fasterxml.jackson.datatype:jackson-datatype-jsr310:jar:2.11.3:compile
[INFO] |     |  +- (com.fasterxml.jackson.core:jackson-annotations:jar:2.11.3:compile - omitted for conflict with 2.12.0)
[INFO] |     |  +- (com.fasterxml.jackson.core:jackson-core:jar:2.11.3:compile - omitted for conflict with 2.12.0)
[INFO] |     |  \- (com.fasterxml.jackson.core:jackson-databind:jar:2.11.3:compile - omitted for conflict with 2.12.0)
[INFO] |     \- (com.fasterxml.jackson.dataformat:jackson-dataformat-xml:jar:2.11.3:compile - omitted for conflict with 2.12.0)
[INFO] \- com.fasterxml.jackson.dataformat:jackson-dataformat-xml:jar:2.12.0:compile
[INFO]    +- com.fasterxml.jackson.core:jackson-core:jar:2.12.0:compile
[INFO]    +- com.fasterxml.jackson.core:jackson-annotations:jar:2.12.0:compile
[INFO]    +- com.fasterxml.jackson.core:jackson-databind:jar:2.12.0:compile
[INFO]    |  +- (com.fasterxml.jackson.core:jackson-annotations:jar:2.12.0:compile - omitted for duplicate)
[INFO]    |  \- (com.fasterxml.jackson.core:jackson-core:jar:2.12.0:compile - omitted for duplicate)
[INFO]    +- com.fasterxml.jackson.module:jackson-module-jaxb-annotations:jar:2.12.0:compile
[INFO]    |  +- (com.fasterxml.jackson.core:jackson-annotations:jar:2.12.0:compile - omitted for duplicate)
[INFO]    |  +- (com.fasterxml.jackson.core:jackson-core:jar:2.12.0:compile - omitted for duplicate)
[INFO]    |  \- (com.fasterxml.jackson.core:jackson-databind:jar:2.12.0:compile - omitted for duplicate)
[INFO]    \- com.fasterxml.woodstox:woodstox-core:jar:6.2.3:compile

[quandor]

Thanks for the hint, we had figured out that already. Will you try to improve the runtime logs? It was a pretty hard and long time until found that one.

[conniey]

@quandor Do you have an example of how we could improve the runtime logs? What were the errors you saw?

[quandor]

After we recognized that eventhub communication did no longer work, we turned on debug logging. A sample out follows. To us this looks like there is trouble accessing the blob storage. But no indication what the cause may be. We just guessed after checking the dependencies that those conflicts might be a problem. After a couple of hours we finally found the problematic dependency.
I attached a sample log. You will see a lot of lines like 09:15:43.420 [reactor-http-epoll-1] DEBUG c.a.m.e.c.blob.BlobCheckpointStore - Found blob for partition eventhubnamespace.servicebus.windows.net/eventhub-name/eventhub-name-consumer-name/ownership/0 Lines like this are repeated until I quit the application.

sample_log.txt

[ppalaga]

I can confirm the issue. Forcing Jackson to 2.11 may work as a short term workaround, but it is rather risky for us. We get Jackson 2.12.1 managed via Quarkus BoM and we'd prefer using the version they test with to avoid any surprises in the Quarkus stack.

[ppalaga]

I can serve with a reproducer:

git clone git@github.com:ppalaga/azure-sdk-issue-18876.git
cd azure-sdk-issue-18876

# export your Azure credentials 
export AZURE_STORAGE_ACCOUNT_NAME=...
export AZURE_STORAGE_ACCOUNT_KEY=...

# First check the working version with Jackson managed in `azure-sdk-bom` 1.0.2
git checkout -b jackson-2.11 origin/jackson-2.11
mvn test
# should pass in a couple of seconds

# Then go back to master where we override the Jackson version to 2.12.1
git checkout master
mvn test

Expected: the test should pass with Jackson 2.12.1 too
Actual: an endless flood of messages like the following:

18:47:11.431 [reactor-http-epoll-2] INFO com.azure.storage.blob.implementation.ServicesImpl$ServicesService.listBlobContainersSegment - <-- 200 https://cqaccpeterpalagap1.blob.core.windows.net?marker=REDACTED&comp=REDACTED (83 ms, unknown-length body)Date:Fri, 05 Mar 2021 17:47:10 GMTServer:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0Transfer-Encoding:chunkedx-ms-version:REDACTEDContent-Type:application/xmlx-ms-request-id:REDACTEDx-ms-client-request-id:de36bb78-6d6f-4e90-ac9b-595aab056095(body content not logged)<-- END HTTP
18:47:11.435 [reactor-http-epoll-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [response_completed])
18:47:11.435 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Removed handler: azureReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.435 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Non Removed handler: azureWriteTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.435 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Non Removed handler: azureResponseTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.435 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Non Removed handler: azureReadTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.435 [reactor-http-epoll-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [disconnecting])
18:47:11.435 [reactor-http-epoll-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Releasing channel
18:47:11.435 [reactor-http-epoll-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Channel cleaned, now 0 active connections and 2 inactive connections
18:47:11.436 [parallel-5] INFO com.azure.storage.blob.implementation.ServicesImpl$ServicesService.listBlobContainersSegment - --> GET https://cqaccpeterpalagap1.blob.core.windows.net?marker=REDACTED&comp=REDACTEDDate:Fri, 05 Mar 2021 17:47:11 GMTAuthorization:REDACTEDContent-Length:0x-ms-version:REDACTEDx-ms-client-request-id:79afb470-857a-49a0-8f76-f4046cdd29acUser-Agent:azsdk-java-azure-storage-blob/12.10.0 (11.0.9; Linux; 5.8.18-100.fc31.x86_64)(empty body)--> END GET
18:47:11.437 [reactor-http-epoll-1] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Channel acquired, now 1 active connections and 1 inactive connections
18:47:11.437 [reactor-http-epoll-1] DEBUG reactor.netty.http.client.HttpClientConnect - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Handler is being applied: {uri=https://cqaccpeterpalagap1.blob.core.windows.net/?marker=&comp=list, method=GET}
18:47:11.437 [reactor-http-epoll-1] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [request_prepared])
18:47:11.437 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Added decoder [azureWriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureWriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
18:47:11.438 [reactor-http-epoll-1] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [request_sent])
18:47:11.438 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Removed handler: azureWriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.438 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Added decoder [azureResponseTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureResponseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
18:47:11.477 [reactor-http-epoll-1] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Received response (auto-read:false) : [Transfer-Encoding=chunked, Content-Type=application/xml, Server=Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0, x-ms-request-id=73fae92c-a01e-0096-55e7-1132fa000000, x-ms-client-request-id=79afb470-857a-49a0-8f76-f4046cdd29ac, x-ms-version=2020-04-08, Date=Fri, 05 Mar 2021 17:47:11 GMT]
18:47:11.477 [reactor-http-epoll-1] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [response_received])
18:47:11.478 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Removed handler: azureResponseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.478 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Added decoder [azureReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
18:47:11.478 [reactor-http-epoll-1] DEBUG reactor.netty.channel.FluxReceive - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
18:47:11.506 [reactor-http-epoll-1] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Received last HTTP packet
18:47:11.506 [reactor-http-epoll-1] INFO com.azure.storage.blob.implementation.ServicesImpl$ServicesService.listBlobContainersSegment - <-- 200 https://cqaccpeterpalagap1.blob.core.windows.net?marker=REDACTED&comp=REDACTED (70 ms, unknown-length body)Date:Fri, 05 Mar 2021 17:47:11 GMTServer:Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0Transfer-Encoding:chunkedx-ms-version:REDACTEDContent-Type:application/xmlx-ms-request-id:REDACTEDx-ms-client-request-id:79afb470-857a-49a0-8f76-f4046cdd29ac(body content not logged)<-- END HTTP
18:47:11.509 [reactor-http-epoll-1] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [response_completed])
18:47:11.509 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Removed handler: azureReadTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.509 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Non Removed handler: azureWriteTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.509 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Non Removed handler: azureResponseTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.509 [reactor-http-epoll-1] DEBUG reactor.netty.ReactorNetty - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Non Removed handler: azureReadTimeoutHandler, context: null, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.509 [reactor-http-epoll-1] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [disconnecting])
18:47:11.509 [reactor-http-epoll-1] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Releasing channel
18:47:11.509 [reactor-http-epoll-1] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x7ad1edbc, L:/192.168.1.106:49182 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Channel cleaned, now 0 active connections and 2 inactive connections
18:47:11.511 [parallel-7] INFO com.azure.storage.blob.implementation.ServicesImpl$ServicesService.listBlobContainersSegment - --> GET https://cqaccpeterpalagap1.blob.core.windows.net?marker=REDACTED&comp=REDACTEDDate:Fri, 05 Mar 2021 17:47:11 GMTAuthorization:REDACTEDContent-Length:0x-ms-version:REDACTEDx-ms-client-request-id:8ef44198-5c2f-4444-b726-6e42c374481aUser-Agent:azsdk-java-azure-storage-blob/12.10.0 (11.0.9; Linux; 5.8.18-100.fc31.x86_64)(empty body)--> END GET
18:47:11.512 [reactor-http-epoll-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Channel acquired, now 1 active connections and 1 inactive connections
18:47:11.512 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClientConnect - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Handler is being applied: {uri=https://cqaccpeterpalagap1.blob.core.windows.net/?marker=&comp=list, method=GET}
18:47:11.512 [reactor-http-epoll-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [request_prepared])
18:47:11.512 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Added decoder [azureWriteTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureWriteTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
18:47:11.513 [reactor-http-epoll-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [request_sent])
18:47:11.513 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Removed handler: azureWriteTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.513 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Added decoder [azureResponseTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureResponseTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
18:47:11.545 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Received response (auto-read:false) : [Transfer-Encoding=chunked, Content-Type=application/xml, Server=Windows-Azure-Blob/1.0 Microsoft-HTTPAPI/2.0, x-ms-request-id=fb537a49-001e-003a-26e7-11136d000000, x-ms-client-request-id=8ef44198-5c2f-4444-b726-6e42c374481a, x-ms-version=2020-04-08, Date=Fri, 05 Mar 2021 17:47:10 GMT]
18:47:11.545 [reactor-http-epoll-2] DEBUG reactor.netty.resources.PooledConnectionProvider - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] onStateChange(GET{uri=/?marker=&comp=list, connection=PooledConnection{channel=[id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443]}}, [response_received])
18:47:11.545 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Removed handler: azureResponseTimeoutHandler, pipeline: DefaultChannelPipeline{(reactor.left.sslHandler = io.netty.handler.ssl.SslHandler), (reactor.left.httpCodec = io.netty.handler.codec.http.HttpClientCodec), (reactor.right.reactiveBridge = reactor.netty.channel.ChannelOperationsHandler)}
18:47:11.545 [reactor-http-epoll-2] DEBUG reactor.netty.ReactorNetty - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Added decoder [azureReadTimeoutHandler] at the end of the user pipeline, full pipeline: [reactor.left.sslHandler, reactor.left.httpCodec, azureReadTimeoutHandler, reactor.right.reactiveBridge, DefaultChannelPipeline$TailContext#0]
18:47:11.545 [reactor-http-epoll-2] DEBUG reactor.netty.channel.FluxReceive - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] FluxReceive{pending=0, cancelled=false, inboundDone=false, inboundError=null}: subscribing inbound receiver
18:47:11.573 [reactor-http-epoll-2] DEBUG reactor.netty.http.client.HttpClientOperations - [id: 0x233fc390, L:/192.168.1.106:49184 - R:cqaccpeterpalagap1.blob.core.windows.net/52.239.140.42:443] Received last HTTP packet

Note that this impacts all users of Azure Java clients on Quarkus 1.12.0.Final that was released on Feb. 23 2021.

Also note that without enabling the logging on the client via httpLogOptions(new HttpLogOptions().setLogLevel(HttpLogDetailLevel.BODY_AND_HEADERS).setPrettyPrintBody(true)) users will have no clue what is going on. The client will just block silently until hitting a timeout on some higher level of the stack.

[ppalaga]

Any chance to check this, please? Staying with Jackson 2.11 is not tenable in the long term.

[ppalaga]

Reminding friendly that this issue exists and that end users on Quarkus 2.12 and 2.13 are facing it.

[mzupnik]

I would like to ask if there are any chances of fixing this issue? In my company, we are developing a project based on the Quarkus. We would like to choose Azure Event Hub for the messaging. This issue prevents us from using the Event Hub in our project. The workaround of staying on the old Jackson library is too risky for us.

[brunoborges]

@JonathanGiles @conniey is it possible to soft dependency on Jackson so users can more easily transition to a later version, or is it because there is a hard dependency on 2.11.2, where 2.12+ breaks compatibility?

[conniey]

@alzimmermsft may be able to provide more information on this because he's working on Jackson.

[alzimmermsft]

Hi @brunoborges, yes, there was an issue before where Jackson 2.11 and 2.12 had implicit serialization/deserialization differences which resulted in regressions for some SDKs. These issues have since been resolved and the Azure SDKs using azure-core 1.14.1 or later should be able to use either Jackson 2.11 or 2.12.

Looking forward, we are investigating new patterns and version shimming to support a wider breadth of Jackson versions to prevent future scenarios such as this.

[ppalaga]

Thanks @brunoborges and @alzimmermsft, I can confirm that upgrading to azure-bom 1.0.3 solves the issue for us in Camel Quarkus apache/camel-quarkus#2758

[ghost]

Hi @quandor. Thank you for opening this issue and giving us the opportunity to assist. We believe that this has been addressed. If you feel that further discussion is needed, please add a comment with the text “/unresolve” to remove the “issue-addressed” label and continue the conversation.