Concurrent Invocations Not Executing?

Serverless Framework
1

I have a simple service that takes HTTP post requests and saves them to a dynamoDB table. If the requests don’t overlap, everything works beautifully. However, when I get requests within a few milliseconds of each other, only the last of those actually seems to run, as indicated by missing console.log statements:

START RequestId: 5cec9307-3408-11e7-9bb7-030ba071efae Version: $LATEST
START RequestId: 5ceb5a97-3408-11e7-b6a4-a3cfd9a995bf Version: $LATEST
2017-05-08 12:07:04.301 (-04:00) 5ceb5a97-3408-11e7-b6a4-a3cfd9a995bf Received request
2017-05-08 12:07:04.303 (-04:00) 5ceb5a97-3408-11e7-b6a4-a3cfd9a995bf Received request and assigned it id 6097bff0-3408-11e7-a6af-cd8bf8ab0924
END RequestId: 5cea974c-3408-11e7-ba65-ffadf5101311
REPORT RequestId: 5cea974c-3408-11e7-ba65-ffadf5101311 Duration: 150.56 ms Billed Duration: 200 ms Memory Size: 1024 MB Max Memory Used: 31 MB

END RequestId: 5ceb5a97-3408-11e7-b6a4-a3cfd9a995bf
REPORT RequestId: 5ceb5a97-3408-11e7-b6a4-a3cfd9a995bf Duration: 158.29 ms Billed Duration: 200 ms Memory Size: 1024 MB Max Memory Used: 32 MB

Looking at these logs, I see two requests. The second request (5ceb…) is handled as expected and has the expected log statements. The first request, though (5cec…) doesn’t have any log statements, and, in fact, never shows as being completed. Instead, we see another request (5cea…) complete without any log entry showing it as starting and without any of the expected console.log statements. Am I interpreting the logs wrong? Is my use of UUID somehow conflicting with Amazon’s request IDs? And why isn’t the function executing?

I’ve spent a while trying to debug this and can’t figure out what I’m doing wrong; any help is much appreciated. I’ve included slightly redacted Node and serverless.yml files below.

serverless.yml

service: myService

custom:
  babelPresets:
    - es2015

plugins
- serverless-babel-plugin

provider:
  name: aws
  runtime: nodejs4.3
  stage: dev
  region: us-east-1
  timeout: 120
  iamRoleStatements:
    - Effect: "Allow"
      Action:
        - "ec2:CreateNetworkInterface"
        - "ec2:DescribeNetworkInterfaces"
        - "ec2:DetachNetworkInterface"
        - "ec2:DeleteNetworkInterface"
        - "dynamodb:DescribeTable"
        - "dynamodb:Query"
        - "dynamodb:Scan"
        - "dynamodb:GetItem"
        - "dynamodb:PutItem"
        - "dynamodb:UpdateItem"
        - "dynamodb:DeleteItem"
        - "dynamodb:DescribeStream"
        - "dynamodb:GetRecords"
        - "dynamodb:GetShardIterator"
        - "dynamodb:ListStreams"
      Resource: "*"
  vpc:
    subnetIds:
      - REDACTED
    securityGroupIds:
      - REDACTED
  environment:
    DYNAMO_REQUEST_TABLE: ${self:service}-${opt:stage, self:provider.stage}-requests
    ENV: 'test'

functions:
  requestFoo
    handler: lib/requestFoo.requestFoo
    events:
      - http:
          path: requestFoo
          method: post
          cors: true
  
resources:
  Resources:
    RequestQueueTable:
      Type: 'AWS::DynamoDB::Table'
      DeletionPolicy: Retain
      Properties:
        AttributeDefinitions:
          -
             AttributeName: id
             AttributeType: S
         KeySchema:
           -
             AttributeName: id
             KeyType: HASH
         ProvisionedThroughput:
           ReadCapacityUnits: 20
           WriteCapacityUnits: 20
         StreamSpecification:
           StreamViewType: NEW_AND_OLD_IMAGES
         TableName: ${self:provider.environment.DYNAMO_REQUEST_TABLE}

###requestFoo.js

const AWS = require('aws-sdk');
const uuid = require('uuid');
const dynamoDb = new AWS.DynamoDB.DocumentClient();
const requestTable = process.env.DYNAMO_REQUEST_TABLE;

function handleSuccess(callback, url) {
  const response = {
    statusCode: 200,
    headers: {
      location: url,
    },
    body: JSON.stringify({
      statusUrl: url,
    }),
  };
  callback(null, response);
}

function handleError(callback, input, err) {
  const errResponse = {
    statusCode: 400,
    body: JSON.stringify(err, Object.getOwnPropertyNames(err)),
    input: input,
  };
  callback(null, errResponse);
}

function requestFoo(event, context, callback) {
  console.log('Received request');
  var request = event.body;
  if (typeof request === 'string') {
    request = JSON.parse(request);
  }

  const id = uuid.v1();
  console.log('Received request and assigned it id ' + id);
  const timestamp = new Date().getTime();
  const params = {
    TableName: requestTable,
    Item: {
      id: id,
      request: request,
      status: 204,
      lastUpdated: timestamp,
      createdAt: timestamp,
    },
  };
  dynamoDb.put(params, (error) => {
    if (error) {
      console.log(error);
      handleError(callback, event.body, error);
      return;
    }

    handleSuccess(callback, '/status/' + id);
  });
}

module.exports = {
  requestFoo: requestFoo
};
2

Can you format the javascript and yaml properly using ```javascript or ```yaml at the top and ``` at the bottom so it’s readable?

3

Do you ever see END or REPORT lines for the first request (i.e. 5cec...)? If not, I’d be logging a support call to AWS - I can’t think of any good reason why you shouldn’t see some additional data (especially billing!) for that first request, and I doubt there’s much you or your code can do about it if not.

4

Done. Thanks for the tip!

5

Those don’t appear, so I guess I’ll reach out to support. Thanks.