node.js amazon-web-services aws-lambda twilio

Twilio is not sending WhatsApp messages in real time through AWS Lambda

Sorry for the long post, but it's just to better explain, since english is not my first language.

I'm using API Gateway + Lambda to send WhatsApp messages though POST requests.

I have encoutered this weird behavior. It looks like the Twilio needs to "wake up" after 2 requests or a period of time. I have made inputs from "1000", "1001", "1002", until "1018" to test and better understand.

When I make resquest 1000 and 1001, I receive nothing on WhatsApp.
When I make request 1002, I receive the 1000 message. So I'm always 2 messages behind.
I continue until 1011 let's say (I receive messages until 1009). Then I wait around 3 minutes or less.
In request 1012 I get "internal server error" in Postman. (sometimes I get this error and sometimes I get a body response, but 1012 is never sent as a message by WhatsApp (read next line for better understand)).
But I should get message 1010 (since I'm 2 messages behind), but nothing happenns. The cycle restarts and I never get responses 1010, 1011 or 1012. I should wait until request 1014, to start getting messages.

What can be happening?

This is my Lambda code

///date is 1000, 1001, 1002, 1003, etc. The numbers I have sent manually to test.
'use strict';
console.log('Trying to send a WhatsApp message...');

exports.handler = async (event) => {
    
const accountSid = 'ACa-------------'; 
const authToken = '7e5--------------'; 

const client = require('twilio')("ACa48----------", "7e5d820---------"); 

 let date = "today";
 if (event.queryStringParameters && event.queryStringParameters.date) {
        console.log("Input received is: " + event.queryStringParameters.date);
        fecha = event.queryStringParameters.date;
    }
client.messages 
      .create({ 
         body: date, 
         from: 'whatsapp:+1---------',       
         to: 'whatsapp:+1---------' 
       }) 
      .then(message => console.log("TWILIO RESPONSE SHOULD BE HERE: " + JSON.stringify(message)))
      .done();

  
    let rspbody = date + " is the input";
    
 let responseBody = {
        message: rspbody,
        input: event
    };
let response = {
        statusCode: 200,
        headers: {
            "x-custom-header" : "my custom header value"
        },
        body: JSON.stringify(responseBody),
        "isBase64Encoded": false
    };
    console.log("response LAMBDA: " + JSON.stringify(response));
    return response;
      
};

This is the relevant API Gateway CloudWatch log (actually, the part that is different from the succesful requests) after the 1012 request (the one that is sent a few minutes after the last continuous request). So it never goes through the API Gateway, so it doesn't appear in the Lambda log (that I attach later).

2021-12-05T20:15:50.171-05:00   (93f6905d-0346-4eff-8b4c-2b03294c6202) Endpoint response headers: {Date=Mon, 06 Dec 2021 01:15:50 GMT, Content-Type=application/json, Content-Length=148, Connection=keep-alive, x-amzn-RequestId=ece04ac8-267b-42fb-ada0-e54e9b6d36c1, X-Amz-Function-Error=Unhandled, x-amzn-Remapped-Content-Length=0, X-Amz-Executed-Version=$LATEST, X-Amzn-Trace-Id=root=1-61ad6446-24dddd3d3b3f9d6c77fdbe4c;sampled=0}

2021-12-05T20:15:50.171-05:00   (93f6905d-0346-4eff-8b4c-2b03294c6202) Endpoint response body before transformations: {"errorMessage":"RequestId: ece04ac8-267b-42fb-ada0-e54e9b6d36c1 Error: Runtime exited with error: exit status 129","errorType":"Runtime.ExitError"}

2021-12-05T20:15:50.171-05:00   (93f6905d-0346-4eff-8b4c-2b03294c6202) Lambda execution failed with status 200 due to customer function error: RequestId: ece04ac8-267b-42fb-ada0-e54e9b6d36c1 Error: Runtime exited with error: exit status 129. Lambda request id: ece04ac8-267b-42fb-ada0-e54e9b6d36c1

2021-12-05T20:15:50.171-05:00   (93f6905d-0346-4eff-8b4c-2b03294c6202) Method completed with status: 502

2021-12-05T20:15:50.171-05:00   (93f6905d-0346-4eff-8b4c-2b03294c6202) AWS Integration Endpoint RequestId : ece04ac8-267b-42fb-ada0-e54e9b6d36c1

And this is the relevant Lambda CloudWatch log.

2021-12-05T20:13:07.975-05:00   START RequestId: 184f018a-3ca1-46aa-981e-942b1340446c Version: $LATEST

2021-12-05T20:13:08.044-05:00   2021-12-06T01:13:08.025Z 184f018a-3ca1-46aa-981e-942b1340446c INFO Input received is: 1002

2021-12-05T20:13:08.064-05:00   2021-12-06T01:13:08.064Z 184f018a-3ca1-46aa-981e-942b1340446c INFO response LAMBDA: {"statusCode":200,"headers":{"x-custom-header":"my custom header value"},"body":"{\"message\":\"1002 is the input\",\"input\":{\"resource\":\"/helloworld\",\"path\":\"/helloworld\",\"httpMethod\":\"POST\",\"headers\":{\"Accept\":\"*/*\",\"Accept-Encoding\":\"gzip, deflate, br\",\"Authorization\":\"Bearer 3fa2c3d0-e110-11eb-b383-0b0630a03147\",\"Host\":\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\",\"Postman-Token\":\"8f8ca586-0b46-4882-a633-653a3a964a2b\",\"User-Agent\":\"PostmanRuntime/7.28.4\",\"X-Amzn-Trace-Id\":\"Root=1-61ad63a3-0782456908e458a6435d1ad5\",\"X-Forwarded-For\":\"190.42.19.71\",\"X-Forwarded-Port\":\"443\",\"X-Forwarded-Proto\":\"https\"},\"multiValueHeaders\":{\"Accept\":[\"*/*\"],\"Accept-Encoding\":[\"gzip, deflate, br\"],\"Authorization\":[\"Bearer 3fa2c3d0-e110-11eb-b383-0b0630a03147\"],\"Host\":[\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\"],\"Postman-Token\":[\"8f8ca586-0b46-4882-a633-653a3a964a2b\"],\"User-Agent\":[\"PostmanRuntime/7.28.4\"],\"X-Amzn-Trace-Id\":[\"Root=1-61ad63a3-0782456908e458a6435d1ad5\"],\"X-Forwarded-For\":[\"190.42.19.71\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"]},\"queryStringParameters\":{\"fecha\":\"1002\"},\"multiValueQueryStringParameters\":{\"fecha\":[\"1002\"]},\"pathParameters\":null,\"stageVariables\":null,\"requestContext\":{\"resourceId\":\"yiygu3\",\"resourcePath\":\"/helloworld\",\"httpMethod\":\"POST\",\"extendedRequestId\":\"J5yBpHOuIAMF_JA=\",\"requestTime\":\"06/Dec/2021:01:13:07 +0000\",\"path\":\"/test/helloworld\",\"accountId\":\"487474028649\",\"protocol\":\"HTTP/1.1\",\"stage\":\"test\",\"domainPrefix\":\"ob9nw3nywj\",\"requestTimeEpoch\":1638753187961,\"requestId\":\"157d7260-fb50-401d-9cd9-b593ddb8a320\",\"identity\":{\"cognitoIdentityPoolId\":null,\"accountId\":null,\"cognitoIdentityId\":null,\"caller\":null,\"sourceIp\":\"190.42.19.71\",\"principalOrgId\":null,\"accessKey\":null,\"cognitoAuthenticationType\":null,\"cognitoAuthenticationProvider\":null,\"userArn\":null,\"userAgent\":\"PostmanRuntime/7.28.4\",\"user\":null},\"domainName\":\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\",\"apiId\":\"ob9nw3nywj\"},\"body\":null,\"isBase64Encoded\":false}}","isBase64Encoded":false}

2021-12-05T20:13:08.084-05:00   END RequestId: 184f018a-3ca1-46aa-981e-942b1340446c

2021-12-05T20:13:08.084-05:00   REPORT RequestId: 184f018a-3ca1-46aa-981e-942b1340446c Duration: 105.32 ms Billed Duration: 106 ms Memory Size: 256 MB Max Memory Used: 116 MB

2021-12-05T20:13:09.705-05:00   START RequestId: c4e087b5-a26b-4753-9552-98a835658af5 Version: $LATEST

2021-12-05T20:13:09.745-05:00   2021-12-06T01:13:09.745Z 184f018a-3ca1-46aa-981e-942b1340446c INFO TWILIO RESPONSE SHOULD BE HERE: {"body":"1000","numSegments":"1","direction":"outbound-api","from":"whatsapp:+14155238886","to":"whatsapp:+1-------------","dateUpdated":"2021-12-06T01:13:08.000Z","price":null,"errorMessage":null,"uri":"/2010-04-01/Accounts/ACa48---------174df747a33beec1c3/Messages/SMadc43552455a49de88056d84bda32bd7.json","accountSid":"ACa48-------67ec1c3","numMedia":"0","status":"queued","messagingServiceSid":null,"sid":"SMadc43552455a49de88056d84bda32bd7","dateSent":null,"dateCreated":"2021-12-06T01:13:08.000Z","errorCode":null,"priceUnit":null,"apiVersion":"2010-04-01","subresourceUris":{"media":"/2010-04-01/Accounts/ACa48--------4df747a33beec1c3/Messages/SMadc43552455a49de88056d84bda32bd7/Media.json"}}

2021-12-05T20:13:09.746-05:00   2021-12-06T01:13:09.746Z c4e087b5-a26b-4753-9552-98a835658af5 INFO Input received is: 1003

2021-12-05T20:13:09.765-05:00   2021-12-06T01:13:09.765Z c4e087b5-a26b-4753-9552-98a835658af5 INFO response LAMBDA: {"statusCode":200,"headers":{"x-custom-header":"my custom header value"},"body":"{\"message\":\"1003 is the input\",\"input\":{\"resource\":\"/helloworld\",\"path\":\"/helloworld\",\"httpMethod\":\"POST\",\"headers\":{\"Accept\":\"*/*\",\"Accept-Encoding\":\"gzip, deflate, br\",\"Authorization\":\"Bearer 3fa2c3d0-e110-11eb-b383-0b0630a03147\",\"Host\":\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\",\"Postman-Token\":\"1ec116a0-e65a-4ecf-8dba-aa9f3ae2d1a0\",\"User-Agent\":\"PostmanRuntime/7.28.4\",\"X-Amzn-Trace-Id\":\"Root=1-61ad63a5-160d7e0c02c8cf7f20f35731\",\"X-Forwarded-For\":\"190.42.19.71\",\"X-Forwarded-Port\":\"443\",\"X-Forwarded-Proto\":\"https\"},\"multiValueHeaders\":{\"Accept\":[\"*/*\"],\"Accept-Encoding\":[\"gzip, deflate, br\"],\"Authorization\":[\"Bearer 3fa2c3d0-e110-11eb-b383-0b0630a03147\"],\"Host\":[\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\"],\"Postman-Token\":[\"1ec116a0-e65a-4ecf-8dba-aa9f3ae2d1a0\"],\"User-Agent\":[\"PostmanRuntime/7.28.4\"],\"X-Amzn-Trace-Id\":[\"Root=1-61ad63a5-160d7e0c02c8cf7f20f35731\"],\"X-Forwarded-For\":[\"190.42.19.71\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"]},\"queryStringParameters\":{\"fecha\":\"1003\"},\"multiValueQueryStringParameters\":{\"fecha\":[\"1003\"]},\"pathParameters\":null,\"stageVariables\":null,\"requestContext\":{\"resourceId\":\"yiygu3\",\"resourcePath\":\"/helloworld\",\"httpMethod\":\"POST\",\"extendedRequestId\":\"J5yB6EtBoAMF96Q=\",\"requestTime\":\"06/Dec/2021:01:13:09 +0000\",\"path\":\"/test/helloworld\",\"accountId\":\"487474028649\",\"protocol\":\"HTTP/1.1\",\"stage\":\"test\",\"domainPrefix\":\"ob9nw3nywj\",\"requestTimeEpoch\":1638753189693,\"requestId\":\"e2d9d7ec-56d3-4685-8590-aa1d5fb2038b\",\"identity\":{\"cognitoIdentityPoolId\":null,\"accountId\":null,\"cognitoIdentityId\":null,\"caller\":null,\"sourceIp\":\"190.42.19.71\",\"principalOrgId\":null,\"accessKey\":null,\"cognitoAuthenticationType\":null,\"cognitoAuthenticationProvider\":null,\"userArn\":null,\"userAgent\":\"PostmanRuntime/7.28.4\",\"user\":null},\"domainName\":\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\",\"apiId\":\"ob9nw3nywj\"},\"body\":null,\"isBase64Encoded\":false}}","isBase64Encoded":false}

2021-12-05T20:13:09.766-05:00   END RequestId: c4e087b5-a26b-4753-9552-98a835658af5

2021-12-05T20:13:09.766-05:00   REPORT RequestId: c4e087b5-a26b-4753-9552-98a835658af5 Duration: 59.03 ms Billed Duration: 60 ms Memory Size: 256 MB Max Memory Used: 117 MB

As you can see, the "1000" (TWILIO RESPONSE SHOULD BE HERE) message is created after the 1002 resuest is sent.

This is the Lambdla Log after the 1012 request.

2021-12-05T20:15:50.118-05:00   START RequestId: ece04ac8-267b-42fb-ada0-e54e9b6d36c1 Version: $LATEST

2021-12-05T20:15:50.121-05:00   2021-12-06T01:15:50.121Z fc58a37e-33bd-47d0-bade-d311d26aad86 ERROR Uncaught Exception {"message":"timeout of 30000ms exceeded","name":"Error","stack":"Error: timeout of 30000ms exceeded\n at createError (/opt/nodejs/node_modules/axios/lib/core/createError.js:16:15)\n at ClientRequest.handleRequestTimeout (/opt/nodejs/node_modules/axios/lib/adapters/http.js:303:16)\n at Object.onceWrapper (events.js:519:28)\n at ClientRequest.emit (events.js:400:28)\n at TLSSocket.emitRequestTimeout (_http_client.js:790:9)\n at Object.onceWrapper (events.js:519:28)\n at TLSSocket.emit (events.js:412:35)\n at TLSSocket.Socket._onTimeout (net.js:495:8)\n at listOnTimeout (internal/timers.js:557:17)\n at processTimers (internal/timers.js:500:7)","config":{"url":"https://api.twilio.com/2010-04-01/Accounts/ACa------4df747a33beec1c3/Messages.json","method":"post","data":"To=whatsapp%3A%2B51-----273&From=whatsapp%3A%2B14155238886&Body=1009","headers":{"Accept":"application/json","Content-Type":"application/x-www-form-urlencoded","User-Agent":"twilio-node/3.71.3 (linux x64) node/v14.18.1","Accept-Charset":"utf-8","Connection":"close","Authorization":"Basic QUNhNDgxOGQ4MmE0ZDY3YTE3NGRmNzQ3YTMzYmVlYzFjMzo3ZTVkODIwNTk2OGFmMTFkNTM5M2NlMzBhNjYzNjk4OQ==","Content-Length":69},"proxy":false,"transformRequest":[null],"transformResponse":[null],"timeout":30000,"xsrfCookieName":"XSRF-TOKEN","xsrfHeaderName":"X-XSRF-TOKEN","maxContentLength":-1,"maxBodyLength":-1,"maxRedirects":0,"transitional":{"silentJSONParsing":true,"forcedJSONParsing":true,"clarifyTimeoutError":false}},"code":"ECONNABORTED"}

2021-12-05T20:15:50.125-05:00   [ERROR] [1638753350125] LAMBDA_RUNTIME Failed to post handler success response. Http response code: 400.

2021-12-05T20:15:50.169-05:00   END RequestId: ece04ac8-267b-42fb-ada0-e54e9b6d36c1

2021-12-05T20:15:50.169-05:00   REPORT RequestId: ece04ac8-267b-42fb-ada0-e54e9b6d36c1 Duration: 47.66 ms Billed Duration: 48 ms Memory Size: 256 MB Max Memory Used: 118 MB

2021-12-05T20:15:50.169-05:00   RequestId: ece04ac8-267b-42fb-ada0-e54e9b6d36c1 Error: Runtime exited with error: exit status 129 Runtime.ExitError

2021-12-05T20:15:50.400-05:00   2021-12-06T01:15:50.400Z undefined INFO Trying to send a WhatsApp message...

2021-12-05T20:15:51.756-05:00   START RequestId: 89f858ae-e5ae-45dc-af37-e911458ac0d0 Version: $LATEST

2021-12-05T20:15:56.829-05:00   2021-12-06T01:15:56.829Z 89f858ae-e5ae-45dc-af37-e911458ac0d0 INFO Input received is: 1013

2021-12-05T20:15:57.007-05:00   2021-12-06T01:15:57.007Z 89f858ae-e5ae-45dc-af37-e911458ac0d0 INFO response LAMBDA: {"statusCode":200,"headers":{"x-custom-header":"my custom header value"},"body":"{\"message\":\"1013 is the input\",\"input\":{\"resource\":\"/helloworld\",\"path\":\"/helloworld\",\"httpMethod\":\"POST\",\"headers\":{\"Accept\":\"*/*\",\"Accept-Encoding\":\"gzip, deflate, br\",\"Authorization\":\"Bearer 3fa2c3d0-e110-11eb-b383-0b0630a03147\",\"Host\":\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\",\"Postman-Token\":\"2bcec7b9-d27a-4003-b2f3-1c69902877d3\",\"User-Agent\":\"PostmanRuntime/7.28.4\",\"X-Amzn-Trace-Id\":\"Root=1-61ad6447-2f4899486209116835f244bc\",\"X-Forwarded-For\":\"190.42.19.71\",\"X-Forwarded-Port\":\"443\",\"X-Forwarded-Proto\":\"https\"},\"multiValueHeaders\":{\"Accept\":[\"*/*\"],\"Accept-Encoding\":[\"gzip, deflate, br\"],\"Authorization\":[\"Bearer 3fa2c3d0-e110-11eb-b383-0b0630a03147\"],\"Host\":[\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\"],\"Postman-Token\":[\"2bcec7b9-d27a-4003-b2f3-1c69902877d3\"],\"User-Agent\":[\"PostmanRuntime/7.28.4\"],\"X-Amzn-Trace-Id\":[\"Root=1-61ad6447-2f4899486209116835f244bc\"],\"X-Forwarded-For\":[\"190.42.19.71\"],\"X-Forwarded-Port\":[\"443\"],\"X-Forwarded-Proto\":[\"https\"]},\"queryStringParameters\":{\"fecha\":\"1013\"},\"multiValueQueryStringParameters\":{\"fecha\":[\"1013\"]},\"pathParameters\":null,\"stageVariables\":null,\"requestContext\":{\"resourceId\":\"yiygu3\",\"resourcePath\":\"/helloworld\",\"httpMethod\":\"POST\",\"extendedRequestId\":\"J5ybPH8IoAMFkWQ=\",\"requestTime\":\"06/Dec/2021:01:15:51 +0000\",\"path\":\"/test/helloworld\",\"accountId\":\"487474028649\",\"protocol\":\"HTTP/1.1\",\"stage\":\"test\",\"domainPrefix\":\"ob9nw3nywj\",\"requestTimeEpoch\":1638753351743,\"requestId\":\"32a656fb-4ae3-4b18-8d8b-68e5880562e7\",\"identity\":{\"cognitoIdentityPoolId\":null,\"accountId\":null,\"cognitoIdentityId\":null,\"caller\":null,\"sourceIp\":\"190.42.19.71\",\"principalOrgId\":null,\"accessKey\":null,\"cognitoAuthenticationType\":null,\"cognitoAuthenticationProvider\":null,\"userArn\":null,\"userAgent\":\"PostmanRuntime/7.28.4\",\"user\":null},\"domainName\":\"ob9nw3nywj.execute-api.us-east-1.amazonaws.com\",\"apiId\":\"ob9nw3nywj\"},\"body\":null,\"isBase64Encoded\":false}}","isBase64Encoded":false}

2021-12-05T20:15:57.166-05:00   END RequestId: 89f858ae-e5ae-45dc-af37-e911458ac0d0

2021-12-05T20:15:57.166-05:00   REPORT RequestId: 89f858ae-e5ae-45dc-af37-e911458ac0d0 Duration: 5407.73 ms Billed Duration: 5408 ms Memory Size: 256 MB Max Memory Used: 65 MB

These are the WhatsApp messages to better understand the trobuleshoot.

[20:13, 12/5/2021] +1 (415) 523-8886: 1000
[20:13, 12/5/2021] +1 (415) 523-8886: 1001
[20:13, 12/5/2021] +1 (415) 523-8886: 1002
[20:13, 12/5/2021] +1 (415) 523-8886: 1003
[20:13, 12/5/2021] +1 (415) 523-8886: 1004
[20:13, 12/5/2021] +1 (415) 523-8886: 1005
[20:13, 12/5/2021] +1 (415) 523-8886: 1006
[20:13, 12/5/2021] +1 (415) 523-8886: 1007
[20:13, 12/5/2021] +1 (415) 523-8886: 1008
[20:13, 12/5/2021] +1 (415) 523-8886: 1009
[20:15, 12/5/2021] +1 (415) 523-8886: 1013
[20:16, 12/5/2021] +1 (415) 523-8886: 1014
[20:16, 12/5/2021] +1 (415) 523-8886: 1015

Please, help. Tell me if you need more information.

Thanks in advance.

Solution

I believe the issue here is that you are returning from the Lambda before the asynchronous request to the Twilio API is complete. You eventually receive the original requests because AWS seems to pause the event loop when a Lambda is complete and then resumes it when a new Lambda is started again.

I believe you can solve this by adding the await keyword before the call to the Twilio API.

await client.messages
  .create({
    body: date,
    from: "whatsapp:+1---------",
    to: "whatsapp:+1---------",
  })
  .then((message) =>
    console.log("TWILIO RESPONSE SHOULD BE HERE: " + JSON.stringify(message))
  )

You should likely add a try/catch around the API call too, so that you can handle API errors.

This should solve your previous question too.