search

Azure / azure-sdk-for-java

This repository is for active development of the Azure SDK for Java. For consumers of the SDK we recommend visiting our public developer docs at https://docs.microsoft.com/java/azure/ or our versioned developer docs at https://azure.github.io/azure-sdk-for-java.
MIT License
2.36k stars 2k forks source link

[BUG] Jackson afterburner warning messages are logged when creating CosmosClient #18215

Closed basclaessen closed 3 years ago

basclaessen commented 3 years ago

Describe the bug When creating a CosmosClient several Jackson afterburner warnings are logged.

To Reproduce Create a CosmosClient

Exception or Stack Trace

Dec 17, 2020 2:03:36 PM com.fasterxml.jackson.module.afterburner.deser.OptimizedSettableBeanProperty _reportProblem
WARNING: Disabling Afterburner deserialization for class com.azure.cosmos.implementation.clientTelemetry.AzureVMMetadata$Compute (field #2; mutator com.fasterxml.jackson.module.afterburner.deser.SettableStringMethodProperty), due to access error (type java.lang.IllegalAccessError, message=tried to access class com.azure.cosmos.implementation.clientTelemetry.AzureVMMetadata$Compute from class com.azure.cosmos.implementation.clientTelemetry.AzureVMMetadata$Compute$Access4JacksonDeserializere47f1822)

java.lang.IllegalAccessError: tried to access class com.azure.cosmos.implementation.clientTelemetry.AzureVMMetadata$Compute from class com.azure.cosmos.implementation.clientTelemetry.AzureVMMetadata$Compute$Access4JacksonDeserializere47f1822
    at com.azure.cosmos.implementation.clientTelemetry.AzureVMMetadata$Compute$Access4JacksonDeserializere47f1822.stringSetter(com/azure/cosmos/implementation/clientTelemetry/AzureVMMetadata$Compute$Access4JacksonDeserializer.java)
    at com.fasterxml.jackson.module.afterburner.deser.SettableStringMethodProperty.deserializeAndSet(SettableStringMethodProperty.java:53)
    at com.fasterxml.jackson.databind.deser.BeanDeserializer.deserialize(BeanDeserializer.java:257)
    at com.fasterxml.jackson.module.afterburner.deser.SuperSonicBeanDeserializer.deserialize(SuperSonicBeanDeserializer.java:155)
    at com.fasterxml.jackson.module.afterburner.deser.SettableObjectMethodProperty.deserializeAndSet(SettableObjectMethodProperty.java:47)
    at com.fasterxml.jackson.module.afterburner.deser.SuperSonicBeanDeserializer.deserialize(SuperSonicBeanDeserializer.java:159)
    at com.fasterxml.jackson.databind.ObjectMapper._readMapAndClose(ObjectMapper.java:4524)
    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3466)
    at com.fasterxml.jackson.databind.ObjectMapper.readValue(ObjectMapper.java:3434)
    at com.azure.cosmos.implementation.Utils.parse(Utils.java:597)
    at com.azure.cosmos.implementation.clientTelemetry.ClientTelemetry.lambda$loadAzureVmMetaData$3(ClientTelemetry.java:167)
    at reactor.core.publisher.FluxMapFuseable$MapFuseableConditionalSubscriber.onNext(FluxMapFuseable.java:273)
    at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1782)
    at reactor.core.publisher.MonoFlatMap$FlatMapInner.onNext(MonoFlatMap.java:241)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onNext(FluxPeek.java:192)
    at reactor.core.publisher.FluxHandle$HandleSubscriber.onNext(FluxHandle.java:112)
    at reactor.core.publisher.FluxMap$MapConditionalSubscriber.onNext(FluxMap.java:213)
    at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.onNext(FluxDoFinally.java:123)
    at reactor.core.publisher.FluxHandleFuseable$HandleFuseableSubscriber.onNext(FluxHandleFuseable.java:178)
    at reactor.core.publisher.FluxContextStart$ContextStartSubscriber.onNext(FluxContextStart.java:96)
    at reactor.core.publisher.Operators$MonoSubscriber.complete(Operators.java:1782)
    at reactor.core.publisher.MonoCollectList$MonoCollectListSubscriber.onComplete(MonoCollectList.java:121)
    at reactor.core.publisher.FluxPeek$PeekSubscriber.onComplete(FluxPeek.java:252)
    at reactor.core.publisher.FluxMap$MapSubscriber.onComplete(FluxMap.java:136)
    at reactor.netty.channel.FluxReceive.onInboundComplete(FluxReceive.java:374)
    at reactor.netty.channel.ChannelOperations.onInboundComplete(ChannelOperations.java:373)
    at reactor.netty.channel.ChannelOperations.terminate(ChannelOperations.java:429)
    at reactor.netty.http.client.HttpClientOperations.onInboundNext(HttpClientOperations.java:655)
    at reactor.netty.channel.ChannelOperationsHandler.channelRead(ChannelOperationsHandler.java:96)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.channel.CombinedChannelDuplexHandler$DelegatingChannelHandlerContext.fireChannelRead(CombinedChannelDuplexHandler.java:436)
    at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:324)
    at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:296)
    at io.netty.channel.CombinedChannelDuplexHandler.channelRead(CombinedChannelDuplexHandler.java:251)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357)
    at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365)
    at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919)
    at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166)
    at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:714)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:650)
    at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:576)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:493)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
    at java.lang.Thread.run(Thread.java:748)

Code Snippet

import com.azure.cosmos.CosmosAsyncClient;
import com.azure.cosmos.CosmosClientBuilder;

public class CosmosAfterburnerWarning {
    public static void main(String[] args) {
        String endpoint = "COSMOS_ENDPOINT";
        String key = "COSMOS_KEY";

        CosmosAsyncClient cosmosAsyncClient = new CosmosClientBuilder()
                .endpoint(endpoint)
                .key(key)
                .buildAsyncClient();
    }
}
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>cosmos.bug</groupId>
    <artifactId>afterburner.warning</artifactId>
    <version>0.0.1-SNAPSHOT</version>
    <dependencies>
        <dependency>
            <groupId>com.azure</groupId>
            <artifactId>azure-cosmos</artifactId>
            <version>4.9.0</version>
        </dependency>
    </dependencies>
</project>

Expected behavior This warning should not be logged

Setup (please complete the following information):

Additional context No additional context

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

ghost commented 3 years ago

Thanks for the feedback! We are routing this to the appropriate team for follow-up. cc @kushagraThapar, @anfeldma-ms

kushagraThapar commented 3 years ago

@moderakh - I recall you have been working on this issue. Seems like this is duplicate of earlier afterburner warning logs issue. Can you please take a look at this ?

moderakh commented 3 years ago

@kushagraThapar this is slightly different and coming from the new ClientTelemtry code because clientTelemetry.AzureVMMetadata$Compute is defined as private class and after burner can't serialize it. also clientTemetry.AzureVMMetadata should be annotated with @JsonSerialize

@simplynaveen20 could you add@JsonSerialize to clientTelemtry AzureVMMetadata and make the following class public: https://github.com/Azure/azure-sdk-for-java/blob/master/sdk/cosmos/azure-cosmos/src/main/java/com/azure/cosmos/implementation/clientTelemetry/AzureVMMetadata.java#L38

We shouldn't pass private classes to ObjectMapper.

simplynaveen20 commented 3 years ago

@basclaessen I tried this on Windows/Linux , still unable to see the warning log of jackson.module.afterburner . Can you please specify the exact environment specification like os, java type and version,log4j property file if we using it

basclaessen commented 3 years ago

@simplynaveen20 os: Microsoft Windows 10 Pro java: openjdk version "11.0.9.1" 2020-11-04 no log4j property file

executed command: mvn clean install exec:java -Dexec.mainClass="CosmosAfterburnerWarning"

basclaessen commented 3 years ago

@simplynaveen20 You can also use a maven docker image to reproduce the error: c:\local\cosmosafterburnerwarning is my local maven directory

docker run -it -v c:\local\cosmosafterburnerwarning:/usr/src/mymaven -w /usr/src/mymaven maven:3.6.3-jdk-11 mvn clean install exec:java -Dexec.mainClass="CosmosAfterburnerWarning"

When you still not see the afterburner warning it could maybe be cosmos endpoint related. I'm using a cosmos endpoint in western europe with a strong default consistency.

sesmyrnov commented 3 years ago

Team - I have noticed this bug error while testing private fork of YCSB benchmark with latest Cosmos JAVA SDK v 4.11 dependency (so presumably this is not fixed in 4.10+) so asking to re-open this bug per @moderakh to look at it. Below is the link to our fork of YCSB with latest 4.11 JAVA SDK - https://github.com/armaansood/YCSB

I was able to simulate the error running different workloads (including default workload $YCSB_HOME/workloads/workloada). Example $YCSB_HOME/bin/ycsb load azurecosmos -P $YCSB_HOME/workloads/workloada -P $YCSB_HOME/azurecosmos/conf/azurecosmos.properties

basclaessen commented 3 years ago

@moderakh The afterburner warning is not logged anymore when creating a cosmosClient when using version 4.12.0. The afterburner warning is now logged when the first cosmos exception occurs.

import com.azure.cosmos.CosmosAsyncClient;
import com.azure.cosmos.CosmosClientBuilder;

public class CosmosAfterburnerWarning {
    public static void main(String[] args) {
        String endpoint = "COSMOS_ENDPOINT";
        String key = "COSMOS_KEY";

        CosmosAsyncClient cosmosAsyncClient = new CosmosClientBuilder()
                .endpoint(endpoint)
                .key(key)
                .buildAsyncClient();

        //force an exception
        CosmosAsyncDatabase database = cosmosAsyncClient.getDatabase("non_existing_database");
        CosmosAsyncContainer container = database.getContainer("non_existing_container");
        container.readItem("itemId", new PartitionKey("partitionKey"), JsonNode.class).block();
    }
}
Feb 10, 2021 3:03:53 PM com.fasterxml.jackson.module.afterburner.ser.OptimizedBeanPropertyWriter _reportProblem
WARNING: Disabling Afterburner serialization for class com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics (field #0; mutator com.fasterxml.jackson.module.afterburner.ser.StringMethodPropertyWriter), due to access error (type java.lang.IllegalAccessError, message=failed to access class com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics from class com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics$Access4JacksonSerializer88dc76f3 (com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics is in unnamed module of loader 'app'; com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics$Access4JacksonSerializer88dc76f3 is in unnamed module of loader com.fasterxml.jackson.module.afterburner.util.MyClassLoader @4f2c9ba6))

java.lang.IllegalAccessError: failed to access class com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics from class com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics$Access4JacksonSerializer88dc76f3 (com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics is in unnamed module of loader 'app'; com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics$Access4JacksonSerializer88dc76f3 is in unnamed module of loader com.fasterxml.jackson.module.afterburner.util.MyClassLoader @4f2c9ba6)
    at com.azure.cosmos.ClientSideRequestStatistics$GatewayStatistics$Access4JacksonSerializer88dc76f3.stringGetter(com/azure/cosmos/ClientSideRequestStatistics$GatewayStatistics$Access4JacksonSerializer.java)
    at com.fasterxml.jackson.module.afterburner.ser.StringMethodPropertyWriter.serializeAsField(StringMethodPropertyWriter.java:44)
    at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:755)
    at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:178)
    at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.java:480)
    at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:319)
    at com.fasterxml.jackson.databind.ObjectMapper.writeValue(ObjectMapper.java:3056)
    at com.fasterxml.jackson.core.base.GeneratorBase.writeObject(GeneratorBase.java:388)
    at com.fasterxml.jackson.core.JsonGenerator.writeObjectField(JsonGenerator.java:1838)
    at com.azure.cosmos.ClientSideRequestStatistics$ClientSideRequestStatisticsSerializer.serialize(ClientSideRequestStatistics.java:311)
    at com.azure.cosmos.ClientSideRequestStatistics$ClientSideRequestStatisticsSerializer.serialize(ClientSideRequestStatistics.java:272)
    at com.fasterxml.jackson.databind.SerializerProvider.defaultSerializeValue(SerializerProvider.java:1119)
    at com.fasterxml.jackson.databind.node.POJONode.serialize(POJONode.java:115)
    at com.fasterxml.jackson.databind.node.ObjectNode.serialize(ObjectNode.java:328)
    at com.fasterxml.jackson.databind.ser.std.SerializableSerializer.serialize(SerializableSerializer.java:39)
    at com.fasterxml.jackson.databind.ser.std.SerializableSerializer.serialize(SerializableSerializer.java:20)
    at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.java:480)
    at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:319)
    at com.fasterxml.jackson.databind.ObjectMapper._writeValueAndClose(ObjectMapper.java:4407)
    at com.fasterxml.jackson.databind.ObjectMapper.writeValueAsString(ObjectMapper.java:3661)
    at com.azure.cosmos.CosmosException.toString(CosmosException.java:342)
    at java.base/java.lang.String.valueOf(String.java:2951)
    at java.base/java.io.PrintStream.println(PrintStream.java:897)
    at java.base/java.lang.Throwable$WrappedPrintStream.println(Throwable.java:752)
    at java.base/java.lang.Throwable.printStackTrace(Throwable.java:659)
    at java.base/java.lang.Throwable.printStackTrace(Throwable.java:648)
    at java.base/java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1059)
    at java.base/java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1050)
    at java.base/java.lang.Thread.dispatchUncaughtException(Thread.java:2002)
xinlian12 commented 3 years ago

@basclaessen This warning will be fixed in the next release. The release date is TBD currently, will update when the new sdk released.

basclaessen commented 3 years ago

@xinlian12 The warning is not fixed in release 4.13.0. I created #19847 to address this.