From b5e3f1e0189ea7410780693142f4961c81dac3ff Mon Sep 17 00:00:00 2001 From: Kjeld Schouten Date: Sat, 26 Oct 2024 00:51:11 +0200 Subject: [PATCH] chore(clustertool): Improve logging --- clustertool/pkg/kubectlcmds/approvecerts.go | 25 ++++++++--- clustertool/pkg/kubectlcmds/checkstatus.go | 20 ++++++++- clustertool/pkg/nodestatus/health.go | 27 ++++++++---- clustertool/pkg/nodestatus/status.go | 30 ++++++++++--- clustertool/pkg/scale/exportapps.go | 30 +++++++++---- clustertool/pkg/sops/checkencrypt.go | 43 ++++++++++++++++--- clustertool/pkg/sops/decrypt.go | 34 +++++++++++---- clustertool/pkg/sops/encrypt.go | 27 ++++++++++-- clustertool/pkg/sops/loadsops.go | 12 +++++- clustertool/pkg/sops/wrapper.go | 42 ++++++++++++++++-- .../pkg/talhelperutil/extractfromtalconfig.go | 21 ++++++++- 11 files changed, 256 insertions(+), 55 deletions(-) diff --git a/clustertool/pkg/kubectlcmds/approvecerts.go b/clustertool/pkg/kubectlcmds/approvecerts.go index e90608d3ff7..68adb2f6536 100644 --- a/clustertool/pkg/kubectlcmds/approvecerts.go +++ b/clustertool/pkg/kubectlcmds/approvecerts.go @@ -14,25 +14,31 @@ import ( // getClientset creates a Kubernetes clientset from the in-cluster config or kubeconfig file func GetClientset() (*kubernetes.Clientset, error) { - // use the current context in kubeconfig + log.Trace().Msg("Attempting to create Kubernetes clientset") + + // Use the current context in kubeconfig config, err := clientcmd.BuildConfigFromFlags("", clientcmd.RecommendedHomeFile) if err != nil { + log.Warn().Err(err).Msg("Failed to load kubeconfig, attempting in-cluster config") config, err = rest.InClusterConfig() if err != nil { + log.Error().Err(err).Msg("Failed to create in-cluster config") return nil, err } } - // create the clientset + // Create the clientset clientset, err := kubernetes.NewForConfig(config) if err != nil { + log.Error().Err(err).Msg("Error creating Kubernetes clientset") return nil, err } + log.Info().Msg("Kubernetes clientset created successfully") return clientset, nil } -// Example function to approve pending CSRs +// ApprovePendingCertificates approves pending CSRs func ApprovePendingCertificates(clientset *kubernetes.Clientset, stopCh <-chan struct{}) { log.Info().Msg("Waiting to approve certificates...") @@ -43,15 +49,20 @@ func ApprovePendingCertificates(clientset *kubernetes.Clientset, stopCh <-chan s return default: // Get the list of pending CSRs + log.Debug().Msg("Retrieving list of pending CSRs") csrList, err := clientset.CertificatesV1().CertificateSigningRequests().List(context.TODO(), metav1.ListOptions{}) if err != nil { - log.Info().Msgf("Error getting CSRs: %v", err) + log.Error().Err(err).Msg("Error getting CSRs") time.Sleep(5 * time.Second) continue } + log.Debug().Msgf("Retrieved %d CSRs", len(csrList.Items)) + // Approve pending CSRs for _, csr := range csrList.Items { + log.Debug().Str("CSRName", csr.Name).Msg("Checking CSR for approval") + if csr.Status.Conditions == nil || len(csr.Status.Conditions) == 0 { // Create a copy of the CSR object csrCopy := csr.DeepCopy() @@ -71,10 +82,12 @@ func ApprovePendingCertificates(clientset *kubernetes.Clientset, stopCh <-chan s // Update approval for the CSR using the copied object _, err := clientset.CertificatesV1().CertificateSigningRequests().UpdateApproval(context.TODO(), csr.Name, csrCopy, metav1.UpdateOptions{}) if err != nil { - log.Info().Msgf("Error approving CSR %s: %v\n", csr.Name, err) + log.Error().Str("CSRName", csr.Name).Err(err).Msg("Error approving CSR") } else { - log.Info().Msgf("Approved CSR: %s", csr.Name) + log.Info().Str("CSRName", csr.Name).Msg("Approved CSR") } + } else { + log.Debug().Str("CSRName", csr.Name).Msg("CSR already has approval conditions") } } diff --git a/clustertool/pkg/kubectlcmds/checkstatus.go b/clustertool/pkg/kubectlcmds/checkstatus.go index 0ac8a776bb2..35cc3f9edc2 100644 --- a/clustertool/pkg/kubectlcmds/checkstatus.go +++ b/clustertool/pkg/kubectlcmds/checkstatus.go @@ -13,28 +13,39 @@ import ( ) func CheckStatus(requiredPods []string, excludePod []string, timeout time.Duration) error { + log.Trace().Msg("Starting CheckStatus function") + // Load kubeconfig from the default location kubeconfig := clientcmd.NewDefaultClientConfigLoadingRules().GetDefaultFilename() config, err := clientcmd.BuildConfigFromFlags("", kubeconfig) if err != nil { + log.Error().Err(err).Msg("Error loading kubeconfig") return fmt.Errorf("error loading kubeconfig: %w", err) } + log.Debug().Msg("Kubeconfig loaded successfully") // Create clientset clientset, err := kubernetes.NewForConfig(config) if err != nil { + log.Error().Err(err).Msg("Error creating Kubernetes clientset") return fmt.Errorf("error creating clientset: %w", err) } + log.Debug().Msg("Kubernetes clientset created successfully") - // Maximum duration to wait (15 minutes) + // Maximum duration to wait (timeout in minutes) maxDuration := timeout * time.Minute endTime := time.Now().Add(maxDuration) + log.Info().Msgf("Checking status of required pods: %v, excluding pods: %v", requiredPods, excludePod) + for time.Now().Before(endTime) { + log.Debug().Msg("Retrieving list of pods") + // Get pods in all namespaces pods, err := clientset.CoreV1().Pods("").List(context.TODO(), metav1.ListOptions{}) if err != nil { - // return fmt.Errorf("error listing pods: %w", err) + log.Error().Err(err).Msg("Error listing pods") + return fmt.Errorf("error listing pods: %w", err) } // Check if the required pods are both present and running @@ -43,15 +54,18 @@ func CheckStatus(requiredPods []string, excludePod []string, timeout time.Durati requiredPodsMap[pod] = false } + log.Debug().Msg("Checking pod statuses") for _, pod := range pods.Items { for _, requiredPod := range requiredPods { for _, excludePod := range excludePod { if strings.Contains(pod.Name, excludePod) { + log.Debug().Str("excludedPod", excludePod).Msg("Excluding pod from check") requiredPodsMap[requiredPod] = true } } if strings.Contains(pod.Name, requiredPod) && pod.Status.Phase == "Running" { requiredPodsMap[requiredPod] = true + log.Debug().Str("podName", pod.Name).Msgf("Required pod %s is running", requiredPod) } } } @@ -69,9 +83,11 @@ func CheckStatus(requiredPods []string, excludePod []string, timeout time.Durati return nil } + log.Warn().Msg("Not all required pods are running, waiting before checking again") // Wait for 5 seconds before checking again time.Sleep(5 * time.Second) } + log.Error().Msg("Timeout: Not all required pods are running after 15 minutes") return fmt.Errorf("timeout: not all required pods are running after 15 minutes") } diff --git a/clustertool/pkg/nodestatus/health.go b/clustertool/pkg/nodestatus/health.go index 0e44d57bf01..8b562ecf18b 100644 --- a/clustertool/pkg/nodestatus/health.go +++ b/clustertool/pkg/nodestatus/health.go @@ -9,6 +9,8 @@ import ( ) func CheckHealth(node string, status string, silent bool) error { + log.Debug().Str("node", node).Str("expectedStatus", status).Msg("Starting health check") + out, err := CheckStatus(node) if err != nil { errstring := "healthcheck failed. status: " + string(out) + " error: " + err.Error() @@ -16,32 +18,38 @@ func CheckHealth(node string, status string, silent bool) error { log.Info().Msgf("Healthcheck: check on node : failed %v", node) log.Info().Msgf("failed with error: %s", errstring) } + log.Error().Err(err).Str("node", node).Msg("Healthcheck failed") return errors.New(errstring) } + out = strings.TrimSpace(out) if !silent { log.Info().Msgf("Healthcheck: node currently reporting status: %v %v", node, out) } - if status != "" && strings.Contains(string(out), status) { + + if status != "" && strings.Contains(out, status) { if !silent { - response := "Healthcheck: detected node " + node + "in mode " + status + " , continuing..." + response := "Healthcheck: detected node " + node + " in mode " + status + " , continuing..." log.Info().Msg(response) } - } else if status == "" && strings.Contains(string(out), "maintenance") { - response := "Healthcheck: WARN detected node " + node + "in mode " + "maintenance" + ".\nLikely a new node, so trying commands anyway. Continuing..." - log.Info().Msg(response) - } else if status == "" && strings.Contains(string(out), "running") { + } else if status == "" && strings.Contains(out, "maintenance") { + response := "Healthcheck: WARN detected node " + node + " in mode " + "maintenance" + ".\nLikely a new node, so trying commands anyway. Continuing..." + log.Warn().Msg(response) + } else if status == "" && strings.Contains(out, "running") { _, err = CheckReadyStatus(node) if err != nil { errstring := "healthcheck failed. status: " + string(out) + " error: " + err.Error() + log.Error().Err(err).Str("node", node).Msg("Healthcheck failed while checking readiness") return errors.New(errstring) } } else { if !silent { log.Info().Msgf("Healthcheck: check on node : failed %v", node) } + log.Error().Str("node", node).Msg("Healthcheck failed with unexpected status") return errors.New("healthcheck failed") } + log.Debug().Str("node", node).Msg("Health check completed successfully") return nil } @@ -49,14 +57,13 @@ func WaitForHealth(node string, status []string) (string, error) { statusmsg := "" if len(status) > 0 { for _, check := range status { - statusmsg = statusmsg + ", " + check + statusmsg += ", " + check } } else { statusmsg = "running" status = []string{""} } - // Corrected log with format specifiers log.Info().Msgf("Healthcheck: Waiting for Node %s to reach status: %s", node, statusmsg) // Duration constants @@ -73,8 +80,10 @@ func WaitForHealth(node string, status []string) (string, error) { // Initial health check before starting the ticker for _, check := range status { + log.Debug().Str("node", node).Str("check", check).Msg("Performing initial health check") err := CheckHealth(node, check, true) if err == nil { + log.Info().Str("node", node).Str("status", check).Msg("Initial health check passed") return check, nil } } @@ -83,9 +92,11 @@ func WaitForHealth(node string, status []string) (string, error) { for { select { case <-ticker.C: + log.Debug().Msg("Running periodic health checks") for _, check := range status { err := CheckHealth(node, check, true) if err == nil { + log.Info().Str("node", node).Str("status", check).Msg("Periodic health check passed") return check, nil } } diff --git a/clustertool/pkg/nodestatus/status.go b/clustertool/pkg/nodestatus/status.go index f5c7e916b06..a7528a8e901 100644 --- a/clustertool/pkg/nodestatus/status.go +++ b/clustertool/pkg/nodestatus/status.go @@ -12,64 +12,84 @@ import ( func baseStatusCMD(node string) []string { argsslice := [...]string{embed.GetTalosExec(), "--talosconfig=" + path.Join(helper.ClusterPath, "/talos/generated/talosconfig"), "-n", node, "-e", node, "get", "machinestatus"} + + log.Debug().Strs("command", argsslice[:]).Msg("Constructed base command for machine status") return argsslice[:] } func CheckNeedBootstrap(node string) (bool, error) { + log.Info().Str("node", node).Msg("Checking if bootstrap is needed") + argsslice := append(baseStatusCMD(node), "-o", "jsonpath={.spec.stage}") out, err := helper.RunCommand(argsslice, true) if err != nil { + log.Warn().Err(err).Str("output", string(out)).Msg("Error running command, checking for certificate issue") if strings.Contains(string(out), "certificate signed by unknown authority") { + log.Debug().Msg("Certificate signed by unknown authority; retrying with insecure flag") argsslice := append(baseStatusCMD(node), "-o", "jsonpath={.spec.stage}", "--insecure") out2, err2 := helper.RunCommand(argsslice, true) if err2 != nil { errstring := "status: " + string(out) + " error: " + err2.Error() + log.Error().Msg(errstring) return false, errors.New(errstring) } if string(out2) != "" && strings.Contains(string(out2), "maintenance") { + log.Info().Msg("Node is in maintenance; bootstrap needed") return true, nil } } else { errstring := "status: " + string(out) + " error: " + err.Error() + log.Error().Msg(errstring) return false, errors.New(errstring) } } - errstring := "status: " + string(out) + " error: " + err.Error() - return false, errors.New(errstring) + log.Debug().Str("output", string(out)).Msg("No bootstrap needed; returning false") + return false, nil } func CheckStatus(node string) (string, error) { + log.Info().Str("node", node).Msg("Checking node status") + argsslice := append(baseStatusCMD(node), "-o", "jsonpath={.spec.stage}") out, err := helper.RunCommand(argsslice, true) if err != nil { + log.Warn().Err(err).Str("output", string(out)).Msg("Error running command, checking for certificate issue") if strings.Contains(string(out), "certificate signed by unknown authority") { - argsslice := append(baseStatusCMD(node), "-o", "jsonpath={.spec.stage}", "--insecure") + log.Debug().Msg("Certificate signed by unknown authority; retrying with insecure flag") + argsslice = append(baseStatusCMD(node), "-o", "jsonpath={.spec.stage}", "--insecure") out2, err2 := helper.RunCommand(argsslice, true) if err2 != nil { errstring := "status: " + string(out) + " error: " + err2.Error() + log.Error().Msg(errstring) return "ERROR", errors.New(errstring) } + log.Info().Msg("Successfully retrieved node status with insecure flag") return string(out2), nil } else { errstring := "status: " + string(out) + " error: " + err.Error() + log.Error().Msg(errstring) return "ERROR", errors.New(errstring) } } + log.Info().Str("status", string(out)).Msg("Node status retrieved successfully") return string(out), nil } func CheckReadyStatus(node string) (string, error) { + log.Info().Str("node", node).Msg("Checking node readiness status") + argsslice := append(baseStatusCMD(node), "-o", "jsonpath={.spec.status.ready}") out, err := helper.RunCommand(argsslice, true) if err != nil { errstring := "status: " + string(out) + " error: " + err.Error() + log.Error().Msg(errstring) return "ERROR", errors.New(errstring) } if strings.Contains(string(out), "true") { - log.Info().Msg("node ready...") + log.Info().Msg("Node is ready") } else { - println("Node not Ready...") + log.Warn().Msg("Node is not ready") } return string(out), nil } diff --git a/clustertool/pkg/scale/exportapps.go b/clustertool/pkg/scale/exportapps.go index 5441546ad7e..7d6c376e21d 100644 --- a/clustertool/pkg/scale/exportapps.go +++ b/clustertool/pkg/scale/exportapps.go @@ -13,54 +13,68 @@ import ( ) func ExportApps() { + log.Info().Msg("Starting the ExportApps process") + // Execute the command and capture its output cmd := exec.Command("midclt", "call", "chart.release.query") var out bytes.Buffer cmd.Stdout = &out + log.Trace().Strs("command", cmd.Args).Msg("Executing command to fetch chart releases") + if err := cmd.Run(); err != nil { log.Error().Err(err).Msgf("Error executing command: %v\n", err) - os.Exit(1) } + log.Info().Msg("Successfully executed command to fetch chart releases") + // Parse the JSON output var releases []map[string]interface{} + log.Debug().Msg("Parsing JSON output from command") if err := json.Unmarshal(out.Bytes(), &releases); err != nil { log.Error().Err(err).Msgf("Error parsing JSON: %v\n", err) - os.Exit(1) } + log.Info().Int("release_count", len(releases)).Msg("Parsed releases from JSON output") + // Ensure the directory exists outputDir := "./truenas_exports" + log.Trace().Str("directory", outputDir).Msg("Checking if output directory exists") if err := os.MkdirAll(outputDir, 0755); err != nil { log.Error().Err(err).Msgf("Error creating directory: %v\n", err) - os.Exit(1) } + log.Info().Msg("Output directory ensured successfully") + // Save each release to a separate file for _, release := range releases { // Extract the release name name, ok := release["name"].(string) if !ok { - fmt.Fprintf(os.Stderr, "Error: release does not have a name field or it is not a string\n") + log.Warn().Msg("Release does not have a name field or it is not a string") continue } // Marshal the release data to JSON data, err := json.MarshalIndent(release, "", " ") if err != nil { - log.Error().Err(err).Msgf("Error marshaling JSON: %v\n", err) - + log.Error().Err(err).Msgf("Error marshaling JSON for release %s: %v\n", name, err) continue } // Create the filename using the release name filename := filepath.Join(outputDir, fmt.Sprintf("%s.json", name)) - if err := ioutil.WriteFile(filename, data, 0644); err != nil { - log.Error().Err(err).Msgf("Error writing file: %v\n", err) + log.Debug().Str("filename", filename).Msg("Writing release data to file") + if err := ioutil.WriteFile(filename, data, 0644); err != nil { + log.Error().Err(err).Msgf("Error writing file %s: %v\n", filename, err) + continue } + + log.Info().Str("release_name", name).Msg("Successfully wrote release data to file") } + + log.Info().Msg("ExportApps process completed") } diff --git a/clustertool/pkg/sops/checkencrypt.go b/clustertool/pkg/sops/checkencrypt.go index 9447a01bce4..1092f249920 100644 --- a/clustertool/pkg/sops/checkencrypt.go +++ b/clustertool/pkg/sops/checkencrypt.go @@ -20,17 +20,23 @@ type EncrFileData struct { } func ExecuteCheck(useStagedFiles bool) ([]EncrFileData, error) { + log.Debug().Msg("Starting ExecuteCheck") + // Step 1: Load the SOPS configuration. config, err := LoadSopsConfig() if err != nil { + log.Error().Err(err).Msg("Failed to load SOPS config") return nil, err } + log.Trace().Msg("SOPS configuration loaded successfully") // Step 2: Get the files from .sops.yaml configuration. allFiles, err := filesToCheck(config) if err != nil { + log.Error().Err(err).Msg("Failed to get files to check") return nil, err } + log.Debug().Msgf("Files to check: %v", allFiles) var filesToCheck []EncrFileData @@ -38,10 +44,12 @@ func ExecuteCheck(useStagedFiles bool) ([]EncrFileData, error) { // Step 3: Get the staged files from Git. stagedFiles, err := helper.GetStagedFiles() if err != nil { + log.Error().Err(err).Msg("Failed to get staged files") return nil, err } if len(stagedFiles) == 0 { + log.Warn().Msg("No staged files to check") return nil, fmt.Errorf("no staged files to check") } log.Info().Msgf("Staged files: %v", stagedFiles) @@ -67,32 +75,40 @@ func ExecuteCheck(useStagedFiles bool) ([]EncrFileData, error) { } if err := helper.StageFiles(filePaths); err != nil { + log.Error().Err(err).Msg("Error staging files") return nil, fmt.Errorf("error staging files: %v", err) } + log.Info().Msg("All staged files processed successfully") } else { // Use all files instead of staged files. filesToCheck = allFiles - // log.Info().Msgf("All files: %v", filesToCheck) + log.Debug().Msgf("Using all files: %v", filesToCheck) } // Step 5: Check the encryption status of each file. for i, file := range filesToCheck { data, err := os.ReadFile(file.Path) if err != nil { + log.Error().Err(err).Msgf("Error reading file %s", file.Path) return nil, fmt.Errorf("error reading file %s: %v", file.Path, err) } + log.Trace().Msgf("Read file %s successfully", file.Path) // Check if the file is encrypted based on the criteria defined in .sops.yaml. filesToCheck[i].Encrypted = isEncrypted(data, file.Path) + log.Debug().Msgf("File %s encrypted status: %v", file.Path, filesToCheck[i].Encrypted) } return filesToCheck, nil } func CheckFilesAndReportEncryption(tryEncrypt bool, checkStaged bool) error { + log.Debug().Msg("Starting CheckFilesAndReportEncryption") + // Step 1: Run the encryption check based on the toggle. files, err := ExecuteCheck(checkStaged) if err != nil { + log.Error().Err(err).Msg("Error executing check") return fmt.Errorf("error executing check: %v", err) } @@ -106,6 +122,7 @@ func CheckFilesAndReportEncryption(tryEncrypt bool, checkStaged bool) error { // Step 3: If there are any unencrypted files, handle based on the tryEncrypt flag. if len(unencryptedFiles) > 0 { + log.Warn().Msg("Found unencrypted files") fmt.Println("The following files are not encrypted:") for _, file := range unencryptedFiles { @@ -115,14 +132,14 @@ func CheckFilesAndReportEncryption(tryEncrypt bool, checkStaged bool) error { if tryEncrypt { err := processFileEncryption(file) if err != nil { - log.Error().Msgf("Failed to encrypt file %s: %v", file.Path, err) + log.Error().Err(err).Msgf("Failed to encrypt file %s", file.Path) } else { log.Info().Msgf("File %s encrypted successfully.", file.Path) // Step 5: Stage the file after successful encryption. err := helper.StageFile(file.Path) if err != nil { - log.Error().Msgf("Failed to stage file %s after encryption: %v", file.Path, err) + log.Error().Err(err).Msgf("Failed to stage file %s after encryption", file.Path) } else { log.Info().Msgf("File %s staged successfully after encryption.", file.Path) } @@ -132,6 +149,7 @@ func CheckFilesAndReportEncryption(tryEncrypt bool, checkStaged bool) error { // If tryEncrypt is false, exit with failure code. if !tryEncrypt { + log.Fatal().Msg("Exiting due to unencrypted files and tryEncrypt is false") os.Exit(1) } else { // Check if all files were successfully encrypted after the attempt. @@ -140,7 +158,7 @@ func CheckFilesAndReportEncryption(tryEncrypt bool, checkStaged bool) error { // Recheck encryption status after attempting to encrypt. data, err := os.ReadFile(file.Path) if err != nil { - log.Error().Msgf("Error reading file %s: %v", file.Path, err) + log.Error().Err(err).Msgf("Error reading file %s", file.Path) stillUnencrypted = append(stillUnencrypted, file.Path) continue } @@ -151,16 +169,19 @@ func CheckFilesAndReportEncryption(tryEncrypt bool, checkStaged bool) error { // If some files are still unencrypted, print them and exit with failure code. if len(stillUnencrypted) > 0 { + log.Warn().Msg("The following files could not be encrypted:") fmt.Println("The following files could not be encrypted:") for _, file := range stillUnencrypted { fmt.Println(file) } + log.Fatal().Msg("Exiting due to unencrypted files after encryption attempt") os.Exit(1) } } } // Step 6: If no unencrypted files are found, print a success message and exit with code 0. + log.Info().Msg("All files are encrypted.") fmt.Println("All files are encrypted.") os.Exit(0) @@ -169,14 +190,16 @@ func CheckFilesAndReportEncryption(tryEncrypt bool, checkStaged bool) error { // filesToCheck returns a list of files to check for encryption based on the logic in .sops.yaml. func filesToCheck(config SopsConfig) ([]EncrFileData, error) { - // Ensure the config is loaded + log.Debug().Msg("Starting filesToCheck") + // Ensure the config is loaded var files []EncrFileData // Iterate over each creation rule and find matching files for _, rule := range config.CreationRules { // Compile the path regex from the rule pathRegex, err := regexp.Compile(rule.PathRegex) if err != nil { + log.Error().Err(err).Msg("Invalid path regex in .sops.yaml") return nil, fmt.Errorf("invalid path regex in .sops.yaml: %v", err) } @@ -187,10 +210,12 @@ func filesToCheck(config SopsConfig) ([]EncrFileData, error) { } if !info.IsDir() && pathRegex.MatchString(path) { files = append(files, EncrFileData{Path: path, Encrypted: false}) + log.Debug().Msgf("Matched file: %s", path) } return nil }) if err != nil { + log.Error().Err(err).Msg("Error walking file paths") return nil, err } } @@ -200,6 +225,7 @@ func filesToCheck(config SopsConfig) ([]EncrFileData, error) { // isEncrypted checks if the given data is encrypted based on the criteria defined in .sops.yaml. func isEncrypted(data []byte, filePath string) bool { + log.Trace().Msgf("Checking if file %s is encrypted", filePath) // Detect the file format based on the file extension switch filepath.Ext(filePath) { case ".yaml", ".yml": @@ -214,6 +240,7 @@ func isEncrypted(data []byte, filePath string) bool { } func GetFormat(filePath string) string { + log.Trace().Msgf("Getting format for file %s", filePath) switch filepath.Ext(filePath) { case ".yaml", ".yml": return "yaml" @@ -228,8 +255,9 @@ func GetFormat(filePath string) string { } } -// containsSopsField checks for the presence of the "sops" field in YAML or JSON data. +// containsSopsField checks if the data contains the SOPS field. func containsSopsField(data []byte) bool { + log.Trace().Msg("Checking for SOPS field in data") var content map[string]interface{} if err := yaml.Unmarshal(data, &content); err != nil { // If the YAML is invalid, consider it not encrypted. @@ -239,7 +267,8 @@ func containsSopsField(data []byte) bool { return ok } -// containsEncMarker checks for the presence of "ENC[" marker in ENV or INI data. +// containsEncMarker checks if the data contains an encryption marker. func containsEncMarker(data []byte) bool { + log.Trace().Msg("Checking for encryption marker in data") return bytes.Contains(data, []byte("ENC[")) } diff --git a/clustertool/pkg/sops/decrypt.go b/clustertool/pkg/sops/decrypt.go index cb386628649..31e8ac9c2c6 100644 --- a/clustertool/pkg/sops/decrypt.go +++ b/clustertool/pkg/sops/decrypt.go @@ -20,9 +20,12 @@ func (e *MacFailureError) Error() string { } func DecryptFiles() error { + log.Trace().Msg("Starting DecryptFiles function") + // Get a list of encrypted files files, err := ExecuteCheck(false) if err != nil { + log.Error().Err(err).Msg("Failed to execute check for encrypted files") return err } @@ -33,21 +36,27 @@ func DecryptFiles() error { for _, file := range files { if file.Encrypted { encryptedFound = true + log.Debug().Msgf("Decrypting file: %s", file.Path) + data, err := os.ReadFile(file.Path) if err != nil { + log.Error().Err(err).Msgf("Error reading file %s", file.Path) return fmt.Errorf("error reading file %s: %v", file.Path, err) } // Decrypt data with retry mechanism decrypted, err := decryptDataWithRetry(data, GetFormat(file.Path)) if err != nil { + log.Error().Err(err).Msgf("Error decrypting file %s", file.Path) return fmt.Errorf("error decrypting file %s: %v", file.Path, err) } // Write decrypted data back to file if err := os.WriteFile(file.Path, decrypted, 0644); err != nil { + log.Error().Err(err).Msgf("Error writing decrypted data to file %s", file.Path) return fmt.Errorf("error writing decrypted data to file %s: %v", file.Path, err) } + log.Info().Msgf("Successfully decrypted file: %s", file.Path) } } @@ -55,11 +64,15 @@ func DecryptFiles() error { if !encryptedFound { log.Info().Msg("Nothing to decrypt") } + initfiles.LoadTalEnv(true) + log.Trace().Msg("Finished DecryptFiles function") return nil } func decryptData(data []byte, format string) ([]byte, error) { + log.Trace().Msg("Starting decryption of data") + os.Setenv("SOPS_AGE_KEY_FILE", "age.agekey") // Decrypt data decrypted, err := decrypt.Data(data, format) @@ -67,13 +80,15 @@ func decryptData(data []byte, format string) ([]byte, error) { // Check for MAC failure error from imported packages if strings.Contains(err.Error(), "Failed to decrypt original mac") || strings.Contains(err.Error(), "Failed to verify data integrity") { - // Log the MAC failure - log.Info().Msg("Ignoring MAC failure from imported packages.") + log.Warn().Msg("Ignoring MAC failure from imported packages.") // Return decrypted data as is return data, nil } + log.Error().Err(err).Msg("Decryption failed") return nil, err } + + log.Debug().Msg("Data decrypted successfully") return decrypted, nil } @@ -82,32 +97,35 @@ func decryptDataWithRetry(data []byte, format string) ([]byte, error) { decrypted, err := decryptData(data, format) if err != nil { if macErr, ok := err.(*MacFailureError); ok { - log.Info().Msgf("MAC failure detected: %v. Retrying without MAC verification.\n", macErr.OriginalError) + log.Info().Msgf("MAC failure detected: %v. Retrying without MAC verification.", macErr.OriginalError) // Proceed without verifying MAC decrypted, err = decryptDataIgnoringMac(data, format) if err != nil { + log.Error().Err(err).Msg("Retry decryption failed") return nil, fmt.Errorf("retry decryption failed: %v", err) } } else { + log.Error().Err(err).Msg("Decryption failed without MAC error") return nil, err } } + log.Debug().Msg("Data decryption with retry succeeded") return decrypted, nil } // Decrypt data ignoring MAC failure (hypothetical function) func decryptDataIgnoringMac(data []byte, format string) ([]byte, error) { - // This function should handle the decryption by bypassing the MAC check - // Since there is no built-in method to do this, we assume decrypted data is valid - // For illustration purposes, we return the same data, but in real cases, - // more specific handling might be necessary. + log.Trace().Msg("Decrypting data while ignoring MAC failure") decrypted, err := decrypt.Data(data, format) if err != nil && isMacFailure(err) { // Log the MAC failure and proceed with the decrypted data - log.Info().Msg("Ignoring MAC failure.") + log.Warn().Msg("Ignoring MAC failure while decrypting data.") return data, nil } + if err != nil { + log.Error().Err(err).Msg("Error decrypting data while ignoring MAC failure") + } return decrypted, err } diff --git a/clustertool/pkg/sops/encrypt.go b/clustertool/pkg/sops/encrypt.go index 511d26d78f9..36a723d01cf 100644 --- a/clustertool/pkg/sops/encrypt.go +++ b/clustertool/pkg/sops/encrypt.go @@ -11,13 +11,19 @@ import ( // EncryptAllFiles encrypts all unencrypted files as specified in the .sops.yaml configuration. func EncryptAllFiles() error { + log.Trace().Msg("Starting EncryptAllFiles function") + files, err := ExecuteCheck(false) // Get the list of files and their encryption status if err != nil { + log.Error().Err(err).Msg("Failed to execute check for file statuses") return err } + log.Debug().Int("fileCount", len(files)).Msg("Found files to process for encryption") + for _, file := range files { if err := processFileEncryption(file); err != nil { + log.Error().Err(err).Msgf("Error processing encryption for file: %s", file.Path) return err } } @@ -37,6 +43,7 @@ func processFileEncryption(file EncrFileData) error { // Check if the file is partially staged fullyStaged, err := helper.IsFileFullyStaged(file.Path) if err != nil { + log.Error().Err(err).Msgf("Error checking staged status of file: %s", file.Path) return fmt.Errorf("error checking staged status of file %s: %v", file.Path, err) } @@ -45,6 +52,7 @@ func processFileEncryption(file EncrFileData) error { log.Info().Msgf("File %s is partially staged, staging fully...\n", file.Path) err := helper.StageFile(file.Path) if err != nil { + log.Error().Err(err).Msgf("Error staging file: %s", file.Path) return fmt.Errorf("error staging file %s: %v", file.Path, err) } log.Info().Msgf("File %s fully staged.\n", file.Path) @@ -53,6 +61,7 @@ func processFileEncryption(file EncrFileData) error { // Encrypt the file err = encryptFile(file.Path) if err != nil { + log.Error().Err(err).Msgf("Error encrypting file: %s", file.Path) return fmt.Errorf("error encrypting file %s: %v", file.Path, err) } @@ -60,18 +69,22 @@ func processFileEncryption(file EncrFileData) error { return nil } -// encryptFilePlaceholder encrypts the content of the specified file and replaces the file with the encrypted data. +// encryptFile encrypts the content of the specified file and replaces the file with the encrypted data. func encryptFile(filePath string) error { + log.Trace().Msgf("Starting encryption for file: %s", filePath) + // Read the content of the file content, err := os.ReadFile(filePath) - log.Info().Msgf("Encrypting '%s'... \n", filePath) + log.Debug().Msgf("Encrypting '%s'... \n", filePath) if err != nil { + log.Error().Err(err).Msg("Error reading file") return fmt.Errorf("error reading file: %v", err) } // Ensure the regex covers the whole content sopsConfig, err := LoadSopsConfig() if err != nil { + log.Error().Err(err).Msg("Error loading SOPS configuration") return err } @@ -80,18 +93,24 @@ func encryptFile(filePath string) error { // Encrypt the content encryptedData, err := EncryptWithAgeKey(content, encrRegex, GetFormat(filePath)) if err != nil { + log.Error().Err(err).Msg("Error encrypting data") return fmt.Errorf("error encrypting data: %v", err) } // Write the encrypted data back to the file if err := os.WriteFile(filePath, encryptedData, 0644); err != nil { + log.Error().Err(err).Msg("Error writing encrypted data to file") return fmt.Errorf("error writing encrypted data to file: %v", err) } + log.Info().Msgf("Successfully encrypted file: %s", filePath) return nil } +// mergeRegex merges regex from the SOPS configuration. func mergeRegex(filePath string, config SopsConfig) string { + log.Trace().Msgf("Merging regex for file: %s", filePath) + // Initialize an empty string for merged regex mergedRegex := "" @@ -100,7 +119,7 @@ func mergeRegex(filePath string, config SopsConfig) string { // Compile the regex pattern r, err := regexp.Compile(rule.PathRegex) if err != nil { - log.Info().Msgf("Error compiling regex: %v", err) + log.Warn().Err(err).Msg("Error compiling regex") continue } @@ -108,12 +127,14 @@ func mergeRegex(filePath string, config SopsConfig) string { if r.MatchString(filePath) { // Merge the encrypted regex into the mergedRegex string mergedRegex += rule.EncryptedRegex + "|" + log.Debug().Msgf("File %s matched regex, adding encrypted regex: %s", filePath, rule.EncryptedRegex) } } // Remove the trailing "|" if mergedRegex is not empty if mergedRegex != "" { mergedRegex = mergedRegex[:len(mergedRegex)-1] + log.Debug().Msgf("Merged regex for file %s: %s", filePath, mergedRegex) } return mergedRegex diff --git a/clustertool/pkg/sops/loadsops.go b/clustertool/pkg/sops/loadsops.go index 62e0b1b512c..e3f60730c5c 100644 --- a/clustertool/pkg/sops/loadsops.go +++ b/clustertool/pkg/sops/loadsops.go @@ -4,6 +4,7 @@ import ( "fmt" "io/ioutil" + "github.com/rs/zerolog/log" "gopkg.in/yaml.v3" ) @@ -16,20 +17,27 @@ type SopsConfig struct { } func LoadSopsConfig() (SopsConfig, error) { + log.Trace().Msg("Starting LoadSopsConfig function") + // Read .sops.yaml file data, err := ioutil.ReadFile(".sops.yaml") if err != nil { + log.Error().Err(err).Msg("Error reading .sops.yaml file") return SopsConfig{}, fmt.Errorf("error reading file: %v", err) } + log.Debug().Msg("Successfully read .sops.yaml file") // Unmarshal YAML data into struct var config SopsConfig err = yaml.Unmarshal(data, &config) if err != nil { + log.Error().Err(err).Msg("Error unmarshaling YAML data") return SopsConfig{}, fmt.Errorf("error unmarshaling YAML: %v", err) } + log.Debug().Msg("Successfully unmarshaled YAML data into struct") + + // Log the loaded struct + log.Info().Interface("loadedConfig", config).Msg("Loaded SopsConfig successfully") - // Print the loaded struct - // log.Info().Msgf("Loaded Config:\n%+v\n %v", config) return config, nil } diff --git a/clustertool/pkg/sops/wrapper.go b/clustertool/pkg/sops/wrapper.go index 60a71154fca..7c67bfbd20d 100644 --- a/clustertool/pkg/sops/wrapper.go +++ b/clustertool/pkg/sops/wrapper.go @@ -14,6 +14,7 @@ import ( "github.com/getsops/sops/v3/keys" "github.com/getsops/sops/v3/keyservice" "github.com/getsops/sops/v3/version" + "github.com/rs/zerolog/log" "github.com/truecharts/public/clustertool/pkg/helper" ) @@ -22,14 +23,18 @@ var encrConfig *EncryptionConfig const ageKeyFilePath = "./age.agekey" func EncryptWithAgeKey(body []byte, regex string, format string) ([]byte, error) { + log.Trace().Msg("Starting EncryptWithAgeKey function") // Create a cypher instance cypher := NewCypher() + log.Debug().Msg("Cypher instance created") sopsConfig, err := LoadSopsConfig() if err != nil { + log.Error().Err(err).Msg("Failed to load Sops config") return nil, err } + log.Debug().Msg("Successfully loaded Sops config") var groups []sops.KeyGroup var ageKeys []string @@ -37,18 +42,22 @@ func EncryptWithAgeKey(body []byte, regex string, format string) ([]byte, error) // Iterate over each creation rule and find matching files for _, rule := range sopsConfig.CreationRules { if err != nil { + log.Error().Err(err).Msg("Invalid path regex in .sops.yaml") return nil, fmt.Errorf("invalid path regex in .sops.yaml: %v", err) } ageKeys = append(ageKeys, rule.Age) } + log.Debug().Strs("ageKeys", ageKeys).Msg("Collected age keys from creation rules") + for _, ageKey := range helper.UniqueNonEmptyElementsOf(ageKeys) { var keyGroup sops.KeyGroup keyGroup = append(keyGroup, NewMasterKey(ageKey)) groups = append(groups, keyGroup) - } + log.Debug().Msg("Key groups created for encryption") + // Encrypt the data using the sops key encryptedData, err := cypher.Encrypt(body, EncryptionConfig{ Keys: groups, @@ -60,19 +69,24 @@ func EncryptWithAgeKey(body []byte, regex string, format string) ([]byte, error) Format: format, }) if err != nil { + log.Error().Err(err).Msg("Error encrypting data") return nil, fmt.Errorf("error encrypting data: %v", err) } + log.Info().Msg("Data encrypted successfully") return encryptedData, nil } /// Custom keygroup func NewMasterKey(pubkey string) (result keys.MasterKey) { + log.Trace().Str("pubkey", pubkey).Msg("Creating new master key") + result, err := age.MasterKeyFromRecipient(pubkey) if err != nil { - + log.Error().Err(err).Msg("Failed to create master key from recipient") } + return result } @@ -91,11 +105,19 @@ type Cypher interface { type cypher struct{} func NewCypher() Cypher { + log.Debug().Msg("Creating new cypher instance") return &cypher{} } func (c *cypher) Decrypt(content []byte, format string) ([]byte, error) { - return decrypt.Data(content, format) + log.Trace().Msg("Decrypting content") + decryptedData, err := decrypt.Data(content, format) + if err != nil { + log.Error().Err(err).Msg("Error during decryption") + return nil, err + } + log.Info().Msg("Content decrypted successfully") + return decryptedData, nil } type EncryptionConfig struct { @@ -109,6 +131,8 @@ type EncryptionConfig struct { } func (m *cypher) Encrypt(content []byte, encrConfig EncryptionConfig) (result []byte, err error) { + log.Trace().Msg("Starting encryption process") + var store common.Store switch encrConfig.Format { case formatYaml: @@ -117,10 +141,14 @@ func (m *cypher) Encrypt(content []byte, encrConfig EncryptionConfig) (result [] store = common.StoreForFormat(formats.Json, config.NewStoresConfig()) } + log.Debug().Msg("Store initialized for encryption") + branches, err := store.LoadPlainFile(content) if err != nil { - return + log.Error().Err(err).Msg("Failed to load plain file for encryption") + return nil, err } + log.Debug().Msg("Plain file loaded successfully") tree := sops.Tree{ Branches: branches, @@ -140,18 +168,24 @@ func (m *cypher) Encrypt(content []byte, encrConfig EncryptionConfig) (result [] ) if len(errs) > 0 { + log.Error().Err(err).Msg("Could not generate data key") return nil, errors.New(fmt.Sprint("Could not generate data key:", errs)) } + log.Debug().Msg("Data key generated successfully") + encryptTreeOpts := common.EncryptTreeOpts{ DataKey: dataKey, Tree: &tree, Cipher: aes.NewCipher(), } + err = common.EncryptTree(encryptTreeOpts) if err != nil { + log.Error().Err(err).Msg("Error during tree encryption") return nil, err } + log.Info().Msg("Tree encrypted successfully") return store.EmitEncryptedFile(tree) } diff --git a/clustertool/pkg/talhelperutil/extractfromtalconfig.go b/clustertool/pkg/talhelperutil/extractfromtalconfig.go index f5718bc3e2b..ab9d547f430 100644 --- a/clustertool/pkg/talhelperutil/extractfromtalconfig.go +++ b/clustertool/pkg/talhelperutil/extractfromtalconfig.go @@ -22,31 +22,48 @@ type Config struct { } func ExtractIPs() { + log.Trace().Msg("Starting the ExtractIPs function") + // Load YAML file file, err := os.ReadFile("config.yaml") if err != nil { - log.Fatal().Err(err).Msg("Failed to read file: %v") + log.Fatal().Err(err).Msg("Failed to read file: config.yaml") } + log.Debug().Msg("Successfully read the YAML file") // Unmarshal YAML content into Config struct var config Config err = yaml.Unmarshal(file, &config) if err != nil { - log.Fatal().Err(err).Msg("Failed to unmarshal YAML: %v") + log.Fatal().Err(err).Msg("Failed to unmarshal YAML") } + log.Debug().Msg("Successfully unmarshaled YAML into Config struct") // Reset the global variables to ensure they are empty before populating + log.Info().Msg("Resetting global IP storage variables") helper.AllIPs = []string{} helper.ControlPlaneIPs = []string{} helper.WorkerIPs = []string{} // Loop through nodes to segregate IP addresses + log.Debug().Msg("Looping through nodes to segregate IP addresses") for _, node := range config.Nodes { + log.Debug(). + Str("hostname", node.Hostname). + Str("ipAddress", node.IPAddress). + Bool("controlPlane", node.ControlPlane). + Msg("Processing node") + helper.AllIPs = append(helper.AllIPs, node.IPAddress) if node.ControlPlane { helper.ControlPlaneIPs = append(helper.ControlPlaneIPs, node.IPAddress) + log.Info().Str("ipAddress", node.IPAddress).Msg("Added to ControlPlaneIPs") } else { helper.WorkerIPs = append(helper.WorkerIPs, node.IPAddress) + log.Info().Str("ipAddress", node.IPAddress).Msg("Added to WorkerIPs") } } + + log.Trace().Msg("Finished processing nodes") + log.Info().Int("totalIPs", len(helper.AllIPs)).Msg("Total IPs extracted") }