Merge pull request #196 from politics-rewired/politics-rewired/add-me…

…ssage-report-delay

Add delay to handling of delivery report

src/containers/AdminAssignmentRequest/index.jsx

@@ -6,12 +6,9 @@ import AssignmentRequestTable, {
 } from "./AssignmentRequestTable";
 import loadData from "../hoc/load-data";
 import wrapMutations from "../hoc/wrap-mutations";
+import { sleep } from "../../lib/utils";
 import CircularProgress from "material-ui/CircularProgress";
 
-function sleep(ms) {
-  return new Promise(resolve => setTimeout(resolve, ms));
-}
-
 class AdminAssignmentRequest extends Component {
   state = {
     assignmentRequests: []

src/lib/index.js

@@ -22,6 +22,8 @@ export { DstHelper } from "./dst-helper";
 export { isClient } from "./is-client";
 import { log } from "./log";
 export { log };
+import { sleep } from "./utils";
+export { sleep };
 import Papa from "papaparse";
 import _ from "lodash";
 import { getFormattedPhoneNumber, getFormattedZip } from "../lib";

src/server/api/lib/twilio.js

@@ -3,6 +3,7 @@ import _ from "lodash";
 import { getFormattedPhoneNumber } from "../../../lib/phone-format";
 import { Log, Message, PendingMessagePart, r } from "../../models";
 import { log } from "../../../lib";
+import { sleep } from "../../../lib/utils";
 import {
   getCampaignContactAndAssignmentForIncomingMessage,
   saveNewIncomingMessage
@@ -373,34 +374,43 @@ const getMessageStatus = twilioStatus => {
   // Other Twilio statuses do not map to Spoke statuses and thus are ignored
 };
 
+// Delivery reports can arrive before sendMessage() has finished. In these cases,
+// the message record in the database will not have a Twilio SID saved and the
+// delivery report lookup will fail. To deal with this we prioritize recording
+// the delivery report itself rather than updating the message. We can then "replay"
+// the delivery reports back on the message table at a later date. We still attempt
+// to update the message record status (after a slight delay).
 async function handleDeliveryReport(report) {
   const { MessageSid: service_id, MessageStatus } = report;
 
-  // Insert log line (we don't care about waiting for this to complete)
-  r.knex("log")
-    .insert({
-      message_sid: service_id,
-      body: JSON.stringify(report)
+  // Record the delivery report
+  const insertResult = await r.knex("log").insert({
+    message_sid: service_id,
+    body: JSON.stringify(report)
+  });
+
+  // Kick off message update after delay, but don't wait around for result
+  sleep(5000)
+    .then(() =>
+      r
+        .knex("message")
+        .update({
+          service_response_at: r.knex.fn.now(),
+          send_status: getMessageStatus(MessageStatus)
+        })
+        .where({ service_id })
+    )
+    .then(rowCount => {
+      if (rowCount !== 1) {
+        console.warn(
+          `Received message report '${MessageStatus}' for Message SID ` +
+            `'${service_id}' that matched ${rowCount} messages. Expected only 1 match.`
+        );
+      }
     })
     .catch(console.error);
 
-  // Update matching message.
-  const rowCount = await r
-    .knex("message")
-    .update({
-      service_response_at: r.knex.fn.now(),
-      send_status: getMessageStatus(MessageStatus)
-    })
-    .where({ service_id });
-
-  if (rowCount !== 1) {
-    // This could happen because the 'queued' report arrived before we finished updating the
-    // message's SID with the created Twilio Message response
-    console.warn(
-      `Received message report '${MessageStatus}' for Message SID '${service_id}' ` +
-        `that matched ${rowCount} messages. Expected only 1 match.`
-    );
-  }
+  return insertResult;
 }
 
 async function handleIncomingMessage(message) {

src/server/index.js

@@ -22,7 +22,8 @@ import nexmo from "./api/lib/nexmo";
 import twilio from "./api/lib/twilio";
 import { seedZipCodes } from "./seeds/seed-zip-codes";
 import { setupUserNotificationObservers } from "./notifications";
-import { TwimlResponse } from "twilio";
+import { twiml } from "twilio";
+const { MessagingResponse } = twiml;
 import basicAuth from "express-basic-auth";
 import { fulfillPendingRequestFor } from "./api/assignment";
 import googleLibPhoneNumber from "google-libphonenumber";
@@ -128,7 +129,7 @@ app.post(
       log.error(ex);
     }
 
-    const resp = new TwimlResponse();
+    const resp = new MessagingResponse();
     res.writeHead(200, { "Content-Type": "text/xml" });
     res.end(resp.toString());
   })
@@ -153,7 +154,7 @@ app.post(
   wrap(async (req, res) => {
     try {
       await twilio.handleDeliveryReport(req.body);
-      const resp = new TwimlResponse();
+      const resp = new MessagingResponse();
       res.writeHead(200, { "Content-Type": "text/xml" });
       return res.end(resp.toString());
     } catch (exc) {

src/workers/job-processes.js

@@ -1,6 +1,7 @@
 import { r } from "../server/models";
-import { sleep, getNextJob } from "./lib";
+import { getNextJob } from "./lib";
 import { log } from "../lib";
+import { sleep } from "../lib/utils";
 import {
   exportCampaign,
   processSqsMessages,

src/workers/lib.js

@@ -1,7 +1,5 @@
 import { r, JobRequest } from "../server/models";
 
-export const sleep = (ms = 0) => new Promise(fn => setTimeout(fn, ms));
-
 export async function updateJob(job, percentComplete) {
   if (job.id) {
     await JobRequest.get(job.id).update({