Uploaded image for project: 'CDAP'
  1. CDAP
  2. CDAP-14223

Severe warning from dataproc client code

    XMLWordPrintableJSON

    Details

    • Release Notes:
      Fixed an issue, where Dataproc client was not being closed, resulting in verbose error logs.
    • Rank:
      1|i00h4v:

      Description

      I created a Dataproc file, and I have a pipeline associated with that profile. Within 2 seconds of running that profile, I see a SEVERE message from the Data

      2018-08-29 13:44:28,162 - INFO  [appfabric-executor-6:c.c.c.i.a.s.ProgramLifecycleService@301] - Attempt to run Workflow program DataPipelineWorkflow as user cdapitn
      2018-08-29 13:44:28,072 - INFO  [dataset.executor-executor-24:c.c.c.d.u.h.DefaultHBaseDDLExecutor@146] - Table 'cdap_system:owner.meta' created.
      2018-08-29 13:44:28,123 - INFO  [dataset.executor-executor-28:c.c.c.d.d.d.s.e.DatasetAdminService@95] - Creating dataset instance dataset:system.config.store.table, type meta: DatasetTypeMeta{name='co.cask.cdap.api.dataset.table.Table', modules=[DatasetModuleM
      eta{name='orderedTable-hbase', className='co.cask.cdap.data2.dataset2.module.lib.hbase.HBaseTableModule', jarLocation=null, jarLocationPath=null, types=[table, co.cask.cdap.api.dataset.table.Table], usesModules=[], usedByModules=[core, objectMappedTable, cube,
       usage, lineage, fieldLineage, queueDataset, app-fabric]}]}
      2018-08-29 13:44:28,158 - INFO  [dataset.executor-executor-15:c.c.c.d.u.h.DefaultHBaseDDLExecutor@146] - Table 'cdap_system:config.store.table' created.
      2018-08-29 13:44:28,788 - INFO  [dataset.service-executor-8:c.c.c.d.d.d.s.DatasetInstanceService@319] - Creating dataset system.program.heartbeat, type name: co.cask.cdap.api.dataset.table.Table, properties: {dataset.table.ttl=2592000}
      2018-08-29 13:44:28,796 - INFO  [dataset.executor-executor-5:c.c.c.d.d.d.s.e.DatasetAdminService@95] - Creating dataset instance dataset:system.program.heartbeat, type meta: DatasetTypeMeta{name='co.cask.cdap.api.dataset.table.Table', modules=[DatasetModuleMet
      a{name='orderedTable-hbase', className='co.cask.cdap.data2.dataset2.module.lib.hbase.HBaseTableModule', jarLocation=null, jarLocationPath=null, types=[table, co.cask.cdap.api.dataset.table.Table], usesModules=[], usedByModules=[core, objectMappedTable, cube, u
      sage, lineage, fieldLineage, queueDataset, app-fabric]}]}
      2018-08-29 13:44:28,961 - INFO  [dataset.executor-executor-5:c.c.c.d.u.h.DefaultHBaseDDLExecutor@146] - Table 'cdap_system:program.heartbeat' created.
      Aug 29, 2018 1:44:30 PM io.grpc.internal.ManagedChannelImpl$ManagedChannelReference cleanQueue
      SEVERE: *~*~*~ Channel io.grpc.internal.ManagedChannelImpl-1 for target dataproc.googleapis.com:443 was not shutdown properly!!! ~*~*~*
          Make sure to call shutdown()/shutdownNow() and awaitTermination().
      java.lang.RuntimeException: ManagedChannel allocation site
              at io.grpc.internal.ManagedChannelImpl$ManagedChannelReference.<init>(ManagedChannelImpl.java:1065)
              at io.grpc.internal.ManagedChannelImpl.<init>(ManagedChannelImpl.java:485)
              at io.grpc.internal.AbstractManagedChannelImplBuilder.build(AbstractManagedChannelImplBuilder.java:349)
              at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createSingleChannel(InstantiatingGrpcChannelProvider.java:185)
              at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.createChannel(InstantiatingGrpcChannelProvider.java:142)
              at com.google.api.gax.grpc.InstantiatingGrpcChannelProvider.getTransportChannel(InstantiatingGrpcChannelProvider.java:134)
              at com.google.api.gax.rpc.ClientContext.create(ClientContext.java:151)
              at com.google.cloud.dataproc.v1.stub.GrpcClusterControllerStub.create(GrpcClusterControllerStub.java:134)
              at com.google.cloud.dataproc.v1.stub.ClusterControllerStubSettings.createStub(ClusterControllerStubSettings.java:177)
              at com.google.cloud.dataproc.v1.ClusterControllerClient.<init>(ClusterControllerClient.java:147)
              at com.google.cloud.dataproc.v1.ClusterControllerClient.create(ClusterControllerClient.java:128)
              at co.cask.cdap.runtime.spi.provisioner.dataproc.DataProcClient.getClusterControllerClient(DataProcClient.java:202)
              at co.cask.cdap.runtime.spi.provisioner.dataproc.DataProcClient.fromConf(DataProcClient.java:117)
              at co.cask.cdap.runtime.spi.provisioner.dataproc.DataProcProvisioner.validateProperties(DataProcProvisioner.java:64)
              at co.cask.cdap.internal.provision.ProvisioningService.validateProperties(ProvisioningService.java:446)
              at co.cask.cdap.gateway.handlers.ProfileHttpHandler.validateProvisionerProperties(ProfileHttpHandler.java:282)
              at co.cask.cdap.gateway.handlers.ProfileHttpHandler.writeProfile(ProfileHttpHandler.java:253)
              at co.cask.cdap.gateway.handlers.ProfileHttpHandler.writeProfile(ProfileHttpHandler.java:164)
              at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
              at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
              at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
              at java.lang.reflect.Method.invoke(Method.java:498)
              at co.cask.http.internal.HttpMethodInfo.invoke(HttpMethodInfo.java:82)
              at co.cask.http.internal.HttpDispatcher.channelRead(HttpDispatcher.java:45)
              at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
              at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:38)
              at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:353)
              at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
              at io.netty.util.concurrent.NonStickyEventExecutorGroup$NonStickyOrderedEventExecutor.run(NonStickyEventExecutorGroup.java:245)
              at io.netty.util.concurrent.UnorderedThreadPoolEventExecutor$NonNotifyRunnable.run(UnorderedThreadPoolEventExecutor.java:277)
              at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
              at java.util.concurrent.FutureTask.run(FutureTask.java:266)
              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
              at java.lang.Thread.run(Thread.java:748)
      

       

      I am unsure if the cluster actually provisioned, but the program's status from CDAP's perspective remained in "Starting" for 10 minutes. This could mean that the run record is in "Pending" state for those 10 minutes.
      Then, when I tried to stop the program, I got:

      18/08/29 13:54:29 INFO producer.SyncProducer: Connected to <HOSTNAME_MASKED>:9092 for producing
      2018-08-29 13:54:29,834 - ERROR [provisioning-service-0:c.c.c.i.p.t.ProvisioningTask@103] - DEPROVISION task failed in REQUESTING_DELETE state for program run program_run:default.GCSToGCS.-SNAPSHOT.workflow.DataPipelineWorkflow.a6326bd1-ab91-11e8-9e45-42010ad20030.
      com.google.api.gax.rpc.FailedPreconditionException: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot delete cluster 'cdap-gcstogcs-a6326bd1-ab91-11e8-9e45-42010ad20030' while it has other pending delete operations.
              at com.google.api.gax.rpc.ApiExceptionFactory.createException(ApiExceptionFactory.java:59) ~[na:na]
              at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:72) ~[na:na]
              at com.google.api.gax.grpc.GrpcApiExceptionFactory.create(GrpcApiExceptionFactory.java:60) ~[na:na]
              at com.google.api.gax.grpc.GrpcExceptionCallable$ExceptionTransformingFuture.onFailure(GrpcExceptionCallable.java:95) ~[na:na]
              at com.google.api.core.ApiFutures$1.onFailure(ApiFutures.java:61) ~[na:na]
              at com.google.common.util.concurrent.Futures$4.run(Futures.java:1123) ~[com.google.guava.guava-13.0.1.jar:na]
              at com.google.common.util.concurrent.MoreExecutors$DirectExecutor.execute(MoreExecutors.java:435) ~[na:na]
              at com.google.common.util.concurrent.AbstractFuture.executeListener(AbstractFuture.java:900) ~[com.google.guava.guava-13.0.1.jar:na]
              at com.google.common.util.concurrent.AbstractFuture.complete(AbstractFuture.java:811) ~[com.google.guava.guava-13.0.1.jar:na]
              at com.google.common.util.concurrent.AbstractFuture.setException(AbstractFuture.java:675) ~[com.google.guava.guava-13.0.1.jar:na]
              at io.grpc.stub.ClientCalls$GrpcFuture.setException(ClientCalls.java:492) ~[na:na]
              at io.grpc.stub.ClientCalls$UnaryStreamToFuture.onClose(ClientCalls.java:467) ~[na:na]
              at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:41) ~[na:na]
              at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:684) ~[na:na]
              at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:41) ~[na:na]
              at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:392) ~[na:na]
              at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:475) ~[na:na]
              at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:63) ~[na:na]
              at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:557) ~[na:na]
              at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$600(ClientCallImpl.java:478) ~[na:na]
              at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:590) ~[na:na]
              at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37) ~[na:na]
              at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123) ~[na:na]
              at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) ~[na:1.8.0_161]
              at java.util.concurrent.FutureTask.run(FutureTask.java:266) ~[na:1.8.0_161]
              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) ~[na:1.8.0_161]
              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) ~[na:1.8.0_161]
              at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_161]
              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_161]
              at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_161]
      Caused by: io.grpc.StatusRuntimeException: FAILED_PRECONDITION: Cannot delete cluster 'cdap-gcstogcs-a6326bd1-ab91-11e8-9e45-42010ad20030' while it has other pending delete operations.
              at io.grpc.Status.asRuntimeException(Status.java:526) ~[na:na]
              ... 19 common frames omitted 

       

      I only noticed this happening once. I did not encounter the same issue running a pipeline with the same profile after this.

        Attachments

          Activity

            People

            • Assignee:
              ali.anwar Ali Anwar
              Reporter:
              ali.anwar Ali Anwar
            • Votes:
              0 Vote for this issue
              Watchers:
              1 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: