diff --git a/.unreleased/fix_6188 b/.unreleased/fix_6188 new file mode 100644 index 00000000000..1a003a61e5b --- /dev/null +++ b/.unreleased/fix_6188 @@ -0,0 +1,2 @@ +Fixes: #6188 Add GUC for setting background worker log level +Thanks: @jflambert for reporting the issue diff --git a/src/bgw/job.c b/src/bgw/job.c index 27b8ec1620b..e6b95ae2557 100644 --- a/src/bgw/job.c +++ b/src/bgw/job.c @@ -1197,6 +1197,10 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS) BackgroundWorkerInitializeConnectionByOid(db_oid, params.user_oid, 0); + log_min_messages = ts_guc_bgw_log_level; + + elog(DEBUG2, "job %d started execution", params.job_id); + ts_license_enable_module_loading(); INSTR_TIME_SET_CURRENT(start); @@ -1216,6 +1220,8 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS) if (job == NULL) elog(ERROR, "job %d not found when running the background worker", params.job_id); + elog(DEBUG2, "job %d (%s) found", params.job_id, NameStr(job->fd.application_name)); + pgstat_report_appname(NameStr(job->fd.application_name)); MemoryContext oldcontext = CurrentMemoryContext; TimestampTz start_time = DT_NOBEGIN, finish_time = DT_NOBEGIN; @@ -1324,7 +1330,7 @@ ts_bgw_job_entrypoint(PG_FUNCTION_ARGS) INSTR_TIME_SET_CURRENT(duration); INSTR_TIME_SUBTRACT(duration, start); - elog(LOG, + elog(DEBUG1, "job %d (%s) exiting with %s: execution time %.2f ms", params.job_id, NameStr(job->fd.application_name), diff --git a/src/bgw/scheduler.c b/src/bgw/scheduler.c index 90755f6e43e..4c32418b946 100644 --- a/src/bgw/scheduler.c +++ b/src/bgw/scheduler.c @@ -448,6 +448,8 @@ ts_update_scheduled_jobs_list(List *cur_jobs_list, MemoryContext mctx) ListCell *new_ptr = list_head(new_jobs); ListCell *cur_ptr = list_head(cur_jobs_list); + elog(DEBUG2, "updating scheduled jobs list"); + while (cur_ptr != NULL && new_ptr != NULL) { ScheduledBgwJob *new_sjob = lfirst(new_ptr); @@ -734,6 +736,8 @@ ts_bgw_scheduler_process(int32 run_for_interval_ms, TimestampTz start = ts_timer_get_current_timestamp(); TimestampTz quit_time = DT_NOEND; + log_min_messages = ts_guc_bgw_log_level; + pgstat_report_activity(STATE_RUNNING, NULL); /* txn to read the list of jobs from the DB */ @@ -747,7 +751,7 @@ ts_bgw_scheduler_process(int32 run_for_interval_ms, if (run_for_interval_ms > 0) quit_time = TimestampTzPlusMilliseconds(start, run_for_interval_ms); - ereport(DEBUG1, (errmsg("database scheduler starting for database %u", MyDatabaseId))); + elog(DEBUG1, "database scheduler for database %u starting", MyDatabaseId); /* * on SIGTERM the process will usually die from the CHECK_FOR_INTERRUPTS @@ -775,6 +779,7 @@ ts_bgw_scheduler_process(int32 run_for_interval_ms, { got_SIGHUP = false; ProcessConfigFile(PGC_SIGHUP); + log_min_messages = ts_guc_bgw_log_level; } /* @@ -798,6 +803,8 @@ ts_bgw_scheduler_process(int32 run_for_interval_ms, MemoryContextReset(scratch_mctx); } + elog(DEBUG1, "database scheduler for database %u exiting", MyDatabaseId); + #ifdef TS_DEBUG if (ts_shutdown_bgw) elog(WARNING, "bgw scheduler stopped due to shutdown_bgw guc"); @@ -863,6 +870,7 @@ ts_bgw_scheduler_register_signal_handlers(void) /* Some SIGHUPS may already have been dropped, so we must load the file here */ got_SIGHUP = false; ProcessConfigFile(PGC_SIGHUP); + log_min_messages = ts_guc_bgw_log_level; } Datum diff --git a/src/guc.c b/src/guc.c index 5027c930229..4f6e5f5f163 100644 --- a/src/guc.c +++ b/src/guc.c @@ -63,6 +63,14 @@ static const struct config_enum_entry dist_copy_transfer_formats[] = { { NULL, 0, false } }; +/* Copied from contrib/auto_explain/auto_explain.c */ +static const struct config_enum_entry loglevel_options[] = { + { "debug5", DEBUG5, false }, { "debug4", DEBUG4, false }, { "debug3", DEBUG3, false }, + { "debug2", DEBUG2, false }, { "debug1", DEBUG1, false }, { "debug", DEBUG2, true }, + { "info", INFO, false }, { "notice", NOTICE, false }, { "warning", WARNING, false }, + { "log", LOG, false }, { NULL, 0, false } +}; + bool ts_guc_enable_deprecation_warnings = true; bool ts_guc_enable_optimizations = true; bool ts_guc_restoring = false; @@ -86,6 +94,7 @@ bool ts_guc_enable_async_append = true; bool ts_guc_enable_chunkwise_aggregation = true; TSDLLEXPORT bool ts_guc_enable_compression_indexscan = true; TSDLLEXPORT bool ts_guc_enable_bulk_decompression = true; +TSDLLEXPORT int ts_guc_bgw_log_level; TSDLLEXPORT bool ts_guc_enable_skip_scan = true; /* default value of ts_guc_max_open_chunks_per_insert and ts_guc_max_cached_chunks_per_hypertable * will be set as their respective boot-value when the GUC mechanism starts up */ @@ -713,6 +722,18 @@ _guc_init(void) /* assign_hook= */ NULL, /* show_hook= */ NULL); + DefineCustomEnumVariable("timescaledb.bgw_log_level", + "Log level for the background worker subsystem.", + "Log level for the scheduler and workers of the background worker " + "subsystem. Requires configuration reload to change.", + /* valueAddr= */ &ts_guc_bgw_log_level, + /* bootValue= */ log_min_messages, + /* options= */ loglevel_options, + /* context= */ PGC_SIGHUP, + 0, + NULL, + NULL, + NULL); #ifdef USE_TELEMETRY DefineCustomStringVariable(/* name= */ "timescaledb_telemetry.cloud", /* short_desc= */ "cloud provider", diff --git a/src/guc.h b/src/guc.h index 409ba38df7c..176b0d86d85 100644 --- a/src/guc.h +++ b/src/guc.h @@ -64,6 +64,7 @@ extern TSDLLEXPORT char *ts_guc_passfile; extern TSDLLEXPORT bool ts_guc_enable_remote_explain; extern TSDLLEXPORT bool ts_guc_enable_compression_indexscan; extern TSDLLEXPORT bool ts_guc_enable_bulk_decompression; +extern TSDLLEXPORT int ts_guc_bgw_log_level; typedef enum DataFetcherType { diff --git a/test/src/bgw/log.c b/test/src/bgw/log.c index 8ce908e072e..e6cee52096b 100644 --- a/test/src/bgw/log.c +++ b/test/src/bgw/log.c @@ -76,10 +76,6 @@ emit_log_hook_callback(ErrorData *edata) if (MyProc == NULL) return; - /* We are only interested in elevel LOG and above. */ - if (edata->elevel < LOG) - return; - /* * Block signals so we don't lose messages generated during signal * processing if they occur while we are saving this log message (since diff --git a/tsl/test/expected/bgw_db_scheduler.out b/tsl/test/expected/bgw_db_scheduler.out index 6a316b4c1a6..b7dc79e596f 100644 --- a/tsl/test/expected/bgw_db_scheduler.out +++ b/tsl/test/expected/bgw_db_scheduler.out @@ -205,14 +205,13 @@ SELECT * FROM timescaledb_information.job_stats; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | unscheduled | Execute job 1 - 1 | unscheduled | job 1000 (unscheduled) exiting with success: execution time (RANDOM) ms -(5 rows) +(4 rows) SELECT delete_job(1000); delete_job @@ -323,13 +322,12 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms -(4 rows) +(3 rows) --Test that the scheduler will not run job again if not enough time has passed SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); @@ -346,14 +344,13 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) -(5 rows) +(4 rows) --After enough time has passed the scheduler will run the job again SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(100, 50); @@ -370,19 +367,17 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms -(10 rows) +(8 rows) --Now it runs it one more time SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(120, 100); @@ -399,24 +394,21 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms -(15 rows) +(12 rows) -- -- Test what happens when running a job that throws an error @@ -431,12 +423,7 @@ SELECT ts_bgw_params_reset_time(); (1 row) DELETE FROM _timescaledb_config.bgw_job; -SELECT insert_job('test_job_2', 'bgw_test_job_2_error', INTERVAL '100ms', INTERVAL '100s', INTERVAL '100ms'); - insert_job ------------- - 1001 -(1 row) - +SELECT insert_job('test_job_2', 'bgw_test_job_2_error', INTERVAL '100ms', INTERVAL '100s', INTERVAL '100ms') AS test_job_2_id \gset \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER --Run the first time and error SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); @@ -612,7 +599,7 @@ SELECT * FROM sorted_bgw_log; -- Get status of failing job `test_job_2` to check it reached `max_retries` and -- the new `job_status` now is `Paused` SELECT job_id, last_run_status, job_status, total_runs, total_successes, total_failures -FROM timescaledb_information.job_stats WHERE job_id = 1001; +FROM timescaledb_information.job_stats WHERE job_id = :test_job_2_id; job_id | last_run_status | job_status | total_runs | total_successes | total_failures --------+-----------------+------------+------------+-----------------+---------------- 1001 | Failed | Paused | 5 | 0 | 5 @@ -621,7 +608,7 @@ FROM timescaledb_information.job_stats WHERE job_id = 1001; -- Alter job to be rescheduled and run it again \c :TEST_DBNAME :ROLE_SUPERUSER TRUNCATE bgw_log; -SELECT scheduled FROM alter_job(1001, scheduled => true) AS discard; +SELECT scheduled FROM alter_job(:test_job_2_id, scheduled => true) AS discard; scheduled ----------- t @@ -635,7 +622,7 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(525); (1 row) SELECT job_id, last_run_success, total_runs, total_successes, total_failures, total_crashes -FROM _timescaledb_internal.bgw_job_stat WHERE job_id = 1001; +FROM _timescaledb_internal.bgw_job_stat WHERE job_id = :test_job_2_id; job_id | last_run_success | total_runs | total_successes | total_failures | total_crashes --------+------------------+------------+-----------------+----------------+--------------- 1001 | f | 6 | 0 | 6 | 0 @@ -736,14 +723,13 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 - 2 | test_job_3_long | job 1003 (test_job_3_long) exiting with success: execution time (RANDOM) ms -(5 rows) +(4 rows) SELECT ts_bgw_params_mock_wait_returns_immediately(:WAIT_ON_JOB); ts_bgw_params_mock_wait_returns_immediately @@ -824,8 +810,8 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 @@ -836,8 +822,7 @@ SELECT * FROM sorted_bgw_log; 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 - 2 | test_job_3_long | job 1004 (test_job_3_long) exiting with success: execution time (RANDOM) ms -(11 rows) +(10 rows) --Test sending a SIGHUP to a job \c :TEST_DBNAME :ROLE_SUPERUSER @@ -1002,8 +987,8 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) @@ -1015,8 +1000,7 @@ SELECT * FROM sorted_bgw_log; 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 - 2 | test_job_3_long | job 1005 (test_job_3_long) exiting with success: execution time (RANDOM) ms -(12 rows) +(11 rows) CREATE FUNCTION wait_for_timer_to_run(started_at INTEGER, spins INTEGER=:TEST_SPINWAIT_ITERS) RETURNS BOOLEAN LANGUAGE PLPGSQL AS $BODY$ @@ -1212,13 +1196,12 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 - 1 | test_job_4 | job 1012 (test_job_4) exiting with success: execution time (RANDOM) ms -(4 rows) +(3 rows) -- Now just make sure that the job actually runs in 200ms SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(200); @@ -1237,18 +1220,16 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 - 1 | test_job_4 | job 1012 (test_job_4) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 - 1 | test_job_4 | job 1012 (test_job_4) exiting with success: execution time (RANDOM) ms -(9 rows) +(7 rows) -- Test updating jobs list TRUNCATE bgw_log; @@ -1596,29 +1577,25 @@ SELECT ts_bgw_params_reset_time(500000, true); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+--------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | another | Execute job 1 - 1 | another | job 1024 (another) exiting with success: execution time (RANDOM) ms 3 | DB Scheduler | [TESTING] Registered new background worker 4 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | another | Execute job 1 - 1 | another | job 1024 (another) exiting with success: execution time (RANDOM) ms 5 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 6 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 7 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 8 | DB Scheduler | [TESTING] Registered new background worker 9 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | new_job | Execute job 1 - 1 | new_job | job 1025 (new_job) exiting with success: execution time (RANDOM) ms 10 | DB Scheduler | [TESTING] Registered new background worker 11 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | new_job | Execute job 1 - 1 | new_job | job 1025 (new_job) exiting with success: execution time (RANDOM) ms -(20 rows) +(16 rows) \x on SELECT * FROM _timescaledb_internal.bgw_job_stat; diff --git a/tsl/test/expected/bgw_db_scheduler_fixed.out b/tsl/test/expected/bgw_db_scheduler_fixed.out index d92dbfead1c..057734c84b3 100644 --- a/tsl/test/expected/bgw_db_scheduler_fixed.out +++ b/tsl/test/expected/bgw_db_scheduler_fixed.out @@ -196,14 +196,13 @@ SELECT * FROM timescaledb_information.job_stats; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | unscheduled | Execute job 1 - 1 | unscheduled | job 1000 (unscheduled) exiting with success: execution time (RANDOM) ms -(5 rows) +(4 rows) SELECT delete_job(1000); delete_job @@ -313,13 +312,12 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms -(4 rows) +(3 rows) --Test that the scheduler will not run job again if not enough time has passed SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); @@ -336,14 +334,13 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) -(5 rows) +(4 rows) --After enough time has passed the scheduler will run the job again SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(100, 50); @@ -360,19 +357,17 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms -(10 rows) +(8 rows) --Now it runs it one more time SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(120, 100); @@ -389,24 +384,21 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_1 | Execute job 1 - 1 | test_job_1 | job 1000 (test_job_1) exiting with success: execution time (RANDOM) ms -(15 rows) +(12 rows) -- -- Test what happens when running a job that throws an error @@ -727,14 +719,13 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 - 2 | test_job_3_long | job 1003 (test_job_3_long) exiting with success: execution time (RANDOM) ms -(5 rows) +(4 rows) SELECT ts_bgw_params_mock_wait_returns_immediately(:WAIT_ON_JOB); ts_bgw_params_mock_wait_returns_immediately @@ -815,8 +806,8 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 @@ -827,8 +818,7 @@ SELECT * FROM sorted_bgw_log; 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 - 2 | test_job_3_long | job 1004 (test_job_3_long) exiting with success: execution time (RANDOM) ms -(11 rows) +(10 rows) --Test sending a SIGHUP to a job \c :TEST_DBNAME :ROLE_SUPERUSER @@ -993,8 +983,8 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+----------------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+----------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) @@ -1006,8 +996,7 @@ SELECT * FROM sorted_bgw_log; 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_3_long | Before sleep job 3 1 | test_job_3_long | After sleep job 3 - 2 | test_job_3_long | job 1005 (test_job_3_long) exiting with success: execution time (RANDOM) ms -(12 rows) +(11 rows) CREATE FUNCTION wait_for_timer_to_run(started_at INTEGER, spins INTEGER=:TEST_SPINWAIT_ITERS) RETURNS BOOLEAN LANGUAGE PLPGSQL AS $BODY$ @@ -1203,13 +1192,12 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 - 1 | test_job_4 | job 1012 (test_job_4) exiting with success: execution time (RANDOM) ms -(4 rows) +(3 rows) -- Now just make sure that the job actually runs in 200ms SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(200); @@ -1228,18 +1216,16 @@ FROM _timescaledb_internal.bgw_job_stat; (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+------------------------------------------------------------------------ + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Registered new background worker 1 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 - 1 | test_job_4 | job 1012 (test_job_4) exiting with success: execution time (RANDOM) ms 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | test_job_4 | Execute job 4 - 1 | test_job_4 | job 1012 (test_job_4) exiting with success: execution time (RANDOM) ms -(9 rows) +(7 rows) -- Test updating jobs list TRUNCATE bgw_log; @@ -1573,29 +1559,25 @@ SELECT ts_bgw_params_reset_time(500000, true); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | application_name | msg ---------+------------------+--------------------------------------------------------------------- + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 1 | DB Scheduler | [TESTING] Registered new background worker 2 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | another | Execute job 1 - 1 | another | job 1024 (another) exiting with success: execution time (RANDOM) ms 3 | DB Scheduler | [TESTING] Registered new background worker 4 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | another | Execute job 1 - 1 | another | job 1024 (another) exiting with success: execution time (RANDOM) ms 5 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 6 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 7 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 8 | DB Scheduler | [TESTING] Registered new background worker 9 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | new_job | Execute job 1 - 1 | new_job | job 1025 (new_job) exiting with success: execution time (RANDOM) ms 10 | DB Scheduler | [TESTING] Registered new background worker 11 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | new_job | Execute job 1 - 1 | new_job | job 1025 (new_job) exiting with success: execution time (RANDOM) ms -(20 rows) +(16 rows) SELECT * FROM _timescaledb_internal.bgw_job_stat; job_id | last_start | last_finish | next_start | last_successful_finish | last_run_success | total_runs | total_duration | total_duration_failures | total_successes | total_failures | total_crashes | consecutive_failures | consecutive_crashes | flags diff --git a/tsl/test/expected/bgw_reorder_drop_chunks.out b/tsl/test/expected/bgw_reorder_drop_chunks.out index 898f3429272..88b2875e3d4 100644 --- a/tsl/test/expected/bgw_reorder_drop_chunks.out +++ b/tsl/test/expected/bgw_reorder_drop_chunks.out @@ -128,12 +128,11 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+-----------------------+----------------------------------------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 0 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms -(3 rows) + msg_no | mock_time | application_name | msg +--------+-----------+------------------+-------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 +(2 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -167,15 +166,13 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+-----------------------+----------------------------------------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 0 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 25000 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms -(6 rows) + msg_no | mock_time | application_name | msg +--------+-----------+------------------+---------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 +(4 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -211,18 +208,15 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(50); -- job info is gone SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+-----------------------+----------------------------------------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 0 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 25000 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 - 0 | 50000 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms -(9 rows) + msg_no | mock_time | application_name | msg +--------+-----------+------------------+----------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 +(6 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -257,19 +251,16 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(100); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+-----------------------+----------------------------------------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 0 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 25000 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 - 0 | 50000 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 100000 | DB Scheduler | [TESTING] Wait until 200000, started at 100000 -(10 rows) + msg_no | mock_time | application_name | msg +--------+-----------+------------------+------------------------------------------------ + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 + 0 | 100000 | DB Scheduler | [TESTING] Wait until 200000, started at 100000 +(7 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -329,20 +320,17 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(125); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+-----------------------+----------------------------------------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 0 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 25000 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker - 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 - 0 | 50000 | Reorder Policy [1000] | job 1000 (Reorder Policy [1000]) exiting with success: execution time (RANDOM) ms - 0 | 100000 | DB Scheduler | [TESTING] Wait until 200000, started at 100000 - 0 | 200000 | DB Scheduler | [TESTING] Wait until 325000, started at 200000 -(11 rows) + msg_no | mock_time | application_name | msg +--------+-----------+------------------+------------------------------------------------ + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 25000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 50000 | DB Scheduler | [TESTING] Registered new background worker + 1 | 50000 | DB Scheduler | [TESTING] Wait until 100000, started at 50000 + 0 | 100000 | DB Scheduler | [TESTING] Wait until 200000, started at 100000 + 0 | 200000 | DB Scheduler | [TESTING] Wait until 325000, started at 200000 +(8 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:reorder_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -456,12 +444,11 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+-------------------------+------------------------------------------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 0 | Retention Policy [1001] | job 1001 (Retention Policy [1001]) exiting with success: execution time (RANDOM) ms -(3 rows) + msg_no | mock_time | application_name | msg +--------+-----------+------------------+-------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 +(2 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:drop_chunks_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -495,13 +482,12 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+-------------------------+------------------------------------------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 0 | Retention Policy [1001] | job 1001 (Retention Policy [1001]) exiting with success: execution time (RANDOM) ms - 0 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 -(4 rows) + msg_no | mock_time | application_name | msg +--------+-----------+------------------+---------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 +(3 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:drop_chunks_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -545,17 +531,15 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(10000); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+-------------------------+------------------------------------------------------------------------------------- - 0 | 0 | DB Scheduler | [TESTING] Registered new background worker - 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 - 0 | 0 | Retention Policy [1001] | job 1001 (Retention Policy [1001]) exiting with success: execution time (RANDOM) ms - 0 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 - 0 | 50000 | DB Scheduler | [TESTING] Wait until 1000000, started at 50000 - 1 | 1000000 | DB Scheduler | [TESTING] Registered new background worker - 2 | 1000000 | DB Scheduler | [TESTING] Wait until 10050000, started at 1000000 - 0 | 1000000 | Retention Policy [1001] | job 1001 (Retention Policy [1001]) exiting with success: execution time (RANDOM) ms -(8 rows) + msg_no | mock_time | application_name | msg +--------+-----------+------------------+--------------------------------------------------- + 0 | 0 | DB Scheduler | [TESTING] Registered new background worker + 1 | 0 | DB Scheduler | [TESTING] Wait until 25000, started at 0 + 0 | 25000 | DB Scheduler | [TESTING] Wait until 50000, started at 25000 + 0 | 50000 | DB Scheduler | [TESTING] Wait until 1000000, started at 50000 + 1 | 1000000 | DB Scheduler | [TESTING] Registered new background worker + 2 | 1000000 | DB Scheduler | [TESTING] Wait until 10050000, started at 1000000 +(6 rows) SELECT * FROM timescaledb_information.jobs WHERE job_id=:drop_chunks_job_id; job_id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | config | next_start | initial_start | hypertable_schema | hypertable_name | check_schema | check_name @@ -660,10 +644,8 @@ SELECT * FROM sorted_bgw_log; 1 | 0 | DB Scheduler | [TESTING] Registered new background worker 2 | 0 | DB Scheduler | [TESTING] Wait until 1000000, started at 0 0 | 0 | Retention Policy [1002] | applying retention policy to hypertable "test_drop_chunks_table_date": dropping ... - 1 | 0 | Retention Policy [1002] | job 1002 (Retention Policy [1002]) exiting with success: execution time (RANDOM) ms 0 | 0 | Retention Policy [1003] | applying retention policy to hypertable "test_drop_chunks_table_tsntz": dropping... - 1 | 0 | Retention Policy [1003] | job 1003 (Retention Policy [1003]) exiting with success: execution time (RANDOM) ms -(7 rows) +(5 rows) -- test the schedule_interval parameter for policies CREATE TABLE test_schedint(time timestamptz, a int, b int); diff --git a/tsl/test/expected/bgw_scheduler_control.out b/tsl/test/expected/bgw_scheduler_control.out new file mode 100644 index 00000000000..725077f7db0 --- /dev/null +++ b/tsl/test/expected/bgw_scheduler_control.out @@ -0,0 +1,128 @@ +-- This file and its contents are licensed under the Timescale License. +-- Please see the included NOTICE for copyright information and +-- LICENSE-TIMESCALE for a copy of the license. +\c :TEST_DBNAME :ROLE_SUPERUSER +CREATE FUNCTION ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(INT, INT) RETURNS VOID +AS :MODULE_PATHNAME LANGUAGE C VOLATILE; +CREATE FUNCTION ts_bgw_params_create() RETURNS VOID +AS :MODULE_PATHNAME LANGUAGE C VOLATILE; +CREATE FUNCTION ts_bgw_params_destroy() RETURNS VOID +AS :MODULE_PATHNAME LANGUAGE C VOLATILE; +CREATE FUNCTION ts_bgw_params_reset_time(set_time BIGINT, wait BOOLEAN) RETURNS VOID +AS :MODULE_PATHNAME LANGUAGE C VOLATILE; +-- These are needed to set up the test scheduler +CREATE TABLE public.bgw_dsm_handle_store(handle BIGINT); +INSERT INTO public.bgw_dsm_handle_store VALUES (0); +SELECT ts_bgw_params_create(); + ts_bgw_params_create +---------------------- + +(1 row) + +-- Test scheduler automatically writes to this table by name, so +-- create it. +CREATE TABLE public.bgw_log( + msg_no INT, + mock_time BIGINT, + application_name TEXT, + msg TEXT +); +CREATE VIEW cleaned_bgw_log AS + SELECT msg_no, application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time|database) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; +-- Remove all default jobs +DELETE FROM _timescaledb_config.bgw_job WHERE TRUE; +TRUNCATE _timescaledb_internal.bgw_job_stat; +-- +-- Set bgw log level and reload config. +-- +-- Debug messages should be in log now which it wasn't before. +-- +\c :TEST_DBNAME :ROLE_SUPERUSER +ALTER SYSTEM SET timescaledb.bgw_log_level = 'DEBUG1'; +SELECT pg_reload_conf(); + pg_reload_conf +---------------- + t +(1 row) + +SELECT ts_bgw_params_reset_time(0, false); + ts_bgw_params_reset_time +-------------------------- + +(1 row) + +INSERT INTO _timescaledb_config.bgw_job( + application_name, + schedule_interval, + max_runtime, + max_retries, + retry_period, + proc_schema, + proc_name, + owner, + scheduled, + fixed_schedule +) VALUES ( + 'test_job_1b', --application_name + INTERVAL '100ms', --schedule_interval + INTERVAL '100s', --max_runtime + 5, --max_retries + INTERVAL '1s', --retry_period + 'public', --proc_schema + 'bgw_test_job_1', --proc_name + CURRENT_ROLE::regrole, --owner + TRUE, --scheduled + FALSE --fixed_schedule +) RETURNING id AS job_id \gset +SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 0); + ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish +------------------------------------------------------------ + +(1 row) + +SELECT * FROM cleaned_bgw_log; + msg_no | application_name | msg +--------+------------------+------------------------------------------------------------------------- + 0 | DB Scheduler | database scheduler for database (RANDOM) starting + 1 | DB Scheduler | launching job 1000 "test_job_1b" + 2 | DB Scheduler | [TESTING] Registered new background worker + 3 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) + 0 | test_job_1b | Execute job 1 + 1 | test_job_1b | job 1000 (test_job_1b) exiting with success: execution time (RANDOM) ms + 4 | DB Scheduler | database scheduler for database (RANDOM) exiting +(7 rows) + +ALTER SYSTEM RESET timescaledb.bgw_log_level; +SELECT pg_reload_conf(); + pg_reload_conf +---------------- + t +(1 row) + +TRUNCATE bgw_log; +SELECT ts_bgw_params_reset_time(0, false); + ts_bgw_params_reset_time +-------------------------- + +(1 row) + +SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 0); + ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish +------------------------------------------------------------ + +(1 row) + +SELECT * FROM cleaned_bgw_log; + msg_no | application_name | msg +--------+------------------+---------------------------------------------------- + 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) +(1 row) + +SELECT delete_job(:job_id); + delete_job +------------ + +(1 row) + diff --git a/tsl/test/expected/cagg_bgw-13.out b/tsl/test/expected/cagg_bgw-13.out index 0b16ab36fc4..3177aa806db 100644 --- a/tsl/test/expected/cagg_bgw-13.out +++ b/tsl/test/expected/cagg_bgw-13.out @@ -159,15 +159,14 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1000] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -2147483648, 6 ] 1 | 0 | Refresh Continuous Aggregate Policy [1000] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_2" 2 | 0 | Refresh Continuous Aggregate Policy [1000] | inserted 3 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_2" - 3 | 0 | Refresh Continuous Aggregate Policy [1000] | job 1000 (Refresh Continuous Aggregate Policy [1000]) exiting with success: execution time (RANDOM) ms -(6 rows) +(5 rows) SELECT * FROM _timescaledb_config.bgw_job where id=:job_id; id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | initial_start | hypertable_id | config | check_schema | check_name | timezone @@ -395,15 +394,14 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 0 | Refresh Continuous Aggregate Policy [1001] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 0 | Refresh Continuous Aggregate Policy [1001] | inserted 6 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 0 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms -(6 rows) +(5 rows) -- job ran once, successfully SELECT job_id, last_finish - next_start as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes @@ -443,21 +441,19 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 0 | Refresh Continuous Aggregate Policy [1001] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 0 | Refresh Continuous Aggregate Policy [1001] | inserted 6 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 0 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | deleted 1 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | inserted 1 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms -(12 rows) +(10 rows) SELECT job_id, next_start - last_finish as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes FROM _timescaledb_internal.bgw_job_stat @@ -677,19 +673,18 @@ SELECT * FROM test_continuous_agg_view_user_2; \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER SELECT * from sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1003] | refreshing continuous aggregate "test_continuous_agg_view_user_2" in window [ -2147483648, 2 ] 1 | 0 | Refresh Continuous Aggregate Policy [1003] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_6" 2 | 0 | Refresh Continuous Aggregate Policy [1003] | inserted 1 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_6" - 3 | 0 | Refresh Continuous Aggregate Policy [1003] | job 1003 (Refresh Continuous Aggregate Policy [1003]) exiting with success: execution time (RANDOM) ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | job 1003 threw an error 1 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | permission denied for table test_continuous_agg_table_w_grant -(10 rows) +(9 rows) -- Count the number of continuous aggregate policies SELECT count(*) FROM _timescaledb_config.bgw_job diff --git a/tsl/test/expected/cagg_bgw-14.out b/tsl/test/expected/cagg_bgw-14.out index 0b16ab36fc4..3177aa806db 100644 --- a/tsl/test/expected/cagg_bgw-14.out +++ b/tsl/test/expected/cagg_bgw-14.out @@ -159,15 +159,14 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1000] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -2147483648, 6 ] 1 | 0 | Refresh Continuous Aggregate Policy [1000] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_2" 2 | 0 | Refresh Continuous Aggregate Policy [1000] | inserted 3 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_2" - 3 | 0 | Refresh Continuous Aggregate Policy [1000] | job 1000 (Refresh Continuous Aggregate Policy [1000]) exiting with success: execution time (RANDOM) ms -(6 rows) +(5 rows) SELECT * FROM _timescaledb_config.bgw_job where id=:job_id; id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | initial_start | hypertable_id | config | check_schema | check_name | timezone @@ -395,15 +394,14 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 0 | Refresh Continuous Aggregate Policy [1001] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 0 | Refresh Continuous Aggregate Policy [1001] | inserted 6 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 0 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms -(6 rows) +(5 rows) -- job ran once, successfully SELECT job_id, last_finish - next_start as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes @@ -443,21 +441,19 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 0 | Refresh Continuous Aggregate Policy [1001] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 0 | Refresh Continuous Aggregate Policy [1001] | inserted 6 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 0 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | deleted 1 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | inserted 1 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms -(12 rows) +(10 rows) SELECT job_id, next_start - last_finish as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes FROM _timescaledb_internal.bgw_job_stat @@ -677,19 +673,18 @@ SELECT * FROM test_continuous_agg_view_user_2; \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER SELECT * from sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1003] | refreshing continuous aggregate "test_continuous_agg_view_user_2" in window [ -2147483648, 2 ] 1 | 0 | Refresh Continuous Aggregate Policy [1003] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_6" 2 | 0 | Refresh Continuous Aggregate Policy [1003] | inserted 1 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_6" - 3 | 0 | Refresh Continuous Aggregate Policy [1003] | job 1003 (Refresh Continuous Aggregate Policy [1003]) exiting with success: execution time (RANDOM) ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | job 1003 threw an error 1 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | permission denied for table test_continuous_agg_table_w_grant -(10 rows) +(9 rows) -- Count the number of continuous aggregate policies SELECT count(*) FROM _timescaledb_config.bgw_job diff --git a/tsl/test/expected/cagg_bgw-15.out b/tsl/test/expected/cagg_bgw-15.out index 0b16ab36fc4..3177aa806db 100644 --- a/tsl/test/expected/cagg_bgw-15.out +++ b/tsl/test/expected/cagg_bgw-15.out @@ -159,15 +159,14 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1000] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -2147483648, 6 ] 1 | 0 | Refresh Continuous Aggregate Policy [1000] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_2" 2 | 0 | Refresh Continuous Aggregate Policy [1000] | inserted 3 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_2" - 3 | 0 | Refresh Continuous Aggregate Policy [1000] | job 1000 (Refresh Continuous Aggregate Policy [1000]) exiting with success: execution time (RANDOM) ms -(6 rows) +(5 rows) SELECT * FROM _timescaledb_config.bgw_job where id=:job_id; id | application_name | schedule_interval | max_runtime | max_retries | retry_period | proc_schema | proc_name | owner | scheduled | fixed_schedule | initial_start | hypertable_id | config | check_schema | check_name | timezone @@ -395,15 +394,14 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-----------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-----------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 0 | Refresh Continuous Aggregate Policy [1001] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 0 | Refresh Continuous Aggregate Policy [1001] | inserted 6 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 0 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms -(6 rows) +(5 rows) -- job ran once, successfully SELECT job_id, last_finish - next_start as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes @@ -443,21 +441,19 @@ SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 25); (1 row) SELECT * FROM sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 0 | Refresh Continuous Aggregate Policy [1001] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 0 | Refresh Continuous Aggregate Policy [1001] | inserted 6 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 0 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | refreshing continuous aggregate "test_continuous_agg_view" in window [ -90, 12 ] 1 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | deleted 1 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_3" 2 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | inserted 1 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_3" - 3 | 43200000000 | Refresh Continuous Aggregate Policy [1001] | job 1001 (Refresh Continuous Aggregate Policy [1001]) exiting with success: execution time (RANDOM) ms -(12 rows) +(10 rows) SELECT job_id, next_start - last_finish as until_next, last_run_success, total_runs, total_successes, total_failures, total_crashes FROM _timescaledb_internal.bgw_job_stat @@ -677,19 +673,18 @@ SELECT * FROM test_continuous_agg_view_user_2; \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER SELECT * from sorted_bgw_log; - msg_no | mock_time | application_name | msg ---------+-------------+--------------------------------------------+-------------------------------------------------------------------------------------------------------- + msg_no | mock_time | application_name | msg +--------+-------------+--------------------------------------------+------------------------------------------------------------------------------------------------- 0 | 0 | DB Scheduler | [TESTING] Registered new background worker 1 | 0 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 0 | Refresh Continuous Aggregate Policy [1003] | refreshing continuous aggregate "test_continuous_agg_view_user_2" in window [ -2147483648, 2 ] 1 | 0 | Refresh Continuous Aggregate Policy [1003] | deleted 0 row(s) from materialization table "_timescaledb_internal._materialized_hypertable_6" 2 | 0 | Refresh Continuous Aggregate Policy [1003] | inserted 1 row(s) into materialization table "_timescaledb_internal._materialized_hypertable_6" - 3 | 0 | Refresh Continuous Aggregate Policy [1003] | job 1003 (Refresh Continuous Aggregate Policy [1003]) exiting with success: execution time (RANDOM) ms 0 | 43200000000 | DB Scheduler | [TESTING] Registered new background worker 1 | 43200000000 | DB Scheduler | [TESTING] Wait until (RANDOM), started at (RANDOM) 0 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | job 1003 threw an error 1 | 43200000000 | Refresh Continuous Aggregate Policy [1003] | permission denied for table test_continuous_agg_table_w_grant -(10 rows) +(9 rows) -- Count the number of continuous aggregate policies SELECT count(*) FROM _timescaledb_config.bgw_job diff --git a/tsl/test/sql/CMakeLists.txt b/tsl/test/sql/CMakeLists.txt index 9a623ffee2d..d4ca1c12904 100644 --- a/tsl/test/sql/CMakeLists.txt +++ b/tsl/test/sql/CMakeLists.txt @@ -43,6 +43,7 @@ if(CMAKE_BUILD_TYPE MATCHES Debug) APPEND TEST_FILES bgw_db_scheduler.sql + bgw_scheduler_control.sql job_errors_permissions.sql troubleshooting_job_errors.sql bgw_db_scheduler_fixed.sql @@ -135,6 +136,9 @@ endif() set(SOLO_TESTS # dist_hypertable needs a lot of memory when the Sanitizer is active dist_hypertable-${PG_VERSION_MAJOR} + # This interferes with other tests since it reloads the config to + # increase log level. + bgw_scheduler_control bgw_db_scheduler job_errors_permissions troubleshooting_job_errors diff --git a/tsl/test/sql/bgw_db_scheduler.sql b/tsl/test/sql/bgw_db_scheduler.sql index 9e78ba0096c..ab0b82fc215 100644 --- a/tsl/test/sql/bgw_db_scheduler.sql +++ b/tsl/test/sql/bgw_db_scheduler.sql @@ -233,7 +233,7 @@ TRUNCATE bgw_log; TRUNCATE _timescaledb_internal.bgw_job_stat; SELECT ts_bgw_params_reset_time(); DELETE FROM _timescaledb_config.bgw_job; -SELECT insert_job('test_job_2', 'bgw_test_job_2_error', INTERVAL '100ms', INTERVAL '100s', INTERVAL '100ms'); +SELECT insert_job('test_job_2', 'bgw_test_job_2_error', INTERVAL '100ms', INTERVAL '100s', INTERVAL '100ms') AS test_job_2_id \gset \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER --Run the first time and error @@ -270,16 +270,16 @@ SELECT * FROM sorted_bgw_log; -- Get status of failing job `test_job_2` to check it reached `max_retries` and -- the new `job_status` now is `Paused` SELECT job_id, last_run_status, job_status, total_runs, total_successes, total_failures -FROM timescaledb_information.job_stats WHERE job_id = 1001; +FROM timescaledb_information.job_stats WHERE job_id = :test_job_2_id; -- Alter job to be rescheduled and run it again \c :TEST_DBNAME :ROLE_SUPERUSER TRUNCATE bgw_log; -SELECT scheduled FROM alter_job(1001, scheduled => true) AS discard; +SELECT scheduled FROM alter_job(:test_job_2_id, scheduled => true) AS discard; \c :TEST_DBNAME :ROLE_DEFAULT_PERM_USER SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(525); SELECT job_id, last_run_success, total_runs, total_successes, total_failures, total_crashes -FROM _timescaledb_internal.bgw_job_stat WHERE job_id = 1001; +FROM _timescaledb_internal.bgw_job_stat WHERE job_id = :test_job_2_id; SELECT * FROM sorted_bgw_log; -- diff --git a/tsl/test/sql/bgw_scheduler_control.sql b/tsl/test/sql/bgw_scheduler_control.sql new file mode 100644 index 00000000000..507877861fc --- /dev/null +++ b/tsl/test/sql/bgw_scheduler_control.sql @@ -0,0 +1,86 @@ +-- This file and its contents are licensed under the Timescale License. +-- Please see the included NOTICE for copyright information and +-- LICENSE-TIMESCALE for a copy of the license. + +\c :TEST_DBNAME :ROLE_SUPERUSER +CREATE FUNCTION ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(INT, INT) RETURNS VOID +AS :MODULE_PATHNAME LANGUAGE C VOLATILE; + +CREATE FUNCTION ts_bgw_params_create() RETURNS VOID +AS :MODULE_PATHNAME LANGUAGE C VOLATILE; + +CREATE FUNCTION ts_bgw_params_destroy() RETURNS VOID +AS :MODULE_PATHNAME LANGUAGE C VOLATILE; + +CREATE FUNCTION ts_bgw_params_reset_time(set_time BIGINT, wait BOOLEAN) RETURNS VOID +AS :MODULE_PATHNAME LANGUAGE C VOLATILE; + +-- These are needed to set up the test scheduler +CREATE TABLE public.bgw_dsm_handle_store(handle BIGINT); +INSERT INTO public.bgw_dsm_handle_store VALUES (0); +SELECT ts_bgw_params_create(); + +-- Test scheduler automatically writes to this table by name, so +-- create it. +CREATE TABLE public.bgw_log( + msg_no INT, + mock_time BIGINT, + application_name TEXT, + msg TEXT +); + +CREATE VIEW cleaned_bgw_log AS + SELECT msg_no, application_name, + regexp_replace(regexp_replace(msg, '(Wait until|started at|execution time|database) [0-9]+(\.[0-9]+)?', '\1 (RANDOM)', 'g'), 'background worker "[^"]+"','connection') AS msg + FROM bgw_log ORDER BY mock_time, application_name COLLATE "C", msg_no; + +-- Remove all default jobs +DELETE FROM _timescaledb_config.bgw_job WHERE TRUE; +TRUNCATE _timescaledb_internal.bgw_job_stat; + +-- +-- Set bgw log level and reload config. +-- +-- Debug messages should be in log now which it wasn't before. +-- +\c :TEST_DBNAME :ROLE_SUPERUSER +ALTER SYSTEM SET timescaledb.bgw_log_level = 'DEBUG1'; +SELECT pg_reload_conf(); + +SELECT ts_bgw_params_reset_time(0, false); +INSERT INTO _timescaledb_config.bgw_job( + application_name, + schedule_interval, + max_runtime, + max_retries, + retry_period, + proc_schema, + proc_name, + owner, + scheduled, + fixed_schedule +) VALUES ( + 'test_job_1b', --application_name + INTERVAL '100ms', --schedule_interval + INTERVAL '100s', --max_runtime + 5, --max_retries + INTERVAL '1s', --retry_period + 'public', --proc_schema + 'bgw_test_job_1', --proc_name + CURRENT_ROLE::regrole, --owner + TRUE, --scheduled + FALSE --fixed_schedule +) RETURNING id AS job_id \gset + +SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 0); +SELECT * FROM cleaned_bgw_log; + +ALTER SYSTEM RESET timescaledb.bgw_log_level; +SELECT pg_reload_conf(); + +TRUNCATE bgw_log; +SELECT ts_bgw_params_reset_time(0, false); +SELECT ts_bgw_db_scheduler_test_run_and_wait_for_scheduler_finish(25, 0); +SELECT * FROM cleaned_bgw_log; + +SELECT delete_job(:job_id);