search

Azure / azure-storage-java

Microsoft Azure Storage Library for Java
https://docs.microsoft.com/en-us/java/api/overview/azure/storage
MIT License
189 stars 164 forks source link

Add Message to Queue Failed #505

Closed thiner closed 4 years ago

thiner commented 5 years ago

Which service(blob, file, queue, table) does this issue concern?

Queue Storage

Which version of the SDK was used?

v8.4.0

What problem was encountered?

I just found an issue, but I am not sure whether it's my configuration issue or caused by queue storage. When my application call this method queue.addMessage(message);, it's stuck for a long time until request timeout. and then throws an exception with below message:

azure storage This SAXParser, "org.apache.xerces.jaxp.SAXParserImpl", does not support the reset functionality. Specification "null" version "null"

It seems to add message action is failed. But when I check the queue in the portal, I can find the message is there and is duplicated for twice for each.

My code has been deployed to production for several months, and it's working fine before last Friday. So I am suspecting it's caused by Azure.

Have you found a mitigation/solution?

No.

rickle-msft commented 5 years ago

@thiner I will check with some people over here to see if there has been any notice of odd behavior in the queue service. As far as the client, goes, I suspect what is happening is that somehow this failure is causing a retry, but it's just failing because of parsing whereas the request actually succeeded. Thus, when it retries, it is successful again and a duplicate message is queued. Then, ultimately the operation times out and this error manifests. We sometimes see these parsing errors when there are dependency conflicts between Jackson artifacts. Is it possible another component of the application has been updated and changed a Jackson dependency that could cause this conflict? Or is it the case that the application has been untouched in prod? And is this affecting the behavior of your application? Or is it able to handle these duplicates?

rickle-msft commented 5 years ago

@thiner Can you also share a more exact time window on when you started seeing this failure? And how often does this happen? Has it started happening on every request or intermittently? Do you have any logs you can share that might capture the retry behavior or if there are any details from the response getting logged before this exception is hit?

thiner commented 5 years ago

Below is the error log I just caught in debugger.

2019-10-22 15:00:32,493:ERROR RxSingleScheduler-1 (AuditingServiceImpl.java:93) - The server encountered an unknown failure: Created
com.microsoft.azure.storage.StorageException: The server encountered an unknown failure: Created
    at com.microsoft.azure.storage.StorageException.translateException(StorageException.java:101) ~[azure-storage-5.5.0.jar:?]
    at com.microsoft.azure.storage.core.ExecutionEngine.executeWithRetry(ExecutionEngine.java:199) ~[azure-storage-5.5.0.jar:?]
    at com.microsoft.azure.storage.queue.CloudQueue.addMessage(CloudQueue.java:269) ~[azure-storage-5.5.0.jar:?]
    at com.microsoft.azure.storage.queue.CloudQueue.addMessage(CloudQueue.java:214) ~[azure-storage-5.5.0.jar:?]
    at c.b.m.o.service.impl.AuditingServiceImpl.lambda$0() ~[classes/:?]
    at io.reactivex.internal.operators.flowable.FlowableFromCallable.subscribeActual(FlowableFromCallable.java:39) ~[rxjava-2.2.11.jar:?]
    at io.reactivex.Flowable.subscribe(Flowable.java:14918) ~[rxjava-2.2.11.jar:?]
    at io.reactivex.Flowable.subscribe(Flowable.java:14865) ~[rxjava-2.2.11.jar:?]
    at io.reactivex.internal.operators.flowable.FlowableSubscribeOn$SubscribeOnSubscriber.run(FlowableSubscribeOn.java:82) ~[rxjava-2.2.11.jar:?]
    at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) [rxjava-2.2.11.jar:?]
    at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) [rxjava-2.2.11.jar:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_202]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_202]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_202]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_202]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_202]
    at java.lang.Thread.run(Thread.java:748) [?:1.8.0_202]
Caused by: java.lang.UnsupportedOperationException: This SAXParser, "org.apache.xerces.jaxp.SAXParserImpl", does not support the reset functionality.  Specification "null" version "null"
    at javax.xml.parsers.SAXParser.reset(SAXParser.java:112) ~[?:1.8.0_202]
    at com.microsoft.azure.storage.core.Utility.getSAXParser(Utility.java:704) ~[azure-storage-5.5.0.jar:?]
    at com.microsoft.azure.storage.queue.QueueMessageHandler.readMessages(QueueMessageHandler.java:69) ~[azure-storage-5.5.0.jar:?]
    at com.microsoft.azure.storage.queue.CloudQueue$1.preProcessResponse(CloudQueue.java:310) ~[azure-storage-5.5.0.jar:?]
    at com.microsoft.azure.storage.queue.CloudQueue$1.preProcessResponse(CloudQueue.java:283) ~[azure-storage-5.5.0.jar:?]
    at com.microsoft.azure.storage.core.ExecutionEngine.executeWithRetry(ExecutionEngine.java:138) ~[azure-storage-5.5.0.jar:?]
    ... 15 more

The failure was observed firstly last Friday. It fails almost every time.

thiner commented 5 years ago

Regarding Jackson version conflict potentials, I'm using azure-cosmosdb:2.6.2 as well. And the resolved jackson libraries dependencies as below:

jackson-annotation: 2.9.0
jackson-core: 2.9.9
jackson-core-asl: 1.9.13
jackson-databind: 2.9.9
jackson-dataformat-yaml: 2.9.9
jackson-datatype-jdk8: 2.9.9
jackson-datatype-jsr310: 2.9.9
jackson-mapper-asl: 1.9.13
jackson-module-parameter-names: 2.9.9
rickle-msft commented 5 years ago

Digging around online a little further suggests that there is a dependency issue, which makes sense since the unknown failure code is "Created," which should be getting read as successful. Can you paste the full output of mvn dependency:tree. In particular, I'll be curious if there are multiple projects trying to use the Xerces SAXParser as that's what seems to be failing.

thiner commented 5 years ago

The complete dependency tree as below.

[INFO] c.b.m:api:war:0.0.1-SNAPSHOT
[INFO] +- org.springframework.boot:spring-boot-starter-web:jar:2.1.6.RELEASE:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-json:jar:2.1.6.RELEASE:compile
[INFO] |  |  +- com.fasterxml.jackson.datatype:jackson-datatype-jdk8:jar:2.9.9:compile
[INFO] |  |  +- com.fasterxml.jackson.datatype:jackson-datatype-jsr310:jar:2.9.9:compile
[INFO] |  |  \- com.fasterxml.jackson.module:jackson-module-parameter-names:jar:2.9.9:compile
[INFO] |  +- org.hibernate.validator:hibernate-validator:jar:6.0.17.Final:compile
[INFO] |  |  \- org.jboss.logging:jboss-logging:jar:3.3.2.Final:compile
[INFO] |  +- org.springframework:spring-web:jar:5.1.8.RELEASE:compile
[INFO] |  \- org.springframework:spring-webmvc:jar:5.1.8.RELEASE:compile
[INFO] |     \- org.springframework:spring-expression:jar:5.1.8.RELEASE:compile
[INFO] +- org.springframework.boot:spring-boot-starter:jar:2.1.6.RELEASE:compile
[INFO] |  +- org.springframework.boot:spring-boot:jar:2.1.6.RELEASE:compile
[INFO] |  +- org.springframework.boot:spring-boot-autoconfigure:jar:2.1.6.RELEASE:compile
[INFO] |  +- javax.annotation:javax.annotation-api:jar:1.3.2:compile
[INFO] |  +- org.springframework:spring-core:jar:5.1.8.RELEASE:compile
[INFO] |  |  \- org.springframework:spring-jcl:jar:5.1.8.RELEASE:compile
[INFO] |  \- org.yaml:snakeyaml:jar:1.23:compile
[INFO] +- org.springframework.boot:spring-boot-starter-log4j2:jar:2.1.6.RELEASE:compile
[INFO] |  +- org.apache.logging.log4j:log4j-slf4j-impl:jar:2.11.2:compile
[INFO] |  |  \- org.apache.logging.log4j:log4j-api:jar:2.11.2:compile
[INFO] |  +- org.apache.logging.log4j:log4j-core:jar:2.11.2:compile
[INFO] |  +- org.apache.logging.log4j:log4j-jul:jar:2.11.2:compile
[INFO] |  \- org.slf4j:jul-to-slf4j:jar:1.7.26:compile
[INFO] +- javax.validation:validation-api:jar:2.0.0.Final:compile
[INFO] +- org.springframework.boot:spring-boot-starter-data-jpa:jar:2.1.6.RELEASE:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-aop:jar:2.1.6.RELEASE:compile
[INFO] |  |  \- org.aspectj:aspectjweaver:jar:1.9.4:compile
[INFO] |  +- org.springframework.boot:spring-boot-starter-jdbc:jar:2.1.6.RELEASE:compile
[INFO] |  |  +- com.zaxxer:HikariCP:jar:3.2.0:compile
[INFO] |  |  \- org.springframework:spring-jdbc:jar:5.1.8.RELEASE:compile
[INFO] |  +- javax.transaction:javax.transaction-api:jar:1.3:compile
[INFO] |  +- javax.xml.bind:jaxb-api:jar:2.3.1:compile
[INFO] |  |  \- javax.activation:javax.activation-api:jar:1.2.0:compile
[INFO] |  +- org.hibernate:hibernate-core:jar:5.3.10.Final:compile
[INFO] |  |  +- javax.persistence:javax.persistence-api:jar:2.2:compile
[INFO] |  |  +- org.javassist:javassist:jar:3.23.2-GA:compile
[INFO] |  |  +- net.bytebuddy:byte-buddy:jar:1.9.13:compile
[INFO] |  |  +- antlr:antlr:jar:2.7.7:compile
[INFO] |  |  +- org.jboss:jandex:jar:2.0.5.Final:compile
[INFO] |  |  +- org.dom4j:dom4j:jar:2.1.1:compile
[INFO] |  |  \- org.hibernate.common:hibernate-commons-annotations:jar:5.0.4.Final:compile
[INFO] |  +- org.springframework.data:spring-data-jpa:jar:2.1.9.RELEASE:compile
[INFO] |  |  +- org.springframework.data:spring-data-commons:jar:2.1.9.RELEASE:compile
[INFO] |  |  +- org.springframework:spring-orm:jar:5.1.8.RELEASE:compile
[INFO] |  |  \- org.springframework:spring-tx:jar:5.1.8.RELEASE:compile
[INFO] |  \- org.springframework:spring-aspects:jar:5.1.8.RELEASE:compile
[INFO] +- com.microsoft.sqlserver:mssql-jdbc:jar:6.4.0.jre8:runtime
[INFO] +- org.springframework.boot:spring-boot-starter-tomcat:jar:2.1.6.RELEASE:provided
[INFO] |  +- org.apache.tomcat.embed:tomcat-embed-core:jar:9.0.21:provided
[INFO] |  +- org.apache.tomcat.embed:tomcat-embed-el:jar:9.0.21:provided
[INFO] |  \- org.apache.tomcat.embed:tomcat-embed-websocket:jar:9.0.21:provided
[INFO] +- com.microsoft.azure:applicationinsights-spring-boot-starter:jar:1.1.1:compile
[INFO] |  +- com.microsoft.azure:applicationinsights-core:jar:2.3.0:compile
[INFO] |  \- com.microsoft.azure:applicationinsights-web:jar:2.3.0:compile
[INFO] +- com.microsoft.azure:applicationinsights-logging-log4j2:jar:2.1.1:compile
[INFO] +- com.microsoft.azure:azure-storage:jar:8.4.0:compile
[INFO] |  +- com.fasterxml.jackson.core:jackson-core:jar:2.9.9:compile
[INFO] |  +- org.slf4j:slf4j-api:jar:1.7.26:compile
[INFO] |  \- com.microsoft.azure:azure-keyvault-core:jar:1.0.0:compile
[INFO] +- com.microsoft.azure:azure-cosmosdb:jar:2.6.2:compile
[INFO] |  +- com.microsoft.azure:azure-cosmosdb-commons:jar:2.6.2:compile
[INFO] |  |  +- io.netty:netty-handler-proxy:jar:4.1.36.Final:compile
[INFO] |  |  |  \- io.netty:netty-codec-socks:jar:4.1.36.Final:compile
[INFO] |  |  \- org.apache.commons:commons-collections4:jar:4.2:compile
[INFO] |  +- com.microsoft.azure:azure-cosmosdb-gateway:jar:2.6.2:compile
[INFO] |  +- com.microsoft.azure:azure-cosmosdb-direct:jar:2.6.2:compile
[INFO] |  |  +- io.dropwizard.metrics:metrics-core:jar:4.0.5:compile
[INFO] |  |  \- io.micrometer:micrometer-core:jar:1.1.5:compile
[INFO] |  |     +- org.hdrhistogram:HdrHistogram:jar:2.1.9:compile
[INFO] |  |     \- org.latencyutils:LatencyUtils:jar:2.0.3:compile
[INFO] |  +- com.fasterxml.uuid:java-uuid-generator:jar:3.1.4:compile
[INFO] |  +- commons-io:commons-io:jar:2.5:compile
[INFO] |  +- com.github.davidmoten:rxjava-extras:jar:0.8.0.17:compile
[INFO] |  +- io.reactivex:rxjava:jar:1.3.8:compile
[INFO] |  +- io.reactivex:rxjava-string:jar:1.1.1:compile
[INFO] |  +- io.reactivex:rxnetty:jar:0.4.20:compile
[INFO] |  +- io.netty:netty-codec-http:jar:4.1.36.Final:compile
[INFO] |  |  +- io.netty:netty-common:jar:4.1.36.Final:compile
[INFO] |  |  +- io.netty:netty-buffer:jar:4.1.36.Final:compile
[INFO] |  |  \- io.netty:netty-codec:jar:4.1.36.Final:compile
[INFO] |  +- io.netty:netty-handler:jar:4.1.36.Final:compile
[INFO] |  \- io.netty:netty-transport:jar:4.1.36.Final:compile
[INFO] |     \- io.netty:netty-resolver:jar:4.1.36.Final:compile
[INFO] +- org.springframework.boot:spring-boot-starter-security:jar:2.1.6.RELEASE:compile
[INFO] |  +- org.springframework:spring-aop:jar:5.1.8.RELEASE:compile
[INFO] |  +- org.springframework.security:spring-security-config:jar:5.1.5.RELEASE:compile
[INFO] |  \- org.springframework.security:spring-security-web:jar:5.1.5.RELEASE:compile
[INFO] +- org.springframework.security.oauth:spring-security-oauth2:jar:2.2.4.RELEASE:compile
[INFO] |  +- org.springframework:spring-beans:jar:5.1.8.RELEASE:compile
[INFO] |  +- org.springframework:spring-context:jar:5.1.8.RELEASE:compile
[INFO] |  +- org.springframework.security:spring-security-core:jar:5.1.5.RELEASE:compile
[INFO] |  +- commons-codec:commons-codec:jar:1.11:compile
[INFO] |  \- org.codehaus.jackson:jackson-mapper-asl:jar:1.9.13:compile
[INFO] |     \- org.codehaus.jackson:jackson-core-asl:jar:1.9.13:compile
[INFO] +- org.springframework.security:spring-security-oauth2-jose:jar:5.1.5.RELEASE:compile
[INFO] |  \- org.springframework.security:spring-security-oauth2-core:jar:5.1.5.RELEASE:compile
[INFO] +- org.springframework.security:spring-security-oauth2-resource-server:jar:5.1.5.RELEASE:compile
[INFO] +- org.springframework.security.oauth.boot:spring-security-oauth2-autoconfigure:jar:2.1.5.RELEASE:compile
[INFO] |  +- com.fasterxml.jackson.core:jackson-annotations:jar:2.9.0:compile
[INFO] |  +- com.sun.xml.bind:jaxb-core:jar:2.3.0.1:compile
[INFO] |  +- com.sun.xml.bind:jaxb-impl:jar:2.3.0.1:compile
[INFO] |  \- org.springframework.security:spring-security-jwt:jar:1.0.10.RELEASE:compile
[INFO] |     \- org.bouncycastle:bcpkix-jdk15on:jar:1.60:compile
[INFO] |        \- org.bouncycastle:bcprov-jdk15on:jar:1.60:compile
[INFO] +- com.nimbusds:nimbus-jose-jwt:jar:7.8:compile
[INFO] |  +- com.github.stephenc.jcip:jcip-annotations:jar:1.0-1:compile
[INFO] |  \- net.minidev:json-smart:jar:2.3:compile (version selected from constraint [1.3.1,2.3])
[INFO] |     \- net.minidev:accessors-smart:jar:1.2:compile
[INFO] |        \- org.ow2.asm:asm:jar:5.0.4:compile
[INFO] +- c.b:azure-token-validator:jar:1.1.8:compile
[INFO] |  +- org.bitbucket.b_c:jose4j:jar:0.5.4:compile
[INFO] |  +- org.ligboy.retrofit2:converter-fastjson:jar:2.1.0:compile
[INFO] |  \- org.slf4j:jcl-over-slf4j:jar:1.7.26:compile
[INFO] +- org.mapstruct:mapstruct:jar:1.3.1.Final:compile
[INFO] +- org.projectlombok:lombok:jar:1.18.8:provided
[INFO] +- com.alibaba:fastjson:jar:1.2.58:compile
[INFO] +- org.apache.commons:commons-lang3:jar:3.9:compile
[INFO] +- io.springfox:springfox-swagger2:jar:2.9.2:compile
[INFO] |  +- io.swagger:swagger-annotations:jar:1.5.20:compile
[INFO] |  +- io.swagger:swagger-models:jar:1.5.20:compile
[INFO] |  +- io.springfox:springfox-spi:jar:2.9.2:compile
[INFO] |  |  \- io.springfox:springfox-core:jar:2.9.2:compile
[INFO] |  +- io.springfox:springfox-schema:jar:2.9.2:compile
[INFO] |  +- io.springfox:springfox-swagger-common:jar:2.9.2:compile
[INFO] |  +- io.springfox:springfox-spring-web:jar:2.9.2:compile
[INFO] |  +- com.google.guava:guava:jar:20.0:compile
[INFO] |  +- com.fasterxml:classmate:jar:1.4.0:compile
[INFO] |  +- org.springframework.plugin:spring-plugin-core:jar:1.2.0.RELEASE:compile
[INFO] |  \- org.springframework.plugin:spring-plugin-metadata:jar:1.2.0.RELEASE:compile
[INFO] +- io.springfox:springfox-swagger-ui:jar:2.9.2:compile
[INFO] +- com.fasterxml.jackson.core:jackson-databind:jar:2.9.9:compile
[INFO] +- com.fasterxml.jackson.dataformat:jackson-dataformat-yaml:jar:2.9.9:compile
[INFO] +- org.springframework.boot:spring-boot-starter-test:jar:2.1.6.RELEASE:test
[INFO] |  +- org.springframework.boot:spring-boot-test:jar:2.1.6.RELEASE:test
[INFO] |  +- org.springframework.boot:spring-boot-test-autoconfigure:jar:2.1.6.RELEASE:test
[INFO] |  +- com.jayway.jsonpath:json-path:jar:2.4.0:test
[INFO] |  +- org.assertj:assertj-core:jar:3.11.1:test
[INFO] |  +- org.mockito:mockito-core:jar:2.23.4:test
[INFO] |  |  +- net.bytebuddy:byte-buddy-agent:jar:1.9.13:test
[INFO] |  |  \- org.objenesis:objenesis:jar:2.6:test
[INFO] |  +- org.hamcrest:hamcrest-core:jar:1.3:test
[INFO] |  +- org.hamcrest:hamcrest-library:jar:1.3:test
[INFO] |  +- org.skyscreamer:jsonassert:jar:1.5.0:test
[INFO] |  |  \- com.vaadin.external.google:android-json:jar:0.0.20131108.vaadin1:test
[INFO] |  +- org.springframework:spring-test:jar:5.1.8.RELEASE:test
[INFO] |  \- org.xmlunit:xmlunit-core:jar:2.6.2:test
[INFO] +- org.junit.jupiter:junit-jupiter-engine:jar:5.3.2:test
[INFO] |  +- org.apiguardian:apiguardian-api:jar:1.0.0:test
[INFO] |  +- org.junit.platform:junit-platform-engine:jar:1.3.2:test
[INFO] |  |  +- org.junit.platform:junit-platform-commons:jar:1.3.2:test
[INFO] |  |  \- org.opentest4j:opentest4j:jar:1.1.1:test
[INFO] |  \- org.junit.jupiter:junit-jupiter-api:jar:5.3.2:test
[INFO] +- com.h2database:h2:jar:1.4.199:test
[INFO] +- org.springframework.security:spring-security-test:jar:5.1.5.RELEASE:test
[INFO] +- org.dbunit:dbunit:jar:2.2:test
[INFO] |  +- junit:junit:jar:4.12:test
[INFO] |  +- junit-addons:junit-addons:jar:1.4:test
[INFO] |  |  +- xerces:xercesImpl:jar:2.6.2:test
[INFO] |  |  \- xerces:xmlParserAPIs:jar:2.6.2:test
[INFO] |  +- poi:poi:jar:2.5.1-final-20040804:test
[INFO] |  +- commons-collections:commons-collections:jar:3.1:test
[INFO] |  +- commons-lang:commons-lang:jar:2.1:test
[INFO] |  \- commons-logging:commons-logging:jar:1.0.4:test
[INFO] +- com.github.springtestdbunit:spring-test-dbunit:jar:1.3.0:test
[INFO] +- net.andreinc.mockneat:mockneat:jar:0.3.6:test
[INFO] |  +- org.apache.commons:commons-text:jar:1.6:compile
[INFO] |  +- com.github.mifmif:generex:jar:1.0.2:test
[INFO] |  |  \- dk.brics.automaton:automaton:jar:1.11-8:test
[INFO] |  +- net.andreinc.aleph:aleph-formatter:jar:0.1.0:test
[INFO] |  \- net.andreinc.markovneat:markovneat:jar:1.7:test
[INFO] +- io.reactivex.rxjava2:rxjava:jar:2.2.11:compile
[INFO] |  \- org.reactivestreams:reactive-streams:jar:1.0.2:compile
[INFO] +- com.squareup.retrofit2:retrofit:jar:2.6.1:compile
[INFO] +- com.squareup.retrofit2:adapter-rxjava2:jar:2.6.1:compile
[INFO] +- com.squareup.okhttp3:okhttp:jar:3.14.2:compile
[INFO] |  \- com.squareup.okio:okio:jar:1.17.2:compile
[INFO] \- com.squareup.okhttp3:logging-interceptor:jar:3.14.2:compile
[INFO] ------------------------------------------------------------------------
thiner commented 5 years ago

OK, I spent some time to google it. It seems the Azure storage SDK expects a specific SAXParser function, reset in this case. But system could not find a proper implementation which has this method. If this is the case, could you explicitly specify the jar which supports this method in your pom.xml file?

thiner commented 5 years ago

I found the root cause of my local error. It's caused by eclipse .classpath file in the project. It referenced a legacy xerces jar file. Although I can't find any jar dependency of that file in pom.xml. However, I think this is still a potential barrier of azure-storage SDK. It's better to explicitly wire a SAXParserImpl instance in your code.

rickle-msft commented 5 years ago

I think the reason we are not seeing the SAXParser come up in the dependency tree is because it's actually a JDK type, so it won't be listed. From what I can tell in the javadocs, it's not actually possible for us as the SDK to target a specific parser as it is intentionally designed to be dependent on the environment. The factory method that we call to get a parser, looks in the environment variables, config files, providers, and ultimately the system default. Unfortunately, I think this is up to the customer to define and configure in their environment. Please let me know if you interpret these docs differently.