From cddfb6cf5ea4bde23df27a2f1dfa115c950ac701 Mon Sep 17 00:00:00 2001 From: steve-chavez Date: Wed, 3 Sep 2025 15:53:15 -0500 Subject: [PATCH] fix: not logging OpenAPI queries Closes https://github.com/PostgREST/postgrest/issues/4226. This requires moving query generation to the top App.hs module. At this point is also simple to log the transaction variables + the pre-request function call but this is not done here to reduce scope. --- CHANGELOG.md | 4 ++ src/PostgREST/App.hs | 21 +++++--- src/PostgREST/Logger.hs | 38 ++++++++++--- src/PostgREST/Observation.hs | 17 +++--- src/PostgREST/Query.hs | 96 +++++++++++++++++++-------------- src/PostgREST/Query/PreQuery.hs | 2 +- test/io/test_io.py | 32 +++++------ 7 files changed, 133 insertions(+), 77 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 2dc670126..420bf6034 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -5,6 +5,10 @@ This project adheres to [Semantic Versioning](http://semver.org/). ## Unreleased +### Fixed + +- Fix not logging OpenAPI queries when `log-query=main-query` is enabled by @steve-chavez in #4226 + ### Added - Improve the `PGRST106` error when the requested schema is invalid by @laurenceisla in #4089 diff --git a/src/PostgREST/App.hs b/src/PostgREST/App.hs index e6974b436..01a29b3a4 100644 --- a/src/PostgREST/App.hs +++ b/src/PostgREST/App.hs @@ -142,21 +142,30 @@ postgrestResponse appState conf@AppConfig{..} maybeSchemaCache authResult@AuthRe (parseTime, apiReq@ApiRequest{..}) <- withTiming $ liftEither . mapLeft Error.ApiRequestError $ ApiRequest.userApiRequest conf prefs req body (planTime, plan) <- withTiming $ liftEither $ Plan.actionPlan iAction conf apiReq sCache - let query = Query.query conf authResult apiReq plan sCache - logSQL = lift . AppState.getObserver appState . DBQuery (Query.getSQLQuery query) + let mainQ = Query.mainQuery plan conf apiReq authResult configDbPreRequest + query = Query.mainTx mainQ conf authResult apiReq plan sCache + observer = AppState.getObserver appState + obsQuery s = when (configLogQuery /= LogQueryDisabled) $ observer $ QueryObs mainQ s (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) - let eitherResp = mapLeft Error.PgErr . mapLeft (Error.PgError (Just authRole /= configDbAnonRole)) $ dbRes - when (configLogQuery /= LogQueryDisabled) $ whenLeft eitherResp $ logSQL . Error.status - liftEither eitherResp >>= liftEither + let eitherResp = join $ mapLeft (Error.PgErr . Error.PgError (Just authRole /= configDbAnonRole)) dbRes + + -- TODO: we use obsQuery twice, one here and one below because in case of an error with the usePool above, the request will finish here and return an error message. + -- This is because of a combination of ExceptT + our Error module which has Wai.responseLBS. + -- This needs refactoring so only the below obsQuery is used. + lift $ whenLeft eitherResp $ obsQuery . Error.status + liftEither eitherResp (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 + status' = either Error.status Response.pgrstStatus response + + -- TODO: see above obsQuery, only this obsQuery should remain after refactoring (because the QueryObs depends on the status) + lift $ obsQuery status' liftEither response return $ toWaiResponse (ServerTiming jwtTime parseTime planTime queryTime respTime) resp diff --git a/src/PostgREST/Logger.hs b/src/PostgREST/Logger.hs index a66fae658..de71b48ca 100644 --- a/src/PostgREST/Logger.hs +++ b/src/PostgREST/Logger.hs @@ -1,3 +1,4 @@ +{-# LANGUAGE RecordWildCards #-} {-| Module : PostgREST.Logger Description : Logging based on the Observation.hs module. Access logs get sent to stdout and server diagnostic get sent to stderr. @@ -10,10 +11,16 @@ module PostgREST.Logger , LoggerState ) where -import Control.AutoUpdate (defaultUpdateSettings, - mkAutoUpdate, updateAction) +import Control.AutoUpdate (defaultUpdateSettings, + mkAutoUpdate, + updateAction) import Control.Debounce -import qualified Data.ByteString.Char8 as BS +import qualified Data.ByteString.Char8 as BS +import qualified Data.Text.Encoding as T +import qualified Hasql.Decoders as HD +import qualified Hasql.DynamicStatements.Snippet as SQL hiding (sql) +import qualified Hasql.DynamicStatements.Statement as SQL +import qualified Hasql.Statement as SQL import Data.Time (ZonedTime, defaultTimeLocale, formatTime, getZonedTime) @@ -26,6 +33,7 @@ import System.IO.Unsafe (unsafePerformIO) import PostgREST.Config (LogLevel (..)) import PostgREST.Observation +import PostgREST.Query (MainQuery (..)) import Protolude @@ -90,10 +98,9 @@ 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 + QueryObs gq status -> do + when (shouldLogResponse logLevel status) $ + logMainQ loggerState gq o@PoolRequest -> when (logLevel >= LogDebug) $ do logWithZTime loggerState $ observationMessage o @@ -113,3 +120,20 @@ logWithZTime :: LoggerState -> Text -> IO () logWithZTime loggerState txt = do zTime <- stateGetZTime loggerState hPutStrLn stderr $ toS (formatTime defaultTimeLocale "%d/%b/%Y:%T %z: " zTime) <> txt + +logMainQ :: LoggerState -> MainQuery -> IO () +logMainQ loggerState MainQuery{mqOpenAPI=(x, y, z),..} = + let snipts = renderSnippet <$> [mqMain, x, y, z] + -- Does not log SQL when it's empty (happens on OPTIONS requests and when the openapi queries are not generated) + logQ q = when (q /= mempty) $ logWithZTime loggerState $ showOnSingleLine '\n' $ T.decodeUtf8 q in + mapM_ logQ snipts + +-- TODO: maybe patch upstream hasql-dynamic-statements so we have a less hackish way to convert +-- the SQL.Snippet or maybe don't use hasql-dynamic-statements and resort to plain strings for the queries and use regular hasql +renderSnippet :: SQL.Snippet -> ByteString +renderSnippet snippet = + let SQL.Statement sql _ _ _ = SQL.dynamicallyParameterized snippet decoder prepared + decoder = HD.noResult -- unused + prepared = False -- unused + in + sql diff --git a/src/PostgREST/Observation.hs b/src/PostgREST/Observation.hs index 481f9ff81..34b11b5e3 100644 --- a/src/PostgREST/Observation.hs +++ b/src/PostgREST/Observation.hs @@ -11,6 +11,7 @@ module PostgREST.Observation , ObsFatalError(..) , observationMessage , ObservationHandler + , showOnSingleLine ) where import qualified Data.ByteString.Lazy as LBS @@ -24,6 +25,7 @@ import Network.HTTP.Types.Status (Status) import Numeric (showFFloat) import PostgREST.Config.PgVersion import qualified PostgREST.Error as Error +import PostgREST.Query (MainQuery) import Protolude hiding (toList) @@ -45,7 +47,7 @@ data Observation | DBListenRetry Int | DBListenerGotSCacheMsg ByteString | DBListenerGotConfigMsg ByteString - | DBQuery ByteString Status + | QueryObs MainQuery Status | ConfigReadErrorObs SQL.UsageError | ConfigInvalidObs Text | ConfigSucceededObs @@ -113,8 +115,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 + QueryObs{} -> + mempty -- TODO pending refactor: The logic for printing the query cannot be done here. Join the observationMessage function into observationLogger to avoid this mempty. ConfigReadErrorObs usageErr -> "Failed to query database settings for the config parameters." <> jsonMessage usageErr QueryRoleSettingsErrorObs usageErr -> @@ -155,11 +157,14 @@ observationMessage = \case jsonMessage err = T.decodeUtf8 . LBS.toStrict . Error.errorPayload $ Error.PgError False err - showOnSingleLine txt = T.intercalate " " $ T.filter (/= '\t') <$> T.lines txt -- the errors from hasql-notifications come intercalated with "\t\n" showListenerConnError :: SQL.ConnectionError -> Text - showListenerConnError = maybe "Connection error" (showOnSingleLine . T.decodeUtf8) + showListenerConnError = maybe "Connection error" (showOnSingleLine '\t' . T.decodeUtf8) showListenerException :: Either SomeException () -> Text showListenerException (Right _) = "Failed getting notifications" -- should not happen as the listener will never finish (hasql-notifications uses `forever` internally) with a Right result - showListenerException (Left e) = showOnSingleLine $ show e + showListenerException (Left e) = showOnSingleLine '\t' $ show e + + +showOnSingleLine :: Char -> Text -> Text +showOnSingleLine split txt = T.intercalate " " $ T.filter (/= split) <$> T.lines txt -- the errors from hasql-notifications come intercalated with "\t\n" diff --git a/src/PostgREST/Query.hs b/src/PostgREST/Query.hs index c698107c7..378719007 100644 --- a/src/PostgREST/Query.hs +++ b/src/PostgREST/Query.hs @@ -7,13 +7,15 @@ Description : PostgREST query executor This module parametrizes, prepares, executes SQL queries and decodes their results. TODO: This module shouldn't depend on SchemaCache: once OpenAPI is removed, this can be done +TOOD: Split the SQL transaction concerns module into another one so Query.hs is pure -} module PostgREST.Query ( Query (..) , QueryResult (..) , ResultSet (..) - , query - , getSQLQuery + , mainTx + , mainQuery + , MainQuery (..) ) where import Control.Lens ((^?)) @@ -28,7 +30,6 @@ import qualified Hasql.Decoders as HD import qualified Hasql.DynamicStatements.Snippet as SQL hiding (sql) import qualified Hasql.DynamicStatements.Statement as SQL import qualified Hasql.Session as SQL (Session) -import qualified Hasql.Statement as SQL import qualified Hasql.Transaction as SQL import qualified Hasql.Transaction.Sessions as SQL @@ -73,7 +74,6 @@ 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 @@ -83,6 +83,16 @@ data QueryResult | MaybeDbResult InspectPlan (Maybe (TablesMap, RoutineMap, Maybe Text)) | NoDbResult InfoPlan +-- The Queries that run on every request +data MainQuery = MainQuery + { mqTxVars :: SQL.Snippet -- ^ the transaction variables that always run on each query + , mqPreReq :: Maybe SQL.Snippet -- ^ the pre-request function that runs if enabled + , mqCount :: SQL.Snippet -- ^ this count query is actually a fragment of the main query, but the same count query also runs after the main one in the case of `count=estimated`, so it's cached here. + -- TODO only one of the following queries actually runs on each request, once OpenAPI is removed from core it will be easier to refactor this + , mqMain :: SQL.Snippet + , mqOpenAPI :: (SQL.Snippet, SQL.Snippet, SQL.Snippet) + } + -- | Standard result set format used for all queries data ResultSet = RSStandard @@ -104,21 +114,21 @@ data ResultSet } | RSPlan BS.ByteString -- ^ the plan of the query -query :: AppConfig -> AuthResult -> ApiRequest -> ActionPlan -> SchemaCache -> Query -query _ _ _ (NoDb x) _ = NoDbQuery $ NoDbResult x -query conf@AppConfig{..} auth@AuthResult{..} apiReq (Db plan) sCache = - DbQuery isoLvl txMode dbHandler transaction mainSQLQuery +mainTx :: MainQuery -> AppConfig -> AuthResult -> ApiRequest -> ActionPlan -> SchemaCache -> Query +mainTx _ _ _ _ (NoDb x) _ = NoDbQuery $ NoDbResult x +mainTx genQ@MainQuery{..} conf@AppConfig{..} AuthResult{..} apiReq (Db plan) sCache = + DbQuery isoLvl txMode dbHandler transaction where transaction = if configDbPreparedStatements then SQL.transaction else SQL.unpreparedTransaction isoLvl = planIsoLvl conf authRole plan txMode = planTxMode plan - (mainActionQuery, mainSQLQuery) = actionQuery plan conf apiReq sCache + mainActionQuery = actionQuery genQ plan conf apiReq sCache dbHandler = do - lift $ SQL.statement mempty $ SQL.dynamicallyParameterized - (PreQuery.txVarQuery plan conf auth apiReq) - HD.noResult configDbPreparedStatements - lift $ whenJust configDbPreRequest $ \prereq -> do - SQL.statement mempty $ SQL.dynamicallyParameterized (PreQuery.preReqQuery prereq) HD.noResult configDbPreparedStatements + lift $ SQL.statement mempty $ SQL.dynamicallyParameterized mqTxVars + HD.noResult configDbPreparedStatements + lift $ whenJust mqPreReq $ \q -> + SQL.statement mempty $ SQL.dynamicallyParameterized q + HD.noResult configDbPreparedStatements mainActionQuery planTxMode :: DbActionPlan -> SQL.Mode @@ -133,32 +143,42 @@ planIsoLvl AppConfig{configRoleIsoLvl} role actPlan = case actPlan of where roleIsoLvl = HM.findWithDefault SQL.ReadCommitted role configRoleIsoLvl +mainQuery :: ActionPlan -> AppConfig -> ApiRequest -> AuthResult -> Maybe QualifiedIdentifier -> MainQuery +mainQuery (NoDb _) _ _ _ _ = MainQuery mempty Nothing mempty mempty (mempty, mempty, mempty) +mainQuery (Db plan) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} authRes preReq = + let genQ = MainQuery (PreQuery.txVarQuery plan conf authRes apiReq) (PreQuery.preReqQuery <$> preReq) in + case plan of + DbCrud WrappedReadPlan{..} -> + let countQuery = QueryBuilder.readPlanToCountQuery wrReadPlan in + genQ countQuery (Statements.mainRead wrReadPlan countQuery preferCount configDbMaxRows wrMedia wrHandler) (mempty, mempty, mempty) + DbCrud MutateReadPlan{..} -> + genQ mempty (Statements.mainWrite mrReadPlan mrMutatePlan mrMedia mrHandler preferRepresentation preferResolution) (mempty, mempty, mempty) + DbCall CallReadPlan{..} -> + genQ mempty (Statements.mainCall crProc crCallPlan crReadPlan preferCount crMedia crHandler) (mempty, mempty, mempty) + MayUseDb InspectPlan{ipSchema=tSchema} -> + genQ mempty mempty (SqlFragment.accessibleTables tSchema, SqlFragment.accessibleFuncs tSchema, SqlFragment.schemaDescription tSchema) + -- TODO: Generate the Hasql Statement in a diferent module after the OpenAPI functionality is removed -actionQuery :: DbActionPlan -> AppConfig -> ApiRequest -> SchemaCache -> (DbHandler QueryResult, ByteString) -actionQuery (DbCrud plan@WrappedReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} _ = - (mainActionQuery, mainSQLQuery) +actionQuery :: MainQuery -> DbActionPlan -> AppConfig -> ApiRequest -> SchemaCache -> DbHandler QueryResult +actionQuery MainQuery{..} (DbCrud plan@WrappedReadPlan{..}) conf@AppConfig{..} apiReq _ = + mainActionQuery where - countQuery = QueryBuilder.readPlanToCountQuery wrReadPlan - result@(SQL.Statement mainSQLQuery _ _ _) = SQL.dynamicallyParameterized - (Statements.mainRead wrReadPlan countQuery preferCount configDbMaxRows wrMedia wrHandler) - decodeIt configDbPreparedStatements + result = SQL.dynamicallyParameterized mqMain decodeIt configDbPreparedStatements mainActionQuery = do resultSet <- lift $ SQL.statement mempty result failNotSingular wrMedia resultSet optionalRollback conf apiReq - DbCrudResult plan <$> resultSetWTotal conf apiReq resultSet countQuery + DbCrudResult plan <$> resultSetWTotal conf apiReq resultSet mqCount decodeIt :: HD.Result ResultSet decodeIt = case wrMedia of MTVndPlan{} -> planRow _ -> HD.singleRow $ standardRow True -actionQuery (DbCrud plan@MutateReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} _ = - (mainActionQuery, mainSQLQuery) +actionQuery MainQuery{..} (DbCrud plan@MutateReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} _ = + mainActionQuery where - result@(SQL.Statement mainSQLQuery _ _ _) = SQL.dynamicallyParameterized - (Statements.mainWrite mrReadPlan mrMutatePlan mrMedia mrHandler preferRepresentation preferResolution) - decodeIt configDbPreparedStatements + result = SQL.dynamicallyParameterized mqMain decodeIt configDbPreparedStatements failMutation resultSet = case mrMutation of MutationCreate -> do failNotSingular mrMedia resultSet @@ -181,12 +201,10 @@ actionQuery (DbCrud plan@MutateReadPlan{..}) conf@AppConfig{..} apiReq@ApiReques MTVndPlan{} -> planRow _ -> fromMaybe (RSStandard Nothing 0 mempty mempty Nothing Nothing Nothing) <$> HD.rowMaybe (standardRow False) -actionQuery (DbCall plan@CallReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} _ = - (mainActionQuery, mainSQLQuery) +actionQuery MainQuery{..} (DbCall plan@CallReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{iPreferences=Preferences{..}} _ = + mainActionQuery where - result@(SQL.Statement mainSQLQuery _ _ _) = SQL.dynamicallyParameterized - (Statements.mainCall crProc crCallPlan crReadPlan preferCount crMedia crHandler) - decodeIt configDbPreparedStatements + result = SQL.dynamicallyParameterized mqMain decodeIt configDbPreparedStatements mainActionQuery = do resultSet <- lift $ SQL.statement mempty result @@ -200,15 +218,15 @@ actionQuery (DbCall plan@CallReadPlan{..}) conf@AppConfig{..} apiReq@ApiRequest{ MTVndPlan{} -> planRow _ -> fromMaybe (RSStandard (Just 0) 0 mempty mempty Nothing Nothing Nothing) <$> HD.rowMaybe (standardRow True) -actionQuery (MayUseDb plan@InspectPlan{ipSchema=tSchema}) AppConfig{..} _ sCache = - (mainActionQuery, mempty) +actionQuery MainQuery{mqOpenAPI=(tblsQ, funcsQ, schQ)} (MayUseDb plan@InspectPlan{ipSchema=tSchema}) AppConfig{..} _ sCache = + mainActionQuery where mainActionQuery = lift $ case configOpenApiMode of OAFollowPriv -> do - tableAccess <- SQL.statement mempty $ SQL.dynamicallyParameterized (SqlFragment.accessibleTables tSchema) decodeAccessibleIdentifiers configDbPreparedStatements - accFuncs <- SQL.statement mempty $ SQL.dynamicallyParameterized (SqlFragment.accessibleFuncs tSchema) SchemaCache.decodeFuncs configDbPreparedStatements - schDesc <- SQL.statement mempty $ SQL.dynamicallyParameterized (SqlFragment.schemaDescription tSchema) decodeSchemaDesc configDbPreparedStatements + tableAccess <- SQL.statement mempty $ SQL.dynamicallyParameterized tblsQ decodeAccessibleIdentifiers configDbPreparedStatements + accFuncs <- SQL.statement mempty $ SQL.dynamicallyParameterized funcsQ SchemaCache.decodeFuncs configDbPreparedStatements + schDesc <- SQL.statement mempty $ SQL.dynamicallyParameterized schQ decodeSchemaDesc configDbPreparedStatements let tbls = HM.filterWithKey (\qi _ -> S.member qi tableAccess) $ SchemaCache.dbTables sCache pure $ MaybeDbResult plan (Just (tbls, accFuncs, schDesc)) @@ -304,10 +322,6 @@ optionalRollback AppConfig{..} ApiRequest{iPreferences=Preferences{..}} = do shouldRollback = preferTransaction == Just Rollback -getSQLQuery :: Query -> ByteString -getSQLQuery DbQuery{dqSQL} = dqSQL -getSQLQuery _ = mempty - -- | We use rowList because when doing EXPLAIN (FORMAT TEXT), the result comes as many rows. FORMAT JSON comes as one. planRow :: HD.Result ResultSet planRow = RSPlan . BS.unlines <$> HD.rowList (column HD.bytea) diff --git a/src/PostgREST/Query/PreQuery.hs b/src/PostgREST/Query/PreQuery.hs index c839068a6..5587fdd08 100644 --- a/src/PostgREST/Query/PreQuery.hs +++ b/src/PostgREST/Query/PreQuery.hs @@ -16,10 +16,10 @@ import qualified Hasql.DynamicStatements.Snippet as SQL hiding (sql) -import PostgREST.Auth.Types (AuthResult (..)) import PostgREST.ApiRequest (ApiRequest (..)) import PostgREST.ApiRequest.Preferences (PreferTimezone (..), Preferences (..)) +import PostgREST.Auth.Types (AuthResult (..)) import PostgREST.Config (AppConfig (..)) import PostgREST.Plan (CallReadPlan (..), DbActionPlan (..)) diff --git a/test/io/test_io.py b/test/io/test_io.py index 8c2f44264..41ff522ef 100644 --- a/test/io/test_io.py +++ b/test/io/test_io.py @@ -1033,13 +1033,7 @@ def test_log_level(level, defaultenv): 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", - } + env = {**defaultenv, "PGRST_LOG_LEVEL": level, "PGRST_LOG_QUERY": "main-query"} with run(env=env) as postgrest: response = postgrest.session.get("/") @@ -1051,7 +1045,9 @@ def test_log_query(level, defaultenv): 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' + root_2xx_regx_ln1 = r".+: SELECT n.nspname AS table_schema, .+ FROM pg_class c .+ ORDER BY table_schema, table_name" + root_2xx_regx_ln2 = r".+: WITH base_types AS \(.+\) SELECT pn.nspname AS proc_schema, .+ FROM pg_proc p.+AND p.pronamespace = \$1::regnamespace" + root_2xx_regx_ln3 = r".+: SELECT pg_catalog\.obj_description\(\$1::regnamespace, 'pg_namespace'\)" get_2xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."projects"\.\* FROM "public"\."projects".+_postgrest_t' infinite_recursion_5xx_regx = r'.+: WITH pgrst_source AS.+SELECT "public"\."infinite_recursion"\.\* FROM "public"\."infinite_recursion".+_postgrest_t' @@ -1067,15 +1063,19 @@ def test_log_query(level, defaultenv): assert re.match(infinite_recursion_5xx_regx, output[1]) assert len(output) == 2 elif level == "info": - output = postgrest.read_stdout(nlines=6) - assert re.match(root_2xx_regx, output[0]) - assert re.match(get_2xx_regx, output[2]) - assert re.match(infinite_recursion_5xx_regx, output[5]) - assert len(output) == 6 + output = postgrest.read_stdout(nlines=8) + assert re.match(root_2xx_regx_ln1, output[0]) + assert re.match(root_2xx_regx_ln2, output[1]) + assert re.match(root_2xx_regx_ln3, output[2]) + assert re.match(get_2xx_regx, output[4]) + assert re.match(infinite_recursion_5xx_regx, output[7]) + assert len(output) == 8 elif level == "debug": - output_root = postgrest.read_stdout(nlines=6) - assert re.match(root_2xx_regx, output_root[4]) - assert len(output_root) == 6 + output_root = postgrest.read_stdout(nlines=8) + assert re.match(root_2xx_regx_ln1, output_root[4]) + assert re.match(root_2xx_regx_ln2, output_root[5]) + assert re.match(root_2xx_regx_ln3, output_root[6]) + assert len(output_root) == 8 output_get = postgrest.read_stdout(nlines=6) assert re.match(get_2xx_regx, output_get[4]) assert len(output_get) == 6