From 9c880c082a29991d185b6517ac854b1db5497f4a Mon Sep 17 00:00:00 2001 From: Laurence Isla Date: Tue, 18 Feb 2025 19:17:26 -0500 Subject: [PATCH] feat: allow logging the SQL query to stderr - Logs the main SQL query when `log-query=main-query`. - Only logs at the current `log-level`. --- CHANGELOG.md | 1 + docs/references/configuration.rst | 24 ++++++++ docs/references/observability.rst | 32 +++++++++- src/PostgREST/App.hs | 16 +++-- src/PostgREST/CLI.hs | 3 + src/PostgREST/Config.hs | 20 +++++++ src/PostgREST/Logger.hs | 4 ++ src/PostgREST/Observation.hs | 4 ++ src/PostgREST/Query.hs | 57 +++++++++++------- src/PostgREST/Query/QueryBuilder.hs | 16 ++--- src/PostgREST/Query/Statements.hs | 21 ++++--- ...est_schema_cache_snapshot[dbRoutines].yaml | 17 ++++++ .../test_schema_cache_snapshot[dbTables].yaml | 12 ++++ test/io/configs/expected/aliases.config | 1 + .../configs/expected/boolean-numeric.config | 1 + .../io/configs/expected/boolean-string.config | 1 + test/io/configs/expected/defaults.config | 1 + .../expected/jwt-role-claim-key1.config | 1 + .../expected/jwt-role-claim-key2.config | 1 + .../expected/jwt-role-claim-key3.config | 1 + .../expected/jwt-role-claim-key4.config | 1 + .../expected/jwt-role-claim-key5.config | 1 + ...efaults-with-db-other-authenticator.config | 1 + .../expected/no-defaults-with-db.config | 1 + test/io/configs/expected/no-defaults.config | 1 + test/io/configs/expected/types.config | 1 + test/io/configs/no-defaults-env.yaml | 1 + test/io/configs/no-defaults.config | 1 + test/io/db_config.sql | 1 + test/io/fixtures.sql | 10 ++++ test/io/test_io.py | 60 +++++++++++++++++++ test/spec/SpecHelper.hs | 2 + 32 files changed, 267 insertions(+), 48 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 56f318a67..d3711238a 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -15,6 +15,7 @@ This project adheres to [Semantic Versioning](http://semver.org/). - #1536, Add string comparison feature for jwt-role-claim-key - @taimoorzaeem - #3747, Allow `not_null` value for the `is` operator - @taimoorzaeem - #2255, Apply `to_tsvector()` explicitly to the full-text search filtered column (excluding `tsvector` types) - @laurenceisla + - #1578, Log the main SQL query to stderr at the current `log-level` when `log-query=main-query` - @laurenceisla ### Fixed diff --git a/docs/references/configuration.rst b/docs/references/configuration.rst index 3d6c1d2b6..5c179e82f 100644 --- a/docs/references/configuration.rst +++ b/docs/references/configuration.rst @@ -708,6 +708,30 @@ log-level Because currently there's no buffering for logging, the levels with minimal logging(``crit/error``) will increase throughput. +.. _log-query: + +log-query +--------- + + =============== ================================= + **Type** String + **Default** "disabled" + **Reloadable** Y + **Environment** PGRST_LOG_QUERY + **In-Database** `n/a` + =============== ================================= + + Logs the SQL query for the corresponding request at the current :ref:`log-level`. + See :ref:``sql_query_logs``. + + .. code:: bash + + # Logs the main SQL query + log-query = "main-query" + + # Disables logging the SQL query + log-query = "disabled" + .. _openapi-mode: openapi-mode diff --git a/docs/references/observability.rst b/docs/references/observability.rst index 04a261ba4..603d8e3de 100644 --- a/docs/references/observability.rst +++ b/docs/references/observability.rst @@ -41,12 +41,38 @@ For diagnostic information about the server itself, PostgREST logs to ``stderr`` 06/May/2024:14:11:27 -0500: Received a config reload message on the "pgrst" channel 06/May/2024:14:11:27 -0500: Config reloaded +.. _sql_query_logs: + +SQL Query Logs +-------------- + +To log the :ref:`main SQL query ` executed for a request, set the :ref:`log-query` to ``main-query``. +It will be logged based on the current :ref:`log-level` setting. +For example, with this configuration: + +.. code-block:: bash + + log-level = "warn" + log-query = "main-query" + +The SQL queries will only be logged on ``400`` HTTP errors and up. +So, if the user requests a resource without sufficient privileges: + +.. code-block:: bash + + curl "localhost:3000/protected_table" + +This will be logged by PostgREST: + +.. code:: + + 17/Feb/2025:17:28:15 -0500: WITH pgrst_source AS ( SELECT "public"."protected_table".* FROM "public"."protected_table" ) SELECT null::bigint AS total_result_set, pg_catalog.count(_postgrest_t) AS page_total, coalesce(json_agg(_postgrest_t), '[]') AS body, nullif(current_setting('response.headers', true), '') AS response_headers, nullif(current_setting('response.status', true), '') AS response_status, '' AS response_inserted FROM ( SELECT * FROM pgrst_source ) _postgrest_t + 127.0.0.1 - web_anon [17/Feb/2025:17:28:15 -0500] "GET /protected_table HTTP/1.1" 401 - "" "curl/8.7.1" + Database Logs ------------- -Currently PostgREST doesn't log the SQL commands executed against the underlying database. - -To find the SQL operations, you can watch the database logs. By default PostgreSQL does not keep these logs, so you'll need to make the configuration changes below. +Additionally, to find all the SQL operations, you can watch the database logs. By default PostgreSQL does not keep these logs, so you'll need to make the configuration changes below. Find :code:`postgresql.conf` inside your PostgreSQL data directory (to find that, issue the command :code:`show data_directory;`). Either find the settings scattered throughout the file and change them to the following values, or append this block of code to the end of the configuration file. diff --git a/src/PostgREST/App.hs b/src/PostgREST/App.hs index b0b56c341..254860afa 100644 --- a/src/PostgREST/App.hs +++ b/src/PostgREST/App.hs @@ -17,7 +17,7 @@ module PostgREST.App import Control.Monad.Except (liftEither) -import Data.Either.Combinators (mapLeft) +import Data.Either.Combinators (mapLeft, whenLeft) import Data.Maybe (fromJust) import Data.String (IsString (..)) import Network.Wai.Handler.Warp (defaultSettings, setHost, setPort, @@ -43,7 +43,8 @@ import qualified PostgREST.Unix as Unix (installSignalHandlers) import PostgREST.ApiRequest (ApiRequest (..)) import PostgREST.AppState (AppState) import PostgREST.Auth.Types (AuthResult (..)) -import PostgREST.Config (AppConfig (..), LogLevel (..)) +import PostgREST.Config (AppConfig (..), LogLevel (..), + LogQuery (..)) import PostgREST.Config.PgVersion (PgVersion (..)) import PostgREST.Error (Error) import PostgREST.Network (resolveHost) @@ -148,16 +149,21 @@ postgrestResponse appState conf@AppConfig{..} maybeSchemaCache pgVer authResult@ (planTime, plan) <- withTiming $ liftEither $ Plan.actionPlan iAction conf apiReq sCache let query = Query.query conf authResult apiReq plan sCache pgVer + logSQL = lift . AppState.getObserver appState . DBQuery (Query.getSQLQuery query) (queryTime, queryResult) <- withTiming $ do case query of Query.NoDbQuery r -> pure r Query.DbQuery{..} -> do dbRes <- lift $ AppState.usePool appState (dqTransaction dqIsoLevel dqTxMode $ runExceptT dqDbHandler) - err <- liftEither . mapLeft Error.PgErr . mapLeft (Error.PgError (Just authRole /= configDbAnonRole)) $ dbRes - liftEither err + let eitherResp = mapLeft Error.PgErr . mapLeft (Error.PgError (Just authRole /= configDbAnonRole)) $ dbRes + when (configLogQuery /= LogQueryDisabled) $ whenLeft eitherResp $ logSQL . Error.status + liftEither eitherResp >>= liftEither - (respTime, resp) <- withTiming $ liftEither $ Response.actionResponse queryResult apiReq (T.decodeUtf8 prettyVersion, docsVersion) conf sCache iSchema iNegotiatedByProfile + (respTime, resp) <- withTiming $ do + let response = Response.actionResponse queryResult apiReq (T.decodeUtf8 prettyVersion, docsVersion) conf sCache iSchema iNegotiatedByProfile + when (configLogQuery /= LogQueryDisabled) $ logSQL $ either Error.status Response.pgrstStatus response + liftEither response return $ toWaiResponse (ServerTiming jwtTime parseTime planTime queryTime respTime) resp diff --git a/src/PostgREST/CLI.hs b/src/PostgREST/CLI.hs index 0ba71144b..e481d4284 100644 --- a/src/PostgREST/CLI.hs +++ b/src/PostgREST/CLI.hs @@ -209,6 +209,9 @@ exampleConfigFile = |## Logging level, the admitted values are: crit, error, warn, info and debug. |log-level = "error" | + |## Log the requested SQL query at the current log-level. + |log-query = "disabled" + | |## Determine if the OpenAPI output should follow or ignore role privileges or be disabled entirely. |## Admitted values: follow-privileges, ignore-privileges, disabled |openapi-mode = "follow-privileges" diff --git a/src/PostgREST/Config.hs b/src/PostgREST/Config.hs index 8f90f2b1f..a9cd9a949 100644 --- a/src/PostgREST/Config.hs +++ b/src/PostgREST/Config.hs @@ -17,6 +17,7 @@ module PostgREST.Config , JSPathExp(..) , FilterExp(..) , LogLevel(..) + , LogQuery(..) , OpenAPIMode(..) , Proxy(..) , toText @@ -98,6 +99,7 @@ data AppConfig = AppConfig , configJwtSecretIsBase64 :: Bool , configJwtCacheMaxLifetime :: Int , configLogLevel :: LogLevel + , configLogQuery :: LogQuery , configOpenApiMode :: OpenAPIMode , configOpenApiSecurityActive :: Bool , configOpenApiServerProxyUri :: Maybe Text @@ -126,6 +128,14 @@ dumpLogLevel = \case LogInfo -> "info" LogDebug -> "debug" +data LogQuery = LogQueryMain | LogQueryDisabled + deriving (Eq) + +dumpLogQuery :: LogQuery -> Text +dumpLogQuery = \case + LogQueryMain -> "main-query" + LogQueryDisabled -> "disabled" + data OpenAPIMode = OAFollowPriv | OAIgnorePriv | OADisabled deriving Eq @@ -169,6 +179,7 @@ toText conf = ,("jwt-secret-is-base64", T.toLower . show . configJwtSecretIsBase64) ,("jwt-cache-max-lifetime", show . configJwtCacheMaxLifetime) ,("log-level", q . dumpLogLevel . configLogLevel) + ,("log-query", q . dumpLogQuery . configLogQuery) ,("openapi-mode", q . dumpOpenApiMode . configOpenApiMode) ,("openapi-security-active", T.toLower . show . configOpenApiSecurityActive) ,("openapi-server-proxy-uri", q . fromMaybe mempty . configOpenApiServerProxyUri) @@ -278,6 +289,7 @@ parser optPath env dbSettings roleSettings roleIsolationLvl = (optBool "secret-is-base64")) <*> (fromMaybe 0 <$> optInt "jwt-cache-max-lifetime") <*> parseLogLevel "log-level" + <*> parseLogQuery "log-query" <*> parseOpenAPIMode "openapi-mode" <*> (fromMaybe False <$> optBool "openapi-security-active") <*> parseOpenAPIServerProxyURI "openapi-server-proxy-uri" @@ -353,6 +365,14 @@ parser optPath env dbSettings roleSettings roleIsolationLvl = Just "debug" -> pure LogDebug Just _ -> fail "Invalid logging level. Check your configuration." + parseLogQuery :: C.Key -> C.Parser C.Config LogQuery + parseLogQuery k = + optString k >>= \case + Nothing -> pure LogQueryDisabled + Just "disabled" -> pure LogQueryDisabled + Just "main-query" -> pure LogQueryMain + Just _ -> fail "Invalid SQL logging value. Check your configuration." + parseTxEnd :: C.Key -> ((Bool, Bool) -> Bool) -> C.Parser C.Config Bool parseTxEnd k f = optString k >>= \case diff --git a/src/PostgREST/Logger.hs b/src/PostgREST/Logger.hs index 48a4d8882..667a9a7da 100644 --- a/src/PostgREST/Logger.hs +++ b/src/PostgREST/Logger.hs @@ -90,6 +90,10 @@ observationLogger loggerState logLevel obs = case obs of o@(HasqlPoolObs _) -> do when (logLevel >= LogDebug) $ do logWithZTime loggerState $ observationMessage o + o@(DBQuery sql status) -> do + -- Does not log SQL when it's empty (for OPTIONS requests or for the default OpenAPI output) + when (sql /= mempty && shouldLogResponse logLevel status) $ do + logWithZTime loggerState $ observationMessage o PoolRequest -> pure () PoolRequestFullfilled -> diff --git a/src/PostgREST/Observation.hs b/src/PostgREST/Observation.hs index 18fbf558d..665192583 100644 --- a/src/PostgREST/Observation.hs +++ b/src/PostgREST/Observation.hs @@ -19,6 +19,7 @@ import qualified Data.Text.Encoding as T import qualified Hasql.Connection as SQL import qualified Hasql.Pool as SQL import qualified Hasql.Pool.Observation as SQL +import Network.HTTP.Types.Status (Status) import qualified Network.Socket as NS import Numeric (showFFloat) import PostgREST.Config.PgVersion @@ -46,6 +47,7 @@ data Observation | DBListenRetry Int | DBListenerGotSCacheMsg ByteString | DBListenerGotConfigMsg ByteString + | DBQuery ByteString Status | ConfigReadErrorObs SQL.UsageError | ConfigInvalidObs Text | ConfigSucceededObs @@ -112,6 +114,8 @@ observationMessage = \case "Received a schema cache reload message on the " <> show channel <> " channel" DBListenerGotConfigMsg channel -> "Received a config reload message on the " <> show channel <> " channel" + DBQuery sql _ -> + T.decodeUtf8 sql ConfigReadErrorObs usageErr -> "Failed to query database settings for the config parameters." <> jsonMessage usageErr QueryRoleSettingsErrorObs usageErr -> diff --git a/src/PostgREST/Query.hs b/src/PostgREST/Query.hs index 1b2c6c75c..f504f64c5 100644 --- a/src/PostgREST/Query.hs +++ b/src/PostgREST/Query.hs @@ -5,6 +5,7 @@ module PostgREST.Query ( Query (..) , QueryResult (..) , query + , getSQLQuery ) where import qualified Data.Aeson as JSON @@ -69,6 +70,7 @@ data Query , dqTxMode :: SQL.Mode , dqDbHandler :: DbHandler QueryResult , dqTransaction :: SQL.IsolationLevel -> SQL.Mode -> SQL.Transaction (Either Error QueryResult) -> SQL.Session (Either Error QueryResult) + , dqSQL :: ByteString } | NoDbQuery QueryResult @@ -81,16 +83,17 @@ data QueryResult query :: AppConfig -> AuthResult -> ApiRequest -> ActionPlan -> SchemaCache -> PgVersion -> Query query _ _ _ (NoDb x) _ _ = NoDbQuery $ NoDbResult x query config AuthResult{..} apiReq (Db plan) sCache pgVer = - DbQuery isoLvl txMode dbHandler transaction + DbQuery isoLvl txMode dbHandler transaction mainSQLQuery where transaction = if prepared then SQL.transaction else SQL.unpreparedTransaction prepared = configDbPreparedStatements config isoLvl = planIsoLvl config authRole plan txMode = planTxMode plan + (mainActionQuery, mainSQLQuery) = actionQuery plan config apiReq pgVer sCache dbHandler = do setPgLocals plan config authClaims authRole apiReq runPreReq config - actionQuery plan config apiReq pgVer sCache + mainActionQuery planTxMode :: DbActionPlan -> SQL.Mode planTxMode (DbCrud x) = pTxMode x @@ -104,12 +107,13 @@ planIsoLvl AppConfig{configRoleIsoLvl} role actPlan = case actPlan of where roleIsoLvl = HM.findWithDefault SQL.ReadCommitted role configRoleIsoLvl -actionQuery :: DbActionPlan -> AppConfig -> ApiRequest -> PgVersion -> SchemaCache -> DbHandler QueryResult +-- TODO: Generate the Hasql Statement in a diferent module after the OpenAPI functionality is removed +actionQuery :: DbActionPlan -> AppConfig -> ApiRequest -> PgVersion -> SchemaCache -> (DbHandler QueryResult, ByteString) actionQuery (DbCrud plan@WrappedReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} _ _ = - mainActionQuery + (mainActionQuery, mainSQLQuery) where countQuery = QueryBuilder.readPlanToCountQuery wrReadPlan - result = Statements.prepareRead + (result, mainSQLQuery) = Statements.prepareRead (QueryBuilder.readPlanToQuery wrReadPlan) (if preferCount == Just EstimatedCount then -- LIMIT maxRows + 1 so we can determine below that maxRows was surpassed @@ -128,10 +132,10 @@ actionQuery (DbCrud plan@WrappedReadPlan{..}) conf@AppConfig{..} apiReq@ApiReque DbCrudResult plan <$> resultSetWTotal conf apiReq resultSet countQuery actionQuery (DbCrud plan@MutateReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} _ _ = - mainActionQuery + (mainActionQuery, mainSQLQuery) where (isPut, isInsert, pkCols) = case mrMutatePlan of {Insert{where_,insPkCols} -> ((not . null) where_, True, insPkCols); _ -> (False,False, mempty);} - result = Statements.prepareWrite + (result, mainSQLQuery) = Statements.prepareWrite (QueryBuilder.readPlanToQuery mrReadPlan) (QueryBuilder.mutatePlanToQuery mrMutatePlan) isInsert @@ -160,9 +164,9 @@ actionQuery (DbCrud plan@MutateReadPlan{..}) conf@AppConfig{..} apiReq@ApiReques pure $ DbCrudResult plan resultSet actionQuery (DbCall plan@CallReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} pgVer _ = - mainActionQuery + (mainActionQuery, mainSQLQuery) where - result = Statements.prepareCall + (result, mainSQLQuery) = Statements.prepareCall crProc (QueryBuilder.callPlanToQuery crCallPlan pgVer) (QueryBuilder.readPlanToQuery crReadPlan) @@ -179,20 +183,23 @@ actionQuery (DbCall plan@CallReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{ pure $ DbCallResult plan resultSet actionQuery (MaybeDb plan@InspectPlan{ipSchema=tSchema}) AppConfig{..} _ _ sCache = - lift $ case configOpenApiMode of - OAFollowPriv -> do - tableAccess <- SQL.statement [tSchema] (SchemaCache.accessibleTables configDbPreparedStatements) - MaybeDbResult plan . Just <$> ((,,) - (HM.filterWithKey (\qi _ -> S.member qi tableAccess) $ SchemaCache.dbTables sCache) - <$> SQL.statement ([tSchema], configDbHoistedTxSettings) (SchemaCache.accessibleFuncs configDbPreparedStatements) - <*> SQL.statement tSchema (SchemaCache.schemaDescription configDbPreparedStatements)) - OAIgnorePriv -> - MaybeDbResult plan . Just <$> ((,,) - (HM.filterWithKey (\(QualifiedIdentifier sch _) _ -> sch == tSchema) $ SchemaCache.dbTables sCache) - (HM.filterWithKey (\(QualifiedIdentifier sch _) _ -> sch == tSchema) $ SchemaCache.dbRoutines sCache) - <$> SQL.statement tSchema (SchemaCache.schemaDescription configDbPreparedStatements)) - OADisabled -> - pure $ MaybeDbResult plan Nothing + (mainActionQuery, mempty) + where + mainActionQuery = lift $ + case configOpenApiMode of + OAFollowPriv -> do + tableAccess <- SQL.statement [tSchema] (SchemaCache.accessibleTables configDbPreparedStatements) + MaybeDbResult plan . Just <$> ((,,) + (HM.filterWithKey (\qi _ -> S.member qi tableAccess) $ SchemaCache.dbTables sCache) + <$> SQL.statement ([tSchema], configDbHoistedTxSettings) (SchemaCache.accessibleFuncs configDbPreparedStatements) + <*> SQL.statement tSchema (SchemaCache.schemaDescription configDbPreparedStatements)) + OAIgnorePriv -> + MaybeDbResult plan . Just <$> ((,,) + (HM.filterWithKey (\(QualifiedIdentifier sch _) _ -> sch == tSchema) $ SchemaCache.dbTables sCache) + (HM.filterWithKey (\(QualifiedIdentifier sch _) _ -> sch == tSchema) $ SchemaCache.dbRoutines sCache) + <$> SQL.statement tSchema (SchemaCache.schemaDescription configDbPreparedStatements)) + OADisabled -> + pure $ MaybeDbResult plan Nothing -- Makes sure the querystring pk matches the payload pk -- e.g. PUT /items?id=eq.1 { "id" : 1, .. } is accepted, @@ -291,3 +298,7 @@ runPreReq conf = lift $ traverse_ (SQL.statement mempty . stmt) (configDbPreRequ ("select " <> fromQi req <> "()") HD.noResult (configDbPreparedStatements conf) + +getSQLQuery :: Query -> ByteString +getSQLQuery DbQuery{dqSQL} = dqSQL +getSQLQuery _ = mempty diff --git a/src/PostgREST/Query/QueryBuilder.hs b/src/PostgREST/Query/QueryBuilder.hs index d6f6fbd80..dd625ad8c 100644 --- a/src/PostgREST/Query/QueryBuilder.hs +++ b/src/PostgREST/Query/QueryBuilder.hs @@ -46,14 +46,14 @@ import Protolude readPlanToQuery :: ReadPlanTree -> SQL.Snippet readPlanToQuery node@(Node ReadPlan{select,from=mainQi,fromAlias,where_=logicForest,order, range_=readRange, relToParent, relJoinConds, relSelect} forest) = "SELECT " <> - intercalateSnippet ", " ((pgFmtSelectItem qi <$> (if null select && null forest then defSelect else select)) ++ joinsSelects) <> " " <> - fromFrag <> " " <> - intercalateSnippet " " joins <> " " <> + intercalateSnippet ", " ((pgFmtSelectItem qi <$> (if null select && null forest then defSelect else select)) ++ joinsSelects) <> + fromFrag <> + intercalateSnippet " " joins <> (if null logicForest && null relJoinConds then mempty - else "WHERE " <> intercalateSnippet " AND " (map (pgFmtLogicTree qi) logicForest ++ map pgFmtJoinCondition relJoinConds)) <> " " <> - groupF qi select relSelect <> " " <> - orderF qi order <> " " <> + else " WHERE " <> intercalateSnippet " AND " (map (pgFmtLogicTree qi) logicForest ++ map pgFmtJoinCondition relJoinConds)) <> " " <> + groupF qi select relSelect <> + orderF qi order <> limitOffsetF readRange where fromFrag = fromF relToParent mainQi fromAlias @@ -94,7 +94,7 @@ getJoin :: RelSelectField -> ReadPlanTree -> SQL.Snippet getJoin fld node@(Node ReadPlan{relJoinType} _) = let correlatedSubquery sub al cond = - (if relJoinType == Just JTInner then "INNER" else "LEFT") <> " JOIN LATERAL ( " <> sub <> " ) AS " <> al <> " ON " <> cond + " " <> (if relJoinType == Just JTInner then "INNER" else "LEFT") <> " JOIN LATERAL ( " <> sub <> " ) AS " <> al <> " ON " <> cond subquery = readPlanToQuery node aggAlias = pgFmtIdent $ rsAggAlias fld in @@ -258,7 +258,7 @@ getQualifiedIdentifier rel mainQi tblAlias = case rel of -- FROM clause plus implicit joins fromF :: Maybe Relationship -> QualifiedIdentifier -> Maybe Alias -> SQL.Snippet -fromF rel mainQi tblAlias = "FROM " <> +fromF rel mainQi tblAlias = " FROM " <> (case rel of -- Due to the use of CTEs on RPC, we need to cast the parameter to the table name in case of function overloading. -- See https://github.com/PostgREST/postgrest/issues/2963#issuecomment-1736557386 diff --git a/src/PostgREST/Query/Statements.hs b/src/PostgREST/Query/Statements.hs index e298347e3..67b6c3612 100644 --- a/src/PostgREST/Query/Statements.hs +++ b/src/PostgREST/Query/Statements.hs @@ -56,10 +56,11 @@ data ResultSet prepareWrite :: SQL.Snippet -> SQL.Snippet -> Bool -> Bool -> MediaType -> MediaHandler -> - Maybe PreferRepresentation -> Maybe PreferResolution -> [Text] -> Bool -> SQL.Statement () ResultSet -prepareWrite selectQuery mutateQuery isInsert isPut mt handler rep resolution pKeys = - SQL.dynamicallyParameterized (mtSnippet mt snippet) decodeIt + Maybe PreferRepresentation -> Maybe PreferResolution -> [Text] -> Bool -> (SQL.Statement () ResultSet, ByteString) +prepareWrite selectQuery mutateQuery isInsert isPut mt handler rep resolution pKeys prepared = + (result, sql) where + result@(SQL.Statement sql _ _ _) = SQL.dynamicallyParameterized (mtSnippet mt snippet) decodeIt prepared checkUpsert snip = if isInsert && (isPut || resolution == Just MergeDuplicates) then snip else "''" pgrstInsertedF = checkUpsert "nullif(current_setting('pgrst.inserted', true),'')::int" snippet = @@ -93,10 +94,11 @@ prepareWrite selectQuery mutateQuery isInsert isPut mt handler rep resolution pK MTVndPlan{} -> planRow _ -> fromMaybe (RSStandard Nothing 0 mempty mempty Nothing Nothing Nothing) <$> HD.rowMaybe (standardRow False) -prepareRead :: SQL.Snippet -> SQL.Snippet -> Bool -> MediaType -> MediaHandler -> Bool -> SQL.Statement () ResultSet -prepareRead selectQuery countQuery countTotal mt handler = - SQL.dynamicallyParameterized (mtSnippet mt snippet) decodeIt +prepareRead :: SQL.Snippet -> SQL.Snippet -> Bool -> MediaType -> MediaHandler -> Bool -> (SQL.Statement () ResultSet, ByteString) +prepareRead selectQuery countQuery countTotal mt handler prepared = + (result, sql) where + result@(SQL.Statement sql _ _ _) = SQL.dynamicallyParameterized (mtSnippet mt snippet) decodeIt prepared snippet = "WITH " <> sourceCTE <> " AS ( " <> selectQuery <> " ) " <> countCTEF <> " " <> @@ -118,10 +120,11 @@ prepareRead selectQuery countQuery countTotal mt handler = prepareCall :: Routine -> SQL.Snippet -> SQL.Snippet -> SQL.Snippet -> Bool -> MediaType -> MediaHandler -> Bool -> - SQL.Statement () ResultSet -prepareCall rout callProcQuery selectQuery countQuery countTotal mt handler = - SQL.dynamicallyParameterized (mtSnippet mt snippet) decodeIt + (SQL.Statement () ResultSet, ByteString) +prepareCall rout callProcQuery selectQuery countQuery countTotal mt handler prepared = + (result, sql) where + result@(SQL.Statement sql _ _ _) = SQL.dynamicallyParameterized (mtSnippet mt snippet) decodeIt prepared snippet = "WITH " <> sourceCTE <> " AS (" <> callProcQuery <> ") " <> countCTEF <> diff --git a/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbRoutines].yaml b/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbRoutines].yaml index 89262c2e8..9f68018d0 100644 --- a/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbRoutines].yaml +++ b/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbRoutines].yaml @@ -308,6 +308,23 @@ pdSchema: public pdVolatility: Volatile +- - qiName: root + qiSchema: public + - - pdDescription: null + pdFuncSettings: [] + pdHasVariadic: false + pdName: root + pdParams: [] + pdReturnType: + contents: + contents: + qiName: json + qiSchema: pg_catalog + tag: Scalar + tag: Single + pdSchema: public + pdVolatility: Volatile + - - qiName: uses_prepared_statements qiSchema: public - - pdDescription: null diff --git a/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbTables].yaml b/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbTables].yaml index 14954aaff..420e4938c 100644 --- a/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbTables].yaml +++ b/test/io/__snapshots__/test_cli/test_schema_cache_snapshot[dbTables].yaml @@ -10,6 +10,18 @@ tableSchema: public tableUpdatable: true +- - qiName: infinite_recursion + qiSchema: public + - tableColumns: {} + tableDeletable: false + tableDescription: null + tableInsertable: false + tableIsView: true + tableName: infinite_recursion + tablePKCols: [] + tableSchema: public + tableUpdatable: false + - - qiName: cats qiSchema: public - tableColumns: diff --git a/test/io/configs/expected/aliases.config b/test/io/configs/expected/aliases.config index 13243d157..bb161df30 100644 --- a/test/io/configs/expected/aliases.config +++ b/test/io/configs/expected/aliases.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = true jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/boolean-numeric.config b/test/io/configs/expected/boolean-numeric.config index 9cdbc660d..0f52b08e9 100644 --- a/test/io/configs/expected/boolean-numeric.config +++ b/test/io/configs/expected/boolean-numeric.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = true jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/boolean-string.config b/test/io/configs/expected/boolean-string.config index 9cdbc660d..0f52b08e9 100644 --- a/test/io/configs/expected/boolean-string.config +++ b/test/io/configs/expected/boolean-string.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = true jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/defaults.config b/test/io/configs/expected/defaults.config index 0e55e8e9e..0c7f98788 100644 --- a/test/io/configs/expected/defaults.config +++ b/test/io/configs/expected/defaults.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/jwt-role-claim-key1.config b/test/io/configs/expected/jwt-role-claim-key1.config index 734650c27..c537df986 100644 --- a/test/io/configs/expected/jwt-role-claim-key1.config +++ b/test/io/configs/expected/jwt-role-claim-key1.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/jwt-role-claim-key2.config b/test/io/configs/expected/jwt-role-claim-key2.config index 1caefcd15..1fe113fae 100644 --- a/test/io/configs/expected/jwt-role-claim-key2.config +++ b/test/io/configs/expected/jwt-role-claim-key2.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/jwt-role-claim-key3.config b/test/io/configs/expected/jwt-role-claim-key3.config index 0b70baeeb..c18a606a1 100644 --- a/test/io/configs/expected/jwt-role-claim-key3.config +++ b/test/io/configs/expected/jwt-role-claim-key3.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/jwt-role-claim-key4.config b/test/io/configs/expected/jwt-role-claim-key4.config index 8e07aab64..6763104ad 100644 --- a/test/io/configs/expected/jwt-role-claim-key4.config +++ b/test/io/configs/expected/jwt-role-claim-key4.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/jwt-role-claim-key5.config b/test/io/configs/expected/jwt-role-claim-key5.config index 9681e8a8b..13cead3ca 100644 --- a/test/io/configs/expected/jwt-role-claim-key5.config +++ b/test/io/configs/expected/jwt-role-claim-key5.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/expected/no-defaults-with-db-other-authenticator.config b/test/io/configs/expected/no-defaults-with-db-other-authenticator.config index a15cd0b4e..d33b144c0 100644 --- a/test/io/configs/expected/no-defaults-with-db-other-authenticator.config +++ b/test/io/configs/expected/no-defaults-with-db-other-authenticator.config @@ -25,6 +25,7 @@ jwt-secret = "ODERREALLYREALLYREALLYREALLYVERYSAFE" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 7200 log-level = "info" +log-query = "main-query" openapi-mode = "disabled" openapi-security-active = false openapi-server-proxy-uri = "https://otherexample.org/api" diff --git a/test/io/configs/expected/no-defaults-with-db.config b/test/io/configs/expected/no-defaults-with-db.config index fc197f2a8..5202d7f71 100644 --- a/test/io/configs/expected/no-defaults-with-db.config +++ b/test/io/configs/expected/no-defaults-with-db.config @@ -25,6 +25,7 @@ jwt-secret = "OVERRIDE=REALLY=REALLY=REALLY=REALLY=VERY=SAFE" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 3600 log-level = "info" +log-query = "main-query" openapi-mode = "ignore-privileges" openapi-security-active = true openapi-server-proxy-uri = "https://example.org/api" diff --git a/test/io/configs/expected/no-defaults.config b/test/io/configs/expected/no-defaults.config index c2d33c509..e5723fbdf 100644 --- a/test/io/configs/expected/no-defaults.config +++ b/test/io/configs/expected/no-defaults.config @@ -25,6 +25,7 @@ jwt-secret = "c2VjdXJpdHl0aHJvdWdob2JzY3VyaXR5aW5iYXNlNjQ=" jwt-secret-is-base64 = true jwt-cache-max-lifetime = 86400 log-level = "info" +log-query = "main-query" openapi-mode = "ignore-privileges" openapi-security-active = true openapi-server-proxy-uri = "https://postgrest.org" diff --git a/test/io/configs/expected/types.config b/test/io/configs/expected/types.config index bc7815e3e..0b3a652cf 100644 --- a/test/io/configs/expected/types.config +++ b/test/io/configs/expected/types.config @@ -25,6 +25,7 @@ jwt-secret = "" jwt-secret-is-base64 = false jwt-cache-max-lifetime = 0 log-level = "error" +log-query = "disabled" openapi-mode = "follow-privileges" openapi-security-active = false openapi-server-proxy-uri = "" diff --git a/test/io/configs/no-defaults-env.yaml b/test/io/configs/no-defaults-env.yaml index 0ab82a3c9..df5bc456a 100644 --- a/test/io/configs/no-defaults-env.yaml +++ b/test/io/configs/no-defaults-env.yaml @@ -28,6 +28,7 @@ PGRST_JWT_SECRET: c2VjdXJpdHl0aHJvdWdob2JzY3VyaXR5aW5iYXNlNjQ= PGRST_JWT_SECRET_IS_BASE64: true PGRST_JWT_CACHE_MAX_LIFETIME: 86400 PGRST_LOG_LEVEL: info +PGRST_LOG_QUERY: 'main-query' PGRST_OPENAPI_MODE: 'ignore-privileges' PGRST_OPENAPI_SECURITY_ACTIVE: true PGRST_OPENAPI_SERVER_PROXY_URI: 'https://postgrest.org' diff --git a/test/io/configs/no-defaults.config b/test/io/configs/no-defaults.config index 5859d6b2a..f730d1685 100644 --- a/test/io/configs/no-defaults.config +++ b/test/io/configs/no-defaults.config @@ -25,6 +25,7 @@ jwt-secret = "c2VjdXJpdHl0aHJvdWdob2JzY3VyaXR5aW5iYXNlNjQ=" jwt-secret-is-base64 = true jwt-cache-max-lifetime = 86400 log-level = "info" +log-query = "main-query" openapi-mode = "ignore-privileges" openapi-security-active = true openapi-server-proxy-uri = "https://postgrest.org" diff --git a/test/io/db_config.sql b/test/io/db_config.sql index b139e87dc..18ac1c297 100644 --- a/test/io/db_config.sql +++ b/test/io/db_config.sql @@ -47,6 +47,7 @@ ALTER ROLE db_config_authenticator SET pgrst.db_pool_max_idletime = 'ignored'; ALTER ROLE db_config_authenticator SET pgrst.db_pool_max_lifetime = 'ignored'; ALTER ROLE db_config_authenticator SET pgrst.db_uri = 'postgresql://ignored'; ALTER ROLE db_config_authenticator SET pgrst.log_level = 'ignored'; +ALTER ROLE db_config_authenticator SET pgrst.log_query = 'ignored'; ALTER ROLE db_config_authenticator SET pgrst.server_host = 'ignored'; ALTER ROLE db_config_authenticator SET pgrst.server_port = 'ignored'; ALTER ROLE db_config_authenticator SET pgrst.server_unix_socket = 'ignored'; diff --git a/test/io/fixtures.sql b/test/io/fixtures.sql index 7c8658cd3..c50f15e7f 100644 --- a/test/io/fixtures.sql +++ b/test/io/fixtures.sql @@ -243,3 +243,13 @@ end $_$ volatile security definer language plpgsql ; create function test.get_current_schema() returns text as $$ select current_schema()::text; $$ language sql; + +create or replace function root() returns json as $_$ + select '{"swagger": "2.0"}'::json; +$_$ language sql; + +create view infinite_recursion as +select * from projects; + +create or replace view infinite_recursion as +select * from infinite_recursion; diff --git a/test/io/test_io.py b/test/io/test_io.py index ff5619fb9..b7d9d912a 100644 --- a/test/io/test_io.py +++ b/test/io/test_io.py @@ -980,6 +980,66 @@ def test_log_level(level, defaultenv): assert len(output) == 7 +@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"]) +def test_log_query(level, defaultenv): + "log_query=true should log the SQL query according to the log_level" + + env = { + **defaultenv, + "PGRST_LOG_LEVEL": level, + "PGRST_LOG_QUERY": "main-query", + # The root path can only log SQL when a function is set in db-root-spec + "PGRST_DB_ROOT_SPEC": "root", + } + + with run(env=env) as postgrest: + response = postgrest.session.get("/") + assert response.status_code == 200 + + response = postgrest.session.get("/projects") + assert response.status_code == 200 + + response = postgrest.session.get("/unknown") + assert response.status_code == 404 + + response = postgrest.session.get("/infinite_recursion") + assert response.status_code == 500 + + root_2xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."root"\(\) pgrst_scalar.+_postgrest_t' + get_2xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."projects"\.\* FROM "public"\."projects".+_postgrest_t' + unknown_4xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."unknown"\.\* FROM "public"\."unknown".+_postgrest_t' + infinite_recursion_5xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."infinite_recursion"\.\* FROM "public"\."infinite_recursion".+_postgrest_t' + + if level == "crit": + output = postgrest.read_stdout(nlines=1) + assert len(output) == 0 + elif level == "error": + output = postgrest.read_stdout(nlines=4) + assert re.match(infinite_recursion_5xx_regx, output[1]) + assert len(output) == 3 + elif level == "warn": + output = postgrest.read_stdout(nlines=6) + assert re.match(unknown_4xx_regx, output[0]) + assert re.match(infinite_recursion_5xx_regx, output[3]) + assert len(output) == 5 + elif level == "info": + output = postgrest.read_stdout(nlines=10) + assert re.match(root_2xx_regx, output[0]) + assert re.match(get_2xx_regx, output[2]) + assert re.match(unknown_4xx_regx, output[4]) + assert re.match(infinite_recursion_5xx_regx, output[7]) + assert len(output) == 9 + elif level == "debug": + output_ok = postgrest.read_stdout(nlines=8) + assert re.match(root_2xx_regx, output_ok[2]) + assert re.match(get_2xx_regx, output_ok[6]) + assert len(output_ok) == 8 + output_err = postgrest.read_stdout(nlines=10) + assert re.match(unknown_4xx_regx, output_err[2]) + assert re.match(infinite_recursion_5xx_regx, output_err[7]) + assert len(output_err) == 9 + + def test_no_pool_connection_required_on_bad_http_logic(defaultenv): "no pool connection should be consumed for failing on invalid http logic" diff --git a/test/spec/SpecHelper.hs b/test/spec/SpecHelper.hs index 988323e3f..341802cde 100644 --- a/test/spec/SpecHelper.hs +++ b/test/spec/SpecHelper.hs @@ -30,6 +30,7 @@ import Data.String (String) import PostgREST.Config (AppConfig (..), JSPathExp (..), LogLevel (..), + LogQuery (..), OpenAPIMode (..), parseSecret) import PostgREST.SchemaCache.Identifiers (QualifiedIdentifier (..)) @@ -138,6 +139,7 @@ baseCfg = let secret = encodeUtf8 "reallyreallyreallyreallyverysafe" in , configJwtSecretIsBase64 = False , configJwtCacheMaxLifetime = 0 , configLogLevel = LogCrit + , configLogQuery = LogQueryDisabled , configOpenApiMode = OAFollowPriv , configOpenApiSecurityActive = False , configOpenApiServerProxyUri = Nothing