From f1be31781cc2f3debc370d7c69df46754553af64 Mon Sep 17 00:00:00 2001 From: Nathan Coad Date: Wed, 11 Feb 2026 11:24:27 +1100 Subject: [PATCH] improve logging --- internal/settings/settings.go | 19 +++++ internal/settings/settings_redaction_test.go | 29 +++++++ internal/tasks/dailyAggregate.go | 84 +++++++++++++++----- 3 files changed, 110 insertions(+), 22 deletions(-) create mode 100644 internal/settings/settings_redaction_test.go diff --git a/internal/settings/settings.go b/internal/settings/settings.go index 3a15ee7..a0dc0cc 100644 --- a/internal/settings/settings.go +++ b/internal/settings/settings.go @@ -6,11 +6,18 @@ import ( "log/slog" "os" "path/filepath" + "regexp" + "strings" "vctp/internal/utils" "gopkg.in/yaml.v2" ) +var ( + postgresURIUserInfoPasswordPattern = regexp.MustCompile(`(?i)(postgres(?:ql)?://[^@/\s]*:)([^@/\s]*)(@)`) + postgresKVPasswordPattern = regexp.MustCompile(`(?i)(\bpassword\s*=\s*)(?:'[^']*'|"[^"]*"|[^\s]+)`) +) + type Settings struct { SettingsPath string Logger *slog.Logger @@ -102,12 +109,24 @@ func (s *Settings) ReadYMLSettings() error { if redacted.Settings.EncryptionKey != "" { redacted.Settings.EncryptionKey = "REDACTED" } + if redacted.Settings.DatabaseURL != "" { + redacted.Settings.DatabaseURL = redactDatabaseURL(redacted.Settings.DatabaseURL) + } s.Logger.Debug("Updating settings", "settings", redacted) s.Values = &settings return nil } +func redactDatabaseURL(databaseURL string) string { + if strings.TrimSpace(databaseURL) == "" { + return databaseURL + } + redacted := postgresURIUserInfoPasswordPattern.ReplaceAllString(databaseURL, `${1}REDACTED${3}`) + redacted = postgresKVPasswordPattern.ReplaceAllString(redacted, `${1}REDACTED`) + return redacted +} + func (s *Settings) WriteYMLSettings() error { if s.Values == nil { return errors.New("settings are not loaded") diff --git a/internal/settings/settings_redaction_test.go b/internal/settings/settings_redaction_test.go new file mode 100644 index 0000000..9661ab5 --- /dev/null +++ b/internal/settings/settings_redaction_test.go @@ -0,0 +1,29 @@ +package settings + +import "testing" + +func TestRedactDatabaseURL_PostgresURI(t *testing.T) { + input := "postgres://vctp_user:Secr3tP%40ss@db-host:5432/vctp?sslmode=disable" + got := redactDatabaseURL(input) + want := "postgres://vctp_user:REDACTED@db-host:5432/vctp?sslmode=disable" + if got != want { + t.Fatalf("unexpected redaction result\nwant: %s\ngot: %s", want, got) + } +} + +func TestRedactDatabaseURL_PostgresKeyValue(t *testing.T) { + input := "host=db-host port=5432 dbname=vctp user=vctp_user password='P@ss:w0rd#%' sslmode=disable" + got := redactDatabaseURL(input) + want := "host=db-host port=5432 dbname=vctp user=vctp_user password=REDACTED sslmode=disable" + if got != want { + t.Fatalf("unexpected redaction result\nwant: %s\ngot: %s", want, got) + } +} + +func TestRedactDatabaseURL_UnchangedWhenNoPassword(t *testing.T) { + input := "host=db-host port=5432 dbname=vctp user=vctp_user sslmode=disable" + got := redactDatabaseURL(input) + if got != input { + t.Fatalf("expected input to remain unchanged\nwant: %s\ngot: %s", input, got) + } +} diff --git a/internal/tasks/dailyAggregate.go b/internal/tasks/dailyAggregate.go index 9edf631..7829d79 100644 --- a/internal/tasks/dailyAggregate.go +++ b/internal/tasks/dailyAggregate.go @@ -315,21 +315,59 @@ LIMIT 1 } nextSnapshotRows.Close() } - nextPresence := make(map[string]struct{}) + + // Build per-vCenter snapshot timelines from observed VM samples so deletion + // inference is only based on times where that vCenter actually reported data. + vcenterTimeSet := make(map[string]map[int64]struct{}, 8) + for _, v := range aggMap { + if v.key.Vcenter == "" { + continue + } + set := vcenterTimeSet[v.key.Vcenter] + if set == nil { + set = make(map[int64]struct{}, len(v.seen)) + vcenterTimeSet[v.key.Vcenter] = set + } + for t := range v.seen { + if t > 0 { + set[t] = struct{}{} + } + } + } + vcenterSnapTimes := make(map[string][]int64, len(vcenterTimeSet)) + for vcenter, set := range vcenterTimeSet { + times := make([]int64, 0, len(set)) + for t := range set { + times = append(times, t) + } + sort.Slice(times, func(i, j int) bool { return times[i] < times[j] }) + vcenterSnapTimes[vcenter] = times + } + + nextPresenceByVcenter := make(map[string]map[string]struct{}, 8) if nextSnapshotTable != "" && db.TableExists(ctx, dbConn, nextSnapshotTable) { - rows, err := querySnapshotRows(ctx, dbConn, nextSnapshotTable, []string{"VmId", "VmUuid", "Name"}, `"Vcenter" = ?`, c.Settings.Values.Settings.VcenterAddresses[0]) + rows, err := querySnapshotRows(ctx, dbConn, nextSnapshotTable, []string{"Vcenter", "VmId", "VmUuid", "Name"}, "") if err == nil { for rows.Next() { + var vcenter string var vmId, vmUuid, name sql.NullString - if err := rows.Scan(&vmId, &vmUuid, &name); err == nil { - if vmId.Valid { - nextPresence["id:"+vmId.String] = struct{}{} + if err := rows.Scan(&vcenter, &vmId, &vmUuid, &name); err == nil { + if strings.TrimSpace(vcenter) == "" { + continue } - if vmUuid.Valid { - nextPresence["uuid:"+vmUuid.String] = struct{}{} + vcPresence := nextPresenceByVcenter[vcenter] + if vcPresence == nil { + vcPresence = make(map[string]struct{}, 1024) + nextPresenceByVcenter[vcenter] = vcPresence } - if name.Valid { - nextPresence["name:"+name.String] = struct{}{} + if vmId.Valid && strings.TrimSpace(vmId.String) != "" { + vcPresence["id:"+strings.TrimSpace(vmId.String)] = struct{}{} + } + if vmUuid.Valid && strings.TrimSpace(vmUuid.String) != "" { + vcPresence["uuid:"+strings.TrimSpace(vmUuid.String)] = struct{}{} + } + if name.Valid && strings.TrimSpace(name.String) != "" { + vcPresence["name:"+strings.ToLower(strings.TrimSpace(name.String))] = struct{}{} } } } @@ -337,23 +375,24 @@ LIMIT 1 } } - var maxSnap int64 - if len(snapTimes) > 0 { - maxSnap = snapTimes[len(snapTimes)-1] - } - inferredDeletions := 0 for _, v := range aggMap { if v.deletion != 0 { continue } + vcSnapTimes := vcenterSnapTimes[v.key.Vcenter] + // Deletion inference needs meaningful per-vCenter continuity. + if len(vcSnapTimes) < 3 { + continue + } + vcMaxSnap := vcSnapTimes[len(vcSnapTimes)-1] // Infer deletion only after seeing at least two consecutive absent snapshots after lastSeen. - if maxSnap > 0 && len(v.seen) > 0 && v.lastSeen < maxSnap { - c.Logger.Debug("inferring deletion window", "vm_id", v.key.VmId, "vm_uuid", v.key.VmUuid, "name", v.key.Name, "last_seen", v.lastSeen, "snapshots", len(snapTimes)) + if vcMaxSnap > 0 && len(v.seen) > 0 && v.lastSeen < vcMaxSnap { + c.Logger.Debug("inferring deletion window", "vcenter", v.key.Vcenter, "vm_id", v.key.VmId, "vm_uuid", v.key.VmUuid, "name", v.key.Name, "last_seen", v.lastSeen, "snapshots", len(vcSnapTimes)) } consecutiveMisses := 0 firstMiss := int64(0) - for _, t := range snapTimes { + for _, t := range vcSnapTimes { if t <= v.lastSeen { continue } @@ -374,18 +413,19 @@ LIMIT 1 } if v.deletion == 0 && firstMiss > 0 { // Not enough consecutive misses within the day; try to use the first snapshot of the next day to confirm. + nextPresence := nextPresenceByVcenter[v.key.Vcenter] if nextSnapshotTable != "" && len(nextPresence) > 0 { - _, presentByID := nextPresence["id:"+v.key.VmId] - _, presentByUUID := nextPresence["uuid:"+v.key.VmUuid] - _, presentByName := nextPresence["name:"+v.key.Name] + _, presentByID := nextPresence["id:"+strings.TrimSpace(v.key.VmId)] + _, presentByUUID := nextPresence["uuid:"+strings.TrimSpace(v.key.VmUuid)] + _, presentByName := nextPresence["name:"+strings.ToLower(strings.TrimSpace(v.key.Name))] if !presentByID && !presentByUUID && !presentByName { v.deletion = firstMiss inferredDeletions++ - c.Logger.Debug("cross-day deletion inferred from next snapshot", "vm_id", v.key.VmId, "vm_uuid", v.key.VmUuid, "name", v.key.Name, "deletion", firstMiss, "next_table", nextSnapshotTable) + c.Logger.Debug("cross-day deletion inferred from next snapshot", "vcenter", v.key.Vcenter, "vm_id", v.key.VmId, "vm_uuid", v.key.VmUuid, "name", v.key.Name, "deletion", firstMiss, "next_table", nextSnapshotTable) } } if v.deletion == 0 { - c.Logger.Debug("pending deletion inference (insufficient consecutive misses)", "vm_id", v.key.VmId, "vm_uuid", v.key.VmUuid, "name", v.key.Name, "last_seen", v.lastSeen, "first_missing_snapshot", firstMiss) + c.Logger.Debug("pending deletion inference (insufficient consecutive misses)", "vcenter", v.key.Vcenter, "vm_id", v.key.VmId, "vm_uuid", v.key.VmUuid, "name", v.key.Name, "last_seen", v.lastSeen, "first_missing_snapshot", firstMiss) } } }