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

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 <[email protected]>

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"
@@ -221,6 +220,7 @@ func (service *BaseService) SetServiceURL(url string) error {
 	}
 
 	service.Options.URL = url
+	GetLogger().Debug("Set service URL: %s\n", url)
 	return nil
 }
 
@@ -289,6 +289,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 +333,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 +416,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) {
@@ -730,6 +733,8 @@ func isRetryableClient(client *http.Client) bool {
 //     individual requests within the retry logic
 //   - Result: Each request is invoked such that the automatic retry logic is employed
 func (service *BaseService) EnableRetries(maxRetries int, maxRetryInterval time.Duration) {
+	GetLogger().Debug("Enabling retries; maxRetries=%d, maxRetryInterval=%s\n", maxRetries, maxRetryInterval.String())
+
 	if isRetryableClient(service.Client) {
 		// If retries are already enabled, then we just need to adjust
 		// the retryable client's config using "maxRetries" and "maxRetryInterval".
@@ -826,6 +831,16 @@ 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`)
 )
 
 // IBMCloudSDKRetryPolicy provides a default implementation of the CheckRetry interface
@@ -834,8 +849,28 @@ var (
 func IBMCloudSDKRetryPolicy(ctx context.Context, resp *http.Response, err error) (bool, error) {
 	// This logic was adapted from go-relyablehttp.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 +879,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 +916,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 +931,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 +946,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.