funknetz/station/log_test.go

package station_test

import (
	"context"
	"net"
	"os"
	"path/filepath"
	"strings"
	"testing"
	"time"

	"gitea.neitzel.de/konrad/funknetz/station"
)

func TestLogAppendsSessionEvents(t *testing.T) {
	logPath := filepath.Join(t.TempDir(), "funknetz.log")
	if err := os.WriteFile(logPath, []byte("kept\n"), 0o640); err != nil {
		t.Fatal(err)
	}
	in := loginLog(t, "DL1ABC", "super-secret-key", 20, 7, []string{"OPUS"}, logPath)

	in.clock.Advance(2 * time.Second)
	in.refl.writeFrame(t, 104, appendStr(appendU32(nil, 20), "DB0XYZ"))
	if _, err := in.st.Wait(context.Background(), func(s station.State) bool { return s.Talker == "DB0XYZ" }); err != nil {
		t.Fatal(err)
	}
	in.clock.Advance(3 * time.Second)
	in.refl.tcp.Close()
	if _, err := in.st.Wait(context.Background(), func(s station.State) bool { return s.Connection == "Disconnected" }); err != nil {
		t.Fatal(err)
	}

	got := readLog(t, logPath)
	want := strings.Join([]string{
		"kept",
		"2026-10-03T12:00:00Z connected",
		"2026-10-03T12:00:02Z DB0XYZ talked for 3 seconds.",
		"2026-10-03T12:00:05Z disconnected",
		"",
	}, "\n")
	if got != want {
		t.Fatalf("log = %q, want %q", got, want)
	}
	if strings.Contains(got, "super-secret-key") {
		t.Fatal("log contains the auth key")
	}
	info, err := os.Stat(logPath)
	if err != nil {
		t.Fatal(err)
	}
	if got, want := info.Mode().Perm(), os.FileMode(0o640); got != want {
		t.Fatalf("mode = %o, want %o", got, want)
	}
}

func TestLogRecordsSendingAndARemoteTalker(t *testing.T) {
	logPath := filepath.Join(t.TempDir(), "funknetz.log")
	in := loginLog(t, "DL1ABC", "key", 20, 7, []string{"OPUS"}, logPath)

	in.st.HoldButton()
	in.st.ReleaseButton()
	in.clock.Advance(2 * time.Second)
	in.st.HoldButton()
	in.refl.writeFrame(t, 104, appendStr(appendU32(nil, 20), "DL1ABC"))
	in.clock.Advance(2 * time.Second)
	in.refl.writeFrame(t, 104, appendStr(appendU32(nil, 20), "DB0XYZ"))
	if _, err := in.st.Wait(context.Background(), func(s station.State) bool { return s.Talker == "DB0XYZ" }); err != nil {
		t.Fatal(err)
	}
	in.st.HoldButton()
	in.st.ReleaseButton()
	in.clock.Advance(4 * time.Second)
	in.refl.writeFrame(t, 105, appendStr(appendU32(nil, 20), "DB0XYZ"))
	if _, err := in.st.Wait(context.Background(), func(s station.State) bool { return s.Talker == "" && !s.Transmitting }); err != nil {
		t.Fatal(err)
	}

	got := readLog(t, logPath)
	want := strings.Join([]string{
		"2026-10-03T12:00:00Z connected",
		"2026-10-03T12:00:00Z sending for 0 seconds.",
		"2026-10-03T12:00:02Z sending for 2 seconds.",
		"2026-10-03T12:00:04Z DB0XYZ talked for 4 seconds.",
		"",
	}, "\n")
	if got != want {
		t.Fatalf("log = %q, want %q", got, want)
	}
	info, err := os.Stat(logPath)
	if err != nil {
		t.Fatal(err)
	}
	if got, want := info.Mode().Perm(), os.FileMode(0o600); got != want {
		t.Fatalf("mode = %o, want %o", got, want)
	}
}

func TestLogFailureStaysInTheIdleSlot(t *testing.T) {
	logPath := filepath.Join(t.TempDir(), "missing", "funknetz.log")
	in := loginLog(t, "DL1ABC", "key", 20, 7, []string{"OPUS"}, logPath)
	notice := "Cannot write " + logPath
	if got := in.st.State(); got.Connection != "Connected" || got.Detail != notice {
		t.Fatalf("State = %+v, want Connected and the log failure", got)
	}
	in.refl.writeFrame(t, 104, appendStr(appendU32(nil, 20), "DB0XYZ"))
	got, err := in.st.Wait(context.Background(), func(s station.State) bool { return s.Talker == "DB0XYZ" })
	if err != nil {
		t.Fatal(err)
	}
	if got.Detail != "Idle" {
		t.Fatalf("Detail = %q, want the talker to take the line", got.Detail)
	}
	in.refl.writeFrame(t, 105, appendStr(appendU32(nil, 20), "DB0XYZ"))
	got, err = in.st.Wait(context.Background(), func(s station.State) bool { return s.Talker == "" })
	if err != nil {
		t.Fatal(err)
	}
	if got.Detail != notice {
		t.Fatalf("Detail = %q, want the log failure back", got.Detail)
	}
}

func TestFirstDialFailureIsLoggedOnce(t *testing.T) {
	logPath := filepath.Join(t.TempDir(), "funknetz.log")
	ln := listenClosed(t)
	path := writeConfigFile(t, configWithLog(t, "127.0.0.1", ln, "DL1ABC", "key", 4, logPath))
	clock := newFakeClock()
	st, err := station.New(station.Options{ConfigPath: path, Clock: clock})
	if err != nil {
		t.Fatal(err)
	}
	ctx, cancel := context.WithCancel(t.Context())
	defer cancel()
	go func() { _ = st.Run(ctx) }()

	want := "2026-10-03T12:00:00Z disconnected\n"
	deadline := time.Now().Add(2 * time.Second)
	for readLog(t, logPath) != want {
		if time.Now().After(deadline) {
			t.Fatalf("log = %q, want %q", readLog(t, logPath), want)
		}
		time.Sleep(time.Millisecond)
	}
	clock.BlockUntilWaiting(t)
	clock.Advance(2 * time.Second)
	clock.BlockUntilWaiting(t)
	if got := readLog(t, logPath); got != want {
		t.Fatalf("log = %q, want the dial failure logged once", got)
	}
}

func TestReflectorErrorsAreOneLogLine(t *testing.T) {
	logPath := filepath.Join(t.TempDir(), "funknetz.log")
	refl := newReflector(t)
	path := writeConfigFile(t, configWithLog(t, "127.0.0.1", refl.port, "DL1ABC", "key", 20, logPath))
	clock := newFakeClock()
	st, err := station.New(station.Options{ConfigPath: path, Clock: clock})
	if err != nil {
		t.Fatal(err)
	}
	ctx, cancel := context.WithCancel(t.Context())
	defer cancel()
	go func() { _ = st.Run(ctx) }()
	refl.accept(t)
	refl.readFrame(t)
	refl.writeFrame(t, 13, appendStr(nil, "bad\nline"))
	if _, err := st.Wait(ctx, func(s station.State) bool { return s.Detail == "bad\nline" }); err != nil {
		t.Fatal(err)
	}
	got := readLog(t, logPath)
	if got != "2026-10-03T12:00:00Z bad line\n" {
		t.Fatalf("log = %q", got)
	}
	if strings.Contains(got, "disconnected") {
		t.Fatalf("log = %q, want no disconnected line", got)
	}
}

func listenClosed(t *testing.T) int {
	t.Helper()
	ln, err := net.Listen("tcp", "127.0.0.1:0")
	if err != nil {
		t.Fatal(err)
	}
	port := ln.Addr().(*net.TCPAddr).Port
	ln.Close()
	return port
}

func readLog(t *testing.T, path string) string {
	t.Helper()
	b, err := os.ReadFile(path)
	if err != nil {
		t.Fatal(err)
	}
	return string(b)
}