Test case clears locks on stop fails when run in a local machine.

[sampathBlam]

I was trying to debug why the a particular test case ( Job - 'clears locks on stop') is failing in Travis CI for #874
(Note: someone has already raised an issue for that - #855, added some fixes for them - #852, but the issue has reappeared again and is not fixed)

Hence I tried to run the tests in my local machine checking out code from the master branch. The test case in question, failed in my local machine too. But with a different error message.
Apparently this test case tries to test if a locked job is cleared on stopping the agenda instance. When I ran the test suite in my local machine, the assertion completes before the job was unlocked. Because of which the test case fails.

I tried changing the job timeout from 500ms to 2500ms (similar to what is being set for Travis). But the same issue prevails. I have attached the debug logs as well for this scenario.

I am running the test suite in a Windows 10 machine.
Node version: 10.16.3
Mongo version: 4.2.1

  agenda:define job [longRunningJob] defined with following options:
  agenda:define { fn: [Function],
  agenda:define   concurrency: 5,
  agenda:define   lockLimit: 0,
  agenda:define   priority: 0,
  agenda:define   lockLifetime: 600000,
  agenda:define   running: 0,
  agenda:define   locked: 0 } +3ms
  agenda:every Agenda.every(10 seconds, 'longRunningJob', undefined) +15s
  agenda:create Agenda.create(longRunningJob, [Object]) +4s
  agenda:job [longRunningJob:undefined] computing next run via interval [10 seconds] +13s
  agenda:job [longRunningJob:undefined] nextRunAt set to [2019-11-25T03:30:40.309Z] +1ms
  agenda:saveJob attempting to save a job into Agenda instance +4s
  agenda:saveJob [job undefined] set job props:
  agenda:saveJob { name: 'longRunningJob',
  agenda:saveJob   data: undefined,
  agenda:saveJob   type: 'single',
  agenda:saveJob   priority: 0,
  agenda:saveJob   nextRunAt: 2019-11-25T03:30:40.309Z,
  agenda:saveJob   repeatInterval: '10 seconds',
  agenda:saveJob   repeatTimezone: null,
  agenda:saveJob   lastModifiedBy: undefined } +1ms
  agenda:saveJob current time stored as 2019-11-25T03:30:40.314Z +3ms
  agenda:saveJob job with type of "single" found +1ms
  agenda:saveJob job has a scheduled nextRunAt time, protecting that field from upsert +2ms
  agenda:saveJob calling findOneAndUpdate() with job name and type of "single" as query +0ms
  agenda:processEvery Agenda.processEvery(NaN) +15s
  agenda:start Agenda.start called, creating interval to call processJobs every [1000ms] +4s
  agenda:internal:processJobs starting to process jobs +4s
  agenda:internal:processJobs queuing up job to process: [someJob] +0ms
  agenda:internal:processJobs job [someJob] lock status: shouldLock = true +4ms
  agenda:internal:_findAndLockNextJob _findAndLockNextJob(someJob, [Function], cb) +4s
  agenda:internal:processJobs queuing up job to process: [send email] +3ms
  agenda:internal:processJobs job [send email] lock status: shouldLock = true +1ms
  agenda:internal:_findAndLockNextJob _findAndLockNextJob(send email, [Function], cb) +3ms
  agenda:internal:processJobs queuing up job to process: [some job] +2ms
  agenda:internal:processJobs job [some job] lock status: shouldLock = true +1ms
  agenda:internal:_findAndLockNextJob _findAndLockNextJob(some job, [Function], cb) +3ms
  agenda:internal:processJobs queuing up job to process: [do work] +3ms
  agenda:internal:processJobs job [do work] lock status: shouldLock = true +1ms
  agenda:internal:_findAndLockNextJob _findAndLockNextJob(do work, [Function], cb) +5ms
  agenda:internal:processJobs queuing up job to process: [longRunningJob] +2ms
  agenda:internal:processJobs job [longRunningJob] lock status: shouldLock = true +1ms
  agenda:internal:_findAndLockNextJob _findAndLockNextJob(longRunningJob, [Function], cb) +3ms
  agenda:saveJob processDbResult() called with success, checking whether to process job immediately or not +84ms
  agenda:stop Agenda.stop called, clearing interval for processJobs() +4s
  agenda:stop Agenda._unlockJobs() +1ms
  agenda:stop no jobs to unlock +2ms
  agenda:internal:_findAndLockNextJob found a job available to lock, creating a new job on Agenda with id [5ddb4ae038e2a679a0f27ee9] +2s
  agenda:internal:processJobs [longRunningJob:5ddb4ae038e2a679a0f27ee9] job locked while filling queue +2s
  agenda:internal:processJobs job [longRunningJob] lock status: shouldLock = true +1ms
  agenda:internal:_findAndLockNextJob _findAndLockNextJob(longRunningJob, [Function], cb) +3ms
  agenda:internal:processJobs [longRunningJob:5ddb4ae038e2a679a0f27ee9] about to process job +2ms
  agenda:internal:processJobs [longRunningJob:5ddb4ae038e2a679a0f27ee9] nextRunAt is in the past, run the job immediately +1ms
      1) clears locks on stop
  agenda:stop Agenda.stop called, clearing interval for processJobs() +3s
  agenda:stop Agenda._unlockJobs() +0ms
  agenda:stop about to unlock jobs with ids: [ 5ddb4ae038e2a679a0f27ee9 ] +1ms


  112 passing (4m)
  1 failing

  1) Job
       start/stop
         clears locks on stop:
     Error: expected Mon, 25 Nov 2019 03:30:40 GMT to equal null
      at Assertion.assert (node_modules\expect.js\index.js:96:13)
      at Assertion.be.Assertion.equal (node_modules\expect.js\index.js:216:10)
      at Assertion.(anonymous function) [as be] (node_modules\expect.js\index.js:69:24)
      at Context.it (test\job.js:627:31)
      at process._tickCallback (internal/process/next_tick.js:68:7)

[dmbarreiro]

The fixes (PR#852) were merged one day before you raised this issue and I see the last time Travis tests were run on PR#874 the fixes of PR#852 were not yet merged. Just saying this to make sure you are running with PR#852 fixes. I'll try to have a look at this this evening and see if I can reproduce it as well.

[leonardlin]

various lock issues have been fixed in the latest master branch