Uploaded image for project: 'CDAP'
  1. CDAP
  2. CDAP-7593 Event-driven schedulers
  3. CDAP-11538

Time triggers fire multiple times

    XMLWordPrintableJSON

    Details

    • Type: Sub-task
    • Status: Resolved
    • Priority: Major
    • Resolution: Won't Fix
    • Affects Version/s: 4.2.0
    • Fix Version/s: 4.2.0
    • Component/s: Scheduler, Test
    • Labels:
      None
    • Rank:
      1|i001nb:

      Description

      It appears that when a tome trigger fires, multiple notifications are sent to TMS. The logs are a little misleading, they should really state "emitting time notification for" instead of "execute program ...". But here is what I see in the logs when running TestFrameworkTestRun.testDeployWorkflowApp:

      2017-05-17 10:54:05,365 - DEBUG [main:c.c.c.i.a.r.s.s.DatasetBasedTimeScheduleStore$4@267] - Schedule: stored trigger with key DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:05,373 - DEBUG [scheduler-executor-0:c.c.c.i.a.r.s.DefaultSchedulerService$ScheduledJob@55] - Trying to run job DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow with trigger DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:05,373 - DEBUG [scheduler-executor-0:c.c.c.i.a.r.s.DefaultSchedulerService$ScheduledJob@70] - Schedule execute testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:06,003 - DEBUG [scheduler-executor-0:c.c.c.i.a.r.s.DefaultSchedulerService$ScheduledJob@55] - Trying to run job DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow with trigger DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:06,004 - DEBUG [scheduler-executor-0:c.c.c.i.a.r.s.DefaultSchedulerService$ScheduledJob@70] - Schedule execute testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:07,002 - DEBUG [scheduler-executor-0:c.c.c.i.a.r.s.DefaultSchedulerService$ScheduledJob@55] - Trying to run job DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow with trigger DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:07,002 - DEBUG [scheduler-executor-0:c.c.c.i.a.r.s.DefaultSchedulerService$ScheduledJob@70] - Schedule execute testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:08,004 - DEBUG [scheduler-executor-0:c.c.c.i.a.r.s.DefaultSchedulerService$ScheduledJob@55] - Trying to run job DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow with trigger DEFAULT.testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:08,004 - DEBUG [scheduler-executor-0:c.c.c.i.a.r.s.DefaultSchedulerService$ScheduledJob@70] - Schedule execute testspace:AppWithSchedule:-SNAPSHOT:WORKFLOW:SampleWorkflow:SampleSchedule
      2017-05-17 10:54:08,191 - INFO  [NettyHttpService STARTING:c.c.h.NettyHttpService@257] - Starting SampleWorkflow-workflow-driver http service on address localhost/127.0.0.1:0...
      2017-05-17 10:54:08,192 - INFO  [NettyHttpService STARTING:c.c.h.NettyHttpService@262] - Started SampleWorkflow-workflow-driver http service on address /127.0.0.1:61449
      2017-05-17 10:54:08,203 - INFO  [constraint-checker-task:c.c.c.s.ConstraintCheckerService$ConstraintCheckerThread@272] - Successfully started program program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow in schedule SampleSchedule.
      2017-05-17 10:54:08,219 - DEBUG [WorkflowDriver:c.c.c.i.a.r.w.WorkflowProgramController$1@78] - Workflow service workflow.testspace.AppWithSchedule.SampleWorkflow.adc76191-3b10-11e7-afc5-acde48001122 announced at /127.0.0.1:61449
      2017-05-17 10:54:08,220 - INFO  [WorkflowDriver:c.c.c.i.a.r.w.WorkflowDriver@561] - Starting workflow execution for 'SampleWorkflow' with Run id 'adc76191-3b10-11e7-afc5-acde48001122'
      2017-05-17 10:54:08,242 - INFO  [WorkflowDriver:c.c.c.t.a.AppWithSchedule$DummyAction@82] - Ran dummy action
      2017-05-17 10:54:08,438 - INFO  [NettyHttpService STARTING:c.c.h.NettyHttpService@257] - Starting SampleWorkflow-workflow-driver http service on address localhost/127.0.0.1:0...
      2017-05-17 10:54:08,440 - INFO  [NettyHttpService STARTING:c.c.h.NettyHttpService@262] - Started SampleWorkflow-workflow-driver http service on address /127.0.0.1:61453
      2017-05-17 10:54:08,442 - INFO  [constraint-checker-task:c.c.c.s.ConstraintCheckerService$ConstraintCheckerThread@272] - Successfully started program program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow in schedule SampleSchedule.
      2017-05-17 10:54:08,452 - DEBUG [WorkflowDriver:c.c.c.i.a.r.w.WorkflowProgramController$1@78] - Workflow service workflow.testspace.AppWithSchedule.SampleWorkflow.adf43df2-3b10-11e7-9209-acde48001122 announced at /127.0.0.1:61453
      2017-05-17 10:54:08,452 - INFO  [WorkflowDriver:c.c.c.i.a.r.w.WorkflowDriver@561] - Starting workflow execution for 'SampleWorkflow' with Run id 'adf43df2-3b10-11e7-9209-acde48001122'
      2017-05-17 10:54:08,461 - INFO  [WorkflowDriver:c.c.c.t.a.AppWithSchedule$DummyAction@82] - Ran dummy action
      2017-05-17 10:54:08,757 - INFO  [WorkflowDriver:c.c.c.i.a.r.w.WorkflowDriver@569] - Workflow 'SampleWorkflow' with run id 'adc76191-3b10-11e7-afc5-acde48001122' completed
      2017-05-17 10:54:08,759 - INFO  [NettyHttpService STOPPING:c.c.h.NettyHttpService@274] - Stopping SampleWorkflow-workflow-driver http service on address /127.0.0.1:61449...
      2017-05-17 10:54:08,765 - INFO  [NettyHttpService STOPPING:c.c.h.NettyHttpService@288] - Stopped SampleWorkflow-workflow-driver http service on address /127.0.0.1:61449
      2017-05-17 10:54:08,767 - DEBUG [WorkflowDriver:c.c.c.i.a.r.w.WorkflowProgramController$1@84] - Workflow service terminated from RUNNING. Un-registering service workflow.testspace.AppWithSchedule.SampleWorkflow.adc76191-3b10-11e7-afc5-acde48001122.
      2017-05-17 10:54:08,767 - DEBUG [WorkflowDriver:c.c.c.i.a.r.w.WorkflowProgramController$1@86] - Service workflow.testspace.AppWithSchedule.SampleWorkflow.adc76191-3b10-11e7-afc5-acde48001122 unregistered.
      2017-05-17 10:54:08,770 - DEBUG [pcontroller-program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow-adc76191-3b10-11e7-afc5-acde48001122:c.c.c.i.a.r.w.WorkflowProgramRunner$1@183] - Program program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow with run id adc76191-3b10-11e7-afc5-acde48001122 completed successfully.
      2017-05-17 10:54:08,785 - INFO  [dataset.service-executor-7:c.c.c.d.d.d.s.DatasetInstanceService@264] - Creating dataset system.workflow.stats, type name: co.cask.cdap.api.dataset.table.Table, properties: {}
      2017-05-17 10:54:08,786 - DEBUG [dataset.executor-executor-4:c.c.c.d.d.d.s.e.DatasetAdminOpHTTPHandler@210] - Propagating userId as andreas
      2017-05-17 10:54:08,787 - INFO  [dataset.executor-executor-4:c.c.c.d.d.d.s.e.DatasetAdminService@101] - Creating dataset instance dataset:system.workflow.stats, type meta: DatasetTypeMeta{name='co.cask.cdap.api.dataset.table.Table', modules=[DatasetModuleMeta{name='orderedTable-memory', className='co.cask.cdap.data2.dataset2.module.lib.inmemory.InMemoryTableModule', jarLocation=null, jarLocationPath=null, types=[table, co.cask.cdap.api.dataset.table.Table], usesModules=[], usedByModules=[core, objectMappedTable, cube, usage, lineage, app-fabric]}]}
      2017-05-17 10:54:08,787 - DEBUG [dataset.executor-executor-4:c.c.c.d.d.d.s.e.DatasetAdminService@272] - Using andreas user for dataset dataset:system.workflow.stats
      2017-05-17 10:54:08,800 - DEBUG [pcontroller-program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow-adc76191-3b10-11e7-afc5-acde48001122:c.c.c.a.r.AbstractProgramRuntimeService@433] - Removing RuntimeInfo: Workflow SampleWorkflow adc76191-3b10-11e7-afc5-acde48001122
      2017-05-17 10:54:08,801 - DEBUG [pcontroller-program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow-adc76191-3b10-11e7-afc5-acde48001122:c.c.c.a.r.AbstractProgramRuntimeService@436] - RuntimeInfo removed: RuntimeInfo{programId=program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow, twillRunId=null}
      2017-05-17 10:54:08,965 - INFO  [WorkflowDriver:c.c.c.i.a.r.w.WorkflowDriver@569] - Workflow 'SampleWorkflow' with run id 'adf43df2-3b10-11e7-9209-acde48001122' completed
      2017-05-17 10:54:08,966 - INFO  [NettyHttpService STOPPING:c.c.h.NettyHttpService@274] - Stopping SampleWorkflow-workflow-driver http service on address /127.0.0.1:61453...
      2017-05-17 10:54:08,966 - INFO  [NettyHttpService STOPPING:c.c.h.NettyHttpService@288] - Stopped SampleWorkflow-workflow-driver http service on address /127.0.0.1:61453
      2017-05-17 10:54:08,968 - DEBUG [WorkflowDriver:c.c.c.i.a.r.w.WorkflowProgramController$1@84] - Workflow service terminated from RUNNING. Un-registering service workflow.testspace.AppWithSchedule.SampleWorkflow.adf43df2-3b10-11e7-9209-acde48001122.
      2017-05-17 10:54:08,968 - DEBUG [WorkflowDriver:c.c.c.i.a.r.w.WorkflowProgramController$1@86] - Service workflow.testspace.AppWithSchedule.SampleWorkflow.adf43df2-3b10-11e7-9209-acde48001122 unregistered.
      2017-05-17 10:54:08,968 - DEBUG [pcontroller-program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow-adf43df2-3b10-11e7-9209-acde48001122:c.c.c.i.a.r.w.WorkflowProgramRunner$1@183] - Program program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow with run id adf43df2-3b10-11e7-9209-acde48001122 completed successfully.
      2017-05-17 10:54:08,979 - DEBUG [pcontroller-program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow-adf43df2-3b10-11e7-9209-acde48001122:c.c.c.a.r.AbstractProgramRuntimeService@433] - Removing RuntimeInfo: Workflow SampleWorkflow adf43df2-3b10-11e7-9209-acde48001122
      2017-05-17 10:54:08,979 - DEBUG [pcontroller-program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow-adf43df2-3b10-11e7-9209-acde48001122:c.c.c.a.r.AbstractProgramRuntimeService@436] - RuntimeInfo removed: RuntimeInfo{programId=program:testspace.AppWithSchedule.-SNAPSHOT.workflow.SampleWorkflow, twillRunId=null}
      2017-05-17 10:54:09,012 - INFO  [main:c.c.c.t.a.TestFrameworkTestRun@838] - workflowRuns = 2
      

      The workflow runs twice even though the schedule should only trigger once in a minute.

      Also, in the logs, I see at least 4 times "trying to run job..." messages, that means there are 4 notifications in TMS and if the test ran a little longer, it would probably start a few more runs.

      This tets case is flaky because of this: It later suspends the schedule and verifies that no more runs are started. But because these notifications are already in the TMS, the workflow sometimes gets started again and fails the test.

        Attachments

          Activity

            People

            • Assignee:
              mao Chengfeng Mao
              Reporter:
              andreas Andreas Neumann
            • Votes:
              0 Vote for this issue
              Watchers:
              2 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: