Details

    • Type: Bug
    • Status: Resolved
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: 5.1.0
    • Fix Version/s: 5.1.0
    • Component/s: App Fabric, Test
    • Labels:
    • Rank:
      1|i00grb:

      Description

      In some cases, the test case fails with:

      build	17-Aug-2018 20:56:20	Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 138.071 sec <<< FAILURE!
      build	17-Aug-2018 20:56:20	testDataStreamsPreviewRun(co.cask.cdap.datastreams.preview.PreviewDataStreamsTest)  Time elapsed: 133.087 sec  <<< ERROR!
      build	17-Aug-2018 20:56:20	java.util.concurrent.TimeoutException: Timeout occurred. Expected KILLED_BY_TIMER but found KILLED.
      build	17-Aug-2018 20:56:20		at co.cask.cdap.common.utils.Tasks.waitFor(Tasks.java:70)
      build	17-Aug-2018 20:56:20		at co.cask.cdap.common.utils.Tasks.waitFor(Tasks.java:91)
      build	17-Aug-2018 20:56:20		at co.cask.cdap.common.utils.Tasks.waitFor(Tasks.java:130)
      build	17-Aug-2018 20:56:20		at co.cask.cdap.datastreams.preview.PreviewDataStreamsTest.testDataStreamsPreviewRun(PreviewDataStreamsTest.java:145)
      

      However, in the logs, it can be seen that the pipeline was terminated because it reached the 1 minute mark:

      2018-08-17 20:54:15,327 - DEBUG [SparkListenerBus:c.c.c.a.r.s.SparkTransactionHandler@144] - Spark job ended: JobTransaction{jobId=1, stageIds=[1], transaction=null}
      2018-08-17 20:54:15,414 - DEBUG [SparkListenerBus:c.c.c.a.r.s.AbstractSparkExecutionContext$$anon$2$$anonfun$onJobStart$1@143] - Spark program=program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming, runId=adfc5c31-a25f-11e8-82c7-000000b127c9, jobId=2 starts without transaction
      2018-08-17 20:54:15,415 - DEBUG [SparkListenerBus:c.c.c.a.r.s.SparkTransactionHandler@110] - Spark job started: JobTransaction{jobId=2, stageIds=[2], transaction=null}
      2018-08-17 20:54:15,468 - DEBUG [SparkListenerBus:c.c.c.a.r.s.SparkTransactionHandler@144] - Spark job ended: JobTransaction{jobId=2, stageIds=[2], transaction=null}
      2018-08-17 20:55:06,463 - INFO  [Timer-0:c.c.c.i.a.p.DefaultPreviewRunner$2$1@168] - Stopping the preview since it has reached running time: 1 mins.
      2018-08-17 20:55:06,476 - TRACE [Timer-0:c.c.c.d.d.d.DatasetServiceClient@317] - Executing GET /v3/namespaces/system/data/datasets/app.meta
      2018-08-17 20:55:06,480 - TRACE [dataset.service-executor-6:c.c.c.d.d.d.s.DatasetInstanceHandler@104] - Received GET for /v3/namespaces/system/data/datasets/app.meta
      2018-08-17 20:55:06,480 - TRACE [dataset.service-executor-6:c.c.c.d.d.d.s.DatasetInstanceService@194] - Authorizing GET for dataset app.meta
      2018-08-17 20:55:06,480 - TRACE [dataset.service-executor-6:c.c.c.d.d.d.s.DatasetInstanceService@197] - Authorized GET for dataset app.meta
      2018-08-17 20:55:06,480 - TRACE [dataset.service-executor-6:c.c.c.d.d.d.s.DatasetInstanceService@204] - Retrieving instance metadata from cache for dataset app.meta
      2018-08-17 20:55:06,480 - TRACE [dataset.service-executor-6:c.c.c.d.d.d.s.DatasetInstanceService@206] - Retrieved instance metadata from cache for dataset app.meta
      2018-08-17 20:55:06,481 - TRACE [dataset.service-executor-6:c.c.c.d.d.d.s.DatasetInstanceHandler@109] - Responded to GET for /v3/namespaces/system/data/datasets/app.meta
      2018-08-17 20:55:06,483 - TRACE [Timer-0:c.c.c.d.d.d.DatasetServiceClient@319] - Executed GET /v3/namespaces/system/data/datasets/app.meta
      2018-08-17 20:55:06,488 - TRACE [Timer-0:c.c.c.i.a.r.AbstractProgramController@150] - Stop program program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming
      2018-08-17 20:55:06,490 - DEBUG [pcontroller-program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming-adfc5c31-a25f-11e8-82c7-000000b127c9:c.c.c.i.a.r.ProgramControllerServiceAdapter@73] - stopping controller service for program program_run:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming.adfc5c31-a25f-11e8-82c7-000000b127c9.
      2018-08-17 20:55:06,491 - DEBUG [pcontroller-program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming-adfc5c31-a25f-11e8-82c7-000000b127c9:c.c.c.a.r.s.SparkRuntimeService@383] - Stop requested for Spark Program SparkRuntimeContext{id=program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming, runId=adfc5c31-a25f-11e8-82c7-000000b127c9}
      2018-08-17 20:55:06,513 - ERROR [dispatcher-event-loop-0:o.a.s.Logging$class@74] - Deregistered receiver for stream 0: Stopped by driver
      2018-08-17 20:55:06,815 - DEBUG [SparkListenerBus:c.c.c.a.r.s.SparkTransactionHandler@144] - Spark job ended: JobTransaction{jobId=0, stageIds=[0], transaction=null}
      ...
      2018-08-17 20:55:08,358 - DEBUG [pcontroller-program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming-adfc5c31-a25f-11e8-82c7-000000b127c9:c.c.c.a.r.s.SparkRuntimeEnv$$anonfun$co$cask$cdap$app$runtime$spark$SparkRuntimeEnv$$createServerCloser$1$$anonfun$apply$10$$anonfun$apply$1@360] - Shutting down Server and ThreadPool used by Spark org.apache.spark.SparkContext@50219d71
      2018-08-17 20:55:08,414 - DEBUG [pcontroller-program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming-adfc5c31-a25f-11e8-82c7-000000b127c9:c.c.c.a.r.s.SparkRuntimeEnv$$anonfun$co$cask$cdap$app$runtime$spark$SparkRuntimeEnv$$createServerCloser$1$$anonfun$apply$10$$anonfun$apply$1@360] - Shutting down Server and ThreadPool used by Spark org.apache.spark.SparkContext@50219d71
      2018-08-17 20:55:08,464 - DEBUG [spark-submitter-DataStreamsSparkStreaming-adfc5c31-a25f-11e8-82c7-000000b127c9:c.c.c.a.r.s.s.AbstractSparkSubmitter@173] - SparkSubmit returned for program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming adfc5c31-a25f-11e8-82c7-000000b127c9
      2018-08-17 20:55:08,465 - INFO  [SparkRunnerDataStreamsSparkStreaming:c.c.c.a.r.s.SparkRuntimeService@351] - Spark program execution cancelled: SparkRuntimeContext{id=program:default.preview-1534539242457.-SNAPSHOT.spark.DataStreamsSparkStreaming, runId=adfc5c31-a25f-11e8-82c7-000000b127c9}
      2018-08-17 20:55:08,467 - INFO  [SparkRunnerDataStreamsSparkStreaming:c.c.c.d.DataStreamsSparkLauncher@168] - Pipeline 'preview-1534539242457' killed
      2018-08-17 20:55:08,472 - DEBUG [SparkRunnerDataStreamsSparkStreaming:c.c.c.a.r.s.SparkRuntimeService@892] - Running Spark shutdown hook org.apache.spark.util.SparkShutdownHookManager$$anon$2@7918547d 

      At the time of the kill, though, there are a bunch of exceptions from Spark (where the ... is). Attaching the full log for reference. It seems that

      • either the state is not correctly recorded due to those Spark errors
      • or the test case does not wait long enough for the state to be recorded

       

        Attachments

          Activity

            People

            • Assignee:
              yaojie Yaojie Feng
              Reporter:
              andreas Andreas Neumann
            • Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: