search

googleapis / java-pubsub

Apache License 2.0
123 stars 88 forks source link

Incompatibility with java-logging-logback #1958

Open augi opened 3 months ago

augi commented 3 months ago

Environment details

  1. PubSub Java client seems to be incompatible with java-logging-logback.
  2. OS type and version: Windows, Linux
  3. Java version: 17
  4. version(s): 1.127.2, and v0.131.3-alpha

Steps to reproduce

Use both dependencies in one project.

Code example

implementation 'com.google.cloud:google-cloud-pubsub:1.127.2'
implementation 'com.google.cloud:google-cloud-logging-logback:0.131.3-alpha'
    <statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />
    <appender name="GcpLoggingAppender" class="com.google.cloud.logging.logback.LoggingAppender">
        <redirectToStdout>true</redirectToStdout>
    </appender>
    <root level="INFO">
        <appender-ref ref="GcpLoggingAppender" />
    </root>
Publisher.newBuilder(TopicName.of("my-project", "mytopic")).build()

Stack trace

java.lang.NoClassDefFoundError: Could not initialize class io.grpc.netty.shaded.io.grpc.netty.NettyChannelBuilder
    at io.grpc.netty.shaded.io.grpc.netty.NettyChannelProvider.builderForAddress(NettyChannelProvider.java:40)
    at io.grpc.netty.shaded.io.grpc.netty.NettyChannelProvider.builderForAddress(NettyChannelProvider.java:26)
    at io.grpc.ManagedChannelBuilder.forAddress(ManagedChannelBuilder.java:44)
    at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createSingleChannel(InstantiatingGrpcChannelProvider.java:404)
    at com.google.api.gax.grpc.ChannelPool.<init>(ChannelPool.java:107)
    at com.google.api.gax.grpc.ChannelPool.create(ChannelPool.java:85)
    at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createChannel(InstantiatingGrpcChannelProvider.java:243)
    at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.getTransportChannel(InstantiatingGrpcChannelProvider.java:237)
    at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:226)
    at com.google.cloud.pubsub.v1.stub.GrpcPublisherStub.create(GrpcPublisherStub.java:203)
    at com.google.cloud.pubsub.v1.Publisher.<init>(Publisher.java:202)
    at com.google.cloud.pubsub.v1.Publisher.<init>(Publisher.java:91)
    at com.google.cloud.pubsub.v1.Publisher$Builder.build(Publisher.java:889)
    at com.myproject.cloudsqltobigqueryshovel.Server$.$anonfun$run$1(Server.scala:31)
    at monix.eval.internal.TaskRunLoop$.startFull(TaskRunLoop.scala:88)
    at monix.eval.Task$.unsafeStartNow(Task.scala:4798)
    at monix.eval.internal.TaskBracket$BaseStart.apply(TaskBracket.scala:181)
    at monix.eval.internal.TaskBracket$BaseStart.apply(TaskBracket.scala:168)
    at monix.eval.internal.TaskRestartCallback.run(TaskRestartCallback.scala:65)
    at monix.execution.internal.Trampoline.monix$execution$internal$Trampoline$$immediateLoop(Trampoline.scala:66)
    at monix.execution.internal.Trampoline.startLoop(Trampoline.scala:32)
    at monix.execution.schedulers.TrampolineExecutionContext$JVMNormalTrampoline.super$startLoop(TrampolineExecutionContext.scala:142)
    at monix.execution.schedulers.TrampolineExecutionContext$JVMNormalTrampoline.$anonfun$startLoop$1(TrampolineExecutionContext.scala:142)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
    at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:94)
    at monix.execution.schedulers.TrampolineExecutionContext$JVMNormalTrampoline.startLoop(TrampolineExecutionContext.scala:142)
    at monix.execution.internal.Trampoline.execute(Trampoline.scala:40)
    at monix.execution.schedulers.TrampolineExecutionContext.execute(TrampolineExecutionContext.scala:57)
    at monix.execution.schedulers.BatchingScheduler.execute(BatchingScheduler.scala:50)
    at monix.execution.schedulers.BatchingScheduler.execute$(BatchingScheduler.scala:47)
    at monix.execution.schedulers.AsyncScheduler.execute(AsyncScheduler.scala:31)
    at monix.eval.internal.TaskRestartCallback.start(TaskRestartCallback.scala:56)
    at monix.eval.internal.TaskRunLoop$.executeAsyncTask(TaskRunLoop.scala:703)
    at monix.eval.internal.TaskRunLoop$.goAsyncForLightCB(TaskRunLoop.scala:731)
    at monix.eval.internal.TaskRunLoop$.startLight(TaskRunLoop.scala:366)
    at monix.eval.Task.runAsyncOptF(Task.scala:812)
    at monix.eval.internal.TaskEffect$.execute(TaskEffect.scala:58)
    at monix.eval.internal.TaskEffect$.$anonfun$runCancelable$1(TaskEffect.scala:51)
    at cats.effect.internals.IORunLoop$.step(IORunLoop.scala:254)
    at cats.effect.IO.unsafeRunTimed(IO.scala:338)
    at cats.effect.IO.unsafeRunSync(IO.scala:256)
    at cats.effect.SyncIO.unsafeRunSync(SyncIO.scala:51)
    at monix.eval.internal.TaskConversions$.$anonfun$toIO$1(TaskConversions.scala:42)
    at cats.effect.IO$.liftedTree1$1(IO.scala:1377)
    at cats.effect.IO$.$anonfun$cancelable$1(IO.scala:1377)
    at cats.effect.IO$.$anonfun$cancelable$1$adapted(IO.scala:1368)
    at cats.effect.internals.IOAsync$.$anonfun$apply$1(IOAsync.scala:37)
    at cats.effect.internals.IOAsync$.$anonfun$apply$1$adapted(IOAsync.scala:37)
    at cats.effect.internals.IORunLoop$RestartCallback.start(IORunLoop.scala:464)
    at cats.effect.internals.IORunLoop$.cats$effect$internals$IORunLoop$$loop(IORunLoop.scala:165)
    at cats.effect.internals.IORunLoop$RestartCallback.signal(IORunLoop.scala:480)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:501)
    at cats.effect.internals.IORunLoop$RestartCallback.apply(IORunLoop.scala:439)
    at cats.effect.internals.Callback$AsyncIdempotentCallback.run(Callback.scala:131)
    at cats.effect.internals.Trampoline.cats$effect$internals$Trampoline$$immediateLoop(Trampoline.scala:67)
    at cats.effect.internals.Trampoline.startLoop(Trampoline.scala:35)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.super$startLoop(TrampolineEC.scala:90)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.$anonfun$startLoop$1(TrampolineEC.scala:90)
    at scala.runtime.java8.JFunction0$mcV$sp.apply(JFunction0$mcV$sp.scala:18)
    at scala.concurrent.BlockContext$.withBlockContext(BlockContext.scala:94)
    at cats.effect.internals.TrampolineEC$JVMTrampoline.startLoop(TrampolineEC.scala:90)
    at cats.effect.internals.Trampoline.execute(Trampoline.scala:43)
    at cats.effect.internals.TrampolineEC.execute(TrampolineEC.scala:42)
    at cats.effect.internals.Callback$AsyncIdempotentCallback.apply(Callback.scala:137)
    at cats.effect.internals.Callback$AsyncIdempotentCallback.apply(Callback.scala:126)
    at cats.effect.Async$$anon$1.run(Async.scala:273)
    at java.base/java.util.concurrent.ForkJoinTask$RunnableExecuteAction.exec(ForkJoinTask.java:1395)
    at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
    at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
    at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
    at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
    at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)
Caused by: java.lang.ExceptionInInitializerError: Exception java.lang.NullPointerException: clazz [in thread "scala-execution-context-global-15"]
    at io.grpc.netty.shaded.io.netty.util.internal.ObjectUtil.checkNotNull(ObjectUtil.java:39)
    at io.grpc.netty.shaded.io.netty.channel.ReflectiveChannelFactory.<init>(ReflectiveChannelFactory.java:32)
    at io.grpc.netty.shaded.io.grpc.netty.NettyChannelBuilder.<clinit>(NettyChannelBuilder.java:85)
    at io.grpc.netty.shaded.io.grpc.netty.NettyChannelProvider.builderForAddress(NettyChannelProvider.java:40)
Caused by: java.lang.ExceptionInInitializerError: Exception java.lang.NullPointerException: clazz [in thread "scala-execution-context-global-15"]

    at io.grpc.netty.shaded.io.grpc.netty.NettyChannelProvider.builderForAddress(NettyChannelProvider.java:26)
    at io.grpc.ManagedChannelBuilder.forAddress(ManagedChannelBuilder.java:44)
    at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createSingleChannel(InstantiatingGrpcChannelProvider.java:404)
    at com.google.api.gax.grpc.ChannelPool.<init>(ChannelPool.java:107)
    at com.google.api.gax.grpc.ChannelPool.create(ChannelPool.java:85)
    at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createChannel(InstantiatingGrpcChannelProvider.java:243)
    at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.getTransportChannel(InstantiatingGrpcChannelProvider.java:237)
    at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:226)
    at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:149)
    at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.<init>(GrpcLoggingRpc.java:150)
    at com.google.cloud.logging.LoggingOptions$DefaultLoggingRpcFactory.create(LoggingOptions.java:66)
    at com.google.cloud.logging.LoggingOptions$DefaultLoggingRpcFactory.create(LoggingOptions.java:60)
    at com.google.cloud.ServiceOptions.getRpc(ServiceOptions.java:602)
    at com.google.cloud.logging.LoggingOptions.getLoggingRpcV2(LoggingOptions.java:153)
    at com.google.cloud.logging.LoggingImpl.<init>(LoggingImpl.java:130)
    at com.google.cloud.logging.LoggingOptions$DefaultLoggingFactory.create(LoggingOptions.java:51)
    at com.google.cloud.logging.LoggingOptions$DefaultLoggingFactory.create(LoggingOptions.java:46)
    at com.google.cloud.ServiceOptions.getService(ServiceOptions.java:582)
    at com.google.cloud.logging.logback.LoggingAppender.getLogging(LoggingAppender.java:424)
    at com.google.cloud.logging.logback.LoggingAppender.start(LoggingAppender.java:358)
    at ch.qos.logback.core.model.processor.AppenderModelHandler.postHandle(AppenderModelHandler.java:84)
    at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:257)
    at ch.qos.logback.core.model.processor.DefaultProcessor.secondPhaseTraverse(DefaultProcessor.java:253)
    at ch.qos.logback.core.model.processor.DefaultProcessor.traversalLoop(DefaultProcessor.java:90)
    at ch.qos.logback.core.model.processor.DefaultProcessor.process(DefaultProcessor.java:106)
    at ch.qos.logback.core.joran.GenericXMLConfigurator.processModel(GenericXMLConfigurator.java:208)
    at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:170)
    at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:122)
    at ch.qos.logback.core.joran.GenericXMLConfigurator.doConfigure(GenericXMLConfigurator.java:65)
    at ch.qos.logback.classic.util.DefaultJoranConfigurator.configureByResource(DefaultJoranConfigurator.java:68)
    at ch.qos.logback.classic.util.DefaultJoranConfigurator.configure(DefaultJoranConfigurator.java:35)
    at ch.qos.logback.classic.util.ContextInitializer.invokeConfigure(ContextInitializer.java:128)
    at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:103)
    at ch.qos.logback.classic.util.ContextInitializer.autoConfig(ContextInitializer.java:66)
    at ch.qos.logback.classic.spi.LogbackServiceProvider.initializeLoggerContext(LogbackServiceProvider.java:52)
    at ch.qos.logback.classic.spi.LogbackServiceProvider.initialize(LogbackServiceProvider.java:41)
    at org.slf4j.LoggerFactory.bind(LoggerFactory.java:196)
    at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:183)
    at org.slf4j.LoggerFactory.getProvider(LoggerFactory.java:486)
    at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:472)
    at io.grpc.netty.shaded.io.netty.util.internal.logging.Slf4JLoggerFactory.<init>(Slf4JLoggerFactory.java:42)
    at io.grpc.netty.shaded.io.netty.util.internal.logging.Slf4JLoggerFactory$NopInstanceHolder.<clinit>(Slf4JLoggerFactory.java:63)
    at io.grpc.netty.shaded.io.netty.util.internal.logging.Slf4JLoggerFactory.getInstanceWithNopCheck(Slf4JLoggerFactory.java:59)
    at io.grpc.netty.shaded.io.netty.util.internal.logging.InternalLoggerFactory.useSlf4JLoggerFactory(InternalLoggerFactory.java:62)
    at io.grpc.netty.shaded.io.netty.util.internal.logging.InternalLoggerFactory.newDefaultFactory(InternalLoggerFactory.java:42)
    at io.grpc.netty.shaded.io.netty.util.internal.logging.InternalLoggerFactory.getDefaultFactory(InternalLoggerFactory.java:111)
    at io.grpc.netty.shaded.io.netty.util.internal.logging.InternalLoggerFactory.getInstance(InternalLoggerFactory.java:134)
    at io.grpc.netty.shaded.io.netty.util.internal.logging.InternalLoggerFactory.getInstance(InternalLoggerFactory.java:127)
    at io.grpc.netty.shaded.io.netty.util.internal.PlatformDependent.<clinit>(PlatformDependent.java:81)
    at io.grpc.netty.shaded.io.netty.util.AsciiString.<init>(AsciiString.java:225)
    at io.grpc.netty.shaded.io.netty.util.AsciiString.<init>(AsciiString.java:212)
    at io.grpc.netty.shaded.io.netty.util.AsciiString.cached(AsciiString.java:1403)
    at io.grpc.netty.shaded.io.netty.util.AsciiString.<clinit>(AsciiString.java:48)
    at io.grpc.netty.shaded.io.grpc.netty.Utils.<clinit>(Utils.java:80)
    at io.grpc.netty.shaded.io.grpc.netty.UdsNettyChannelProvider.isAvailable(UdsNettyChannelProvider.java:35)
    at io.grpc.ManagedChannelRegistry$ManagedChannelPriorityAccessor.isAvailable(ManagedChannelRegistry.java:211)
    at io.grpc.ManagedChannelRegistry$ManagedChannelPriorityAccessor.isAvailable(ManagedChannelRegistry.java:207)
    at io.grpc.ServiceProviders.loadAll(ServiceProviders.java:68)
    at io.grpc.ManagedChannelRegistry.getDefaultRegistry(ManagedChannelRegistry.java:101)
    at io.grpc.ManagedChannelProvider.provider(ManagedChannelProvider.java:43)
    ... 70 more

External references such as API reference guides

Any additional information below

I checked that both dependencies use the same version of gRPC. There is no issue if we replace the GCP logging with plain stdout logging.

augi commented 3 months ago

Work around: Write a log message before the PubSub client is created. Looks like there is a race or chicken-egg at the startup.

michaelpri10 commented 2 weeks ago

I have been able to reproduce this and found a similar workaround that just by instantiating a logger using SLF4J, this error is not thrown. Example:

private static final Logger logger = LoggerFactory.getLogger(PublisherExample.class);

I'm not of the exact cause of the issue right now, but it seems to lie in a layer below the Pub/Sub client library. Some initial thoughts are that there is some dependency conflict, but I've been unable to find definitive evidence or a fix for that yet. WE will continue investigating, but currently using a workaround is the best option for this issue.