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

Cloud Controller has always skipped writing the TASK_STOPPED usage event
when a task finishes without a start event on record. The earlier
commits on this branch keep that rule and apply it on the destroy path
too. The skip is correct -- a stop event with no start event is a record
consumers cannot use -- but it has always been silent.

This commit does not fix a bug in the earlier commits. It surfaces
information about the long-standing skip: 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.

Author: joyvuu-dave

app/models/runtime/task_model.rb

@@ -155,13 +155,38 @@ 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. Run ' \
+                  "'rake db:was_running_backfill' and check whether usage events were deleted or purged.")
+    end
+
+    def logger
+      @logger ||= Steno.logger('cc.models.task')
+    end
   end
 end

spec/unit/models/runtime/task_model_spec.rb

@@ -44,13 +44,28 @@ 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. Run ' \
+              "'rake db:was_running_backfill' and check whether usage events were deleted or purged."
+            )
+          end
         end
       end
 
@@ -81,25 +96,51 @@ 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. Run ' \
+                "'rake db:was_running_backfill' and check whether usage events were deleted or purged."
+              )
+            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 +172,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 +256,70 @@ 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. Run ' \
+              "'rake db:was_running_backfill' and check whether usage events were deleted or purged."
+            )
+          end
         end
       end