multiple jobs added at same time may not all execute before being destroyed with self destruct true and @every schedule

[gaslitbytech]

Describe the bug
When creating a script to backfill some data that didn't load with unrelated issues the function timetable.add_job with job_schedule using timetable.cron of '@every 1 day' and job_self_destruct true .

To Reproduce
Steps to reproduce the behaviour:

Add 2 or more jobs using timetable.add_job with @every schedule and self destruct is true.

SELECT timetable.add_job(
            job_name => 'daily task backfill:' || to_char(dates.date, 'yyyy-mm-dd'),
            job_command => 'sh',
            job_parameters =>jsonb_build_array(
                '-c',
                format('/daily-script.sh %s',to_char(dates.date, 'yyyy-mm-dd'))
            )::jsonb,
            job_kind => timetable.command_kind 'PROGRAM',
            job_schedule => '@every 1 day'::timetable.cron,
            --job_schedule =>  format('%s * * * *', to_char(now() + interval '1 minutes','MI'))::timetable.cron, -- workaround as self destruct seems to work with traditional cron time.
            job_max_instances => 1,
            job_live => true,
            job_self_destruct => true  -- if this is true this with a @every job schedule it is itermittent. if false debugging it is consistent.
        )
        from ( VALUES
            ('2023-10-08'::date),
            ('2023-10-11'::date),
            ('2023-10-31'::date)
        ) dates(date)
        ;

Expected behavior
I would expect after a minute three jobs are added (they are) and then destroyed (they are), they all executed in the execution log (they are though mostly only 1 or 2 with output of INSERT 0 1), and finally the jobs are actually run (Should be 3 rows in the example public.daily_task table. If only 1 or 2 rows are executed successfully I'd also expect the remaining timetable.task to be present for the next day as per @every 1 day though they seem prematurely destroyed.

This does seem a little intermittent though I only seen all 3 jobs execute successfully once though often just 1 or 2 jobs execute.

Additional context
When changing job_self_destruct => false all 3 jobs are executed.

Or can keep the job_self_destruct => true and change the timetable.cron to specify an minute in the future like job_schedule => format('%s * * * *', to_char(now() + interval '1 minutes','MI'))::timetable.cron and all 3 jobs are executed and destroyed as wanted.

Full reproduceable test script:

#!/usr/bin/env bash
set -euo pipefail # Exit with nonzero exit code if anything fails
set -x # Display commands and their arguments as they are executed.

daily_script=$(mktemp /tmp/daily-script.XXXXXX)
cat << 'EOF' > ${daily_script}
#!/usr/bin/env sh
param_date=${1:-$(TZ='Australia/Brisbane' date -d yesterday +"%Y-%m-%d")}
PGPASSWORD=mysecretpassword psql --host postgres --username postgres --dbname postgres -c "INSERT INTO public.daily_task(created_date, message) VALUES ('${param_date}', 'test');"
EOF
chmod +x ${daily_script}

# for us this would be in a sql file in the repo handled by sqitch
daily_script_kickoff=$(mktemp /tmp/daily-script-kickoff.XXXXXX)
cat << 'EOF' > ${daily_script_kickoff}
        SELECT timetable.add_job(
            job_name => 'daily task backfill:' || to_char(dates.date, 'yyyy-mm-dd'),
            job_command => 'sh',
            job_parameters =>jsonb_build_array(
                '-c',
                format('/daily-script.sh %s',to_char(dates.date, 'yyyy-mm-dd'))
            )::jsonb,
            job_kind => timetable.command_kind 'PROGRAM',
            job_schedule => '@every 1 day'::timetable.cron,
            --job_schedule =>  format('%s * * * *', to_char(now() + interval '1 minutes','MI'))::timetable.cron, --'@every 1 minute'::timetable.cron,  -- workaround as self destruct seems to work with traditional cron time.
            job_max_instances => 1,
            job_live => true,
            job_self_destruct => true  -- if this is true this with a @every job schedule it is itermittent. if false debugging it is consistent.
        )
        from ( VALUES
            ('2023-10-08'::date),
            ('2023-10-11'::date),
            ('2023-10-31'::date)
        ) dates(date)
        ;
EOF

{
  for version in "5.7"; do  # "5.4" "5.6" "5.7"
    docker rm -f postgres pg-timetable-init-only pg-timetable-worker001 || true
    docker run --rm --name postgres \
    -p 54321:5432 \
    -v "${daily_script_kickoff}:/daily-script-kickoff.sql" \
    -ePOSTGRES_USER=postgres -e POSTGRES_PASSWORD=mysecretpassword \
    -d postgres:13.11  # pg version found issue is 13.11.
    timeout 90s /usr/bin/env bash -c "until docker exec postgres pg_isready ; do sleep 5 ; done" # wait for db to be ready

    docker exec postgres psql --username postgres --dbname postgres -c "CREATE TABLE public.daily_task(id serial, created_date date, message text);"

    docker run \
      --name=pg-timetable-init-only \
      --link "postgres:postgres" \
      cybertecpostgresql/pg_timetable:$version \
      -h postgres -p 5432 -d postgres -u postgres --password mysecretpassword -c init-only --init
    echo "$? - exit code for pg_timetable: $version "

    docker run -d \
      --name=pg-timetable-worker001 \
      --link "postgres:postgres" \
      -v "${daily_script}:/daily-script.sh" \
      cybertecpostgresql/pg_timetable:$version \
      -h postgres -p 5432 -d postgres -u postgres --password mysecretpassword -c worker001

    docker exec postgres psql --username postgres --dbname postgres -f daily-script-kickoff.sql

    original_task_count=-1
    original_task_count=$(docker exec postgres psql --username postgres --dbname postgres -X -A -t -c "SELECT count(*) FROM timetable.task;")
    echo "original task count: $original_task_count"


    sleep 60 # sleep for 1 minute

    execution_log_count=0
    while [[ $execution_log_count == 0 ]] ;
    do
        sleep 5 # sleep for 5 seconds
        execution_log_count=$(docker exec postgres psql --username postgres --dbname postgres -X -A -t -c "SELECT count(*) FROM timetable.execution_log;")
        echo "execution_log_count: $execution_log_count"
    done

    insert_count=-1
    insert_count=$(docker exec postgres psql --username postgres --dbname postgres -X -A -t -c "SELECT count(*) FROM public.daily_task;")

    updated_task_count=-1
    updated_task_count=$(docker exec postgres psql --username postgres --dbname postgres -X -A -t -c "SELECT count(*) FROM timetable.task;")
    echo "updated task count: $updated_task_count"


    echo "original task count: $original_task_count vs updated task count: $updated_task_count vs execution_log_count: $execution_log_count vs insert count: $insert_count"
    echo $(docker exec postgres psql --username postgres --dbname postgres -c "select el.kind, el.command, el.returncode, el.output from timetable.execution_log el;");
    echo $(docker exec postgres psql --username postgres --dbname postgres -c "SELECT * FROM timetable.task;");
    echo $(docker exec postgres psql --username postgres --dbname postgres -c "SELECT * FROM public.daily_task;");
  done
}

Results

+++ mktemp /tmp/daily-script.XXXXXX
++ daily_script=/tmp/daily-script.4RzEu7
++ cat
++ chmod +x /tmp/daily-script.4RzEu7
+++ mktemp /tmp/daily-script-kickoff.XXXXXX
++ daily_script_kickoff=/tmp/daily-script-kickoff.hte5Gb
++ cat
++ for version in "5.7"
++ docker rm -f postgres pg-timetable-init-only pg-timetable-worker001
postgres
pg-timetable-init-only
pg-timetable-worker001
++ docker run --rm --name postgres -p 54321:5432 -v /tmp/daily-script-kickoff.hte5Gb:/daily-script-kickoff.sql -ePOSTGRES_USER=postgres -e POSTGRES_PASSWORD=mysecretpassword -d postgres:13.11
6b924481ab84095909222eb252d4cbebe08ac68419e394a012060965401d5597
++ timeout 90s /usr/bin/env bash -c 'until docker exec postgres pg_isready ; do sleep 5 ; done'
/var/run/postgresql:5432 - no response
/var/run/postgresql:5432 - accepting connections
++ docker exec postgres psql --username postgres --dbname postgres -c 'CREATE TABLE public.daily_task(id serial, created_date date, message text);'
CREATE TABLE
++ docker run --name=pg-timetable-init-only --link postgres:postgres cybertecpostgresql/pg_timetable:5.7 -h postgres -p 5432 -d postgres -u postgres --password mysecretpassword -c init-only --init
2023-12-31 02:09:42.207 [INFO] [port:8008] Starting REST API server...
2023-12-31 02:09:42.207 [INFO] [sid:1102520019] Starting new session... 
2023-12-31 02:09:42.210 [INFO] Database connection established
2023-12-31 02:09:42.212 [INFO] Executing script: Schema Init
2023-12-31 02:09:42.216 [INFO] Schema file executed: Schema Init
2023-12-31 02:09:42.216 [INFO] Executing script: Cron Functions
2023-12-31 02:09:42.221 [INFO] Schema file executed: Cron Functions
2023-12-31 02:09:42.221 [INFO] Executing script: Tables and Views
2023-12-31 02:09:42.247 [INFO] Schema file executed: Tables and Views
2023-12-31 02:09:42.247 [INFO] Executing script: JSON Schema
2023-12-31 02:09:42.249 [INFO] Schema file executed: JSON Schema
2023-12-31 02:09:42.249 [INFO] Executing script: Job Functions
2023-12-31 02:09:42.251 [INFO] Schema file executed: Job Functions
2023-12-31 02:09:42.251 [INFO] Configuration schema created...
2023-12-31 02:09:42.252 [INFO] Closing session
++ echo '0 - exit code for pg_timetable: 5.7 '
0 - exit code for pg_timetable: 5.7 
++ docker run -d --name=pg-timetable-worker001 --link postgres:postgres -v /tmp/daily-script.4RzEu7:/daily-script.sh cybertecpostgresql/pg_timetable:5.7 -h postgres -p 5432 -d postgres -u postgres --password mysecretpassword -c worker001
bfa3beba3caf6e31b54a4949b6c77592a061e5ffa89a4f258e2c3e4050c82b70
++ docker exec postgres psql --username postgres --dbname postgres -f daily-script-kickoff.sql
 add_job 
---------
       1
       2
       3
(3 rows)

++ original_task_count=-1
+++ docker exec postgres psql --username postgres --dbname postgres -X -A -t -c 'SELECT count(*) FROM timetable.task;'
++ original_task_count=3
++ echo 'original task count: 3'
original task count: 3
++ sleep 60
++ execution_log_count=0
++ [[ 0 == 0 ]]
++ sleep 5
+++ docker exec postgres psql --username postgres --dbname postgres -X -A -t -c 'SELECT count(*) FROM timetable.execution_log;'
++ execution_log_count=3
++ echo 'execution_log_count: 3'
execution_log_count: 3
++ [[ 3 == 0 ]]
++ insert_count=-1
+++ docker exec postgres psql --username postgres --dbname postgres -X -A -t -c 'SELECT count(*) FROM public.daily_task;'
++ insert_count=2
++ updated_task_count=-1
+++ docker exec postgres psql --username postgres --dbname postgres -X -A -t -c 'SELECT count(*) FROM timetable.task;'
++ updated_task_count=0
++ echo 'updated task count: 0'
updated task count: 0
++ echo 'original task count: 3 vs updated task count: 0 vs execution_log_count: 3 vs insert count: 2'
original task count: 3 vs updated task count: 0 vs execution_log_count: 3 vs insert count: 2
+++ docker exec postgres psql --username postgres --dbname postgres -c 'select el.kind, el.command, el.returncode, el.output from timetable.execution_log el;'
++ echo kind '|' command '|' returncode '|' output ---------+---------+------------+------------ PROGRAM '|' sh '|' 0 '|' INSERT 0 1 PROGRAM '|' sh '|' 0 '|' PROGRAM '|' sh '|' 0 '|' INSERT 0 1 '(3' 'rows)'
kind | command | returncode | output ---------+---------+------------+------------ PROGRAM | sh | 0 | INSERT 0 1 PROGRAM | sh | 0 | PROGRAM | sh | 0 | INSERT 0 1 (3 rows)
+++ docker exec postgres psql --username postgres --dbname postgres -c 'SELECT * FROM timetable.task;'
++ echo task_id '|' chain_id '|' task_order '|' task_name '|' kind '|' command '|' run_as '|' database_connection '|' ignore_error '|' autonomous '|' timeout ---------+----------+------------+-----------+------+---------+--------+---------------------+--------------+------------+--------- '(0' 'rows)'
task_id | chain_id | task_order | task_name | kind | command | run_as | database_connection | ignore_error | autonomous | timeout ---------+----------+------------+-----------+------+---------+--------+---------------------+--------------+------------+--------- (0 rows)
+++ docker exec postgres psql --username postgres --dbname postgres -c 'SELECT * FROM public.daily_task;'
++ echo id '|' created_date '|' message ----+--------------+--------- 1 '|' 2023-10-31 '|' test 2 '|' 2023-10-08 '|' test '(2' 'rows)'
id | created_date | message ----+--------------+--------- 1 | 2023-10-31 | test 2 | 2023-10-08 | test (2 rows)

I realised our pg version of 13.11 is getting quite old though just reproduced with 15.5 to be sure before submitting.

[pashagolub]

Thanks for pointing this out! Would you please check #637

[gaslitbytech]

I've verified that it works as I expect with the latest docker tag now. Thank you.