fix(logging): improve go core's debug logging (#227)

This commit adds some debug logging in various
components, and also modifies some tests so that
it's easy to enable debug logging when running
individual sets of tests.

Signed-off-by: Phil Adams <phil_adams@us.ibm.com>

core/authentication_error_test.go

@@ -1,3 +1,5 @@
+//go:build all || slow || auth
+
 package core
 
 // (C) Copyright IBM Corp. 2024.

core/authenticator_factory.go

@@ -1,6 +1,6 @@
 package core
 
-// (C) Copyright IBM Corp. 2019, 2023.
+// (C) Copyright IBM Corp. 2019, 2024.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -22,6 +22,7 @@ import (
 // GetAuthenticatorFromEnvironment instantiates an Authenticator using service properties
 // retrieved from external config sources.
 func GetAuthenticatorFromEnvironment(credentialKey string) (authenticator Authenticator, err error) {
+	GetLogger().Debug("Get authenticator from environment, key=%s\n", credentialKey)
 	properties, err := getServiceProperties(credentialKey)
 	if len(properties) == 0 {
 		return
@@ -71,5 +72,9 @@ func GetAuthenticatorFromEnvironment(credentialKey string) (authenticator Authen
 		)
 	}
 
+	if authenticator != nil {
+		GetLogger().Debug("Returning authenticator, type=%s\n", authenticator.AuthenticationType())
+	}
+
 	return
 }

core/authenticator_factory_test.go

@@ -2,7 +2,7 @@
 
 package core
 
-// (C) Copyright IBM Corp. 2019, 2023.
+// (C) Copyright IBM Corp. 2019, 2024.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -22,11 +22,17 @@ import (
 	"github.com/stretchr/testify/assert"
 )
 
+var (
+	// To enable debug logging during test execution, set this to "LevelDebug"
+	authFactoryTestLogLevel LogLevel = LevelError
+)
+
 // Note: the following functions are used from the config_utils_test.go file:
 // setTestEnvironment()
 // setTestVCAP()
 
 func TestGetAuthenticatorFromEnvironment1(t *testing.T) {
+	GetLogger().SetLogLevel(authFactoryTestLogLevel)
 	t.Setenv("IBM_CREDENTIALS_FILE", "../resources/my-credentials.env")
 
 	authenticator, err := GetAuthenticatorFromEnvironment("service-1")
@@ -133,6 +139,7 @@ func TestGetAuthenticatorFromEnvironment1(t *testing.T) {
 }
 
 func TestGetAuthenticatorFromEnvironment2(t *testing.T) {
+	GetLogger().SetLogLevel(authFactoryTestLogLevel)
 	setTestEnvironment(t)
 
 	authenticator, err := GetAuthenticatorFromEnvironment("service-1")
@@ -232,6 +239,7 @@ func TestGetAuthenticatorFromEnvironment2(t *testing.T) {
 }
 
 func TestGetAuthenticatorFromEnvironment3(t *testing.T) {
+	GetLogger().SetLogLevel(authFactoryTestLogLevel)
 	setTestVCAP(t)
 
 	authenticator, err := GetAuthenticatorFromEnvironment("service-1")

core/base_service.go

@@ -1,6 +1,6 @@
 package core
 
-// (C) Copyright IBM Corp. 2019, 2022.
+// (C) Copyright IBM Corp. 2019, 2024.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.
@@ -18,7 +18,6 @@ import (
 	"bytes"
 	"context"
 	"crypto/tls"
-	"crypto/x509"
 	"encoding/json"
 	"errors"
 	"fmt"
@@ -131,6 +130,8 @@ func (service *BaseService) Clone() *BaseService {
 
 // ConfigureService updates the service with external configuration values.
 func (service *BaseService) ConfigureService(serviceName string) error {
+	GetLogger().Debug("Configuring BaseService instance with service name: %s\n", serviceName)
+
 	// Try to load service properties from external config.
 	serviceProps, err := getServiceProperties(serviceName)
 	if err != nil {
@@ -144,7 +145,7 @@ func (service *BaseService) ConfigureService(serviceName string) error {
 
 		// URL
 		if url, ok := serviceProps[PROPNAME_SVC_URL]; ok && url != "" {
-			err := service.SetURL(url)
+			err := service.SetServiceURL(url)
 			if err != nil {
 				err = RepurposeSDKProblem(err, "set-url-fail")
 				return err
@@ -221,6 +222,7 @@ func (service *BaseService) SetServiceURL(url string) error {
 	}
 
 	service.Options.URL = url
+	GetLogger().Debug("Set service URL: %s\n", url)
 	return nil
 }
 
@@ -289,6 +291,7 @@ func (service *BaseService) DisableSSLVerification() {
 		// Disable server ssl cert & hostname verification.
 		tr.TLSClientConfig.InsecureSkipVerify = true // #nosec G402
 	}
+	GetLogger().Debug("Disabled SSL verification in HTTP client")
 }
 
 // IsSSLDisabled returns true if and only if the service's http.Client instance
@@ -332,11 +335,12 @@ func (service *BaseService) buildUserAgent() string {
 }
 
 // SetUserAgent sets the user agent value.
-func (service *BaseService) SetUserAgent(userAgentString string) {
-	if userAgentString == "" {
-		userAgentString = service.buildUserAgent()
+func (service *BaseService) SetUserAgent(userAgent string) {
+	if userAgent == "" {
+		userAgent = service.buildUserAgent()
 	}
-	service.UserAgent = userAgentString
+	service.UserAgent = userAgent
+	GetLogger().Debug("Set User-Agent: %s\n", userAgent)
 }
 
 // Request invokes the specified HTTP request and returns the response.
@@ -414,16 +418,17 @@ func (service *BaseService) Request(req *http.Request, result interface{}) (deta
 	}
 
 	// Invoke the request, then check for errors during the invocation.
+	GetLogger().Debug("Sending HTTP request message...")
 	var httpResponse *http.Response
 	httpResponse, err = service.Client.Do(req)
-
 	if err != nil {
 		if strings.Contains(err.Error(), SSL_CERTIFICATION_ERROR) {
 			err = fmt.Errorf(ERRORMSG_SSL_VERIFICATION_FAILED + "\n" + err.Error())
 		}
 		err = SDKErrorf(err, "", "no-connection-made", getComponentInfo())
 		return
 	}
+	GetLogger().Debug("Received HTTP response message, status code %d", httpResponse.StatusCode)
 
 	// If debug is enabled, then dump the response.
 	if GetLogger().IsLogLevelEnabled(LevelDebug) {
@@ -754,6 +759,7 @@ func (service *BaseService) EnableRetries(maxRetries int, maxRetryInterval time.
 		// Hang the retryable client off the base service via the "shim" client.
 		service.Client = client.StandardClient()
 	}
+	GetLogger().Debug("Enabled retries; maxRetries=%d, maxRetryInterval=%s\n", maxRetries, maxRetryInterval.String())
 }
 
 // DisableRetries will disable automatic retries in the service.
@@ -765,6 +771,8 @@ func (service *BaseService) DisableRetries() {
 		// the retryable client instance.
 		tr := service.Client.Transport.(*retryablehttp.RoundTripper)
 		service.Client = tr.Client.HTTPClient
+
+		GetLogger().Debug("Disabled retries\n")
 	}
 }
 
@@ -826,16 +834,46 @@ var (
 	// scheme specified in the URL is invalid. This error isn't typed
 	// specifically so we resort to matching on the error string.
 	schemeErrorRe = regexp.MustCompile(`unsupported protocol scheme`)
+
+	// A regular expression to match the error returned by net/http when a
+	// request header or value is invalid. This error isn't typed
+	// specifically so we resort to matching on the error string.
+	invalidHeaderErrorRe = regexp.MustCompile(`invalid header`)
+
+	// A regular expression to match the error returned by net/http when the
+	// TLS certificate is not trusted. This error isn't typed
+	// specifically so we resort to matching on the error string.
+	notTrustedErrorRe = regexp.MustCompile(`certificate is not trusted|certificate is signed by unknown authority`)
 )
 
 // IBMCloudSDKRetryPolicy provides a default implementation of the CheckRetry interface
 // associated with a retryablehttp.Client.
 // This function will return true if the specified request/response should be retried.
 func IBMCloudSDKRetryPolicy(ctx context.Context, resp *http.Response, err error) (bool, error) {
-	// This logic was adapted from go-relyablehttp.ErrorPropagatedRetryPolicy().
+	// This logic was adapted from go-retryablehttp.ErrorPropagatedRetryPolicy().
+
+	if GetLogger().IsLogLevelEnabled(LevelDebug) {
+		// Compile the details to be included in the debug message.
+		var details []string
+		if resp != nil {
+			details = append(details, fmt.Sprintf("status_code=%d", resp.StatusCode))
+			if resp.Request != nil {
+				details = append(details, fmt.Sprintf("method=%s", resp.Request.Method))
+				details = append(details, fmt.Sprintf("url=%s", resp.Request.URL.Redacted()))
+			}
+		}
+		if err != nil {
+			details = append(details, fmt.Sprintf("error=%s", err.Error()))
+		} else {
+			details = append(details, "error=nil")
+		}
+
+		GetLogger().Debug("Considering retry attempt; %s\n", strings.Join(details, ", "))
+	}
 
 	// Do not retry on a Context-related error (Canceled or DeadlineExceeded).
 	if ctx.Err() != nil {
+		GetLogger().Debug("No retry, Context error: %s\n", ctx.Err().Error())
 		return false, ctx.Err()
 	}
 
@@ -844,21 +882,35 @@ func IBMCloudSDKRetryPolicy(ctx context.Context, resp *http.Response, err error)
 		if v, ok := err.(*url.Error); ok {
 			// Don't retry if the error was due to too many redirects.
 			if redirectsErrorRe.MatchString(v.Error()) {
+				GetLogger().Debug("No retry, too many redirects: %s\n", v.Error())
 				return false, SDKErrorf(v, "", "too-many-redirects", getComponentInfo())
 			}
 
 			// Don't retry if the error was due to an invalid protocol scheme.
 			if schemeErrorRe.MatchString(v.Error()) {
+				GetLogger().Debug("No retry, invalid protocol scheme: %s\n", v.Error())
 				return false, SDKErrorf(v, "", "invalid-scheme", getComponentInfo())
 			}
 
+			// Don't retry if the error was due to an invalid header.
+			if invalidHeaderErrorRe.MatchString(v.Error()) {
+				GetLogger().Debug("No retry, invalid header: %s\n", v.Error())
+				return false, SDKErrorf(v, "", "invalid-header", getComponentInfo())
+			}
+
 			// Don't retry if the error was due to TLS cert verification failure.
-			if _, ok := v.Err.(x509.UnknownAuthorityError); ok {
+			if notTrustedErrorRe.MatchString(v.Error()) {
+				GetLogger().Debug("No retry, TLS certificate is not trusted: %s\n", v.Error())
+				return false, SDKErrorf(v, "", "cert-not-trusted", getComponentInfo())
+			}
+			if _, ok := v.Err.(*tls.CertificateVerificationError); ok {
+				GetLogger().Debug("No retry, TLS certificate validation error: %s\n", v.Error())
 				return false, SDKErrorf(v, "", "cert-failure", getComponentInfo())
 			}
 		}
 
 		// The error is likely recoverable so retry.
+		GetLogger().Debug("Retry will be attempted...")
 		return true, nil
 	}
 
@@ -867,9 +919,11 @@ func IBMCloudSDKRetryPolicy(ctx context.Context, resp *http.Response, err error)
 	// A 429 should be retryable.
 	// All codes in the 500's range except for 501 (Not Implemented) should be retryable.
 	if resp.StatusCode == 429 || (resp.StatusCode >= 500 && resp.StatusCode <= 599 && resp.StatusCode != 501) {
+		GetLogger().Debug("Retry will be attempted")
 		return true, nil
 	}
 
+	GetLogger().Debug("No retry for status code: %d\n")
 	return false, nil
 }
 
@@ -880,6 +934,8 @@ func IBMCloudSDKBackoffPolicy(min, max time.Duration, attemptNum int, resp *http
 	// Check for a Retry-After header.
 	if resp != nil {
 		if s, ok := resp.Header["Retry-After"]; ok {
+			GetLogger().Debug("Found Retry-After header: %s\n", s)
+
 			// First, try to parse the value as an integer (number of seconds to wait)
 			if sleep, err := strconv.ParseInt(s[0], 10, 64); err == nil {
 				return time.Second * time.Duration(sleep)
@@ -893,7 +949,6 @@ func IBMCloudSDKBackoffPolicy(min, max time.Duration, attemptNum int, resp *http
 				}
 				return sleep
 			}
-
 		}
 	}
 

core/base_service_retries_test.go

@@ -2,7 +2,7 @@
 
 package core
 
-// (C) Copyright IBM Corp. 2020, 2022.
+// (C) Copyright IBM Corp. 2020, 2024.
 //
 // Licensed under the Apache License, Version 2.0 (the "License");
 // you may not use this file except in compliance with the License.