banger/internal/daemon/logger_test.go

package daemon

import (
	"bytes"
	"context"
	"encoding/json"
	"errors"
	"fmt"
	"os"
	"os/exec"
	"path/filepath"
	"strings"
	"testing"

	"banger/internal/api"
	"banger/internal/model"
	"banger/internal/paths"
)

func TestNewDaemonLoggerEmitsJSONAtConfiguredLevel(t *testing.T) {
	var buf bytes.Buffer
	logger, level, err := newDaemonLogger(&buf, "")
	if err != nil {
		t.Fatalf("newDaemonLogger: %v", err)
	}
	if level != "info" {
		t.Fatalf("level = %q, want info", level)
	}

	logger.Debug("hidden debug")
	logger.Info("visible info", "vm_name", "otter")

	entries := parseLogEntries(t, buf.Bytes())
	if len(entries) != 1 {
		t.Fatalf("entry count = %d, want 1", len(entries))
	}
	if entries[0]["msg"] != "visible info" {
		t.Fatalf("msg = %v, want visible info", entries[0]["msg"])
	}
	if entries[0]["vm_name"] != "otter" {
		t.Fatalf("vm_name = %v, want otter", entries[0]["vm_name"])
	}
}

func TestStartVMLockedLogsBridgeFailure(t *testing.T) {
	ctx := context.Background()
	binDir := t.TempDir()
	for _, name := range []string{
		"sudo", "ip", "dmsetup", "losetup", "blockdev", "truncate", "pgrep", "ps",
		"chown", "chmod", "kill", "e2cp", "e2rm", "debugfs", "mkfs.ext4", "mount",
		"umount", "cp",
	} {
		writeFakeExecutable(t, filepath.Join(binDir, name))
	}
	t.Setenv("PATH", binDir)

	firecrackerBin := filepath.Join(t.TempDir(), "firecracker")
	if err := os.WriteFile(firecrackerBin, []byte("#!/bin/sh\nexit 0\n"), 0o755); err != nil {
		t.Fatalf("write firecracker: %v", err)
	}
	rootfsPath := filepath.Join(t.TempDir(), "rootfs.ext4")
	kernelPath := filepath.Join(t.TempDir(), "vmlinux")
	for _, path := range []string{rootfsPath, kernelPath} {
		if err := os.WriteFile(path, []byte("artifact"), 0o644); err != nil {
			t.Fatalf("write %s: %v", path, err)
		}
	}

	runner := &scriptedRunner{
		t: t,
		steps: []runnerStep{
			{call: runnerCall{name: "ip", args: []string{"link", "show", "br-fc"}}, out: []byte("1: br-fc\n")},
			sudoStep("", errors.New("bridge up failed"), "ip", "link", "set", "br-fc", "up"),
		},
	}
	var buf bytes.Buffer
	logger, _, err := newDaemonLogger(&buf, "info")
	if err != nil {
		t.Fatalf("newDaemonLogger: %v", err)
	}

	vmDir := filepath.Join(t.TempDir(), "vm")
	vm := testVM("loggy", "image-loggy", "172.16.0.50")
	vm.Runtime.DNSName = ""
	vm.Runtime.VMDir = vmDir
	vm.Runtime.SystemOverlay = filepath.Join(vmDir, "system.cow")
	vm.Runtime.WorkDiskPath = filepath.Join(vmDir, "root.ext4")
	vm.Runtime.LogPath = filepath.Join(vmDir, "firecracker.log")
	vm.Runtime.MetricsPath = filepath.Join(vmDir, "metrics.json")
	image := testImage("image-loggy")
	image.RootfsPath = rootfsPath
	image.KernelPath = kernelPath

	d := &Daemon{
		layout: paths.Layout{RuntimeDir: filepath.Join(t.TempDir(), "runtime")},
		config: model.DaemonConfig{
			BridgeName:        "br-fc",
			BridgeIP:          model.DefaultBridgeIP,
			DefaultDNS:        model.DefaultDNS,
			FirecrackerBin:    firecrackerBin,
			StatsPollInterval: model.DefaultStatsPollInterval,
		},
		runner: runner,
		logger: logger,
	}

	_, err = d.startVMLocked(ctx, vm, image)
	if err == nil || !strings.Contains(err.Error(), "bridge up failed") {
		t.Fatalf("startVMLocked() error = %v, want bridge failure", err)
	}
	runner.assertExhausted()

	entries := parseLogEntries(t, buf.Bytes())
	if !hasLogEntry(entries, map[string]string{"msg": "operation stage", "operation": "vm.start", "stage": "bridge", "vm_name": "loggy"}) {
		t.Fatalf("expected bridge stage log, got %v", entries)
	}
	if !hasLogEntry(entries, map[string]string{"msg": "operation failed", "operation": "vm.start", "vm_name": "loggy", "error": "bridge up failed"}) {
		t.Fatalf("expected operation failure log, got %v", entries)
	}
}

func TestBuildImagePreservesBuildLogOnFailure(t *testing.T) {
	ctx := context.Background()
	store := openDaemonStore(t)
	stateDir := filepath.Join(t.TempDir(), "state")
	imagesDir := filepath.Join(stateDir, "images")
	if err := os.MkdirAll(imagesDir, 0o755); err != nil {
		t.Fatalf("mkdir images dir: %v", err)
	}

	binDir := t.TempDir()
	for _, name := range []string{"sudo", "ip", "curl", "ssh", "jq", "sha256sum", "e2fsck", "resize2fs"} {
		writeFakeExecutable(t, filepath.Join(binDir, name))
	}
	bashPath, err := exec.LookPath("bash")
	if err != nil {
		t.Fatalf("lookpath bash: %v", err)
	}
	bashWrapper := filepath.Join(binDir, "bash")
	if err := os.WriteFile(bashWrapper, []byte(fmt.Sprintf("#!/bin/sh\nexec %q \"$@\"\n", bashPath)), 0o755); err != nil {
		t.Fatalf("write bash wrapper: %v", err)
	}
	t.Setenv("PATH", binDir)

	script := filepath.Join(t.TempDir(), "customize.sh")
	scriptBody := "#!/bin/sh\necho helper-stdout\necho helper-stderr >&2\nexit 17\n"
	if err := os.WriteFile(script, []byte(scriptBody), 0o755); err != nil {
		t.Fatalf("write customize script: %v", err)
	}
	baseRootfs := filepath.Join(t.TempDir(), "base.ext4")
	kernelPath := filepath.Join(t.TempDir(), "vmlinux")
	for _, path := range []string{baseRootfs, kernelPath} {
		if err := os.WriteFile(path, []byte("artifact"), 0o644); err != nil {
			t.Fatalf("write %s: %v", path, err)
		}
	}

	var buf bytes.Buffer
	logger, _, err := newDaemonLogger(&buf, "info")
	if err != nil {
		t.Fatalf("newDaemonLogger: %v", err)
	}
	d := &Daemon{
		layout: paths.Layout{
			StateDir:  stateDir,
			ImagesDir: imagesDir,
		},
		config: model.DaemonConfig{
			RuntimeDir:       t.TempDir(),
			CustomizeScript:  script,
			DefaultImageName: "default",
		},
		store:  store,
		logger: logger,
	}

	_, err = d.BuildImage(ctx, api.ImageBuildParams{
		Name:       "broken-image",
		BaseRootfs: baseRootfs,
		KernelPath: kernelPath,
	})
	if err == nil || !strings.Contains(err.Error(), "inspect ") {
		t.Fatalf("BuildImage() error = %v, want build log hint", err)
	}

	buildLogs, globErr := filepath.Glob(filepath.Join(stateDir, "image-build", "*.log"))
	if globErr != nil {
		t.Fatalf("glob build logs: %v", globErr)
	}
	if len(buildLogs) != 1 {
		t.Fatalf("build log count = %d, want 1", len(buildLogs))
	}
	logData, readErr := os.ReadFile(buildLogs[0])
	if readErr != nil {
		t.Fatalf("read build log: %v", readErr)
	}
	if !strings.Contains(string(logData), "helper-stdout") || !strings.Contains(string(logData), "helper-stderr") {
		t.Fatalf("build log = %q, want helper stdout/stderr", string(logData))
	}

	entries := parseLogEntries(t, buf.Bytes())
	if !hasLogEntry(entries, map[string]string{"msg": "operation stage", "operation": "image.build", "stage": "launch_helper"}) {
		t.Fatalf("expected launch_helper log, got %v", entries)
	}
	if !strings.Contains(buf.String(), buildLogs[0]) {
		t.Fatalf("daemon logs = %q, want build log path %s", buf.String(), buildLogs[0])
	}
}

func parseLogEntries(t *testing.T, data []byte) []map[string]any {
	t.Helper()
	lines := bytes.Split(bytes.TrimSpace(data), []byte("\n"))
	if len(lines) == 1 && len(lines[0]) == 0 {
		return nil
	}
	entries := make([]map[string]any, 0, len(lines))
	for _, line := range lines {
		if len(bytes.TrimSpace(line)) == 0 {
			continue
		}
		var entry map[string]any
		if err := json.Unmarshal(line, &entry); err != nil {
			t.Fatalf("unmarshal log line %q: %v", string(line), err)
		}
		entries = append(entries, entry)
	}
	return entries
}

func hasLogEntry(entries []map[string]any, want map[string]string) bool {
	for _, entry := range entries {
		match := true
		for key, value := range want {
			if !strings.Contains(stringValue(entry[key]), value) {
				match = false
				break
			}
		}
		if match {
			return true
		}
	}
	return false
}

func stringValue(value any) string {
	return fmt.Sprint(value)
}