[FIXED] AWS Lambda (RequestStreamLambda) IOStream Issues

Issue

I have a Java 11 Lambda that implements RequestStreamLambda:

public class ListArticlesHandler implements RequestStreamHandler {

    @Inject
    private ListArticlesService listArticlesService;

    @Override
    public void handleRequest(InputStream inputStream, OutputStream outputStream, Context context)
            throws IOException {

        LambdaLogger logger = context.getLogger();
        logger.log("log me something, please, anything...");
        ObjectMapper om = new ObjectMapper();
        logger.log("again, anything...");

        String event = readEvent(inputStream, logger);
        logger.log("I survived the stringing of the stream!");
        logger.log("did I get the event though?: " + event);
        // LOGGER.info(this, event);
        JsonNode node = JsonNodeFactory.instance.nullNode();
        try {
            node = om.readTree(event);
        } catch (JsonProcessingException e) {
            logger.log("unable to parse event into JSON: " + event);
        }

        JsonNode queryParams = node.get("queryStringParameters");

        List<Article> articles = null;
        if (queryParams != null) {
            JsonNode author = queryParams.get("author");
            if (author != null) {
                articles = listArticlesService.listArticlesCreatedBy(author.asText());
                logger.log(articles != null ? articles.stream().map(Article::getTitle).collect(Collectors.joining()) : "null");
                // LOGGER.info(this, "articles", articles != null ? articles.stream().map(Article::getTitle).collect(Collectors.joining()) : "null");
            }

            JsonNode month = queryParams.get("month");
            JsonNode year = queryParams.get("year");
            if (month != null && year != null) {
                LocalDateTime ldts = LocalDate.of(year.asInt(), month.asInt(), 1).atStartOfDay();
                long millisStart = ldts.toEpochSecond(ZoneOffset.UTC);

                LocalDateTime ldte = LocalDate.of(year.asInt(), month.asInt(), 1).with(TemporalAdjusters.lastDayOfMonth()).atTime(23, 59, 59);
                long millisEnd = ldte.toEpochSecond(ZoneOffset.UTC);

                articles = listArticlesService.listArticlesCreatedBetween(millisStart, millisEnd);
                logger.log(articles != null ? articles.stream().map(Article::getTitle).collect(Collectors.joining()) : "null");
                //LOGGER.info(this, "articles", articles != null ? articles.stream().map(Article::getTitle).collect(Collectors.joining()) : "null");
            }

            JsonNode tag = queryParams.get("tag");
            if (tag != null) {
                articles = listArticlesService.listArticlesWithTag(tag.asText());
                logger.log(articles != null ? articles.stream().map(Article::getTitle).collect(Collectors.joining()) : "null");
                //LOGGER.info(this, "articles", articles != null ? articles.stream().map(Article::getTitle).collect(Collectors.joining()) : "null");
            }

        }

        if (articles != null) {
            StreamResponse<List<Article>> res = new StreamResponse<>(200, 0, articles);
            logger.log(articles.stream().map(Article::getTitle).collect(Collectors.joining()));
            //LOGGER.info(this, "returning articles", articles.stream().map(Article::getTitle).collect(Collectors.joining()));
            String responseJson = om.writeValueAsString(res);
            OutputStreamWriter writer = new OutputStreamWriter(outputStream, StandardCharsets.UTF_8);
            writer.write(responseJson);
            writer.close();
        }
    }


    protected String readEvent(InputStream inputStream, LambdaLogger logger) {

        logger.log("running readEvent on inputStream");
        StringBuilder textBuilder = new StringBuilder();
        Reader reader = new BufferedReader(new InputStreamReader
                (inputStream, Charset.forName(StandardCharsets.UTF_8.name())));
        int c = 0;
        try {
            while ((c = reader.read()) != -1) {
                textBuilder.append((char) c);
            }
        } catch (IOException e) {
            logger.log(e.getMessage());
        }

        logger.log("returning event: " + textBuilder.toString());
        return textBuilder.toString();
    }

}

It is wired up to AWS APIGateway via a CloudFormation deployment, using the following template (note that this is an extract from that template):

Resources:
  UTableArticle:
    Type: AWS::DynamoDB::Table
    Properties:
      KeySchema:
        - AttributeName: id
          KeyType: HASH
      AttributeDefinitions:
        - AttributeName: id
          AttributeType: S
      ProvisionedThroughput:
        ReadCapacityUnits: 1
        WriteCapacityUnits: 1
      TableName: !Sub ${AWS::StackName}-Article
    UpdateReplacePolicy: Retain
    DeletionPolicy: Retain

  FunctionAssumeRoleRole:
    Type: AWS::IAM::Role
    Properties:
      AssumeRolePolicyDocument:
        Statement:
          - Action: sts:AssumeRole
            Effect: Allow
            Principal:
              Service: lambda.amazonaws.com
        Version: "2012-10-17"
      ManagedPolicyArns:
        - 'arn:aws:iam::aws:policy/service-role/AWSLambdaBasicExecutionRole'

  DynamoActionsPolicy:
    Type: AWS::IAM::Policy
    Properties:
      PolicyDocument:
        Statement:
          - Action:
              - dynamodb:BatchGetItem
              - dynamodb:GetRecords
              - dynamodb:GetShardIterator
              - dynamodb:Query
              - dynamodb:GetItem
              - dynamodb:Scan
              - dynamodb:BatchWriteItem
              - dynamodb:PutItem
              - dynamodb:UpdateItem
              - dynamodb:DeleteItem
            Effect: Allow
            Resource:
              - !GetAtt [ UTableArticle, Arn ]
              - !Ref AWS::NoValue
        Version: "2012-10-17"
      PolicyName: DynamoActionsPolicy
      Roles:
        - !Ref FunctionAssumeRoleRole
  BFunctionListArticles:
    Type: AWS::Lambda::Function
    Properties:
      Code:
        S3Bucket: !Ref ArtefactRepositoryBucket
        S3Key: !Join [ '', [!Ref ArtefactRepositoryKeyPrefix, '.zip' ] ]
      Handler: !Ref 'ListArticlesHandler'
      Role: !GetAtt [ FunctionAssumeRoleRole, Arn ]
      Runtime: java11
      Environment:
        Variables:
          TABLE_NAME: !Ref UTableArticle
          PRIMARY_KEY: id
    DependsOn:
      - DynamoActionsPolicy
      - FunctionAssumeRoleRole

  BFunctionGWPermissionGetArticle:
    Type: AWS::Lambda::Permission
    DependsOn:
      - BlogRestApi
      - BFunctionListArticles
    Properties:
      Action: lambda:InvokeFunction
      FunctionName: !GetAtt [ BFunctionListArticles, Arn ]
      Principal: apigateway.amazonaws.com
      SourceArn: !Join ['', ['arn:', !Ref 'AWS::Partition', ':execute-api:', !Ref 'AWS::Region', ':', !Ref 'AWS::AccountId', ':', !Ref BlogRestApi, '/*/GET/article'] ]
  BlogRestApi:
    Type: AWS::ApiGateway::RestApi
    Properties:
      Name: Article
  AGWDeploymentArticle:
    Type: AWS::ApiGateway::Deployment
    Properties:
      RestApiId: !Ref BlogRestApi
      Description: Automatically created by the RestApi construct
    DependsOn:
      - MethodArticleIdGet
      - MethodArticleIdPatch
      - ResourceArticleId
      - MethodArticleGet
      - MethodArticlePost
      - ResourceArticle
  BAGDeploymentStageProdArticle:
    Type: AWS::ApiGateway::Stage
    Properties:
      RestApiId: !Ref BlogRestApi
      DeploymentId: !Ref AGWDeploymentArticle
      StageName: prod
  ResourceArticle:
    Type: AWS::ApiGateway::Resource
    Properties:
      ParentId: !GetAtt [ BlogRestApi, RootResourceId ]
      PathPart: article
      RestApiId: !Ref BlogRestApi
  MethodArticleGet:
    Type: AWS::ApiGateway::Method
    Properties:
      HttpMethod: GET
      ResourceId: !Ref ResourceArticle
      RestApiId: !Ref BlogRestApi
      AuthorizationType: NONE
      Integration:
        IntegrationHttpMethod: POST
        Type: AWS_PROXY
        Uri: !Join [ "", ['arn:', !Ref 'AWS::Partition', ':apigateway:', !Ref 'AWS::Region', ':lambda:path/2015-03-31/functions/', !GetAtt [ BFunctionListArticles, Arn ], '/invocations' ] ]

CloudFromation deploys correctly and I can make calls through a cURL on the deployment as a whole or I can go to the API Gateway resource and conduct a test there. In either case, a call into the Lambda seems to stall with a timeout. What's strange about this is that the first log message:

logger.log("log me something, please, anything...");

actually comes out, but the second one:

logger.log("again, anything...");

Does not. If I remove all logging, I get the same issue, namely:

Fri May 08 23:58:44 UTC 2020 : Received response. Status: 200, Integration latency: 3573 ms
Fri May 08 23:58:44 UTC 2020 : Endpoint response headers: {Date=Fri, 08 May 2020 23:58:44 GMT, Content-Type=application/json, Content-Length=114, Connection=keep-alive, x-amzn-RequestId=1bac3448-38d6-4545-9169-665dc555c47b, X-Amz-Function-Error=Unhandled, x-amzn-Remapped-Content-Length=0, X-Amz-Executed-Version=$LATEST, X-Amzn-Trace-Id=root=1-5eb5f230-4ecec6172243f15370738cce;sampled=0}
Fri May 08 23:58:44 UTC 2020 : Endpoint response body before transformations: {"errorMessage":"2020-05-08T23:58:44.545Z 1bac3448-38d6-4545-9169-665dc555c47b Task timed out after 3.00 seconds"}
Fri May 08 23:58:44 UTC 2020 : Lambda execution failed with status 200 due to customer function error: 2020-05-08T23:58:44.545Z 1bac3448-38d6-4545-9169-665dc555c47b Task timed out after 3.00 seconds. Lambda request id: 1bac3448-38d6-4545-9169-665dc555c47b
Fri May 08 23:58:44 UTC 2020 : Method completed with status: 502

It feels like I haven't handled the InputStream properly, or I am somehow chopping it off, or something. The AWS documentation I've read hasn't provided any clues as to what's going on here. Any suggestions (not involving serveless.com)?

Solution

Your lambda is timing out after 3 seconds. From your error message:

Task timed out after 3.00 seconds

I think increasing the timeout should help. In CloudFormation you have Timeout parameter for that:

The amount of time that Lambda allows a function to run before stopping it. The default is 3 seconds. The maximum allowed value is 900 seconds.

Answered By - Marcin
Answer Checked By - Cary Denson (JavaFixing Admin)