diff --git a/docs/adr/0003-optional-station-log.md b/docs/adr/0003-optional-station-log.md new file mode 100644 index 0000000..818332a --- /dev/null +++ b/docs/adr/0003-optional-station-log.md @@ -0,0 +1,3 @@ +# Optional station log + +The operator can append a log of the session. `~/.funknetz.json` gains `enableLogging` and `logFile` when either key is missing, so the switch is visible in the file they already edit. A missing key is not the same as a bad `port`: a log path that is mistyped or not writable leaves the station running and shows the failure in the window. Quitting would drop the callsign off the reflector because the log could not be written. The file is append-only so the operator can follow it with `tail -f`. Silent defaults were rejected because the new keys would stay invisible. diff --git a/station/behavior_test.go b/station/behavior_test.go index 92c2f06..827846c 100644 --- a/station/behavior_test.go +++ b/station/behavior_test.go @@ -24,9 +24,18 @@ type loggedIn struct { } func login(t *testing.T, callsign, key string, tg int, id uint16, codecs []string) loggedIn { + t.Helper() + return loginLog(t, callsign, key, tg, id, codecs, "") +} + +func loginLog(t *testing.T, callsign, key string, tg int, id uint16, codecs []string, logPath string) loggedIn { t.Helper() refl := newReflector(t) - path := writeConfigFile(t, configJSON("127.0.0.1", refl.port, callsign, key, tg)) + file := configJSON("127.0.0.1", refl.port, callsign, key, tg) + if logPath != "" { + file = configWithLog("127.0.0.1", refl.port, callsign, key, tg, logPath) + } + path := writeConfigFile(t, file) clock := newFakeClock() st, err := station.New(station.Options{ConfigPath: path, Clock: clock}) if err != nil { @@ -63,6 +72,11 @@ func login(t *testing.T, callsign, key string, tg int, id uint16, codecs []strin refl.writeFrame(t, 12, nil) refl.writeFrame(t, 100, serverInfo(id, []string{"db0abc"}, codecs)) typ, body = refl.readFrame(t) + if typ != 111 { + t.Fatalf("type %d, want software identity", typ) + } + requireSoftwareIdentity(t, body) + typ, body = refl.readFrame(t) if typ != 106 { t.Fatalf("type %d, want select talk group", typ) } diff --git a/station/config.go b/station/config.go index 33610e8..21bc583 100644 --- a/station/config.go +++ b/station/config.go @@ -4,6 +4,7 @@ import ( "fmt" "math" "os" + "path/filepath" "regexp" "strings" @@ -12,27 +13,34 @@ import ( ) type loaded struct { - host string - port int - callsign string - authKey string - talkGroup int + host string + port int + callsign string + authKey string + talkGroup int + enableLogging bool + logPath string + logNotice string } type fileShape struct { - Host jsontext.Value `json:"host"` - Port jsontext.Value `json:"port"` - Callsign jsontext.Value `json:"callsign"` - AuthKey jsontext.Value `json:"authKey"` - TalkGroup jsontext.Value `json:"talkGroup"` + Host jsontext.Value `json:"host"` + Port jsontext.Value `json:"port"` + Callsign jsontext.Value `json:"callsign"` + AuthKey jsontext.Value `json:"authKey"` + TalkGroup jsontext.Value `json:"talkGroup"` + EnableLogging jsontext.Value `json:"enableLogging"` + LogFile jsontext.Value `json:"logFile"` } type templateFile struct { - Host string `json:"host"` - Port int `json:"port"` - Callsign string `json:"callsign"` - AuthKey string `json:"authKey"` - TalkGroup int `json:"talkGroup"` + Host string `json:"host"` + Port int `json:"port"` + Callsign string `json:"callsign"` + AuthKey string `json:"authKey"` + TalkGroup int `json:"talkGroup"` + EnableLogging bool `json:"enableLogging"` + LogFile string `json:"logFile"` } var callsignPattern = regexp.MustCompile(`^[A-Z0-9][A-Z]{0,2}\d[A-Z0-9]{0,3}[A-Z](?:-[A-Z0-9]{1,3})?$`) @@ -48,11 +56,11 @@ func loadConfig(path string) (loaded, error) { } return loaded{}, fmt.Errorf("could not be read") } - return parseConfig(body) + return parseConfig(path, body) } func writeTemplate(path string) error { - body, err := jsonv2.Marshal(templateFile{}) + body, err := jsonv2.Marshal(templateFile{LogFile: defaultLogPath()}) if err != nil { return err } @@ -72,11 +80,36 @@ func writeTemplate(path string) error { return os.Chmod(path, 0o600) } -func parseConfig(body []byte) (loaded, error) { +func parseConfig(path string, body []byte) (loaded, error) { var shape fileShape if err := jsonv2.Unmarshal(body, &shape); err != nil { return loaded{}, fmt.Errorf("could not be read") } + if block, notice := blockedLog(shape); block { + cfg, err := parseOperational(shape) + if err != nil { + return loaded{}, err + } + cfg.logNotice = notice + return cfg, nil + } + if missingLog(shape) { + if !operationalKindsOK(shape) { + return parseOperational(shape) + } + shape = withLogDefaults(shape) + if err := rewriteConfig(path, shape); err != nil { + return loaded{}, fmt.Errorf("could not be read") + } + } + cfg, err := parseOperational(shape) + if err != nil { + return loaded{}, err + } + return applyLog(cfg, shape), nil +} + +func parseOperational(shape fileShape) (loaded, error) { host, err := stringField("host", shape.Host) if err != nil { return loaded{}, err @@ -153,3 +186,139 @@ func intField(name string, v jsontext.Value, min, max int) (int, error) { } return n, nil } + +func defaultLogPath() string { + home, err := os.UserHomeDir() + if err != nil { + return "" + } + return filepath.Join(home, "funknetz.log") +} + +func present(v jsontext.Value) bool { return len(v) > 0 } + +func isBool(v jsontext.Value) bool { + return v.Kind() == jsontext.KindTrue || v.Kind() == jsontext.KindFalse +} + +func missingLog(shape fileShape) bool { + return !present(shape.EnableLogging) || !present(shape.LogFile) +} + +func operationalKindsOK(shape fileShape) bool { + if present(shape.Host) && shape.Host.Kind() != jsontext.KindString { + return false + } + if present(shape.Callsign) && shape.Callsign.Kind() != jsontext.KindString { + return false + } + if present(shape.AuthKey) && shape.AuthKey.Kind() != jsontext.KindString { + return false + } + if present(shape.Port) && shape.Port.Kind() != jsontext.KindNumber { + return false + } + if present(shape.TalkGroup) && shape.TalkGroup.Kind() != jsontext.KindNumber { + return false + } + return true +} + +// blockedLog reports that a log value has the wrong JSON type, so the file +// must not be rewritten. notice is empty when logging is not switched on. +func blockedLog(shape fileShape) (block bool, notice string) { + enBad := present(shape.EnableLogging) && !isBool(shape.EnableLogging) + fileBad := present(shape.LogFile) && shape.LogFile.Kind() != jsontext.KindString + if !enBad && !fileBad { + return false, "" + } + if enBad { + return true, "enableLogging has the wrong type" + } + if shape.EnableLogging.Kind() == jsontext.KindTrue { + return true, "logFile has the wrong type" + } + return true, "" +} + +func withLogDefaults(shape fileShape) fileShape { + shape.Host = rawOr(shape.Host, `""`) + shape.Port = rawOr(shape.Port, "0") + shape.Callsign = rawOr(shape.Callsign, `""`) + shape.AuthKey = rawOr(shape.AuthKey, `""`) + shape.TalkGroup = rawOr(shape.TalkGroup, "0") + shape.EnableLogging = rawOr(shape.EnableLogging, "false") + if !present(shape.LogFile) { + raw, err := jsonv2.Marshal(defaultLogPath()) + if err != nil { + raw = []byte(`""`) + } + shape.LogFile = jsontext.Value(raw) + } + return shape +} + +func rawOr(v jsontext.Value, fallback string) jsontext.Value { + if len(v) == 0 { + return jsontext.Value(fallback) + } + return v +} + +func rewriteConfig(path string, shape fileShape) error { + info, err := os.Stat(path) + if err != nil { + return err + } + body, err := jsonv2.Marshal(shape) + if err != nil { + return err + } + body = append(body, '\n') + tmp, err := os.CreateTemp(filepath.Dir(path), ".funknetz-*.json") + if err != nil { + return err + } + tmpName := tmp.Name() + _, werr := tmp.Write(body) + cerr := tmp.Chmod(info.Mode().Perm()) + clerr := tmp.Close() + if werr != nil || cerr != nil || clerr != nil { + os.Remove(tmpName) + if werr != nil { + return werr + } + if cerr != nil { + return cerr + } + return clerr + } + if err := os.Rename(tmpName, path); err != nil { + os.Remove(tmpName) + return err + } + return nil +} + +func applyLog(cfg loaded, shape fileShape) loaded { + if shape.EnableLogging.Kind() != jsontext.KindTrue { + return cfg + } + var path string + if err := jsonv2.Unmarshal(shape.LogFile, &path); err != nil { + cfg.logNotice = "logFile has the wrong type" + return cfg + } + path = strings.TrimSpace(path) + if path == "" { + cfg.logNotice = "Cannot write logFile" + return cfg + } + if !filepath.IsAbs(path) { + cfg.logNotice = "Cannot write " + path + return cfg + } + cfg.enableLogging = true + cfg.logPath = path + return cfg +} diff --git a/station/config_test.go b/station/config_test.go index 0dbbba8..bca58f2 100644 --- a/station/config_test.go +++ b/station/config_test.go @@ -44,11 +44,21 @@ func TestMissingConfigIsCreatedAndRejected(t *testing.T) { if got["port"] != float64(0) || got["talkGroup"] != float64(0) { t.Fatalf("numeric fields = %#v, want port and talkGroup at zero", got) } + home, err := os.UserHomeDir() + if err != nil { + t.Fatal(err) + } + if got["enableLogging"] != false { + t.Fatalf("enableLogging = %#v, want false", got["enableLogging"]) + } + if got["logFile"] != filepath.Join(home, "funknetz.log") { + t.Fatalf("logFile = %#v, want funknetz.log in the home directory", got["logFile"]) + } } func TestExistingConfigIsNotRewritten(t *testing.T) { path := filepath.Join(t.TempDir(), "funknetz.json") - original := []byte("{\"host\":\"127.0.0.1\",\"port\":5308,\"callsign\":\"DL1ABC\",\"authKey\":\"a b\",\"talkGroup\":20}\n") + original := []byte("{\"host\":\"127.0.0.1\",\"port\":5308,\"callsign\":\"DL1ABC\",\"authKey\":\"a b\",\"talkGroup\":20,\"enableLogging\":false,\"logFile\":\"/tmp/funknetz.log\"}\n") if err := os.WriteFile(path, original, 0o640); err != nil { t.Fatal(err) } @@ -117,8 +127,21 @@ func TestInvalidConfigNamesTheField(t *testing.T) { if err != nil { t.Fatal(err) } - if string(after) != string(before) { - t.Fatalf("file = %q, want it left untouched", after) + if strings.Contains(tt.want, "wrong type") { + if string(after) != string(before) { + t.Fatalf("file = %q, want it left untouched", after) + } + return + } + var got map[string]any + if err := jsonv2.Unmarshal(after, &got); err != nil { + t.Fatalf("rewritten file is not JSON: %v\n%s", err, after) + } + if got["enableLogging"] != false { + t.Fatalf("enableLogging = %#v, want false", got["enableLogging"]) + } + if _, ok := got["logFile"].(string); !ok { + t.Fatalf("logFile = %#v, want a string", got["logFile"]) } }) } @@ -163,6 +186,179 @@ func TestCallsignIsTrimmedAndUppercased(t *testing.T) { } } +func TestMissingLogKeysAreRewritten(t *testing.T) { + path := filepath.Join(t.TempDir(), "funknetz.json") + original := []byte("{\"note\":true,\"host\":\" 127.0.0.1 \",\"port\":5308,\"callsign\":\" dl1abc \",\"authKey\":\"a b\",\"talkGroup\":20}\n") + if err := os.WriteFile(path, original, 0o640); err != nil { + t.Fatal(err) + } + st, err := station.New(station.Options{ConfigPath: path}) + if err != nil { + t.Fatal(err) + } + t.Cleanup(st.Close) + if st.State().Callsign != "DL1ABC" { + t.Fatalf("Callsign = %q", st.State().Callsign) + } + info, err := os.Stat(path) + 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) + } + body, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + var got map[string]any + if err := jsonv2.Unmarshal(body, &got); err != nil { + t.Fatal(err) + } + if _, ok := got["note"]; ok { + t.Fatalf("note = %#v, want it dropped", got["note"]) + } + if got["callsign"] != " dl1abc " || got["authKey"] != "a b" || got["host"] != " 127.0.0.1 " { + t.Fatalf("kept fields = %#v", got) + } + if got["enableLogging"] != false { + t.Fatalf("enableLogging = %#v", got["enableLogging"]) + } + home, err := os.UserHomeDir() + if err != nil { + t.Fatal(err) + } + if got["logFile"] != filepath.Join(home, "funknetz.log") { + t.Fatalf("logFile = %#v", got["logFile"]) + } + if st.State().Detail != "Idle" { + t.Fatalf("Detail = %q, want Idle", st.State().Detail) + } +} + +func TestLogSettingsDoNotStopTheStation(t *testing.T) { + home := t.TempDir() + t.Setenv("HOME", home) + + t.Run("missing log file uses home", func(t *testing.T) { + path := filepath.Join(t.TempDir(), "funknetz.json") + body := []byte(`{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":true}`) + if err := os.WriteFile(path, body, 0o600); err != nil { + t.Fatal(err) + } + st, err := station.New(station.Options{ConfigPath: path}) + if err != nil { + t.Fatal(err) + } + t.Cleanup(st.Close) + got, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + var fields map[string]any + if err := jsonv2.Unmarshal(got, &fields); err != nil { + t.Fatal(err) + } + wantPath := filepath.Join(home, "funknetz.log") + if fields["logFile"] != wantPath || fields["enableLogging"] != true { + t.Fatalf("fields = %#v", fields) + } + if _, err := os.Stat(wantPath); err != nil { + t.Fatal(err) + } + }) + + t.Run("logging off ignores a bad path", func(t *testing.T) { + path := filepath.Join(t.TempDir(), "funknetz.json") + logPath := filepath.Join(t.TempDir(), "funknetz.log") + body := []byte(`{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":false,"logFile":1}`) + if err := os.WriteFile(path, body, 0o600); err != nil { + t.Fatal(err) + } + before, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + st, err := station.New(station.Options{ConfigPath: path}) + if err != nil { + t.Fatal(err) + } + t.Cleanup(st.Close) + if st.State().Detail != "Idle" { + t.Fatalf("Detail = %q, want Idle", st.State().Detail) + } + after, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if string(after) != string(before) { + t.Fatalf("file = %s, want it left untouched", after) + } + if _, err := os.Stat(logPath); !os.IsNotExist(err) { + t.Fatalf("log file err = %v, want not exist", err) + } + }) + + cases := []struct { + name string + body string + detail string + same bool + }{ + {name: "relative", body: `{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":true,"logFile":"funknetz.log"}`, detail: "Cannot write funknetz.log", same: true}, + {name: "empty", body: `{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":true,"logFile":" "}`, detail: "Cannot write logFile", same: true}, + {name: "tilde", body: `{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":true,"logFile":"~/funknetz.log"}`, detail: "Cannot write ~/funknetz.log", same: true}, + {name: "enable type", body: `{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":"yes","logFile":"/tmp/funknetz.log"}`, detail: "enableLogging has the wrong type", same: true}, + {name: "file type", body: `{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":true,"logFile":1}`, detail: "logFile has the wrong type", same: true}, + {name: "both types", body: `{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":"yes","logFile":1}`, detail: "enableLogging has the wrong type", same: true}, + {name: "missing enable and bad file", body: `{"host":"127.0.0.1","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"logFile":1}`, detail: "Idle", same: true}, + } + for _, tt := range cases { + t.Run(tt.name, func(t *testing.T) { + path := filepath.Join(t.TempDir(), "funknetz.json") + if err := os.WriteFile(path, []byte(tt.body), 0o600); err != nil { + t.Fatal(err) + } + st, err := station.New(station.Options{ConfigPath: path}) + if err != nil { + t.Fatal(err) + } + t.Cleanup(st.Close) + if st.State().Detail != tt.detail { + t.Fatalf("Detail = %q, want %q", st.State().Detail, tt.detail) + } + if tt.same { + after, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if string(after) != tt.body { + t.Fatalf("file = %s, want it left untouched", after) + } + } + }) + } + + t.Run("bad host still quits", func(t *testing.T) { + path := filepath.Join(t.TempDir(), "funknetz.json") + body := []byte(`{"host":"","port":5308,"callsign":"DL1ABC","authKey":"key","talkGroup":20,"enableLogging":"yes"}`) + if err := os.WriteFile(path, body, 0o600); err != nil { + t.Fatal(err) + } + _, err := station.New(station.Options{ConfigPath: path}) + if err == nil || err.Error() != "host is empty" { + t.Fatalf("New() error = %v, want host is empty", err) + } + after, err := os.ReadFile(path) + if err != nil { + t.Fatal(err) + } + if string(after) != string(body) { + t.Fatalf("file = %s, want it left untouched", after) + } + }) +} + func configJSON(host string, port int, callsign, authKey string, talkGroup int) string { body, err := jsonv2.Marshal(map[string]any{ "host": host, @@ -176,3 +372,19 @@ func configJSON(host string, port int, callsign, authKey string, talkGroup int) } return string(body) } + +func configWithLog(host string, port int, callsign, authKey string, talkGroup int, logPath string) string { + body, err := jsonv2.Marshal(map[string]any{ + "host": host, + "port": port, + "callsign": callsign, + "authKey": authKey, + "talkGroup": talkGroup, + "enableLogging": true, + "logFile": logPath, + }) + if err != nil { + panic(err) + } + return string(body) +} diff --git a/station/log.go b/station/log.go new file mode 100644 index 0000000..1a487a6 --- /dev/null +++ b/station/log.go @@ -0,0 +1,125 @@ +package station + +import ( + "fmt" + "os" + "strings" + "time" +) + +// Close releases the log file. It is safe to call more than once. +func (s *Station) Close() { + s.mu.Lock() + defer s.mu.Unlock() + s.closeLogLocked() +} + +func (s *Station) openLog() { + f, err := os.OpenFile(s.logPath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o600) + if err != nil { + s.logNotice = "Cannot write " + s.logPath + if s.state.Talker == "" { + s.state.Detail = s.logNotice + } + return + } + s.logFile = f +} + +func (s *Station) closeLogLocked() { + if s.logFile != nil { + s.logFile.Close() + s.logFile = nil + } +} + +func (s *Station) writeLog(ts time.Time, msg string) { + if s.logFile == nil { + return + } + line := ts.Format(time.RFC3339) + " " + msg + "\n" + if _, err := s.logFile.Write([]byte(line)); err != nil { + s.closeLogLocked() + if s.logNotice == "" { + s.logNotice = "Cannot write " + s.logPath + } + } +} + +func (s *Station) noteTransmitLocked() { + s.noteTransmitAt(s.clock.Now()) +} + +func (s *Station) noteTransmitAt(now time.Time) { + tx := s.transmitting() + if tx && !s.sending { + s.sending = true + s.sendStart = now + return + } + if !tx && s.sending { + start := s.sendStart + s.sending = false + s.writeLog(start, fmt.Sprintf("sending for %d seconds.", wholeSeconds(start, now))) + } +} + +func (s *Station) closeTalkerLocked(now time.Time) { + if s.talkCall == "" { + return + } + call := s.talkCall + start := s.talkStart + s.talkCall = "" + s.writeLog(start, fmt.Sprintf("%s talked for %d seconds.", call, wholeSeconds(start, now))) +} + +func (s *Station) noteDownLocked(now time.Time, dial bool) { + s.closeTalkerLocked(now) + s.state.Connection = "Disconnected" + s.remoteTalker = "" + s.roomBusy = false + s.noteTransmitAt(now) + switch { + case s.up: + s.up = false + s.outage = true + s.writeLog(now, "disconnected") + case dial && !s.outage: + s.outage = true + s.writeLog(now, "disconnected") + } + s.publish() +} + +func (s *Station) endFatal(msg string, log bool) { + s.mu.Lock() + defer s.mu.Unlock() + if s.fatal != "" { + return + } + now := s.clock.Now() + s.closeTalkerLocked(now) + s.fatal = msg + s.remoteTalker = "" + s.roomBusy = false + s.noteTransmitAt(now) + if log { + s.up = false + s.outage = true + s.writeLog(now, oneLine(msg)) + } + s.publish() +} + +func wholeSeconds(start, end time.Time) int { + d := end.Sub(start) + if d <= 0 { + return 0 + } + return int(d / time.Second) +} + +func oneLine(msg string) string { + return strings.NewReplacer("\r\n", " ", "\n", " ", "\r", " ").Replace(msg) +} diff --git a/station/log_test.go b/station/log_test.go new file mode 100644 index 0000000..d705908 --- /dev/null +++ b/station/log_test.go @@ -0,0 +1,197 @@ +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("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("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) +} diff --git a/station/protocol.go b/station/protocol.go index 2d795a3..de8c800 100644 --- a/station/protocol.go +++ b/station/protocol.go @@ -17,6 +17,7 @@ const ( tcpTalkerStart = 104 tcpTalkerStop = 105 tcpSelectTG = 106 + tcpNodeInfo = 111 udpHeartbeat = 1 udpAudio = 101 diff --git a/station/reflector_test.go b/station/reflector_test.go index b7dafe0..286b83f 100644 --- a/station/reflector_test.go +++ b/station/reflector_test.go @@ -2,6 +2,7 @@ package station_test import ( "encoding/binary" + "encoding/json" "io" "net" "os" @@ -283,6 +284,21 @@ func takeU32(t *testing.T, b []byte) (uint32, []byte) { return binary.BigEndian.Uint32(b[:4]), b[4:] } +func requireSoftwareIdentity(t *testing.T, body []byte) { + t.Helper() + raw, rest := takeStr(t, body) + if len(rest) != 0 { + t.Fatalf("software identity has %d trailing bytes", len(rest)) + } + var got map[string]string + if err := json.Unmarshal([]byte(raw), &got); err != nil { + t.Fatalf("software identity %q: %v", raw, err) + } + if len(got) != 2 || got["sw"] != station.SoftwareName || got["swVer"] != station.SoftwareVersion { + t.Fatalf("software identity = %#v, want sw %q and swVer %q only", got, station.SoftwareName, station.SoftwareVersion) + } +} + func takeStr(t *testing.T, b []byte) (string, []byte) { t.Helper() n, rest := takeU16(t, b) diff --git a/station/session.go b/station/session.go index 763d2ac..8e02e95 100644 --- a/station/session.go +++ b/station/session.go @@ -20,6 +20,7 @@ var errStopped = errors.New("session stopped") // Run keeps the reflector session until ctx is canceled. func (s *Station) Run(ctx context.Context) error { + defer s.Close() for { if ctx.Err() != nil { return nil @@ -41,8 +42,7 @@ func (s *Station) Run(ctx context.Context) error { return nil } s.mu.Lock() - s.state.Connection = "Disconnected" - s.publish() + s.noteDownLocked(s.clock.Now(), true) s.mu.Unlock() if !s.wait(ctx, 2*time.Second) { return nil @@ -54,14 +54,13 @@ func (s *Station) Run(ctx context.Context) error { conn.Close() s.mu.Lock() s.closeUDP() - if s.fatal == "" { - s.state.Connection = "Disconnected" - s.remoteTalker = "" - s.roomBusy = false - } s.mic = nil s.play = nil - s.publish() + if s.fatal == "" { + s.noteDownLocked(s.clock.Now(), false) + } else { + s.publish() + } fatal := s.fatal != "" s.mu.Unlock() if ctx.Err() != nil { @@ -289,7 +288,7 @@ func (s *Station) onTCP(conn net.Conn, f frame, done <-chan struct{}, udpCh *cha if err != nil { msg = "could not be read" } - s.stop(msg) + s.endFatal(msg, true) return errStopped case tcpServerInfo: return s.onServerInfo(conn, f.body, done, udpCh, udpErr, udpReady, udpRx, lastTCP) @@ -310,7 +309,7 @@ func (s *Station) onServerInfo(conn net.Conn, body []byte, done <-chan struct{}, return err } if !hasOPUS(codecs) { - s.stop(noOpus) + s.endFatal(noOpus, true) return errStopped } enc, err := opus.NewEncoder() @@ -322,6 +321,17 @@ func (s *Station) onServerInfo(conn net.Conn, body []byte, done <-chan struct{}, enc.Close() return err } + info, err := softwareIdentityBody() + if err != nil { + enc.Close() + dec.Close() + return err + } + if err := writeFrame(conn, tcpNodeInfo, info); err != nil { + enc.Close() + dec.Close() + return err + } var tg [4]byte binary.BigEndian.PutUint32(tg[:], uint32(s.cfg.talkGroup)) if err := writeFrame(conn, tcpSelectTG, tg[:]); err != nil { @@ -362,6 +372,10 @@ func (s *Station) onServerInfo(conn net.Conn, body []byte, done <-chan struct{}, return err } s.state.Connection = "Connected" + s.up = true + s.outage = false + s.noteTransmitLocked() + s.writeLog(s.clock.Now(), "connected") s.publish() s.mu.Unlock() @@ -372,12 +386,7 @@ func (s *Station) onServerInfo(conn net.Conn, body []byte, done <-chan struct{}, return nil } -func (s *Station) stop(msg string) { - s.mu.Lock() - defer s.mu.Unlock() - s.fatal = msg - s.publish() -} +func (s *Station) stop(msg string) { s.endFatal(msg, false) } // Fail stops retries and shows message until the operator quits. func (s *Station) Fail(message string) { s.stop(message) } @@ -393,19 +402,24 @@ func (s *Station) onTalker(body []byte, start bool) { } s.mu.Lock() defer s.mu.Unlock() + now := s.clock.Now() if start { if call == s.cfg.callsign { return } + s.closeTalkerLocked(now) was := s.transmitting() s.remoteTalker = call s.roomBusy = true + s.talkCall = call + s.talkStart = now if was && !s.transmitting() { s.endTransmit() } s.publish() return } + s.closeTalkerLocked(now) s.remoteTalker = "" s.roomBusy = false s.publish() @@ -500,6 +514,7 @@ func (s *Station) transmitting() bool { } func (s *Station) publish() { + s.noteTransmitLocked() s.state.Callsign = s.cfg.callsign s.state.TalkGroup = s.cfg.talkGroup if s.fatal != "" { @@ -517,6 +532,9 @@ func (s *Station) publish() { } else { s.state.Talker = s.remoteTalker } + if s.state.Talker == "" && s.logNotice != "" { + s.state.Detail = s.logNotice + } } select { case s.wake <- struct{}{}: diff --git a/station/session_test.go b/station/session_test.go index 21f7e82..6a384c9 100644 --- a/station/session_test.go +++ b/station/session_test.go @@ -67,6 +67,12 @@ func TestLoginAnnouncesProtocolAndJoinsTheTalkGroup(t *testing.T) { refl.writeFrame(t, 12, nil) refl.writeFrame(t, 100, serverInfo(0x1234, []string{"db0abc"}, []string{"GSM", "OPUS"})) + typ, body = refl.readFrame(t) + if typ != 111 { + t.Fatalf("frame type %d, want software identity", typ) + } + requireSoftwareIdentity(t, body) + typ, body = refl.readFrame(t) if typ != 106 { t.Fatalf("frame type %d, want select talk group", typ) @@ -89,7 +95,7 @@ func TestLoginAnnouncesProtocolAndJoinsTheTalkGroup(t *testing.T) { t.Fatalf("State = %+v, want Connected Idle", got) } - // No other talk group and no station profile: the next TCP message is a heartbeat, not type 107 or 111. + // No other talk group: the next TCP message is a heartbeat, not a monitor set. clock.BlockUntilWaiting(t) clock.Advance(10 * time.Second) typ, _ = refl.readFrame(t) diff --git a/station/software.go b/station/software.go new file mode 100644 index 0000000..e39b992 --- /dev/null +++ b/station/software.go @@ -0,0 +1,24 @@ +package station + +import "encoding/json" + +// SoftwareName and SoftwareVersion are the identity sent to the reflector +// after login. Edit them here. +const ( + SoftwareName = "funknetz" + SoftwareVersion = "1.0.0" +) + +func softwareIdentityBody() ([]byte, error) { + raw, err := json.Marshal(struct { + SW string `json:"sw"` + SWVer string `json:"swVer"` + }{ + SW: SoftwareName, + SWVer: SoftwareVersion, + }) + if err != nil { + return nil, err + } + return appendString(nil, string(raw)), nil +} diff --git a/station/station.go b/station/station.go index c9db2b5..6cac3a4 100644 --- a/station/station.go +++ b/station/station.go @@ -5,6 +5,7 @@ package station import ( "context" "net" + "os" "sync" "time" @@ -48,6 +49,16 @@ type Station struct { lastUDPSend time.Time enc *opus.Encoder dec *opus.Decoder + + logFile *os.File + logPath string + logNotice string + up bool + outage bool + sending bool + sendStart time.Time + talkCall string + talkStart time.Time } // New loads the config at opt.ConfigPath. A missing file is created mode 0600 @@ -61,17 +72,26 @@ func New(opt Options) (*Station, error) { if clock == nil { clock = wallClock{} } + detail := "Idle" + if cfg.logNotice != "" { + detail = cfg.logNotice + } s := &Station{ - cfg: cfg, - clock: clock, - wake: make(chan struct{}, 1), + cfg: cfg, + clock: clock, + wake: make(chan struct{}, 1), + logPath: cfg.logPath, + logNotice: cfg.logNotice, state: State{ Connection: "Disconnected", - Detail: "Idle", + Detail: detail, Callsign: cfg.callsign, TalkGroup: cfg.talkGroup, }, } + if cfg.enableLogging { + s.openLog() + } return s, nil }