Часть моей лямбда-функции выполняется дважды

Я пишу лямбда-функцию AWS, которая должна обновлять ежедневную статистику игрока каждый раз, когда он выполняет упражнение. Функция запускается один раз с настроенным 0 повторных попыток при новом событии строки DynamoDB.

Я тестирую только эту функцию, уверен, что создаю только одну строку в DynamoDB, которая запускает выполнение лямбда-выражения. Теперь самое интересное. Моя лямбда выполняется один раз целиком, но какая-то ее часть выполняется дважды в одном запросе.

Вот лямбда-код:

    const AWS = require('aws-sdk');
    var docClient = new AWS.DynamoDB.DocumentClient({region: 'us-west-2'});
    
    const dailyStatsTableName = 'xxx';
    const weeklyStatsTableName = 'yyy';
    const monthlyStatsPlayerTableName = 'zzz';
    const requestsTableName = 'qqq';
    
    exports.handler = async (event, context, callback) => {
      //Ensure idempotency of lambda as a whole
      let requestID = context.awsRequestId;
      let requestAlreadyProcessed = false;
      
      await getRequest(requestsTableName, requestID, (err, data) => {
        if (err) {
          console.log(err);
        } else {
          if (data.Item) {
            requestAlreadyProcessed = true;
          }
        }
      });
      
      if (requestAlreadyProcessed) {
        console.log("This request has already been processed. Aborting.");
        return;
      }
      
      console.log("Processing new assigned drill performance event. RequestID: " + requestID);
      console.log(event);
      const record = event.Records[0].dynamodb;
      console.log(record);
      if (!record || !record.NewImage) {
        console.log("New record image undefined");
        return;
      }
      console.log(record.NewImage);
      
      //Get performed touches to count them in statistics
      let touches = 0;
      try {
        touches = parseInt(record.NewImage.touches.N, 10);
      } catch (error) {
        console.error(error);
      }
      
      //Unpack date from record.NewImage.createdAt string
      let performanceDate = new Date(Date.parse(record.NewImage.createdAt.S));
      console.log("CreatedAt date: " + performanceDate);
      
      //Get daily statistics object from table - I want to update if already exist
      let dailyStats = {
        drillID: record.NewImage.drillID.S,
        targetUserID: record.NewImage.targetUserID.S,
        performDay: performanceDate.getDate(),
        performMonth: performanceDate.getMonth(),
        performYear: performanceDate.getFullYear(),
        performDate: performanceDate.toISOString(),
        touches: 0,
        id: undefined
      };
      let result = await getDailyStats(dailyStatsTableName, dailyStats.performDay, dailyStats.performMonth, dailyStats.performYear, dailyStats.drillID, dailyStats.targetUserID, (err, data) => {
        if (err) {
          console.log(err);
        } else {
          if (data.Items.length !== 0) {
            console.log("Found daily stats object"); //this console.log is logged twice. Everything below that line is executed twice.
            dailyStats = data.Items[0];
          }
        }
        return "success";
      });
      
      //Create or update daily statistics
      if (!dailyStats.id) {
        console.log("DailyStats ID not found. Creating new with touches " + touches);
        dailyStats.touches = touches;
        result = await createDailyStats(dailyStatsTableName, dailyStats, requestID, (err, data) => {
          if (err) {
            console.log(err);
          } else {
            console.log("Success creating daily stats " + dailyStats.drillID + " " + dailyStats.targetUserID + " " + dailyStats.touches);
          }
          return "success";
        });
      } else {
        console.log("DailyStats ID found. Updating existing with touches " + touches);
        result = await updateDailyStats(dailyStatsTableName, dailyStats.id, touches, requestID, (err, data) => {
          if (err) {
            console.log(err);
          } else {
            console.log("Success updating daily stats " + dailyStats.drillID + " " + dailyStats.targetUserID + " " + touches);
          }
          return "success";
        });
      }
      //Mark this request as processed to ensure idempotency of lambda as a whole
      result = await createProcessedRequest(requestsTableName, requestID, (err, data) => {
          if (err) {
            console.log(err);
          } else {
            console.log("Success creating processed request " + requestID);
          }
          return "success";
        });
      return "success";
    };
    
    function createDailyStats(tableName, stats, requestID, callback) {
      let now = new Date();
      let dateTimeString = now.toISOString();
      let params = {
        TableName:tableName,
        Item:{
          "__typename": "PersonalDrillDailyStatistic",
          "createdAt": dateTimeString,
          "updatedAt": dateTimeString,
          "id": stats.id ? stats.id : createUUID(),
          "drillID": stats.drillID,
          "targetUserID": stats.targetUserID,
          "touches": stats.touches,
          "performDay": stats.performDay,
          "performMonth": stats.performMonth,
          "performYear": stats.performYear,
          "lastRequestID": requestID
        }
      };
      
      console.log("Adding a new daily stats (with id) item... " + stats.drillID + " " + stats.targetUserID + " " + stats.touches);
      return docClient.put(params, callback).promise();
    }
    
    function updateDailyStats(tableName, statsID, touches, requestID, callback) {
      var params = {
        TableName:tableName,
        Key:{
            "id": statsID
        },
        UpdateExpression: "set touches = touches + :val, lastRequestID = :reqID",
        ExpressionAttributeValues:{
            ":val": touches,
            ":reqID": requestID
        },
        ConditionExpression: "lastRequestID <> :reqID", //conditional check exception is being thrown during second call, hence Exception in logs output
        ReturnValues:"UPDATED_NEW"
      };
      
      console.log("Updating daily stats (with id) item... " + statsID + " " + touches);
      return docClient.update(params, callback).promise();
    }
    
    function getDailyStats(tableName, performDay, performMonth, performYear, drillID, targetUserID, callback) {
      console.log("Querying for daily statistics |" + performDay + "." + performMonth + "." + performYear + "| userID: |" + targetUserID + "| drillID: |" + drillID + "| from table " + tableName);
      let params = {
        TableName: tableName,
        FilterExpression: "drillID = :drill_id and targetUserID = :user_id and performDay = :day and performMonth = :month and performYear = :year",
        ExpressionAttributeValues: {
            ":drill_id": drillID,
            ":user_id": targetUserID,
            ":day": performDay,
            ":month": performMonth,
            ":year": performYear,
        }
      };
      return docClient.scan(params, callback).promise();
    }
    
    function createUUID(){
      (...)
    }
    
    function getRequest(tableName, requestID, callback) {
      let params = {
        TableName: tableName,
        Key: {
          "id": requestID
        }
      };
      return docClient.get(params, callback).promise();
    }
    
    function createProcessedRequest(tableName, requestID, callback) {
      let params = {
        TableName:tableName,
        Item:{
          "id": requestID,
          "name": requestID
        }
      };
      
      return docClient.put(params, callback).promise();
    }

Вот выходные данные CloudWatch для этого выполнения лямбда-выражения:

2021-04-16T22:24:49.754+02:00   START RequestId: 8766c005-c1f3-42fb-aee9-9e8352da67ed Version: $LATEST

2021-04-16T22:24:50.464+02:00   2021-04-16T20:24:50.464Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO Processing new assigned drill performance event. RequestID: 8766c005-c1f3-42fb-aee9-9e8352da67ed

2021-04-16T22:24:50.523+02:00   2021-04-16T20:24:50.523Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO { Records: [ { eventID: 'e09a400894c178ef66840f54e71b6c26', eventName: 'INSERT', eventVersion: '1.1', eventSource: 'aws:dynamodb', awsRegion: 'us-west-2', dynamodb: [Object], eventSourceARN: 'arn:aws:dynamodb:us-west-2:900776852541:table/FDrillPerformance-y22t7izqyvb2xiruvbf4zhadvm-fissiondev/stream/2021-04-15T21:48:06.158' } ] }

2021-04-16T22:24:50.541+02:00   2021-04-16T20:24:50.541Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO { ApproximateCreationDateTime: 1618604689, Keys: { id: { S: '7321fcf5-fed2-402a-b1cf-7667e958f73a' } }, NewImage: { createdAt: { S: '2021-04-16T20:24:49.077Z' }, touches: { N: '25' }, __typename: { S: 'FDrillPerformance' }, drillID: { S: '01adc7e6-67be-4bdf-828b-36833cbd7070' }, targetUserID: { S: 'd4a95710-c4fb-4f0f-8355-76082e41c43a' }, id: { S: '7321fcf5-fed2-402a-b1cf-7667e958f73a' }, updatedAt: { S: '2021-04-16T20:24:49.077Z' } }, SequenceNumber: '218143500000000009280556527', SizeBytes: 269, StreamViewType: 'NEW_IMAGE' }

2021-04-16T22:24:50.561+02:00   2021-04-16T20:24:50.561Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO { createdAt: { S: '2021-04-16T20:24:49.077Z' }, touches: { N: '25' }, __typename: { S: 'FDrillPerformance' }, drillID: { S: '01adc7e6-67be-4bdf-828b-36833cbd7070' }, targetUserID: { S: 'd4a95710-c4fb-4f0f-8355-76082e41c43a' }, id: { S: '7321fcf5-fed2-402a-b1cf-7667e958f73a' }, updatedAt: { S: '2021-04-16T20:24:49.077Z' } }

2021-04-16T22:24:50.581+02:00   2021-04-16T20:24:50.581Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO CreatedAt date: Fri Apr 16 2021 20:24:49 GMT+0000 (Coordinated Universal Time)

2021-04-16T22:24:50.581+02:00   2021-04-16T20:24:50.581Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO Querying for daily statistics |16.3.2021| userID: |d4a95710-c4fb-4f0f-8355-76082e41c43a| drillID: |01adc7e6-67be-4bdf-828b-36833cbd7070| from table PersonalDrillDailyStatistic-y22t7izqyvb2xiruvbf4zhadvm-fissiondev

2021-04-16T22:24:50.784+02:00   2021-04-16T20:24:50.783Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO Found daily stats object

2021-04-16T22:24:50.784+02:00   2021-04-16T20:24:50.784Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO DailyStats ID found. Updating existing with touches 25

2021-04-16T22:24:50.784+02:00   2021-04-16T20:24:50.784Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO Updating daily stats (with id) item... ab00afe1-ed4b-4895-b1bb-31ac570fe46d 25

2021-04-16T22:24:50.883+02:00   2021-04-16T20:24:50.883Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO Found daily stats object

2021-04-16T22:24:51.302+02:00   2021-04-16T20:24:51.302Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO Success updating daily stats 01adc7e6-67be-4bdf-828b-36833cbd7070 d4a95710-c4fb-4f0f-8355-76082e41c43a 25

2021-04-16T22:24:51.401+02:00   2021-04-16T20:24:51.384Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO ConditionalCheckFailedException: The conditional request failed at Request.extractError (/var/runtime/node_modules/aws-sdk/lib/protocol/json.js:52:27) at Request.callListeners (/var/runtime/node_modules/aws-sdk/lib/sequential_executor.js:106:20) at Request.emit (/var/runtime/node_modules/aws-sdk/lib/sequential_executor.js:78:10) at Request.emit (/var/runtime/node_modules/aws-sdk/lib/request.js:688:14) at Request.transition (/var/runtime/node_modules/aws-sdk/lib/request.js:22:10) at AcceptorStateMachine.runTo (/var/runtime/node_modules/aws-sdk/lib/state_machine.js:14:12) at /var/runtime/node_modules/aws-sdk/lib/state_machine.js:26:10 at Request.<anonymous> (/var/runtime/node_modules/aws-sdk/lib/request.js:38:9) at Request.<anonymous> (/var/runtime/node_modules/aws-sdk/lib/request.js:690:12) at Request.callListeners (/var/runtime/node_modules/aws-sdk/lib/sequential_executor.js:116:18) { code: 'ConditionalCheckFailedException', time: 2021-04-16T20:24:51.383Z, requestId: 'H8PC553OQABGJKR9KFIJMR1EHJVV4KQNSO5AEMVJF66Q9ASUAAJG', statusCode: 400, retryable: false, retryDelay: 36.82252581429517 }

2021-04-16T22:24:51.462+02:00   2021-04-16T20:24:51.462Z 8766c005-c1f3-42fb-aee9-9e8352da67ed INFO Success creating processed request 8766c005-c1f3-42fb-aee9-9e8352da67ed

2021-04-16T22:24:51.482+02:00   END RequestId: 8766c005-c1f3-42fb-aee9-9e8352da67ed

2021-04-16T22:24:51.482+02:00   REPORT RequestId: 8766c005-c1f3-42fb-aee9-9e8352da67ed Duration: 1728.11 ms Billed Duration: 1729 ms Memory Size: 128 MB Max Memory Used: 91 MB Init Duration: 413.89 ms

Итак, вы можете видеть, что хотя лямбда вызывается один раз, некоторые ее части вызываются дважды, и я не знаю, как с этим бороться. Мне также нужно обновлять еженедельную и ежемесячную статистику, поэтому проблема усложняется. Взлом с ConditionExpression по последнему идентификатору запроса работает, но я бы позаботился о том, чтобы код внутри моей функции не запускался дважды, вместо того, чтобы пытаться использовать такие обходные пути.


person greenskin    schedule 16.04.2021    source источник
comment
Не уверен, что это ваша проблема, но вы комбинируете обратные вызовы с async / await. Когда вы выполняете ожидание, вы не используете механизм обратного вызова в цепочке обещаний.   -  person Jason Wadsworth    schedule 17.04.2021


Ответы (1)


Следуя комментарию @Jason Wadsworth, я изменил все вызовы функций в функции exports.handler, удалив функции обратного вызова. Обратите внимание, что я оставил параметры обратного вызова в функциях, связанных с динамо, например updateDailyStats - без него код по какой-то причине не записывался в базу данных.

person greenskin    schedule 17.04.2021