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

2019.11.25

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回、呼び出しています。

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

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

// レスポンスを受けるのに1秒必要な外部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<string[]> {
// 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を作成してみました。

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