diff --git a/internal/civisibility/integrations/civisibility.go b/internal/civisibility/integrations/civisibility.go index 92c0e2ee77..aca1d2e5ee 100644 --- a/internal/civisibility/integrations/civisibility.go +++ b/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() diff --git a/internal/civisibility/integrations/civisibility_features.go b/internal/civisibility/integrations/civisibility_features.go index c12d5cc0f1..a10b596a45 100644 --- a/internal/civisibility/integrations/civisibility_features.go +++ b/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 } } diff --git a/internal/civisibility/integrations/gotesting/testing_test.go b/internal/civisibility/integrations/gotesting/testing_test.go index 2f41387280..8d655719aa 100644 --- a/internal/civisibility/integrations/gotesting/testing_test.go +++ b/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) diff --git a/internal/civisibility/utils/ci_providers.go b/internal/civisibility/utils/ci_providers.go index bb8b6940d5..9b714ce59e 100644 --- a/internal/civisibility/utils/ci_providers.go +++ b/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 } diff --git a/internal/civisibility/utils/codeowners.go b/internal/civisibility/utils/codeowners.go index fa930d5af2..0674945151 100644 --- a/internal/civisibility/utils/codeowners.go +++ b/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) diff --git a/internal/civisibility/utils/environmentTags.go b/internal/civisibility/utils/environmentTags.go index 6592fcb587..8904596e59 100644 --- a/internal/civisibility/utils/environmentTags.go +++ b/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 } diff --git a/internal/civisibility/utils/home.go b/internal/civisibility/utils/home.go index 8625010feb..fd2000c893 100644 --- a/internal/civisibility/utils/home.go +++ b/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 diff --git a/internal/civisibility/utils/net/client.go b/internal/civisibility/utils/net/client.go index 366aa9409c..f49117adcf 100644 --- a/internal/civisibility/utils/net/client.go +++ b/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, diff --git a/internal/civisibility/utils/net/http.go b/internal/civisibility/utils/net/http.go index a8d08fd03f..ead82d48ca 100644 --- a/internal/civisibility/utils/net/http.go +++ b/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)) + } } }