Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
67 changes: 67 additions & 0 deletions SW.Bitween.Api/Services/DatabaseTimeoutMiddleware.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,67 @@
using System;
using System.Data.Common;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Http;
using Microsoft.Extensions.Logging;
using SW.Bitween.Services.Background;

namespace SW.Bitween.Services;

/// <summary>
/// A request whose database command ran past its time limit, answered as that: 504 with
/// <c>DATABASE_TIMED_OUT</c>, where it used to be a bare 500 like any other failure. The admin UI
/// doesn't ask again for it - asked again, it takes as long again - and says what happened rather
/// than showing an empty page.
/// </summary>
public class DatabaseTimeoutMiddleware(RequestDelegate next, ILogger<DatabaseTimeoutMiddleware> logger)
{
public const string Code = "DATABASE_TIMED_OUT";

public async Task InvokeAsync(HttpContext context)
{
try
{
await next(context);
}
catch (Exception ex) when (IsDatabaseTimeout(ex) && !context.Response.HasStarted)
{
logger.LogError(ex, "{Method} {Path} ran past the database's time limit.", context.Request.Method,
context.Request.Path);
// Not Response.Clear(): that also drops the security and CORS headers set before the
// endpoint ran. Nothing has been written, so only a length set for another body is wrong.
context.Response.Headers.ContentLength = null;
context.Response.StatusCode = StatusCodes.Status504GatewayTimeout;
context.Response.ContentType = "application/json";
await context.Response.Body.WriteAsync(BackgroundRequests.Problem(Code,
"The database took too long to answer. Asking for less, such as a shorter time range, may help."));
}
}

/// <summary>
/// A command that ran out of time: past the connection's Command Timeout, which Npgsql throws as
/// its own exception around a <see cref="TimeoutException"/>, or past a <c>statement_timeout</c>
/// set on the database, which Postgres reports as 57014. A timeout only inside a database
/// exception, so a call elsewhere that timed out isn't put down to the database, and not a
/// cancellation the caller asked for, which Postgres also reports as 57014. SQL Server and MySQL
/// say it differently, and keep the 500.
/// </summary>
internal static bool IsDatabaseTimeout(Exception ex)
{
var inDatabase = false;
for (var e = ex; e != null; e = e.InnerException)
switch (e)
{
case OperationCanceledException:
return false;
case DbException { SqlState: "57014" }:
return true;
case DbException:
inDatabase = true;
break;
case TimeoutException when inDatabase:
return true;
}

return false;
}
}
4 changes: 3 additions & 1 deletion SW.Bitween.HttpTests/BackgroundRequestTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -62,7 +62,9 @@ public async Task A_read_that_does_not_ask_keeps_the_usual_limit()

var response = await admin.SendAsync(Read("/api/slowreads/3"));

Assert.Equal(HttpStatusCode.InternalServerError, response.StatusCode);
// Answered as the timeout it is, which the admin UI doesn't ask again for.
Assert.Equal(HttpStatusCode.GatewayTimeout, response.StatusCode);
Assert.Contains("DATABASE_TIMED_OUT", await response.Content.ReadAsStringAsync());
}

[Fact]
Expand Down
71 changes: 71 additions & 0 deletions SW.Bitween.IntegrationTests/Tests/DatabaseTimeoutTests.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,71 @@
using System;
using System.IO;
using System.Threading;
using System.Threading.Tasks;
using Microsoft.AspNetCore.Http;
using Microsoft.EntityFrameworkCore;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging.Abstractions;
using SW.Bitween.IntegrationTests.Fixtures;
using SW.Bitween.Services;
using Xunit;

namespace SW.Bitween.IntegrationTests.Tests;

/// <summary>
/// A request whose query runs past the database's time limit answers 504 with
/// <c>DATABASE_TIMED_OUT</c>: the admin UI doesn't ask again for it, and says what happened.
/// </summary>
[Collection("Bitween")]
public class DatabaseTimeoutTests(BitweenFixture fixture)
{
[Fact]
public async Task A_query_past_the_database_time_limit_is_answered_as_a_timeout()
{
// What real timeouts throw, rather than exceptions made up to look like them: past the
// connection's Command Timeout, past the database's own statement_timeout, and cancelled by
// the caller, which is not one.
Exception commandTimedOut, statementTimedOut, cancelled;
await using (var scope = fixture.CreateScope())
{
var db = scope.ServiceProvider.GetRequiredService<BitweenDbContext>();
db.Database.SetCommandTimeout(1);
commandTimedOut = await Record.ExceptionAsync(() => db.Database.ExecuteSqlRawAsync("SELECT pg_sleep(5)"));
}

await using (var scope = fixture.CreateScope())
{
var db = scope.ServiceProvider.GetRequiredService<BitweenDbContext>();
await using var transaction = await db.Database.BeginTransactionAsync();
await db.Database.ExecuteSqlRawAsync("SET LOCAL statement_timeout = 500");
statementTimedOut = await Record.ExceptionAsync(() => db.Database.ExecuteSqlRawAsync("SELECT pg_sleep(5)"));
}

await using (var scope = fixture.CreateScope())
{
var db = scope.ServiceProvider.GetRequiredService<BitweenDbContext>();
using var cancel = new CancellationTokenSource(TimeSpan.FromMilliseconds(500));
cancelled = await Record.ExceptionAsync(() => db.Database.ExecuteSqlRawAsync("SELECT pg_sleep(5)", cancel.Token));
}

Assert.True(DatabaseTimeoutMiddleware.IsDatabaseTimeout(statementTimedOut), statementTimedOut?.ToString());
Assert.False(DatabaseTimeoutMiddleware.IsDatabaseTimeout(cancelled), cancelled?.ToString());

var context = new DefaultHttpContext { Response = { Body = new MemoryStream() } };
context.Response.Headers["X-Content-Type-Options"] = "nosniff";
await Answer(context, commandTimedOut);

Assert.Equal(StatusCodes.Status504GatewayTimeout, context.Response.StatusCode);
Assert.Equal("nosniff", context.Response.Headers["X-Content-Type-Options"]);
context.Response.Body.Position = 0;
Assert.Contains(DatabaseTimeoutMiddleware.Code, await new StreamReader(context.Response.Body).ReadToEndAsync());

// Anything else fails as it did, a timeout outside the database included.
await Assert.ThrowsAsync<InvalidOperationException>(() => Answer(new DefaultHttpContext(), new InvalidOperationException()));
await Assert.ThrowsAsync<TimeoutException>(() => Answer(new DefaultHttpContext(), new TimeoutException()));
}

private static Task Answer(HttpContext context, Exception thrown) =>
new DatabaseTimeoutMiddleware(_ => throw thrown, NullLogger<DatabaseTimeoutMiddleware>.Instance)
.InvokeAsync(context);
}
Original file line number Diff line number Diff line change
Expand Up @@ -24,9 +24,11 @@ describe("errors from the API", () => {
expect(refusal.errors).toEqual({ Name: ["A name is needed."], Port: ["The port must be a number."] });
});

it("doesn't ask again for a refusal, but does for a server error or a dropped connection", () => {
it("doesn't ask again for a refusal or a timeout, but does for a server error or a dropped connection", () => {
expect(shouldRetryQuery(0, new ApiRequestError("NOT_FOUND", "gone", 404))).toBe(false);
expect(shouldRetryQuery(0, new ApiRequestError("HTTP_403", "no", 403))).toBe(false);
expect(shouldRetryQuery(0, new ApiRequestError("DATABASE_TIMED_OUT", "too long", 504))).toBe(false);
expect(shouldRetryQuery(0, new ApiRequestError("ERROR", "gateway timeout", 504))).toBe(false);
expect(shouldRetryQuery(0, new ApiRequestError("ERROR", "boom", 500))).toBe(true);
expect(shouldRetryQuery(0, new TypeError("Failed to fetch"))).toBe(true);
expect(shouldRetryQuery(3, new ApiRequestError("ERROR", "boom", 500))).toBe(false);
Expand Down
8 changes: 5 additions & 3 deletions SW.Bitween.Web/ClientApp/src/api/types.ts
Original file line number Diff line number Diff line change
Expand Up @@ -155,11 +155,13 @@ export const isPermanentError = (error: unknown): boolean =>

/**
* Whether a failed query is asked again. A refusal answers the same however often it is asked:
* retrying it only held "Loading…" on screen for the ~7s of backoff before the error showed.
* Server errors and dropped connections are retried, up to three times.
* retrying it only held "Loading…" on screen for the ~7s of backoff before the error showed. A
* timeout (504) takes as long again each time: three more of the database's 30 seconds held a list
* on "Loading…" for two minutes. Other server errors and dropped connections are retried, up to
* three times.
*/
export const shouldRetryQuery = (failureCount: number, error: unknown): boolean =>
!isPermanentError(error) && failureCount < 3;
!isPermanentError(error) && !(error instanceof ApiRequestError && error.status === 504) && failureCount < 3;

// --- Configuration entities (sub-phase 2) ---

Expand Down
27 changes: 22 additions & 5 deletions SW.Bitween.Web/ClientApp/src/pages/exchanges/ExchangesPage.tsx
Original file line number Diff line number Diff line change
Expand Up @@ -5,14 +5,15 @@ import { ArrowUp, Download, Pause, Play, Plus, RefreshCw, RotateCcw, TriangleAle
import {
api,
type BulkRetrySelection,
type ExchangeBreakdown,
type ExchangeStatus,
type ExportFilesCheck,
} from "../../api";
import { Can } from "../../auth/guards";
import { PageHeader } from "../../components/layout/PageHeader";
import { useBackgroundProgress } from "../../lib/useBackground";
import { followDownload } from "../../lib/saveFile";
import { Button, EmptyState, LoadingBlock } from "../../components/ui/basics";
import { Button, EmptyState, LoadError, LoadingBlock } from "../../components/ui/basics";
import { ConfirmDialog } from "../../components/ui/overlays";
import { openDialogs } from "../../components/ui/dialogStack";
import { useSubscriptionsCache } from "../../components/config/lookups";
Expand All @@ -34,6 +35,7 @@ import {
filterSignature,
hasTimeFilter,
idsIn,
keepCounted,
readQuery,
timeLabel,
toLocalInput,
Expand Down Expand Up @@ -109,10 +111,12 @@ export function ExchangesPage() {
// keeps showing the last hour rather than the hour before the page was opened.
// The rows alone, so they show as soon as they're found: how many match comes with the status
// counts below, which can take far longer to work out on a busy instance.
const { data, isLoading, isFetching, isPlaceholderData, dataUpdatedAt, refetch } = useQuery({
const { data, isLoading, isFetching, isPlaceholderData, isError, error, dataUpdatedAt, refetch } = useQuery({
queryKey: keys.exchanges.search(viewSearch(searchParams) + `&offset=${query.offset}`),
queryFn: () => api.searchExchanges(readQuery(searchParams), { count: false }),
refetchInterval: refreshMs || false,
// A list that failed with nothing to show waits for Try again: asked every 15s, a timeout kept
// the database busy with the same query for as long as the page stayed open.
refetchInterval: (q) => (q.state.status === "error" && q.state.data === undefined ? false : refreshMs || false),
placeholderData: keepPreviousData,
});
// Loads someone is waiting on: a changed filter or page (the old rows stay up meanwhile), or the
Expand All @@ -131,11 +135,15 @@ export function ExchangesPage() {
const breakdownKey = viewSearch(withParams(searchParams, { status: null }));
const askAgain = (q: { state: { data?: { counting: boolean } } }) =>
refreshMs || (q.state.data?.counting ? COUNTING_MS : false);
// A number, once in, stays while a later answer is still counting it: see keepCounted.
const keepNumbers = (previous: unknown, next: unknown) =>
keepCounted(previous as ExchangeBreakdown | undefined, next as ExchangeBreakdown);
const breakdown = useQuery({
queryKey: keys.exchanges.breakdown(breakdownKey),
queryFn: () => api.getExchangeBreakdown(readQuery(searchParams)),
refetchInterval: askAgain,
placeholderData: keepPreviousData,
structuralSharing: keepNumbers,
retry: false,
});
const chartParams = timed ? null : withParams(searchParams, { range: "24h", status: null });
Expand All @@ -145,6 +153,7 @@ export function ExchangesPage() {
enabled: !!chartParams,
refetchInterval: askAgain,
placeholderData: keepPreviousData,
structuralSharing: keepNumbers,
retry: false,
});
const volume = timed ? breakdown.data : chartBreakdown.data;
Expand Down Expand Up @@ -489,6 +498,9 @@ export function ExchangesPage() {
<div className="flex min-w-0 flex-1 flex-col gap-3">
{isLoading ? (
<LoadingBlock />
) : isError && !data ? (
/* Without it, a list that couldn't be read said "No exchanges match", as if there were none. */
<LoadError error={error} what="the exchanges" onRetry={() => void refetch()} />
) : rows.length === 0 ? (
/* An empty page and an empty search are different problems. This branch replaces the
table, paging footer and all, so a page past the end of the list would otherwise
Expand Down Expand Up @@ -589,8 +601,13 @@ export function ExchangesPage() {
size="sm"
/* Past the cap the total no longer says where the end is, so fall back to "was this
page full" - otherwise Next would dead-end at row 10,000 - as while it is still
being counted. Below the cap the total is exact, so Next stops on the true last page. */
disabled={total === undefined || totalIsCapped ? rows.length < PAGE_SIZE : query.offset + PAGE_SIZE >= total}
being counted, when the number on screen may be one kept from an earlier answer.
Otherwise the total is exact, so Next stops on the true last page. */
disabled={
total === undefined || totalIsCapped || breakdown.data?.counting
? rows.length < PAGE_SIZE
: query.offset + PAGE_SIZE >= total
}
onClick={() => apply({ offset: String(query.offset + PAGE_SIZE) }, { resetOffset: false })}
>
Next
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -412,6 +412,79 @@ describe("the exchanges list", () => {
}
});

/**
* The server runs as more than one copy, each counting a slow view for itself: after a copy that
* has finished, one still counting can answer.
*/
it("keeps a number once it's in, while a later answer is still counting it", async () => {
vi.useFakeTimers({ shouldAdvanceTime: true });
try {
let asked = 0;
renderApp("/exchanges", {
handlers: [
http.get(apiPath("/xchanges/summary"), () =>
HttpResponse.json(
++asked === 1
? { counts: { processing: 7, success: 0, badResponse: 0, failed: 3 }, buckets: [], bucketMinutes: 0, counting: false }
: { counts: { processing: null, success: 0, badResponse: 0, failed: 4 }, buckets: [], bucketMinutes: 0, counting: true },
),
),
exchanges({ total: 3 }).handler,
...filterOptions,
],
});
const tabs = within(await screen.findByRole("group", { name: "Status" }));
expect(await tabs.findByRole("button", { name: "Processing 7" })).toBeVisible();

// Live refresh asks again; the copy that answers has Failed but is still counting Processing.
await act(() => vi.advanceTimersByTimeAsync(15_000));
expect(await tabs.findByRole("button", { name: "Failed 4" })).toBeVisible();
expect(tabs.getByRole("button", { name: "Processing 7" })).toBeVisible();
} finally {
vi.useRealTimers();
}
});

it("says when the list couldn't be read, rather than that nothing matches, and reads it again on Try again", async () => {
vi.useFakeTimers({ shouldAdvanceTime: true });
try {
let timedOut = true;
let listAsks = 0;
const list = exchanges({ total: 3 });
renderApp("/exchanges?status=failed&latest=1", {
handlers: [
http.get(/\/api\/xchanges(\?|$)/, () => {
listAsks++;
return timedOut
? HttpResponse.json(
{ DATABASE_TIMED_OUT: ["The database took too long to answer. Asking for less, such as a shorter time range, may help."] },
{ status: 504 },
)
: undefined;
}),
list.handler,
...filterOptions,
],
});

const alert = await screen.findByRole("alert");
expect(within(alert).getByText("Couldn't load the exchanges")).toBeVisible();
expect(within(alert).getByText(/The database took too long to answer/)).toBeVisible();
expect(screen.queryByText("No exchanges match")).not.toBeInTheDocument();

// Live refresh doesn't run the same query again meanwhile: it waits for Try again.
const asked = listAsks;
await act(() => vi.advanceTimersByTimeAsync(15_000));
expect(listAsks).toBe(asked);

timedOut = false;
fireEvent.click(within(alert).getByRole("button", { name: "Try again" }));
expect(await screen.findByText("Showing 1-3 of 3")).toBeVisible();
} finally {
vi.useRealTimers();
}
});

it("can show only the newest attempt of each chain", async () => {
const latest = (q: URLSearchParams) => q.getAll("filter").includes("LatestOnly:1:true");
const list = exchanges({ total: (q) => (latest(q) ? 30 : 40) });
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,6 +3,7 @@ import {
filterChips,
filterSignature,
idsIn,
keepCounted,
notWith,
parseBound,
propertyFilters,
Expand Down Expand Up @@ -253,3 +254,33 @@ describe("the search box", () => {
expect(first.changes).toEqual({ prop: ["city:paris", "orderNo:SO-1"], propertyKey: null, property: null, not: null });
});
});

/** A later answer that is still counting, from an app copy that hasn't caught up yet. */
describe("keeping what was counted", () => {
const bucket = { start: "2026-11-03T10:00:00Z", processing: 0, success: 5, badResponse: 0, failed: 1 };
const counted = {
counts: { processing: 7, success: 100, badResponse: 0, failed: 3 },
buckets: [bucket],
bucketMinutes: 60,
counting: false,
};

it("keeps a number, and the chart, that the later answer is still counting", () => {
const later = keepCounted(counted, {
counts: { processing: null, success: 101, badResponse: 0, failed: 4 },
buckets: [],
bucketMinutes: 0,
counting: true,
});
expect(later.counts).toEqual({ processing: 7, success: 101, badResponse: 0, failed: 4 });
expect(later.buckets).toEqual([bucket]);
expect(later.bucketMinutes).toBe(60);
// Still asked again until the rest is in.
expect(later.counting).toBe(true);
});

it("takes the later answer whole once it has counted it all, an empty chart included", () => {
const later = { counts: { processing: 0, success: 101, badResponse: 0, failed: 4 }, buckets: [], bucketMinutes: 0, counting: false };
expect(keepCounted(counted, later)).toEqual(later);
});
});
Loading
Loading