feat: add log-level=debug

Author: steve-chavez

CHANGELOG.md

@@ -14,6 +14,7 @@ This project adheres to [Semantic Versioning](http://semver.org/).
  - #3210, Dump schema cache through admin API - @taimoorzaeem
  - #2676, Performance improvement on bulk json inserts, around 10% increase on requests per second by removing `json_typeof` from write queries - @steve-chavez
  - #3214, Log connection pool events on log-level=info - @steve-chavez
+ - #3435, Add log-level=debug, for development purposes - @steve-chavez
 
 ### Fixed
 

docs/references/configuration.rst

@@ -680,6 +680,8 @@ log-level
       # All the "warn" level events plus all requests (every status code) are logged
       log-level = "info"
 
+      # All the above plus events for development purposes are logged
+      log-level = "debug"
 
   Because currently there's no buffering for logging, the levels with minimal logging(``crit/error``) will increase throughput.
 

src/PostgREST/CLI.hs

@@ -203,7 +203,7 @@ exampleConfigFile =
       |## Enables and set JWT Cache max lifetime, disables caching with 0
       |# jwt-cache-max-lifetime = 0
       |
-      |## Logging level, the admitted values are: crit, error, warn and info.
+      |## Logging level, the admitted values are: crit, error, warn, info and debug.
       |log-level = "error"
       |
       |## Determine if the OpenAPI output should follow or ignore role privileges or be disabled entirely.

src/PostgREST/Config.hs

@@ -114,7 +114,7 @@ data AppConfig = AppConfig
   , configInternalSCSleep          :: Maybe Int32
   }
 
-data LogLevel = LogCrit | LogError | LogWarn | LogInfo
+data LogLevel = LogCrit | LogError | LogWarn | LogInfo | LogDebug
   deriving (Eq, Ord)
 
 dumpLogLevel :: LogLevel -> Text
@@ -123,6 +123,7 @@ dumpLogLevel = \case
   LogError -> "error"
   LogWarn  -> "warn"
   LogInfo  -> "info"
+  LogDebug -> "debug"
 
 data OpenAPIMode = OAFollowPriv | OAIgnorePriv | OADisabled
   deriving Eq
@@ -338,6 +339,7 @@ parser optPath env dbSettings roleSettings roleIsolationLvl =
         Just "error" -> pure LogError
         Just "warn"  -> pure LogWarn
         Just "info"  -> pure LogInfo
+        Just "debug" -> pure LogDebug
         Just _       -> fail "Invalid logging level. Check your configuration."
 
     parseTxEnd :: C.Key -> ((Bool, Bool) -> Bool) -> C.Parser C.Config Bool

src/PostgREST/Logger.hs

@@ -56,10 +56,11 @@ logWithDebounce loggerState action = do
 
 middleware :: LogLevel -> (Wai.Request -> Maybe BS.ByteString) -> Wai.Middleware
 middleware logLevel getAuthRole = case logLevel of
-  LogInfo  -> requestLogger (const True)
-  LogWarn  -> requestLogger (>= status400)
-  LogError -> requestLogger (>= status500)
   LogCrit  -> requestLogger (const False)
+  LogError -> requestLogger (>= status500)
+  LogWarn  -> requestLogger (>= status400)
+  LogInfo  -> requestLogger (const True)
+  LogDebug -> requestLogger (const True)
   where
     requestLogger filterStatus = unsafePerformIO $
       Wai.mkRequestLogger Wai.defaultRequestLoggerSettings
@@ -84,6 +85,9 @@ observationLogger loggerState logLevel obs = case obs of
   o@(HasqlPoolObs _) -> do
     when (logLevel >= LogInfo) $ do
       logWithZTime loggerState $ observationMessage o
+  o@(SchemaCacheLoadedObs _) -> do
+    when (logLevel >= LogDebug) $ do
+      logWithZTime loggerState $ observationMessage o
   o ->
     logWithZTime loggerState $ observationMessage o
 

test/io/test_io.py

@@ -575,7 +575,7 @@ def sleep(i=i):
         assert delta > 1 and delta < 1.5
 
 
-@pytest.mark.parametrize("level", ["crit", "error", "warn", "info"])
+@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"])
 def test_pool_acquisition_timeout(level, defaultenv, metapostgrest):
     "Verify that PGRST_DB_POOL_ACQUISITION_TIMEOUT times out when the pool is empty"
 
@@ -597,7 +597,7 @@ def test_pool_acquisition_timeout(level, defaultenv, metapostgrest):
 
         if level == "crit":
             assert len(output) == 0
-        elif level == "info":
+        elif level in ["info", "debug"]:
             assert " 504 " in output[0]
             assert "Timed out acquiring connection from connection pool." in output[2]
 
@@ -772,7 +772,7 @@ def test_admin_works_with_host_special_values(specialhostvalue, defaultenv):
         assert response.status_code == 200
 
 
-@pytest.mark.parametrize("level", ["crit", "error", "warn", "info"])
+@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"])
 def test_log_level(level, defaultenv):
     "log_level should filter request logging"
 
@@ -1358,7 +1358,7 @@ def test_no_preflight_request_with_CORS_config_should_not_return_header(defaulte
         assert "Access-Control-Allow-Origin" not in response.headers
 
 
-@pytest.mark.parametrize("level", ["crit", "error", "warn", "info"])
+@pytest.mark.parametrize("level", ["crit", "error", "warn", "info", "debug"])
 def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest):
     "verify that DB errors are logged to stderr"
 
@@ -1381,7 +1381,7 @@ def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest):
 
         if level == "crit":
             assert len(output) == 0
-        elif level == "info":
+        elif level in ["info", "debug"]:
             assert " 500 " in output[0]
             assert "canceling statement due to statement timeout" in output[3]
         else: