From 87bca0167c1320cc6db2e572814b14d8a2fc5017 Mon Sep 17 00:00:00 2001 From: Phil Adams Date: Fri, 16 Aug 2024 15:46:29 -0500 Subject: [PATCH] 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 --- core/authentication_error_test.go | 2 + core/authenticator_factory.go | 7 ++- core/authenticator_factory_test.go | 10 +++- core/base_service.go | 70 +++++++++++++++++++--- core/base_service_retries_test.go | 2 +- core/base_service_test.go | 79 +++++++++++++++++++++++-- core/basic_authenticator.go | 15 ++--- core/basic_authenticator_test.go | 6 ++ core/bearer_token_authenticator.go | 9 +-- core/bearer_token_authenticator_test.go | 6 ++ core/common_test.go | 4 +- core/config_utils.go | 4 ++ core/config_utils_test.go | 15 +++++ core/container_authenticator.go | 1 + core/cp4d_authenticator.go | 5 ++ core/file_with_metadata_test.go | 4 +- core/http_problem_test.go | 2 + core/iam_authenticator.go | 9 ++- core/ibm_problem_test.go | 2 + core/mcsp_authenticator.go | 5 ++ core/mcsp_authenticator_test.go | 5 +- core/ordered_maps_test.go | 2 + core/parameterized_url.go | 2 + core/problem_utils_test.go | 2 + core/sdk_problem_test.go | 4 +- core/vpc_instance_authenticator.go | 1 + core/vpc_instance_authenticator_test.go | 2 +- 27 files changed, 239 insertions(+), 36 deletions(-) diff --git a/core/authentication_error_test.go b/core/authentication_error_test.go index 0bc22d1..b95abda 100644 --- a/core/authentication_error_test.go +++ b/core/authentication_error_test.go @@ -1,3 +1,5 @@ +//go:build all || slow || auth + package core // (C) Copyright IBM Corp. 2024. diff --git a/core/authenticator_factory.go b/core/authenticator_factory.go index 455fba0..cd1a63c 100644 --- a/core/authenticator_factory.go +++ b/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 } diff --git a/core/authenticator_factory_test.go b/core/authenticator_factory_test.go index c82a40d..fb9ca16 100644 --- a/core/authenticator_factory_test.go +++ b/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") diff --git a/core/base_service.go b/core/base_service.go index 6a9f85a..3866fa4 100644 --- a/core/base_service.go +++ b/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,9 +416,9 @@ 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()) @@ -424,6 +426,7 @@ func (service *BaseService) Request(req *http.Request, result interface{}) (deta 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 } - } } diff --git a/core/base_service_retries_test.go b/core/base_service_retries_test.go index 5f6d517..1d85f2d 100644 --- a/core/base_service_retries_test.go +++ b/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. diff --git a/core/base_service_test.go b/core/base_service_test.go index 17ae524..fa60df2 100644 --- a/core/base_service_test.go +++ b/core/base_service_test.go @@ -2,7 +2,7 @@ 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. @@ -34,6 +34,11 @@ import ( "github.com/stretchr/testify/assert" ) +var ( + // To enable debug logging during test execution, set this to "LevelDebug" + basesvcAuthTestLogLevel LogLevel = LevelError +) + // getRetryableHTTPClient returns the "retryable" Client hidden inside the specified http.Client instance // or nil if "client" is not hiding a retryable Client instance. func getRetryableHTTPClient(client *http.Client) *retryablehttp.Client { @@ -50,6 +55,7 @@ func getRetryableHTTPClient(client *http.Client) *retryablehttp.Client { } func TestClone(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) var service *BaseService = nil var err error @@ -77,7 +83,8 @@ func TestClone(t *testing.T) { } // Test a normal JSON-based response. -func TestRequestGoodResponseJSON(t *testing.T) { +func TestCloneRequestGoodResponseJSON(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") w.WriteHeader(http.StatusCreated) @@ -121,7 +128,8 @@ func TestRequestGoodResponseJSON(t *testing.T) { } // Test a normal JSON-based response using a vendor-specific Content-Type -func TestRequestGoodResponseCustomJSONContentType(t *testing.T) { +func TestCloneRequestGoodResponseCustomJSONContentType(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) customContentType := "application/vnd.sdksquad.custom.semantics+json;charset=UTF8" server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", customContentType) @@ -166,7 +174,8 @@ func TestRequestGoodResponseCustomJSONContentType(t *testing.T) { } // Test a JSON-based response that should be returned as a stream (io.ReadCloser). -func TestRequestGoodResponseJSONStream(t *testing.T) { +func TestCloneRequestGoodResponseJSONStream(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") w.WriteHeader(http.StatusCreated) @@ -219,7 +228,8 @@ func TestRequestGoodResponseJSONStream(t *testing.T) { } // Verify that extra fields in result are silently ignored. -func TestRequestGoodResponseJSONExtraFields(t *testing.T) { +func TestCloneRequestGoodResponseJSONExtraFields(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-Type", "application/json") w.WriteHeader(http.StatusOK) @@ -251,6 +261,7 @@ func TestRequestGoodResponseJSONExtraFields(t *testing.T) { // Test a binary response. func TestRequestGoodResponseStream(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) expectedResponse := []byte("This is an octet stream response.") server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/octet-stream") @@ -291,6 +302,7 @@ func TestRequestGoodResponseStream(t *testing.T) { // Test a text response. func TestRequestGoodResponseText(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) expectedResponse := "This is a text response." server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "text/plain") @@ -327,6 +339,7 @@ func TestRequestGoodResponseText(t *testing.T) { // Test a string response. func TestRequestGoodResponseString(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) expectedBytes := []byte("This is a string response.") expectedResponse := string(expectedBytes) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { @@ -370,6 +383,7 @@ func TestRequestGoodResponseString(t *testing.T) { // Test a non-JSON response with no Content-Type set. func TestRequestGoodResponseNonJSONNoContentType(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) expectedResponse := []byte("This is a non-json response.") server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "") @@ -410,6 +424,7 @@ func TestRequestGoodResponseNonJSONNoContentType(t *testing.T) { // Test a JSON response with no Content-Type set. func TestRequestGoodResponseByteSliceNoContentType(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) expectedResponse := []byte("This is a non-json response.") server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "") @@ -445,6 +460,7 @@ func TestRequestGoodResponseByteSliceNoContentType(t *testing.T) { // Test unexpected response content. func TestRequestUnexpectedResponse(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) expectedResponse := []byte("This is an unexpected response.") server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "") @@ -478,6 +494,7 @@ func TestRequestUnexpectedResponse(t *testing.T) { // Test a JSON response that causes a deserialization error. func TestRequestGoodResponseJSONDeserFailure(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") fmt.Fprint(w, `{"name": {"unknown_object_id": "abc123"}}`) @@ -508,6 +525,7 @@ func TestRequestGoodResponseJSONDeserFailure(t *testing.T) { } func TestRequestNoAuthenticatorFailure(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) builder := NewRequestBuilder("GET") _, err := builder.ResolveRequestURL("https://myservice.ibm.com/api", "", nil) assert.Nil(t, err) @@ -529,6 +547,7 @@ func TestRequestNoAuthenticatorFailure(t *testing.T) { // Test a good response with no response body. func TestRequestGoodResponseNoBody(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusCreated) })) @@ -563,6 +582,7 @@ func TestRequestGoodResponseNoBody(t *testing.T) { // Test a good response with unexpected response body. func TestRequestGoodResponseUnexpectedBody(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") w.WriteHeader(http.StatusCreated) @@ -598,6 +618,7 @@ func TestRequestGoodResponseUnexpectedBody(t *testing.T) { // Test request with result that receives a good response with no response body. func TestRequestWithResultGoodResponseNoBody(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusCreated) })) @@ -634,6 +655,7 @@ func TestRequestWithResultGoodResponseNoBody(t *testing.T) { // Test request with result that receives a good response with no response body and JSON content-type. func TestRequestWithResultGoodResponseNoBodyJSONObject(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") w.WriteHeader(http.StatusCreated) @@ -670,6 +692,7 @@ func TestRequestWithResultGoodResponseNoBodyJSONObject(t *testing.T) { // Test request with result that receives a good response with no response body and JSON content-type. func TestRequestWithResultGoodResponseNoBodyJSONArray(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") w.WriteHeader(http.StatusCreated) @@ -706,6 +729,7 @@ func TestRequestWithResultGoodResponseNoBodyJSONArray(t *testing.T) { // Test request with result that receives a good response with no response body and JSON content-type. func TestRequestWithResultGoodResponseNoBodyString(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "text/plain") w.WriteHeader(http.StatusCreated) @@ -742,6 +766,7 @@ func TestRequestWithResultGoodResponseNoBodyString(t *testing.T) { // Test request with result that receives a good response with an empty object body. func TestRequestWithResultGoodResponseEmptyObjectBody(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") w.WriteHeader(http.StatusCreated) @@ -779,6 +804,7 @@ func TestRequestWithResultGoodResponseEmptyObjectBody(t *testing.T) { // Test request with result that receives a good response with an empty array body and JSON content-type. func TestRequestGoodResponseEmptyArrayBody(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") w.WriteHeader(http.StatusCreated) @@ -855,6 +881,7 @@ var nonJSONErrorResponse string = `This is a non-JSON error response body.` // Test an error response with a JSON response body. func TestRequestErrorResponseJSON(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") w.WriteHeader(http.StatusBadRequest) @@ -890,6 +917,7 @@ func TestRequestErrorResponseJSON(t *testing.T) { // Test an error response with an invalid JSON response body. func TestRequestErrorResponseJSONDeserError(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) var expectedResponse = []byte(`"{"this is a malformed": "json object".......`) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") @@ -923,6 +951,7 @@ func TestRequestErrorResponseJSONDeserError(t *testing.T) { // Test error response with a non-JSON response body. func TestRequestErrorResponseNotJSON(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "text/plain") w.WriteHeader(http.StatusBadRequest) @@ -957,6 +986,7 @@ func TestRequestErrorResponseNotJSON(t *testing.T) { // Test an error response with no response body. func TestRequestErrorResponseNoBody(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusInternalServerError) })) @@ -994,6 +1024,7 @@ func TestRequestErrorResponseNoBody(t *testing.T) { } func TestClient(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) mockClient := http.Client{} authenticator, _ := NewBasicAuthenticator("username", "password") service, _ := NewBaseService(&ServiceOptions{Authenticator: authenticator}) @@ -1002,6 +1033,7 @@ func TestClient(t *testing.T) { } func TestRequestForDefaultUserAgent(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") fmt.Fprint(w, `{"name": "wonder woman"}`) @@ -1028,6 +1060,7 @@ func TestRequestForDefaultUserAgent(t *testing.T) { } func TestRequestForProvidedUserAgent(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") fmt.Fprint(w, `{"name": "wonder woman"}`) @@ -1057,6 +1090,7 @@ func TestRequestForProvidedUserAgent(t *testing.T) { } func TestRequestHostHeaderDefault(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Content-type", "application/json") fmt.Fprint(w, `{"name": "wonder woman"}`) @@ -1086,6 +1120,7 @@ func TestRequestHostHeaderDefault(t *testing.T) { } func TestIncorrectURL(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) authenticator, _ := NewNoAuthAuthenticator() options := &ServiceOptions{ URL: "{xxx}", @@ -1097,6 +1132,7 @@ func TestIncorrectURL(t *testing.T) { } func TestDisableSSLVerification(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) options := &ServiceOptions{ URL: "test.com", Authenticator: &NoAuthAuthenticator{}, @@ -1116,6 +1152,7 @@ func TestDisableSSLVerification(t *testing.T) { } func TestDisableSSLVerificationWithRetries(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) options := &ServiceOptions{ URL: "test.com", Authenticator: &NoAuthAuthenticator{}, @@ -1160,6 +1197,7 @@ func TestDisableSSLVerificationWithRetries(t *testing.T) { } func TestRequestBasicAuth1(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) @@ -1193,6 +1231,7 @@ func TestRequestBasicAuth1(t *testing.T) { } func TestRequestBasicAuth2(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) firstTime := true server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) @@ -1242,6 +1281,7 @@ func TestRequestBasicAuth2(t *testing.T) { } func TestBasicAuthConfigError(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) options := &ServiceOptions{ URL: "https://myservice", Authenticator: &BasicAuthenticator{ @@ -1256,6 +1296,7 @@ func TestBasicAuthConfigError(t *testing.T) { } func TestRequestNoAuth1(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) assert.Equal(t, "", r.Header.Get("Authorization")) @@ -1284,6 +1325,7 @@ func TestRequestNoAuth1(t *testing.T) { } func TestRequestNoAuth2(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) assert.Equal(t, "", r.Header.Get("Authorization")) @@ -1319,6 +1361,7 @@ func TestRequestNoAuth2(t *testing.T) { } func TestRequestIAMAuth(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) firstCall := true server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) @@ -1375,6 +1418,7 @@ func TestRequestIAMAuth(t *testing.T) { } func TestRequestIAMFailure(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusForbidden) _, _ = w.Write([]byte("Sorry you are forbidden")) @@ -1411,6 +1455,7 @@ func TestRequestIAMFailure(t *testing.T) { } func TestRequestIAMFailureRetryAfter(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Retry-After", "20") w.WriteHeader(http.StatusTooManyRequests) @@ -1450,6 +1495,7 @@ func TestRequestIAMFailureRetryAfter(t *testing.T) { } func TestRequestIAMWithIdSecret(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) body, _ := io.ReadAll(r.Body) @@ -1496,6 +1542,7 @@ func TestRequestIAMWithIdSecret(t *testing.T) { } func TestIAMErrorClientIdOnly(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) _, err := NewBaseService( &ServiceOptions{ URL: "don't care", @@ -1508,6 +1555,7 @@ func TestIAMErrorClientIdOnly(t *testing.T) { } func TestIAMErrorClientSecretOnly(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) _, err := NewBaseService( &ServiceOptions{ URL: "don't care", @@ -1520,6 +1568,7 @@ func TestIAMErrorClientSecretOnly(t *testing.T) { } func TestRequestIAMNoApiKey(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) _, err := NewBaseService( &ServiceOptions{ URL: "don't care", @@ -1538,6 +1587,7 @@ const ( ) func TestRequestCP4DAuth(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusOK) if strings.HasSuffix(r.URL.String(), "/v1/authorize") { @@ -1573,6 +1623,7 @@ func TestRequestCP4DAuth(t *testing.T) { } func TestRequestCP4DFail(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.WriteHeader(http.StatusForbidden) _, _ = w.Write([]byte("Sorry you are forbidden")) @@ -1610,6 +1661,7 @@ func TestRequestCP4DFail(t *testing.T) { } func TestRequestCp4dFailureRetryAfter(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { w.Header().Set("Retry-After", "20") w.WriteHeader(http.StatusTooManyRequests) @@ -1651,6 +1703,7 @@ func TestRequestCp4dFailureRetryAfter(t *testing.T) { // Test for the deprecated SetURL method. func TestSetURL(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService( &ServiceOptions{ Authenticator: &IamAuthenticator{ @@ -1665,6 +1718,7 @@ func TestSetURL(t *testing.T) { } func TestSetServiceURL(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService( &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, @@ -1687,6 +1741,7 @@ func TestSetServiceURL(t *testing.T) { } func TestSetUserAgent(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService( &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, @@ -1712,6 +1767,7 @@ func getRetriesConfig(service *BaseService) (int, time.Duration) { } func TestEnableRetries(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) options := &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, } @@ -1747,6 +1803,7 @@ func TestEnableRetries(t *testing.T) { } func TestClientWithRetries(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) options := &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, } @@ -1807,6 +1864,7 @@ func TestClientWithRetries(t *testing.T) { } func TestSetEnableGzipCompression(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService( &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, @@ -1822,6 +1880,7 @@ func TestSetEnableGzipCompression(t *testing.T) { } func TestExtConfigFromCredentialFile(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) pwd, _ := os.Getwd() credentialFilePath := path.Join(pwd, "/../resources/my-credentials.env") t.Setenv("IBM_CREDENTIALS_FILE", credentialFilePath) @@ -1891,6 +1950,7 @@ func TestExtConfigFromCredentialFile(t *testing.T) { } func TestExtConfigError(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) pwd, _ := os.Getwd() credentialFilePath := path.Join(pwd, "/../resources/my-credentials.env") t.Setenv("IBM_CREDENTIALS_FILE", credentialFilePath) @@ -1905,6 +1965,7 @@ func TestExtConfigError(t *testing.T) { } func TestExtConfigFromEnvironment(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) setTestEnvironment(t) service, _ := NewBaseService( @@ -1921,6 +1982,7 @@ func TestExtConfigFromEnvironment(t *testing.T) { } func TestExtConfigFromVCAP(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) setTestVCAP(t) service, _ := NewBaseService( @@ -1936,6 +1998,7 @@ func TestExtConfigFromVCAP(t *testing.T) { } func TestConfigureServiceFromCredFile(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService( &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, @@ -1959,6 +2022,7 @@ func TestConfigureServiceFromCredFile(t *testing.T) { } func TestConfigureServiceFromVCAP(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService( &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, @@ -1977,6 +2041,7 @@ func TestConfigureServiceFromVCAP(t *testing.T) { } func TestConfigureServiceFromEnv(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService( &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, @@ -1996,6 +2061,7 @@ func TestConfigureServiceFromEnv(t *testing.T) { } func TestConfigureServiceError(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) pwd, _ := os.Getwd() credentialFilePath := path.Join(pwd, "/../resources/my-credentials.env") t.Setenv("IBM_CREDENTIALS_FILE", credentialFilePath) @@ -2011,12 +2077,14 @@ func TestConfigureServiceError(t *testing.T) { } func TestAuthNotConfigured(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService(&ServiceOptions{}) assert.NotNil(t, err) assert.Nil(t, service) } func TestAuthInterfaceNilValue(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) var authenticator *NoAuthAuthenticator = nil options := &ServiceOptions{ @@ -2115,6 +2183,7 @@ func getTLSVersion(service *BaseService) int { } func TestMinSSLVersion(t *testing.T) { + GetLogger().SetLogLevel(basesvcAuthTestLogLevel) service, err := NewBaseService( &ServiceOptions{ Authenticator: &NoAuthAuthenticator{}, diff --git a/core/basic_authenticator.go b/core/basic_authenticator.go index b0c12eb..4506eb1 100644 --- a/core/basic_authenticator.go +++ b/core/basic_authenticator.go @@ -64,8 +64,9 @@ func (BasicAuthenticator) AuthenticationType() string { // Basic Authorization will be added to the request's headers in the form: // // Authorization: Basic -func (this *BasicAuthenticator) Authenticate(request *http.Request) error { - request.SetBasicAuth(this.Username, this.Password) +func (authenticator *BasicAuthenticator) Authenticate(request *http.Request) error { + request.SetBasicAuth(authenticator.Username, authenticator.Password) + GetLogger().Debug("Authenticated outbound request (type=%s)\n", authenticator.AuthenticationType()) return nil } @@ -73,23 +74,23 @@ func (this *BasicAuthenticator) Authenticate(request *http.Request) error { // // Ensures the username and password are not Nil. Additionally, ensures // they do not contain invalid characters. -func (this BasicAuthenticator) Validate() error { - if this.Username == "" { +func (authenticator BasicAuthenticator) Validate() error { + if authenticator.Username == "" { err := fmt.Errorf(ERRORMSG_PROP_MISSING, "Username") return SDKErrorf(err, "", "no-user", getComponentInfo()) } - if this.Password == "" { + if authenticator.Password == "" { err := fmt.Errorf(ERRORMSG_PROP_MISSING, "Password") return SDKErrorf(err, "", "no-pass", getComponentInfo()) } - if HasBadFirstOrLastChar(this.Username) { + if HasBadFirstOrLastChar(authenticator.Username) { err := fmt.Errorf(ERRORMSG_PROP_INVALID, "Username") return SDKErrorf(err, "", "bad-user", getComponentInfo()) } - if HasBadFirstOrLastChar(this.Password) { + if HasBadFirstOrLastChar(authenticator.Password) { err := fmt.Errorf(ERRORMSG_PROP_INVALID, "Password") return SDKErrorf(err, "", "bad-pass", getComponentInfo()) } diff --git a/core/basic_authenticator_test.go b/core/basic_authenticator_test.go index bd5fc2e..3b6249d 100644 --- a/core/basic_authenticator_test.go +++ b/core/basic_authenticator_test.go @@ -23,6 +23,11 @@ import ( "github.com/stretchr/testify/assert" ) +var ( + // To enable debug logging during test execution, set this to "LevelDebug" + basicAuthTestLogLevel LogLevel = LevelError +) + func TestBasicAuthUsername(t *testing.T) { authenticator := &BasicAuthenticator{ Username: "{username}", @@ -64,6 +69,7 @@ func TestBasicAuthPassword(t *testing.T) { } func TestBasicAuthAuthenticate(t *testing.T) { + GetLogger().SetLogLevel(basicAuthTestLogLevel) authenticator := &BasicAuthenticator{ Username: "foo", Password: "bar", diff --git a/core/bearer_token_authenticator.go b/core/bearer_token_authenticator.go index ab26448..ce37cb9 100644 --- a/core/bearer_token_authenticator.go +++ b/core/bearer_token_authenticator.go @@ -61,16 +61,17 @@ func (BearerTokenAuthenticator) AuthenticationType() string { // The bearer token will be added to the request's headers in the form: // // Authorization: Bearer -func (this *BearerTokenAuthenticator) Authenticate(request *http.Request) error { - request.Header.Set("Authorization", fmt.Sprintf(`Bearer %s`, this.BearerToken)) +func (authenticator *BearerTokenAuthenticator) Authenticate(request *http.Request) error { + request.Header.Set("Authorization", fmt.Sprintf(`Bearer %s`, authenticator.BearerToken)) + GetLogger().Debug("Authenticated outbound request (type=%s)\n", authenticator.AuthenticationType()) return nil } // Validate the authenticator's configuration. // // Ensures the bearer token is not Nil. -func (this BearerTokenAuthenticator) Validate() error { - if this.BearerToken == "" { +func (authenticator BearerTokenAuthenticator) Validate() error { + if authenticator.BearerToken == "" { err := fmt.Errorf(ERRORMSG_PROP_MISSING, "BearerToken") return SDKErrorf(err, "", "no-token", getComponentInfo()) } diff --git a/core/bearer_token_authenticator_test.go b/core/bearer_token_authenticator_test.go index 2585d7e..65d24bb 100644 --- a/core/bearer_token_authenticator_test.go +++ b/core/bearer_token_authenticator_test.go @@ -23,6 +23,11 @@ import ( "github.com/stretchr/testify/assert" ) +var ( + // To enable debug logging during test execution, set this to "LevelDebug" + bearerAuthTestLogLevel LogLevel = LevelError +) + func TestBearerToken(t *testing.T) { authenticator := &BearerTokenAuthenticator{ BearerToken: "", @@ -37,6 +42,7 @@ func TestBearerToken(t *testing.T) { } func TestBearerTokenAuthenticate(t *testing.T) { + GetLogger().SetLogLevel(bearerAuthTestLogLevel) authenticator := &BearerTokenAuthenticator{ BearerToken: "my-bearer-token", } diff --git a/core/common_test.go b/core/common_test.go index 5a9b501..0ab5ef7 100644 --- a/core/common_test.go +++ b/core/common_test.go @@ -1,4 +1,4 @@ -//go:build all || fast || basesvc +//go:build all || fast || basesvc || retries package core @@ -8,7 +8,7 @@ import ( "testing" ) -// (C) Copyright IBM Corp. 2020. +// (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. diff --git a/core/config_utils.go b/core/config_utils.go index 24d535d..39e7207 100644 --- a/core/config_utils.go +++ b/core/config_utils.go @@ -63,6 +63,8 @@ func getServiceProperties(serviceName string) (serviceProps map[string]string, e return } + GetLogger().Debug("Retrieving config properties for service '%s'\n", serviceName) + // First try to retrieve service properties from a credential file. serviceProps = getServicePropertiesFromCredentialFile(serviceName) @@ -76,6 +78,8 @@ func getServiceProperties(serviceName string) (serviceProps map[string]string, e serviceProps = getServicePropertiesFromVCAP(serviceName) } + GetLogger().Debug("Retrieved %d properties\n", len(serviceProps)) + return } diff --git a/core/config_utils_test.go b/core/config_utils_test.go index eb39df9..0fc39bd 100644 --- a/core/config_utils_test.go +++ b/core/config_utils_test.go @@ -25,6 +25,11 @@ import ( "github.com/stretchr/testify/assert" ) +var ( + // To enable debug logging during test execution, set this to "LevelDebug" + configUtilsTestLogLevel LogLevel = LevelDebug +) + const vcapServicesKey = "VCAP_SERVICES" // Sets a test VCAP_SERVICES value in the environment for testing. @@ -36,17 +41,20 @@ func setTestVCAP(t *testing.T) { } func TestGetServicePropertiesError(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) _, err := getServiceProperties("") assert.NotNil(t, err) } func TestGetServicePropertiesNoConfig(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) props, err := getServiceProperties("not_a_service") assert.Nil(t, err) assert.Nil(t, props) } func TestGetServicePropertiesFromCredentialFile(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) pwd, _ := os.Getwd() credentialFilePath := path.Join(pwd, "/../resources/my-credentials.env") t.Setenv("IBM_CREDENTIALS_FILE", credentialFilePath) @@ -106,6 +114,7 @@ func TestGetServicePropertiesFromCredentialFile(t *testing.T) { } func TestGetServicePropertiesFromEnvironment(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) setTestEnvironment(t) props, err := GetServiceProperties("service-1") @@ -162,6 +171,7 @@ func TestGetServicePropertiesFromEnvironment(t *testing.T) { } func TestGetServicePropertiesFromVCAP(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) setTestVCAP(t) props, err := getServiceProperties("service-1") @@ -193,6 +203,7 @@ func TestGetServicePropertiesFromVCAP(t *testing.T) { } func TestLoadFromVCAPServicesWithServiceEntries(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) setTestVCAP(t) // Verify we checked service entry names first credential1 := loadFromVCAPServices("service_entry_key_and_key_to_service_entries") @@ -222,6 +233,7 @@ func TestLoadFromVCAPServicesWithServiceEntries(t *testing.T) { } func TestLoadFromVCAPServicesEmptyService(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) setTestVCAP(t) // Verify we checked service entry names first credential := loadFromVCAPServices("empty_service") @@ -229,6 +241,7 @@ func TestLoadFromVCAPServicesEmptyService(t *testing.T) { } func TestLoadFromVCAPServicesNoCredentials(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) setTestVCAP(t) // Verify we checked service entry names first credential := loadFromVCAPServices("no-creds-service") @@ -236,11 +249,13 @@ func TestLoadFromVCAPServicesNoCredentials(t *testing.T) { } func TestLoadFromVCAPServicesWithEmptyString(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) credential := loadFromVCAPServices("watson") assert.Nil(t, credential, "Credentials should nil") } func TestLoadFromVCAPServicesWithInvalidJSON(t *testing.T) { + GetLogger().SetLogLevel(configUtilsTestLogLevel) vcapServicesFail := `{ "watson": [ "credentials": { diff --git a/core/container_authenticator.go b/core/container_authenticator.go index 2d7c3f5..5919889 100644 --- a/core/container_authenticator.go +++ b/core/container_authenticator.go @@ -255,6 +255,7 @@ func (authenticator *ContainerAuthenticator) Authenticate(request *http.Request) } request.Header.Set("Authorization", "Bearer "+token) + GetLogger().Debug("Authenticated outbound request (type=%s)\n", authenticator.AuthenticationType()) return nil } diff --git a/core/cp4d_authenticator.go b/core/cp4d_authenticator.go index 8f9a811..66c1f10 100644 --- a/core/cp4d_authenticator.go +++ b/core/cp4d_authenticator.go @@ -207,6 +207,7 @@ func (authenticator *CloudPakForDataAuthenticator) Authenticate(request *http.Re } request.Header.Set("Authorization", fmt.Sprintf(`Bearer %s`, token)) + GetLogger().Debug("Authenticated outbound request (type=%s)\n", authenticator.AuthenticationType()) return nil } @@ -231,15 +232,19 @@ func (authenticator *CloudPakForDataAuthenticator) setTokenData(tokenData *cp4dT // or the existing token has expired), a new access token is fetched from the token server. func (authenticator *CloudPakForDataAuthenticator) GetToken() (string, error) { if authenticator.getTokenData() == nil || !authenticator.getTokenData().isTokenValid() { + GetLogger().Debug("Performing synchronous token fetch...") // synchronously request the token err := authenticator.synchronizedRequestToken() if err != nil { return "", RepurposeSDKProblem(err, "request-token-fail") } } else if authenticator.getTokenData().needsRefresh() { + GetLogger().Debug("Performing background asynchronous token fetch...") // If refresh needed, kick off a go routine in the background to get a new token //nolint: errcheck go authenticator.invokeRequestTokenData() + } else { + GetLogger().Debug("Using cached access token...") } // return an error if the access token is not valid or was not fetched diff --git a/core/file_with_metadata_test.go b/core/file_with_metadata_test.go index 6f4c5de..68952db 100644 --- a/core/file_with_metadata_test.go +++ b/core/file_with_metadata_test.go @@ -1,6 +1,8 @@ +//go:build all || fast + package core -// (C) Copyright IBM Corp. 2021. +// (C) Copyright IBM Corp. 2021, 2024. // // Licensed under the Apache License, Version 2.0 (the "License"); // you may not use this file except in compliance with the License. diff --git a/core/http_problem_test.go b/core/http_problem_test.go index 767b33c..133d7c5 100644 --- a/core/http_problem_test.go +++ b/core/http_problem_test.go @@ -1,3 +1,5 @@ +//go:build all || fast || problem + package core // (C) Copyright IBM Corp. 2024. diff --git a/core/iam_authenticator.go b/core/iam_authenticator.go index da9feb6..ff73a69 100644 --- a/core/iam_authenticator.go +++ b/core/iam_authenticator.go @@ -249,9 +249,9 @@ func (*IamAuthenticator) AuthenticationType() string { // Authenticate adds IAM authentication information to the request. // -// The IAM bearer token will be added to the request's headers in the form: +// The IAM access token will be added to the request's headers in the form: // -// Authorization: Bearer +// Authorization: Bearer func (authenticator *IamAuthenticator) Authenticate(request *http.Request) error { token, err := authenticator.GetToken() if err != nil { @@ -259,6 +259,7 @@ func (authenticator *IamAuthenticator) Authenticate(request *http.Request) error } request.Header.Set("Authorization", "Bearer "+token) + GetLogger().Debug("Authenticated outbound request (type=%s)\n", authenticator.AuthenticationType()) return nil } @@ -362,15 +363,19 @@ func (authenticator *IamAuthenticator) Validate() error { // or the existing token has expired), a new access token is fetched from the token server. func (authenticator *IamAuthenticator) GetToken() (string, error) { if authenticator.getTokenData() == nil || !authenticator.getTokenData().isTokenValid() { + GetLogger().Debug("Performing synchronous token fetch...") // synchronously request the token err := authenticator.synchronizedRequestToken() if err != nil { return "", RepurposeSDKProblem(err, "request-token-fail") } } else if authenticator.getTokenData().needsRefresh() { + GetLogger().Debug("Performing background asynchronous token fetch...") // If refresh needed, kick off a go routine in the background to get a new token //nolint: errcheck go authenticator.invokeRequestTokenData() + } else { + GetLogger().Debug("Using cached access token...") } // return an error if the access token is not valid or was not fetched diff --git a/core/ibm_problem_test.go b/core/ibm_problem_test.go index 5246143..e339cf5 100644 --- a/core/ibm_problem_test.go +++ b/core/ibm_problem_test.go @@ -1,3 +1,5 @@ +//go:build all || fast || problem + package core // (C) Copyright IBM Corp. 2024. diff --git a/core/mcsp_authenticator.go b/core/mcsp_authenticator.go index 3bd2a2f..3884507 100644 --- a/core/mcsp_authenticator.go +++ b/core/mcsp_authenticator.go @@ -183,6 +183,7 @@ func (authenticator *MCSPAuthenticator) Authenticate(request *http.Request) erro } request.Header.Set("Authorization", "Bearer "+token) + GetLogger().Debug("Authenticated outbound request (type=%s)\n", authenticator.AuthenticationType()) return nil } @@ -227,15 +228,19 @@ func (authenticator *MCSPAuthenticator) Validate() error { // or the existing token has expired), a new access token is fetched from the token server. func (authenticator *MCSPAuthenticator) GetToken() (string, error) { if authenticator.getTokenData() == nil || !authenticator.getTokenData().isTokenValid() { + GetLogger().Debug("Performing synchronous token fetch...") // synchronously request the token err := authenticator.synchronizedRequestToken() if err != nil { return "", RepurposeSDKProblem(err, "request-token-fail") } } else if authenticator.getTokenData().needsRefresh() { + GetLogger().Debug("Performing background asynchronous token fetch...") // If refresh needed, kick off a go routine in the background to get a new token. //nolint: errcheck go authenticator.invokeRequestTokenData() + } else { + GetLogger().Debug("Using cached access token...") } // return an error if the access token is not valid or was not fetched diff --git a/core/mcsp_authenticator_test.go b/core/mcsp_authenticator_test.go index e94ddc3..82263f3 100644 --- a/core/mcsp_authenticator_test.go +++ b/core/mcsp_authenticator_test.go @@ -40,6 +40,7 @@ var ( // Tests involving the Builder func TestMCSPAuthBuilderErrors(t *testing.T) { + GetLogger().SetLogLevel(mcspAuthTestLogLevel) var err error var auth *MCSPAuthenticator @@ -63,6 +64,7 @@ func TestMCSPAuthBuilderErrors(t *testing.T) { } func TestMCSPAuthBuilderSuccess(t *testing.T) { + GetLogger().SetLogLevel(mcspAuthTestLogLevel) var err error var auth *MCSPAuthenticator var expectedHeaders = map[string]string{ @@ -100,6 +102,7 @@ func TestMCSPAuthBuilderSuccess(t *testing.T) { } func TestMCSPAuthReuseAuthenticator(t *testing.T) { + GetLogger().SetLogLevel(mcspAuthTestLogLevel) auth, err := NewMCSPAuthenticatorBuilder(). SetApiKey(mcspAuthMockApiKey). SetURL(mcspAuthMockURL). @@ -126,6 +129,7 @@ func TestMCSPAuthReuseAuthenticator(t *testing.T) { // Tests that construct an authenticator via map properties. func TestNewMCSPAuthenticatorFromMap(t *testing.T) { + GetLogger().SetLogLevel(mcspAuthTestLogLevel) _, err := newMCSPAuthenticatorFromMap(nil) assert.NotNil(t, err) @@ -723,5 +727,4 @@ func TestMCSPLiveTokenServer(t *testing.T) { // Make sure the auth header values from the two requests are the same. // We should have just used the cached access token in the second request. assert.Equal(t, authHeader1, authHeader2) - } diff --git a/core/ordered_maps_test.go b/core/ordered_maps_test.go index 8a2f9b8..1dfb8b9 100644 --- a/core/ordered_maps_test.go +++ b/core/ordered_maps_test.go @@ -1,3 +1,5 @@ +//go:build all || fast + package core // (C) Copyright IBM Corp. 2024. diff --git a/core/parameterized_url.go b/core/parameterized_url.go index 849dad6..81b6506 100644 --- a/core/parameterized_url.go +++ b/core/parameterized_url.go @@ -39,6 +39,7 @@ func ConstructServiceURL( defaultUrlVariables map[string]string, providedUrlVariables map[string]string, ) (string, error) { + GetLogger().Debug("Constructing service URL from parameterized URL: %s\n", parameterizedUrl) // Verify the provided variable names. for providedName := range providedUrlVariables { @@ -70,5 +71,6 @@ func ConstructServiceURL( } formattedUrl = strings.Replace(formattedUrl, "{"+name+"}", providedValue, 1) } + GetLogger().Debug("Returning service URL: %s\n", formattedUrl) return formattedUrl, nil } diff --git a/core/problem_utils_test.go b/core/problem_utils_test.go index 1edbddd..095695b 100644 --- a/core/problem_utils_test.go +++ b/core/problem_utils_test.go @@ -1,3 +1,5 @@ +//go:build all || fast || problem + package core // (C) Copyright IBM Corp. 2024. diff --git a/core/sdk_problem_test.go b/core/sdk_problem_test.go index 7a7c5dc..bdb3b27 100644 --- a/core/sdk_problem_test.go +++ b/core/sdk_problem_test.go @@ -1,3 +1,5 @@ +//go:build all || fast || problem + package core // (C) Copyright IBM Corp. 2024. @@ -191,7 +193,7 @@ func TestSDKErrorf(t *testing.T) { assert.Equal(t, "github.com/IBM/go-sdk-core/v5/core.TestSDKErrorf", stack[0].Function) assert.Contains(t, stack[0].File, "core/sdk_problem_test.go") // This might be too fragile. If it becomes an issue, we can remove it. - assert.Equal(t, 179, stack[0].Line) + assert.Equal(t, 181, stack[0].Line) } func TestSDKErrorfNoCausedBy(t *testing.T) { diff --git a/core/vpc_instance_authenticator.go b/core/vpc_instance_authenticator.go index 562318b..4c60ee7 100644 --- a/core/vpc_instance_authenticator.go +++ b/core/vpc_instance_authenticator.go @@ -189,6 +189,7 @@ func (authenticator *VpcInstanceAuthenticator) Authenticate(request *http.Reques } request.Header.Set("Authorization", "Bearer "+token) + GetLogger().Debug("Authenticated outbound request (type=%s)\n", authenticator.AuthenticationType()) return nil } diff --git a/core/vpc_instance_authenticator_test.go b/core/vpc_instance_authenticator_test.go index a649eff..f96ce77 100644 --- a/core/vpc_instance_authenticator_test.go +++ b/core/vpc_instance_authenticator_test.go @@ -1,4 +1,4 @@ -//go:build all || auth +//go:build all || slow || auth package core