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

[steve-chavez]

For #3214.

The logs look like this (only for log-level=info):

14/Apr/2024:22:03:37 -0500: Starting PostgREST 12.1 (36ba330)...
14/Apr/2024:22:03:37 -0500: Attempting to connect to the database...
14/Apr/2024:22:03:37 -0500: Connection b63f8c6d-1423-4f7e-bd81-73ff25244033 is being established
14/Apr/2024:22:03:37 -0500: Connection b63f8c6d-1423-4f7e-bd81-73ff25244033 is available

...
14/Apr/2024:22:05:43 -0500: Connection b63f8c6d-1423-4f7e-bd81-73ff25244033 is terminated due to max idletime

...
14/Apr/2024:22:05:43 -0500: Connection f0813512-f4e6-4795-b156-ba140d2bc602 is being established
14/Apr/2024:22:05:43 -0500: Connection f0813512-f4e6-4795-b156-ba140d2bc602 is terminated due to network error

...
14/Apr/2024:21:47:44 -0500: Connection 63b40544-5a6d-4ec8-890a-c9c68f181e70 is terminated max lifetime

...
14/Apr/2024:21:50:33 -0500: Connection ad9b94c1-c6d7-4faa-bcc6-5edfb53d1119 is terminated due to release

Based on the new nikita-volkov/hasql-pool#40

[steve-chavez]

The existing io tests are hard to fix because the connection pool logs show everywhere when log-level=info:

FAILED test/io/test_io.py::test_pool_acquisition_timeout[info] - AssertionError: assert ' 504 ' in '14/Apr/2024:22:12:55 -0500: Connection f2b3a3b8-1de4-477a-89b8-26418a776539 is used\n'
FAILED test/io/test_io.py::test_log_level[info-has_output0] - assert None
FAILED test/io/test_io.py::test_db_error_logging_to_stderr[info] - AssertionError: assert ' 500 ' in '14/Apr/2024:22:13:20 -0500: Connection ce746d16-b53f-4c94-9b5a-fdcfc347d930 is available\n'

Tempted to just create a new debug level to avoid modifying those tests. . Will try fixing in the morning.

[steve-chavez]

stack is always a pain to update.

cabal.project.freeze is also a problem as I've no idea where to search for index states. It was introduced on #3004. I'm tempted to remove it. Edit: will open an issue for it.

[wolfgangwalther]

cabal.project.freeze is also a problem as I've no idea where to search for index states.

Just set it to the current timestamp. Then run cabal - it will tell you which index state it will fall back to. You can either keep your current timestamp or use that fallback to avoid the warning.

[taimoorzaeem]

@steve-chavez postgrest-build failing after this. See:

Error: cabal: Could not resolve dependencies:
[__0] trying: postgrest-12.1 (user goal)
[__1] next goal: hasql-pool (dependency of postgrest)
[__1] rejecting: hasql-pool-0.10/installed-5MlhXuVQq8PFeKDYospHAG (conflict:
postgrest => hasql-pool>=1.0.1 && <1.1)
[__1] skipping: hasql-pool-0.10.0.1, hasql-pool-0.10, hasql-pool-0.9.0.1,
hasql-pool-0.9, hasql-pool-0.8.0.7, hasql-pool-0.8.0.6, hasql-pool-0.8.0.5,
hasql-pool-0.8.0.4, hasql-pool-0.8.0.3, hasql-pool-0.8.0.2,
hasql-pool-0.8.0.1, hasql-pool-0.8, hasql-pool-0.7.2.1, hasql-pool-0.7.2,
hasql-pool-0.7.1.3, hasql-pool-0.7.1.2, hasql-pool-0.7.1.1, hasql-pool-0.7.1,
hasql-pool-0.7, hasql-pool-0.6.0.1, hasql-pool-0.6, hasql-pool-0.5.2.2,
hasql-pool-0.5.2, hasql-pool-0.5.1, hasql-pool-0.5.0.2, hasql-pool-0.5.0.1,
hasql-pool-0.5, hasql-pool-0.4.3.1, hasql-pool-0.4.3, hasql-pool-0.4.2.1,
hasql-pool-0.4.2, hasql-pool-0.4.1, hasql-pool-0.4, hasql-pool-0.3,
hasql-pool-0.1, hasql-pool-0.5.2.1 (has the same characteristics that caused
the previous version to fail: excluded by constraint '>=1.0.1 && <1.1' from
'postgrest')
[__1] fail (backjumping, conflict set: hasql-pool, postgrest)
After searching the rest of the dependency tree exhaustively, these were the
goals I've had most trouble fulfilling: postgrest, hasql-pool

I have tried postgrest-clean but no luck. Do I need to update? If yes how so?

[steve-chavez]

@taimoorzaeem Have you tried going in and out of nix-shell?

@laurenceisla Can you reproduce?

[laurenceisla]

@steve-chavez

No problems for me. Logging in and out of nix-shell should do it.

[taimoorzaeem]

Thanks. Going in and out of nix-shell fixed it.