Log errors when retrying Diego requests (#4747)

Also use "{e.class} - {e.message}" consistently in log messages instead
of "{e.inspect}".

Author: philippthun

app/jobs/runtime/create_buildpack_installer.rb

@@ -22,7 +22,7 @@ def perform
 
           logger.info "Buildpack #{name} created and installed"
         rescue StandardError => e
-          logger.error("Buildpack #{name} failed to install or update. Error: #{e.inspect}")
+          logger.error("Buildpack #{name} failed to install or update. Error: #{e.class} - #{e.message}")
           raise e
         end
       end

app/jobs/runtime/update_buildpack_installer.rb

@@ -17,7 +17,7 @@ def perform
 
           logger.info "Buildpack #{name} updated"
         rescue StandardError => e
-          logger.error("Buildpack #{name} failed to update. Error: #{e.inspect}")
+          logger.error("Buildpack #{name} failed to update. Error: #{e.class} - #{e.message}")
           raise
         end
       end

lib/cloud_controller/routing_api/routing_api_client.rb

@@ -64,7 +64,7 @@ def to_router_group_objects(body)
     def token_info
       uaa_client.token_info
     rescue CF::UAA::BadResponse => e
-      logger.error("uaa request for token failed: #{e.inspect}")
+      logger.error("uaa request for token failed: #{e.class} - #{e.message}")
       raise UaaUnavailable
     end
 

lib/cloud_controller/uaa/uaa_client.rb

@@ -33,7 +33,7 @@ def get_clients(client_ids)
     def token_info
       token_issuer.client_credentials_grant
     rescue CF::UAA::NotFound, CF::UAA::BadTarget, CF::UAA::BadResponse => e
-      logger.error("UAA request for token failed: #{e.inspect}")
+      logger.error("UAA request for token failed: #{e.class} - #{e.message}")
       raise UaaUnavailable
     end
 
@@ -44,7 +44,7 @@ def users_for_ids(user_ids)
     def usernames_for_ids(user_ids)
       fetch_users(user_ids).transform_values { |user| user['username'] }
     rescue UaaUnavailable, CF::UAA::UAAError => e
-      logger.error("Failed to retrieve usernames from UAA: #{e.inspect}#{error_info_from_target_error(e)}")
+      logger.error("Failed to retrieve usernames from UAA: #{e.class} - #{e.message}#{error_info_from_target_error(e)}")
       {}
     end
 
@@ -56,7 +56,7 @@ def id_for_username(username, origin: nil)
       user = results['resources'].first
       user && user['id']
     rescue CF::UAA::UAAError => e
-      logger.error("Failed to retrieve user id from UAA: #{e.inspect}#{error_info_from_target_error(e)}")
+      logger.error("Failed to retrieve user id from UAA: #{e.class} - #{e.message}#{error_info_from_target_error(e)}")
       raise UaaUnavailable
     end
 
@@ -92,7 +92,7 @@ def origins_for_username(username)
 
       results['resources'].pluck('origin')
     rescue UaaUnavailable, CF::UAA::UAAError => e
-      logger.error("Failed to retrieve origins from UAA: #{e.inspect}#{error_info_from_target_error(e)}")
+      logger.error("Failed to retrieve origins from UAA: #{e.class} - #{e.message}#{error_info_from_target_error(e)}")
       raise UaaUnavailable
     end
 
@@ -104,14 +104,14 @@ def create_shadow_user(username, origin)
       { 'id' => e.info['user_id'] }
     rescue CF::UAA::BadResponse => e
       unless e.message == 'invalid status response: 429'
-        logger.error("UAA request for creating a user failed: #{e.inspect}")
+        logger.error("UAA request for creating a user failed: #{e.class} - #{e.message}")
         raise UaaUnavailable
       end
 
-      logger.warn("UAA request for creating a user ran into rate limits: #{e.inspect}")
+      logger.warn("UAA request for creating a user ran into rate limits: #{e.class} - #{e.message}")
       raise UaaRateLimited
     rescue CF::UAA::UAAError => e
-      logger.error("UAA request for creating a user failed: #{e.inspect}")
+      logger.error("UAA request for creating a user failed: #{e.class} - #{e.message}")
       raise UaaUnavailable
     end
 
@@ -128,15 +128,15 @@ def with_request_error_handling
       begin
         yield
       rescue CF::UAA::InvalidToken => e
-        logger.error("UAA request for token failed: #{e.inspect}")
+        logger.error("UAA request for token failed: #{e.class} - #{e.message}")
         raise
       rescue UaaUnavailable, CF::UAA::UAAError => e
         if Time.now.utc > retry_until
           logger.error('Unable to establish a connection to UAA, no more retries, raising an exception.')
           raise UaaUnavailable
         else
           sleep_time = [delay, max_delay].min
-          logger.error("Failed to retrieve details from UAA: #{e.inspect}#{error_info_from_target_error(e)}")
+          logger.error("Failed to retrieve details from UAA: #{e.class} - #{e.message}#{error_info_from_target_error(e)}")
           logger.info("Attempting to connect to the UAA. Total #{(retry_until - Time.now.utc).round(2)} seconds remaining. Next retry after #{sleep_time} seconds.")
           sleep(sleep_time)
           delay *= factor

lib/diego/client.rb

@@ -166,6 +166,7 @@ def with_request_error_handling
           raise RequestError.new(e.message)
         else
           sleep_time = [delay, max_delay].min
+          @logger.error("Request to the diego backend failed with error: #{e.class} - #{e.message}")
           @logger.info("Attempting to connect to the diego backend. Total #{(retry_until - Time.now.utc).round(2)} seconds remaining. Next retry after #{sleep_time} seconds.")
           sleep(sleep_time)
           delay *= factor

middleware/base_rate_limiter.rb

@@ -64,7 +64,7 @@ def increment(key, expires_in, logger)
 
           [count_str.to_i, ttl_int]
         rescue Redis::BaseError => e
-          logger.error("Redis error: #{e.inspect}")
+          logger.error("Redis error: #{e.class} - #{e.message}")
           [1, expires_in]
         end
       end

middleware/service_broker_rate_limiter.rb

@@ -70,15 +70,15 @@ def try_increment?(key, max_concurrent_requests, logger)
           @redis.decr(key)
           false
         rescue Redis::BaseError => e
-          logger.error("Redis error: #{e.inspect}")
+          logger.error("Redis error: #{e.class} - #{e.message}")
           true
         end
 
         def decrement(key, logger)
           count_str = @redis.decr(key)
           @redis.incr(key) if count_str.to_i < 0
         rescue Redis::BaseError => e
-          logger.error("Redis error: #{e.inspect}")
+          logger.error("Redis error: #{e.class} - #{e.message}")
         end
       end
     end

spec/diego/client_spec.rb

@@ -767,9 +767,10 @@ module Diego
               raise 'Error!'
             end
           end.to raise_error(RequestError, 'Error!')
+          expect(logger).to have_received(:error).with(/Request to the diego backend failed with error/)
           expect(logger).to have_received(:info).with(/Attempting to connect to the diego backend./)
           expect(logger).to have_received(:error).with(/Unable to establish a connection to diego backend/)
-          expect(logger).to have_received(:error).once
+          expect(logger).to have_received(:error).twice
           expect(logger).to have_received(:info).once
           expect(attempts).to eq(2)
         end

spec/unit/lib/uaa/uaa_client_spec.rb

@@ -231,7 +231,7 @@ module VCAP::CloudController
 
         it 'logs the error' do
           uaa_client.usernames_for_ids([userid_1])
-          expect(mock_logger).to have_received(:error).with("Failed to retrieve usernames from UAA: #{uaa_error.inspect}")
+          expect(mock_logger).to have_received(:error).with("Failed to retrieve usernames from UAA: #{uaa_error.class} - #{uaa_error.message}")
         end
 
         context 'TargetError with details' do
@@ -243,7 +243,7 @@ module VCAP::CloudController
 
           it 'logs the error details' do
             uaa_client.usernames_for_ids([userid_1])
-            expect(mock_logger).to have_received(:error).with("Failed to retrieve usernames from UAA: #<CF::UAA::TargetError: error response>, error_info: #{error_info}")
+            expect(mock_logger).to have_received(:error).with("Failed to retrieve usernames from UAA: CF::UAA::TargetError - error response, error_info: #{error_info}")
           end
         end
       end
@@ -519,7 +519,7 @@ module VCAP::CloudController
 
         it 'logs the error and raises UaaUnavailable' do
           expect { uaa_client.create_shadow_user('test-user@idp.local', 'idp.local') }.to raise_error(UaaUnavailable)
-          expect(mock_logger).to have_received(:error).with("UAA request for creating a user failed: #{uaa_error.inspect}")
+          expect(mock_logger).to have_received(:error).with("UAA request for creating a user failed: #{uaa_error.class} - #{uaa_error.message}")
         end
       end
 
@@ -535,7 +535,7 @@ module VCAP::CloudController
 
         it 'logs the error and raises UaaRateLimited' do
           expect { uaa_client.create_shadow_user('test-user@idp.local', 'idp.local') }.to raise_error(UaaRateLimited)
-          expect(mock_logger).to have_received(:warn).with("UAA request for creating a user ran into rate limits: #{uaa_error.inspect}")
+          expect(mock_logger).to have_received(:warn).with("UAA request for creating a user ran into rate limits: #{uaa_error.class} - #{uaa_error.message}")
         end
       end
 
@@ -551,7 +551,7 @@ module VCAP::CloudController
 
         it 'logs and raises the error' do
           expect { uaa_client.create_shadow_user('test-user@idp.local', 'idp.local') }.to raise_error(UaaUnavailable)
-          expect(mock_logger).to have_received(:error).with("UAA request for creating a user failed: #{uaa_error.inspect}")
+          expect(mock_logger).to have_received(:error).with("UAA request for creating a user failed: #{uaa_error.class} - #{uaa_error.message}")
         end
       end
     end
@@ -924,7 +924,7 @@ module VCAP::CloudController
           expect do
             uaa_client.origins_for_username(username)
           end.to raise_error(UaaUnavailable)
-          expect(mock_logger).to have_received(:error).with("Failed to retrieve origins from UAA: #{uaa_error.inspect}")
+          expect(mock_logger).to have_received(:error).with("Failed to retrieve origins from UAA: #{uaa_error.class} - #{uaa_error.message}")
         end
       end
     end