Add logging to the licence-import import jobs (#685)

https://eaflood.atlassian.net/browse/WATER-4024
https://eaflood.atlassian.net/browse/WATER-4039

This follows the same pattern used to get [non-noisy logging included in the NALD import jobs](#677).

Because the import process is run through jobs, it means for each company and licence to be imported, a 'job' is created. The legacy code would then log each time this happened. But when each entails creating approximately 70K jobs (140K in total!) the logs just become a sea of noise.

We implemented a pattern of including information in the job data about how many jobs in total there are, and what was the index of the current job when added to the queue. We can then use this information to log when the first job is started, and the last is completed.

In this way, we are only logging the start and end of the 'job' (even though there are thousands of them).

This change applies the same pattern to the licence-import company and licence-import jobs. We also do some tweaking to bring both NALD import and licence import in line.

src/modules/licence-import/controller.js

@@ -20,7 +20,14 @@ const postImport = async (request, h) => {
 }
 
 const postImportCompany = async (request, h) => {
- const message = ImportCompanyJob.createMessage(request.query.regionCode, request.query.partyId)
+ const { regionCode, partyId } = request.query
+ const data = {
+ regionCode,
+ partyId,
+ jobNumber: 1,
+ numberOfJobs: 1
+ }
+ const message = ImportCompanyJob.createMessage(data)
 
  try {
  await request.server.messageQueue.deleteQueue(ImportCompanyJob.name)
@@ -33,7 +40,13 @@ const postImportCompany = async (request, h) => {
 }
 
 const postImportLicence = async (request, h) => {
- const message = ImportLicenceJob.createMessage(request.query.licenceNumber)
+ const { licenceNumber } = request.query
+ const data = {
+ licenceNumber,
+ jobNumber: 1,
+ numberOfJobs: 1
+ }
+ const message = ImportLicenceJob.createMessage(data)
 
  try {
  await request.server.messageQueue.deleteQueue(ImportLicenceJob.name)

src/modules/licence-import/jobs/import-company.js

@@ -14,29 +14,50 @@ const options = {
 }
 
 /**
- * Formats arguments to publish a PG boss event to import company
+ * Data needed by the import company handler to process the job
  *
- * @param {Number} regionCode - NALD region code
- * @param {Number} partyId - NALD party ID
+ * This is a convention with PGBoss. A number of the jobs/handlers implement a `createMessage()` function which returns
+ * a data object that will be used to queue the job. When it then gets processed the data object is passed to the
+ * handler.
  *
- * @return {Object}
+ * It may also contain non-default config to be used by PGBoss when adding the job, for example, the use of
+ * `singletonKey` in this job.
+ *
+ * @param {Object} data - information needed for the handler to complete the job
+ * @param {Object.string} data.regionCode - region Code from NALD_PARTIES
+ * @param {Object.string} data.partyId - id from NALD_PARTIES
+ * @param {Object.number} data.jobNumber - index position of this job from all jobs when added to the queue
+ * @param {Object.number} data.numberOfJobs - total number of import-company jobs queued in this session
+ *
+ * @return {Object} the message object used by the handler to process the job
  */
-function createMessage (regionCode, partyId) {
+function createMessage (data) {
  return {
  name: JOB_NAME,
- data: {
- regionCode,
- partyId
- },
+ data,
  options: {
- singletonKey: `${JOB_NAME}.${regionCode}.${partyId}`,
+ singletonKey: `${JOB_NAME}.${data.regionCode}.${data.partyId}`,
  expireIn: '1 hours'
  }
  }
 }
 
 async function handler (job) {
  try {
+ // Most 'jobs' are single operation things in the licence import process, for example, delete any removed documents
+ // or import the purposes types. However, there are typically 69K instances of this job queued up as part of the
+ // process! Previously, we logged every instance hence this was a primary offender in adding noise to the logs. We
+ // removed that logging but that leaves us with no way of confirming the job is running. So, instead we get
+ // src/modules/licence-import/jobs/queue-companies.js to include details on how many jobs are queued and when each
+ // one was added to the queue. We then use this information to log when the first is picked up and the last.
+ //
+ // N.B. It's not entirely accurate. If you added logging for all back in you might see the start message appear
+ // after a few jobs and likewise the finished message a few before the end. But it's good enough to give an
+ // indication that the 'jobs' did start and finish.
+ if (job.data.jobNumber === 1) {
+ global.GlobalNotifier.omg(`${JOB_NAME}: started`, { numberOfJobs: job.data.numberOfJobs })
+ }
+
  const { regionCode, partyId } = job.data
 
  // Extract data

src/modules/licence-import/jobs/import-licence.js

@@ -11,20 +11,49 @@ const options = {
  teamConcurrency: 1
 }
 
-function createMessage (licenceNumber) {
+/**
+ * Data needed by the import licence handler to process the job
+ *
+ * This is a convention with PGBoss. A number of the jobs/handlers implement a `createMessage()` function which returns
+ * a data object that will be used to queue the job. When it then gets processed the data object is passed to the
+ * handler.
+ *
+ * It may also contain non-default config to be used by PGBoss when adding the job, for example, the use of
+ * `singletonKey` in this job.
+ *
+ * @param {Object} data - information needed for the handler to complete the job
+ * @param {Object.string} data.licenceNumber - reference of the licence to import
+ * @param {Object.number} data.jobNumber - index position of this job from all jobs when added to the queue
+ * @param {Object.number} data.numberOfJobs - total number of import-licence jobs queued in this session
+ *
+ * @return {Object} the message object used by the handler to process the job
+ */
+function createMessage (data) {
  return {
  name: JOB_NAME,
- data: {
- licenceNumber
- },
+ data,
  options: {
- singletonKey: `${JOB_NAME}.${licenceNumber}`
+ singletonKey: `${JOB_NAME}.${data.licenceNumber}`
  }
  }
 }
 
 async function handler (job) {
  try {
+ // Most 'jobs' are single operation things in the licence import process, for example, delete any removed documents
+ // or import the purposes types. However, there are typically 69K instances of this job queued up as part of the
+ // process! Previously, we logged every instance hence this was a primary offender in adding noise to the logs. We
+ // removed that logging but that leaves us with no way of confirming the job is running. So, instead we get
+ // src/modules/licence-import/jobs/queue-licences.js to include details on how many jobs are queued and when each
+ // one was added to the queue. We then use this information to log when the first is picked up and the last.
+ //
+ // N.B. It's not entirely accurate. If you added logging for all back in you might see the start message appear
+ // after a few jobs and likewise the finished message a few before the end. But it's good enough to give an
+ // indication that the 'jobs' did start and finish.
+ if (job.data.jobNumber === 1) {
+ global.GlobalNotifier.omg(`${JOB_NAME}: started`, { numberOfJobs: job.data.numberOfJobs })
+ }
+
  // Extract data
  const data = await extract.getLicenceData(job.data.licenceNumber)
 
@@ -33,6 +62,10 @@ async function handler (job) {
 
  // Load licence to DB
  await load.licence.loadLicence(mapped)
+
+ if (job.data.jobNumber === job.data.numberOfJobs) {
+ global.GlobalNotifier.omg(`${JOB_NAME}: finished`, { numberOfJobs: job.data.numberOfJobs })
+ }
  } catch (error) {
  global.GlobalNotifier.omfg(`${JOB_NAME}: errored`, error)
  throw error

src/modules/licence-import/jobs/queue-companies.js

@@ -37,9 +37,18 @@ async function handler () {
 async function onComplete (messageQueue, job) {
  if (!job.failed) {
  const { value: parties } = job.data.response
-
- for (const party of parties) {
- await messageQueue.publish(ImportCompanyJob.createMessage(party.regionCode, party.partyId))
+ const numberOfJobs = parties.length
+
+ for (const [index, party] of parties.entries()) {
+ // This information is to help us log when the import company jobs start and finish. See
+ // src/modules/licence-import/jobs/import-company.js for more details
+ const data = {
+ regionCode: party.regionCode,
+ partyId: party.partyId,
+ jobNumber: index + 1,
+ numberOfJobs
+ }
+ await messageQueue.publish(ImportCompanyJob.createMessage(data))
  }
  }
 

src/modules/licence-import/jobs/queue-licences.js

@@ -31,9 +31,17 @@ async function handler () {
 async function onComplete (messageQueue, job) {
  if (!job.failed) {
  const { value: licences } = job.data.response
-
- for (const licence of licences) {
- await messageQueue.publish(ImportLicenceJob.createMessage(licence.LIC_NO))
+ const numberOfJobs = licences.length
+
+ for (const [index, licence] of licences.entries()) {
+ // This information is to help us log when the import licence jobs start and finish. See
+ // src/modules/licence-import/jobs/import-licence.js for more details
+ const data = {
+ licenceNumber: licence.LIC_NO,
+ jobNumber: index + 1,
+ numberOfJobs
+ }
+ await messageQueue.publish(ImportLicenceJob.createMessage(data))
  }
  }
 

src/modules/nald-import/controller.js

@@ -96,7 +96,7 @@ const postImportLicence = async (request, h) => {
  const data = {
  licenceNumber,
  jobNumber: 1,
- numberOfLicences: 1
+ numberOfJobs: 1
  }
  const message = importLicenceJob.createMessage(data)
 

src/modules/nald-import/jobs/import-licence.js

@@ -19,10 +19,10 @@ const options = {
  * It may also contain non-default config to be used by PGBoss when adding the job, for example, the use of
  * `singletonKey` in this job.
  *
- * @param {Object} data information needed for the handler to complete the job
- * @param {Object.string} data.licenceNumber reference of the licence to import
- * @param {Object.number} data.jobNumber index position of all licence numbers when this job was added to the queue
- * @param {Object.number} data.numberOfLicences total number of licences to be imported
+ * @param {Object} data - information needed for the handler to complete the job
+ * @param {Object.string} data.licenceNumber - reference of the licence to import
+ * @param {Object.number} data.jobNumber - index position of all licence numbers when this job was added to the queue
+ * @param {Object.number} data.numberOfJobs - total number of import-licence jobs queued in this session
  *
  * @returns {Object} the message object used by the handler to process the job
  */
@@ -38,34 +38,27 @@ function createMessage (data) {
  }
 }
 
-/**
- * Imports a single licence
- *
- * @param {Object} job
- * @param {String} job.data.licenceNumber
- */
 async function handler (job) {
  try {
  // Most 'jobs' are single operation things in the NALD import process, for example, deal with the NALD zip file or
  // delete any removed documents. However, there are typically 71K instances of this job queued up as part of the
  // process! Previously, we logged every instance hence this was a primary offender in adding noise to the logs. We
  // removed that logging but that leaves us with no way of confirming the job is running. So, instead we get
- // src/modules/nald-import/jobs/populate-pending-import-complete.js to include details on how many licences there
- // are to import and when each one was added to the queue. We then use this information to log when the first is
- // picked up and the last.
+ // src/modules/nald-import/jobs/queue-licences.js to include details on how many jobs are queued and when each one
+ // was added to the queue. We then use this information to log when the first is picked up and the last.
  //
- // N.B. It's not entirely accurate. If you log all you might see the start message appear after a few jobs and
- // likewise the finished message a few before the end. But it's good enough to give an indication that the 'jobs'
- // did start and finish.
+ // N.B. It's not entirely accurate. If you added logging for all back in you might see the start message appear
+ // after a few jobs and likewise the finished message a few before the end. But it's good enough to give an
+ // indication that the 'jobs' did start and finish.
  if (job.data.jobNumber === 1) {
- global.GlobalNotifier.omg(`${JOB_NAME}: started`, { numberOfLicences: job.data.numberOfLicences })
+ global.GlobalNotifier.omg(`${JOB_NAME}: started`, { numberOfJobs: job.data.numberOfJobs })
  }
 
  // Import the licence
  await licenceLoader.load(job.data.licenceNumber)
 
- if (job.data.jobNumber === job.data.numberOfLicences) {
- global.GlobalNotifier.omg(`${JOB_NAME}: finished`, { numberOfLicences: job.data.numberOfLicences })
+ if (job.data.jobNumber === job.data.numberOfJobs) {
+ global.GlobalNotifier.omg(`${JOB_NAME}: finished`, { numberOfJobs: job.data.numberOfJobs })
  }
  } catch (error) {
  global.GlobalNotifier.omfg(`${JOB_NAME}: errored`, job.data, error)

src/modules/nald-import/jobs/queue-licences.js

@@ -33,15 +33,15 @@ async function handler () {
 async function onComplete (messageQueue, job) {
  if (!job.failed) {
  const { licenceNumbers } = job.data.response
- const numberOfLicences = licenceNumbers.length
+ const numberOfJobs = licenceNumbers.length
 
  for (const [index, licenceNumber] of licenceNumbers.entries()) {
  // This information is to help us log when the import licence jobs start and finish. See
  // src/modules/nald-import/jobs/import-licence.js for more details
  const data = {
  licenceNumber,
  jobNumber: index + 1,
- numberOfLicences
+ numberOfJobs
  }
  await messageQueue.publish(ImportLicenceJob.createMessage(data))
  }

test/modules/licence-import/controller.test.js

@@ -103,7 +103,7 @@ experiment('modules/licence-import/controller.js', () => {
 
  expect(message).to.equal({
  name: 'licence-import.import-company',
- data: { regionCode: 1, partyId: 37760 },
+ data: { regionCode: 1, partyId: 37760, jobNumber: 1, numberOfJobs: 1 },
  options: { singletonKey: 'licence-import.import-company.1.37760', expireIn: '1 hours' }
  })
  })
@@ -139,7 +139,7 @@ experiment('modules/licence-import/controller.js', () => {
 
  expect(message).to.equal({
  name: 'licence-import.import-licence',
- data: { licenceNumber: '01/123' },
+ data: { licenceNumber: '01/123', jobNumber: 1, numberOfJobs: 1 },
  options: { singletonKey: 'licence-import.import-licence.01/123' }
  })
  })