タイムアウトでエラーとなってしまったLambdaのリカバリを行うLambdaを作成してみました

1 はじめに

CX事業本部の平内（SIN）です。

Lambda関数は、タイムアウトに設定した時間が経過すると、エラーとなります。

2019-11-25T03:03:27.778Z 5f46427d-c6f4-4785-be32-060acf425de0 Task timed out after 3.00 seconds

タイムアウトの場合、Dead Letter Queueでリカバリすることは出来ません。 CloudWatchメトリックスのアラートでは、エラーとなった関数名は分かりますが、RequestIdなど、スレッドを識別する情報が取得できません。また、アラートは、敷居値を跨いだ際のイベントなので、全てのエラーをタイムリーにリカバリするのは難しいと思います。

今回は、外部呼び出しなどが予想外に時間がかかってしまって、意図せず、タイムアウトとなってしまった場合の、リカバリ用のLambdaを起動する要領を試して見ました。

2 タイムアウトする関数

サンプルとして、下記のような関数を作成してみました。外部APIの呼び出しイメージしたメソッドを同期処理で5回、呼び出しています。

メソッドは、１秒の処理時間がかかるので、最後まで実行するには、最低5秒が必要です。

exports.handler = async (event) => {
    apiFunction(); // 外部APIに呼び出し
    apiFunction(); // 外部APIに呼び出し
    apiFunction(); // 外部APIに呼び出し
    apiFunction(); // 外部APIに呼び出し
    apiFunction(); // 外部APIに呼び出し
    return {};
};

// レスポンスを受けるのに１秒必要な外部APIをコールする処理
function apiFunction() {
  const msec = 1000;
  var start = new Date();
  while (new Date() - start < msec);
}

タイムアウトがデフォルトの3秒となっている場合、この関数は、エラーとなって途中で修了してしまいます。

3 リカバリ処理用のLambda

先のLambdaがタイムアウトした場合に、それをリカバリするLambda関数の定義です。

タイムアウト時のエラーメッセージとして表示される「Task timed out after」をフィルターパターンとした、Clodwatch Logsをトリガーにしています。また、先のLambdaのログを取得するためにCloudWatch Logsを読み込むパーミッションも追加しています。

Lambdaのコードは、以下のようになっています。トリガーで起動された場合、そのリクエストには、当該行のログが含まれますが、その中からRequestIdを取得し、RequestIdとキーワード（ここでは、RECAVERYとしました）が、含まれるログを抽出しています。

抽出されたログを元に、リカバリ処理をイメージしている関数が、recaveryFunction(logs :string[])です。

const zlib = require('zlib');
const KEYWORD = 'RECAVERY';
const cloudwatchlogs = new AWS.CloudWatchLogs();

exports.handler = async (event: any) => {

    if(event && event.awslogs && event.awslogs.data){
        const log = await decode(event.awslogs.data);
        const events = parseEvent(JSON.parse(log));
        await Promise.all(events.map(async (event: Event) => {
            // 当該RequestIdのログからKEYWORDを含むメッセージを取得する
            const logs = await getLog(event, KEYWORD);
            // ここで必要なリカバリ処理を行う
            recaveryFunction(logs);
        }));
    }
    return {};
}

function recaveryFunction(logs :string[]){
    console.log('Recovery Function start.');
    logs.forEach( log =>{
        console.log(`> ${log.split('\t')[3]}`);
    })
    console.log('Recovery Function finish.')
}


async function getLog(event: Event, keyword: string): Promise {
    // logGroup 及び、logStreamのログを抽出
    const params = {
        logGroupName: event.logGroup,
        logStreamName: event.logStream,
    }
    const data = await cloudwatchlogs.getLogEvents(params).promise();
    if(data.events){
        // RequestId及び、KEYWORDを含むメッセージを取得
        return  data.events.filter( e => {
            return (e.message!.indexOf(event.requestId)>0) && (e.message!.indexOf(keyword)>0)
        }).map( event => event.message!)
    }
    return [];
}

type Event = {
    logGroup: string,
    logStream: string,
    requestId: string
};

// ClouWatch Eventのリクエストを分解する 
function parseEvent(json: {logGroup: string, logStream: string, logEvents: any[]}):Event[]  {
    const events: Event[] = [];

    const logGroup = json.logGroup;
    const logStream = json.logStream;
    json.logEvents.forEach((event: any) => {
        const requestId = event.message.split(' ')[1];
        if(requestId){
            events.push({
                logGroup: logGroup,
                logStream: logStream,
                requestId: requestId
            })
        }
    });
    return events;
}

4 試してみる

それでは、キーワードを追加して、エラーとなる側のファンクションをタイムアウト3秒で実行してみます。

const KEYWORD = 'RECAVERY'

exports.handler = async (event) => {
    console.log(`${KEYWORD} function 01 start`);
    apiFunction();
    console.log(`${KEYWORD} function 02 start`);
    apiFunction();
    console.log(`${KEYWORD} function 03 start`);
    apiFunction();
    console.log(`${KEYWORD} function 04 start`);
    apiFunction();
    console.log(`${KEYWORD} function 05 start`);
    apiFunction();

    return {};
};

function apiFunction() {
  const msec = 1000;
  var start = new Date();
  while (new Date() - start < msec);
}

下記が、リカバリ側のLambdaのログです。リカバリ用のメソッドが呼ばれ、対象のLambdaは、API呼び出しが3回始まった後で、終了してしまっている情報が渡されています。

タイムアウト値を4秒に設定した場合は、以下のようになります。

対象となるLambdaでは、リカバリに必要な情報を、キーワードを含んだログで出力しておいて、リカバリ側では、そのログに基づいて必要なリカバリ処理するというイメージです。

5 最後に

今回は、タイムアウトで修了してしまったLambdaのリカバリをするLambdaを作成してみました。

どれぐら実用に耐えるか、ちょっと負荷をかけた環境で、試してみたいと思います。何か、思い違い、アドバイスなど有りましたら、ご指摘ただければ幸いです。