Add logging of service metadata during instance create/update/delete (#4386)

* Inform operators which service plan, offering and broker is involved in service instance creation/update/deletion

* Refactor service plan lookup to eager load service and broker associations

* simplify update managed with adding only 1 simple sql query

* use more specific joins for delete request

* Add tests for the log info

* Eager load associations of service instance

* Remove unnecessary reload of service_instance

Reloading the service_instance just ensures that follow-up preflight checks run with the original service instance values.
This can also be achieved by applying changes on a copy of the object. With that, we don't loose eagerly loaded associations and save a few DB queries.

* Further reduce DB queries

---------

Co-authored-by: Sven Krieger <[email protected]>

Author: kathap

app/actions/v3/service_instance_update_managed.rb

@@ -268,11 +268,12 @@ def raise_if_cannot_proceed!
       def raise_if_invalid_update!
         return unless message.updates.any?
 
-        service_instance.set(message.updates)
-        return service_instance.reload if service_instance.valid?
+        service_instance_copy = service_instance.dup
+        service_instance_copy.set(message.updates)
+        return if service_instance_copy.valid?
 
-        service_instance_name_errors = service_instance.errors.on(:name).to_a
-        service_plan_errors = service_instance.errors.on(:service_plan).to_a
+        service_instance_name_errors = service_instance_copy.errors.on(:name).to_a
+        service_plan_errors = service_instance_copy.errors.on(:service_plan).to_a
 
         if service_instance_name_errors.include?(:unique)
           raise UnprocessableUpdate.new_from_details('ServiceInstanceNameTaken', message.name)
@@ -282,7 +283,7 @@ def raise_if_invalid_update!
           raise UnprocessableUpdate.new_from_details('ServiceInstanceServicePlanNotAllowed')
         end
 
-        raise Sequel::ValidationFailed.new(service_instance)
+        raise Sequel::ValidationFailed.new(service_instance_copy)
       end
 
       def raise_if_renaming_shared_service_instance!

app/controllers/v3/service_instances_controller.rb

@@ -253,7 +253,11 @@ def create_user_provided(message)
   end
 
   def create_managed(message, space:)
-    service_plan = ServicePlan.first(guid: message.service_plan_guid)
+    service_plan_relations = ServicePlan.eager_graph(service: :service_broker).
+                             where(Sequel[:service_plans][:guid] => message.service_plan_guid).
+                             all
+    service_plan = service_plan_relations[0]
+
     service_plan_does_not_exist! unless service_plan
     service_plan_not_visible_to_user!(service_plan) unless visible_to_current_user?(plan: service_plan)
     unavailable_service_plan!(service_plan) unless service_plan_active?(service_plan)
@@ -270,6 +274,16 @@ def create_managed(message, space:)
         audit_hash: message.audit_hash
       )
 
+      service_name = service_plan.service.name
+      broker_name = service_plan.service.service_broker.name
+
+      logger.info(
+        "Creating managed service instance with name '#{instance.name}' " \
+        "using service plan '#{service_plan.name}' " \
+        "from service offering '#{service_name}' " \
+        "provided by broker '#{broker_name}'."
+      )
+
       pollable_job = Jobs::Enqueuer.new(queue: Jobs::Queues.generic).enqueue_pollable(provision_job)
 
       head :accepted, 'Location' => url_builder.build_url(path: "/v3/jobs/#{pollable_job.guid}")
@@ -296,8 +310,12 @@ def update_managed(service_instance)
 
     action = V3::ServiceInstanceUpdateManaged.new(service_instance, message, user_audit_info, message.audit_hash)
     action.preflight!
+
     if action.update_broker_needed?
+      # enqueue_update will reload the service instance and we loose the eagerly loaded associations
+      service_instance_with_eager_load = service_instance.dup
       update_job = action.enqueue_update
+      log_service_instance_update(message, service_instance_with_eager_load)
       head :accepted, 'Location' => url_builder.build_url(path: "/v3/jobs/#{update_job.guid}")
     else
       service_instance = action.update_sync
@@ -309,6 +327,26 @@ def update_managed(service_instance)
     raise CloudController::Errors::ApiError.new_from_details('AsyncServiceBindingOperationInProgress', e.service_binding.app.name, e.service_binding.service_instance.name)
   end
 
+  def log_service_instance_update(message, service_instance)
+    if message.service_plan_guid && message.service_plan_guid != service_instance.service_plan.guid
+      new_service_plan_name = ServicePlan.first(guid: message.service_plan_guid).name
+
+      logger.info(
+        "Updating managed service instance with name '#{service_instance.name}' " \
+        "changing plan from '#{service_instance.service_plan.name}' to '#{new_service_plan_name}' " \
+        "from service offering '#{service_instance.service_plan.service.label}' " \
+        "provided by broker '#{service_instance.service_plan.service.service_broker.name}'."
+      )
+    else
+      logger.info(
+        "Updating managed service instance with name '#{service_instance.name}' " \
+        "using service plan '#{service_instance.service_plan.name}' " \
+        "from service offering '#{service_instance.service_plan.service.label}' " \
+        "provided by broker '#{service_instance.service_plan.service.service_broker.name}'."
+      )
+    end
+  end
+
   def check_spaces_exist_and_are_writeable!(service_instance, request_guids, found_spaces)
     unreadable_spaces = found_spaces.reject { |s| can_read_from_space?(s) }
     unwriteable_spaces = found_spaces.reject { |s| (can_write_to_active_space?(s) && is_space_active?(s)) || unreadable_spaces.include?(s) }
@@ -342,7 +380,10 @@ def build_create_message(params)
   end
 
   def fetch_writable_service_instance(guid)
-    service_instance = ServiceInstance.first(guid:)
+    service_instances = ManagedServiceInstance.eager_graph(service_plan: { service: :service_broker }).where(Sequel[:service_instances][:guid] => guid).all
+    service_instance = service_instances[0] unless service_instances.empty?
+    service_instance = UserProvidedServiceInstance.first(guid:) if service_instance.nil?
+
     service_instance_not_found! unless service_instance && can_read_service_instance?(service_instance)
     unauthorized! unless can_write_to_active_space?(service_instance.space)
     suspended! unless is_space_active?(service_instance.space)
@@ -352,6 +393,18 @@ def fetch_writable_service_instance(guid)
 
   def enqueue_delete_job(service_instance)
     delete_job = V3::DeleteServiceInstanceJob.new(service_instance.guid, user_audit_info)
+
+    plan = service_instance.service_plan
+    service = plan.service
+    broker = service.service_broker
+
+    logger.info(
+      "Deleting managed service instance with name '#{service_instance.name}' " \
+      "using service plan '#{plan.name}' " \
+      "from service offering '#{service.label}' " \
+      "provided by broker '#{broker.name}'."
+    )
+
     pollable_job = Jobs::Enqueuer.new(queue: Jobs::Queues.generic).enqueue_pollable(delete_job)
     pollable_job.guid
   end

spec/request/service_instances_spec.rb

@@ -1080,6 +1080,12 @@ def check_filtered_instances(*instances)
       end
       let(:instance) { VCAP::CloudController::ServiceInstance.last }
       let(:job) { VCAP::CloudController::PollableJobModel.last }
+      let(:mock_logger) { instance_double(Steno::Logger, info: nil) }
+
+      before do
+        allow(Steno).to receive(:logger).and_call_original
+        allow(Steno).to receive(:logger).with('cc.api').and_return(mock_logger)
+      end
 
       it 'creates a service instance in the database' do
         api_call.call(space_dev_headers)
@@ -1107,6 +1113,17 @@ def check_filtered_instances(*instances)
         expect(job.resource_type).to eq('service_instances')
       end
 
+      it 'logs the correct names when creating a managed service instance' do
+        api_call.call(space_dev_headers)
+
+        expect(mock_logger).to have_received(:info).with(
+          "Creating managed service instance with name '#{instance.name}' " \
+          "using service plan '#{service_plan.name}' " \
+          "from service offering '#{service_plan.service.name}' " \
+          "provided by broker '#{service_plan.service.service_broker.name}'."
+        )
+      end
+
       context 'when the name has already been taken' do
         it 'fails when the same name is already used in this space' do
           VCAP::CloudController::ServiceInstance.make(name:, space:)
@@ -1847,6 +1864,12 @@ def check_filtered_instances(*instances)
           }
         end
         let(:job) { VCAP::CloudController::PollableJobModel.last }
+        let(:mock_logger) { instance_double(Steno::Logger, info: nil) }
+
+        before do
+          allow(Steno).to receive(:logger).and_call_original
+          allow(Steno).to receive(:logger).with('cc.api').and_return(mock_logger)
+        end
 
         it 'responds with a pollable job' do
           api_call.call(space_dev_headers)
@@ -1883,6 +1906,41 @@ def check_filtered_instances(*instances)
           )
         end
 
+        describe 'logging of updates' do
+          it 'logs info including the change of service plans' do
+            api_call.call(space_dev_headers)
+
+            expect(mock_logger).to have_received(:info).with(
+              "Updating managed service instance with name '#{service_instance.name}' " \
+              "changing plan from '#{original_service_plan.name}' to '#{new_service_plan.name}' " \
+              "from service offering '#{service_offering.name}' " \
+              "provided by broker '#{original_service_plan.service.service_broker.name}'."
+            )
+          end
+
+          context 'when service plan does not change' do
+            let(:request_body) do
+              {
+                parameters: {
+                  foo: 'bar',
+                  baz: 'qux'
+                }
+              }
+            end
+
+            it 'logs info accordingly' do
+              api_call.call(space_dev_headers)
+
+              expect(mock_logger).to have_received(:info).with(
+                "Updating managed service instance with name '#{service_instance.name}' " \
+                "using service plan '#{original_service_plan.name}' " \
+                "from service offering '#{service_offering.name}' " \
+                "provided by broker '#{original_service_plan.service.service_broker.name}'."
+              )
+            end
+          end
+        end
+
         describe 'the pollable job' do
           let(:broker_response) { { dashboard_url: 'http://new-dashboard.url' } }
           let(:broker_status_code) { 200 }
@@ -2970,6 +3028,12 @@ def check_filtered_instances(*instances)
                }).
           to_return(status: broker_status_code, body: broker_response.to_json, headers: {})
       end
+      let(:mock_logger) { instance_double(Steno::Logger, info: nil) }
+
+      before do
+        allow(Steno).to receive(:logger).and_call_original
+        allow(Steno).to receive(:logger).with('cc.api').and_return(mock_logger)
+      end
 
       it 'responds with job resource' do
         api_call.call(admin_headers)
@@ -2984,6 +3048,17 @@ def check_filtered_instances(*instances)
         expect(job.resource_type).to eq('service_instance')
       end
 
+      it 'logs the correct names when deleting a managed service instance' do
+        api_call.call(admin_headers)
+
+        expect(mock_logger).to have_received(:info).with(
+          "Deleting managed service instance with name '#{instance.name}' " \
+          "using service plan '#{instance.service_plan.name}' " \
+          "from service offering '#{instance.service_plan.service.name}' " \
+          "provided by broker '#{instance.service_plan.service.service_broker.name}'."
+        )
+      end
+
       describe 'the pollable job' do
         it 'sends a delete request with the right arguments to the service broker' do
           api_call.call(headers_for(user, scopes: %w[cloud_controller.admin]))

spec/unit/actions/v3/service_instance_update_managed_spec.rb

@@ -75,6 +75,28 @@ module V3
       end
 
       describe '#preflight!' do
+        context 'when changes were requested' do
+          let(:body) do
+            {
+              name: 'new-name',
+              relationships: {
+                service_plan: {
+                  data: {
+                    guid: new_plan.guid
+                  }
+                }
+              }
+            }
+          end
+
+          let(:new_plan) { ServicePlan.make(service: original_service_offering) }
+
+          it 'does not change the original service instance object' do
+            action.preflight!
+            expect(original_instance.changed_columns).not_to be_any
+          end
+        end
+
         describe 'invalid name updates' do
           context 'when the new name is already taken' do
             let(:instance_in_same_space) { ServiceInstance.make(space: original_instance.space) }