Job exiting before finished

[rileymd88]

Hi I am having a small issue where the job is finishing and exiting before it is finished. Here is the code for my job:

import { parentPort, workerData } from 'worker_threads'
import * as c from '../controller.js'

// store boolean if the job is cancelled
let isCancelled = false;

// handle cancellation (this is a very simple example)
if (parentPort)
  parentPort.once('message', message => {
    if (message === 'cancel') isCancelled = true;
  });

(async () => {
  try {
   console.log('running')
    let email = 'myemail@gmail.com'
    let id = 'drTXEEyI5FCl3YSg'
    const automation = await c.getAutomation(email, id)
    const checkAutomation = await c.checkTimeAutomation(email, automation)
    if (checkAutomation) {
      await c.triggerActions(automation.carId, email, automation.actions)
    }
    console.log('done')
  }
  catch (err) {
    console.error(err)
  }
  if (parentPort) {
    parentPort.postMessage('done');
  }
  else {
    process.exit(0);
  }
})();

What I see in the console is the following:

Worker for job "firstRun!" signaled completion { message: 'done' }
running
done

If I run the same example in a seperate file then it works without any issues:

import * as c from './controller.js'

async function run() {
    try {
        console.log('running')
        let email = 'myemail@gmail.com'
        let id = 'drTXEEyI5FCl3YSg'
        const automation = await c.getAutomation(email, id)
        const checkAutomation = await c.checkTimeAutomation(email, automation)
        if (checkAutomation) {
            await c.triggerActions(automation.carId, email, automation.actions)
        }
        console.log('done')
    }
    catch(err) {
        console.error(err)
    }
}
run()

What I see in the console is then the following:

running
done

Thanks,
Riley

[shadowgate15]

see #108 about console calls.

[rileymd88]

Thanks for your quick response @shadowgate15

After removing the console calls the job is still exiting before it is finished. Any ideas? I am really unsure why this is happening.

[shadowgate15]

What is the debug log from Bree when you try to run it?

[rileymd88]

@shadowgate15 How would I generate a debug log? I saw that you are able to add a logger and manually log some messages but nothing about how to run Bree in debug mode to generate logs. Thanks

[shadowgate15]

just set the DEBUG environment variable to *

[rileymd88]

Thank you again for taking your time to help me.. I should also add how I add the job in the first place:

import Bree from 'bree'
import Graceful from '@ladjs/graceful'
import crypto from 'crypto'

const genRandomString = async (length) => {
    return crypto.randomBytes(Math.ceil(length / 2))
        .toString('hex') /** convert to hexadecimal format */
        .slice(0, length);   /** return required number of characters */
}

const bree = new Bree({
    jobs: [
        {
            name: `firstRun!`,
            path: './jobs/timeTriggered.js',
            worker: {
                workerData: {
                    id: 'firstRun'
                }
            }
        }
    ]
});

// handle graceful reloads, pm2 support, and events like SIGHUP, SIGINT, etc.
const graceful = new Graceful({ brees: [bree] });
graceful.listen();

// start all jobs (this is the equivalent of reloading a crontab):
bree.start();

export async function addJob(id,t) {
    const randomId = await genRandomString(16)
    const job = {
        name: `${id}_${randomId}`,
        path: './jobs/timeTriggered.js',
        interval: t,
        worker: {
            workerData: {
                id: id
            }
        }
    }
    bree.add(job)
    bree.start()
}

The add job function is being used within an express route so that I add new jobs via a REST call.

Here is the debug log. I did the following when generating these logs:

1. I started my express server (this kicks of the firstRun job)
2. I sent a REST call to my express server to schedule the job to run at 10:48 pm

  bree config {
  logger: Object [console] {     
    log: [Function: log],        
    warn: [Function: warn],      
    dir: [Function: dir],        
    time: [Function: time],      
    timeEnd: [Function: timeEnd],
    timeLog: [Function: timeLog],
    trace: [Function: trace],
    assert: [Function: assert],
    clear: [Function: clear],
    count: [Function: count],
    countReset: [Function: countReset],
    group: [Function: group],
    groupEnd: [Function: groupEnd],
    table: [Function: table],
    debug: [Function: debug],
    info: [Function: info],
    dirxml: [Function: dirxml],
    error: [Function: error],
    groupCollapsed: [Function: groupCollapsed],
    Console: [Function: Console],
    profile: [Function: profile],
    profileEnd: [Function: profileEnd],
    timeStamp: [Function: timeStamp],
    context: [Function: context]
  },
  root: 'server\\cache\\jobs',
  timeout: 0,
  interval: 0,
  jobs: [
    {
      name: 'firstRun!',
      path: './jobs/timeTriggered.js',
      worker: [Object]
    }
  ],
  hasSeconds: false,
  cronValidate: {},
  closeWorkerAfterMs: 0,
  defaultExtension: 'js',
  worker: {},
  errorHandler: null,
  workerMessageHandler: null,
  outputWorkerMetadata: false
} +0ms
  bree timeout 0 +8ms
  bree interval 0 +0ms
  bree this.config.jobs [
  {
    name: 'firstRun!',
    path: './jobs/timeTriggered.js',
    worker: { workerData: [Object] },
    timeout: 0
  }
] +1ms
  bree start undefined +1ms
  bree start firstRun! +1ms
  bree job {
  name: 'firstRun!',
  path: './jobs/timeTriggered.js',
  worker: { workerData: { id: 'firstRun' } },
  timeout: 0
} +0ms
  bree job timeout is finite {
  name: 'firstRun!',
  path: './jobs/timeTriggered.js',
  worker: { workerData: { id: 'firstRun' } },
  timeout: 0
} +0ms
  express:router:route new '/addStateKeys' +0ms
  express:router:layer new '/addStateKeys' +1ms
  express:router:route post '/addStateKeys' +1ms
  express:router:layer new '/' +0ms
  express:router:route new '/deleteStateKeys' +0ms
  express:router:layer new '/deleteStateKeys' +1ms
  express:router:route delete '/deleteStateKeys' +0ms
  express:router:layer new '/' +0ms
  express:router:route new '/addGeofenceStateKeys' +1ms
  express:router:layer new '/addGeofenceStateKeys' +0ms
  express:router:route post '/addGeofenceStateKeys' +0ms
  express:router:layer new '/' +1ms
  express:router:route new '/deleteGeofenceStateKeys' +0ms
  express:router:layer new '/deleteGeofenceStateKeys' +1ms
  express:router:route delete '/deleteGeofenceStateKeys' +0ms
  express:router:layer new '/' +0ms
  express:router:route new '/startStreaming' +0ms
  express:router:layer new '/startStreaming' +0ms
  express:router:route post '/startStreaming' +1ms
  express:router:layer new '/' +0ms
  express:application set "x-powered-by" to true +0ms
  express:application set "etag" to 'weak' +1ms
  express:application set "etag fn" to [Function: generateETag] +0ms
  express:application set "env" to 'dev ' +0ms
  express:application set "query parser" to 'extended' +0ms
  express:application set "query parser fn" to [Function: parseExtendedQueryString] +1ms
  express:application set "subdomain offset" to 2 +0ms
  express:application set "trust proxy" to false +0ms
  express:application set "trust proxy fn" to [Function: trustNone] +0ms
  express:application booting in dev  mode +0ms
  express:application set "view" to [Function: View] +1ms
  express:application set "views" to 'server\\cache\\views' +0ms
  express:application set "jsonp callback name" to 'callback' +0ms
  express:router use '/' query +1ms
  express:router:layer new '/' +0ms
  express:router use '/' expressInit +0ms
  express:router:layer new '/' +0ms
  express:router use '/' jsonParser +1ms
  express:router:layer new '/' +0ms
  express:router use '/api/v1' router +0ms
  express:router:layer new '/api/v1' +0ms
Connected!
  bree run firstRun! +34ms
  bree starting worker firstRun! +0ms
  bree worker started firstRun! +2ms
Worker for job "firstRun!" online undefined
2021-06-08T20:45:32.018Z bree config {
  logger: Object [console] {
    log: [Function: log],
    warn: [Function: warn],
    dir: [Function: dir],
    time: [Function: time],
    timeEnd: [Function: timeEnd],
    timeLog: [Function: timeLog],
    trace: [Function: trace],
    assert: [Function: assert],
    clear: [Function: clear],
    count: [Function: count],
    countReset: [Function: countReset],
    group: [Function: group],
    groupEnd: [Function: groupEnd],
    table: [Function: table],
    debug: [Function: debug],
    info: [Function: info],
    dirxml: [Function: dirxml],
    error: [Function: error],
    groupCollapsed: [Function: groupCollapsed],
    Console: [Function: Console],
    profile: [Function: profile],
    profileEnd: [Function: profileEnd],
    timeStamp: [Function: timeStamp],
    context: [Function: context]
  },
  root: 'server\\cache\\jobs',
  timeout: 0,
  interval: 0,
  jobs: [
    {
      name: 'firstRun!',
      path: './jobs/timeTriggered.js',
      worker: [Object]
    }
  ],
  hasSeconds: false,
  cronValidate: {},
  closeWorkerAfterMs: 0,
  defaultExtension: 'js',
  worker: {},
  errorHandler: null,
  workerMessageHandler: null,
  outputWorkerMetadata: false
}
Worker for job "firstRun!" signaled completion { message: 'done' }
  express:router dispatching POST /api/v1/addStateKeys +2m
  express:router query  : /api/v1/addStateKeys +1ms
  express:router expressInit  : /api/v1/addStateKeys +0ms
  express:router jsonParser  : /api/v1/addStateKeys +1ms
  body-parser:json content-type "application/json" +0ms
  body-parser:json content-encoding "identity" +1ms
  body-parser:json read body +0ms
  body-parser:json parse body +11ms
  body-parser:json parse json +0ms
  express:router trim prefix (/api/v1) from url /api/v1/addStateKeys +0ms
  express:router router /api/v1 : /api/v1/addStateKeys +1ms
  express:router dispatching POST /addStateKeys +0ms
  bree jobs added [
  {
    name: 'firstRun!',
    path: './jobs/timeTriggered.js',
    worker: { workerData: [Object] },
    timeout: 0
  },
  {
    name: 'myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222',
    path: './jobs/timeTriggered.js',
    interval: { schedules: [Array], exceptions: [], error: -1 },
    worker: { workerData: [Object] }
  }
] +2m
  bree start undefined +2ms
  bree start firstRun! +0ms
  bree job {
  name: 'firstRun!',
  path: './jobs/timeTriggered.js',
  worker: { workerData: { id: 'firstRun' } },
  timeout: 0
} +0ms
  bree job timeout is finite {
  name: 'firstRun!',
  path: './jobs/timeTriggered.js',
  worker: { workerData: { id: 'firstRun' } },
  timeout: 0
} +1ms
  bree start myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222 +1ms
  bree job {
  name: 'myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222',
  path: './jobs/timeTriggered.js',
  interval: { schedules: [ [Object] ], exceptions: [], error: -1 },
  worker: { workerData: { id: 'myemail@gmail.com,m57Wu4OAoI03wx7c' } }
} +0ms
  bree job.interval is schedule {
  name: 'myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222',
  path: './jobs/timeTriggered.js',
  interval: { schedules: [ [Object] ], exceptions: [], error: -1 },
  worker: { workerData: { id: 'myemail@gmail.com,m57Wu4OAoI03wx7c' } }
} +0ms
  bree run firstRun! +4ms
  bree starting worker firstRun! +1ms
  bree worker started firstRun! +1ms
Worker for job "firstRun!" online undefined
2021-06-08T20:47:02.987Z bree config {
  logger: Object [console] {
    log: [Function: log],
    warn: [Function: warn],
    dir: [Function: dir],
    time: [Function: time],
    timeEnd: [Function: timeEnd],
    timeLog: [Function: timeLog],
    trace: [Function: trace],
    assert: [Function: assert],
    clear: [Function: clear],
    count: [Function: count],
    countReset: [Function: countReset],
    group: [Function: group],
    groupEnd: [Function: groupEnd],
    table: [Function: table],
    debug: [Function: debug],
    info: [Function: info],
    dirxml: [Function: dirxml],
    error: [Function: error],
    groupCollapsed: [Function: groupCollapsed],
    Console: [Function: Console],
    profile: [Function: profile],
    profileEnd: [Function: profileEnd],
    timeStamp: [Function: timeStamp],
    context: [Function: context]
  },
  root: 'server\\cache\\jobs',
  timeout: 0,
  interval: 0,
  jobs: [
    {
      name: 'firstRun!',
      path: './jobs/timeTriggered.js',
      worker: [Object]
    }
  ],
  hasSeconds: false,
  cronValidate: {},
  closeWorkerAfterMs: 0,
  defaultExtension: 'js',
  worker: {},
  errorHandler: null,
  workerMessageHandler: null,
  outputWorkerMetadata: false
}
Worker for job "firstRun!" signaled completion { message: 'done' }
  bree run myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222 +57s
  bree starting worker myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222 +1ms
  bree worker started myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222 +1ms
Worker for job "myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222" online undefined
2021-06-08T20:48:00.414Z bree config {
  logger: Object [console] {
    log: [Function: log],
    warn: [Function: warn],
    dir: [Function: dir],
    time: [Function: time],
    timeEnd: [Function: timeEnd],
    timeLog: [Function: timeLog],
    trace: [Function: trace],
    assert: [Function: assert],
    clear: [Function: clear],
    count: [Function: count],
    countReset: [Function: countReset],
    group: [Function: group],
    groupEnd: [Function: groupEnd],
    table: [Function: table],
    debug: [Function: debug],
    info: [Function: info],
    dirxml: [Function: dirxml],
    error: [Function: error],
    groupCollapsed: [Function: groupCollapsed],
    Console: [Function: Console],
    profile: [Function: profile],
    profileEnd: [Function: profileEnd],
    timeStamp: [Function: timeStamp],
    context: [Function: context]
  },
  root: 'server\\cache\\jobs',
  timeout: 0,
  interval: 0,
  jobs: [
    {
      name: 'firstRun!',
      path: './jobs/timeTriggered.js',
      worker: [Object]
    }
  ],
  hasSeconds: false,
  cronValidate: {},
  closeWorkerAfterMs: 0,
  defaultExtension: 'js',
  worker: {},
  errorHandler: null,
  workerMessageHandler: null,
  outputWorkerMetadata: false
}
2021-06-08T20:48:00.416Z bree timeout 0
2021-06-08T20:48:00.416Z bree interval 0
2021-06-08T20:48:00.417Z bree this.config.jobs [
  {
    name: 'firstRun!',
    path: './jobs/timeTriggered.js',
    worker: { workerData: [Object] },
    timeout: 0
  }
]
2021-06-08T20:48:00.418Z bree start undefined
2021-06-08T20:48:00.418Z bree start firstRun!
2021-06-08T20:48:00.418Z bree job {
  name: 'firstRun!',
  path: './jobs/timeTriggered.js',
  worker: { workerData: { id: 'firstRun' } },
  timeout: 0
}
2021-06-08T20:48:00.418Z bree job timeout is finite {
  name: 'firstRun!',
  path: './jobs/timeTriggered.js',
  worker: { workerData: { id: 'firstRun' } },
  timeout: 0
}
2021-06-08T20:48:00.433Z bree run firstRun!
2021-06-08T20:48:00.433Z bree starting worker firstRun!
2021-06-08T20:48:00.435Z bree worker started firstRun!
Worker for job "firstRun!" online undefined
2021-06-08T20:48:00.832Z bree config {
  logger: Object [console] {
    log: [Function: log],
    warn: [Function: warn],
    dir: [Function: dir],
    time: [Function: time],
    timeEnd: [Function: timeEnd],
    timeLog: [Function: timeLog],
    trace: [Function: trace],
    assert: [Function: assert],
    clear: [Function: clear],
    count: [Function: count],
    countReset: [Function: countReset],
    group: [Function: group],
    groupEnd: [Function: groupEnd],
    table: [Function: table],
    debug: [Function: debug],
    info: [Function: info],
    dirxml: [Function: dirxml],
    error: [Function: error],
    groupCollapsed: [Function: groupCollapsed],
    Console: [Function: Console],
    profile: [Function: profile],
    profileEnd: [Function: profileEnd],
    timeStamp: [Function: timeStamp],
    context: [Function: context]
  },
  root: 'server\\cache\\jobs',
  timeout: 0,
  interval: 0,
  jobs: [
    {
      name: 'firstRun!',
      path: './jobs/timeTriggered.js',
      worker: [Object]
    }
  ],
  hasSeconds: false,
  cronValidate: {},
  closeWorkerAfterMs: 0,
  defaultExtension: 'js',
  worker: {},
  errorHandler: null,
  workerMessageHandler: null,
  outputWorkerMetadata: false
}
Worker for job "firstRun!" signaled completion { message: 'done' }
Worker for job "myemail@gmail.com,m57Wu4OAoI03wx7c_85b03ab64d35b222" signaled completion { message: 'done' }

[shadowgate15]

so a few things to note. under your current setup every time you add a new job it will run all of the jobs again.
Bree does not remove jobs after the worker has completed. This is something you would need to designate via a listener on worker deleted.

I would change bree.start() in addJob() to bree.start(job.name) This way only that job is started and not all of the jobs.

how do you know the job is exiting before it is finished? It does not look as though bree is returning any errors from the worker.

[rileymd88]

@shadowgate15 I know that the job is exiting before it is finished as triggerActions makes some API calls which are not reaching the server. I am still very unsure where the problem lies.

[shadowgate15]

Is the problem coming from within that if statement that would stop triggerActions from being called.

[rileymd88]

Hi @shadowgate15 No there is no problem with that if statement...Exact same code works when not being triggered through a job. Also if I remove this following code from the job, then it works fine:

  if (parentPort) {
    parentPort.postMessage('done');
  }
  else {
    process.exit(0);
  }

[shadowgate15]

hmm... strange. This definitely seems like a potential issue with Node Workers and not Bree. Are you certain that triggerActions returns a promise?

[sumanchalki]

Facing the same issue, when the job (worker thread) contains a promise and waits for it to be completed. Worker thread is returning before completion.
A simple promise with setTimeout does not even work for me.

[shadowgate15]

make sure that your promise returns before sending done.