Files
admin 95c821deb2 feat: comprehensive debug logging across all controller modules
Add detailed [DEBUG] logging to every controller module when
logging.level is set to "debug". Each module with stateful debug
uses SetDebug(bool) wired from main.go. Covers stacks, backup,
cloudflare, integrations, system, monitor, settings, scheduler,
web handlers, storage, metrics, API, selfupdate, and assets.

Also includes the app export/import (.fab bundles) feature from
v0.32.0 and its debug page integration.

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
2026-02-26 18:14:43 +01:00

794 lines
22 KiB
Go

package appexport
import (
"archive/tar"
"compress/gzip"
"context"
"fmt"
"io"
"log"
"os"
"os/exec"
"path/filepath"
"strings"
"sync"
"time"
"gitea.dooplex.hu/admin/felhom-controller/internal/backup"
)
// Step tracks one step of an export/import operation.
type Step struct {
Label string `json:"label"`
Status string `json:"status"` // "pending", "running", "done", "failed"
Error string `json:"error,omitempty"`
}
// Job tracks an in-progress export or import operation.
type Job struct {
mu sync.RWMutex
StackName string `json:"stack_name"`
DisplayName string `json:"display_name"`
Steps []Step `json:"steps"`
Running bool `json:"running"`
Done bool `json:"done"`
Error string `json:"error,omitempty"`
OutputPath string `json:"output_path,omitempty"`
OutputSize string `json:"output_size,omitempty"`
JobType string `json:"job_type"` // "export" or "import"
}
// Snapshot returns a thread-safe copy for JSON serialization.
func (j *Job) Snapshot() map[string]interface{} {
j.mu.RLock()
defer j.mu.RUnlock()
steps := make([]Step, len(j.Steps))
copy(steps, j.Steps)
return map[string]interface{}{
"ok": true,
"running": j.Running,
"done": j.Done,
"error": j.Error,
"steps": steps,
"output_path": j.OutputPath,
"output_size": j.OutputSize,
"stack_name": j.StackName,
"display_name": j.DisplayName,
"job_type": j.JobType,
}
}
func (j *Job) setStep(idx int, status, errMsg string) {
j.mu.Lock()
defer j.mu.Unlock()
if idx < len(j.Steps) {
j.Steps[idx].Status = status
j.Steps[idx].Error = errMsg
}
}
// ExportRequest holds user-provided parameters for an export.
type ExportRequest struct {
StackName string
DestDrive string // drive mount path (e.g., "/mnt/hdd_1")
Password string // empty = no encryption
StopApp bool // stop app before export
}
// Exporter manages app export/import operations.
type Exporter struct {
provider ExportStackProvider
logger *log.Logger
version string
debug bool
mu sync.Mutex
activeJob *Job
}
// NewExporter creates a new export/import engine.
func NewExporter(provider ExportStackProvider, logger *log.Logger, version string) *Exporter {
return &Exporter{
provider: provider,
logger: logger,
version: version,
}
}
// SetDebug enables or disables verbose debug logging.
func (e *Exporter) SetDebug(debug bool) {
e.debug = debug
}
// debugf logs a message only when debug mode is enabled.
func (e *Exporter) debugf(format string, args ...interface{}) {
if e.debug {
e.logger.Printf("[DEBUG] [appexport] "+format, args...)
}
}
// IsRunning returns true if an export/import is in progress.
func (e *Exporter) IsRunning() bool {
e.mu.Lock()
defer e.mu.Unlock()
return e.activeJob != nil && e.activeJob.Running
}
// GetActiveJob returns the current job (for status polling).
func (e *Exporter) GetActiveJob() *Job {
e.mu.Lock()
defer e.mu.Unlock()
return e.activeJob
}
// StartExport validates and starts an async export. Returns error if blocked.
func (e *Exporter) StartExport(req ExportRequest) error {
e.mu.Lock()
if e.activeJob != nil && e.activeJob.Running {
e.mu.Unlock()
e.debugf("StartExport rejected: another job is already running")
return fmt.Errorf("export or import already in progress")
}
if !e.provider.IsStackDeployed(req.StackName) {
e.mu.Unlock()
e.debugf("StartExport rejected: stack %q is not deployed", req.StackName)
return fmt.Errorf("stack %q is not deployed", req.StackName)
}
e.debugf("StartExport: stack=%q dest=%q password=%v stopApp=%v",
req.StackName, req.DestDrive, req.Password != "", req.StopApp)
steps := []Step{
{Label: "Előkészítés", Status: "pending"},
{Label: "Konfiguráció mentése", Status: "pending"},
{Label: "Adatbázis mentése", Status: "pending"},
{Label: "Felhasználói adatok", Status: "pending"},
{Label: "Csomag készítése", Status: "pending"},
}
if req.Password != "" {
steps = append(steps, Step{Label: "Titkosítás", Status: "pending"})
}
job := &Job{
StackName: req.StackName,
DisplayName: e.provider.GetStackDisplayName(req.StackName),
Steps: steps,
Running: true,
JobType: "export",
}
e.activeJob = job
e.mu.Unlock()
go e.executeExport(req, job)
return nil
}
func (e *Exporter) executeExport(req ExportRequest, job *Job) {
exportStart := time.Now()
e.debugf("=== EXPORT START: stack=%q dest=%q encrypted=%v stopApp=%v ===",
req.StackName, req.DestDrive, req.Password != "", req.StopApp)
defer func() {
job.mu.Lock()
job.Running = false
job.Done = true
job.mu.Unlock()
e.debugf("=== EXPORT END: stack=%q elapsed=%v ===", req.StackName, time.Since(exportStart))
}()
step := 0
// --- Step 0: Preparation ---
job.setStep(step, "running", "")
stepStart := time.Now()
destDir := ExportDir(req.DestDrive)
e.debugf("export dest dir: %s", destDir)
if err := os.MkdirAll(destDir, 0755); err != nil {
e.failJob(job, step, fmt.Sprintf("Nem sikerült létrehozni az export könyvtárat: %v", err))
return
}
// Check free space
est, err := e.EstimateExport(req.StackName, req.DestDrive)
if err != nil {
e.debugf("estimate error (non-fatal): %v", err)
} else {
e.debugf("estimate: config=%s data=%s total=%s destFree=%s fits=%v",
est.ConfigSizeHuman, est.DataSizeHuman, est.TotalSizeHuman, est.DestFreeHuman, est.FitsOnDest)
if !est.FitsOnDest {
e.failJob(job, step, fmt.Sprintf("Nincs elég hely: szükséges ~%s, szabad %s",
est.TotalSizeHuman, est.DestFreeHuman))
return
}
}
// Optionally stop the app
wasRunning := false
if req.StopApp && e.provider.IsStackRunning(req.StackName) {
wasRunning = true
e.logger.Printf("[INFO] Export: stopping %s", req.StackName)
e.debugf("stopping stack %s before export", req.StackName)
if err := e.provider.StopStack(req.StackName); err != nil {
e.logger.Printf("[WARN] Export: could not stop %s: %v", req.StackName, err)
} else {
e.debugf("stack %s stopped successfully", req.StackName)
}
} else {
e.debugf("skip stop: stopApp=%v isRunning=%v", req.StopApp, e.provider.IsStackRunning(req.StackName))
}
// Always restart after export if we stopped it
if wasRunning {
defer func() {
e.logger.Printf("[INFO] Export: restarting %s", req.StackName)
e.debugf("restarting stack %s after export", req.StackName)
if err := e.provider.StartStack(req.StackName); err != nil {
e.logger.Printf("[WARN] Export: could not restart %s: %v", req.StackName, err)
} else {
e.debugf("stack %s restarted successfully", req.StackName)
}
}()
}
e.debugf("step 0 (preparation) done in %v", time.Since(stepStart))
job.setStep(step, "done", "")
step++
// --- Step 1: Config files ---
job.setStep(step, "running", "")
stepStart = time.Now()
tmpDir, err := os.MkdirTemp("", "felhom-export-*")
if err != nil {
e.failJob(job, step, fmt.Sprintf("Temp könyvtár hiba: %v", err))
return
}
e.debugf("temp dir: %s", tmpDir)
defer os.RemoveAll(tmpDir)
configDir := filepath.Join(tmpDir, "config")
if err := os.MkdirAll(configDir, 0755); err != nil {
e.failJob(job, step, err.Error())
return
}
stackDir, ok := e.provider.GetStackDir(req.StackName)
if !ok {
e.failJob(job, step, "Stack könyvtár nem található")
return
}
e.debugf("stack dir: %s", stackDir)
configFiles, err := copyStackConfig(stackDir, configDir, req.StackName, e.provider)
if err != nil {
e.failJob(job, step, fmt.Sprintf("Konfiguráció mentése sikertelen: %v", err))
return
}
e.debugf("config files copied: %v (%d files)", configFiles, len(configFiles))
e.debugf("step 1 (config) done in %v", time.Since(stepStart))
job.setStep(step, "done", "")
step++
// --- Step 2: Database dump ---
job.setStep(step, "running", "")
stepStart = time.Now()
dbDir := filepath.Join(tmpDir, "database")
os.MkdirAll(dbDir, 0755)
manifest := &Manifest{
Version: ManifestVersion,
AppName: req.StackName,
DisplayName: e.provider.GetStackDisplayName(req.StackName),
ExportedAt: time.Now().UTC(),
ControllerVer: e.version,
NeedsHDD: e.provider.GetStackNeedsHDD(req.StackName),
Encrypted: req.Password != "",
ConfigFiles: configFiles,
}
e.debugf("manifest: app=%s display=%s needsHDD=%v encrypted=%v",
manifest.AppName, manifest.DisplayName, manifest.NeedsHDD, manifest.Encrypted)
dbDumped := e.dumpDatabase(req.StackName, dbDir, manifest)
if !dbDumped {
e.debugf("no database found for %s — skipping DB step", req.StackName)
os.Remove(dbDir)
} else {
e.debugf("database dumped: type=%s", manifest.DBType)
// Log the dump file size
entries, _ := os.ReadDir(dbDir)
for _, entry := range entries {
if info, err := entry.Info(); err == nil {
e.debugf(" db dump file: %s (%s)", entry.Name(), humanizeBytes(info.Size()))
}
}
}
e.debugf("step 2 (database) done in %v", time.Since(stepStart))
job.setStep(step, "done", "")
step++
// --- Step 3: User data ---
job.setStep(step, "running", "")
stepStart = time.Now()
dataDir := filepath.Join(tmpDir, "data")
os.MkdirAll(dataDir, 0755)
if e.provider.GetStackNeedsHDD(req.StackName) {
e.debugf("exporting HDD data for %s", req.StackName)
e.exportHDDData(req.StackName, dataDir, manifest)
e.debugf("HDD data exported: subdirs=%v hasData=%v", manifest.HDDSubdirs, manifest.HasHDDData)
} else {
e.debugf("exporting Docker volumes for %s", req.StackName)
e.exportVolumeData(req.StackName, dataDir, manifest)
e.debugf("volume data exported: volumes=%v hasData=%v", manifest.VolumeNames, manifest.HasVolumeData)
}
e.debugf("step 3 (user data) done in %v", time.Since(stepStart))
job.setStep(step, "done", "")
step++
// --- Step 4: Create .fab bundle ---
job.setStep(step, "running", "")
stepStart = time.Now()
// Calculate total size
manifest.TotalSizeBytes = calcDirSize(tmpDir)
e.debugf("total bundle content size: %s (%d bytes)", humanizeBytes(manifest.TotalSizeBytes), manifest.TotalSizeBytes)
// Write manifest.json to tmpDir root
manifestData, err := manifest.Marshal()
if err != nil {
e.failJob(job, step, fmt.Sprintf("Manifest hiba: %v", err))
return
}
e.debugf("manifest JSON: %d bytes", len(manifestData))
if err := os.WriteFile(filepath.Join(tmpDir, "manifest.json"), manifestData, 0644); err != nil {
e.failJob(job, step, err.Error())
return
}
timestamp := time.Now().Format("20060102-150405")
fabName := fmt.Sprintf("%s_%s.fab", req.StackName, timestamp)
fabPath := filepath.Join(destDir, fabName)
e.debugf("target .fab path: %s", fabPath)
// Build tar.gz (to .tmp if encrypting, to final path if not)
targetPath := fabPath
if req.Password != "" {
targetPath = fabPath + ".tgz.tmp"
} else {
targetPath = fabPath + ".tmp"
}
e.debugf("creating tar.gz: %s", targetPath)
tgzStart := time.Now()
if err := createTarGz(targetPath, tmpDir); err != nil {
os.Remove(targetPath)
e.failJob(job, step, fmt.Sprintf("Csomag készítése sikertelen: %v", err))
return
}
if tgzInfo, err := os.Stat(targetPath); err == nil {
e.debugf("tar.gz created: %s (%s) in %v", targetPath, humanizeBytes(tgzInfo.Size()), time.Since(tgzStart))
}
job.setStep(step, "done", "")
step++
// --- Step 5: Encrypt (optional) ---
if req.Password != "" {
job.setStep(step, "running", "")
encStart := time.Now()
encPath := fabPath + ".tmp"
e.debugf("encrypting: %s → %s", targetPath, encPath)
if err := EncryptFile(targetPath, encPath, req.Password); err != nil {
os.Remove(targetPath)
e.failJob(job, step, fmt.Sprintf("Titkosítás sikertelen: %v", err))
return
}
os.Remove(targetPath)
targetPath = encPath
if encInfo, err := os.Stat(encPath); err == nil {
e.debugf("encryption done: %s in %v", humanizeBytes(encInfo.Size()), time.Since(encStart))
}
job.setStep(step, "done", "")
}
// Atomic rename to final path
e.debugf("atomic rename: %s → %s", targetPath, fabPath)
if err := os.Rename(targetPath, fabPath); err != nil {
e.failJob(job, step, fmt.Sprintf("Fájl átnevezés sikertelen: %v", err))
return
}
// Record result
stat, _ := os.Stat(fabPath)
job.mu.Lock()
job.OutputPath = fabPath
if stat != nil {
job.OutputSize = humanizeBytes(stat.Size())
}
job.mu.Unlock()
e.logger.Printf("[INFO] Export completed: %s → %s (%s) in %v", req.StackName, fabPath, job.OutputSize, time.Since(exportStart))
}
func (e *Exporter) failJob(job *Job, stepIdx int, msg string) {
job.setStep(stepIdx, "failed", msg)
job.mu.Lock()
job.Error = msg
job.mu.Unlock()
e.logger.Printf("[ERROR] Export/import failed at step %d: %s", stepIdx, msg)
e.debugf("FAIL at step %d: %s", stepIdx, msg)
}
// GetDebugInfo returns diagnostic information about the exporter state.
func (e *Exporter) GetDebugInfo() map[string]interface{} {
e.mu.Lock()
defer e.mu.Unlock()
info := map[string]interface{}{
"debug_enabled": e.debug,
"version": e.version,
"has_active_job": e.activeJob != nil,
}
if e.activeJob != nil {
info["active_job"] = e.activeJob.Snapshot()
}
return info
}
// copyStackConfig copies all relevant config files from the stack dir.
// app.yaml is saved with decrypted (plaintext) secrets for portability.
func copyStackConfig(stackDir, configDir, stackName string, provider ExportStackProvider) ([]string, error) {
var copied []string
entries, err := os.ReadDir(stackDir)
if err != nil {
return nil, err
}
for _, entry := range entries {
if entry.IsDir() {
continue
}
name := entry.Name()
// Skip temp files
if strings.HasSuffix(name, ".tmp") {
continue
}
src := filepath.Join(stackDir, name)
dst := filepath.Join(configDir, name)
// app.yaml: save with plaintext secrets
if name == "app.yaml" {
env := provider.GetDecryptedEnv(stackName)
if env != nil {
if err := writeDecryptedAppYaml(dst, env); err != nil {
return nil, fmt.Errorf("writing decrypted app.yaml: %w", err)
}
copied = append(copied, name)
continue
}
}
// Copy file as-is
if err := copyFile(src, dst); err != nil {
return nil, fmt.Errorf("copying %s: %w", name, err)
}
copied = append(copied, name)
}
return copied, nil
}
// writeDecryptedAppYaml writes a plaintext app.yaml with the given env map.
func writeDecryptedAppYaml(dst string, env map[string]string) error {
var sb strings.Builder
sb.WriteString("# Exported by felhom-controller — plaintext secrets\n")
sb.WriteString("deployed: true\n")
sb.WriteString("env:\n")
for k, v := range env {
// YAML-safe: quote values
sb.WriteString(fmt.Sprintf(" %s: %q\n", k, v))
}
return os.WriteFile(dst, []byte(sb.String()), 0644)
}
// dumpDatabase discovers and dumps the database for a stack.
func (e *Exporter) dumpDatabase(stackName, dbDir string, manifest *Manifest) bool {
ctx, cancel := context.WithTimeout(context.Background(), 5*time.Minute)
defer cancel()
e.debugf("discovering databases (looking for stack %s)...", stackName)
dbs, err := backup.DiscoverDatabases(ctx, e.logger, e.debug)
if err != nil {
e.logger.Printf("[WARN] Export: DB discovery error: %v", err)
return false
}
e.debugf("found %d databases total", len(dbs))
for i := range dbs {
e.debugf(" db[%d]: stack=%s container=%s type=%s", i, dbs[i].StackName, dbs[i].ContainerName, dbs[i].DBType)
}
var stackDB *backup.DiscoveredDB
for i := range dbs {
if dbs[i].StackName == stackName {
stackDB = &dbs[i]
break
}
}
if stackDB == nil {
e.debugf("no database container found for stack %s", stackName)
return false
}
e.debugf("matched DB: container=%s type=%s", stackDB.ContainerName, stackDB.DBType)
dumpStart := time.Now()
result := backup.DumpOne(ctx, *stackDB, dbDir, e.logger, e.debug)
if result.Error != nil {
e.logger.Printf("[WARN] Export: DB dump failed for %s: %v", stackName, result.Error)
return false
}
e.debugf("DB dump completed in %v: %s", time.Since(dumpStart), result.FilePath)
// Gzip the dump
if result.FilePath != "" {
gzPath := result.FilePath + ".gz"
gzStart := time.Now()
if err := gzipFile(result.FilePath, gzPath); err != nil {
e.logger.Printf("[WARN] Export: gzip dump failed: %v", err)
} else {
if origInfo, _ := os.Stat(result.FilePath); origInfo != nil {
if gzInfo, _ := os.Stat(gzPath); gzInfo != nil {
e.debugf("gzip: %s → %s (ratio %.1f%%) in %v",
humanizeBytes(origInfo.Size()), humanizeBytes(gzInfo.Size()),
float64(gzInfo.Size())/float64(origInfo.Size())*100, time.Since(gzStart))
}
}
os.Remove(result.FilePath)
}
}
manifest.HasDatabase = true
manifest.DBType = string(stackDB.DBType)
return true
}
// exportHDDData copies HDD bind mount data for the export.
func (e *Exporter) exportHDDData(stackName, dataDir string, manifest *Manifest) {
hddDir := filepath.Join(dataDir, "hdd")
os.MkdirAll(hddDir, 0755)
mounts := e.provider.GetStackHDDMounts(stackName)
e.debugf("HDD mounts for %s: %v (%d total)", stackName, mounts, len(mounts))
if len(mounts) == 0 {
e.debugf("no HDD mounts — skipping HDD data export")
return
}
for _, mount := range mounts {
if _, err := os.Stat(mount); os.IsNotExist(err) {
e.debugf("HDD mount %s does not exist — skipping", mount)
continue
}
subdir := filepath.Base(mount)
manifest.HDDSubdirs = append(manifest.HDDSubdirs, subdir)
tarPath := filepath.Join(hddDir, subdir+".tar")
e.debugf("tarring HDD mount: %s → %s", mount, tarPath)
tarStart := time.Now()
if err := tarDirectory(mount, tarPath); err != nil {
e.logger.Printf("[WARN] Export: failed to tar %s: %v", mount, err)
} else {
if info, _ := os.Stat(tarPath); info != nil {
e.debugf("HDD tar complete: %s (%s) in %v", subdir, humanizeBytes(info.Size()), time.Since(tarStart))
}
}
}
manifest.HasHDDData = len(manifest.HDDSubdirs) > 0
}
// exportVolumeData exports Docker named volumes for apps without HDD storage.
func (e *Exporter) exportVolumeData(stackName, dataDir string, manifest *Manifest) {
volDir := filepath.Join(dataDir, "volumes")
os.MkdirAll(volDir, 0755)
volumes := e.provider.GetDockerVolumes(stackName)
e.debugf("Docker volumes for %s: %v (%d total)", stackName, volumes, len(volumes))
if len(volumes) == 0 {
e.debugf("no Docker volumes — skipping volume data export")
return
}
for _, volName := range volumes {
tarPath := filepath.Join(volDir, volName+".tar")
e.debugf("exporting volume %s via docker run alpine tar...", volName)
volStart := time.Now()
ctx, cancel := context.WithTimeout(context.Background(), 10*time.Minute)
cmd := exec.CommandContext(ctx, "docker", "run", "--rm",
"-v", volName+":/vol:ro",
"-v", volDir+":/out",
"alpine", "tar", "cf", "/out/"+volName+".tar", "-C", "/vol", ".")
out, err := cmd.CombinedOutput()
cancel()
if err != nil {
e.logger.Printf("[WARN] Export: volume %s export failed: %s — %v",
volName, strings.TrimSpace(string(out)), err)
e.debugf("volume %s export failed: %s", volName, strings.TrimSpace(string(out)))
os.Remove(tarPath)
continue
}
if info, _ := os.Stat(tarPath); info != nil {
e.debugf("volume %s exported: %s in %v", volName, humanizeBytes(info.Size()), time.Since(volStart))
}
manifest.VolumeNames = append(manifest.VolumeNames, volName)
}
manifest.HasVolumeData = len(manifest.VolumeNames) > 0
}
// createTarGz creates a gzipped tar archive of a directory.
func createTarGz(outputPath, sourceDir string) error {
outFile, err := os.Create(outputPath)
if err != nil {
return err
}
defer outFile.Close()
gw := gzip.NewWriter(outFile)
defer gw.Close()
tw := tar.NewWriter(gw)
defer tw.Close()
return filepath.Walk(sourceDir, func(path string, info os.FileInfo, err error) error {
if err != nil {
return err
}
// Get path relative to sourceDir
relPath, err := filepath.Rel(sourceDir, path)
if err != nil {
return err
}
if relPath == "." {
return nil
}
header, err := tar.FileInfoHeader(info, "")
if err != nil {
return err
}
header.Name = relPath
if err := tw.WriteHeader(header); err != nil {
return err
}
if info.IsDir() {
return nil
}
f, err := os.Open(path)
if err != nil {
return err
}
defer f.Close()
_, err = io.Copy(tw, f)
return err
})
}
// tarDirectory creates a tar (not gzipped) of a directory's contents.
func tarDirectory(sourceDir, outputPath string) error {
outFile, err := os.Create(outputPath)
if err != nil {
return err
}
defer outFile.Close()
tw := tar.NewWriter(outFile)
defer tw.Close()
return filepath.Walk(sourceDir, func(path string, info os.FileInfo, err error) error {
if err != nil {
return err
}
relPath, err := filepath.Rel(sourceDir, path)
if err != nil {
return err
}
if relPath == "." {
return nil
}
header, err := tar.FileInfoHeader(info, "")
if err != nil {
return err
}
header.Name = relPath
if err := tw.WriteHeader(header); err != nil {
return err
}
if info.IsDir() {
return nil
}
f, err := os.Open(path)
if err != nil {
return err
}
defer f.Close()
_, err = io.Copy(tw, f)
return err
})
}
// gzipFile compresses a file with gzip.
func gzipFile(src, dst string) error {
in, err := os.Open(src)
if err != nil {
return err
}
defer in.Close()
out, err := os.Create(dst)
if err != nil {
return err
}
defer out.Close()
gw := gzip.NewWriter(out)
defer gw.Close()
_, err = io.Copy(gw, in)
return err
}
// copyFile copies a file from src to dst.
func copyFile(src, dst string) error {
in, err := os.Open(src)
if err != nil {
return err
}
defer in.Close()
out, err := os.Create(dst)
if err != nil {
return err
}
defer out.Close()
if _, err := io.Copy(out, in); err != nil {
return err
}
return out.Sync()
}
// calcDirSize recursively calculates total file size in a directory.
func calcDirSize(dir string) int64 {
var total int64
filepath.Walk(dir, func(_ string, info os.FileInfo, err error) error {
if err != nil || info.IsDir() {
return nil
}
total += info.Size()
return nil
})
return total
}