Warn when a stop event is skipped for a task that was running

Cloud Controller skips the TASK_STOPPED usage event when a task finishes
with no start event on record. That is the right choice: a stop event
with no start event is a record consumers cannot use. But the skip has
always been silent, so nobody learns that a task's start record went
missing. Now, when the skip fires for a task that was RUNNING, log a
warning.

A task can only reach RUNNING through the state change that also writes
its TASK_STARTED event, in the same transaction. So a running task with
no start record means something deleted the record later: the
destructive v2 purge, or the events cleanup job of an older version,
which deleted the start events of long-running tasks. Someone should
find out which one happened, and the warning names the repair: run
'rake db:was_running_backfill'.

The warning fires only when the task was RUNNING, because only then is
it certain the task ran. A task canceled while still PENDING also passes
through CANCELING, so a CANCELING task with no start record may simply
never have run. Warning there would be noise.

The tasks sync spec created a task directly in RUNNING state with no
TASK_STARTED event and then completed it, which now triggers the warning
and fails the spec's strict logger double. It now creates the start
event, so the test data matches what production always has.

Author: joyvuu-dave

app/models/runtime/task_model.rb

@@ -159,13 +159,39 @@ def create_stop_event_if_needed
         Repositories::AppUsageEventRepository::TASK_WAS_RUNNING_EVENT_STATE
       ]
       started = app_usage_repo.find_by_task_and_state(task: self, state: start_evidence_states)
-      return if started.nil?
+      if started.nil?
+        warn_if_running_task_has_no_start_record
+        return
+      end
 
       create_stop_event
     end
 
     def create_stop_event
       Repositories::AppUsageEventRepository.new.create_from_task(self, 'TASK_STOPPED')
     end
+
+    # The skip above is silent. That is fine for a task that never ran. But a
+    # task can only reach RUNNING through the state change that also writes
+    # its TASK_STARTED event, in the same transaction. So a running task with
+    # no start record means something deleted the record later: the
+    # destructive v2 purge, or the events cleanup job of an older version
+    # that did not yet keep the start events of running tasks. Someone should
+    # find out which, so log a warning. We warn only for RUNNING because only
+    # RUNNING is certain: a task canceled while still PENDING also passes
+    # through CANCELING, so a CANCELING task may never have run.
+    def warn_if_running_task_has_no_start_record
+      state_before_stop = column_changed?(:state) ? initial_value(:state) : state
+      return unless state_before_stop == RUNNING_STATE
+
+      logger.warn("Not writing a TASK_STOPPED usage event for task #{guid}: the task was running but has no " \
+                  'TASK_STARTED or TASK_WAS_RUNNING usage event on record. This should not happen. Find out ' \
+                  "what deleted or purged the usage events, and run 'rake db:was_running_backfill' so the other " \
+                  'tasks that are still running get a baseline. (It cannot help this task; it is no longer running.)')
+    end
+
+    def logger
+      @logger ||= Steno.logger('cc.models.task')
+    end
   end
 end

spec/unit/lib/cloud_controller/diego/tasks_sync_spec.rb

@@ -351,6 +351,10 @@ def exceptions
           context 'and the newly started task completes before the iteration completes', isolation: :truncation do
             # Can't use transactions for isolation because we're using multiple threads
             let!(:cc_task) { create(:task_model, guid: 'some-task-guid', state: TaskModel::RUNNING_STATE) }
+            # A real running task always has a start event; without it, the
+            # update to SUCCEEDED skips the stop event and logs a warning that
+            # the strict logger double rejects.
+            let!(:cc_task_start_event) { create(:app_usage_event, task_guid: cc_task.guid, state: 'TASK_STARTED') }
             let(:bbs_tasks) { [] }
 
             before do

spec/unit/models/runtime/task_model_spec.rb

@@ -44,13 +44,29 @@ module VCAP::CloudController
 
         context 'when there is neither a TASK_STARTED event nor a TASK_WAS_RUNNING baseline' do
           let!(:start_event) { nil }
+          let(:fake_logger) { instance_double(Steno::Logger, info: nil, warn: nil, debug: nil, error: nil) }
+
+          before do
+            allow(Steno).to receive(:logger).and_return(fake_logger)
+          end
 
           it 'does not create a TASK_STOPPED event, since no consumer ever saw the task start' do
             task.update(state: TaskModel::SUCCEEDED_STATE)
 
             event = AppUsageEvent.find(task_guid: task.guid, state: 'TASK_STOPPED')
             expect(event).to be_nil
           end
+
+          it 'logs a warning, because a task that reached RUNNING must have had a start record once' do
+            task.update(state: TaskModel::SUCCEEDED_STATE)
+
+            expect(fake_logger).to have_received(:warn).with(
+              "Not writing a TASK_STOPPED usage event for task #{task.guid}: the task was running but has no " \
+              'TASK_STARTED or TASK_WAS_RUNNING usage event on record. This should not happen. Find out ' \
+              "what deleted or purged the usage events, and run 'rake db:was_running_backfill' so the other " \
+              'tasks that are still running get a baseline. (It cannot help this task; it is no longer running.)'
+            )
+          end
         end
       end
 
@@ -81,25 +97,52 @@ module VCAP::CloudController
 
           context 'when there is neither a TASK_STARTED event nor a TASK_WAS_RUNNING baseline' do
             let!(:start_event) { nil }
+            let(:fake_logger) { instance_double(Steno::Logger, info: nil, warn: nil, debug: nil, error: nil) }
+
+            before do
+              allow(Steno).to receive(:logger).and_return(fake_logger)
+            end
 
             it 'does not create a TASK_STOPPED event, since no consumer ever saw the task start' do
               task.update(state: TaskModel::FAILED_STATE)
 
               event = AppUsageEvent.find(task_guid: task.guid, state: 'TASK_STOPPED')
               expect(event).to be_nil
             end
+
+            it 'logs a warning, because a task that reached RUNNING must have had a start record once' do
+              task.update(state: TaskModel::FAILED_STATE)
+
+              expect(fake_logger).to have_received(:warn).with(
+                "Not writing a TASK_STOPPED usage event for task #{task.guid}: the task was running but has no " \
+                'TASK_STARTED or TASK_WAS_RUNNING usage event on record. This should not happen. Find out ' \
+                "what deleted or purged the usage events, and run 'rake db:was_running_backfill' so the other " \
+                'tasks that are still running get a baseline. (It cannot help this task; it is no longer running.)'
+              )
+            end
           end
         end
 
         context 'when the task is moving from the PENDING state' do
           let(:task) { create(:task_model, app: parent_app, state: TaskModel::PENDING_STATE) }
+          let(:fake_logger) { instance_double(Steno::Logger, info: nil, warn: nil, debug: nil, error: nil) }
+
+          before do
+            allow(Steno).to receive(:logger).and_return(fake_logger)
+          end
 
           it 'does not create a TASK_STOPPED event' do
             task.update(state: TaskModel::FAILED_STATE)
 
             event = AppUsageEvent.find(task_guid: task.guid, state: 'TASK_STOPPED')
             expect(event).to be_nil
           end
+
+          it 'does not log a warning, because a task that never ran is not supposed to have a start record' do
+            task.update(state: TaskModel::FAILED_STATE)
+
+            expect(fake_logger).not_to have_received(:warn)
+          end
         end
 
         context 'when the task is moving from the CANCELING state' do
@@ -131,13 +174,25 @@ module VCAP::CloudController
 
           context 'when the task does not have a TASK_STARTED event' do
             let!(:start_event) { nil }
+            let(:fake_logger) { instance_double(Steno::Logger, info: nil, warn: nil, debug: nil, error: nil) }
+
+            before do
+              allow(Steno).to receive(:logger).and_return(fake_logger)
+            end
 
             it 'does not create a TASK_STOPPED event' do
               task.update(state: TaskModel::FAILED_STATE)
 
               event = AppUsageEvent.find(task_guid: task.guid, state: 'TASK_STOPPED')
               expect(event).to be_nil
             end
+
+            it 'does not log a warning, because a task canceled while PENDING also passes through CANCELING, ' \
+               'so we cannot be sure this task ever ran' do
+              task.update(state: TaskModel::FAILED_STATE)
+
+              expect(fake_logger).not_to have_received(:warn)
+            end
           end
         end
 
@@ -203,24 +258,71 @@ module VCAP::CloudController
 
       context 'when the TASK_STARTED event has been pruned and a TASK_WAS_RUNNING baseline exists' do
         let!(:start_event) { create(:app_usage_event, task_guid: task.guid, state: 'TASK_WAS_RUNNING') }
+        let(:fake_logger) { instance_double(Steno::Logger, info: nil, warn: nil, debug: nil, error: nil) }
+
+        before do
+          allow(Steno).to receive(:logger).and_return(fake_logger)
+        end
 
         it 'still creates a TASK_STOPPED event' do
           task.destroy
 
           event = AppUsageEvent.find(task_guid: task.guid, state: 'TASK_STOPPED')
           expect(event).not_to be_nil
         end
+
+        it 'does not log a warning, because the stop event was written' do
+          task.destroy
+
+          expect(fake_logger).not_to have_received(:warn)
+        end
       end
 
       context 'when there is neither a TASK_STARTED event nor a TASK_WAS_RUNNING baseline' do
-        let(:task) { create(:task_model, app: parent_app, state: TaskModel::PENDING_STATE) }
         let!(:start_event) { nil }
+        let(:fake_logger) { instance_double(Steno::Logger, info: nil, warn: nil, debug: nil, error: nil) }
 
-        it 'does not create a TASK_STOPPED event, since no consumer ever saw the task start' do
-          task.destroy
+        before do
+          allow(Steno).to receive(:logger).and_return(fake_logger)
+        end
 
-          event = AppUsageEvent.find(task_guid: task.guid, state: 'TASK_STOPPED')
-          expect(event).to be_nil
+        context 'when the task is PENDING' do
+          let(:task) { create(:task_model, app: parent_app, state: TaskModel::PENDING_STATE) }
+
+          it 'does not create a TASK_STOPPED event, since no consumer ever saw the task start' do
+            task.destroy
+
+            event = AppUsageEvent.find(task_guid: task.guid, state: 'TASK_STOPPED')
+            expect(event).to be_nil
+          end
+
+          it 'does not log a warning, because a task that never ran is not supposed to have a start record' do
+            task.destroy
+
+            expect(fake_logger).not_to have_received(:warn)
+          end
+        end
+
+        context 'when the task is RUNNING' do
+          let(:task) { create(:task_model, app: parent_app, state: TaskModel::RUNNING_STATE) }
+
+          it 'does not create a TASK_STOPPED event, since no consumer ever saw the task start' do
+            task.destroy
+
+            event = AppUsageEvent.find(task_guid: task.guid, state: 'TASK_STOPPED')
+            expect(event).to be_nil
+          end
+
+          it 'logs a warning, because a task that reached RUNNING must have had a start record once' do
+            task.destroy
+
+            expect(fake_logger).to have_received(:warn).with(
+              "Not writing a TASK_STOPPED usage event for task #{task.guid}: the task was running but has no " \
+              'TASK_STARTED or TASK_WAS_RUNNING usage event on record. This should not happen. Find out ' \
+              "what deleted or purged the usage events, and run 'rake db:was_running_backfill' so the other " \
+              'tasks that are still running get a baseline. (It cannot help this task; it is no longer running.)'
+            )
+          end
         end
       end