Skip to content

Commit 514d1a5

Browse files
jfrochejfroche
authored
refactor: improve test harness logging and error handling (#1834)
* refactor: improve test harness logging and error handling Integrate bashlog framework throughout the test harness to provide better visibility and debuggability: - Add log_cmd function to capture command execution, stdout, and stderr to debug.log - Replace raw echo statements with structured log info/error/debug calls - Extract check_postgres_ready function to eliminate code duplication - Improve error handling with proper trap handling via on_exit function - Show debug logs only on test failures to reduce noise - Switch from 'set -e' to 'set -uo pipefail' for better error control * refactor: convert postgres check harness from runCommand to writeShellApplication Migrate test harness to use writeShellApplication for better shell script handling, fix shellcheck warnings.
1 parent 52deb6f commit 514d1a5

File tree

1 file changed

+145
-94
lines changed

1 file changed

+145
-94
lines changed

‎nix/checks.nix‎

Lines changed: 145 additions & 94 deletions
Original file line numberDiff line numberDiff line change
@@ -15,6 +15,10 @@
1515
psql_orioledb-17 = self'.packages."psql_orioledb-17/bin";
1616
inherit (self.supabase) defaults;
1717
};
18+
bashlog = builtins.fetchurl {
19+
url = "https://raw.githubusercontent.com/Zordrak/bashlog/master/log.sh";
20+
sha256 = "1vrjcbzls0ba2qkg7ffddz2gxqn2rlj3wyvril2gz0mfi89y9vk9";
21+
};
1822
in
1923
{
2024
checks =
@@ -151,51 +155,102 @@
151155
) filteredSqlTests;
152156
sortedTestList = builtins.sort (a: b: a < b) testList;
153157
in
154-
pkgs.runCommand "postgres-${pgpkg.version}-check-harness"
155-
{
156-
nativeBuildInputs = with pkgs; [
157-
coreutils
158-
bash
159-
perl
160-
pgpkg
161-
pg_prove
162-
pg_regress
163-
procps
164-
start-postgres-server-bin
165-
which
166-
getkey-script
167-
supabase-groonga
168-
python3
169-
netcat
170-
];
171-
}
172-
''
173-
set -e
158+
pkgs.writeShellApplication rec {
159+
name = "postgres-${pgpkg.version}-check-harness";
160+
bashOptions = [
161+
"nounset"
162+
"pipefail"
163+
];
164+
runtimeInputs = with pkgs; [
165+
coreutils
166+
bash
167+
perl
168+
pgpkg
169+
pg_prove
170+
pg_regress
171+
procps
172+
start-postgres-server-bin
173+
which
174+
getkey-script
175+
supabase-groonga
176+
python3
177+
netcat
178+
];
174179

175-
# Start HTTP mock server for http extension tests
180+
text = ''
181+
182+
#shellcheck disable=SC1091
183+
source ${bashlog}
184+
#shellcheck disable=SC1091
185+
source ${pkgs.stdenv}/setup
186+
export PATH="${lib.makeBinPath runtimeInputs}:$PATH"
187+
188+
export BASHLOG_FILE=1
189+
export BASHLOG_FILE_PATH=debug.log
176190
# Use a build-specific directory for coordination
177191
BUILD_TMP=$(mktemp -d)
192+
193+
# Function to log command execution with stdout and stderr
194+
function log_cmd {
195+
local cmd_name="$1"
196+
shift
197+
log debug "Executing: $cmd_name $*"
198+
local exit_code=0
199+
echo "\$ $cmd_name $*" >> debug.log
200+
201+
"$cmd_name" "$@" >> debug.log 2>&1 || exit_code=$?
202+
log debug "Exit code: $exit_code"
203+
return $exit_code
204+
}
205+
206+
function on_exit {
207+
local exit_code=$?
208+
kill $HTTP_MOCK_PID 2>/dev/null || true
209+
rm -rf "$BUILD_TMP"
210+
if [ $exit_code -ne 0 ]; then
211+
log error "An error occurred. Exit code: $exit_code"
212+
log error "Debug logs:"
213+
cat debug.log || log error "No debug.log file found"
214+
fi
215+
}
216+
trap on_exit EXIT
217+
trap "" DEBUG
218+
219+
function check_postgres_ready {
220+
for i in {1..60}; do
221+
if log_cmd pg_isready -h localhost -p ${pgPort} -U supabase_admin -q; then
222+
log info "PostgreSQL is ready"
223+
break
224+
fi
225+
sleep 1
226+
if [ "$i" -eq 60 ]; then
227+
log error "PostgreSQL failed to start"
228+
exit 1
229+
fi
230+
done
231+
}
232+
233+
# Start HTTP mock server for http extension tests
178234
HTTP_MOCK_PORT_FILE="$BUILD_TMP/http-mock-port"
179235
180-
echo "Starting HTTP mock server (will find free port)..."
181-
HTTP_MOCK_PORT_FILE="$HTTP_MOCK_PORT_FILE" ${pkgs.python3}/bin/python3 ${./tests/http-mock-server.py} &
236+
log info "Starting HTTP mock server (will find free port)..."
237+
HTTP_MOCK_PORT_FILE="$HTTP_MOCK_PORT_FILE" log_cmd ${pkgs.python3}/bin/python3 ${./tests/http-mock-server.py} &
182238
HTTP_MOCK_PID=$!
183239
184240
# Clean up on exit
185-
trap "kill $HTTP_MOCK_PID 2>/dev/null || true; rm -rf '$BUILD_TMP'" EXIT
186241
187242
# Wait for server to start and write port file
188243
for i in {1..10}; do
189244
if [ -f "$HTTP_MOCK_PORT_FILE" ]; then
190245
HTTP_MOCK_PORT=$(cat "$HTTP_MOCK_PORT_FILE")
191-
echo "HTTP mock server started on port $HTTP_MOCK_PORT"
246+
log info "HTTP mock server started on port $HTTP_MOCK_PORT"
192247
break
193248
fi
194249
sleep 1
195250
done
196251
197252
if [ ! -f "$HTTP_MOCK_PORT_FILE" ]; then
198-
echo "Failed to start HTTP mock server"
253+
log error "Failed to start HTTP mock server"
199254
exit 1
200255
fi
201256
@@ -205,139 +260,135 @@
205260
#First we need to create a generic pg cluster for pgtap tests and run those
206261
export GRN_PLUGINS_DIR=${pkgs.supabase-groonga}/lib/groonga/plugins
207262
PGTAP_CLUSTER=$(mktemp -d)
208-
initdb --locale=C --username=supabase_admin -D "$PGTAP_CLUSTER"
263+
log info "Creating temporary PostgreSQL cluster at $PGTAP_CLUSTER"
264+
log_cmd initdb --locale=C --username=supabase_admin -D "$PGTAP_CLUSTER"
209265
substitute ${./tests/postgresql.conf.in} "$PGTAP_CLUSTER"/postgresql.conf \
210266
--subst-var-by PGSODIUM_GETKEY_SCRIPT "${getkey-script}/bin/pgsodium-getkey"
211-
echo "listen_addresses = '*'" >> "$PGTAP_CLUSTER"/postgresql.conf
267+
echo "listen_addresses = '127.0.0.1'" >> "$PGTAP_CLUSTER"/postgresql.conf
212268
echo "port = ${pgPort}" >> "$PGTAP_CLUSTER"/postgresql.conf
213-
echo "host all all 127.0.0.1/32 trust" >> $PGTAP_CLUSTER/pg_hba.conf
214-
echo "Checking shared_preload_libraries setting:"
215-
grep -rn "shared_preload_libraries" "$PGTAP_CLUSTER"/postgresql.conf
269+
echo "host all all 127.0.0.1/32 trust" >> "$PGTAP_CLUSTER/pg_hba.conf"
270+
log info "Checking shared_preload_libraries setting:"
271+
log info "$(grep -rn "shared_preload_libraries" "$PGTAP_CLUSTER"/postgresql.conf)"
216272
# Remove timescaledb if running orioledb-17 check
217-
echo "I AM ${pgpkg.version}===================================================="
273+
log info "pgpkg.version is: ${pgpkg.version}"
274+
#shellcheck disable=SC2193
218275
if [[ "${pgpkg.version}" == *"17"* ]]; then
219276
perl -pi -e 's/ timescaledb,//g' "$PGTAP_CLUSTER/postgresql.conf"
220277
fi
221278
#NOTE in the future we may also need to add the orioledb extension to the cluster when cluster is oriole
222-
echo "PGTAP_CLUSTER directory contents:"
223-
ls -la "$PGTAP_CLUSTER"
224279
225280
# Check if postgresql.conf exists
226281
if [ ! -f "$PGTAP_CLUSTER/postgresql.conf" ]; then
227-
echo "postgresql.conf is missing!"
282+
log error "postgresql.conf is missing!"
228283
exit 1
229284
fi
230285
231286
# PostgreSQL startup
232287
if [[ "$(uname)" == "Darwin" ]]; then
233-
pg_ctl -D "$PGTAP_CLUSTER" -l "$PGTAP_CLUSTER"/postgresql.log -o "-k "$PGTAP_CLUSTER" -p ${pgPort} -d 5" start 2>&1
288+
log_cmd pg_ctl -D "$PGTAP_CLUSTER" -l "$PGTAP_CLUSTER/postgresql.log" -o "-k $PGTAP_CLUSTER -p ${pgPort} -d 5" start
234289
else
235290
mkdir -p "$PGTAP_CLUSTER/sockets"
236-
pg_ctl -D "$PGTAP_CLUSTER" -l "$PGTAP_CLUSTER"/postgresql.log -o "-k $PGTAP_CLUSTER/sockets -p ${pgPort} -d 5" start 2>&1
291+
log_cmd pg_ctl -D "$PGTAP_CLUSTER" -l "$PGTAP_CLUSTER/postgresql.log" -o "-k $PGTAP_CLUSTER/sockets -p ${pgPort} -d 5" start
237292
fi || {
238-
echo "pg_ctl failed to start PostgreSQL"
239-
echo "Contents of postgresql.log:"
293+
log error "pg_ctl failed to start PostgreSQL"
294+
log error "Contents of postgresql.log:"
240295
cat "$PGTAP_CLUSTER"/postgresql.log
241296
exit 1
242297
}
243-
for i in {1..60}; do
244-
if pg_isready -h ${self.supabase.defaults.host} -p ${pgPort}; then
245-
echo "PostgreSQL is ready"
246-
break
247-
fi
248-
sleep 1
249-
if [ $i -eq 60 ]; then
250-
echo "PostgreSQL is not ready after 60 seconds"
251-
echo "PostgreSQL status:"
252-
pg_ctl -D "$PGTAP_CLUSTER" status
253-
echo "PostgreSQL log content:"
254-
cat "$PGTAP_CLUSTER"/postgresql.log
255-
exit 1
256-
fi
257-
done
258-
createdb -p ${pgPort} -h ${self.supabase.defaults.host} --username=supabase_admin testing
259-
if ! psql -p ${pgPort} -h ${self.supabase.defaults.host} --username=supabase_admin -d testing -v ON_ERROR_STOP=1 -Xf ${./tests/prime.sql}; then
260-
echo "Error executing SQL file. PostgreSQL log content:"
298+
299+
log info "Waiting for PostgreSQL to be ready..."
300+
check_postgres_ready
301+
302+
log info "Creating test database"
303+
log_cmd createdb -p ${pgPort} -h localhost --username=supabase_admin testing
304+
305+
log info "Loading prime SQL file"
306+
if ! log_cmd psql -p ${pgPort} -h localhost --username=supabase_admin -d testing -v ON_ERROR_STOP=1 -Xf ${./tests/prime.sql}; then
307+
log error "Error executing SQL file. PostgreSQL log content:"
261308
cat "$PGTAP_CLUSTER"/postgresql.log
262309
pg_ctl -D "$PGTAP_CLUSTER" stop
263310
exit 1
264311
fi
265312
266313
# Create a table to store test configuration
267-
psql -p ${pgPort} -h ${self.supabase.defaults.host} --username=supabase_admin -d testing -c "
314+
log info "Creating test_config table"
315+
log_cmd psql -p ${pgPort} -h localhost --username=supabase_admin -d testing -c "
268316
CREATE TABLE IF NOT EXISTS test_config (key TEXT PRIMARY KEY, value TEXT);
269317
INSERT INTO test_config (key, value) VALUES ('http_mock_port', '$HTTP_MOCK_PORT')
270318
ON CONFLICT (key) DO UPDATE SET value = EXCLUDED.value;
271319
"
272320
SORTED_DIR=$(mktemp -d)
273321
for t in $(printf "%s\n" ${builtins.concatStringsSep " " sortedTestList}); do
274-
psql -p ${pgPort} -h ${self.supabase.defaults.host} --username=supabase_admin -d testing -f "${./tests/sql}/$t.sql" || true
322+
log info "Running pgtap test: $t.sql"
323+
#XXX enable ON_ERROR_STOP ?
324+
log_cmd psql -p ${pgPort} -h localhost --username=supabase_admin -d testing -f "${./tests/sql}/$t.sql"
275325
done
276326
rm -rf "$SORTED_DIR"
277-
pg_ctl -D "$PGTAP_CLUSTER" stop
278-
rm -rf $PGTAP_CLUSTER
327+
log_cmd pg_ctl -D "$PGTAP_CLUSTER" stop
328+
rm -rf "$PGTAP_CLUSTER"
279329
280330
# End of pgtap tests
281331
# from here on out we are running pg_regress tests, we use a different cluster for this
282332
# which is start by the start-postgres-server-bin script
283333
# start-postgres-server-bin script closely matches our AMI setup, configurations and migrations
284334
335+
log info "Starting PostgreSQL server for pg_regress tests"
285336
unset GRN_PLUGINS_DIR
286-
${start-postgres-server-bin}/bin/start-postgres-server ${getVersionArg pgpkg} --daemonize
337+
if ! log_cmd ${start-postgres-server-bin}/bin/start-postgres-server ${getVersionArg pgpkg} --daemonize; then
338+
log error "Failed to start PostgreSQL server for pg_regress tests"
339+
exit 1
340+
fi
287341
288-
for i in {1..60}; do
289-
if pg_isready -h ${self.supabase.defaults.host} -p ${pgPort} -U supabase_admin -q; then
290-
echo "PostgreSQL is ready"
291-
break
292-
fi
293-
sleep 1
294-
if [ $i -eq 60 ]; then
295-
echo "PostgreSQL failed to start"
296-
exit 1
297-
fi
298-
done
342+
check_postgres_ready
299343
300-
if ! psql -p ${pgPort} -h ${self.supabase.defaults.host} --no-password --username=supabase_admin -d postgres -v ON_ERROR_STOP=1 -Xf ${./tests/prime.sql}; then
301-
echo "Error executing SQL file"
344+
log info "Loading prime SQL file"
345+
if ! log_cmd psql -p ${pgPort} -h localhost --no-password --username=supabase_admin -d postgres -v ON_ERROR_STOP=1 -Xf ${./tests/prime.sql} 2>&1; then
346+
log error "Error executing SQL file"
302347
exit 1
303348
fi
304349
305350
# Create a table to store test configuration for pg_regress tests
306-
psql -p ${pgPort} -h ${self.supabase.defaults.host} --no-password --username=supabase_admin -d postgres -c "
351+
log info "Creating test_config table for pg_regress tests"
352+
log_cmd psql -p ${pgPort} -h localhost --no-password --username=supabase_admin -d postgres -c "
307353
CREATE TABLE IF NOT EXISTS test_config (key TEXT PRIMARY KEY, value TEXT);
308354
INSERT INTO test_config (key, value) VALUES ('http_mock_port', '$HTTP_MOCK_PORT')
309355
ON CONFLICT (key) DO UPDATE SET value = EXCLUDED.value;
310356
"
311357
312-
mkdir -p $out/regression_output
313-
if ! pg_regress \
358+
#shellcheck disable=SC2154
359+
mkdir -p "$out/regression_output"
360+
log info "Running pg_regress tests"
361+
if ! log_cmd pg_regress \
314362
--use-existing \
315363
--dbname=postgres \
316364
--inputdir=${./tests} \
317-
--outputdir=$out/regression_output \
318-
--host=${self.supabase.defaults.host} \
365+
--outputdir="$out/regression_output" \
366+
--host=localhost \
319367
--port=${pgPort} \
320368
--user=supabase_admin \
321-
${builtins.concatStringsSep " " sortedTestList}; then
322-
echo "pg_regress tests failed"
323-
cat $out/regression_output/regression.diffs
369+
${builtins.concatStringsSep " " sortedTestList} 2>&1; then
370+
log error "pg_regress tests failed"
371+
cat "$out/regression_output/regression.diffs"
324372
exit 1
325373
fi
374+
log info "pg_regress tests completed successfully"
326375
327-
echo "Running migrations tests"
328-
pg_prove -p ${pgPort} -U supabase_admin -h ${self.supabase.defaults.host} -d postgres -v ${../migrations/tests}/test.sql
329-
330-
# Copy logs to output
331-
for logfile in $(find /tmp -name postgresql.log -type f); do
332-
cp "$logfile" $out/postgresql.log
333-
done
334-
exit 0
376+
log info "Running migrations tests"
377+
log_cmd pg_prove -p ${pgPort} -U supabase_admin -h localhost -d postgres -v ${../migrations/tests}/test.sql
378+
log info "Migrations tests completed successfully"
335379
'';
380+
};
336381
in
337382
{
338-
psql_15 = makeCheckHarness self'.packages."psql_15/bin";
339-
psql_17 = makeCheckHarness self'.packages."psql_17/bin";
340-
psql_orioledb-17 = makeCheckHarness self'.packages."psql_orioledb-17/bin";
383+
psql_15 = pkgs.runCommand "run-check-harness-psql-15" { } (
384+
lib.getExe (makeCheckHarness self'.packages."psql_15/bin")
385+
);
386+
psql_17 = pkgs.runCommand "run-check-harness-psql-17" { } (
387+
lib.getExe (makeCheckHarness self'.packages."psql_17/bin")
388+
);
389+
psql_orioledb-17 = pkgs.runCommand "run-check-harness-psql-orioledb-17" { } (
390+
lib.getExe (makeCheckHarness self'.packages."psql_orioledb-17/bin")
391+
);
341392
inherit (self'.packages)
342393
wal-g-2
343394
wal-g-3

0 commit comments

Comments
 (0)