[reproduction] nodejs10.x lambda error: handler called twice in same request

README.md

This is a minimal* reproduction for a bug in the AWS lambda Node 10.X runtime.

* I'm still honing in on the precise cause to make this smaller.

Description

The lambda runtime nodejs10.x sometimes calls the handler twice with the same event within the same request.

Note this is different than the known "SQS at least once" behaviour, as that would be much less common and have differing request ids.

Example output is included as cloudwatch.log.

Reproduction

• Create a blank nodejs10.x lambda in eu-west-1
• Replace index.js with the implementation included
• Create a new SQS queue (default options, i.e. not FIFO)
• Set the SQS queue as the event source, with a batch size one 1
• Set an environment variable for QUEUE_URL to the url for the queue
• Reserve a concurrency of 2 for the lambda function
• Add sqs:* permissions to the lambda role for the queue
• Start the lambda with the included test.json
• Watch the logs in cloudwatch, soon (apx. 1/10) you'll see a "double call"
• Redeploy with STOP=false (top of file) to stop lambda

cloudwatch.log

START RequestId: caed6a0c-1015-44e8-892a-3e1d87d0bdc1 Version: $LATEST
2019-05-23T14:11:13.626Z caed6a0c-1015-44e8-892a-3e1d87d0bdc1 INFO start 1
2019-05-23T14:11:13.627Z caed6a0c-1015-44e8-892a-3e1d87d0bdc1 INFO 1 '35a958fa-9e02-40eb-a9bf'
2019-05-23T14:11:14.506Z caed6a0c-1015-44e8-892a-3e1d87d0bdc1 INFO { message: 'enqueued 1 records successfully', function: 'retryEnqueue' }
2019-05-23T14:11:14.506Z caed6a0c-1015-44e8-892a-3e1d87d0bdc1 INFO end 1
2019-05-23T14:11:14.586Z caed6a0c-1015-44e8-892a-3e1d87d0bdc1 INFO start 2
2019-05-23T14:11:14.586Z caed6a0c-1015-44e8-892a-3e1d87d0bdc1 INFO 1 '35a958fa-9e02-40eb-a9bf'
2019-05-23T14:11:14.687Z caed6a0c-1015-44e8-892a-3e1d87d0bdc1 INFO { message: 'enqueued 1 records successfully', function: 'retryEnqueue' }
2019-05-23T14:11:14.687Z caed6a0c-1015-44e8-892a-3e1d87d0bdc1 INFO end 2
END RequestId: caed6a0c-1015-44e8-892a-3e1d87d0bdc1
REPORT RequestId: caed6a0c-1015-44e8-892a-3e1d87d0bdc1 Duration: 1177.77 ms Billed Duration: 1200 ms Memory Size: 128 MB Max Memory Used: 92 MB
START RequestId: c981f632-97b1-518b-bb40-a3523b8855a6 Version: $LATEST
2019-05-23T14:11:19.299Z c981f632-97b1-518b-bb40-a3523b8855a6 INFO start 3

index.js

/* eslint-disable no-console */
const { SQS } = require('aws-sdk'); // eslint-disable-line import/no-extraneous-dependencies

// opts:

const STOP = false;
const SqsQueueUrl = process.env.QUEUE_URL;

// aws-sdk:

const region = 'eu-west-1';
const sqs = new SQS({ region });

// sqs
const tick = () => new Promise(r => setTimeout(r, 1));

async function hold(payload) {
  const message = JSON.stringify({ d: payload });
  tick(); // omit: saving record in s3
  return message;
}

async function enqueue(records, {
  QueueUrl,
  DelaySeconds = 0,
  partition,
  ...options
}) {
  const Entries = await Promise.all(Object.entries(records).map(async ([idx, r]) => {
    const MessageBody = await hold(r, { partition, recordCount: records.length });
    return { Id: idx.toString(), MessageBody, DelaySeconds };
  }));

  return sqs.sendMessageBatch({ QueueUrl, Entries, ...options }).promise()
    .then(({ Successful, Failed }) => {
      if (Failed.length === 0) {
        console.log({ message: `enqueued ${Successful.length} records successfully` });
        return Promise.resolve([]);
      }
      const retrySet = Failed.map(({ Id }) => records[Id]);
      console.error({ message: `failed to enqueue ${retrySet.length} records` });
      return Promise.reject(retrySet);
    });
}

async function retrieve({ body }) {
  const parsed = JSON.parse(body);
  await tick(); // omit: s3 capabilities.
  return parsed;
}
async function extract({ Records }) {
  const payloads = await Promise.all(Records.map(retrieve));
  return payloads;
}

// handler

let count = 0;

async function schedule(event) {
  if (STOP) {
    return true;
  }
  count += 1;
  console.log('start', count);
  console.log(event.Records.length, event.Records[0].messageId);
  try {
    const [messageMonitor] = await extract(event);
    const DelaySeconds = 5;
    await enqueue([messageMonitor], { QueueUrl: SqsQueueUrl, DelaySeconds });
  } catch (error) {
    console.error({
      message: 'unhandled error',
      event,
      error,
    });
    throw error;
  }
  console.log('end', count);
  return true;
}

// lambda

exports.handler = schedule;

test-event.json

{
  "Records": [
    {
      "messageId": "35a958fa-9e02-40eb-a9bf",
      "body": "{}",
      "attributes": {
        "ApproximateReceiveCount": "1",
        "SentTimestamp": "1558552981584",
        "ApproximateFirstReceiveTimestamp": "1558553040584"
      },
      "messageAttributes": {},
      "eventSource": "aws:sqs",
      "awsRegion": "eu-west-1"
    }
  ]
}