Add more logging

cmd/remote-work-processor/main.go

@@ -111,7 +111,6 @@ Loop:
 
 			log.Printf("Creating processor for operation: %T\n", operation.Body)
 			processor, err := factory.CreateProcessor(operation)
-			// TODO: handle this error better. the server must receive an answer if the message is successfully read
 			if err != nil {
 				log.Printf("error creating operation processor: %v\n", err)
 				continue

internal/executors/http/authorization_header.go

@@ -2,6 +2,7 @@ package http
 
 import (
 	"github.com/SAP/remote-work-processor/internal/executors"
+	"log"
 	"regexp"
 )
 
@@ -16,6 +17,7 @@ var iasTokenUrlRegex = regexp.MustCompile(IasTokenUrlPattern)
 // OAuth 2.0 will be added later
 
 func CreateAuthorizationHeader(params *HttpRequestParameters) (string, error) {
+	log.Println("HTTP Client: creating authorization header...")
 	authHeader := params.GetAuthorizationHeader()
 
 	if authHeader != "" {
@@ -28,19 +30,24 @@ func CreateAuthorizationHeader(params *HttpRequestParameters) (string, error) {
 
 	if tokenUrl != "" {
 		if user != "" && iasTokenUrlRegex.Match([]byte(tokenUrl)) {
+			log.Println("HTTP Client: using IAS Authorization Header...")
 			return NewIasAuthorizationHeader(tokenUrl, user, params.GetCertificateAuthentication().GetClientCertificate()).Generate()
 		}
+		log.Println("HTTP Client: using OAuth Authorization Header...")
 		return NewOAuthHeaderGenerator(params).GenerateWithCacheAside()
 	}
 
 	if user != "" {
+		log.Println("HTTP Client: using basic auth...")
 		return NewBasicAuthorizationHeader(user, pass).Generate()
 	}
 
 	if noAuthorizationRequired(params) {
+		log.Println("HTTP Client: not using authorization...")
 		return "", nil
 	}
 
+	log.Println("HTTP Client: failed to determine auth header...")
 	return "", executors.NewNonRetryableError("Input values for the authentication-related keys " +
 		"(user, password & authorizationHeader) are not combined properly.")
 }

internal/executors/http/basic_authorization_header.go

@@ -3,6 +3,7 @@ package http
 import (
 	"encoding/base64"
 	"fmt"
+	"log"
 )
 
 type basicAuthorizationHeader struct {
@@ -18,6 +19,7 @@ func NewBasicAuthorizationHeader(u string, p string) AuthorizationHeaderGenerato
 }
 
 func (h *basicAuthorizationHeader) Generate() (string, error) {
+	log.Println("Basic Authorization Header: generating auth header...")
 	encoded := base64.StdEncoding.EncodeToString(
 		fmt.Appendf(nil, "%s:%s", h.username, h.password),
 	)

internal/executors/http/csrf_token_fetcher.go

@@ -3,6 +3,7 @@ package http
 import (
 	"fmt"
 	"github.com/SAP/remote-work-processor/internal/utils"
+	"log"
 	"net/http"
 )
 
@@ -27,10 +28,12 @@ func NewCsrfTokenFetcher(p *HttpRequestParameters, authHeader string) TokenFetch
 }
 
 func (f *csrfTokenFetcher) Fetch() (string, error) {
+	log.Println("CSRF token fetcher: fetching new CSRF token from:", f.csrfUrl)
 	params, _ := f.createRequestParameters()
 
 	resp, err := f.HttpExecutor.ExecuteWithParameters(params)
 	if err != nil {
+		log.Println("CSRF token fetcher: failed to fetch CSRF token:", err)
 		return "", err
 	}
 
@@ -39,6 +42,8 @@ func (f *csrfTokenFetcher) Fetch() (string, error) {
 			return value, nil
 		}
 	}
+
+	log.Println("CSRF token fetcher: CSRF token header not found in response")
 	return "", fmt.Errorf("no csrf header present in response from %s", f.csrfUrl)
 }
 

internal/executors/http/http_client.go

@@ -1,6 +1,7 @@
 package http
 
 import (
+	"log"
 	"net/http"
 	"time"
 
@@ -12,10 +13,12 @@ const (
 )
 
 func CreateHttpClient(timeoutInS uint64, certAuth *tls.CertificateAuthentication) (*http.Client, error) {
+	log.Println("Creating HTTP Client...")
 	var tp http.RoundTripper
 	if certAuth != nil {
 		var err error
 
+		log.Println("Creating TLS transport...")
 		tp, err = tls.NewTLSConfigurationProvider(certAuth).CreateTransport()
 		if err != nil {
 			return nil, err
@@ -32,6 +35,7 @@ func CreateHttpClient(timeoutInS uint64, certAuth *tls.CertificateAuthentication
 	} else {
 		c.Timeout = time.Duration(timeoutInS) * time.Second
 	}
+	log.Println("HTTP Client: using timeout:", c.Timeout.String())
 
 	return c, nil
 }

internal/executors/http/http_executor.go

@@ -32,6 +32,7 @@ func (e *HttpRequestExecutor) Execute(ctx executors.Context) *executors.Executor
 	log.Println("Executing HttpRequest command...")
 	params, err := NewHttpRequestParametersFromContext(ctx)
 	if err != nil {
+		log.Println("Could not create HTTP request params: returning Task state Failed Non-Retryable Error with:", err)
 		return executors.NewExecutorResult(
 			executors.Status(pb.TaskExecutionResponseMessage_TASK_STATE_FAILED_NON_RETRYABLE),
 			executors.Error(err),
@@ -40,29 +41,31 @@ func (e *HttpRequestExecutor) Execute(ctx executors.Context) *executors.Executor
 
 	resp, err := e.ExecuteWithParameters(params)
 
-	// TODO: add more logging
 	switch typedErr := err.(type) {
 	case *executors.RetryableError:
-		// TODO: test on dev as the Delay service crashes localdev
+		log.Println("Returning Task state Failed Retryable Error...")
 		return executors.NewExecutorResult(
 			executors.Status(pb.TaskExecutionResponseMessage_TASK_STATE_FAILED_RETRYABLE),
 			executors.Error(typedErr),
 		)
 	case *executors.NonRetryableError:
+		log.Println("Returning Task state Failed Non-Retryable Error...")
 		return executors.NewExecutorResult(
 			executors.Status(pb.TaskExecutionResponseMessage_TASK_STATE_FAILED_NON_RETRYABLE),
 			executors.Error(typedErr),
 		)
 	default:
 		m := resp.ToMap()
 		if !resp.successful {
+			log.Println("Returning Task state Failed Retryable Error from HTTP response...")
 			return executors.NewExecutorResult(
 				executors.Output(m),
 				executors.Status(pb.TaskExecutionResponseMessage_TASK_STATE_FAILED_RETRYABLE),
 				executors.ErrorString(buildHttpError(resp)),
 			)
 		}
 
+		log.Println("Returning Task state Completed...")
 		return executors.NewExecutorResult(
 			executors.Output(m),
 			executors.Status(pb.TaskExecutionResponseMessage_TASK_STATE_COMPLETED),
@@ -106,29 +109,34 @@ func execute(c *http.Client, p *HttpRequestParameters, authHeader string) (*Http
 		return nil, executors.NewNonRetryableError("could not create http request: %v", err).WithCause(err)
 	}
 
-	log.Printf("Executing request %s %s...\n", p.method, p.url)
+	log.Printf("HTTP Client: executing request %s %s...\n", p.method, p.url)
 	resp, err := c.Do(req)
 	if requestTimedOut(err) {
-		log.Println("Request timed out...")
+		log.Println("HTTP Client: request timed out after", p.timeout, "seconds")
 		if p.succeedOnTimeout {
-			log.Println("SucceedOnTimeout has been configured. Returning successful response...")
+			log.Println("HTTP Client: SucceedOnTimeout has been configured. Returning successful response...")
 			return newTimedOutHttpResponse(req, resp)
 		}
 
 		return nil, executors.NewRetryableError("HTTP request timed out after %d seconds", p.timeout).WithCause(err)
 	}
 
 	if err != nil {
+		log.Println("HTTP Client: error occurred while executing request: ", err)
 		return nil, executors.NewNonRetryableError("Error occurred while executing HTTP request: %v", err).WithCause(err)
 	}
 	defer resp.Body.Close()
 
-	log.Println("Reading response body...")
+	log.Println("HTTP Client: received response:", resp.Status)
+
+	log.Println("HTTP Client: reading response body...")
 	body, err := io.ReadAll(resp.Body)
 	if err != nil {
+		log.Println("HTTP Client: error reading response body:", err)
 		return nil, executors.NewNonRetryableError("Error occurred while trying to read HTTP response body: %v", err).WithCause(err)
 	}
 
+	log.Println("HTTP Client: building response object...")
 	r, err := NewHttpResponse(
 		Url(req.URL.String()),
 		Method(req.Method),
@@ -140,7 +148,7 @@ func execute(c *http.Client, p *HttpRequestParameters, authHeader string) (*Http
 		Time(<-timeCh),
 	)
 	if err != nil {
-		log.Println("Could not build response object:", err)
+		log.Println("HTTP Client: could not build response object:", err)
 		return nil, executors.NewNonRetryableError("Error occurred while trying to build HTTP response: %v", err).WithCause(err)
 	}
 	return r, nil
@@ -152,10 +160,12 @@ func requestTimedOut(err error) bool {
 }
 
 func createRequest(method string, url string, headers map[string]string, body, authHeader string) (*http.Request, <-chan int64, error) {
+	log.Println("HTTP Client: creating request:", method, url)
 	timeCh := make(chan int64, 1)
 
 	req, err := http.NewRequest(method, url, strings.NewReader(body))
 	if err != nil {
+		log.Println("HTTP Client: error creating request:", err)
 		return nil, nil, err
 	}
 	addHeaders(req, headers, authHeader)

internal/executors/http/ias_authorization_header.go

@@ -3,6 +3,7 @@ package http
 import (
 	"fmt"
 	"github.com/SAP/remote-work-processor/internal/utils"
+	"log"
 )
 
 const PASSCODE string = "passcode"
@@ -27,13 +28,16 @@ func (h *iasAuthorizationHeader) Generate() (string, error) {
 
 	parsed := make(map[string]any)
 	if err = utils.FromJson(raw, &parsed); err != nil {
+		log.Println("IAS authorization header: failed to parse IAS token response:", err)
 		return "", fmt.Errorf("failed to parse IAS token response: %v", err)
 	}
 
 	pass, prs := parsed[PASSCODE]
 	if !prs {
+		log.Println("IAS authorization header: passcode does not exist in the HTTP response")
 		return "", fmt.Errorf("passcode does not exist in the HTTP response")
 	}
 
+	log.Println("IAS authorization header: using basic auth with passcode...")
 	return NewBasicAuthorizationHeader(h.user, pass.(string)).Generate()
 }

internal/executors/http/ias_token_fetcher.go

@@ -1,6 +1,7 @@
 package http
 
 import (
+	"log"
 	"net/http"
 
 	"github.com/SAP/remote-work-processor/internal/executors/http/tls"
@@ -23,10 +24,12 @@ func NewIasTokenFetcher(tokenUrl, user, clientCert string) TokenFetcher {
 }
 
 func (f *iasTokenFetcher) Fetch() (string, error) {
+	log.Println("IAS token fetcher: fetching new token from:", f.tokenUrl)
 	params, _ := f.createRequestParameters()
 
 	resp, err := f.HttpExecutor.ExecuteWithParameters(params)
 	if err != nil {
+		log.Println("IAS token fetcher: failed to fetch token:", err)
 		return "", err
 	}
 

internal/executors/http/oauth_header_generator.go

@@ -3,6 +3,7 @@ package http
 import (
 	"fmt"
 	"github.com/SAP/remote-work-processor/internal/utils"
+	"log"
 	"time"
 
 	"github.com/SAP/remote-work-processor/internal/executors/http/tls"
@@ -73,14 +74,18 @@ func (h *oAuthorizationHeaderGenerator) Generate() (string, error) {
 }
 
 func (h *oAuthorizationHeaderGenerator) GenerateWithCacheAside() (string, error) {
+	log.Println("OAuth token header: checking for token in cache...")
 	var cached cachedToken
 	if cachedValue, inCache := h.requestStore[h.cachingKey]; inCache {
+		log.Println("OAuth token header: token found in cache")
 		if err := utils.FromJson(cachedValue, &cached); err != nil {
+			log.Println("OAuth token header: error decoding cached token:", err)
 			return "", fmt.Errorf("failed to deserialize cached OAuth token: %v", err)
 		}
 	}
 
 	if h.tokenAboutToExpire(cached) {
+		log.Println("OAuth token header: token is close to expiry. regenerating...")
 		newToken, err := h.fetchToken()
 		if err != nil {
 			return "", err
@@ -93,9 +98,11 @@ func (h *oAuthorizationHeaderGenerator) GenerateWithCacheAside() (string, error)
 
 		newCachedToken, err := utils.ToJson(cached)
 		if err != nil {
-			return "", fmt.Errorf("failed to serialize cached OAuth token: %v", err)
+			log.Println("OAuth token header: failed to serialize token:", err)
+			return "", fmt.Errorf("failed to serialize OAuth token: %v", err)
 		}
 
+		log.Println("OAuth token header: setting new token in cache")
 		h.requestStore[h.cachingKey] = newCachedToken
 	}
 
@@ -110,19 +117,22 @@ func (h *oAuthorizationHeaderGenerator) tokenAboutToExpire(token cachedToken) bo
 func (h *oAuthorizationHeaderGenerator) fetchToken() (*OAuthToken, error) {
 	rawToken, err := h.fetcher.Fetch()
 	if err != nil {
+		log.Println("OAuth token header: failed to fetch token:", err)
 		return nil, fmt.Errorf("failed to fetch OAuth token: %v", err)
 	}
 	return NewOAuthToken(rawToken)
 }
 
 func (h *oAuthorizationHeaderGenerator) formatToken(oAuthToken *OAuthToken) (string, error) {
+	log.Println("OAuth token header: formatting token...")
 	var token string
 	switch h.tokenType {
 	case TokenType_ACCESS:
 		token = oAuthToken.AccessToken
 	case TokenType_ID:
 		token = oAuthToken.IdToken
 	default:
+		log.Println("OAuth token header: invalid token type:", h.tokenType)
 		return "", NewIllegalTokenTypeError(h.tokenType)
 	}
 

internal/executors/http/oauth_token_fetcher.go

@@ -1,6 +1,7 @@
 package http
 
 import (
+	"log"
 	"net/http"
 
 	"github.com/SAP/remote-work-processor/internal/executors/http/tls"
@@ -58,9 +59,11 @@ func withCertificateAuthentication(auth *tls.CertificateAuthentication) function
 func (f *oAuthTokenFetcher) Fetch() (string, error) {
 	params, _ := f.createRequestParameters()
 
+	log.Println("OAuth token fetcher: fetching new token from", f.tokenUrl)
 	// TODO: TOTP should be handled here
 	req, err := f.HttpExecutor.ExecuteWithParameters(params)
 	if err != nil {
+		log.Println("OAuth token fetcher: failed to fetch token:", err)
 		return "", err
 	}