From 5c003e4ddc215c7bc19ab164998cb9191f728955 Mon Sep 17 00:00:00 2001 From: Benjamin Chrobot Date: Tue, 25 Feb 2020 13:32:00 -0500 Subject: [PATCH 1/2] chore: clean up logging Winston handles .error(message, err) okay, but not .error(err) by itself. For reability we also want to make sure the provided message ends with a space so that the concatenated message from the error is separate. Due to a winston regression introduced in 3.x, we cannot pass other meta information after the error without passing error.message and error.stack explicitly. This means we may lose additional error properties. We cannot destructure the error either (non-iterable properties). A better fix would be to write a custom log formatter that is error-aware. There are a few examples on GitHub, but none that looked straightforward. We don't want to break JSON logging and parsing. --- src/server/api/lib/assemble-numbers.js | 5 +- src/server/api/lib/nexmo.js | 2 +- src/server/api/lib/twilio.js | 8 +- .../models/cacheable_queries/opt-out.js | 2 +- src/server/routes/assemble-numbers.js | 9 +- src/server/routes/twilio.js | 4 +- src/workers/cron/deliverability-report.js | 2 +- .../cron/release-old-unsent-messages.js | 2 +- src/workers/cron/slack-teams-update.js | 2 +- src/workers/job-processes.js | 8 +- src/workers/jobs.js | 101 ++++++++++-------- 11 files changed, 81 insertions(+), 64 deletions(-) diff --git a/src/server/api/lib/assemble-numbers.js b/src/server/api/lib/assemble-numbers.js index 556214491..2a69461d7 100644 --- a/src/server/api/lib/assemble-numbers.js +++ b/src/server/api/lib/assemble-numbers.js @@ -141,7 +141,10 @@ export const sendMessage = async (message, organizationId, _trx) => { }) .where({ id: spokeMessageId }); } catch (exc) { - logger.error("Error sending message with Assemble Numbers: ", exc, { + const {} + logger.error({ + message: `"Error sending message with Assemble Numbers: ${exc.message}`, + stack: exc.stack, messageInput }); await r diff --git a/src/server/api/lib/nexmo.js b/src/server/api/lib/nexmo.js index 7b00c11d2..b7a473a0e 100644 --- a/src/server/api/lib/nexmo.js +++ b/src/server/api/lib/nexmo.js @@ -191,7 +191,7 @@ async function handleIncomingMessage(message) { !message.hasOwnProperty("text") || !message.hasOwnProperty("messageId") ) { - logger.error(`This is not an incoming message: ${JSON.stringify(message)}`); + logger.error("This is not an incoming message", { payload: message }); } const { to, msisdn, concat } = message; diff --git a/src/server/api/lib/twilio.js b/src/server/api/lib/twilio.js index 7c347cdba..1a5bbd800 100644 --- a/src/server/api/lib/twilio.js +++ b/src/server/api/lib/twilio.js @@ -175,8 +175,8 @@ async function sendMessage(message, organizationId, trx = r.knex) { if (!twilio) { logger.error( - "cannot actually send SMS message -- twilio is not fully configured:", - message.id + "cannot actually send SMS message -- twilio is not fully configured", + { messageId: message.id } ); if (message.id) { await trx("message") @@ -242,7 +242,7 @@ async function sendMessage(message, organizationId, trx = r.knex) { let hasError = false; if (err) { hasError = true; - logger.error(`Error sending message ${message.id}`, err); + logger.error(`Error sending message ${message.id}: `, err); const jsonErr = typeof err === "object" ? err : { error: err }; messageToSave.service_response = appendServiceResponse( messageToSave.service_response, @@ -352,7 +352,7 @@ async function handleIncomingMessage(message) { !message.hasOwnProperty("Body") || !message.hasOwnProperty("MessageSid") ) { - logger.error(`This is not an incoming message: ${JSON.stringify(message)}`); + logger.error("This is not an incoming message", { payload: message }); } const { From, To, MessageSid } = message; diff --git a/src/server/models/cacheable_queries/opt-out.js b/src/server/models/cacheable_queries/opt-out.js index 514f634a6..fed01f528 100644 --- a/src/server/models/cacheable_queries/opt-out.js +++ b/src/server/models/cacheable_queries/opt-out.js @@ -102,7 +102,7 @@ export const optOutCache = { cell }); } catch (error) { - logger.error("Error creating opt-out", error); + logger.error("Error creating opt-out: ", error); } // update all organization's active campaigns as well diff --git a/src/server/routes/assemble-numbers.js b/src/server/routes/assemble-numbers.js index 56efff938..2c59ec34e 100644 --- a/src/server/routes/assemble-numbers.js +++ b/src/server/routes/assemble-numbers.js @@ -13,8 +13,11 @@ router.post( await assembleNumbers.handleIncomingMessage(req.body); return res.status(200).send({ success: true }); } catch (err) { - logger.error("Error handling incoming assemble numbers message", { - err, + logger.error({ + message: `Error handling incoming assemble numbers message: ${ + err.message + }`, + stack: err.stack, body: req.body }); res.status(500).send({ error: err.message }); @@ -31,7 +34,7 @@ router.post( await assembleNumbers.handleDeliveryReport(req.body); return res.status(200).send({ success: true }); } catch (err) { - logger.error("Error handling assemble numbers message report", err); + logger.error("Error handling assemble numbers message report: ", err); res.status(500).send({ error: err.message }); } } diff --git a/src/server/routes/twilio.js b/src/server/routes/twilio.js index b27e90043..08c1a1d37 100644 --- a/src/server/routes/twilio.js +++ b/src/server/routes/twilio.js @@ -14,7 +14,7 @@ router.post("/twilio", headerValidator, async (req, res) => { res.writeHead(200, { "Content-Type": "text/xml" }); res.end(resp.toString()); } catch (ex) { - logger.error("Error handling incoming twilio message", ex); + logger.error("Error handling incoming twilio message: ", ex); res.status(500).send(ex.message); } }); @@ -26,7 +26,7 @@ router.post("/twilio-message-report", headerValidator, async (req, res) => { res.writeHead(200, { "Content-Type": "text/xml" }); return res.end(resp.toString()); } catch (exc) { - logger.error("Error handling twilio message report", exc); + logger.error("Error handling twilio message report: ", exc); res.status(500).send(exc.message); } }); diff --git a/src/workers/cron/deliverability-report.js b/src/workers/cron/deliverability-report.js index 1b0f3d33f..d47acd44b 100644 --- a/src/workers/cron/deliverability-report.js +++ b/src/workers/cron/deliverability-report.js @@ -267,6 +267,6 @@ main() process.exit(0); }) .catch(error => { - logger.error(error); + logger.error("Error creating deliverability report: ", error); process.exit(1); }); diff --git a/src/workers/cron/release-old-unsent-messages.js b/src/workers/cron/release-old-unsent-messages.js index d63d5451c..7acc022f8 100644 --- a/src/workers/cron/release-old-unsent-messages.js +++ b/src/workers/cron/release-old-unsent-messages.js @@ -40,6 +40,6 @@ main() process.exit(0); }) .catch(error => { - logger.error(error); + logger.error("Error releasing old unsent messages: ", error); process.exit(1); }); diff --git a/src/workers/cron/slack-teams-update.js b/src/workers/cron/slack-teams-update.js index b5f23658d..b75b1a41d 100644 --- a/src/workers/cron/slack-teams-update.js +++ b/src/workers/cron/slack-teams-update.js @@ -99,6 +99,6 @@ const fetchAllChannels = async (acc = [], next_cursor) => { main() .then(() => process.exit(0)) .catch(error => { - logger.error(error); + logger.error("Error updating Slack teams: ", error); process.exit(1); }); diff --git a/src/workers/job-processes.js b/src/workers/job-processes.js index 9c5c72f3b..b00befd6c 100644 --- a/src/workers/job-processes.js +++ b/src/workers/job-processes.js @@ -49,7 +49,7 @@ export async function processJobs() { // clear out stuck jobs await clearOldJobs(twoMinutesAgo); } catch (ex) { - logger.error("Error processing jobs", ex); + logger.error("Error processing jobs: ", ex); } } } @@ -65,7 +65,7 @@ export async function checkMessageQueue() { await sleep(10000); processSqsMessages(); } catch (ex) { - logger.error("Error checking message queue", ex); + logger.error("Error checking message queue: ", ex); } } } @@ -84,7 +84,7 @@ const messageSenderCreator = (subQuery, defaultStatus) => { await sleep(delay); await sendMessages(subQuery, defaultStatus); } catch (ex) { - logger.error("Error sending messages from messageSender", ex); + logger.error("Error sending messages from messageSender: ", ex); } } }; @@ -168,7 +168,7 @@ export async function handleIncomingMessages() { await handleIncomingMessageParts(); } } catch (ex) { - logger.error("Error at handleIncomingMessages", ex); + logger.error("Error at handleIncomingMessages: ", ex); } } } diff --git a/src/workers/jobs.js b/src/workers/jobs.js index 2b4ae5dd1..6913fceb0 100644 --- a/src/workers/jobs.js +++ b/src/workers/jobs.js @@ -128,7 +128,10 @@ export async function processSqsMessages() { const p = new Promise((resolve, reject) => { sqs.receiveMessage(params, async (err, data) => { if (err) { - logger.error(err, err.stack); + logger.error({ + message: err.message, + stack: err.stack + }); reject(err); } else if (data.Messages) { logger.info(data); @@ -147,7 +150,10 @@ export async function processSqsMessages() { }, (delMessageErr, delMessageData) => { if (delMessageErr) { - logger.error(delMessageErr, delMessageErr.stack); // an error occurred + logger.error({ + message: delMessageErr, + stack: delMessageErr.stack + }); // an error occurred } else { logger.info(delMessageData); // successful response } @@ -239,7 +245,7 @@ export async function uploadContacts(job) { await numbersRequest.addPhoneNumbers(chunk.map(c => c.cell)); } } catch (exc) { - logger.error("Error inserting contacts:", exc); + logger.error("Error inserting contacts: ", exc); throw exc; } @@ -298,7 +304,7 @@ export async function uploadContacts(job) { ); } } catch (exc) { - logger.error("Error deleting opt-outs:", exc); + logger.error("Error deleting opt-outs: ", exc); throw exc; } @@ -337,7 +343,7 @@ export async function uploadContacts(job) { ); } } catch (exc) { - logger.error("Error deleting excluded contacts:", exc); + logger.error("Error deleting excluded contacts: ", exc); throw exc; } @@ -374,12 +380,11 @@ export async function loadContactsFromDataWarehouseFragment(jobEvent) { .select("status") .first(); if (!jobCompleted) { - logger.error( - "loadContactsFromDataWarehouseFragment job no longer exists", - jobEvent.campaignId, + logger.error("loadContactsFromDataWarehouseFragment job no longer exists", { + campaignId: jobEvent.campaignId, jobCompleted, jobEvent - ); + }); return { alreadyComplete: 1 }; } @@ -395,7 +400,7 @@ export async function loadContactsFromDataWarehouseFragment(jobEvent) { warehouseConnection = warehouseConnection || datawarehouse(); logger.error( "loadContactsFromDataWarehouseFragment RUNNING WAREHOUSE query", - sqlQuery + { sqlQuery } ); knexResult = await warehouseConnection.raw(sqlQuery); } catch (err) { @@ -421,9 +426,11 @@ export async function loadContactsFromDataWarehouseFragment(jobEvent) { }); if (!("first_name" in fields && "last_name" in fields && "cell" in fields)) { logger.error( - "SQL statement does not return first_name, last_name, and cell: ", - sqlQuery, - fields + "SQL statement does not return first_name, last_name, and cell", + { + sqlQuery, + fields + } ); jobMessages.push( `SQL statement does not return first_name, last_name and cell => ${sqlQuery} => with fields ${fields}` @@ -475,18 +482,16 @@ export async function loadContactsFromDataWarehouseFragment(jobEvent) { .where("id", jobEvent.jobId) .select("status") .first(); - logger.error( - "loadContactsFromDataWarehouseFragment toward end", + logger.error("loadContactsFromDataWarehouseFragment toward end", { completed, jobEvent - ); + }); if (!completed) { - logger.error( - "loadContactsFromDataWarehouseFragment job has been deleted", + logger.error("loadContactsFromDataWarehouseFragment job has been deleted", { completed, - jobEvent.campaignId - ); + campaignId: jobEvent.campaignId + }); } else if (jobEvent.totalParts && completed.status >= jobEvent.totalParts) { if (jobEvent.organizationId) { // now that we've saved them all, we delete everyone that is opted out locally @@ -500,9 +505,11 @@ export async function loadContactsFromDataWarehouseFragment(jobEvent) { .delete() .then(result => { logger.error( - `loadContactsFromDataWarehouseFragment # of contacts opted out removed from DW query (${ - jobEvent.campaignId - }): ${result}` + "loadContactsFromDataWarehouseFragment # of contacts opted out removed from DW query", + { + campaignId: jobEvent.campaignId, + result + } ); validationStats.optOutCount = result; }); @@ -515,9 +522,11 @@ export async function loadContactsFromDataWarehouseFragment(jobEvent) { .delete() .then(result => { logger.error( - `loadContactsFromDataWarehouseFragment # of contacts with invalid cells removed from DW query (${ - jobEvent.campaignId - }): ${result}` + "loadContactsFromDataWarehouseFragment # of contacts with invalid cells removed from DW query", + { + campaignId: jobEvent.campaignId, + result + } ); validationStats.invalidCellCount = result; }); @@ -541,9 +550,11 @@ export async function loadContactsFromDataWarehouseFragment(jobEvent) { .delete() .then(result => { logger.error( - `loadContactsFromDataWarehouseFragment # of contacts with duplicate cells removed from DW query (${ - jobEvent.campaignId - }): ${result}` + "loadContactsFromDataWarehouseFragment # of contacts with duplicate cells removed from DW query", + { + campaignId: jobEvent.campaignId, + result + } ); validationStats.duplicateCellCount = result; }); @@ -583,13 +594,15 @@ export async function loadContactsFromDataWarehouse(job) { if (!sqlQuery.startsWith("SELECT") || sqlQuery.indexOf(";") >= 0) { logger.error( - "Malformed SQL statement. Must begin with SELECT and not have any semicolons: ", - sqlQuery + "Malformed SQL statement. Must begin with SELECT and not have any semicolons", + { sqlQuery } ); return; } if (!datawarehouse) { - logger.error("No data warehouse connection, so cannot load contacts", job); + logger.error("No data warehouse connection, so cannot load contacts", { + job + }); return; } @@ -1058,7 +1071,7 @@ export async function assignTexters(job) { execute() .then(trx.commit) .catch(error => { - logger.error("Rolling back!", error); + logger.error("Error assigning texters. Rolling back! ", error); trx.rollback(error); }); }); @@ -1322,7 +1335,7 @@ const deleteJob = async (jobId, retries = 0) => { if (retries < 5) { await deleteJob(jobId, retries + 1); } else { - logger.error(`Could not delete job. Err: ${err.message}`); + logger.error("Could not delete job. Err: ", err); } } }; @@ -1345,7 +1358,7 @@ export async function exportCampaign(job) { isAutomatedExport } = await fetchExportData(job)); } catch (exc) { - logger.error("Error fetching export data:", exc); + logger.error("Error fetching export data: ", exc); return; } @@ -1367,7 +1380,7 @@ export async function exportCampaign(job) { messageRows = messageRows.concat(chunkMessageResult.messages); } } catch (exc) { - logger.error("Error building message rows:", exc); + logger.error("Error building message rows: ", exc); } // Contact rows @@ -1387,7 +1400,7 @@ export async function exportCampaign(job) { contactRows = contactRows.concat(chunkContactResult.contacts); } } catch (exc) { - logger.error("Error building campaign contact rows:", exc); + logger.error("Error building campaign contact rows: ", exc); } // Create the CSV paylaods @@ -1397,7 +1410,7 @@ export async function exportCampaign(job) { campaignsCsv = Papa.unparse(contactRows); messagesCsv = Papa.unparse(messageRows); } catch (exc) { - logger.error("Error building CSVs:", exc); + logger.error("Error building CSVs: ", exc); } const validAwsCredentials = @@ -1434,7 +1447,7 @@ export async function exportCampaign(job) { ` Campaign export: ${campaignExportUrl}` + ` Message export: ${campaignMessagesExportUrl}` }).catch(err => { - logger.error(err); + logger.error("Error sending export email: ", err); logger.info(`Campaign Export URL - ${campaignExportUrl}`); logger.info( `Campaign Messages Export URL - ${campaignMessagesExportUrl}` @@ -1443,7 +1456,7 @@ export async function exportCampaign(job) { } logger.info(`Successfully exported ${campaignId}`); } catch (err) { - logger.error("Error uploading to cloud storage", err); + logger.error("Error uploading export to cloud storage: ", err); await sendEmail({ to: notificationEmail, @@ -1515,14 +1528,12 @@ export async function sendMessages(queryFunc, defaultStatus) { trx.commit(); } catch (err) { - logger.error("error sending messages:"); - logger.error(err); + logger.error("Error in sendMessages: ", err); trx.rollback(); } }); } catch (err) { - logger.error("sendMessages transaction errored:"); - logger.error(err); + logger.error("sendMessages transaction errored: ", err); } } @@ -1671,7 +1682,7 @@ export async function fixOrgless() { config.DEFAULT_ORG ); } catch (err) { - logger.error("error on userOrganization save in orgless", error); + logger.error("error on userOrganization save in orgless: ", error); } }); // forEach } // if From 7501f74f8d2932c533d105fd64f5da50d50011f3 Mon Sep 17 00:00:00 2001 From: Benjamin Chrobot Date: Wed, 26 Feb 2020 06:53:14 -0500 Subject: [PATCH 2/2] fix: remove extraneous line --- src/server/api/lib/assemble-numbers.js | 1 - 1 file changed, 1 deletion(-) diff --git a/src/server/api/lib/assemble-numbers.js b/src/server/api/lib/assemble-numbers.js index 2a69461d7..ccd289731 100644 --- a/src/server/api/lib/assemble-numbers.js +++ b/src/server/api/lib/assemble-numbers.js @@ -141,7 +141,6 @@ export const sendMessage = async (message, organizationId, _trx) => { }) .where({ id: spokeMessageId }); } catch (exc) { - const {} logger.error({ message: `"Error sending message with Assemble Numbers: ${exc.message}`, stack: exc.stack,