"RuntimeException: ManagedChannel allocation site exception" when cancelling a task

[1fish2]

Ryan got lots of exceptions like the following (always?) when cancelling a task.

SEVERE: *~*~*~ Channel ManagedChannelImpl{logId=14, target=logging.googleapis.com:443} was not shutdown properly!!! ~*~*~*
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:     Make sure to call shutdown()/shutdownNow() and wait until awaitTermination() returns true.
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]: java.lang.RuntimeException: ManagedChannel allocation site
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at io.grpc.internal.ManagedChannelOrphanWrapper$ManagedChannelReference.<init>(ManagedChannelOrphanWrapper.java:94)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:52)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at io.grpc.internal.ManagedChannelOrphanWrapper.<init>(ManagedChannelOrphanWrapper.java:43)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at io.grpc.internal.AbstractManagedChannelImplBuilder.build(AbstractManagedChannelImplBuilder.java:514)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createSingleChannel(InstantiatingGrpcChannelProvider.java:268)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createChannel(InstantiatingGrpcChannelProvider.java:185)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.getTransportChannel(InstantiatingGrpcChannelProvider.java:177)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:160)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:122)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.logging.spi.v2.GrpcLoggingRpc.<init>(GrpcLoggingRpc.java:132)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.logging.LoggingOptions$DefaultLoggingRpcFactory.create(LoggingOptions.java:61)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.logging.LoggingOptions$DefaultLoggingRpcFactory.create(LoggingOptions.java:55)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.ServiceOptions.getRpc(ServiceOptions.java:518)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.logging.LoggingOptions.getLoggingRpcV2(LoggingOptions.java:129)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.logging.LoggingImpl.<init>(LoggingImpl.java:109)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.logging.LoggingOptions$DefaultLoggingFactory.create(LoggingOptions.java:46)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.logging.LoggingOptions$DefaultLoggingFactory.create(LoggingOptions.java:41)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.google.cloud.ServiceOptions.getService(ServiceOptions.java:498)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at sisyphus.log$make_logger.invokeStatic(log.clj:42)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at sisyphus.log$make_logger.invoke(log.clj:38)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at sisyphus.log$tag.invokeStatic(log.clj:52)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at sisyphus.log$tag.invoke(log.clj:49)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at sisyphus.task$perform_task_BANG_.invokeStatic(task.clj:161)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at sisyphus.task$perform_task_BANG_.invoke(task.clj:144)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at sisyphus.core$sisyphus_handle_rabbit.invokeStatic(core.clj:96)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at sisyphus.core$sisyphus_handle_rabbit.invoke(core.clj:87)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at clojure.core$partial$fn__5824.invoke(core.clj:2626)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at langohr.consumers$create_default$fn__18449.invoke(consumers.clj:83)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at langohr.consumers.proxy$com.rabbitmq.client.DefaultConsumer$ff19274a.handleDelivery(Unknown Source)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.rabbitmq.client.impl.ConsumerDispatcher$5.run(ConsumerDispatcher.java:149)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at com.rabbitmq.client.impl.ConsumerWorkService$WorkPoolRunnable.run(ConsumerWorkService.java:104)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
Jul 23 17:55:12 sisyphus-jerry-0 bash[1016]:         at java.base/java.lang.Thread.run(Thread.java:834)

[1fish2]

Notes:

• This stack trace includes the code that allocates a Logging service instance. That can be a tough place to log an exception although in this case the calling stack frame is trying to push a new Logging on the stack, so it ought to be able to log to the current Logging.
• It's an unchecked RuntimeException. Not declared in the API.
• Was it recursively trying to push new Logging objects?
• I think this occurred on Ryan's local computer, not on GCE.
• I think the code can get by with a single, static Logging objects. I'll try that after digging into what the exception means.

[1fish2]

The Logging object implements AutoCloseable and we should call its .close() method when popping one off the stack. I'd add a try/finally but it turned out easier to push info outside of it, I'll switch to a single static instance.