Commit Graph
1203 Commits
Author SHA1 Message Date
steve-chavez bcc8998e5e add: log schema cache queries' timings
This adds a new log line that shows each schema cache query time individually, only on
`log-level=debug`. Like so:

```
$ PGRST_LOG_LEVEL=debug postgrest-with-pg-17 -f test/spec/fixtures/load.sql postgrest-run

....
10/Apr/2026:21:48:45 -0500: Schema cache queried in 192.2 milliseconds
10/Apr/2026:21:48:45 -0500: tables: 72.027 ms, keydeps: 20.118 ms, rels: 6.189 ms, funcs: 35.010 ms, comprels: 4.319 ms, dreps: 1.614 ms, mhandlers: 7.419 ms, tzones: 43.025 ms
```

This helps debug specific schema cache queries being slow like on
https://github.com/PostgREST/postgrest/issues/4613#issuecomment-4210191065 and
https://github.com/PostgREST/postgrest/issues/3046#issuecomment-3469059948.
It also closes https://github.com/PostgREST/postgrest/issues/3215,
which main motivation was to find out which query is slow.

Implementation details
---------------------

To time each query inside a transaction in pure SQL, we do:

```sql
-- start timer
select set_config('pgrst.tmp_x', clock_timestamp()::text, false);
-- run the query
select <query>
-- end timer
select set_config('pgrst.tmp_x', (clock_timestamp() - current_setting('pgrst.tmp_x', false)::timestamptz)::text, false);

-- .... repeated for every query

-- at the end we capture all the timings with
select extract('milliseconds' from current_setting('pgrst.tmp_x', false)::interval), extract(..;
```

Considerations
--------------

Only added this on `log-level=debug` because while the queries are fast
and the data is valuable, it triples the amount of queries we run during schema cache refresh,
which could be troublesome on slow networks. It's possible to reduce the
amount of queries by starting and stopping timers in one statement, but
this would still double the amount of queries and makes the code messy,
doesn't seem worth it.

Also it would pollute pg_stat_statements, it's only required to debug certain
extreme cases anyway.
2026-04-16 13:10:24 -05:00
Michal KleczekandGitHub aca58c8571 fix: Flush pool as late as possible during schema cache reloading (#4645)
retryingSchemaCacheLoad flushes the pool upon every retry before it starts reloading the schema. This is too early as schema reloading might take some time during which new connections might be acquired. The consequence is that:
* upon successful schema cache reload we might have some connections created with the old schema cache
* we close connections upon each retry and under load we will keep closing and re-opening connections until schema cache load succeeds

This change is to make sure we flush the pool only after successful schema cache querying but before loading (so that connections acquired during loading wait for it and do not interfere with timing the loading process).
2026-04-14 17:09:25 -05:00
steve-chavez 2fb2e86473 fix: remove red herring warp logs on default log-level
The logs added on e95e815483 are red
herrings under normal operation.

This moves them to `log-level=debug` and removes "error" from the
message prefix.

Fixes https://github.com/PostgREST/postgrest/issues/4799
2026-04-09 16:44:25 -05:00
Michał KłeczekandSteve Chavez c31aeecdcf test: add test_pool_acquisition_timeout_logs_are_debounced to io tests 2026-04-09 13:59:17 -05:00
Michał KłeczekandSteve Chavez 5d4f82d70f add: log pool flushes
Emit a dedicated PoolFlushed observation when the DB pool is released during schema cache reload.
2026-04-09 10:41:29 -05:00
Michał KłeczekandSteve Chavez ad907219be test(refactor): make debug output testing more robust
This change introduces a match_log function, that implements lenient matching of log output lines. Tests of log output are retrofited to use the function.
2026-04-09 10:41:29 -05:00
Artur Bento de CarvalhoandGitHub 69c6a0aa36 fix: use int32/int64 formats for integer types
Fixed integer type mapping in OpenAPI 2.0: replaced the invalid integer format with int32/int64 and added the toSwaggerFormat function to map PostgreSQL types to valid OpenAPI 2.0 formats:

smallint -> int32
integer -> int32
bigint -> int64
2026-04-03 14:21:32 -05:00
Michał KłeczekandSteve Chavez 328598eaed test: Schema cache load debouncing
test: adjust replicateM to 100
2026-04-02 09:02:18 -05:00
Taimoor ZaeemandSteve Chavez d6c338d588 add: config db-timezone-enabled for optional querying of timezones
To avoid repeated querying of `pg_timezone_names` every time schema
cache is reset, `Prefer: timezone` can be disabled by setting
`db-timezone-enabled = false`.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-04-01 12:48:38 -05:00
Michał KłeczekandSteve Chavez bd5de884fa test(io): add test_so_reuseport_zero_downtime_handover 2026-03-31 13:33:33 -05:00
Michal KleczekandGitHub 8d5b1018d3 refactor(test): provide means to validate metrics and observations
Some helpers are provided for introspecting metrics already (used in JWT cache tests). This change provides facilities to additionally validate emited Observation events.
A new Spec module is also implemented, adding basic tests of schema cache reloading - their main goal is to excercise the new infrastructure.
2026-03-31 13:15:56 -05:00
Taimoor ZaeemandSteve Chavez 1b402d16ad test(spec): move preference tests into separate modules
Towards #4751.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-03-26 12:36:47 -05:00
Taimoor ZaeemandSteve Chavez 135b77d12b test(io): rename jwt-role-claim-key*.config dump files
These files were added to cover the config dumping of
string comparison operators in `JSPath`. Renaming and
adding a comment in these to make it clear.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-03-24 11:11:43 -05:00
steve-chavez 622c6d3f19 fix: not logging termination unix signals
Under container environments like ECS, it's hard to know when PostgREST
is being terminated.
2026-03-20 13:09:10 -05:00
Taimoor ZaeemandSteve Chavez 12ef63370b nix(test): add test suite for observability tests
- Create separate test suite for observability tests

- Create wrapper script `postgrest-test-observability`

- Add to CI and `postgrest-check`

- Move JWT cache tests under observability tests

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-03-19 10:38:42 -05:00
Andrei DziahelandSteve Chavez 1f54e2accc add: add "Vary" header to responses
Co-authored-by: Steve Chavez <stevechavezast@gmail.com>
2026-03-16 09:55:20 -05:00
Michał KłeczekandSteve Chavez bee2ea6fa6 test(io): add test_graceful_shutdown_waits_for_in_flight_request 2026-03-12 15:24:46 -05:00
Michał KłeczekandSteve Chavez a4aa58b4de refactor: move socket creation and management to App module
Right now listening sockets initialization, management and usage is split between App, AppState and Admin modules: they are created in AppState.init and remembered in AppState but used only in App and Admin.

It has several negative consequences:
- sockets are initialized even if not needed (eg. command line invocations like dump-config or dump-schema)
- it is impossible to start listening on a socket after initial schema cache load because it requires AppState

This change decouples listen socket management from AppState. Sockets are created only when needed (ie. not in command line tools invocation) and passed to admin application and to Warp by the App module.
2026-03-12 10:03:47 -05:00
Taimoor ZaeemandSteve Chavez 5abacba0d8 fix(error): leaking table and function names when calculating hint
Increase similarity score to 0.75 from 0.33 for table and functions
error hint.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-03-06 16:03:21 -05:00
Michał KłeczekandSteve Chavez 2408cd332d refactor: get rid of redundant SchemaCacheSummaryObs
There is unnecessary coupling between observation messages and emited log entries. This causes schema loading logic to emit redundant events: SchemaCacheSummaryObs and SchemaCacheLoadedObs.

Logically - we want to emit a single event containing both summary and timing information. How it is logged is a different matter and should be decoupled.

This commit
* changes observationMessage function returning Text to observationMessages returning [Text] so that it is possible to return multiple (or zero) messages to log based on an observation event
* Removes SchemaCacheSummaryObs constructor from Observation type and adds summary text to SchemaCacheLoadedObs
2026-03-02 14:45:31 -05:00
Taimoor ZaeemandSteve Chavez 83dc082acf add: config client-error-verbosity to set error verbosity
Set error verbosity using this config. The verbosity can
be set to `verbose` or `minimal` for client error responses.

This only affects client side HTTP responses, server side logs
are not affected by this config.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-02-25 15:24:27 -05:00
Taimoor ZaeemandWolfgang Walther b977ffbb90 test(io): reset statement_timeout of anon role to correct value
Forgot to do this in bfb4f900e7.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-02-18 12:46:30 +00:00
Michał KłeczekandSteve Chavez 85a313a8cc test(spec): Move metrics state helpers from JwtCacheSpec to SpecHelpers
Refactoring: State validation helpers used in JwtCacheSpec moved to SpecHelper
to make them available in other Spec modules.
2026-02-17 17:55:16 -05:00
Taimoor ZaeemandSteve Chavez bfb4f900e7 test(io): increase statement_timeout value of anonymous role
It is too low which leaves a small window of values to
use when testing other features.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-02-17 11:35:12 -05:00
steve-chavez e95e815483 fix: don't hide async exceptions in logs
Fixes #4646. Using the repro on #4646, this now produces the log:

```
11/Feb/2026:09:40:08 -0500: Warp server error: stack overflow
```

When:
```
$ curl localhost:3000/
curl: (52) Empty reply from server
```
2026-02-12 19:43:50 -05:00
Taimoor ZaeemandSteve Chavez aaaf7e96bd test(io): set client_min_messages to warning in SQL fixtures
To suppress unwanted "NOTICE: ..." messages which pollute the log.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-02-04 09:20:03 -05:00
Taimoor ZaeemandSteve Chavez 37fc0a211b test(io): refactor SQL fixtures
- Move privileges and grants to privileges.sql
- Move schema, tables and functions to schema.sql
- Move global database settings to database.sql

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-02-04 09:20:03 -05:00
Taimoor ZaeemandSteve Chavez c35eb7a6c2 test(io): move role fixtures to roles.sql
Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2026-02-02 17:38:32 -05:00
Laurence Isla d10c779fc6 perf: optimize count=exact when there's no limits, offsets or db-max-rows 2026-01-28 18:43:44 -05:00
Laurence Isla 1682677297 fix: filtering the returned representation whenn using or/and filters on mutations 2026-01-27 21:24:19 +00:00
Michał KłeczekandSteve Chavez 21b8c3458a add: Log pg version details of listener connection
Follow-up to #4617 adding more information to log entry produced upon successful listener connection establishement.
2026-01-27 15:44:05 -05:00
Michał KłeczekandSteve Chavez 5356f4e973 add: Log actual host and port of listener connection
Diagnosing problems with listener channel notifications not being handled properly by PostgREST connected to read replicas is difficult. Issues might be related to lost connections and listener not being connected to the right host after failover or database server restarts.
This patch adds logging of actual host:port used by libpq connection opened by the listener. It should make it easier to find out if PostgREST is connected to the right host.
2026-01-27 11:00:30 -05:00
Taimoor ZaeemandGitHub fe0386e9c4 add: string slicing operator for jwt-role-claim-key (#4603) 2026-01-24 05:40:21 -05:00
Michał KłeczekandSteve Chavez 886df84e87 test: Fix flakiness of test_second_request_for_non_existent_table_should_be_quick
Changed divider in assertion (response.elapsed.total_seconds() < first_duration / divider) to 2 (from 10).
2026-01-13 11:37:50 +07:00
Michał KłeczekandSteve Chavez e592d568c6 fix: Performance and high memory usage of relation hint calculation
* Calculation of hint message when requested relation is not present in schema cache requires creation of a FuzzySet (to use fuzzy search to find candidate tables). For schemas with many tables it is costly.
This patch introduces dbTablesFuzzyIndex in SchemaCache to memoize the FuzzySet creation.

* Additionally, because of FuzzySet large memory requirements, this patch introduces a limit of 500 relations per schema, above which FuzzySet is not created and hint calculation disabled.
2026-01-03 07:56:12 +08:00
steve-chavez b8ca1bb04c nix: add new loadtest for errors
Also included it in CI.
2025-12-23 15:00:24 -05:00
steve-chavez 013f078bc4 fix: inaccurate Server-Timing durations
The transaction duration was notably off, doing:

```
curl localhost:3000/rpc/sleep?seconds=5 -i
```

Shows `46.1` for the `transaction;dur`, with this fix we obtain
`5007.3`.

Fixes https://github.com/PostgREST/postgrest/issues/4522

This also fixes inaccurate "schema cache queried" logs,
see https://github.com/PostgREST/postgrest/issues/4551.
2025-12-18 17:35:18 -05:00
Joel JakobssonandGitHub fd6a3bdccf fix: hasSingleUnnamedParam incorrectly matching named parameters
The hasSingleUnnamedParam function was only checking the parameter type
but not whether the parameter actually had no name. This caused functions
with a single NAMED parameter (e.g., `foo(data json)`) to incorrectly
match the single-param fallback mode.

The result was a confusing PostgreSQL error 42883 "function does not exist"
instead of a clean PGRST202 error explaining that no matching function
was found.

Added ppName == mempty check so functions with named parameters don't
incorrectly match the single-param fallback.
2025-12-15 15:34:48 -05:00
Taimoor ZaeemandSteve Chavez abad47ff1b add: log error when db-schemas config contain restricted schemas
We don't allow accessing schemas "pg_catalog" and "information_schema".
Instead of silently failing requests on these schemas, this now adds
logging an error on startup when these schemas are found in `db-schemas`
config.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-12-11 14:28:08 -05:00
Laurence Isla 9200a98087 fix: add missing Content-Length to empty HTTP 201 responses
For when a preference other than return=representation is requested.
2025-12-10 14:18:19 +00:00
Laurence Isla 3b27b2220d fix: regression that truncates error message when offset is out of bounds
- Happens when offset > the number of rows and when "Prefer: count=exact" header is sent
- Regression introduced in commit 57ef998
2025-12-10 14:18:19 +00:00
Taimoor ZaeemandSteve Chavez 50eec773bf test(io): fix freeport function to prevent failures
Sometimes, a healthcheck related test fails as occurred in
https://github.com/PostgREST/postgrest/actions/runs/19771357953/job/56655949002.
This happens due to freeport function accidently picking up a used port.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-11-29 18:17:00 -05:00
Taimoor ZaeemandSteve Chavez 35de13eebd test(io): move fixtures to fixtures/ directory
Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-11-27 17:08:03 -05:00
Taimoor ZaeemandSteve Chavez c561a3749c test(io): move authentication related tests to test_auth.py
The `test_io.py` module is too bloated (2100+ lines). To
logically group related tests, as a first step, this commit
separates authentication related IO tests into `test_auth.py`
module.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-11-21 13:21:15 -05:00
Taimoor ZaeemandSteve Chavez 379eaec8e0 test(io): remove stale jwt cache test
Removes a test related to jwt cache which is stale
since #4084.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-11-19 11:17:18 -05:00
Taimoor ZaeemandWolfgang Walther 462798dc2d nix: shorten postgrest-with-postgresql-xx scripts
Renames these scripts to `postgrest-with-pg-xx`. The renaming
helps reduce the length of temporary filenames. This is needed
to ensure that socket file names remain under the maximum
allowed length of 107 chars.

Closes #4461.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-11-18 09:40:16 +00:00
Taimoor ZaeemandSteve Chavez 91abcd49e1 test(io): move resource embedding tests to test_io.py
- Adds fixtures to `test/io/fixtures.sql` to test resource
  embedding related queries.

- Moves the resource embedding related tests that no longer
  require big schema from `test_big_schema.py` to `test_io.py`.

Closes #4417.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-11-11 13:43:10 -05:00
Taimoor ZaeemandSteve Chavez 58efc2680e fix: server-host !6 incorrectly binds to IPv4 address
Updates streaming-commons to version 0.2.3.1. This resolves #3202.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-11-02 12:24:14 -05:00
Taimoor ZaeemandSteve Chavez db2be093b5 refactor: move dumpQi to Config.hs and clarify quoteQi
The `dumpQi` function is only used in the `Config.hs` module, so
it is moved there. This also adds a doctest for `quoteQi` and
clarifies its usage.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-10-30 12:26:29 -05:00
Taimoor ZaeemandSteve Chavez a688878236 fix: db-pre-config function failing with pg reserved words
When db-pre-config is accidentally set to a pg reserved word
like "true", it fails with a confusing error. The function
names should be properly quoted to avoid such errors. This commit
resolves this by quoting the pre-config function name.

Signed-off-by: Taimoor Zaeem <taimoorzaeem@gmail.com>
2025-10-29 16:54:24 -05:00