From 1790075d9f7b0708521bf005a0b4e68bf7c1edc7 Mon Sep 17 00:00:00 2001 From: Raj Nakarja Date: Fri, 2 Oct 2026 17:11:22 +0200 Subject: [PATCH 1/2] Add tail to follow a fleet's logs tail takes one fleet id and optional IMEIs. It prints the newest logs, then each new one as the server's long poll returns it, and retries a dropped connection from the same cursor so no line is lost or repeated. Each line is the local time the server received the log, the device's name or IMEI, the kind in brackets, and the text. Tabs, quotes, and backslashes print as the device sent them. Other control characters are escaped so device output cannot drive the terminal. --- README.md | 43 ++- internal/logs/logs.go | 232 ++++++++++++++ internal/logs/logs_test.go | 610 +++++++++++++++++++++++++++++++++++++ main.go | 3 +- main_test.go | 7 +- 5 files changed, 889 insertions(+), 6 deletions(-) create mode 100644 internal/logs/logs.go create mode 100644 internal/logs/logs_test.go diff --git a/README.md b/README.md index 97a17b4..5796673 100644 --- a/README.md +++ b/README.md @@ -4,8 +4,6 @@ fleets, manage devices, and control who can reach them. It is a single static binary for managing Superstack from a terminal. -Streaming logs is not available yet. - ## Install - **macOS**, with [Homebrew](https://brew.sh): @@ -40,6 +38,47 @@ Streaming logs is not available yet. [releases page](https://github.com/siliconwitchery/superstack-cli/releases), unpack it, and move `superstack` onto your `PATH`. Repeat to update. +## Follow a fleet's logs + +`tail` shows a fleet's logs as they arrive. Keep it open in one terminal while +you upload code from another: + +```sh +superstack tail [imei ...] [-n num] [--log-file ] +``` + +- IMEIs after the fleet id limit the logs to those devices. +- `-n` sets how many earlier logs to show first, from 0 to 1000. The default + is 10. +- `--log-file` appends every line shown to a file. +- Ctrl-C ends it. + +Each line gives the local date and time, the device's name or IMEI, the kind +of log in brackets, and the text. The kind is `lua` for `print` output, +`lifecycle` for code starting or stopping, and `error` for an error: + +``` +2026-10-02 12:01:07 kitchen[lua]: hello 1 +2026-10-02 12:01:07 kitchen[lifecycle]: Code started +2026-10-02 12:01:09 kitchen[error]: Code crashed: main.lua:3: attempt to index a nil value +``` + +Lines from `tail` itself carry `superstack:` in place of a device. + +Filter the output, or a file written by `--log-file`, with `grep`: + +```sh +grep ' kitchen\[' tail.log # one device +grep '\[error\]: ' tail.log # only errors +grep '^2026-10-02 12:' tail.log # one hour +``` + +`print` output appears as Lua prints it. Characters that would control the +terminal appear escaped, such as `\x1b`. + +If the server stops answering, `tail` says so and keeps trying. It then carries +on from where it stopped, with no log lost or repeated. + ## Local development 1. Clone the repository: diff --git a/internal/logs/logs.go b/internal/logs/logs.go new file mode 100644 index 0000000..23e2a61 --- /dev/null +++ b/internal/logs/logs.go @@ -0,0 +1,232 @@ +package logs + +import ( + "errors" + "fmt" + "net/http" + "net/url" + "os" + "strconv" + "strings" + "time" + + "github.com/siliconwitchery/superstack-cli/internal/api" +) + +func Tail(invocation api.Invocation, arguments []string) error { + positionals := []string{} + count := 10 + logFilePath := "" + + for index := 0; index < len(arguments); index++ { + switch arguments[index] { + case "-n": + index++ + + value := "" + + if index < len(arguments) { + value = arguments[index] + } + + parsed, err := strconv.Atoi(value) + + if err != nil || parsed < 0 || parsed > 1000 { + return errors.New("-n needs the number of earlier logs to show, from 0 to 1000") + } + + count = parsed + + case "--log-file": + index++ + + if index == len(arguments) { + return errors.New("--log-file needs a file") + } + + logFilePath = arguments[index] + + default: + positionals = append(positionals, arguments[index]) + } + } + + if len(positionals) == 0 { + return errors.New("tail takes one fleet id, then optional IMEIs, each the 15-digit number printed on the device") + } + + imeis := []string{} + + for index, positional := range positionals { + isImei := len(positional) == 15 && !strings.ContainsFunc(positional, func(digit rune) bool { return digit < '0' || digit > '9' }) + + if index == 0 && isImei || index > 0 && !isImei { + return errors.New("tail takes one fleet id, then optional IMEIs, each the 15-digit number printed on the device") + } + + if isImei { + imeis = append(imeis, positional) + } + } + + fleetId, err := strconv.ParseInt(positionals[0], 10, 64) + + if err != nil || fleetId < 1 { + return errors.New("the fleet id is the number shown by fleet list") + } + + var logFile *os.File + + if logFilePath != "" { + logFile, err = os.OpenFile(logFilePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644) + + if err != nil { + return fmt.Errorf("%s could not be opened for writing", logFilePath) + } + + defer logFile.Close() + } + + show := func(lines string) error { + fmt.Fprint(invocation.Out, lines) + + if logFile == nil { + return nil + } + + _, err := logFile.WriteString(lines) + + if err != nil { + return fmt.Errorf("%s could not be written", logFilePath) + } + + return nil + } + + path := "/fleets/" + strconv.FormatInt(fleetId, 10) + "/logs?" + query := url.Values{"imei": imeis, "last": {strconv.Itoa(count)}} + failures := 0 + + for { + request, err := api.AuthenticatedRequest(invocation, http.MethodGet, path+query.Encode(), nil) + + if err != nil { + return err + } + + answer := struct { + Logs []struct { + Imei string `json:"imei"` + Name *string `json:"name"` + Kind string `json:"kind"` + Text string `json:"text"` + ReceivedAt string `json:"received_at"` + } `json:"logs"` + Next int64 `json:"next"` + }{} + + response, err := invocation.Client.Do(request) + + failed := err != nil + + if !failed { + switch { + case response.StatusCode == http.StatusOK: + err = api.Decode(response, &answer) + + failed = err != nil + + case response.StatusCode >= 500: + failed = true + + default: + refusal := api.ServerError(response) + + response.Body.Close() + + return refusal + } + + response.Body.Close() + } + + // The query is unchanged on a retry, so no log is lost or shown twice. + if failed { + if failures == 0 { + err = show(time.Now().Format("2006-01-02 15:04:05") + " superstack: The server stopped answering. Trying again.\n") + + if err != nil { + return err + } + } + + delay := 10 * time.Second + + if failures < 3 { + delay = time.Second << failures // 1, 2, then 4 seconds + } + + time.Sleep(delay) + + failures++ + + continue + } + + if failures > 0 { + err = show(time.Now().Format("2006-01-02 15:04:05") + " superstack: The server is answering again.\n") + + if err != nil { + return err + } + + failures = 0 + } + + lines := strings.Builder{} + + for _, entry := range answer.Logs { + received := "---------- --:--:--" + + receivedAt, err := time.Parse(time.RFC3339, entry.ReceivedAt) + + if err == nil { + received = receivedAt.Local().Format("2006-01-02 15:04:05") + } + + device := entry.Imei + + if entry.Name != nil && *entry.Name != "" { + device = *entry.Name + } + + for _, line := range strings.Split(entry.Text, "\n") { + lines.WriteString(received + " " + api.Printable(device) + "[" + api.Printable(entry.Kind) + "]: ") + + // Tabs and every graphic character print as Lua would print + // them. The rest is escaped so a device cannot drive the terminal. + for _, letter := range line { + if letter == '\t' || strconv.IsGraphic(letter) { + lines.WriteRune(letter) + continue + } + + quoted := strconv.QuoteRuneToGraphic(letter) + + lines.WriteString(quoted[1 : len(quoted)-1]) + } + + lines.WriteString("\n") + } + } + + err = show(lines.String()) + + if err != nil { + return err + } + + // The server holds this request for up to 20 seconds, inside the client's 30-second timeout. + query = url.Values{"after": {strconv.FormatInt(answer.Next, 10)}, "imei": imeis, "wait": {"20"}} + } +} diff --git a/internal/logs/logs_test.go b/internal/logs/logs_test.go new file mode 100644 index 0000000..97ac278 --- /dev/null +++ b/internal/logs/logs_test.go @@ -0,0 +1,610 @@ +package logs + +import ( + "bytes" + "encoding/json" + "fmt" + "net/http" + "os" + "path/filepath" + "slices" + "strconv" + "strings" + "sync" + "testing" + "time" + + "github.com/siliconwitchery/superstack-cli/internal/api" + "github.com/siliconwitchery/superstack-cli/internal/api/apitest" +) + +const kitchen = "111111111111111" +const porch = "222222222222222" + +type scriptedAnswer struct { + status int + body string + drop bool + stall bool +} + +type servedLog struct { + Id int64 `json:"id"` + Imei string `json:"imei"` + Name *string `json:"name"` + Kind string `json:"kind"` + Text string `json:"text"` + ReceivedAt string `json:"received_at"` +} + +// Served in UTC and shown as 2026-01-15 12:01 and that many seconds, whatever zone the test runs in. +func served(second int, imei string, name string, kind string, text string) servedLog { + log := servedLog{ + Id: int64(second), + Imei: imei, + Kind: kind, + Text: text, + ReceivedAt: time.Date(2026, time.January, 15, 12, 1, second, 0, time.Local).UTC().Format(time.RFC3339), + } + + if name != "" { + log.Name = &name + } + + return log +} + +func answer(t *testing.T, next int64, logs ...servedLog) scriptedAnswer { + t.Helper() + + if logs == nil { + logs = []servedLog{} + } + + body, err := json.Marshal(struct { + Logs []servedLog `json:"logs"` + Next int64 `json:"next"` + }{logs, next}) + + if err != nil { + t.Fatal(err) + } + + return scriptedAnswer{status: http.StatusOK, body: string(body)} +} + +// Serves the answers in order, then refuses with "the test is over", which +// ends a tail that would otherwise run until Ctrl-C. +func serveLogs(t *testing.T, answers []scriptedAnswer) (api.Invocation, *bytes.Buffer, func() []string) { + t.Helper() + + lock := sync.Mutex{} + queries := []string{} + + mux := http.NewServeMux() + mux.HandleFunc("GET /fleets/3/logs", func(w http.ResponseWriter, r *http.Request) { + lock.Lock() + index := len(queries) + queries = append(queries, r.URL.RawQuery) + lock.Unlock() + + if index >= len(answers) { + http.Error(w, "the test is over", http.StatusGone) + return + } + + switch { + case answers[index].drop: + connection, _, err := w.(http.Hijacker).Hijack() + + if err != nil { + t.Error(err) + return + } + + connection.Close() + + case answers[index].stall: + select { + case <-r.Context().Done(): + case <-time.After(10 * time.Second): + } + + default: + w.WriteHeader(answers[index].status) + fmt.Fprint(w, answers[index].body) + } + }) + + invocation, out := apitest.LoggedInInvocation(t, mux) + + // A reused connection would let the transport quietly resend a dropped request. + client := *invocation.Client + client.Transport = &http.Transport{DisableKeepAlives: true} + invocation.Client = &client + + seen := func() []string { + lock.Lock() + defer lock.Unlock() + + return slices.Clone(queries) + } + + return invocation, out, seen +} + +// Checks that each notice leads with the local time it was printed, then +// swaps that time for so the rest of the output compares exactly. +func checkNoticeTimes(t *testing.T, shown string, started time.Time) string { + t.Helper() + + lines := strings.SplitAfter(shown, "\n") + + for index, line := range lines { + if len(line) < 19 || !strings.HasPrefix(line[19:], " superstack: ") { + continue + } + + printedAt, err := time.ParseInLocation("2006-01-02 15:04:05", line[:19], time.Local) + + if err != nil || printedAt.Before(started.Truncate(time.Second)) || printedAt.After(time.Now()) { + t.Errorf("the notice %q does not lead with the local time it was printed", line) + } + + lines[index] = "" + line[19:] + } + + return strings.Join(lines, "") +} + +func TestTail(t *testing.T) { + const usage = "tail takes one fleet id, then optional IMEIs" + + tests := []struct { + name string + arguments []string + answers []scriptedAnswer + loggedOut bool + clientTimeout time.Duration + wantQueries []string + wantOutput string + wantError string + wantAtLeast time.Duration + }{ + { + name: "history, then new logs, for a whole fleet", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + answer(t, 2, served(1, kitchen, "kitchen", "lua", "hello\t1"), served(2, porch, "", "lua", "ready")), + answer(t, 3, served(3, kitchen, "kitchen", "lua", "tick")), + answer(t, 3), + answer(t, 5, served(4, porch, "", "lua", "tock"), served(5, kitchen, "kitchen", "lua", "tick")), + }, + wantQueries: []string{"last=10", "after=2&wait=20", "after=3&wait=20", "after=3&wait=20", "after=5&wait=20"}, + wantOutput: "2026-01-15 12:01:01 kitchen[lua]: hello\t1\n" + + "2026-01-15 12:01:02 222222222222222[lua]: ready\n" + + "2026-01-15 12:01:03 kitchen[lua]: tick\n" + + "2026-01-15 12:01:04 222222222222222[lua]: tock\n" + + "2026-01-15 12:01:05 kitchen[lua]: tick\n", + }, + { + name: "one IMEI", + arguments: []string{"3", kitchen}, + answers: []scriptedAnswer{ + answer(t, 1, served(1, kitchen, "kitchen", "lua", "hello")), + answer(t, 3, served(3, kitchen, "kitchen", "lua", "tick")), + }, + wantQueries: []string{ + "imei=111111111111111&last=10", + "after=1&imei=111111111111111&wait=20", + "after=3&imei=111111111111111&wait=20", + }, + wantOutput: "2026-01-15 12:01:01 kitchen[lua]: hello\n2026-01-15 12:01:03 kitchen[lua]: tick\n", + }, + { + name: "several IMEIs", + arguments: []string{"3", porch, kitchen}, + answers: []scriptedAnswer{ + answer(t, 2, served(1, kitchen, "kitchen", "lua", "hello"), served(2, porch, "", "lua", "ready")), + }, + wantQueries: []string{ + "imei=222222222222222&imei=111111111111111&last=10", + "after=2&imei=222222222222222&imei=111111111111111&wait=20", + }, + wantOutput: "2026-01-15 12:01:01 kitchen[lua]: hello\n2026-01-15 12:01:02 222222222222222[lua]: ready\n", + }, + { + name: "a fleet with no logs yet", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + answer(t, 0), + answer(t, 1, served(1, kitchen, "kitchen", "lifecycle", "Code started")), + }, + wantQueries: []string{"last=10", "after=0&wait=20", "after=1&wait=20"}, + wantOutput: "2026-01-15 12:01:01 kitchen[lifecycle]: Code started\n", + }, + { + name: "a device stops, takes new code, and starts again", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + answer(t, 1, served(1, kitchen, "kitchen", "lua", "old code 1")), + answer(t, 2, served(2, kitchen, "kitchen", "lifecycle", "Code stopped")), + answer(t, 4, served(3, kitchen, "kitchen", "lifecycle", "Code started"), served(4, kitchen, "kitchen", "lua", "new code\t1")), + answer(t, 5, served(5, kitchen, "kitchen", "error", "Code crashed: main.lua:3: attempt to index a nil value")), + }, + wantQueries: []string{"last=10", "after=1&wait=20", "after=2&wait=20", "after=4&wait=20", "after=5&wait=20"}, + wantOutput: "2026-01-15 12:01:01 kitchen[lua]: old code 1\n" + + "2026-01-15 12:01:02 kitchen[lifecycle]: Code stopped\n" + + "2026-01-15 12:01:03 kitchen[lifecycle]: Code started\n" + + "2026-01-15 12:01:04 kitchen[lua]: new code\t1\n" + + "2026-01-15 12:01:05 kitchen[error]: Code crashed: main.lua:3: attempt to index a nil value\n", + }, + { + name: "an error that spans lines names its device on each", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + answer(t, 1, served(1, porch, "", "error", "Code crashed: main.lua:3: boom\nstack traceback:\n\tmain.lua:3: in main chunk")), + }, + wantQueries: []string{"last=10", "after=1&wait=20"}, + wantOutput: "2026-01-15 12:01:01 222222222222222[error]: Code crashed: main.lua:3: boom\n" + + "2026-01-15 12:01:01 222222222222222[error]: stack traceback:\n" + + "2026-01-15 12:01:01 222222222222222[error]: \tmain.lua:3: in main chunk\n", + }, + { + name: "a device name cannot drive the terminal", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + answer(t, 1, served(1, kitchen, "\x1b[2K\rkitchen", "lua", "hello")), + }, + wantQueries: []string{"last=10", "after=1&wait=20"}, + wantOutput: "2026-01-15 12:01:01 \\x1b[2K\\rkitchen[lua]: hello\n", + }, + { + name: "a device name with spaces, and kinds this CLI does not know", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + answer(t, 2, served(1, kitchen, "back door", "firmware", "Firmware updated"), served(2, kitchen, "back door", "\x1b[2Jlua", "hello")), + }, + wantQueries: []string{"last=10", "after=2&wait=20"}, + wantOutput: "2026-01-15 12:01:01 back door[firmware]: Firmware updated\n" + + "2026-01-15 12:01:02 back door[\\x1b[2Jlua]: hello\n", + }, + { + name: "an unreadable time leaves the rest of the line", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + {status: http.StatusOK, body: `{"logs":[{"id":1,"imei":"111111111111111","name":"kitchen","kind":"lua","text":"hello","received_at":"yesterday"}],"next":1}`}, + }, + wantQueries: []string{"last=10", "after=1&wait=20"}, + wantOutput: "---------- --:--:-- kitchen[lua]: hello\n", + }, + { + name: "-n given", + arguments: []string{"3", "-n", "3"}, + answers: []scriptedAnswer{ + answer(t, 7, served(5, kitchen, "kitchen", "lua", "a"), served(6, kitchen, "kitchen", "lua", "b"), served(7, kitchen, "kitchen", "lua", "c")), + }, + wantQueries: []string{"last=3", "after=7&wait=20"}, + wantOutput: "2026-01-15 12:01:05 kitchen[lua]: a\n2026-01-15 12:01:06 kitchen[lua]: b\n2026-01-15 12:01:07 kitchen[lua]: c\n", + }, + { + name: "-n before the fleet id, with an IMEI", + arguments: []string{"-n", "1000", "3", kitchen}, + answers: []scriptedAnswer{answer(t, 0)}, + wantQueries: []string{"imei=111111111111111&last=1000", "after=0&imei=111111111111111&wait=20"}, + }, + { + name: "-n 0 shows only new logs", + arguments: []string{"3", "-n", "0"}, + answers: []scriptedAnswer{ + answer(t, 41), + answer(t, 42, served(42, kitchen, "kitchen", "lua", "new")), + }, + wantQueries: []string{"last=0", "after=41&wait=20", "after=42&wait=20"}, + wantOutput: "2026-01-15 12:01:42 kitchen[lua]: new\n", + }, + { + name: "a refused and a dropped request in a row, then recovery", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + answer(t, 1, served(1, kitchen, "kitchen", "lua", "before")), + {status: http.StatusServiceUnavailable, body: "the server is restarting"}, + {drop: true}, + answer(t, 3, served(2, kitchen, "kitchen", "lua", "during"), served(3, kitchen, "kitchen", "lua", "after")), + }, + wantQueries: []string{"last=10", "after=1&wait=20", "after=1&wait=20", "after=1&wait=20", "after=3&wait=20"}, + wantOutput: "2026-01-15 12:01:01 kitchen[lua]: before\n" + + " superstack: The server stopped answering. Trying again.\n" + + " superstack: The server is answering again.\n" + + "2026-01-15 12:01:02 kitchen[lua]: during\n" + + "2026-01-15 12:01:03 kitchen[lua]: after\n", + wantAtLeast: 3 * time.Second, + }, + { + name: "the first request times out, and a later answer is cut short", + arguments: []string{"3", "-n", "1"}, + clientTimeout: 200 * time.Millisecond, + answers: []scriptedAnswer{ + {stall: true}, + answer(t, 1, served(1, kitchen, "kitchen", "lua", "before")), + {status: http.StatusOK, body: `{"logs":[{"id":2,"imei":"111111111111111","name":"kitchen","kind":"lua","text":"aft`}, + answer(t, 2, served(2, kitchen, "kitchen", "lua", "after")), + }, + wantQueries: []string{"last=1", "last=1", "after=1&wait=20", "after=1&wait=20", "after=2&wait=20"}, + wantOutput: " superstack: The server stopped answering. Trying again.\n" + + " superstack: The server is answering again.\n" + + "2026-01-15 12:01:01 kitchen[lua]: before\n" + + " superstack: The server stopped answering. Trying again.\n" + + " superstack: The server is answering again.\n" + + "2026-01-15 12:01:02 kitchen[lua]: after\n", + wantAtLeast: 2 * time.Second, + }, + { + name: "the login is no longer valid", + arguments: []string{"3"}, + answers: []scriptedAnswer{{status: http.StatusUnauthorized, body: "the login is no longer valid, log in again"}}, + wantQueries: []string{"last=10"}, + wantError: "the login is no longer valid, log in again", + }, + { + name: "not logged in", + arguments: []string{"3"}, + loggedOut: true, + wantError: "you are not logged in, run login first", + }, + { + name: "no such fleet", + arguments: []string{"3"}, + answers: []scriptedAnswer{{status: http.StatusNotFound, body: "no such fleet"}}, + wantQueries: []string{"last=10"}, + wantError: "no such fleet", + }, + { + name: "a device outside the fleet", + arguments: []string{"3", porch}, + answers: []scriptedAnswer{{status: http.StatusNotFound, body: "device 222222222222222 is not in that fleet"}}, + wantQueries: []string{"imei=222222222222222&last=10"}, + wantError: "device 222222222222222 is not in that fleet", + }, + { + name: "an out-of-date CLI", + arguments: []string{"3"}, + answers: []scriptedAnswer{{status: http.StatusUpgradeRequired, body: "update superstack to carry on"}}, + wantQueries: []string{"last=10"}, + wantError: "update superstack to carry on", + }, + { + name: "a refusal while following ends the command", + arguments: []string{"3"}, + answers: []scriptedAnswer{ + answer(t, 1, served(1, kitchen, "kitchen", "lua", "hello")), + {status: http.StatusTooManyRequests, body: "too many tails are open, close one first"}, + }, + wantQueries: []string{"last=10", "after=1&wait=20"}, + wantOutput: "2026-01-15 12:01:01 kitchen[lua]: hello\n", + wantError: "too many tails are open, close one first", + }, + {name: "no arguments", wantError: usage}, + {name: "two fleet ids", arguments: []string{"3", "4"}, wantError: usage}, + {name: "an IMEI in first place", arguments: []string{kitchen}, wantError: usage}, + {name: "an IMEI before the fleet id", arguments: []string{kitchen, "3"}, wantError: usage}, + {name: "an IMEI that is too short", arguments: []string{"3", "11111111111111"}, wantError: usage}, + {name: "an IMEI with a letter", arguments: []string{"3", kitchen, "22222222222222a"}, wantError: usage}, + {name: "a wordy fleet id", arguments: []string{"pilot"}, wantError: "the fleet id is the number shown by fleet list"}, + {name: "fleet id zero", arguments: []string{"0", kitchen}, wantError: "the fleet id is the number shown by fleet list"}, + {name: "-n that is not a number", arguments: []string{"3", "-n", "many"}, wantError: "-n needs the number of earlier logs to show, from 0 to 1000"}, + {name: "-n below zero", arguments: []string{"3", "-n", "-1"}, wantError: "-n needs the number of earlier logs to show, from 0 to 1000"}, + {name: "-n above the most the server returns", arguments: []string{"3", "-n", "1001"}, wantError: "-n needs the number of earlier logs to show, from 0 to 1000"}, + {name: "-n with nothing after it", arguments: []string{"3", "-n"}, wantError: "-n needs the number of earlier logs to show, from 0 to 1000"}, + {name: "--log-file with nothing after it", arguments: []string{"3", "--log-file"}, wantError: "--log-file needs a file"}, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + invocation, out, seen := serveLogs(t, test.answers) + + if test.clientTimeout != 0 { + invocation.Client.Timeout = test.clientTimeout + } + + if test.loggedOut { + path, err := api.LoginKeyPath() + + if err != nil { + t.Fatal(err) + } + + err = os.Remove(path) + + if err != nil { + t.Fatal(err) + } + } + + started := time.Now() + + err := Tail(invocation, test.arguments) + + elapsed := time.Since(started) + + wantError := test.wantError + + if wantError == "" { + wantError = "the test is over" + } + + if err == nil || !strings.Contains(err.Error(), wantError) { + t.Errorf("error = %v, want %q", err, wantError) + } + + if !slices.Equal(seen(), test.wantQueries) { + t.Errorf("queries = %q, want %q", seen(), test.wantQueries) + } + + shown := checkNoticeTimes(t, out.String(), started) + + if shown != test.wantOutput { + t.Errorf("output = %q, want %q", shown, test.wantOutput) + } + + if elapsed < test.wantAtLeast { + t.Errorf("it took %s, want at least %s between the retries", elapsed, test.wantAtLeast) + } + }) + } +} + +func TestTailShowsTextAsLuaPrintsIt(t *testing.T) { + tests := []struct { + name string + text string + servedText string + want []string + }{ + {name: "plain text", text: "hello", want: []string{"hello"}}, + {name: "the tab between print's arguments", text: "a\t1\tnil", want: []string{"a\t1\tnil"}}, + {name: "quotes", text: `say "hi" and 'bye'`, want: []string{`say "hi" and 'bye'`}}, + {name: "a backslash", text: `C:\temp\new`, want: []string{`C:\temp\new`}}, + {name: "an embedded newline", text: "first\nsecond", want: []string{"first", "second"}}, + {name: "a trailing newline", text: "first\n", want: []string{"first", ""}}, + {name: "an empty print", text: "", want: []string{""}}, + {name: "other scripts and symbols", text: "気温 21°C \U0001F321", want: []string{"気温 21°C \U0001F321"}}, + {name: "a clear-screen sequence", text: "\x1b[2J\x1b[Hcleared", want: []string{`\x1b[2J\x1b[Hcleared`}}, + {name: "a window title sequence", text: "\x1b]0;title\a", want: []string{`\x1b]0;title\a`}}, + {name: "a carriage return", text: "progress\rdone", want: []string{`progress\rdone`}}, + {name: "a carriage return before a newline", text: "first\r\nsecond", want: []string{`first\r`, "second"}}, + {name: "a bell and a backspace", text: "a\bb\a", want: []string{`a\bb\a`}}, + {name: "a vertical tab and a form feed", text: "a\vb\fc", want: []string{`a\vb\fc`}}, + {name: "a null and a delete", text: "a\x00b\x7fc", want: []string{`a\x00b\x7fc`}}, + {name: "an eight-bit control sequence introducer", text: "a\u009b2Jb", want: []string{`a\u009b2Jb`}}, + {name: "a right-to-left override", text: "a\u202eb", want: []string{`a\u202eb`}}, + {name: "a zero-width joiner", text: "a\u200db", want: []string{`a\u200db`}}, + {name: "bytes that are not UTF-8", servedText: "\"a\xff\xfeb\"", want: []string{"a\ufffd\ufffdb"}}, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + servedText := test.servedText + + if servedText == "" { + encoded, err := json.Marshal(test.text) + + if err != nil { + t.Fatal(err) + } + + servedText = string(encoded) + } + + invocation, out, _ := serveLogs(t, []scriptedAnswer{{ + status: http.StatusOK, + body: `{"logs":[{"id":1,"imei":"111111111111111","name":"kitchen","kind":"lua","text":` + servedText + `,"received_at":"yesterday"}],"next":1}`, + }}) + + err := Tail(invocation, []string{"3"}) + + if err == nil || err.Error() != "the test is over" { + t.Fatalf("error = %v", err) + } + + want := "" + + for _, line := range test.want { + want += "---------- --:--:-- kitchen[lua]: " + line + "\n" + } + + if out.String() != want { + t.Errorf("output = %q, want %q", out.String(), want) + } + + for _, letter := range out.String() { + if letter != '\t' && letter != '\n' && !strconv.IsGraphic(letter) { + t.Errorf("output %q still holds %U, which a terminal would act on", out.String(), letter) + } + } + }) + } +} + +func TestTailLogFile(t *testing.T) { + tests := []struct { + name string + directory string + existing string + wantError string + }{ + {name: "a new file receives what the terminal shows"}, + {name: "an existing file is added to", existing: "2026-01-15 12:00:00 kitchen[lua]: earlier\n"}, + {name: "a file that cannot be opened fails before any request", directory: "missing", wantError: "tail.log could not be opened for writing"}, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + invocation, out, seen := serveLogs(t, []scriptedAnswer{ + answer(t, 1, served(1, kitchen, "kitchen", "lifecycle", "Code started")), + {status: http.StatusBadGateway, body: "the server is restarting"}, + answer(t, 2, served(2, kitchen, "kitchen", "lua", "first\nsecond")), + }) + + path := filepath.Join(t.TempDir(), test.directory, "tail.log") + + if test.existing != "" { + err := os.WriteFile(path, []byte(test.existing), 0o644) + + if err != nil { + t.Fatal(err) + } + } + + started := time.Now() + + err := Tail(invocation, []string{"3", "--log-file", path}) + + if test.wantError != "" { + if err == nil || !strings.Contains(err.Error(), test.wantError) { + t.Errorf("error = %v, want %q", err, test.wantError) + } + + if len(seen()) != 0 || out.String() != "" { + t.Errorf("it asked for %q and printed %q before failing", seen(), out.String()) + } + + return + } + + if err == nil || err.Error() != "the test is over" { + t.Fatalf("error = %v", err) + } + + wantOutput := "2026-01-15 12:01:01 kitchen[lifecycle]: Code started\n" + + " superstack: The server stopped answering. Trying again.\n" + + " superstack: The server is answering again.\n" + + "2026-01-15 12:01:02 kitchen[lua]: first\n" + + "2026-01-15 12:01:02 kitchen[lua]: second\n" + + shown := checkNoticeTimes(t, out.String(), started) + + if shown != wantOutput { + t.Errorf("output = %q, want %q", shown, wantOutput) + } + + written, err := os.ReadFile(path) + + if err != nil { + t.Fatal(err) + } + + if string(written) != test.existing+out.String() { + t.Errorf("the log file holds %q, want %q", written, test.existing+out.String()) + } + }) + } +} + +func TestTheClientTimeoutOutlastsTheWait(t *testing.T) { + invocation := api.NewInvocation("", "test", strings.NewReader(""), &bytes.Buffer{}) + + if invocation.Client.Timeout <= 20*time.Second { + t.Errorf("the client gives up after %s, inside the 20 seconds the server may hold a request", invocation.Client.Timeout) + } +} diff --git a/main.go b/main.go index 166e2cd..7b7cb83 100644 --- a/main.go +++ b/main.go @@ -11,6 +11,7 @@ import ( "github.com/siliconwitchery/superstack-cli/internal/fleet" "github.com/siliconwitchery/superstack-cli/internal/fleetkey" "github.com/siliconwitchery/superstack-cli/internal/login" + "github.com/siliconwitchery/superstack-cli/internal/logs" "github.com/siliconwitchery/superstack-cli/internal/member" ) @@ -57,7 +58,7 @@ var sections = []dispatch.Section{ { Title: "Logs", Commands: []dispatch.Command{ - {Name: "tail", Arguments: " [-n num] [--log-file ]", Summary: "Stream a device or fleet's log as it arrives"}, + {Name: "tail", Arguments: " [imei ...] [-n num] [--log-file ]", Summary: "Show a fleet's logs as they arrive", Run: logs.Tail}, }, }, { diff --git a/main_test.go b/main_test.go index ac95ef7..b244196 100644 --- a/main_test.go +++ b/main_test.go @@ -43,8 +43,7 @@ func TestCommandTable(t *testing.T) { func TestOnlyPlannedCommandsAreUnimplemented(t *testing.T) { plannedCommands := map[string]bool{ - "dev": true, - "tail": true, + "dev": true, } answeredByDispatch := map[string]bool{ "version": true, @@ -97,6 +96,7 @@ func TestNoPartImportsAnother(t *testing.T) { "fleet": {"api"}, "fleetkey": {"api"}, "login": {"api"}, + "logs": {"api"}, "member": {"api"}, } @@ -163,6 +163,7 @@ func TestTheTableWiresEveryCommandOffered(t *testing.T) { "key create", "key list", "key revoke", "login", "logout", "member add", "member list", "member remove", + "tail", "upload", } @@ -227,7 +228,7 @@ func TestMainReportsFailureWithANonZeroExit(t *testing.T) { {name: "no arguments", arguments: " ", wantCode: 0, wantSays: "Usage: superstack"}, {name: "the version", arguments: "version", wantCode: 0}, {name: "an unknown command", arguments: "nonsense", wantCode: 1, wantSays: "unknown command"}, - {name: "a command nobody has built yet", arguments: "tail 111111111111111", wantCode: 1, wantSays: "not available yet"}, + {name: "a command nobody has built yet", arguments: "dev 111111111111111 main.lua", wantCode: 1, wantSays: "not available yet"}, {name: "a command that needs a login", arguments: "fleet list", wantCode: 1, wantSays: "not logged in"}, {name: "a flag with no value", arguments: "--server", wantCode: 1, wantSays: "needs an address"}, } From cf93757f50286174ae79d7b2137d6d152dd6095c Mon Sep 17 00:00:00 2001 From: Raj Nakarja Date: Mon, 5 Oct 2026 12:32:20 +0200 Subject: [PATCH 2/2] Make tail -n print and exit, and put the IMEI and name on every line -n has no upper limit and pages through the server's answers. Each line is time, IMEI, kind, then the name in brackets. --log-file is gone, and tail's own notices go to the error stream so the output holds only logs. --- README.md | 44 ++-- internal/logs/logs.go | 129 ++++------ internal/logs/logs_test.go | 487 +++++++++++++++++-------------------- main.go | 2 +- 4 files changed, 289 insertions(+), 373 deletions(-) diff --git a/README.md b/README.md index 5796673..dc67d37 100644 --- a/README.md +++ b/README.md @@ -44,40 +44,44 @@ binary for managing Superstack from a terminal. you upload code from another: ```sh -superstack tail [imei ...] [-n num] [--log-file ] +superstack tail [imei ...] [-n num] ``` - IMEIs after the fleet id limit the logs to those devices. -- `-n` sets how many earlier logs to show first, from 0 to 1000. The default - is 10. -- `--log-file` appends every line shown to a file. -- Ctrl-C ends it. +- Without `-n`, `tail` prints the 10 newest logs, then each new log as it + arrives. Ctrl-C ends it. +- `-n` prints that many of the newest logs and ends. The server keeps logs for + fourteen days. -Each line gives the local date and time, the device's name or IMEI, the kind -of log in brackets, and the text. The kind is `lua` for `print` output, -`lifecycle` for code starting or stopping, and `error` for an error: +Each line gives the time, the IMEI, the kind of log, the device's name in +brackets, and the text. The time is local and carries its offset. The kind is +`lua` for `print` output, `lifecycle` for code starting or stopping, and +`error` for an error. A device with no name prints `[]`: ``` -2026-10-02 12:01:07 kitchen[lua]: hello 1 -2026-10-02 12:01:07 kitchen[lifecycle]: Code started -2026-10-02 12:01:09 kitchen[error]: Code crashed: main.lua:3: attempt to index a nil value +2026-10-02T12:01:07+02:00 356938035643809 lua [back door] hello +2026-10-02T12:01:09+02:00 356938035643809 error [back door] Code crashed: main.lua:3: ... +2026-10-02T12:01:09+02:00 356938035643810 lifecycle [] Code started ``` -Lines from `tail` itself carry `superstack:` in place of a device. - -Filter the output, or a file written by `--log-file`, with `grep`: +The time, the IMEI, and the kind never contain a space, so `grep` and `awk` +can match on them: ```sh -grep ' kitchen\[' tail.log # one device -grep '\[error\]: ' tail.log # only errors -grep '^2026-10-02 12:' tail.log # one hour +superstack tail 3 -n 500 | grep ' 356938035643809 error ' # one device's errors ``` -`print` output appears as Lua prints it. Characters that would control the +`print` output appears as Lua prints it. A log of several lines prints one +line for each, with every field repeated. Characters that would control the terminal appear escaped, such as `\x1b`. -If the server stops answering, `tail` says so and keeps trying. It then carries -on from where it stopped, with no log lost or repeated. +If the server stops answering, `tail` says so on the error stream and keeps +trying. It then carries on from where it stopped, with no log lost or +repeated. The output holds only logs, so `tee` can keep a copy: + +```sh +superstack tail 3 | tee tail.log +``` ## Local development diff --git a/internal/logs/logs.go b/internal/logs/logs.go index 23e2a61..f51cf17 100644 --- a/internal/logs/logs.go +++ b/internal/logs/logs.go @@ -13,42 +13,35 @@ import ( "github.com/siliconwitchery/superstack-cli/internal/api" ) +const timeLayout = "2006-01-02T15:04:05-07:00" + func Tail(invocation api.Invocation, arguments []string) error { positionals := []string{} count := 10 - logFilePath := "" + follow := true for index := 0; index < len(arguments); index++ { - switch arguments[index] { - case "-n": - index++ - - value := "" - - if index < len(arguments) { - value = arguments[index] - } - - parsed, err := strconv.Atoi(value) - - if err != nil || parsed < 0 || parsed > 1000 { - return errors.New("-n needs the number of earlier logs to show, from 0 to 1000") - } + if arguments[index] != "-n" { + positionals = append(positionals, arguments[index]) + continue + } - count = parsed + index++ - case "--log-file": - index++ + value := "" - if index == len(arguments) { - return errors.New("--log-file needs a file") - } + if index < len(arguments) { + value = arguments[index] + } - logFilePath = arguments[index] + parsed, err := strconv.Atoi(value) - default: - positionals = append(positionals, arguments[index]) + if err != nil || parsed < 0 { + return errors.New("-n needs the number of logs to show") } + + count = parsed + follow = false } if len(positionals) == 0 { @@ -75,37 +68,10 @@ func Tail(invocation api.Invocation, arguments []string) error { return errors.New("the fleet id is the number shown by fleet list") } - var logFile *os.File - - if logFilePath != "" { - logFile, err = os.OpenFile(logFilePath, os.O_APPEND|os.O_CREATE|os.O_WRONLY, 0o644) - - if err != nil { - return fmt.Errorf("%s could not be opened for writing", logFilePath) - } - - defer logFile.Close() - } - - show := func(lines string) error { - fmt.Fprint(invocation.Out, lines) - - if logFile == nil { - return nil - } - - _, err := logFile.WriteString(lines) - - if err != nil { - return fmt.Errorf("%s could not be written", logFilePath) - } - - return nil - } - path := "/fleets/" + strconv.FormatInt(fleetId, 10) + "/logs?" query := url.Values{"imei": imeis, "last": {strconv.Itoa(count)}} failures := 0 + remaining := count for { request, err := api.AuthenticatedRequest(invocation, http.MethodGet, path+query.Encode(), nil) @@ -116,11 +82,11 @@ func Tail(invocation api.Invocation, arguments []string) error { answer := struct { Logs []struct { - Imei string `json:"imei"` - Name *string `json:"name"` - Kind string `json:"kind"` - Text string `json:"text"` - ReceivedAt string `json:"received_at"` + Imei string `json:"imei"` + Name string `json:"name"` + Kind string `json:"kind"` + Text string `json:"text"` + ReceivedAt time.Time `json:"received_at"` } `json:"logs"` Next int64 `json:"next"` }{} @@ -153,11 +119,7 @@ func Tail(invocation api.Invocation, arguments []string) error { // The query is unchanged on a retry, so no log is lost or shown twice. if failed { if failures == 0 { - err = show(time.Now().Format("2006-01-02 15:04:05") + " superstack: The server stopped answering. Trying again.\n") - - if err != nil { - return err - } + fmt.Fprintln(os.Stderr, time.Now().Format(timeLayout)+" superstack: The server stopped answering. Trying again.") } delay := 10 * time.Second @@ -174,34 +136,31 @@ func Tail(invocation api.Invocation, arguments []string) error { } if failures > 0 { - err = show(time.Now().Format("2006-01-02 15:04:05") + " superstack: The server is answering again.\n") - - if err != nil { - return err - } + fmt.Fprintln(os.Stderr, time.Now().Format(timeLayout)+" superstack: The server is answering again.") failures = 0 } - lines := strings.Builder{} - - for _, entry := range answer.Logs { - received := "---------- --:--:--" + ended := false - receivedAt, err := time.Parse(time.RFC3339, entry.ReceivedAt) + if !follow { + isFull := len(answer.Logs) == 1000 // the most the server puts in one answer - if err == nil { - received = receivedAt.Local().Format("2006-01-02 15:04:05") + if len(answer.Logs) > remaining { + answer.Logs = answer.Logs[:remaining] } - device := entry.Imei + remaining -= len(answer.Logs) + ended = remaining == 0 || !isFull + } - if entry.Name != nil && *entry.Name != "" { - device = *entry.Name - } + lines := strings.Builder{} + + for _, entry := range answer.Logs { + prefix := entry.ReceivedAt.Local().Format(timeLayout) + " " + entry.Imei + " " + entry.Kind + " [" + api.Printable(entry.Name) + "] " for _, line := range strings.Split(entry.Text, "\n") { - lines.WriteString(received + " " + api.Printable(device) + "[" + api.Printable(entry.Kind) + "]: ") + lines.WriteString(prefix) // Tabs and every graphic character print as Lua would print // them. The rest is escaped so a device cannot drive the terminal. @@ -220,13 +179,13 @@ func Tail(invocation api.Invocation, arguments []string) error { } } - err = show(lines.String()) + fmt.Fprint(invocation.Out, lines.String()) - if err != nil { - return err + if ended { + return nil } - // The server holds this request for up to 20 seconds, inside the client's 30-second timeout. - query = url.Values{"after": {strconv.FormatInt(answer.Next, 10)}, "imei": imeis, "wait": {"20"}} + // The server holds this request for up to 20 seconds when it has no logs, inside the client's 30-second timeout. + query = url.Values{"after": {strconv.FormatInt(answer.Next, 10)}, "imei": imeis} } } diff --git a/internal/logs/logs_test.go b/internal/logs/logs_test.go index 97ac278..d8ff3c5 100644 --- a/internal/logs/logs_test.go +++ b/internal/logs/logs_test.go @@ -1,17 +1,21 @@ package logs import ( + "bufio" "bytes" "encoding/json" "fmt" + "io" "net/http" "os" - "path/filepath" + "os/exec" + "runtime" "slices" "strconv" "strings" "sync" "testing" + "testing/synctest" "time" "github.com/siliconwitchery/superstack-cli/internal/api" @@ -21,6 +25,10 @@ import ( const kitchen = "111111111111111" const porch = "222222222222222" +func init() { + time.Local = time.FixedZone("", 2*60*60) +} + type scriptedAnswer struct { status int body string @@ -37,7 +45,7 @@ type servedLog struct { ReceivedAt string `json:"received_at"` } -// Served in UTC and shown as 2026-01-15 12:01 and that many seconds, whatever zone the test runs in. +// Served in UTC and shown as 2026-01-15T12:01 and that many seconds, at +02:00. func served(second int, imei string, name string, kind string, text string) servedLog { log := servedLog{ Id: int64(second), @@ -73,6 +81,31 @@ func answer(t *testing.T, next int64, logs ...servedLog) scriptedAnswer { return scriptedAnswer{status: http.StatusOK, body: string(body)} } +// One full answer from the server when from and to are 1,000 apart. +func page(t *testing.T, from int, to int) scriptedAnswer { + t.Helper() + + logs := []servedLog{} + + for id := from; id <= to; id++ { + logs = append(logs, served(id, kitchen, "kitchen", "lua", "tick "+strconv.Itoa(id))) + } + + return answer(t, int64(to), logs...) +} + +func printedPage(from int, to int) string { + lines := strings.Builder{} + + for id := from; id <= to; id++ { + receivedAt := time.Date(2026, time.January, 15, 12, 1, id, 0, time.Local) + + lines.WriteString(receivedAt.Format("2006-01-02T15:04:05-07:00") + " 111111111111111 lua [kitchen] tick " + strconv.Itoa(id) + "\n") + } + + return lines.String() +} + // Serves the answers in order, then refuses with "the test is over", which // ends a tail that would otherwise run until Ctrl-C. func serveLogs(t *testing.T, answers []scriptedAnswer) (api.Invocation, *bytes.Buffer, func() []string) { @@ -133,73 +166,36 @@ func serveLogs(t *testing.T, answers []scriptedAnswer) (api.Invocation, *bytes.B return invocation, out, seen } -// Checks that each notice leads with the local time it was printed, then -// swaps that time for so the rest of the output compares exactly. -func checkNoticeTimes(t *testing.T, shown string, started time.Time) string { - t.Helper() - - lines := strings.SplitAfter(shown, "\n") - - for index, line := range lines { - if len(line) < 19 || !strings.HasPrefix(line[19:], " superstack: ") { - continue - } - - printedAt, err := time.ParseInLocation("2006-01-02 15:04:05", line[:19], time.Local) - - if err != nil || printedAt.Before(started.Truncate(time.Second)) || printedAt.After(time.Now()) { - t.Errorf("the notice %q does not lead with the local time it was printed", line) - } - - lines[index] = "" + line[19:] - } - - return strings.Join(lines, "") -} - func TestTail(t *testing.T) { const usage = "tail takes one fleet id, then optional IMEIs" + const over = "the test is over" tests := []struct { - name string - arguments []string - answers []scriptedAnswer - loggedOut bool - clientTimeout time.Duration - wantQueries []string - wantOutput string - wantError string - wantAtLeast time.Duration + name string + arguments []string + answers []scriptedAnswer + loggedOut bool + wantQueries []string + wantOutput string + wantNotices string + wantError string + wantElapsed time.Duration }{ { - name: "history, then new logs, for a whole fleet", + name: "earlier logs, then new logs, for a whole fleet", arguments: []string{"3"}, answers: []scriptedAnswer{ - answer(t, 2, served(1, kitchen, "kitchen", "lua", "hello\t1"), served(2, porch, "", "lua", "ready")), - answer(t, 3, served(3, kitchen, "kitchen", "lua", "tick")), + answer(t, 2, served(1, kitchen, "back door", "lua", "hello\t1"), served(2, porch, "", "lifecycle", "Code started")), + answer(t, 3, served(3, kitchen, "back door", "error", "Code crashed: main.lua:3: attempt to index a nil value")), answer(t, 3), - answer(t, 5, served(4, porch, "", "lua", "tock"), served(5, kitchen, "kitchen", "lua", "tick")), - }, - wantQueries: []string{"last=10", "after=2&wait=20", "after=3&wait=20", "after=3&wait=20", "after=5&wait=20"}, - wantOutput: "2026-01-15 12:01:01 kitchen[lua]: hello\t1\n" + - "2026-01-15 12:01:02 222222222222222[lua]: ready\n" + - "2026-01-15 12:01:03 kitchen[lua]: tick\n" + - "2026-01-15 12:01:04 222222222222222[lua]: tock\n" + - "2026-01-15 12:01:05 kitchen[lua]: tick\n", - }, - { - name: "one IMEI", - arguments: []string{"3", kitchen}, - answers: []scriptedAnswer{ - answer(t, 1, served(1, kitchen, "kitchen", "lua", "hello")), - answer(t, 3, served(3, kitchen, "kitchen", "lua", "tick")), - }, - wantQueries: []string{ - "imei=111111111111111&last=10", - "after=1&imei=111111111111111&wait=20", - "after=3&imei=111111111111111&wait=20", + answer(t, 4, served(4, porch, "", "lua", "tock")), }, - wantOutput: "2026-01-15 12:01:01 kitchen[lua]: hello\n2026-01-15 12:01:03 kitchen[lua]: tick\n", + wantQueries: []string{"last=10", "after=2", "after=3", "after=3", "after=4"}, + wantOutput: "2026-01-15T12:01:01+02:00 111111111111111 lua [back door] hello\t1\n" + + "2026-01-15T12:01:02+02:00 222222222222222 lifecycle [] Code started\n" + + "2026-01-15T12:01:03+02:00 111111111111111 error [back door] Code crashed: main.lua:3: attempt to index a nil value\n" + + "2026-01-15T12:01:04+02:00 222222222222222 lua [] tock\n", + wantError: over, }, { name: "several IMEIs", @@ -209,46 +205,23 @@ func TestTail(t *testing.T) { }, wantQueries: []string{ "imei=222222222222222&imei=111111111111111&last=10", - "after=2&imei=222222222222222&imei=111111111111111&wait=20", + "after=2&imei=222222222222222&imei=111111111111111", }, - wantOutput: "2026-01-15 12:01:01 kitchen[lua]: hello\n2026-01-15 12:01:02 222222222222222[lua]: ready\n", + wantOutput: "2026-01-15T12:01:01+02:00 111111111111111 lua [kitchen] hello\n" + + "2026-01-15T12:01:02+02:00 222222222222222 lua [] ready\n", + wantError: over, }, { - name: "a fleet with no logs yet", - arguments: []string{"3"}, - answers: []scriptedAnswer{ - answer(t, 0), - answer(t, 1, served(1, kitchen, "kitchen", "lifecycle", "Code started")), - }, - wantQueries: []string{"last=10", "after=0&wait=20", "after=1&wait=20"}, - wantOutput: "2026-01-15 12:01:01 kitchen[lifecycle]: Code started\n", - }, - { - name: "a device stops, takes new code, and starts again", - arguments: []string{"3"}, - answers: []scriptedAnswer{ - answer(t, 1, served(1, kitchen, "kitchen", "lua", "old code 1")), - answer(t, 2, served(2, kitchen, "kitchen", "lifecycle", "Code stopped")), - answer(t, 4, served(3, kitchen, "kitchen", "lifecycle", "Code started"), served(4, kitchen, "kitchen", "lua", "new code\t1")), - answer(t, 5, served(5, kitchen, "kitchen", "error", "Code crashed: main.lua:3: attempt to index a nil value")), - }, - wantQueries: []string{"last=10", "after=1&wait=20", "after=2&wait=20", "after=4&wait=20", "after=5&wait=20"}, - wantOutput: "2026-01-15 12:01:01 kitchen[lua]: old code 1\n" + - "2026-01-15 12:01:02 kitchen[lifecycle]: Code stopped\n" + - "2026-01-15 12:01:03 kitchen[lifecycle]: Code started\n" + - "2026-01-15 12:01:04 kitchen[lua]: new code\t1\n" + - "2026-01-15 12:01:05 kitchen[error]: Code crashed: main.lua:3: attempt to index a nil value\n", - }, - { - name: "an error that spans lines names its device on each", + name: "a log of several lines carries every field on each", arguments: []string{"3"}, answers: []scriptedAnswer{ answer(t, 1, served(1, porch, "", "error", "Code crashed: main.lua:3: boom\nstack traceback:\n\tmain.lua:3: in main chunk")), }, - wantQueries: []string{"last=10", "after=1&wait=20"}, - wantOutput: "2026-01-15 12:01:01 222222222222222[error]: Code crashed: main.lua:3: boom\n" + - "2026-01-15 12:01:01 222222222222222[error]: stack traceback:\n" + - "2026-01-15 12:01:01 222222222222222[error]: \tmain.lua:3: in main chunk\n", + wantQueries: []string{"last=10", "after=1"}, + wantOutput: "2026-01-15T12:01:01+02:00 222222222222222 error [] Code crashed: main.lua:3: boom\n" + + "2026-01-15T12:01:01+02:00 222222222222222 error [] stack traceback:\n" + + "2026-01-15T12:01:01+02:00 222222222222222 error [] \tmain.lua:3: in main chunk\n", + wantError: over, }, { name: "a device name cannot drive the terminal", @@ -256,95 +229,84 @@ func TestTail(t *testing.T) { answers: []scriptedAnswer{ answer(t, 1, served(1, kitchen, "\x1b[2K\rkitchen", "lua", "hello")), }, - wantQueries: []string{"last=10", "after=1&wait=20"}, - wantOutput: "2026-01-15 12:01:01 \\x1b[2K\\rkitchen[lua]: hello\n", + wantQueries: []string{"last=10", "after=1"}, + wantOutput: "2026-01-15T12:01:01+02:00 111111111111111 lua [\\x1b[2K\\rkitchen] hello\n", + wantError: over, }, { - name: "a device name with spaces, and kinds this CLI does not know", - arguments: []string{"3"}, - answers: []scriptedAnswer{ - answer(t, 2, served(1, kitchen, "back door", "firmware", "Firmware updated"), served(2, kitchen, "back door", "\x1b[2Jlua", "hello")), - }, - wantQueries: []string{"last=10", "after=2&wait=20"}, - wantOutput: "2026-01-15 12:01:01 back door[firmware]: Firmware updated\n" + - "2026-01-15 12:01:02 back door[\\x1b[2Jlua]: hello\n", + name: "-n under 1,000, given first, with an IMEI", + arguments: []string{"-n", "3", "3", kitchen}, + answers: []scriptedAnswer{page(t, 5, 7)}, + wantQueries: []string{"imei=111111111111111&last=3"}, + wantOutput: printedPage(5, 7), }, { - name: "an unreadable time leaves the rest of the line", - arguments: []string{"3"}, - answers: []scriptedAnswer{ - {status: http.StatusOK, body: `{"logs":[{"id":1,"imei":"111111111111111","name":"kitchen","kind":"lua","text":"hello","received_at":"yesterday"}],"next":1}`}, - }, - wantQueries: []string{"last=10", "after=1&wait=20"}, - wantOutput: "---------- --:--:-- kitchen[lua]: hello\n", + name: "-n over 1,000 pages to the newest log", + arguments: []string{"3", "-n", "2500"}, + answers: []scriptedAnswer{page(t, 1, 1000), page(t, 1001, 2000), page(t, 2001, 2500)}, + wantQueries: []string{"last=2500", "after=1000", "after=2000"}, + wantOutput: printedPage(1, 2500), }, { - name: "-n given", - arguments: []string{"3", "-n", "3"}, - answers: []scriptedAnswer{ - answer(t, 7, served(5, kitchen, "kitchen", "lua", "a"), served(6, kitchen, "kitchen", "lua", "b"), served(7, kitchen, "kitchen", "lua", "c")), - }, - wantQueries: []string{"last=3", "after=7&wait=20"}, - wantOutput: "2026-01-15 12:01:05 kitchen[lua]: a\n2026-01-15 12:01:06 kitchen[lua]: b\n2026-01-15 12:01:07 kitchen[lua]: c\n", + name: "-n of exactly two full answers asks for no third", + arguments: []string{"3", "-n", "2000"}, + answers: []scriptedAnswer{page(t, 1, 1000), page(t, 1001, 2000)}, + wantQueries: []string{"last=2000", "after=1000"}, + wantOutput: printedPage(1, 2000), }, { - name: "-n before the fleet id, with an IMEI", - arguments: []string{"-n", "1000", "3", kitchen}, - answers: []scriptedAnswer{answer(t, 0)}, - wantQueries: []string{"imei=111111111111111&last=1000", "after=0&imei=111111111111111&wait=20"}, + name: "-n prints no more than asked when logs arrive meanwhile", + arguments: []string{"3", "-n", "1500"}, + answers: []scriptedAnswer{page(t, 1, 1000), page(t, 1001, 2000)}, + wantQueries: []string{"last=1500", "after=1000"}, + wantOutput: printedPage(1, 1500), }, { - name: "-n 0 shows only new logs", - arguments: []string{"3", "-n", "0"}, - answers: []scriptedAnswer{ - answer(t, 41), - answer(t, 42, served(42, kitchen, "kitchen", "lua", "new")), - }, - wantQueries: []string{"last=0", "after=41&wait=20", "after=42&wait=20"}, - wantOutput: "2026-01-15 12:01:42 kitchen[lua]: new\n", + name: "-n above the logs the server keeps prints them all", + arguments: []string{"3", "-n", "5000"}, + answers: []scriptedAnswer{page(t, 1, 1000), page(t, 1001, 1200)}, + wantQueries: []string{"last=5000", "after=1000"}, + wantOutput: printedPage(1, 1200), + }, + { + name: "-n 0 prints nothing", + arguments: []string{"3", "-n", "0"}, + answers: []scriptedAnswer{answer(t, 41)}, + wantQueries: []string{"last=0"}, }, { - name: "a refused and a dropped request in a row, then recovery", + name: "a refused, a dropped, and a cut-short answer in a row, then recovery", arguments: []string{"3"}, answers: []scriptedAnswer{ answer(t, 1, served(1, kitchen, "kitchen", "lua", "before")), - {status: http.StatusServiceUnavailable, body: "the server is restarting"}, + {status: http.StatusServiceUnavailable, body: "the server could not read the logs"}, {drop: true}, + {status: http.StatusOK, body: `{"logs":[{"id":2,"imei":"111111111111111","name":"kitchen","kind":"lua","text":"dur`}, + {status: http.StatusBadGateway}, + {status: http.StatusServiceUnavailable, body: "the server could not check the fleet"}, answer(t, 3, served(2, kitchen, "kitchen", "lua", "during"), served(3, kitchen, "kitchen", "lua", "after")), }, - wantQueries: []string{"last=10", "after=1&wait=20", "after=1&wait=20", "after=1&wait=20", "after=3&wait=20"}, - wantOutput: "2026-01-15 12:01:01 kitchen[lua]: before\n" + - " superstack: The server stopped answering. Trying again.\n" + - " superstack: The server is answering again.\n" + - "2026-01-15 12:01:02 kitchen[lua]: during\n" + - "2026-01-15 12:01:03 kitchen[lua]: after\n", - wantAtLeast: 3 * time.Second, + wantQueries: []string{"last=10", "after=1", "after=1", "after=1", "after=1", "after=1", "after=1", "after=3"}, + wantOutput: "2026-01-15T12:01:01+02:00 111111111111111 lua [kitchen] before\n" + + "2026-01-15T12:01:02+02:00 111111111111111 lua [kitchen] during\n" + + "2026-01-15T12:01:03+02:00 111111111111111 lua [kitchen] after\n", + wantNotices: "2000-01-01T02:00:00+02:00 superstack: The server stopped answering. Trying again.\n" + + "2000-01-01T02:00:27+02:00 superstack: The server is answering again.\n", + wantError: over, + wantElapsed: 27 * time.Second, }, { - name: "the first request times out, and a later answer is cut short", - arguments: []string{"3", "-n", "1"}, - clientTimeout: 200 * time.Millisecond, + name: "-n waits for a server that does not answer at first", + arguments: []string{"3", "-n", "1"}, answers: []scriptedAnswer{ - {stall: true}, - answer(t, 1, served(1, kitchen, "kitchen", "lua", "before")), - {status: http.StatusOK, body: `{"logs":[{"id":2,"imei":"111111111111111","name":"kitchen","kind":"lua","text":"aft`}, - answer(t, 2, served(2, kitchen, "kitchen", "lua", "after")), + {status: http.StatusServiceUnavailable, body: "the server could not read the logs"}, + page(t, 1, 1), }, - wantQueries: []string{"last=1", "last=1", "after=1&wait=20", "after=1&wait=20", "after=2&wait=20"}, - wantOutput: " superstack: The server stopped answering. Trying again.\n" + - " superstack: The server is answering again.\n" + - "2026-01-15 12:01:01 kitchen[lua]: before\n" + - " superstack: The server stopped answering. Trying again.\n" + - " superstack: The server is answering again.\n" + - "2026-01-15 12:01:02 kitchen[lua]: after\n", - wantAtLeast: 2 * time.Second, - }, - { - name: "the login is no longer valid", - arguments: []string{"3"}, - answers: []scriptedAnswer{{status: http.StatusUnauthorized, body: "the login is no longer valid, log in again"}}, - wantQueries: []string{"last=10"}, - wantError: "the login is no longer valid, log in again", + wantQueries: []string{"last=1", "last=1"}, + wantOutput: printedPage(1, 1), + wantNotices: "2000-01-01T02:00:00+02:00 superstack: The server stopped answering. Trying again.\n" + + "2000-01-01T02:00:01+02:00 superstack: The server is answering again.\n", + wantElapsed: time.Second, }, { name: "not logged in", @@ -359,54 +321,31 @@ func TestTail(t *testing.T) { wantQueries: []string{"last=10"}, wantError: "no such fleet", }, - { - name: "a device outside the fleet", - arguments: []string{"3", porch}, - answers: []scriptedAnswer{{status: http.StatusNotFound, body: "device 222222222222222 is not in that fleet"}}, - wantQueries: []string{"imei=222222222222222&last=10"}, - wantError: "device 222222222222222 is not in that fleet", - }, - { - name: "an out-of-date CLI", - arguments: []string{"3"}, - answers: []scriptedAnswer{{status: http.StatusUpgradeRequired, body: "update superstack to carry on"}}, - wantQueries: []string{"last=10"}, - wantError: "update superstack to carry on", - }, { name: "a refusal while following ends the command", arguments: []string{"3"}, answers: []scriptedAnswer{ answer(t, 1, served(1, kitchen, "kitchen", "lua", "hello")), - {status: http.StatusTooManyRequests, body: "too many tails are open, close one first"}, + {status: http.StatusTooManyRequests, body: "you already have 8 log reads open, close one first"}, }, - wantQueries: []string{"last=10", "after=1&wait=20"}, - wantOutput: "2026-01-15 12:01:01 kitchen[lua]: hello\n", - wantError: "too many tails are open, close one first", + wantQueries: []string{"last=10", "after=1"}, + wantOutput: "2026-01-15T12:01:01+02:00 111111111111111 lua [kitchen] hello\n", + wantError: "you already have 8 log reads open, close one first", }, {name: "no arguments", wantError: usage}, {name: "two fleet ids", arguments: []string{"3", "4"}, wantError: usage}, - {name: "an IMEI in first place", arguments: []string{kitchen}, wantError: usage}, {name: "an IMEI before the fleet id", arguments: []string{kitchen, "3"}, wantError: usage}, - {name: "an IMEI that is too short", arguments: []string{"3", "11111111111111"}, wantError: usage}, - {name: "an IMEI with a letter", arguments: []string{"3", kitchen, "22222222222222a"}, wantError: usage}, {name: "a wordy fleet id", arguments: []string{"pilot"}, wantError: "the fleet id is the number shown by fleet list"}, {name: "fleet id zero", arguments: []string{"0", kitchen}, wantError: "the fleet id is the number shown by fleet list"}, - {name: "-n that is not a number", arguments: []string{"3", "-n", "many"}, wantError: "-n needs the number of earlier logs to show, from 0 to 1000"}, - {name: "-n below zero", arguments: []string{"3", "-n", "-1"}, wantError: "-n needs the number of earlier logs to show, from 0 to 1000"}, - {name: "-n above the most the server returns", arguments: []string{"3", "-n", "1001"}, wantError: "-n needs the number of earlier logs to show, from 0 to 1000"}, - {name: "-n with nothing after it", arguments: []string{"3", "-n"}, wantError: "-n needs the number of earlier logs to show, from 0 to 1000"}, - {name: "--log-file with nothing after it", arguments: []string{"3", "--log-file"}, wantError: "--log-file needs a file"}, + {name: "-n that is not a number", arguments: []string{"3", "-n", "many"}, wantError: "-n needs the number of logs to show"}, + {name: "-n below zero", arguments: []string{"3", "-n", "-1"}, wantError: "-n needs the number of logs to show"}, + {name: "-n with nothing after it", arguments: []string{"3", "-n"}, wantError: "-n needs the number of logs to show"}, } for _, test := range tests { t.Run(test.name, func(t *testing.T) { invocation, out, seen := serveLogs(t, test.answers) - if test.clientTimeout != 0 { - invocation.Client.Timeout = test.clientTimeout - } - if test.loggedOut { path, err := api.LoginKeyPath() @@ -421,34 +360,56 @@ func TestTail(t *testing.T) { } } - started := time.Now() + notices, err := os.CreateTemp(t.TempDir(), "notices") - err := Tail(invocation, test.arguments) + if err != nil { + t.Fatal(err) + } - elapsed := time.Since(started) + defer notices.Close() - wantError := test.wantError + errorStream := os.Stderr + os.Stderr = notices - if wantError == "" { - wantError = "the test is over" - } + defer func() { os.Stderr = errorStream }() - if err == nil || !strings.Contains(err.Error(), wantError) { - t.Errorf("error = %v, want %q", err, wantError) - } + // The retries sleep on the bubble's clock, which starts at midnight UTC on 2000-01-01. + synctest.Test(t, func(t *testing.T) { + started := time.Now() + + err := Tail(invocation, test.arguments) + + elapsed := time.Since(started) + + if test.wantError == "" && err != nil { + t.Errorf("error = %v, want none", err) + } + + if test.wantError != "" && (err == nil || !strings.Contains(err.Error(), test.wantError)) { + t.Errorf("error = %v, want %q", err, test.wantError) + } + + if elapsed != test.wantElapsed { + t.Errorf("it slept %s between the retries, want %s", elapsed, test.wantElapsed) + } + }) if !slices.Equal(seen(), test.wantQueries) { t.Errorf("queries = %q, want %q", seen(), test.wantQueries) } - shown := checkNoticeTimes(t, out.String(), started) + if out.String() != test.wantOutput { + t.Errorf("output = %q, want %q", out.String(), test.wantOutput) + } + + written, err := os.ReadFile(notices.Name()) - if shown != test.wantOutput { - t.Errorf("output = %q, want %q", shown, test.wantOutput) + if err != nil { + t.Fatal(err) } - if elapsed < test.wantAtLeast { - t.Errorf("it took %s, want at least %s between the retries", elapsed, test.wantAtLeast) + if string(written) != test.wantNotices { + t.Errorf("the error stream holds %q, want %q", written, test.wantNotices) } }) } @@ -470,11 +431,7 @@ func TestTailShowsTextAsLuaPrintsIt(t *testing.T) { {name: "an empty print", text: "", want: []string{""}}, {name: "other scripts and symbols", text: "気温 21°C \U0001F321", want: []string{"気温 21°C \U0001F321"}}, {name: "a clear-screen sequence", text: "\x1b[2J\x1b[Hcleared", want: []string{`\x1b[2J\x1b[Hcleared`}}, - {name: "a window title sequence", text: "\x1b]0;title\a", want: []string{`\x1b]0;title\a`}}, - {name: "a carriage return", text: "progress\rdone", want: []string{`progress\rdone`}}, {name: "a carriage return before a newline", text: "first\r\nsecond", want: []string{`first\r`, "second"}}, - {name: "a bell and a backspace", text: "a\bb\a", want: []string{`a\bb\a`}}, - {name: "a vertical tab and a form feed", text: "a\vb\fc", want: []string{`a\vb\fc`}}, {name: "a null and a delete", text: "a\x00b\x7fc", want: []string{`a\x00b\x7fc`}}, {name: "an eight-bit control sequence introducer", text: "a\u009b2Jb", want: []string{`a\u009b2Jb`}}, {name: "a right-to-left override", text: "a\u202eb", want: []string{`a\u202eb`}}, @@ -498,19 +455,19 @@ func TestTailShowsTextAsLuaPrintsIt(t *testing.T) { invocation, out, _ := serveLogs(t, []scriptedAnswer{{ status: http.StatusOK, - body: `{"logs":[{"id":1,"imei":"111111111111111","name":"kitchen","kind":"lua","text":` + servedText + `,"received_at":"yesterday"}],"next":1}`, + body: `{"logs":[{"id":1,"imei":"111111111111111","name":"kitchen","kind":"lua","text":` + servedText + `,"received_at":"2026-01-15T10:01:01Z"}],"next":1}`, }}) - err := Tail(invocation, []string{"3"}) + err := Tail(invocation, []string{"3", "-n", "1"}) - if err == nil || err.Error() != "the test is over" { + if err != nil { t.Fatalf("error = %v", err) } want := "" for _, line := range test.want { - want += "---------- --:--:-- kitchen[lua]: " + line + "\n" + want += "2026-01-15T12:01:01+02:00 111111111111111 lua [kitchen] " + line + "\n" } if out.String() != want { @@ -526,78 +483,74 @@ func TestTailShowsTextAsLuaPrintsIt(t *testing.T) { } } -func TestTailLogFile(t *testing.T) { - tests := []struct { - name string - directory string - existing string - wantError string - }{ - {name: "a new file receives what the terminal shows"}, - {name: "an existing file is added to", existing: "2026-01-15 12:00:00 kitchen[lua]: earlier\n"}, - {name: "a file that cannot be opened fails before any request", directory: "missing", wantError: "tail.log could not be opened for writing"}, +// Re-runs this test binary as a child that follows the fleet's logs, so the +// interrupt reaches a whole process as Ctrl-C does. +func TestCtrlCEndsTail(t *testing.T) { + base, isChild := os.LookupEnv("SUPERSTACK_TAIL_SERVER") + + if isChild { + t.Fatal(Tail(api.NewInvocation(base, "test", os.Stdin, os.Stdout), []string{"3"})) } - for _, test := range tests { - t.Run(test.name, func(t *testing.T) { - invocation, out, seen := serveLogs(t, []scriptedAnswer{ - answer(t, 1, served(1, kitchen, "kitchen", "lifecycle", "Code started")), - {status: http.StatusBadGateway, body: "the server is restarting"}, - answer(t, 2, served(2, kitchen, "kitchen", "lua", "first\nsecond")), - }) + if runtime.GOOS == "windows" { + t.Skip("Windows has no interrupt signal to send to a child") + } - path := filepath.Join(t.TempDir(), test.directory, "tail.log") + invocation, _, _ := serveLogs(t, []scriptedAnswer{ + answer(t, 1, served(1, kitchen, "kitchen", "lua", "hello")), + {stall: true}, + }) - if test.existing != "" { - err := os.WriteFile(path, []byte(test.existing), 0o644) + command := exec.Command(os.Args[0], "-test.run=TestCtrlCEndsTail") + command.Env = append(os.Environ(), "SUPERSTACK_TAIL_SERVER="+invocation.Base) - if err != nil { - t.Fatal(err) - } - } + notices := &bytes.Buffer{} + command.Stderr = notices - started := time.Now() + output, err := command.StdoutPipe() - err := Tail(invocation, []string{"3", "--log-file", path}) + if err != nil { + t.Fatal(err) + } - if test.wantError != "" { - if err == nil || !strings.Contains(err.Error(), test.wantError) { - t.Errorf("error = %v, want %q", err, test.wantError) - } + err = command.Start() - if len(seen()) != 0 || out.String() != "" { - t.Errorf("it asked for %q and printed %q before failing", seen(), out.String()) - } + if err != nil { + t.Fatal(err) + } - return - } + reader := bufio.NewReader(output) - if err == nil || err.Error() != "the test is over" { - t.Fatalf("error = %v", err) - } + shown, err := reader.ReadString('\n') - wantOutput := "2026-01-15 12:01:01 kitchen[lifecycle]: Code started\n" + - " superstack: The server stopped answering. Trying again.\n" + - " superstack: The server is answering again.\n" + - "2026-01-15 12:01:02 kitchen[lua]: first\n" + - "2026-01-15 12:01:02 kitchen[lua]: second\n" + if err != nil { + t.Fatalf("tail printed %q and then %v, having said %q", shown, err, notices) + } - shown := checkNoticeTimes(t, out.String(), started) + err = command.Process.Signal(os.Interrupt) - if shown != wantOutput { - t.Errorf("output = %q, want %q", shown, wantOutput) - } + if err != nil { + t.Fatal(err) + } - written, err := os.ReadFile(path) + rest, err := io.ReadAll(reader) - if err != nil { - t.Fatal(err) - } + if err != nil { + t.Fatal(err) + } - if string(written) != test.existing+out.String() { - t.Errorf("the log file holds %q, want %q", written, test.existing+out.String()) - } - }) + err = command.Wait() + + if err == nil || err.Error() != "signal: interrupt" { + t.Errorf("tail ended with %v, want it ended by the interrupt", err) + } + + if shown+string(rest) != "2026-01-15T12:01:01+02:00 111111111111111 lua [kitchen] hello\n" { + t.Errorf("output = %q, want the one log", shown+string(rest)) + } + + if notices.String() != "" { + t.Errorf("the error stream holds %q, want nothing", notices) } } diff --git a/main.go b/main.go index 7b7cb83..ec9fb25 100644 --- a/main.go +++ b/main.go @@ -58,7 +58,7 @@ var sections = []dispatch.Section{ { Title: "Logs", Commands: []dispatch.Command{ - {Name: "tail", Arguments: " [imei ...] [-n num] [--log-file ]", Summary: "Show a fleet's logs as they arrive", Run: logs.Tail}, + {Name: "tail", Arguments: " [imei ...] [-n num]", Summary: "Show a fleet's logs as they arrive", Run: logs.Tail}, }, }, {