jimmy/postgrest
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

feat: log connection pool events on log-level=info

Browse Source
This commit is contained in:
steve-chavez
2024-04-15 18:31:51 -05:00
committed by Steve Chavez
parent 9d1dc783bf
commit 1bf0c54dd6
11 changed files with 93 additions and 45 deletions
Download Patch File Download Diff File Expand all files Collapse all files
CHANGELOG.md
+1
View File
@@ -13,6 +13,7 @@ This project adheres to [Semantic Versioning](http://semver.org/).
- #3171, #3046, Log schema cache stats to stderr - @steve-chavez
- #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
### Fixed
cabal.project.freeze
+1 -1
View File
@@ -1 +1 @@
index-state: hackage.haskell.org 2024-03-13T22:43:26Z
index-state: hackage.haskell.org 2024-04-15T20:28:44Z
nix/overlays/haskell-packages.nix
+18 -7
View File
@@ -35,11 +35,14 @@ let
# - <subpath> is usually "."
# - When adding a new library version here, postgrest.cabal and stack.yaml must also be updated
#
# Note:
# Notes:
# - This should NOT be the first place to start managing dependencies. Check postgrest.cabal.
# - When adding a new package version here, you have to update stack:
# + For stack.yml add:
# extra-deps:
# - <package>-<ver>
# + For stack.yml.lock, CI should report an error with the correct lock, copy/paste that one into the file
# - To modify and try packages locally, see "Working with locally modified Haskell packages" in the Nix README.
#
configurator-pg =
prev.callHackageDirect
@@ -60,18 +63,26 @@ let
}
{ };
hasql-pool =
lib.dontCheck (prev.callHackageDirect
{
pkg = "hasql-pool";
ver = "1.0.1";
sha256 = "sha256-Hf1f7lX0LWkjrb25SDBovCYPRdmUP1H6pAxzi7kT4Gg=";
}
{ }
);
postgresql-libpq = lib.dontCheck
(prev.postgresql-libpq_0_10_0_0.override {
postgresql = super.libpq;
});
hasql-pool = lib.dontCheck prev.hasql-pool_0_10;
hasql-notifications = lib.dontCheck (prev.callHackageDirect
{
pkg = "hasql-notifications";
ver = "0.2.1.0";
sha256 = "sha256-MEIirDKR81KpiBOnWJbVInWevL6Kdb/XD1Qtd8e6KsQ=";
ver = "0.2.1.1";
sha256 = "sha256-oPhKA/pSQGJvgQyhsi7CVr9iDT7uWpKUz0iJfXsaxXo=";
}
{ }
);
postgrest.cabal
+3 -3
View File
@@ -108,8 +108,8 @@ library
, gitrev >= 1.2 && < 1.4
, hasql >= 1.6.1.1 && < 1.7
, hasql-dynamic-statements >= 0.3.1 && < 0.4
, hasql-notifications >= 0.2.1.0 && < 0.3
, hasql-pool >= 0.10 && < 0.11
, hasql-notifications >= 0.2.1.1 && < 0.3
, hasql-pool >= 1.0.1 && < 1.1
, hasql-transaction >= 1.0.1 && < 1.1
, heredoc >= 0.2 && < 0.3
, http-types >= 0.12.2 && < 0.13
@@ -254,7 +254,7 @@ test-suite spec
, bytestring >= 0.10.8 && < 0.13
, case-insensitive >= 1.2 && < 1.3
, containers >= 0.5.7 && < 0.7
, hasql-pool >= 0.10 && < 0.11
, hasql-pool >= 1.0.1 && < 1.1
, hasql-transaction >= 1.0.1 && < 1.1
, heredoc >= 0.2 && < 0.3
, hspec >= 2.3 && < 2.12
src/PostgREST/AppState.hs
+12 -9
View File
@@ -39,6 +39,7 @@ import qualified Data.Text as T (unpack)
import Hasql.Connection (acquire)
import qualified Hasql.Notifications as SQL
import qualified Hasql.Pool as SQL
import qualified Hasql.Pool.Config as SQL
import qualified Hasql.Session as SQL
import qualified Hasql.Transaction.Sessions as SQL
import qualified Network.HTTP.Types.Status as HTTP
@@ -122,7 +123,7 @@ init :: AppConfig -> IO AppState
init conf@AppConfig{configLogLevel} = do
loggerState <- Logger.init
let observer = Logger.observationLogger loggerState configLogLevel
pool <- initPool conf
pool <- initPool conf observer
(sock, adminSock) <- initSockets conf
state' <- initWithPool (sock, adminSock) pool conf loggerState observer
pure state' { stateSocketREST = sock, stateSocketAdmin = adminSock}
@@ -193,14 +194,16 @@ initSockets AppConfig{..} = do
pure (sock, adminSock)
initPool :: AppConfig -> IO SQL.Pool
initPool AppConfig{..} =
SQL.acquire
configDbPoolSize
(fromIntegral configDbPoolAcquisitionTimeout)
(fromIntegral configDbPoolMaxLifetime)
(fromIntegral configDbPoolMaxIdletime)
(toUtf8 $ addFallbackAppName prettyVersion configDbUri)
initPool :: AppConfig -> ObservationHandler -> IO SQL.Pool
initPool AppConfig{..} observer =
SQL.acquire $ SQL.settings
[ SQL.size configDbPoolSize
, SQL.acquisitionTimeout $ fromIntegral configDbPoolAcquisitionTimeout
, SQL.agingTimeout $ fromIntegral configDbPoolMaxLifetime
, SQL.idlenessTimeout $ fromIntegral configDbPoolMaxIdletime
, SQL.staticConnectionSettings (toUtf8 $ addFallbackAppName prettyVersion configDbUri)
, SQL.observationHandler $ observer . HasqlPoolObs
]
-- | Run an action with a database connection.
usePool :: AppState -> SQL.Session a -> IO (Either SQL.UsageError a)
src/PostgREST/Logger.hs
+3
View File
@@ -81,6 +81,9 @@ observationLogger loggerState logLevel obs = case obs of
o@(QueryErrorCodeHighObs _) -> do
when (logLevel >= LogError) $ do
logWithZTime loggerState $ observationMessage o
o@(HasqlPoolObs _) -> do
when (logLevel >= LogInfo) $ do
logWithZTime loggerState $ observationMessage o
o ->
logWithZTime loggerState $ observationMessage o
src/PostgREST/Observation.hs
+22 -8
View File
@@ -9,14 +9,15 @@ module PostgREST.Observation
, ObservationHandler
) where
import qualified Data.ByteString.Lazy as LBS
import qualified Data.Text as T
import qualified Data.Text.Encoding as T
import qualified Hasql.Connection as SQL
import qualified Hasql.Pool as SQL
import qualified Network.Socket as NS
import Numeric (showFFloat)
import qualified PostgREST.Error as Error
import qualified Data.ByteString.Lazy as LBS
import qualified Data.Text as T
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 qualified Network.Socket as NS
import Numeric (showFFloat)
import qualified PostgREST.Error as Error
import Protolude
import Protolude.Partial (fromJust)
@@ -50,6 +51,7 @@ data Observation
| QueryRoleSettingsErrorObs SQL.UsageError
| QueryErrorCodeHighObs SQL.UsageError
| PoolAcqTimeoutObs SQL.UsageError
| HasqlPoolObs SQL.Observation
type ObservationHandler = Observation -> IO ()
@@ -111,6 +113,18 @@ observationMessage = \case
"Config reloaded"
PoolAcqTimeoutObs usageErr ->
jsonMessage usageErr
HasqlPoolObs (SQL.ConnectionObservation uuid status) ->
"Connection " <> show uuid <> (
case status of
SQL.ConnectingConnectionStatus -> " is being established"
SQL.ReadyForUseConnectionStatus -> " is available"
SQL.InUseConnectionStatus -> " is used"
SQL.TerminatedConnectionStatus reason -> " is terminated due to " <> case reason of
SQL.AgingConnectionTerminationReason -> "max lifetime"
SQL.IdlenessConnectionTerminationReason -> "max idletime"
SQL.ReleaseConnectionTerminationReason -> "release"
SQL.NetworkErrorConnectionTerminationReason _ -> "network error" -- usage error is already logged, no need to repeat the same message.
)
where
showMillis :: Double -> Text
showMillis x = toS $ showFFloat (Just 1) (x * 1000) ""
stack.yaml
+2 -2
View File
@@ -12,7 +12,7 @@ nix:
extra-deps:
- configurator-pg-0.2.7
- fuzzyset-0.2.4
- hasql-notifications-0.2.1.0
- hasql-pool-0.10
- hasql-notifications-0.2.1.1
- hasql-pool-1.0.1
- megaparsec-9.2.2
- postgresql-libpq-0.10.0.0
stack.yaml.lock
+7 -7
View File
@@ -19,19 +19,19 @@ packages:
original:
hackage: fuzzyset-0.2.4
- completed:
hackage: hasql-notifications-0.2.1.0@sha256:c9c0ba3ac0866142836d2d0a08a0d10a945bcbe1c163ee1ef6aed407d046a24e,2022
hackage: hasql-notifications-0.2.1.1@sha256:e4f41f462e96f3af3f088b747daeeb2275ceaebd0e4b0d05187bd10d329afada,2021
pantry-tree:
sha256: 65a646ed0a77ee1dfe902faedc590103ee385eaa78f407c4cf02a1eb5783d464
sha256: f9041b1c242436324372f6be9a4f2e5cf70203c3efad36a4e9ea4cca5113a2ec
size: 452
original:
hackage: hasql-notifications-0.2.1.0
hackage: hasql-notifications-0.2.1.1
- completed:
hackage: hasql-pool-0.10@sha256:912197a328acb85505f98bb9700d61f366b87659ca45126c5c2d636687b801c3,2112
hackage: hasql-pool-1.0.1@sha256:3cfb4c7153a6c536ac7e126c17723e6d26ee03794954deed2d72bcc826d05a40,2302
pantry-tree:
sha256: b655c540a49764a8d16b62941137e295b936b96edc0785eb9250972f0f92dc47
size: 346
sha256: d98e1269bdd60989b0eb0b84e1d5357eaa9f92821439d9f206663b7251ee95b2
size: 799
original:
hackage: hasql-pool-0.10
hackage: hasql-pool-1.0.1
- completed:
hackage: megaparsec-9.2.2@sha256:c306a135ec25d91d252032c6128f03598a00e87ea12fcf5fc4878fdffc75c768,3219
pantry-tree:
test/io/test_io.py
+16 -7
View File
@@ -593,13 +593,13 @@ def test_pool_acquisition_timeout(level, defaultenv, metapostgrest):
assert data["message"] == "Timed out acquiring connection from connection pool."
# ensure the message appears on the logs as well
output = sorted(postgrest.read_stdout(nlines=2))
output = sorted(postgrest.read_stdout(nlines=3))
if level == "crit":
assert len(output) == 0
else:
elif level == "info":
assert " 504 " in output[0]
assert "Timed out acquiring connection from connection pool." in output[1]
assert "Timed out acquiring connection from connection pool." in output[2]
def test_change_statement_timeout_held_connection(defaultenv, metapostgrest):
@@ -792,7 +792,7 @@ def test_log_level(level, defaultenv):
response = postgrest.session.get("/")
assert response.status_code == 200
output = sorted(postgrest.read_stdout(nlines=3))
output = sorted(postgrest.read_stdout(nlines=7))
if level == "crit":
assert len(output) == 0
@@ -825,7 +825,11 @@ def test_log_level(level, defaultenv):
r'- - postgrest_test_anonymous \[.+\] "GET /unknown HTTP/1.1" 404 - "" "python-requests/.+"',
output[2],
)
assert len(output) == 3
assert "Connection" and "is available" in output[3]
assert "Connection" and "is available" in output[4]
assert "Connection" and "is used" in output[5]
assert "Connection" and "is used" in output[6]
assert len(output) == 7
def test_no_pool_connection_required_on_bad_http_logic(defaultenv):
@@ -1083,12 +1087,14 @@ def test_get_pgrst_version_with_keyval_connection_string(defaultenv):
def test_log_postgrest_version(defaultenv):
"Should show the PostgREST version in the logs"
env = {**defaultenv, "PGRST_LOG_LEVEL": "crit"}
with run(env=defaultenv, no_startup_stdout=False) as postgrest:
version = postgrest.session.head("/").headers["Server"].split("/")[1]
output = sorted(postgrest.read_stdout(nlines=5))
assert "Starting PostgREST %s..." % version in output[3]
assert "Starting PostgREST %s..." % version in output[4]
def test_succeed_w_role_having_superuser_settings(defaultenv):
@@ -1371,10 +1377,13 @@ def test_db_error_logging_to_stderr(level, defaultenv, metapostgrest):
assert response.status_code == 500
# ensure the message appears on the logs
output = sorted(postgrest.read_stdout(nlines=2))
output = sorted(postgrest.read_stdout(nlines=4))
if level == "crit":
assert len(output) == 0
elif level == "info":
assert " 500 " in output[0]
assert "canceling statement due to statement timeout" in output[3]
else:
assert " 500 " in output[0]
assert "canceling statement due to statement timeout" in output[1]
test/spec/Main.hs
+8 -1
View File
@@ -1,6 +1,7 @@
module Main where
import qualified Hasql.Pool as P
import qualified Hasql.Pool.Config as P
import qualified Hasql.Transaction.Sessions as HT
import Data.Function (id)
@@ -70,7 +71,13 @@ import qualified Feature.RpcPreRequestGucsSpec
main :: IO ()
main = do
let observer = const $ pure ()
pool <- P.acquire 3 10 60 60 $ toUtf8 $ configDbUri testCfg
pool <- P.acquire $ P.settings
[ P.size 3
, P.acquisitionTimeout 10
, P.agingTimeout 60
, P.idlenessTimeout 60
, P.staticConnectionSettings (toUtf8 $ configDbUri testCfg)
]
actualPgVersion <- either (panic . show) id <$> P.use pool (queryPgVersion False)