MaxRunning and MaxConcurrency are not respected when the jobs runs longer than scheduled

[hammer90]

Hello,

jobs are executed in parallel in case the job runs longer than the scheduling interval even if configured with withConcurrency(1) and withMaxRunning(1). A minimal sample can be found here: https://github.com/hammer90/momo-scheduling

steps to reproduce:

• define a job to run every ten seconds
• let the job sleep for 30 seconds

expected result:

• job is always executed only once

actual result:

• after the first execution of the job the job is executed in parallel
• with the timing from above constantly three times in parallel

Some logs from the sample repo:

{
  message: 'define job',
  data: {
    name: 'job',
    concurrency: 1,
    interval: '10 seconds',
    parsedInterval: 10000,
    firstRunAfter: 0,
    parsedFirstRunAfter: 0,
    maxRunning: 1
  }
}
{ message: 'save job to database', data: { name: 'job' } }
{ message: 'starting the schedule', data: { jobCount: 1 } }
{
  message: 'This schedule is active',
  data: {
    name: 'scheduler',
    scheduleId: '3fc2db87-ccdf-4cb3-b1cb-9adf750e0309'
  }
}
{
  message: 'This schedule just turned active',
  data: {
    name: 'scheduler',
    scheduleId: '3fc2db87-ccdf-4cb3-b1cb-9adf750e0309'
  }
}
{
  message: 'scheduled job to run at 2023-12-01T11:01:46.243+01:00',
  data: { name: 'job', interval: '10 seconds', firstRunAfter: 0 }
}
{
  message: 'Finished starting scheduled jobs',
  data: {
    name: 'scheduler',
    scheduleId: '3fc2db87-ccdf-4cb3-b1cb-9adf750e0309'
  }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting ff4eca29-1973-46d7-a294-601cce465980, jobs running 1
{ message: 'execute job', data: { name: 'job', times: 0 } }
{ message: 'execute job', data: { name: 'job', times: 0 } }
finished ff4eca29-1973-46d7-a294-601cce465980
{ message: 'execute job', data: { name: 'job', times: 0 } }
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting 9b3359da-bd7c-4b2b-bae2-4cbd1838e891, jobs running 1
{ message: 'execute job', data: { name: 'job', times: 0 } }
{
  message: 'This schedule is active',
  data: {
    name: 'scheduler',
    scheduleId: '3fc2db87-ccdf-4cb3-b1cb-9adf750e0309'
  }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting acdcc925-910c-4aa0-963f-c562398a15f1, jobs running 2
finished 9b3359da-bd7c-4b2b-bae2-4cbd1838e891
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting ff2f6409-ce71-4641-854e-f3fd7daf0d4c, jobs running 2
{ message: 'execute job', data: { name: 'job', times: 0 } }
finished acdcc925-910c-4aa0-963f-c562398a15f1
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting 11635d6a-2ac1-4a79-aa50-0082aefca0d6, jobs running 2
finished ff2f6409-ce71-4641-854e-f3fd7daf0d4c
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting e6edcc53-6d8e-4951-94d6-de00fd90815c, jobs running 2
{ message: 'execute job', data: { name: 'job', times: 0 } }
{
  message: 'This schedule is active',
  data: {
    name: 'scheduler',
    scheduleId: '3fc2db87-ccdf-4cb3-b1cb-9adf750e0309'
  }
}
finished 11635d6a-2ac1-4a79-aa50-0082aefca0d6
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting 274e08b8-064f-4095-8a64-7afc3dc99b8f, jobs running 2
finished e6edcc53-6d8e-4951-94d6-de00fd90815c
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting e1a38fbc-77db-4f9e-a145-0b770eccb505, jobs running 2
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting 0fa1285c-f663-4eb7-9aaa-c717362039ec, jobs running 3
finished 274e08b8-064f-4095-8a64-7afc3dc99b8f
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting 4974b69f-8ac7-447c-b973-a1ec40579d1b, jobs running 3
finished e1a38fbc-77db-4f9e-a145-0b770eccb505
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}
{ message: 'execute job', data: { name: 'job', times: 1 } }
{ message: 'run job', data: { name: 'job' } }
starting d6e9eeac-6aa6-4487-8773-2e142b7d0915, jobs running 3
finished 0fa1285c-f663-4eb7-9aaa-c717362039ec
{
  message: 'finished job',
  data: { name: 'job', status: 'finished', stopped: false }
}

best regards
Sebastian

[weissu42]

Thanks for reporting this. @YaniKolev was able to reproduce this.

We found the bug already, the problem is that the internal ping accidentally overwrites the information on how often the job is already running. Working on a fix.

[hammer90]

Thank you for fixing it so fast.