From 391cfbc50cea76a7c1d483988edefdcf0bb75983 Mon Sep 17 00:00:00 2001
From: StarFleetCPTN <starfleetcptn@protonmail.com>
Date: Sun, 30 Mar 2025 12:26:50 -0700
Subject: [PATCH] feat: Enhance notification form handling and logging
 improvements

- Added a hidden input for the notification form to ensure proper handling of the 'is_enabled' state.
- Updated the configuration loading to allow skipping SSL verification with a new environment variable.
- Introduced temporary log file creation for rclone commands, improving error handling and logging of file processing.
- Enhanced the transfer executor to parse rclone logs for file metadata, ensuring accurate tracking of processed files.
- Added debug logging for received form data in the notification service update handler to aid in troubleshooting.
---
 components/notifications/form/form.templ   |   1 +
 internal/config/config.go                  |  16 +--
 internal/scheduler/notification.go         |   2 +
 internal/scheduler/transfer_executor.go    | 133 ++++++++++++++++++++-
 internal/web/handlers/settings_handlers.go |  37 +++++-
 5 files changed, 178 insertions(+), 11 deletions(-)

diff --git a/components/notifications/form/form.templ b/components/notifications/form/form.templ
index 3a1aedb..4cddb99 100644
--- a/components/notifications/form/form.templ
+++ b/components/notifications/form/form.templ
@@ -127,6 +127,7 @@ templ NotificationForm(ctx context.Context, data types.NotificationFormData) {
 
 						<div class="flex items-start mb-6 hidden common-fields">
 							<div class="flex items-center h-5">
+        						<input type="hidden" name="is_enabled" value="false">
 								<input
 									id="is_enabled"
 									name="is_enabled"
diff --git a/internal/config/config.go b/internal/config/config.go
index 3ae3881..b63e408 100644
--- a/internal/config/config.go
+++ b/internal/config/config.go
@@ -122,11 +122,12 @@ func Load() (*Config, error) {
 			cfg.Email.RequireAuth = strings.ToLower(emailRequireAuth) == "true"
 		}
 
-		// SSL Verification configuration
-		if sslVerify := os.Getenv("SSL_VERIFY"); sslVerify != "" {
-			// Default is true (verify), only set SkipSSLVerify to true if env var is explicitly "false"
-			cfg.SkipSSLVerify = strings.ToLower(sslVerify) == "false"
+		// Skip SSL Verification configuration
+		if skipSSLVerify := os.Getenv("SKIP_SSL_VERIFY"); skipSSLVerify != "" {
+			// If SKIP_SSL_VERIFY is set, parse its boolean value
+			cfg.SkipSSLVerify = strings.ToLower(skipSSLVerify) == "true"
 		}
+		// Otherwise, the default from line 44 (false) is used.
 	} else if !os.IsNotExist(err) {
 		return nil, err
 	} else {
@@ -157,9 +158,10 @@ func Load() (*Config, error) {
 			"EMAIL_USERNAME=" + cfg.Email.Username,
 			"EMAIL_PASSWORD=" + cfg.Email.Password,
 			"",
-			"# SSL Verification for outgoing notifications (webhooks, etc.)",
-			"# Set to false to disable SSL certificate verification (USE WITH CAUTION)",
-			"SSL_VERIFY=" + strconv.FormatBool(!cfg.SkipSSLVerify), // Default is true (verify)
+			"# Skip SSL Verification for outgoing notifications (webhooks, etc.)",
+			"# Set to true to disable SSL certificate verification (USE WITH CAUTION)",
+			"# Defaults to false (verification enabled) if not set.",
+			"SKIP_SSL_VERIFY=" + strconv.FormatBool(cfg.SkipSSLVerify), // Default is false
 		}
 
 		if err := os.WriteFile(envPath, []byte(strings.Join(envContent, "\n")), 0644); err != nil {
diff --git a/internal/scheduler/notification.go b/internal/scheduler/notification.go
index a1ceeed..28cb898 100644
--- a/internal/scheduler/notification.go
+++ b/internal/scheduler/notification.go
@@ -117,6 +117,8 @@ func (n *Notifier) sendJobWebhookNotification(job *db.Job, history *db.JobHistor
 		return
 	}
 
+	fmt.Println(job.WebhookURL)
+
 	// Set headers
 	req.Header.Set("Content-Type", "application/json")
 	req.Header.Set("User-Agent", "GoMFT-Webhook/1.0")
diff --git a/internal/scheduler/transfer_executor.go b/internal/scheduler/transfer_executor.go
index e445e02..d17990e 100644
--- a/internal/scheduler/transfer_executor.go
+++ b/internal/scheduler/transfer_executor.go
@@ -786,6 +786,26 @@ func (te *TransferExecutor) executeSimpleCommand(cmdName string, cmdType string,
 		args = append(args, sourcePath)
 	}
 
+	// Create a temporary file for rclone logs
+	tempLogFile, err := os.CreateTemp("", "rclone-log-*.txt")
+	if err != nil {
+		te.logger.LogError("Error creating temporary log file for job %d, config %d: %v", job.ID, config.ID, err)
+		// Update history and return if log file creation fails
+		history.Status = "failed"
+		history.ErrorMessage = fmt.Sprintf("Log File Creation Error: %v", err)
+		endTime := time.Now()
+		history.EndTime = &endTime
+		if updateErr := te.db.UpdateJobHistory(history); updateErr != nil {
+			te.logger.LogError("Error updating job history after log file error for job %d, config %d: %v", job.ID, config.ID, updateErr)
+		}
+		te.notifier.SendNotifications(&job, history, &config)
+		return
+	}
+	defer os.Remove(tempLogFile.Name()) // Ensure cleanup
+
+	// Add logging flags to arguments
+	args = append(args, "--log-file", tempLogFile.Name(), "--log-level", "DEBUG")
+
 	// Execute the command
 	rclonePath := os.Getenv("RCLONE_PATH")
 	if rclonePath == "" {
@@ -805,11 +825,109 @@ func (te *TransferExecutor) executeSimpleCommand(cmdName string, cmdType string,
 	startTime := time.Now()
 
 	// Run the command
-	err := cmd.Run() // This will use the mocked command if execCommandContext is replaced
+	err = cmd.Run() // This will use the mocked command if execCommandContext is replaced
 
 	// Calculate duration
 	duration := time.Since(startTime)
 
+	var filesProcessedFromLog int = 0 // Declare counter for files processed based on log
+
+	// Read the rclone log file content
+	logContent, logReadErr := os.ReadFile(tempLogFile.Name())
+	if logReadErr != nil {
+		te.logger.LogError("Error reading rclone log file %s for job %d, config %d: %v", tempLogFile.Name(), job.ID, config.ID, logReadErr)
+		// Proceed without log content, but log the error
+	} else {
+		te.logger.LogDebug("Rclone log content for job %d, config %d:\n%s", job.ID, config.ID, string(logContent))
+
+		// --- Start Log Parsing for FileMetadata ---
+		if cmdType == "transfer" && logReadErr == nil { // Only parse for transfer commands if log was read
+			logLines := strings.Split(string(logContent), "\n")
+
+			// --- First Pass: Extract Hashes ---
+			// Regex to find lines like: "DEBUG : filename.txt: md5 = hashvalue OK"
+			// Captures filename (group 1) and hash value (group 2)
+			hashLogRegex := regexp.MustCompile(`DEBUG\s*:\s*(.*?):\s*(?:md5|sha1)\s*=\s*([a-f0-9]+)\s*OK`)
+			fileHashMap := make(map[string]string)
+			for _, line := range logLines {
+				matches := hashLogRegex.FindStringSubmatch(line)
+				if len(matches) >= 3 {
+					fileName := strings.TrimSpace(matches[1])
+					hashValue := strings.TrimSpace(matches[2])
+					if fileName != "" && hashValue != "" {
+						fileHashMap[fileName] = hashValue
+						te.logger.LogDebug("Extracted hash for %s: %s", fileName, hashValue)
+					}
+				}
+			}
+			// --- End Hash Extraction ---
+
+			// --- Second Pass: Process Copied Files and Create Metadata ---
+			// Regex to find lines like: "INFO : path/to/file.txt: Copied (new)" or "INFO : path/to/file.txt: Copied (replaced existing)"
+			// It captures the filename (group 1)
+			copyLogRegex := regexp.MustCompile(`INFO\s*:\s*(.*?):\s*Copied`)
+			processedFilesInLog := make(map[string]bool) // Track files found in log to avoid duplicates
+
+			for _, line := range logLines {
+				matches := copyLogRegex.FindStringSubmatch(line)
+				if len(matches) >= 2 {
+					fileName := strings.TrimSpace(matches[1])
+					if fileName == "" || processedFilesInLog[fileName] {
+						continue // Skip empty or duplicate filenames within the log
+					}
+					processedFilesInLog[fileName] = true // Mark as processed in this log
+
+					// Construct destination path for metadata
+					var destPathForDB string
+					destFile := fileName // Assume filename is the same unless output pattern is used (not handled here)
+					if config.DestinationType == "local" {
+						destPathForDB = filepath.Join(config.DestinationPath, destFile)
+					} else if config.DestinationType == "s3" || config.DestinationType == "minio" || config.DestinationType == "b2" {
+						if config.DestinationPath != "" && config.DestinationPath != "/" {
+							destPathForDB = fmt.Sprintf("%s/%s/%s", config.DestBucket, config.DestinationPath, destFile)
+						} else {
+							destPathForDB = fmt.Sprintf("%s/%s", config.DestBucket, destFile)
+						}
+					} else {
+						destPathForDB = fmt.Sprintf("%s/%s", config.DestinationPath, destFile)
+					}
+
+					// Get hash from the map
+					fileHash := fileHashMap[fileName] // Will be empty string if not found
+
+					// Create FileMetadata record
+					now := time.Now()
+					metadata := &db.FileMetadata{
+						JobID:           job.ID,
+						ConfigID:        config.ID,
+						FileName:        fileName,
+						OriginalPath:    config.SourcePath, // Base source path
+						FileSize:        0,                 // Unknown from log
+						FileHash:        fileHash,          // Use extracted hash
+						CreationTime:    now,               // Approximation
+						ModTime:         now,               // Approximation
+						ProcessedTime:   now,
+						DestinationPath: destPathForDB,
+						Status:          "processed", // Assumed success based on log line
+						ErrorMessage:    "",
+					}
+
+					if err := te.db.CreateFileMetadata(metadata); err != nil {
+						te.logger.LogError("Error creating file metadata from log for %s: %v", fileName, err)
+						// Don't stop processing other files
+					} else {
+						filesProcessedFromLog++
+						te.logger.LogDebug("Created file metadata from log for %s (ID: %d, Hash: %s)", fileName, metadata.ID, fileHash)
+					}
+				}
+			}
+			te.logger.LogInfo("Processed %d files based on rclone log for job %d, config %d", filesProcessedFromLog, job.ID, config.ID)
+			// --- End Metadata Creation ---
+		}
+		// --- End Log Parsing ---
+
+	}
+
 	// Update history with basic info
 	history.EndTime = &time.Time{}
 	*history.EndTime = startTime.Add(duration)
@@ -839,7 +957,7 @@ func (te *TransferExecutor) executeSimpleCommand(cmdName string, cmdType string,
 			history.FilesTransferred = lines
 			history.Status = "completed"
 		} else if cmdType == "transfer" {
-			// Try to extract transfer statistics from command output
+			// Try to extract transfer statistics from command output (stderr)
 			history.Status = "completed"
 
 			// Look for metrics in stderr which is where rclone puts stats
@@ -858,6 +976,17 @@ func (te *TransferExecutor) executeSimpleCommand(cmdName string, cmdType string,
 					history.FilesTransferred = filesTransferred
 				}
 			}
+
+			// If stats weren't found in stderr OR the log parsing yielded a count, use the log count
+			// This prioritizes the count derived from actual file processing logs.
+			if filesProcessedFromLog > 0 {
+				history.FilesTransferred = filesProcessedFromLog
+				te.logger.LogDebug("Updated FilesTransferred count to %d based on log parsing", filesProcessedFromLog)
+			} else if history.FilesTransferred == 0 && logReadErr == nil {
+				// Fallback message if stats were 0 and log parsing also yielded 0 (or wasn't applicable)
+				te.logger.LogDebug("Could not determine FilesTransferred from stderr stats or log parsing.")
+			}
+
 		} else {
 			// For other commands, we don't have file counts, but the command completed
 			history.Status = "completed"
diff --git a/internal/web/handlers/settings_handlers.go b/internal/web/handlers/settings_handlers.go
index 679a82b..a850894 100644
--- a/internal/web/handlers/settings_handlers.go
+++ b/internal/web/handlers/settings_handlers.go
@@ -1307,11 +1307,44 @@ func (h *Handlers) HandleUpdateNotificationService(c *gin.Context) {
 		return
 	}
 
+	// --- DEBUG: Print received form data ---
+	log.Println("--- Received POST Form Data (Update Notification) ---")
+	if err := c.Request.ParseForm(); err == nil {
+		postData := c.Request.PostForm
+		if len(postData) > 0 {
+			for key, values := range postData {
+				log.Printf("  %s: %v\n", key, values)
+			}
+		} else {
+			log.Println("  (No POST form data found or parsed)")
+		}
+	} else {
+		log.Printf("  Error parsing form: %v\n", err)
+	}
+	log.Println("-------------------------------------------------")
+	// --- END DEBUG ---
+
 	// Parse form data
 	name := c.PostForm("name")
 	serviceType := c.PostForm("type")
 	description := c.PostForm("description")
-	isEnabled := c.PostForm("is_enabled") == "on"
+
+	// Correctly handle boolean checkbox with hidden input
+	isEnabled := false                            // Default to false
+	if err := c.Request.ParseForm(); err == nil { // Ensure form is parsed
+		isEnabledValues := c.Request.PostForm["is_enabled"] // Get slice of values
+		for _, v := range isEnabledValues {
+			if v == "true" {
+				isEnabled = true // Checkbox was checked if "true" is present
+				break
+			}
+		}
+	} else {
+		log.Printf("Error parsing form during update: %v", err)
+		// Decide if this is a fatal error or if we can proceed assuming false
+		// For now, we proceed with isEnabled = false
+	}
+
 	eventTriggers := c.PostFormArray("event_triggers[]")
 
 	// Validate required fields
@@ -1325,7 +1358,7 @@ func (h *Handlers) HandleUpdateNotificationService(c *gin.Context) {
 	service.Type = serviceType
 	service.Description = description
 	service.EventTriggers = eventTriggers
-	service.SetIsEnabled(isEnabled) // Use setter
+	service.SetIsEnabled(isEnabled) // Use the correctly determined boolean
 
 	// Update type-specific fields based on service type
 	switch serviceType {