Add logging of service metadata during instance create/update/delete

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}")
@@ -297,6 +311,13 @@ 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?
+      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}'."
+      )
+
       update_job = action.enqueue_update
       head :accepted, 'Location' => url_builder.build_url(path: "/v3/jobs/#{update_job.guid}")
     else
@@ -342,7 +363,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 +376,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,17 @@ def check_filtered_instances(*instances)
           )
         end
 
+        it 'logs the correct names when updating a managed service instance' 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
+
         describe 'the pollable job' do
           let(:broker_response) { { dashboard_url: 'http://new-dashboard.url' } }
           let(:broker_status_code) { 200 }
@@ -2970,6 +3004,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 +3024,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]))