internal/civisibility: add and improve debug logs (#2912)

internal/civisibility/integrations/civisibility.go

@@ -15,8 +15,10 @@ import (
 
 	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace/mocktracer"
 	"gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal"
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/civisibility/constants"
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/civisibility/utils"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
 )
 
 // ciVisibilityCloseAction defines an action to be executed when CI visibility is closing.
@@ -55,6 +57,14 @@ func InitializeCIVisibilityMock() mocktracer.Tracer {
 
 func internalCiVisibilityInitialization(tracerInitializer func([]tracer.StartOption)) {
 	ciVisibilityInitializationOnce.Do(func() {
+		// check the debug flag to enable debug logs. The tracer initialization happens
+		// after the CI Visibility initialization so we need to handle this flag ourselves
+		if internal.BoolEnv("DD_TRACE_DEBUG", false) {
+			log.SetLevel(log.LevelDebug)
+		}
+
+		log.Debug("civisibility: initializing")
+
 		// Since calling this method indicates we are in CI Visibility mode, set the environment variable.
 		_ = os.Setenv(constants.CIVisibilityEnabledEnvironmentVariable, "1")
 
@@ -88,6 +98,7 @@ func internalCiVisibilityInitialization(tracerInitializer func([]tracer.StartOpt
 		go func() { ensureAdditionalFeaturesInitialization(serviceName) }()
 
 		// Initialize the tracer
+		log.Debug("civisibility: initializing tracer")
 		tracerInitializer(opts)
 
 		// Handle SIGINT and SIGTERM signals to ensure we close all open spans and flush the tracer before exiting
@@ -110,13 +121,16 @@ func PushCiVisibilityCloseAction(action ciVisibilityCloseAction) {
 
 // ExitCiVisibility executes all registered close actions and stops the tracer.
 func ExitCiVisibility() {
+	log.Debug("civisibility: exiting")
 	closeActionsMutex.Lock()
 	defer closeActionsMutex.Unlock()
 	defer func() {
 		closeActions = []ciVisibilityCloseAction{}
 
+		log.Debug("civisibility: flushing and stopping tracer")
 		tracer.Flush()
 		tracer.Stop()
+		log.Debug("civisibility: done.")
 	}()
 	for _, v := range closeActions {
 		v()

internal/civisibility/integrations/civisibility_features.go

@@ -48,17 +48,19 @@ var (
 // ensureAdditionalFeaturesInitialization initialize all the additional features
 func ensureAdditionalFeaturesInitialization(serviceName string) {
 	additionalFeaturesInitializationOnce.Do(func() {
+		log.Debug("civisibility: initializing additional features")
+
 		// Create the CI Visibility client
 		ciVisibilityClient = net.NewClientWithServiceName(serviceName)
 		if ciVisibilityClient == nil {
-			log.Error("CI Visibility: error getting the ci visibility http client")
+			log.Error("civisibility: error getting the ci visibility http client")
 			return
 		}
 
 		// Get the CI Visibility settings payload for this test session
 		ciSettings, err := ciVisibilityClient.GetSettings()
 		if err != nil {
-			log.Error("CI Visibility: error getting CI visibility settings: %v", err)
+			log.Error("civisibility: error getting CI visibility settings: %v", err)
 		} else if ciSettings != nil {
 			ciVisibilitySettings = *ciSettings
 		}
@@ -67,9 +69,10 @@ func ensureAdditionalFeaturesInitialization(serviceName string) {
 		if ciVisibilitySettings.EarlyFlakeDetection.Enabled {
 			ciEfdData, err := ciVisibilityClient.GetEarlyFlakeDetectionData()
 			if err != nil {
-				log.Error("CI Visibility: error getting CI visibility early flake detection data: %v", err)
+				log.Error("civisibility: error getting CI visibility early flake detection data: %v", err)
 			} else if ciEfdData != nil {
 				ciVisibilityEarlyFlakyDetectionSettings = *ciEfdData
+				log.Debug("civisibility: early flake detection data loaded.")
 			}
 		}
 
@@ -78,13 +81,15 @@ func ensureAdditionalFeaturesInitialization(serviceName string) {
 			flakyRetryEnabledByEnv := internal.BoolEnv(constants.CIVisibilityFlakyRetryEnabledEnvironmentVariable, true)
 			if flakyRetryEnabledByEnv {
 				totalRetriesCount := (int64)(internal.IntEnv(constants.CIVisibilityTotalFlakyRetryCountEnvironmentVariable, DefaultFlakyTotalRetryCount))
+				retryCount := (int64)(internal.IntEnv(constants.CIVisibilityFlakyRetryCountEnvironmentVariable, DefaultFlakyRetryCount))
 				ciVisibilityFlakyRetriesSettings = FlakyRetriesSetting{
-					RetryCount:               (int64)(internal.IntEnv(constants.CIVisibilityFlakyRetryCountEnvironmentVariable, DefaultFlakyRetryCount)),
+					RetryCount:               retryCount,
 					TotalRetryCount:          totalRetriesCount,
 					RemainingTotalRetryCount: totalRetriesCount,
 				}
+				log.Debug("civisibility: automatic test retries enabled [retryCount: %v, totalRetryCount: %v]", retryCount, totalRetriesCount)
 			} else {
-				log.Warn("CI Visibility: flaky test retries was disabled by the environment variable")
+				log.Warn("civisibility: flaky test retries was disabled by the environment variable")
 				ciVisibilitySettings.FlakyTestRetriesEnabled = false
 			}
 		}

internal/civisibility/integrations/gotesting/testing_test.go

@@ -23,6 +23,7 @@ import (
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/civisibility/constants"
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/civisibility/integrations"
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/civisibility/utils/net"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
 
 	"github.com/stretchr/testify/assert"
 )
@@ -33,6 +34,8 @@ var mTracer mocktracer.Tracer
 // TestMain is the entry point for testing and runs before any test.
 func TestMain(m *testing.M) {
 
+	log.SetLevel(log.LevelDebug)
+
 	// mock the settings api to enable automatic test retries
 	server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
 		fmt.Printf("MockApi received request: %s\n", r.URL.Path)

internal/civisibility/utils/ci_providers.go

@@ -14,6 +14,7 @@ import (
 	"strings"
 
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/civisibility/constants"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
 )
 
 // providerType defines a function type that returns a map of string key-value pairs.
@@ -77,6 +78,14 @@ func getProviderTags() map[string]string {
 		}
 	}
 
+	if log.DebugEnabled() {
+		if providerName, ok := tags[constants.CIProviderName]; ok {
+			log.Debug("civisibility: detected ci provider: %v", providerName)
+		} else {
+			log.Debug("civisibility: no ci provider was detected.")
+		}
+	}
+
 	return tags
 }
 

internal/civisibility/utils/codeowners.go

@@ -76,6 +76,9 @@ func GetCodeOwners() *CodeOwners {
 			if _, err := os.Stat(path); err == nil {
 				codeowners, err = NewCodeOwners(path)
 				if err == nil {
+					if logger.DebugEnabled() {
+						logger.Debug("civisibility: codeowner file '%v' was loaded successfully.", path)
+					}
 					return codeowners
 				}
 				logger.Debug("Error parsing codeowners: %s", err)

internal/civisibility/utils/environmentTags.go

@@ -15,6 +15,7 @@ import (
 	"sync"
 
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/civisibility/constants"
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
 	"gopkg.in/DataDog/dd-trace-go.v1/internal/osinfo"
 )
 
@@ -101,6 +102,9 @@ func createCITagsMap() map[string]string {
 	localTags[constants.OSArchitecture] = runtime.GOARCH
 	localTags[constants.RuntimeName] = runtime.Compiler
 	localTags[constants.RuntimeVersion] = runtime.Version()
+	log.Debug("civisibility: os platform: %v", runtime.GOOS)
+	log.Debug("civisibility: os architecture: %v", runtime.GOARCH)
+	log.Debug("civisibility: runtime version: %v", runtime.Version())
 
 	// Get command line test command
 	var cmd string
@@ -116,6 +120,7 @@ func createCITagsMap() map[string]string {
 	cmd = regexp.MustCompile(`(?si)-test.testlogfile=(.*)\s`).ReplaceAllString(cmd, "")
 	cmd = strings.TrimSpace(cmd)
 	localTags[constants.TestCommand] = cmd
+	log.Debug("civisibility: test command: %v", cmd)
 
 	// Populate the test session name
 	if testSessionName, ok := os.LookupEnv(constants.CIVisibilityTestSessionNameEnvironmentVariable); ok {
@@ -125,6 +130,7 @@ func createCITagsMap() map[string]string {
 	} else {
 		localTags[constants.TestSessionName] = cmd
 	}
+	log.Debug("civisibility: test session name: %v", localTags[constants.TestSessionName])
 
 	// Populate missing git data
 	gitData, _ := getLocalGitData()
@@ -168,6 +174,8 @@ func createCITagsMap() map[string]string {
 		}
 	}
 
+	log.Debug("civisibility: workspace directory: %v", localTags[constants.CIWorkspacePath])
+	log.Debug("civisibility: common tags created with %v items", len(localTags))
 	return localTags
 }
 
@@ -180,5 +188,6 @@ func createCIMetricsMap() map[string]float64 {
 	localMetrics := make(map[string]float64)
 	localMetrics[constants.LogicalCPUCores] = float64(runtime.NumCPU())
 
+	log.Debug("civisibility: common metrics created with %v items", len(localMetrics))
 	return localMetrics
 }

internal/civisibility/utils/home.go

@@ -13,6 +13,8 @@ import (
 	"runtime"
 	"strconv"
 	"strings"
+
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
 )
 
 // This code is based on: https://github.com/mitchellh/go-homedir/blob/v1.1.0/homedir.go (MIT License)
@@ -55,7 +57,11 @@ func ExpandPath(path string) string {
 // Returns:
 //
 //	The home directory of the current user.
-func getHomeDir() string {
+func getHomeDir() (homeDir string) {
+	defer func() {
+		log.Debug("civisibility: home directory: %v", homeDir)
+	}()
+
 	if runtime.GOOS == "windows" {
 		if home := os.Getenv("HOME"); home != "" {
 			// First prefer the HOME environment variable

internal/civisibility/utils/net/client.go

@@ -183,6 +183,8 @@ func NewClientWithServiceName(serviceName string) Client {
 	defaultHeaders["trace_id"] = id
 	defaultHeaders["parent_id"] = id
 
+	log.Debug("ciVisibilityHttpClient: new client created [id: %v, agentless: %v, url: %v, env: %v, serviceName: %v]",
+		id, agentlessEnabled, baseURL, environment, serviceName)
 	return &client{
 		id:               id,
 		agentless:        agentlessEnabled,

internal/civisibility/utils/net/http.go

@@ -18,6 +18,8 @@ import (
 	"net/textproto"
 	"strconv"
 	"time"
+
+	"gopkg.in/DataDog/dd-trace-go.v1/internal/log"
 )
 
 // Constants for common strings
@@ -114,6 +116,8 @@ func (rh *RequestHandler) SendRequest(config RequestConfig) (*Response, error) {
 	}
 
 	for attempt := 0; attempt <= config.MaxRetries; attempt++ {
+		log.Debug("ciVisibilityHttpClient: new request [method: %v, url: %v, attempt: %v, maxRetries: %v]",
+			config.Method, config.URL, attempt, config.MaxRetries)
 		stopRetries, rs, err := rh.internalSendRequest(&config, attempt)
 		if stopRetries {
 			return rs, err
@@ -133,6 +137,14 @@ func (rh *RequestHandler) internalSendRequest(config *RequestConfig, attempt int
 		if err != nil {
 			return true, nil, err
 		}
+
+		if log.DebugEnabled() {
+			var files []string
+			for _, f := range config.Files {
+				files = append(files, f.FileName)
+			}
+			log.Debug("ciVisibilityHttpClient: sending files %v", files)
+		}
 		req, err = http.NewRequest(config.Method, config.URL, bytes.NewBuffer(body))
 		if err != nil {
 			return true, nil, err
@@ -148,6 +160,10 @@ func (rh *RequestHandler) internalSendRequest(config *RequestConfig, attempt int
 			return true, nil, err
 		}
 
+		if log.DebugEnabled() {
+			log.Debug("ciVisibilityHttpClient: serialized body [compressed: %v] %v", config.Compressed, string(serializedBody))
+		}
+
 		// Compress body if needed
 		if config.Compressed {
 			serializedBody, err = compressData(serializedBody)
@@ -185,6 +201,7 @@ func (rh *RequestHandler) internalSendRequest(config *RequestConfig, attempt int
 
 	resp, err := rh.Client.Do(req)
 	if err != nil {
+		log.Debug("ciVisibilityHttpClient: error [%v].", err)
 		// Retry if there's an error
 		exponentialBackoff(attempt, config.Backoff)
 		return false, nil, nil
@@ -194,6 +211,7 @@ func (rh *RequestHandler) internalSendRequest(config *RequestConfig, attempt int
 
 	// Capture the status code
 	statusCode := resp.StatusCode
+	log.Debug("ciVisibilityHttpClient: response status code [%v]", resp.StatusCode)
 
 	// Check for rate-limiting (HTTP 429)
 	if resp.StatusCode == HTTPStatusTooManyRequests {
@@ -246,6 +264,9 @@ func (rh *RequestHandler) internalSendRequest(config *RequestConfig, attempt int
 	if err == nil {
 		if mediaType == ContentTypeJSON || mediaType == ContentTypeJSONAlternative {
 			responseFormat = FormatJSON
+			if log.DebugEnabled() {
+				log.Debug("ciVisibilityHttpClient: serialized response [%v]", string(responseBody))
+			}
 		}
 	}