| 1 | package console |
| 2 | |
| 3 | import ( |
| 4 | "context" |
| 5 | "encoding/json" |
| 6 | "fmt" |
| 7 | "io" |
| 8 | "net/http" |
| 9 | "net/url" |
| 10 | "strings" |
| 11 | "testing" |
| 12 | "time" |
| 13 | |
| 14 | "github.com/carlosframework/platform/internal/applog" |
| 15 | "github.com/carlosframework/platform/internal/registry" |
| 16 | "github.com/carlosframework/platform/internal/release" |
| 17 | ) |
| 18 | |
| 19 | func logsURL(fx *consoleFixture, acct, app, query string) string { |
| 20 | u := fx.ts.URL + "/api/cli/apps/" + acct + "/" + app + "/logs" |
| 21 | if query != "" { |
| 22 | u += "?" + query |
| 23 | } |
| 24 | return u |
| 25 | } |
| 26 | |
| 27 | // seedLogChunks ships a small timeline for titogo: an app line and a wake |
| 28 | // failure, recent enough for the default 1h window. |
| 29 | func seedLogChunks(t *testing.T, fx *consoleFixture, now time.Time) []applog.Record { |
| 30 | t.Helper() |
| 31 | recs := []applog.Record{ |
| 32 | {TS: now.Add(-10 * time.Minute), Box: "box1", Host: "titogo.example.com", |
| 33 | Stream: applog.StreamApp, Msg: "listening on socket", Seq: 100, |
| 34 | Fields: map[string]string{"request_id": "r1"}}, |
| 35 | {TS: now.Add(-5 * time.Minute), Box: "box1", Host: "titogo.example.com", |
| 36 | Stream: applog.StreamPlatform, Level: applog.LevelError, |
| 37 | Msg: "wake failed: nothing is promoted for this instance's channel", Seq: 101}, |
| 38 | } |
| 39 | body, err := applog.EncodeChunk(recs) |
| 40 | if err != nil { |
| 41 | t.Fatal(err) |
| 42 | } |
| 43 | key := mustKey(t)(applog.ChunkKey(release.OpsAccount, "titogo", "box1", applog.HourOf(recs[0].TS), recs[0].Seq, len(body))) |
| 44 | if _, err := fx.rel.Put(context.Background(), key, body, ""); err != nil { |
| 45 | t.Fatal(err) |
| 46 | } |
| 47 | return recs |
| 48 | } |
| 49 | |
| 50 | func seedManyLogRecords(t *testing.T, fx *consoleFixture, now time.Time, n int) []applog.Record { |
| 51 | t.Helper() |
| 52 | recs := make([]applog.Record, n) |
| 53 | for i := range recs { |
| 54 | recs[i] = applog.Record{TS: now.Add(time.Duration(i) * time.Millisecond), Box: "box-many", |
| 55 | Host: "titogo.example.com", Stream: applog.StreamApp, Msg: fmt.Sprintf("line %d", i), Seq: uint64(1000 + i)} |
| 56 | } |
| 57 | body, err := applog.EncodeChunk(recs) |
| 58 | if err != nil { |
| 59 | t.Fatal(err) |
| 60 | } |
| 61 | key := mustKey(t)(applog.ChunkKey(release.OpsAccount, "titogo", "box-many", applog.HourOf(recs[0].TS), recs[0].Seq, len(body))) |
| 62 | if _, err := fx.rel.Put(context.Background(), key, body, ""); err != nil { |
| 63 | t.Fatal(err) |
| 64 | } |
| 65 | return recs |
| 66 | } |
| 67 | |
| 68 | // TestAPILogsTailFiltersAndFollow drives the endpoint end to end: default |
| 69 | // tail, stream/level/grep/field filters, and the cursor follow loop. |
| 70 | func TestAPILogsTailFiltersAndFollow(t *testing.T) { |
| 71 | fx, token := instanceFixture(t, "code-logs-1") |
| 72 | now := time.Now().UTC() |
| 73 | seedLogChunks(t, fx, now) |
| 74 | |
| 75 | get := func(query string) logsResponse { |
| 76 | t.Helper() |
| 77 | status, _, body := rawReq(t, http.MethodGet, logsURL(fx, fx.sqid, "titogo", query), token, "") |
| 78 | if status != http.StatusOK { |
| 79 | t.Fatalf("GET ?%s = %d: %s", query, status, body) |
| 80 | } |
| 81 | var resp logsResponse |
| 82 | if err := json.Unmarshal([]byte(body), &resp); err != nil { |
| 83 | t.Fatalf("bad JSON: %v: %s", err, body) |
| 84 | } |
| 85 | return resp |
| 86 | } |
| 87 | |
| 88 | // Default window: both records, oldest first, cursor present. |
| 89 | resp := get("") |
| 90 | if len(resp.Records) != 2 || resp.Records[0].Msg != "listening on socket" { |
| 91 | t.Fatalf("tail: %+v", resp) |
| 92 | } |
| 93 | if resp.Cursor == "" || resp.Truncated { |
| 94 | t.Fatalf("cursor/truncated: %+v", resp) |
| 95 | } |
| 96 | |
| 97 | // Filters compose: stream, level, grep, field. |
| 98 | if r := get("stream=platform"); len(r.Records) != 1 || r.Records[0].Level != "error" { |
| 99 | t.Fatalf("stream filter: %+v", r.Records) |
| 100 | } |
| 101 | if r := get("level=error"); len(r.Records) != 1 { |
| 102 | t.Fatalf("level filter: %+v", r.Records) |
| 103 | } |
| 104 | if r := get("grep=promoted"); len(r.Records) != 1 || r.Records[0].Stream != "platform" { |
| 105 | t.Fatalf("grep filter: %+v", r.Records) |
| 106 | } |
| 107 | if r := get("field=request_id%3Dr1"); len(r.Records) != 1 || r.Records[0].Stream != "app" { |
| 108 | t.Fatalf("field filter: %+v", r.Records) |
| 109 | } |
| 110 | if r := get("host=titogo.example.com"); len(r.Records) != 2 { |
| 111 | t.Fatalf("host filter: %+v", r.Records) |
| 112 | } |
| 113 | if r := get("host=other.example.com"); len(r.Records) != 0 { |
| 114 | t.Fatalf("host mismatch filter: %+v", r.Records) |
| 115 | } |
| 116 | |
| 117 | // limit=1 tails to the NEWEST record and says truncated. |
| 118 | r := get("limit=1") |
| 119 | if len(r.Records) != 1 || r.Records[0].Stream != "platform" || !r.Truncated { |
| 120 | t.Fatalf("limit tail: %+v", r) |
| 121 | } |
| 122 | |
| 123 | // Follow: the cursor from the full read sees nothing new, keeps itself. |
| 124 | full := get("") |
| 125 | fr := get("cursor=" + full.Cursor) |
| 126 | if len(fr.Records) != 0 || fr.Cursor != full.Cursor { |
| 127 | t.Fatalf("follow at tip: %+v", fr) |
| 128 | } |
| 129 | // A new record lands; the same cursor now yields exactly it. |
| 130 | extra := []applog.Record{{TS: now.Add(-time.Minute), Box: "box1", |
| 131 | Host: "titogo.example.com", Stream: applog.StreamApp, Msg: "fresh line", Seq: 102}} |
| 132 | body, err := applog.EncodeChunk(extra) |
| 133 | if err != nil { |
| 134 | t.Fatal(err) |
| 135 | } |
| 136 | key := mustKey(t)(applog.ChunkKey(release.OpsAccount, "titogo", "box1", applog.HourOf(extra[0].TS), 102, len(body))) |
| 137 | if _, err := fx.rel.Put(context.Background(), key, body, ""); err != nil { |
| 138 | t.Fatal(err) |
| 139 | } |
| 140 | fr2 := get("cursor=" + full.Cursor) |
| 141 | if len(fr2.Records) != 1 || fr2.Records[0].Msg != "fresh line" { |
| 142 | t.Fatalf("follow after new record: %+v", fr2) |
| 143 | } |
| 144 | } |
| 145 | |
| 146 | // TestAPILogsRefusals: a non-member's read is the family's byte-identical |
| 147 | // 404; bad parameters name themselves in a 400. |
| 148 | func TestAPILogsRefusals(t *testing.T) { |
| 149 | fx, _ := instanceFixture(t, "code-logs-2") |
| 150 | eve := cliToken(t, fx, "eve@keymail.dev", "code-logs-eve") |
| 151 | want := canonicalNotFound(t) |
| 152 | status, h, body := rawReq(t, http.MethodGet, logsURL(fx, fx.sqid, "titogo", ""), eve, "") |
| 153 | assertNotFound(t, "logs as non-member", want, status, h, body) |
| 154 | |
| 155 | _, token := func() (*consoleFixture, string) { return fx, cliToken(t, fx, "alice@keymail.dev", "code-logs-3") }() |
| 156 | for _, q := range []string{"since=garbage", "stream=nope", "level=shouting", "grep=%5B", "field=nokey", "limit=zero"} { |
| 157 | status, _, body := rawReq(t, http.MethodGet, logsURL(fx, fx.sqid, "titogo", q), token, "") |
| 158 | if status != http.StatusBadRequest { |
| 159 | t.Errorf("?%s = %d, want 400 (%s)", q, status, body) |
| 160 | } |
| 161 | } |
| 162 | |
| 163 | // An app with no logs at all: an empty list, not an error and not null. |
| 164 | status, _, body = rawReq(t, http.MethodGet, logsURL(fx, fx.sqid, "titogo", ""), token, "") |
| 165 | if status != http.StatusOK || !json.Valid([]byte(body)) { |
| 166 | t.Fatalf("empty logs: %d %s", status, body) |
| 167 | } |
| 168 | var resp logsResponse |
| 169 | if err := json.Unmarshal([]byte(body), &resp); err != nil || resp.Records == nil { |
| 170 | t.Fatalf("records must be [], got %s", body) |
| 171 | } |
| 172 | _ = fmt.Sprintf("%v", resp) |
| 173 | } |
| 174 | |
| 175 | func TestAppLogsDataUsesBrowserSessionAndFilters(t *testing.T) { |
| 176 | fx, _ := instanceFixture(t, "code-logs-browser-data") |
| 177 | seedLogChunks(t, fx, time.Now().UTC()) |
| 178 | fx.setUser("alice@keymail.dev") |
| 179 | c := newBrowser(t) |
| 180 | signUp(t, fx, c, "code-logs-browser-data-signin") |
| 181 | |
| 182 | status, _, body := get(t, c, fx.u("/apps/titogo/logs/data?host=titogo.example.com&level=error")) |
| 183 | if status != http.StatusOK { |
| 184 | t.Fatalf("browser logs data = %d: %s", status, body) |
| 185 | } |
| 186 | var resp appLogsDataResponse |
| 187 | if err := json.Unmarshal([]byte(body), &resp); err != nil { |
| 188 | t.Fatalf("browser logs JSON: %v: %s", err, body) |
| 189 | } |
| 190 | if len(resp.Lines) != 1 || !strings.Contains(resp.Lines[0].Msg, "wake failed") || resp.Lines[0].Tone != "error" { |
| 191 | t.Fatalf("filtered browser lines = %+v", resp.Lines) |
| 192 | } |
| 193 | status, _, body = get(t, c, fx.u("/apps/titogo/logs/data?host=deleted.example.com")) |
| 194 | if status != http.StatusOK || !strings.Contains(body, `"lines":[]`) { |
| 195 | t.Fatalf("historical host filter broadened = %d: %s", status, body) |
| 196 | } |
| 197 | status, _, body = get(t, c, fx.u("/apps/titogo/logs/data?text=wake%5B")) |
| 198 | if status != http.StatusOK || !strings.Contains(body, `"lines":[]`) { |
| 199 | t.Fatalf("browser text search was treated as a regular expression = %d: %s", status, body) |
| 200 | } |
| 201 | assertNonMember404(t, fx, "/apps/titogo/logs/data") |
| 202 | } |
| 203 | |
| 204 | func TestAppLogsDataCursorPaginationAndRefusals(t *testing.T) { |
| 205 | fx, _ := instanceFixture(t, "code-logs-browser-cursor") |
| 206 | now := time.Now().UTC() |
| 207 | recs := seedLogChunks(t, fx, now) |
| 208 | fx.setUser("alice@keymail.dev") |
| 209 | c := newBrowser(t) |
| 210 | signUp(t, fx, c, "code-logs-browser-cursor-signin") |
| 211 | |
| 212 | read := func(query string) (int, http.Header, appLogsDataResponse, string) { |
| 213 | t.Helper() |
| 214 | req, err := http.NewRequest(http.MethodGet, fx.u("/apps/titogo/logs/data?"+query), nil) |
| 215 | if err != nil { |
| 216 | t.Fatal(err) |
| 217 | } |
| 218 | res, err := c.Do(req) |
| 219 | if err != nil { |
| 220 | t.Fatal(err) |
| 221 | } |
| 222 | defer res.Body.Close() |
| 223 | b, err := io.ReadAll(res.Body) |
| 224 | if err != nil { |
| 225 | t.Fatal(err) |
| 226 | } |
| 227 | status, headers, body := res.StatusCode, res.Header, string(b) |
| 228 | var out appLogsDataResponse |
| 229 | if status == http.StatusOK { |
| 230 | if err := json.Unmarshal([]byte(body), &out); err != nil { |
| 231 | t.Fatalf("decode logs data: %v: %s", err, body) |
| 232 | } |
| 233 | } |
| 234 | return status, headers, out, body |
| 235 | } |
| 236 | |
| 237 | status, headers, out, body := read("cursor=" + url.QueryEscape(applog.EncodeCursor(recs[0]))) |
| 238 | if status != http.StatusOK || len(out.Lines) != 1 || !strings.Contains(out.Lines[0].Msg, "wake failed") { |
| 239 | t.Fatalf("cursor read = %d %+v: %s", status, out, body) |
| 240 | } |
| 241 | if headers.Get("Cache-Control") != "no-store" { |
| 242 | t.Fatalf("logs data Cache-Control = %q", headers.Get("Cache-Control")) |
| 243 | } |
| 244 | last := applog.EncodeCursor(recs[1]) |
| 245 | _, _, out, _ = read("cursor=" + url.QueryEscape(last)) |
| 246 | if len(out.Lines) != 0 || out.Cursor != last || out.Gap { |
| 247 | t.Fatalf("empty cursor read = %+v", out) |
| 248 | } |
| 249 | expired := applog.EncodeCursor(applog.Record{TS: now.Add(-2 * time.Hour), Box: "old", Seq: 1}) |
| 250 | _, _, out, _ = read("since=1h&cursor=" + url.QueryEscape(expired)) |
| 251 | if !out.Gap || len(out.Lines) != 0 { |
| 252 | t.Fatalf("expired cursor did not report a gap: %+v", out) |
| 253 | } |
| 254 | _, _, out, _ = read("cursor=not-a-cursor") |
| 255 | if !out.Gap { |
| 256 | t.Fatalf("invalid cursor did not report a gap: %+v", out) |
| 257 | } |
| 258 | |
| 259 | seedManyLogRecords(t, fx, now.Add(-2*time.Minute), appLogsPageCap+1) |
| 260 | _, _, out, _ = read("limit=999") |
| 261 | if len(out.Lines) != appLogsPageCap || !out.Truncated || out.Gap { |
| 262 | t.Fatalf("bounded page = %d lines, truncated=%v gap=%v", len(out.Lines), out.Truncated, out.Gap) |
| 263 | } |
| 264 | for _, query := range []string{"since=bad", "level=loud"} { |
| 265 | status, _, _, _ := read(query) |
| 266 | if status != http.StatusBadRequest { |
| 267 | t.Errorf("%s = %d, want 400", query, status) |
| 268 | } |
| 269 | } |
| 270 | fx.srv.cfg.Releases = nil |
| 271 | status, headers, _, _ = read("") |
| 272 | if status != http.StatusServiceUnavailable || headers.Get("Cache-Control") != "no-store" { |
| 273 | t.Fatalf("bucketless logs data = %d, Cache-Control %q", status, headers.Get("Cache-Control")) |
| 274 | } |
| 275 | } |
| 276 | |
| 277 | // TestAppLogsPage: the console tab renders the same timeline — filters as |
| 278 | // GET params, member-gated like every app page, honest empty state. |
| 279 | func TestAppLogsPage(t *testing.T) { |
| 280 | fx, _ := instanceFixture(t, "code-logs-page") |
| 281 | reg, err := registry.Open(fx.regPath) |
| 282 | if err != nil { |
| 283 | t.Fatal(err) |
| 284 | } |
| 285 | for _, rt := range []registry.Route{ |
| 286 | {Host: "legacy.example.com", Kind: "instance", App: "titogo", Account: "bab"}, |
| 287 | {Host: "foreign.example.com", Kind: "instance", App: "titogo", Account: "other"}, |
| 288 | } { |
| 289 | if err := reg.Upsert(rt); err != nil { |
| 290 | t.Fatal(err) |
| 291 | } |
| 292 | } |
| 293 | if err := reg.Close(); err != nil { |
| 294 | t.Fatal(err) |
| 295 | } |
| 296 | now := time.Now().UTC() |
| 297 | seedLogChunks(t, fx, now) |
| 298 | fx.setUser("paul@keymail.dev") |
| 299 | c := newBrowser(t) |
| 300 | signUp(t, fx, c, "code-logs-signin") |
| 301 | |
| 302 | status, _, body := get(t, c, fx.u("/apps/titogo/logs")) |
| 303 | if status != http.StatusOK { |
| 304 | t.Fatalf("logs page: %d %s", status, body) |
| 305 | } |
| 306 | for _, want := range []string{"listening on socket", "wake failed", "carlos logs --app titogo -f"} { |
| 307 | if !strings.Contains(body, want) { |
| 308 | t.Errorf("page missing %q", want) |
| 309 | } |
| 310 | } |
| 311 | for _, want := range []string{"All instances", "Search logs", "All levels", "Follow live", "Pause"} { |
| 312 | if !strings.Contains(body, want) { |
| 313 | t.Errorf("page missing approved copy %q", want) |
| 314 | } |
| 315 | } |
| 316 | if !strings.Contains(body, `option value="legacy.example.com"`) || strings.Contains(body, `option value="foreign.example.com"`) { |
| 317 | t.Fatalf("instance filter did not include only the account's legacy routes") |
| 318 | } |
| 319 | // Stream filter narrows. |
| 320 | status, _, body = get(t, c, fx.u("/apps/titogo/logs?stream=platform")) |
| 321 | if status != http.StatusOK || strings.Contains(body, "listening on socket") || !strings.Contains(body, "wake failed") { |
| 322 | t.Fatalf("stream filter page: %d", status) |
| 323 | } |
| 324 | // Instance, severity and text filters compose on the browser page too. |
| 325 | status, _, body = get(t, c, fx.u("/apps/titogo/logs?host=titogo.example.com&level=error&text=wake")) |
| 326 | if status != http.StatusOK || strings.Contains(body, "listening on socket") || !strings.Contains(body, "wake failed") { |
| 327 | t.Fatalf("composed browser filters: %d", status) |
| 328 | } |
| 329 | if !strings.Contains(body, `option value="titogo.example.com" selected`) { |
| 330 | t.Fatalf("browser host filter was not retained: %s", body) |
| 331 | } |
| 332 | status, _, body = get(t, c, fx.u("/apps/titogo/logs?host=deleted.example.com")) |
| 333 | if status != http.StatusOK || strings.Contains(body, "wake failed") { |
| 334 | t.Fatalf("historical browser host broadened: %d", status) |
| 335 | } |
| 336 | stamp := url.QueryEscape(now.Add(-30 * time.Minute).Format(time.RFC3339)) |
| 337 | status, _, body = get(t, c, fx.u("/apps/titogo/logs?since="+stamp+"&grep=wake&follow=1")) |
| 338 | if status != http.StatusOK || !strings.Contains(body, `selected>`+now.Add(-30*time.Minute).Format(time.RFC3339)+`</option>`) || |
| 339 | !strings.Contains(body, `type="hidden" name="grep" value="wake"`) || |
| 340 | !strings.Contains(body, `name="text" value=""`) || !strings.Contains(body, `setFollowing(true); poll();`) { |
| 341 | t.Fatalf("non-preset/legacy/follow state was not retained = %d: %s", status, body) |
| 342 | } |
| 343 | status, _, body = get(t, c, fx.u("/apps/titogo/logs?cursor=hand-written")) |
| 344 | if status != http.StatusOK || !strings.Contains(body, `<option value="1h" selected>hour</option>`) { |
| 345 | t.Fatalf("page cursor without since lost the bounded default window = %d: %s", status, body) |
| 346 | } |
| 347 | // Window with nothing in it: the honest empty state, still a 200. |
| 348 | status, _, body = get(t, c, fx.u("/apps/titogo/logs?since=1ns")) |
| 349 | if status != http.StatusOK || !strings.Contains(body, "No log lines in this window") { |
| 350 | t.Fatalf("empty window page: %d", status) |
| 351 | } |
| 352 | } |
| 353 | |
| 354 | // must unwraps a key builder's (key, error) for fixtures whose names are |
| 355 | // known good: mustKey(t)(ChunkKey(...)). |
| 356 | func mustKey(t testing.TB) func(string, error) string { |
| 357 | return func(k string, err error) string { |
| 358 | t.Helper() |
| 359 | if err != nil { |
| 360 | t.Fatal(err) |
| 361 | } |
| 362 | return k |
| 363 | } |
| 364 | } |
| 365 | |
amadan