Skip to content

Commit 4a6fda2

Browse files
fuziontechclaude
andauthored
fix(session): raise session-init timeout to 60s and drop the duplicate catalog probe (#1192)
Two fixes for client-facing session-creation failures on tenants with large DuckLake catalogs, found while root-causing a mw-prod-us incident on portola. 1. DefaultSessionInitTimeout 10s -> 60s. Session init runs its probes with DuckLake as the session default, so each statement starts a DuckLake transaction. When the catalog's schema version moved since the DuckDB instance last loaded it, that transaction pays a full catalog reload first. Measured on mw-prod-us (~5,900 live tables, ~1.0M live columns) the reload takes 12-22s, so the 10s budget expired mid-reload. The failure is fatal and client-facing: the worker returns "detect ducklake attachment: INTERRUPT Error", flight_handler maps it to ResourceExhausted, and the CP refuses the connection with 58000 without retrying this error class. It hit ~3% of worker spawns for that tenant. 60s rather than 30s because one reload is not the worst case: these tenants churn DDL continuously, so a second schema-version bump inside one init window is plausible. Nothing upstream clips it - the CP derives the init context from the cancel-only connection context, the worker queue timeout is minutes, and workerSpawnActivateTimeout governs the spawn/activate phase. 2. Stop probing for the DuckLake catalog twice per session create. Every session-init caller ran HasAttachedCatalog and then called InitSessionDatabaseMetadata*, which ran it again internally - two duckdb_databases() queries per session create, each starting a DuckLake transaction on the path above. InitSessionDatabaseMetadataWithAttached takes the caller's answer; the probe-or-reuse branch lives in an unexported helper so the probe keeps its original position in the statement order. Tests: sessionmeta gains coverage asserting zero probe queries and the exact deferred statements (USE ducklake / SET search_path) for attached and unattached, plus the probing entry point still issuing exactly one probe. The e2e-skip rationale is recorded in harness.sh above logical_catalog_alias, which already drives this path. Docs and help text follow the 60s default. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
1 parent 86a4226 commit 4a6fda2

11 files changed

Lines changed: 170 additions & 17 deletions

File tree

‎README.md‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -357,7 +357,7 @@ Create a `duckgres.yaml` file (see `duckgres.example.yaml` for a complete exampl
357357
host: "0.0.0.0"
358358
port: 5432
359359
data_dir: "./data"
360-
session_init_timeout: "10s"
360+
session_init_timeout: "60s"
361361
admission_reclaimer_max_reservations: 4096
362362

363363
tls:
@@ -424,7 +424,7 @@ Run with config file:
424424
| `DUCKGRES_PROCESS_RETIRE_ON_SESSION_END` | Retire a process worker immediately after its last session ends instead of keeping it warm for reuse | `false` |
425425
| `DUCKGRES_IDLE_TIMEOUT` | Connection idle timeout (e.g., `30m`, `1h`, `-1` to disable) | `24h` standalone, `5m` control-plane |
426426
| `DUCKGRES_CLIENT_IDLE_TIMEOUT_MAX` | Maximum client-requested `duckgres.idle_timeout`; unset disables client overrides | disabled |
427-
| `DUCKGRES_SESSION_INIT_TIMEOUT` | Session startup metadata initialization and catalog probe timeout | `10s` |
427+
| `DUCKGRES_SESSION_INIT_TIMEOUT` | Session startup metadata initialization and catalog probe timeout | `60s` |
428428
| `DUCKGRES_WORKER_QUEUE_TIMEOUT` | Max time to wait for worker acquisition and per-org/per-user vCPU resource admission; the managed K8s queue TTL uses this value | `60s` |
429429
| `DUCKGRES_ADMISSION_RECLAIMER_MAX_RESERVATIONS` | Max queued/live admission identities whose cleanup ownership one control plane may retain; new admissions are rejected before enqueue when full | `4096` |
430430
| `DUCKGRES_HANDOVER_DRAIN_TIMEOUT` | Max time to drain planned shutdowns and upgrades before forcing exit | `24h` in process mode, `15m` in remote K8s mode |

‎controlplane/control.go‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -2070,7 +2070,9 @@ func (cp *ControlPlane) initSessionMetadata(
20702070
// the connection selected one — so current_database() and the
20712071
// information_schema views agree with the name the client connected
20722072
// with. Everything that executes below still uses effectiveCatalog.
2073-
if err := sessionmeta.InitSessionDatabaseMetadataWithAccess(initCtx, exec, res.visibleCatalog, metadataAccess); err != nil {
2073+
// duckLakeAttached comes from the probe above; passing it keeps
2074+
// sessionmeta from repeating that `duckdb_databases()` query.
2075+
if err := sessionmeta.InitSessionDatabaseMetadataWithAttached(initCtx, exec, res.visibleCatalog, metadataAccess, duckLakeAttached); err != nil {
20742076
initContextErr := initCtx.Err()
20752077
initCancel()
20762078
outcome, reason := controlPlaneSessionStartOperationResult(

‎duckdbservice/service.go‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1845,7 +1845,9 @@ func initAttachedDuckLakeSessionMetadata(conn *sql.Conn, db *sql.DB, cfg server.
18451845
if !duckLakeAttached {
18461846
return nil
18471847
}
1848-
if err := sessionmeta.InitSessionDatabaseMetadata(initCtx, executor, "ducklake"); err != nil {
1848+
// Reuse the probe above instead of letting sessionmeta run a second
1849+
// `duckdb_databases()` query against the DuckLake catalog.
1850+
if err := sessionmeta.InitSessionDatabaseMetadataWithAttached(initCtx, executor, "ducklake", nil, duckLakeAttached); err != nil {
18491851
return fmt.Errorf("initialize ducklake session metadata: %w", err)
18501852
}
18511853
return nil

‎k8s/README.md‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -63,7 +63,7 @@ Key flags for Kubernetes multitenant mode:
6363
|------|---------|-------------|
6464
| `--worker-backend remote` | - | Use K8s remote workers in config-store-backed multitenant mode |
6565
| `--config-store` | `DUCKGRES_CONFIG_STORE` | PostgreSQL config-store connection string required for remote mode |
66-
| `--session-init-timeout` | `DUCKGRES_SESSION_INIT_TIMEOUT` | Session startup metadata initialization and catalog probe timeout (`10s` default) |
66+
| `--session-init-timeout` | `DUCKGRES_SESSION_INIT_TIMEOUT` | Session startup metadata initialization and catalog probe timeout (`60s` default) |
6767
| `--handover-drain-timeout` | `DUCKGRES_HANDOVER_DRAIN_TIMEOUT` | Max time to drain planned shutdowns/upgrades before forced exit (`15m` default in remote mode) |
6868
| `--sni-routing-mode` | `DUCKGRES_SNI_ROUTING_MODE` | Managed-hostname routing: `off`, `passthrough`, or `enforce`. Postgres uses requested dbname first; managed SNI must resolve to the same org, and SNI supplies the database only when dbname is empty |
6969
| `--managed-hostname-suffixes` | `DUCKGRES_MANAGED_HOSTNAME_SUFFIXES` | Comma-separated managed hostname suffixes such as `.dw.test.local` |

‎main.go‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -129,7 +129,7 @@ func main() {
129129
fmt.Fprintf(os.Stderr, " DUCKGRES_PROCESS_ISOLATION Enable process isolation (1 or true)\n")
130130
fmt.Fprintf(os.Stderr, " DUCKGRES_IDLE_TIMEOUT Connection idle timeout (e.g., 30m, 1h, -1 to disable)\n")
131131
fmt.Fprintf(os.Stderr, " DUCKGRES_CLIENT_IDLE_TIMEOUT_MAX Maximum client-requested idle timeout; unset disables client overrides\n")
132-
fmt.Fprintf(os.Stderr, " DUCKGRES_SESSION_INIT_TIMEOUT Session startup metadata/probe timeout (default: 10s)\n")
132+
fmt.Fprintf(os.Stderr, " DUCKGRES_SESSION_INIT_TIMEOUT Session startup metadata/probe timeout (default: 60s)\n")
133133
fmt.Fprintf(os.Stderr, " DUCKGRES_MEMORY_LIMIT DuckDB memory_limit per session (e.g., 4GB)\n")
134134
fmt.Fprintf(os.Stderr, " DUCKGRES_THREADS DuckDB threads per session\n")
135135
fmt.Fprintf(os.Stderr, " DUCKGRES_MEMORY_BUDGET Total memory for all DuckDB sessions (e.g., 24GB)\n")
@@ -149,7 +149,7 @@ func main() {
149149
fmt.Fprintf(os.Stderr, " DUCKGRES_DUCKDB_TOKEN DuckDB service bearer token (duckdb-service mode)\n")
150150
fmt.Fprintf(os.Stderr, " DUCKGRES_DUCKDB_MAX_SESSIONS DuckDB service max sessions (duckdb-service mode)\n")
151151
fmt.Fprintf(os.Stderr, " DUCKGRES_CONFIG_STORE PostgreSQL connection string for config store (multi-tenant)\n")
152-
fmt.Fprintf(os.Stderr, " DUCKGRES_CONFIG_POLL_INTERVAL Config store poll interval (default: 30s)\n")
152+
fmt.Fprintf(os.Stderr, " DUCKGRES_CONFIG_POLL_INTERVAL Config store poll interval (default: 60s)\n")
153153
fmt.Fprintf(os.Stderr, " DUCKGRES_INTERNAL_SECRET Shared secret for API authentication\n")
154154
fmt.Fprintf(os.Stderr, " DUCKGRES_INTERNAL_SECRET_FALLBACKS Comma-separated previous internal secrets still accepted during rotation\n")
155155
fmt.Fprintf(os.Stderr, " DUCKGRES_AWS_REGION AWS region for STS client\n")

‎main_test.go‎

Lines changed: 4 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -594,11 +594,11 @@ func TestResolveEffectiveConfigInvalidWorkerEnvVars(t *testing.T) {
594594

595595
func TestResolveEffectiveConfigSessionInitTimeout(t *testing.T) {
596596
resolved := configresolve.ResolveEffective(nil, configresolve.CLIInputs{}, nil, nil)
597-
if resolved.SessionInitTimeout != 10*time.Second {
598-
t.Fatalf("expected default session init timeout 10s, got %s", resolved.SessionInitTimeout)
597+
if resolved.SessionInitTimeout != 60*time.Second {
598+
t.Fatalf("expected default session init timeout 60s, got %s", resolved.SessionInitTimeout)
599599
}
600-
if resolved.Server.SessionInitTimeout != 10*time.Second {
601-
t.Fatalf("expected server default session init timeout 10s, got %s", resolved.Server.SessionInitTimeout)
600+
if resolved.Server.SessionInitTimeout != 60*time.Second {
601+
t.Fatalf("expected server default session init timeout 60s, got %s", resolved.Server.SessionInitTimeout)
602602
}
603603
}
604604

‎server/conn.go‎

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1052,7 +1052,9 @@ func (c *clientConn) serve() error {
10521052
if duckLakeAttached {
10531053
catalog = physicalDuckLakeCatalog
10541054
}
1055-
if err := sessionmeta.InitSessionDatabaseMetadata(initCtx, c.executor, catalog); err != nil {
1055+
// duckLakeAttached comes from the probe above; passing it keeps
1056+
// sessionmeta from repeating that `duckdb_databases()` query.
1057+
if err := sessionmeta.InitSessionDatabaseMetadataWithAttached(initCtx, c.executor, catalog, nil, duckLakeAttached); err != nil {
10561058
initCancel()
10571059
c.sendError("FATAL", "XX000", fmt.Sprintf("failed to initialize session database metadata: %v", err))
10581060
return err

‎server/server.go‎

Lines changed: 27 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -43,7 +43,33 @@ type DuckLakeConfig = ducklake.Config
4343
const DefaultDuckLakeSpecVersion = ducklake.DefaultSpecVersion
4444

4545
// DefaultSessionInitTimeout bounds startup metadata initialization and catalog probes.
46-
const DefaultSessionInitTimeout = 10 * time.Second
46+
//
47+
// 10s → 60s (2026-09-16): session init runs its probes with the DuckLake
48+
// catalog as the session default, so each statement starts a DuckLake
49+
// transaction. When the catalog's schema version changed since the DuckDB
50+
// instance last loaded it, that transaction pays a full catalog reload before
51+
// the probe returns. On a large tenant catalog (measured on mw-prod-us: ~5,900
52+
// live tables, ~1.0M live columns) the reload takes 12-22s, so a 10s budget
53+
// expired mid-reload. The failure is client-facing and fatal: the worker
54+
// returns "detect ducklake attachment: INTERRUPT Error", flight_handler maps
55+
// it to ResourceExhausted, and the control plane refuses the connection with
56+
// 58000 rather than retrying. It hit ~3% of worker spawns for that tenant.
57+
//
58+
// 60s rather than 30s because one reload is not the worst case: the tenants
59+
// that hit this churn DDL (sqlmesh creates and drops tables continuously), so
60+
// a second schema-version bump inside a single init window is plausible, and
61+
// 30s covers one 12-22s reload but not two.
62+
//
63+
// This bounds a pathological metadata store, not the steady state: a warm
64+
// instance completes session init in milliseconds, so raising the ceiling
65+
// costs nothing on a healthy path. The only price is a slower time-to-FATAL
66+
// for the one client already waiting on that worker. Override per deployment
67+
// with DUCKGRES_SESSION_INIT_TIMEOUT / --session-init-timeout.
68+
//
69+
// Nothing upstream clips this: the control plane derives the init context from
70+
// the cancel-only connection context, the worker queue timeout is minutes, and
71+
// workerSpawnActivateTimeout governs the spawn/activate phase instead.
72+
const DefaultSessionInitTimeout = 60 * time.Second
4773

4874
// Re-exports of the migration / backup / delta-path entry points so callers
4975
// that referenced them under the server package continue to compile after

‎server/sessionmeta/sessionmeta.go‎

Lines changed: 33 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -37,8 +37,31 @@ func InitSessionDatabaseMetadata(ctx context.Context, executor sqlcore.QueryExec
3737
}
3838

3939
// InitSessionDatabaseMetadataWithAccess installs metadata views filtered to
40-
// the relations the current principal can query.
40+
// the relations the current principal can query. It probes for the DuckLake
41+
// catalog itself; callers that already hold that answer should pass it to
42+
// InitSessionDatabaseMetadataWithAttached instead.
4143
func InitSessionDatabaseMetadataWithAccess(ctx context.Context, executor sqlcore.QueryExecutor, catalog string, access *MetadataAccessPolicy) error {
44+
return initSessionDatabaseMetadata(ctx, executor, catalog, access, nil)
45+
}
46+
47+
// InitSessionDatabaseMetadataWithAttached is InitSessionDatabaseMetadataWithAccess
48+
// with the DuckLake attachment state supplied by the caller.
49+
//
50+
// Every session-init caller already runs HasAttachedCatalog before this
51+
// function, which then ran it a second time — two `duckdb_databases()` queries
52+
// per session create. With DuckLake as the session default each of those
53+
// starts a DuckLake transaction, and a transaction on a catalog whose schema
54+
// version moved pays a full reload. Passing the known value drops the second
55+
// probe.
56+
func InitSessionDatabaseMetadataWithAttached(ctx context.Context, executor sqlcore.QueryExecutor, catalog string, access *MetadataAccessPolicy, duckLakeAttached bool) error {
57+
return initSessionDatabaseMetadata(ctx, executor, catalog, access, &duckLakeAttached)
58+
}
59+
60+
// initSessionDatabaseMetadata does the work for both exported entry points. A
61+
// nil `attached` probes; a non-nil one reuses the caller's answer. The pointer
62+
// stays unexported so no caller has to reason about a nil-able bool, and the
63+
// probe keeps its original position in the statement order.
64+
func initSessionDatabaseMetadata(ctx context.Context, executor sqlcore.QueryExecutor, catalog string, access *MetadataAccessPolicy, attached *bool) error {
4265
if executor == nil {
4366
return fmt.Errorf("session executor is required")
4467
}
@@ -55,9 +78,15 @@ func InitSessionDatabaseMetadataWithAccess(ctx context.Context, executor sqlcore
5578
return fmt.Errorf("create current_database() macro: %w", err)
5679
}
5780

58-
duckLakeAttached, err := HasAttachedCatalog(ctx, executor, "ducklake")
59-
if err != nil {
60-
return fmt.Errorf("detect ducklake attachment: %w", err)
81+
var duckLakeAttached bool
82+
if attached != nil {
83+
duckLakeAttached = *attached
84+
} else {
85+
probed, err := HasAttachedCatalog(ctx, executor, "ducklake")
86+
if err != nil {
87+
return fmt.Errorf("detect ducklake attachment: %w", err)
88+
}
89+
duckLakeAttached = probed
6190
}
6291

6392
if _, err := executor.ExecContext(ctx, "USE memory"); err != nil {

‎server/sessionmeta/sessionmeta_test.go‎

Lines changed: 81 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -12,10 +12,12 @@ import (
1212
type countingExecutor struct {
1313
execCalls int
1414
execQueries []string
15+
queryCalls int
1516
queryRows sqlcore.RowSet
1617
}
1718

1819
func (e *countingExecutor) QueryContext(_ context.Context, _ string, _ ...any) (sqlcore.RowSet, error) {
20+
e.queryCalls++
1921
if e.queryRows == nil {
2022
return nil, errors.New("no query rows configured")
2123
}
@@ -122,3 +124,82 @@ func TestBuildSessionMetadataSQLContainsAllExpectedStatements(t *testing.T) {
122124
t.Errorf("buildSessionMetadataSQL did not interpolate database literal")
123125
}
124126
}
127+
128+
// TestInitSessionDatabaseMetadataWithAttachedSkipsProbe pins the duplicate-probe
129+
// fix. Every session-init caller runs HasAttachedCatalog before calling in here,
130+
// and this function used to run it a second time — two `duckdb_databases()`
131+
// queries per session create. With DuckLake as the session default each one
132+
// starts a DuckLake transaction, and a transaction on a catalog whose schema
133+
// version moved pays a full catalog reload. The executor below has no queryRows
134+
// configured, so any probe would both bump queryCalls and fail the call.
135+
func TestInitSessionDatabaseMetadataWithAttachedSkipsProbe(t *testing.T) {
136+
for _, tc := range []struct {
137+
name string
138+
attached bool
139+
// The deferred restore runs only when DuckLake is attached. Assert on
140+
// the statements themselves: a bare count would still pass if the
141+
// restore ran against the wrong catalog.
142+
wantRestore bool
143+
}{
144+
{name: "attached", attached: true, wantRestore: true},
145+
{name: "not attached", attached: false, wantRestore: false},
146+
} {
147+
t.Run(tc.name, func(t *testing.T) {
148+
exec := &countingExecutor{}
149+
150+
if err := InitSessionDatabaseMetadataWithAttached(
151+
context.Background(), exec, "analytics", nil, tc.attached,
152+
); err != nil {
153+
t.Fatalf("InitSessionDatabaseMetadataWithAttached: %v", err)
154+
}
155+
156+
if exec.queryCalls != 0 {
157+
t.Errorf("issued %d probe queries, want 0 — the caller's answer must be reused", exec.queryCalls)
158+
}
159+
160+
joined := strings.Join(exec.execQueries, "\n---\n")
161+
gotRestore := false
162+
gotSearchPath := false
163+
for _, q := range exec.execQueries {
164+
if strings.EqualFold(strings.TrimSpace(q), "USE ducklake") {
165+
gotRestore = true
166+
}
167+
if strings.HasPrefix(strings.TrimSpace(q), "SET search_path") {
168+
gotSearchPath = true
169+
}
170+
}
171+
if gotRestore != tc.wantRestore {
172+
t.Errorf("`USE ducklake` issued = %v, want %v.\nQueries:\n%s", gotRestore, tc.wantRestore, joined)
173+
}
174+
if gotSearchPath != tc.wantRestore {
175+
t.Errorf("`SET search_path` issued = %v, want %v.\nQueries:\n%s", gotSearchPath, tc.wantRestore, joined)
176+
}
177+
// The session must always leave the memory catalog and install the
178+
// metadata surfaces, attached or not.
179+
if !strings.Contains(joined, "USE memory") {
180+
t.Errorf("did not switch to the memory catalog.\nQueries:\n%s", joined)
181+
}
182+
if !strings.Contains(joined, "current_database()") {
183+
t.Errorf("did not create the current_database() macro.\nQueries:\n%s", joined)
184+
}
185+
})
186+
}
187+
}
188+
189+
// TestInitSessionDatabaseMetadataProbesWhenAttachmentUnknown keeps the nil case
190+
// probing, so the exported wrappers and any caller that does not already hold
191+
// the answer behave exactly as before.
192+
func TestInitSessionDatabaseMetadataProbesWhenAttachmentUnknown(t *testing.T) {
193+
exec := &countingExecutor{queryRows: &singleIntRow{v: 1}}
194+
195+
// The probing entry point must still issue exactly one probe.
196+
if err := InitSessionDatabaseMetadataWithAccess(
197+
context.Background(), exec, "analytics", nil,
198+
); err != nil {
199+
t.Fatalf("InitSessionDatabaseMetadataWithAccess: %v", err)
200+
}
201+
202+
if exec.queryCalls != 1 {
203+
t.Errorf("issued %d probe queries, want 1", exec.queryCalls)
204+
}
205+
}

0 commit comments

Comments
 (0)