nathan/vctp2
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

enhance database logging
All checks were successful
continuous-integration/drone/push Build is passing
Details

Browse Source
This commit is contained in:
Nathan Coad
2026-01-16 14:28:26 +11:00
parent 588a552e4c
commit ab01c0fc4d
14 changed files with 1406 additions and 68 deletions
Download Patch File Download Diff File Expand all files Collapse all files

188
db/helpers.go
View File

@@ -5,6 +5,7 @@ import (
"database/sql"
"fmt"
"log/slog"
"sort"
"strings"
"time"
@@ -33,7 +34,7 @@ func TableRowCount(ctx context.Context, dbConn *sqlx.DB, table string) (int64, e
}
var count int64
query := fmt.Sprintf(`SELECT COUNT(*) FROM %s`, table)
if err := dbConn.GetContext(ctx, &count, query); err != nil {
if err := getLog(ctx, dbConn, &count, query); err != nil {
return 0, err
}
return count, nil
@@ -52,13 +53,37 @@ func EnsureColumns(ctx context.Context, dbConn *sqlx.DB, tableName string, colum
return nil
}
func execLog(ctx context.Context, dbConn *sqlx.DB, query string, args ...interface{}) (sql.Result, error) {
res, err := dbConn.ExecContext(ctx, query, args...)
if err != nil {
slog.Warn("db exec failed", "query", strings.TrimSpace(query), "error", err)
}
return res, err
}
func getLog(ctx context.Context, dbConn *sqlx.DB, dest interface{}, query string, args ...interface{}) error {
err := dbConn.GetContext(ctx, dest, query, args...)
if err != nil {
slog.Warn("db get failed", "query", strings.TrimSpace(query), "error", err)
}
return err
}
func selectLog(ctx context.Context, dbConn *sqlx.DB, dest interface{}, query string, args ...interface{}) error {
err := dbConn.SelectContext(ctx, dest, query, args...)
if err != nil {
slog.Warn("db select failed", "query", strings.TrimSpace(query), "error", err)
}
return err
}
// AddColumnIfMissing performs a best-effort ALTER TABLE to add a column, ignoring "already exists".
func AddColumnIfMissing(ctx context.Context, dbConn *sqlx.DB, tableName string, column ColumnDef) error {
if _, err := SafeTableName(tableName); err != nil {
return err
}
query := fmt.Sprintf(`ALTER TABLE %s ADD COLUMN "%s" %s`, tableName, column.Name, column.Type)
if _, err := dbConn.ExecContext(ctx, query); err != nil {
if _, err := execLog(ctx, dbConn, query); err != nil {
errText := strings.ToLower(err.Error())
if strings.Contains(errText, "duplicate column") || strings.Contains(errText, "already exists") {
return nil
@@ -97,7 +122,7 @@ func TableHasRows(ctx context.Context, dbConn *sqlx.DB, table string) (bool, err
}
query := fmt.Sprintf(`SELECT 1 FROM %s LIMIT 1`, table)
var exists int
if err := dbConn.GetContext(ctx, &exists, query); err != nil {
if err := getLog(ctx, dbConn, &exists, query); err != nil {
if err == sql.ErrNoRows {
return false, nil
}
@@ -116,7 +141,7 @@ func TableExists(ctx context.Context, dbConn *sqlx.DB, table string) bool {
return err == nil && count > 0
case "pgx", "postgres":
var count int
err := dbConn.GetContext(ctx, &count, `
err := getLog(ctx, dbConn, &count, `
SELECT COUNT(1)
FROM pg_catalog.pg_tables
WHERE schemaname = 'public' AND tablename = $1
@@ -160,7 +185,7 @@ func ColumnExists(ctx context.Context, dbConn *sqlx.DB, tableName string, column
return false, rows.Err()
case "pgx", "postgres":
var count int
err := dbConn.GetContext(ctx, &count, `
err := getLog(ctx, dbConn, &count, `
SELECT COUNT(1)
FROM information_schema.columns
WHERE table_name = $1 AND column_name = $2
@@ -189,7 +214,7 @@ FROM %s
`, table)
var totals SnapshotTotals
if err := dbConn.GetContext(ctx, &totals, query); err != nil {
if err := getLog(ctx, dbConn, &totals, query); err != nil {
return SnapshotTotals{}, err
}
return totals, nil
@@ -209,7 +234,7 @@ FROM (
`, unionQuery)
var totals SnapshotTotals
if err := dbConn.GetContext(ctx, &totals, query); err != nil {
if err := getLog(ctx, dbConn, &totals, query); err != nil {
return SnapshotTotals{}, err
}
return totals, nil
@@ -274,7 +299,7 @@ func EnsureSnapshotTable(ctx context.Context, dbConn *sqlx.DB, tableName string)
);`, tableName)
}
_, err := dbConn.ExecContext(ctx, ddl)
_, err := execLog(ctx, dbConn, ddl)
if err != nil {
return err
}
@@ -303,7 +328,7 @@ func EnsureSnapshotIndexes(ctx context.Context, dbConn *sqlx.DB, tableName strin
)
}
for _, idx := range indexes {
if _, err := dbConn.ExecContext(ctx, idx); err != nil {
if _, err := execLog(ctx, dbConn, idx); err != nil {
return err
}
}
@@ -322,7 +347,7 @@ func BackfillSerialColumn(ctx context.Context, dbConn *sqlx.DB, tableName, colum
`UPDATE %s SET "%s" = nextval(pg_get_serial_sequence('%s','%s')) WHERE "%s" IS NULL`,
tableName, columnName, tableName, columnName, columnName,
)
_, err := dbConn.ExecContext(ctx, query)
_, err := execLog(ctx, dbConn, query)
if err != nil {
errText := strings.ToLower(err.Error())
if strings.Contains(errText, "pg_get_serial_sequence") || strings.Contains(errText, "sequence") {
@@ -347,7 +372,7 @@ func ApplySQLiteTuning(ctx context.Context, dbConn *sqlx.DB) {
`PRAGMA optimize;`,
}
for _, pragma := range pragmas {
_, err = dbConn.ExecContext(ctx, pragma)
_, err = execLog(ctx, dbConn, pragma)
if logger, ok := ctx.Value("logger").(*slog.Logger); ok && logger != nil {
logger.Debug("Applied SQLite tuning pragma", "pragma", pragma, "error", err)
}
@@ -408,10 +433,10 @@ CREATE TABLE IF NOT EXISTS vm_renames (
"SnapshotTime" BIGINT NOT NULL
)`
}
if _, err := dbConn.ExecContext(ctx, identityDDL); err != nil {
if _, err := execLog(ctx, dbConn, identityDDL); err != nil {
return err
}
if _, err := dbConn.ExecContext(ctx, renameDDL); err != nil {
if _, err := execLog(ctx, dbConn, renameDDL); err != nil {
return err
}
indexes := []string{
@@ -421,7 +446,7 @@ CREATE TABLE IF NOT EXISTS vm_renames (
`CREATE INDEX IF NOT EXISTS vm_renames_vcenter_idx ON vm_renames ("Vcenter","SnapshotTime")`,
}
for _, idx := range indexes {
if _, err := dbConn.ExecContext(ctx, idx); err != nil {
if _, err := execLog(ctx, dbConn, idx); err != nil {
return err
}
}
@@ -446,7 +471,7 @@ func UpsertVmIdentity(ctx context.Context, dbConn *sqlx.DB, vcenter string, vmId
LastSeen sql.NullInt64 `db:"LastSeen"`
}
var existing identityRow
err := dbConn.GetContext(ctx, &existing, `
err := getLog(ctx, dbConn, &existing, `
SELECT "Name","Cluster","FirstSeen","LastSeen"
FROM vm_identity
WHERE "Vcenter" = $1 AND "VmId" = $2 AND "VmUuid" = $3
@@ -454,7 +479,7 @@ WHERE "Vcenter" = $1 AND "VmId" = $2 AND "VmUuid" = $3
if err != nil {
if strings.Contains(strings.ToLower(err.Error()), "no rows") {
_, err = dbConn.ExecContext(ctx, `
_, err = execLog(ctx, dbConn, `
INSERT INTO vm_identity ("VmId","VmUuid","Vcenter","Name","Cluster","FirstSeen","LastSeen")
VALUES ($1,$2,$3,$4,$5,$6,$6)
`, keyVmID, keyUuid, vcenter, name, nullString(cluster), snapshotTime.Unix())
@@ -465,12 +490,12 @@ VALUES ($1,$2,$3,$4,$5,$6,$6)
renamed := !strings.EqualFold(existing.Name, name) || !strings.EqualFold(strings.TrimSpace(existing.Cluster.String), strings.TrimSpace(cluster.String))
if renamed {
_, _ = dbConn.ExecContext(ctx, `
_, _ = execLog(ctx, dbConn, `
INSERT INTO vm_renames ("VmId","VmUuid","Vcenter","OldName","NewName","OldCluster","NewCluster","SnapshotTime")
VALUES ($1,$2,$3,$4,$5,$6,$7,$8)
`, keyVmID, keyUuid, vcenter, existing.Name, name, existing.Cluster.String, cluster.String, snapshotTime.Unix())
}
_, err = dbConn.ExecContext(ctx, `
_, err = execLog(ctx, dbConn, `
UPDATE vm_identity
SET "Name" = $1, "Cluster" = $2, "LastSeen" = $3
WHERE "Vcenter" = $4 AND "VmId" = $5 AND "VmUuid" = $6
@@ -511,14 +536,14 @@ CREATE TABLE IF NOT EXISTS vcenter_totals (
"RamTotalGB" BIGINT NOT NULL
);`
}
if _, err := dbConn.ExecContext(ctx, ddl); err != nil {
if _, err := execLog(ctx, dbConn, ddl); err != nil {
return err
}
indexes := []string{
`CREATE INDEX IF NOT EXISTS vcenter_totals_vc_time_idx ON vcenter_totals ("Vcenter","SnapshotTime" DESC)`,
}
for _, idx := range indexes {
if _, err := dbConn.ExecContext(ctx, idx); err != nil {
if _, err := execLog(ctx, dbConn, idx); err != nil {
return err
}
}
@@ -533,7 +558,7 @@ func InsertVcenterTotals(ctx context.Context, dbConn *sqlx.DB, vcenter string, s
if err := EnsureVcenterTotalsTable(ctx, dbConn); err != nil {
return err
}
_, err := dbConn.ExecContext(ctx, `
_, err := execLog(ctx, dbConn, `
INSERT INTO vcenter_totals ("Vcenter","SnapshotTime","VmCount","VcpuTotal","RamTotalGB")
VALUES ($1,$2,$3,$4,$5)
`, vcenter, snapshotTime.Unix(), vmCount, vcpuTotal, ramTotal)
@@ -585,7 +610,7 @@ FROM vcenter_totals
WHERE "Vcenter" = $1
ORDER BY "SnapshotTime" DESC
LIMIT $2`
if err := dbConn.SelectContext(ctx, &rows, query, vcenter, limit); err != nil {
if err := selectLog(ctx, dbConn, &rows, query, vcenter, limit); err != nil {
return nil, err
}
return rows, nil
@@ -623,7 +648,7 @@ LIMIT $2
TableName string `db:"table_name"`
SnapshotTime int64 `db:"snapshot_time"`
}
if err := dbConn.SelectContext(ctx, &regRows, query, snapshotType, limit); err != nil {
if err := selectLog(ctx, dbConn, &regRows, query, snapshotType, limit); err != nil {
return nil, err
}
@@ -671,12 +696,87 @@ WHERE "Vcenter" = $1
query = strings.ReplaceAll(query, "$1", "?")
}
var agg summaryAgg
if err := dbConn.GetContext(ctx, &agg, query, vcenter); err != nil {
if err := getLog(ctx, dbConn, &agg, query, vcenter); err != nil {
return summaryAgg{}, err
}
return agg, nil
}
// VmTraceRow holds snapshot data for a single VM across tables.
type VmTraceRow struct {
SnapshotTime int64 `db:"SnapshotTime"`
Name string `db:"Name"`
Vcenter string `db:"Vcenter"`
VmId string `db:"VmId"`
VmUuid string `db:"VmUuid"`
ResourcePool string `db:"ResourcePool"`
VcpuCount int64 `db:"VcpuCount"`
RamGB int64 `db:"RamGB"`
ProvisionedDisk float64 `db:"ProvisionedDisk"`
CreationTime sql.NullInt64 `db:"CreationTime"`
DeletionTime sql.NullInt64 `db:"DeletionTime"`
}
// FetchVmTrace returns combined hourly snapshot records for a VM (by id/uuid/name) ordered by snapshot time.
// To avoid SQLite's UNION term limits, this iterates tables one by one and merges in-memory.
func FetchVmTrace(ctx context.Context, dbConn *sqlx.DB, vmID, vmUUID, name string) ([]VmTraceRow, error) {
var tables []struct {
TableName string `db:"table_name"`
SnapshotTime int64 `db:"snapshot_time"`
}
if err := selectLog(ctx, dbConn, &tables, `
SELECT table_name, snapshot_time
FROM snapshot_registry
WHERE snapshot_type = 'hourly'
ORDER BY snapshot_time
`); err != nil {
return nil, err
}
if len(tables) == 0 {
return nil, nil
}
rows := make([]VmTraceRow, 0, len(tables))
driver := strings.ToLower(dbConn.DriverName())
slog.Debug("vm trace scanning tables", "table_count", len(tables), "vm_id", vmID, "vm_uuid", vmUUID, "name", name)
for _, t := range tables {
if err := ValidateTableName(t.TableName); err != nil {
slog.Warn("vm trace skipping table (invalid name)", "table", t.TableName, "error", err)
continue
}
query := fmt.Sprintf(`
SELECT %d AS "SnapshotTime",
"Name","Vcenter","VmId","VmUuid","ResourcePool","VcpuCount","RamGB","ProvisionedDisk",
COALESCE("CreationTime",0) AS "CreationTime",
COALESCE("DeletionTime",0) AS "DeletionTime"
FROM %s
WHERE ("VmId" = ? OR "VmUuid" = ? OR lower("Name") = lower(?))
`, t.SnapshotTime, t.TableName)
args := []interface{}{vmID, vmUUID, name}
if driver != "sqlite" {
// convert ? to $1 style for postgres/pgx
query = strings.Replace(query, "?", "$1", 1)
query = strings.Replace(query, "?", "$2", 1)
query = strings.Replace(query, "?", "$3", 1)
}
var tmp []VmTraceRow
if err := selectLog(ctx, dbConn, &tmp, query, args...); err != nil {
slog.Warn("vm trace query failed for table", "table", t.TableName, "error", err)
continue
}
slog.Debug("vm trace table rows", "table", t.TableName, "snapshot_time", t.SnapshotTime, "rows", len(tmp))
rows = append(rows, tmp...)
}
sort.Slice(rows, func(i, j int) bool {
return rows[i].SnapshotTime < rows[j].SnapshotTime
})
slog.Info("vm trace combined rows", "total_rows", len(rows))
return rows, nil
}
// SyncVcenterTotalsFromSnapshots backfills vcenter_totals using hourly snapshot tables in snapshot_registry.
func SyncVcenterTotalsFromSnapshots(ctx context.Context, dbConn *sqlx.DB) error {
if err := EnsureVcenterTotalsTable(ctx, dbConn); err != nil {
@@ -687,7 +787,7 @@ func SyncVcenterTotalsFromSnapshots(ctx context.Context, dbConn *sqlx.DB) error
TableName string `db:"table_name"`
SnapshotTime int64 `db:"snapshot_time"`
}
if err := dbConn.SelectContext(ctx, &hourlyTables, `
if err := selectLog(ctx, dbConn, &hourlyTables, `
SELECT table_name, snapshot_time
FROM snapshot_registry
WHERE snapshot_type = 'hourly'
@@ -715,7 +815,7 @@ GROUP BY "Vcenter"
RamTotal int64 `db:"ram_total"`
}
var aggs []aggRow
if err := dbConn.SelectContext(ctx, &aggs, query); err != nil {
if err := selectLog(ctx, dbConn, &aggs, query); err != nil {
continue
}
for _, a := range aggs {
@@ -730,7 +830,9 @@ WHERE NOT EXISTS (
if driver == "sqlite" {
insert = strings.ReplaceAll(insert, "$", "?")
}
_, _ = dbConn.ExecContext(ctx, insert, a.Vcenter, ht.SnapshotTime, a.VmCount, a.VcpuTotal, a.RamTotal)
if _, err := execLog(ctx, dbConn, insert, a.Vcenter, ht.SnapshotTime, a.VmCount, a.VcpuTotal, a.RamTotal); err != nil {
slog.Warn("failed to backfill vcenter_totals", "table", ht.TableName, "vcenter", a.Vcenter, "snapshot_time", ht.SnapshotTime, "error", err)
}
}
}
return nil
@@ -745,7 +847,9 @@ func AnalyzeTableIfPostgres(ctx context.Context, dbConn *sqlx.DB, tableName stri
if driver != "pgx" && driver != "postgres" {
return
}
_, _ = dbConn.ExecContext(ctx, fmt.Sprintf(`ANALYZE %s`, tableName))
if _, err := execLog(ctx, dbConn, fmt.Sprintf(`ANALYZE %s`, tableName)); err != nil {
slog.Warn("failed to ANALYZE table", "table", tableName, "error", err)
}
}
// SetPostgresWorkMem sets a per-session work_mem for heavy aggregations; no-op for other drivers.
@@ -757,7 +861,9 @@ func SetPostgresWorkMem(ctx context.Context, dbConn *sqlx.DB, workMemMB int) {
if driver != "pgx" && driver != "postgres" {
return
}
_, _ = dbConn.ExecContext(ctx, fmt.Sprintf(`SET LOCAL work_mem = '%dMB'`, workMemMB))
if _, err := execLog(ctx, dbConn, fmt.Sprintf(`SET LOCAL work_mem = '%dMB'`, workMemMB)); err != nil {
slog.Warn("failed to set work_mem", "work_mem_mb", workMemMB, "error", err)
}
}
// CheckMigrationState ensures goose migrations are present and not dirty.
@@ -766,14 +872,14 @@ func CheckMigrationState(ctx context.Context, dbConn *sqlx.DB) error {
var tableExists bool
switch driver {
case "sqlite":
err := dbConn.GetContext(ctx, &tableExists, `
err := getLog(ctx, dbConn, &tableExists, `
SELECT COUNT(1) > 0 FROM sqlite_master WHERE type='table' AND name='goose_db_version'
`)
if err != nil {
return err
}
case "pgx", "postgres":
err := dbConn.GetContext(ctx, &tableExists, `
err := getLog(ctx, dbConn, &tableExists, `
SELECT EXISTS (
SELECT 1 FROM pg_tables WHERE schemaname = 'public' AND tablename = 'goose_db_version'
)
@@ -790,7 +896,7 @@ SELECT EXISTS (
}
var dirty bool
err := dbConn.GetContext(ctx, &dirty, `
err := getLog(ctx, dbConn, &dirty, `
SELECT NOT is_applied
FROM goose_db_version
ORDER BY id DESC
@@ -1061,7 +1167,7 @@ WHERE EXISTS (
`, unionQuery, summaryTable)
}
_, err := dbConn.ExecContext(ctx, sql)
_, err := execLog(ctx, dbConn, sql)
return err
}
@@ -1230,13 +1336,13 @@ func EnsureSummaryTable(ctx context.Context, dbConn *sqlx.DB, tableName string)
);`, tableName)
}
if _, err := dbConn.ExecContext(ctx, ddl); err != nil {
if _, err := execLog(ctx, dbConn, ddl); err != nil {
return err
}
// Best-effort: drop legacy IsPresent column if it exists.
if hasIsPresent, err := ColumnExists(ctx, dbConn, tableName, "IsPresent"); err == nil && hasIsPresent {
_, _ = dbConn.ExecContext(ctx, fmt.Sprintf(`ALTER TABLE %s DROP COLUMN "IsPresent"`, tableName))
_, _ = execLog(ctx, dbConn, fmt.Sprintf(`ALTER TABLE %s DROP COLUMN "IsPresent"`, tableName))
}
indexes := []string{
@@ -1250,7 +1356,7 @@ func EnsureSummaryTable(ctx context.Context, dbConn *sqlx.DB, tableName string)
)
}
for _, idx := range indexes {
if _, err := dbConn.ExecContext(ctx, idx); err != nil {
if _, err := execLog(ctx, dbConn, idx); err != nil {
return err
}
}
@@ -1283,7 +1389,7 @@ CREATE TABLE IF NOT EXISTS snapshot_runs (
);
`
}
if _, err := dbConn.ExecContext(ctx, ddl); err != nil {
if _, err := execLog(ctx, dbConn, ddl); err != nil {
return err
}
indexes := []string{
@@ -1291,7 +1397,7 @@ CREATE TABLE IF NOT EXISTS snapshot_runs (
`CREATE INDEX IF NOT EXISTS snapshot_runs_success_idx ON snapshot_runs ("Success")`,
}
for _, idx := range indexes {
if _, err := dbConn.ExecContext(ctx, idx); err != nil {
if _, err := execLog(ctx, dbConn, idx); err != nil {
return err
}
}
@@ -1311,7 +1417,7 @@ func UpsertSnapshotRun(ctx context.Context, dbConn *sqlx.DB, vcenter string, sna
driver := strings.ToLower(dbConn.DriverName())
switch driver {
case "sqlite":
_, err := dbConn.ExecContext(ctx, `
_, err := execLog(ctx, dbConn, `
INSERT INTO snapshot_runs ("Vcenter","SnapshotTime","Attempts","Success","LastError","LastAttempt")
VALUES (?, ?, 1, ?, ?, ?)
ON CONFLICT("Vcenter","SnapshotTime") DO UPDATE SET
@@ -1322,7 +1428,7 @@ ON CONFLICT("Vcenter","SnapshotTime") DO UPDATE SET
`, vcenter, snapshotTime.Unix(), successStr, errMsg, now)
return err
case "pgx", "postgres":
_, err := dbConn.ExecContext(ctx, `
_, err := execLog(ctx, dbConn, `
INSERT INTO snapshot_runs ("Vcenter","SnapshotTime","Attempts","Success","LastError","LastAttempt")
VALUES ($1, $2, 1, $3, $4, $5)
ON CONFLICT("Vcenter","SnapshotTime") DO UPDATE SET
@@ -1368,7 +1474,7 @@ ORDER BY "LastAttempt" ASC
Attempts int `db:"Attempts"`
}
rows := []row{}
if err := dbConn.SelectContext(ctx, &rows, query, args...); err != nil {
if err := selectLog(ctx, dbConn, &rows, query, args...); err != nil {
return nil, err
}
results := make([]struct {