From 44f571a8aaa9b5e52102dfff49f03618ece347a9 Mon Sep 17 00:00:00 2001 From: Yuneng Jiang Date: Fri, 24 Jul 2026 17:28:17 -0700 Subject: [PATCH] fix(logs): keep the End User filter window in step with the logs table Two issues Greptile raised on the filter window and the capped scan. A preset date range ends at "now", which the logs query re-reads on every fetch, so live tail keeps moving the table's end bound. The filter window was memoized on the date controls alone, so it pinned whichever "now" it was first built with: an end user that started sending traffic afterwards showed up in the table but stayed missing from the dropdown until something remounted it. formatLogsWindow now takes the preset end bound as an argument, and getLogsWindowEndBound derives it from the logs query's last fetch, rounded up to the next minute. Rounding up rather than down means the filter window never trails the table; bucketing means the query key holds steady between ticks instead of churning once per render. The panel reads it from logsQuery.dataUpdatedAt so it advances exactly when the table refreshes, falling back to the stored end time before the first fetch. Deriving it from Date.now() during render is what the purity rule forbids. The capped inner scan ordered by startTime alone, so rows sharing a timestamp could be cut differently between two requests and successive OFFSET pages would disagree about the set they were paging through. request_id now breaks the tie, which the (startTime, request_id) index already covers. Drift from rows genuinely arriving inside the window between page fetches is left alone. Removing it means keyset pagination over the distinct set, which cannot keep the inner row cap, and that cap is what stops this query from degrading into a full scan of LiteLLM_SpendLogs. --- .../customer_endpoints.py | 5 +- .../test_customer_endpoints.py | 11 ++++ .../components/view_logs/RequestLogsPanel.tsx | 15 ++++- .../view_logs/log_filter_logic.test.tsx | 61 +++++++++++++++++++ .../components/view_logs/log_filter_logic.tsx | 23 ++++++- 5 files changed, 109 insertions(+), 6 deletions(-) diff --git a/litellm/proxy/management_endpoints/customer_endpoints.py b/litellm/proxy/management_endpoints/customer_endpoints.py index 8c0e67e7d0a..cc6bacbd21e 100644 --- a/litellm/proxy/management_endpoints/customer_endpoints.py +++ b/litellm/proxy/management_endpoints/customer_endpoints.py @@ -914,6 +914,9 @@ async def list_customer_aliases( # The inner LIMIT is the safety bound: it walks the startTime index newest # first and stops, so DISTINCT never runs over an unbounded row set. + # request_id breaks startTime ties so the cut-off row is deterministic and + # successive OFFSET pages agree on the set they are paging through; the + # (startTime, request_id) index means the tiebreaker costs nothing. # size + 1: one row beyond the page reveals has_more without a COUNT(*). params = query_params + [MAX_SPENDLOG_ROWS_TO_SCAN_FOR_FILTERS, size + 1, (page - 1) * size] scan_idx = len(params) - 2 @@ -922,7 +925,7 @@ async def list_customer_aliases( f" SELECT end_user" f' FROM "LiteLLM_SpendLogs"' f" WHERE {' AND '.join(where_parts)}" - f' ORDER BY "startTime" DESC' + f' ORDER BY "startTime" DESC, request_id DESC' f" LIMIT ${scan_idx}" f") recent" f" ORDER BY end_user ASC" diff --git a/tests/test_litellm/proxy/management_endpoints/test_customer_endpoints.py b/tests/test_litellm/proxy/management_endpoints/test_customer_endpoints.py index 5954d07bbb8..db91984f63d 100644 --- a/tests/test_litellm/proxy/management_endpoints/test_customer_endpoints.py +++ b/tests/test_litellm/proxy/management_endpoints/test_customer_endpoints.py @@ -831,6 +831,17 @@ def test_customer_aliases_caps_the_rows_it_scans(mock_prisma_client, mock_user_a assert 'ORDER BY "startTime" DESC' in inner +def test_customer_aliases_breaks_start_time_ties_deterministically(mock_prisma_client, mock_user_api_key_auth): + """Without a unique tiebreaker the capped scan can cut differently per request, + so OFFSET page 2 would page through a different set than page 1 did.""" + query_raw = _mock_alias_rows(mock_prisma_client, []) + + client.get(f"/customer/aliases?{WINDOW}", headers={"Authorization": "Bearer k"}) + + sql = query_raw.call_args.args[0] + assert 'ORDER BY "startTime" DESC, request_id DESC' in sql + + def test_customer_aliases_requires_a_time_window(mock_prisma_client, mock_user_api_key_auth): """No window means no index bound, which is the unbounded scan we must not allow.""" _mock_alias_rows(mock_prisma_client, []) diff --git a/ui/litellm-dashboard/src/components/view_logs/RequestLogsPanel.tsx b/ui/litellm-dashboard/src/components/view_logs/RequestLogsPanel.tsx index cc5e6e899f5..b3b1e8c0640 100644 --- a/ui/litellm-dashboard/src/components/view_logs/RequestLogsPanel.tsx +++ b/ui/litellm-dashboard/src/components/view_logs/RequestLogsPanel.tsx @@ -12,7 +12,13 @@ import { keyInfoV1Call } from "../networking"; import KeyInfoView from "../templates/key_info_view"; import type { LogEntry } from "./columns"; import { AGENT_CALL_TYPES, MCP_CALL_TYPES } from "./constants"; -import { DEFAULT_LOGS_SORTING, formatLogsWindow, LOG_FILTER_IDS, useLogFilterLogic } from "./log_filter_logic"; +import { + DEFAULT_LOGS_SORTING, + formatLogsWindow, + getLogsWindowEndBound, + LOG_FILTER_IDS, + useLogFilterLogic, +} from "./log_filter_logic"; import { LogDetailsDrawer } from "./LogDetailsDrawer"; import { LiveTailBanner, LogsTableToolbar } from "./LogsTableToolbar"; import { RequestLogsTable } from "./RequestLogsTable"; @@ -76,9 +82,12 @@ export default function RequestLogsPanel({ accessToken, token, userRole, userID, sorting, }); + // Follow the table's own last fetch so a live-tail refresh carries the filter + // window with it; before the first fetch, fall back to the stored end time. + const windowEndBound = getLogsWindowEndBound(logsQuery.dataUpdatedAt || Date.parse(endTime)); const logsWindow = useMemo( - () => formatLogsWindow(startTime, endTime, isCustomDate), - [startTime, endTime, isCustomDate], + () => formatLogsWindow(startTime, endTime, isCustomDate, windowEndBound), + [startTime, endTime, isCustomDate, windowEndBound], ); const keyInfoQueryOptions: UseQueryOptions = { diff --git a/ui/litellm-dashboard/src/components/view_logs/log_filter_logic.test.tsx b/ui/litellm-dashboard/src/components/view_logs/log_filter_logic.test.tsx index 9f8f2fbe542..080bf6b380a 100644 --- a/ui/litellm-dashboard/src/components/view_logs/log_filter_logic.test.tsx +++ b/ui/litellm-dashboard/src/components/view_logs/log_filter_logic.test.tsx @@ -6,10 +6,13 @@ import React, { ReactNode } from "react"; import { beforeEach, describe, expect, it, vi } from "vitest"; import { DEFAULT_LOGS_SORTING, + formatLogsWindow, getFilterValue, getLiveTailRefetchInterval, + getLogsWindowEndBound, LIVE_TAIL_INTERVAL_MS, LOG_FILTER_IDS, + LOGS_WINDOW_TICK_MS, useLogFilterLogic, type PaginatedResponse, } from "./log_filter_logic"; @@ -233,3 +236,61 @@ describe("getLiveTailRefetchInterval", () => { expect(getLiveTailRefetchInterval(true, 1)).toBe(false); }); }); + +describe("formatLogsWindow", () => { + it("pins the end bound for a custom range", () => { + const w = formatLogsWindow("2026-07-23T00:00", "2026-07-24T06:00", true); + + expect(w.start_date).toBe(moment("2026-07-23T00:00").utc().format("YYYY-MM-DD HH:mm:ss")); + expect(w.end_date).toBe(moment("2026-07-24T06:00").utc().format("YYYY-MM-DD HH:mm:ss")); + }); + + it("ends a preset range at now, not at the stored end time", () => { + const w = formatLogsWindow("2026-07-23T00:00", "1999-01-01T00:00", false); + + expect(w.end_date > "2020-01-01 00:00:00").toBe(true); + }); +}); + +describe("getLogsWindowEndBound", () => { + const BUCKET_START = 16666 * LOGS_WINDOW_TICK_MS; + + it("holds steady inside a bucket so a memoized window does not refetch per render", () => { + expect(getLogsWindowEndBound(BUCKET_START)).toBe(getLogsWindowEndBound(BUCKET_START + LOGS_WINDOW_TICK_MS - 1)); + }); + + it("advances once the bucket rolls over so a preset window follows the table", () => { + expect(getLogsWindowEndBound(BUCKET_START + LOGS_WINDOW_TICK_MS)).toBe( + getLogsWindowEndBound(BUCKET_START) + LOGS_WINDOW_TICK_MS, + ); + }); + + it("never trails the fetch it was derived from", () => { + // Trailing is the live-tail bug: the table shows rows the filter window excludes. + for (const offset of [0, 1, LOGS_WINDOW_TICK_MS - 1]) { + expect(getLogsWindowEndBound(BUCKET_START + offset)).toBeGreaterThan(BUCKET_START + offset); + } + }); + + it("advances at least once per live-tail refetch interval", () => { + expect(LOGS_WINDOW_TICK_MS).toBeLessThanOrEqual(4 * LIVE_TAIL_INTERVAL_MS); + }); +}); + +describe("formatLogsWindow preset end bound", () => { + it("uses the supplied bound for a preset range so callers can memoize it", () => { + const bound = Date.UTC(2026, 6, 24, 12, 0, 0); + + expect(formatLogsWindow("2026-07-23T00:00", "1999-01-01T00:00", false, bound).end_date).toBe( + moment(bound).utc().format("YYYY-MM-DD HH:mm:ss"), + ); + }); + + it("ignores the supplied bound for a custom range", () => { + const bound = Date.UTC(2026, 6, 24, 12, 0, 0); + + expect(formatLogsWindow("2026-07-23T00:00", "2026-07-24T06:00", true, bound).end_date).toBe( + moment("2026-07-24T06:00").utc().format("YYYY-MM-DD HH:mm:ss"), + ); + }); +}); diff --git a/ui/litellm-dashboard/src/components/view_logs/log_filter_logic.tsx b/ui/litellm-dashboard/src/components/view_logs/log_filter_logic.tsx index 9b3e2334a35..8244066cadb 100644 --- a/ui/litellm-dashboard/src/components/view_logs/log_filter_logic.tsx +++ b/ui/litellm-dashboard/src/components/view_logs/log_filter_logic.tsx @@ -49,13 +49,32 @@ export interface LogsWindow { end_date: string; } -export const formatLogsWindow = (startTime: string, endTime: string, isCustomDate: boolean): LogsWindow => ({ +export const formatLogsWindow = ( + startTime: string, + endTime: string, + isCustomDate: boolean, + presetEndMs: number = Date.now(), +): LogsWindow => ({ start_date: moment(startTime).utc().format("YYYY-MM-DD HH:mm:ss"), end_date: isCustomDate ? moment(endTime).utc().format("YYYY-MM-DD HH:mm:ss") - : moment().utc().format("YYYY-MM-DD HH:mm:ss"), + : moment(presetEndMs).utc().format("YYYY-MM-DD HH:mm:ss"), }); +export const LOGS_WINDOW_TICK_MS = 60000; + +/** + * Stable end bound for anything that memoizes a preset (non-custom) window. + * + * The logs query re-reads "now" on every fetch, so a live-tail refresh keeps moving + * its end bound. A memoized window needs to follow, or it pins a bound the table has + * already passed and stops offering end users the table is showing. Rounding the + * last-fetch time UP to the next bucket keeps the value stable between ticks (so the + * query key does not churn per render) while never trailing behind the table. + */ +export const getLogsWindowEndBound = (lastFetchedAtMs: number): number => + (Math.floor(lastFetchedAtMs / LOGS_WINDOW_TICK_MS) + 1) * LOGS_WINDOW_TICK_MS; + export const LIVE_TAIL_INTERVAL_MS = 15000; export const getLiveTailRefetchInterval = (isLiveTail: boolean, pageIndex: number): number | false =>