SnapStartでリストアされたLambda実行環境はスナップショット取得時と同じMACアドレスを利用する

前回の検証結果がうまく説明つかなかったので、改めて検証し直したところ新たな事実が判明しました

#AWS Lambda

#AWS

#Lambda SnapStart

岩田智哉

2022.12.05

この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。

CX事業本部@大阪の岩田です。

SnapStartでリストアされたLambda実行環境のMACアドレスが再生成されるか検証してみたところ、なんとも不思議な結果になりました。

この結果が気になったので改めて検証してみました。

先に結論を書いておくと、以下の事実が判明しました。

スナップショットを作成するためにLambdaのInit処理を実行するログは欠落するケースがある
SnapStartでリストアされたLambda実行環境はスナップショット取得時と同じMACアドレスを利用する

おさらい

前回の検証を要約すると以下のようなロジックをLambdaに実装して検証を行いました。

a. スナップショット取得直前にLambda実行環境のMACアドレスを/tmp/macaddr.txtに書き出し & ログ出力 b. スナップショットリストア直後に/tmp/macaddr.txtの中身をログ出力、改めてMACアドレスの情報を取得してログ出力 c. handler内でもスナップショットリストア直後と同様の処理を実施

この検証で得られた結果は以下の通りでした。

b,cで出力されたMACアドレスは全てaで出力されたMACアドレスとは異なる
b,cで出力されたログは/tmp/macaddr.txtの中身(スナップショット取得直前に書き出したMACアドレス)と、改めて取得し直したMACアドレスが一致する

2についてはLambda実行環境リストア時にMACアドレスは再生成されない仕様と考えればそれでOKなのですが、1に関しては説明が付きませんでした。スナップショットからリストアする際にMACアドレスを再生成しないのであれば、なぜb,cのログにaのMACアドレスが含まれないのでしょうか？

再検証

前回の検証結果を改めて考察したのですが、Init処理実行のログが残っているLambda実行環境とは別にLambda実行環境のスナップショットが取得されていて、リストア時にはそのスナップショットからLambda実行環境がリストアされているとしたら検証結果の説明がつくと考えました。以下のようなイメージです。

SnapStart用にスナップショットを作成
- Lambda実行環境-1でInit処理を実行し、スナップショットを生成
- この処理はCW Logsにログが残っていない
- Lambda実行環境-2でInit処理を実行....
- この処理はCW Logsにログが残っている
スナップショットからリストアしたLambda実行環境でhandler内の処理を実行
- このLambda実行環境はLambda実行環境-1からリストアされたLambda実行環境

この仮説が正しいとすれば、CW Logsにログが残っていないInit処理がどこかで実行されていたことになります。この可能性を改めて検証してみましょう。

検証用コード

まず以下のLambdaを用意しました

import json

def handler(event, context):
    
    print (event)
    
    return {
        'statusCode': 200,
        'body': json.dumps(event),
    }

受け取ったイベントデータをそのままログに出力しつつ、イベントデータをそのまま返却するだけの処理です。このLambdaをAPI GWのバックエンドとして統合します。

続いてSnapStart検証用Lambdaのコードに以下の処理を追加します。

    private void postRequest(String macAddresses) throws InterruptedException, IOException {

        HttpClient client = HttpClient.newHttpClient();
        HttpRequest req = HttpRequest.newBuilder()
                .uri(URI.create("<ログ出力用API GWのエンドポイント>"))
                .POST(HttpRequest.BodyPublishers.ofString(macAddresses))
                .build();
        client.send(req, HttpResponse.BodyHandlers.ofByteArray());        
        
    }

引数でMACアドレスを受け取った文字列をリクエストボディにセットしてログ出力用API GWにPOSTするだけのシンプルな処理です。この処理をスナップショット取得前、リストア直後、handler内にそれぞれ追加します。前回の検証ではCW Logsに出力されたログを分析していましたが、CW Logsにログが残らないパターンがあることを考慮し、自前でログ出力の機構を追加したイメージです。

最終的なLambdaのコードは以下です。

package helloworld;

import java.io.BufferedWriter;
import java.io.File;
import java.io.FileWriter;
import java.io.IOException;
import java.net.NetworkInterface;
import java.net.SocketException;
import java.net.URI;
import java.net.http.HttpClient;
import java.net.http.HttpRequest;
import java.net.http.HttpResponse;
import java.nio.file.Files;
import java.nio.file.Paths;
import java.util.*;

import com.amazonaws.services.lambda.runtime.Context;
import com.amazonaws.services.lambda.runtime.RequestHandler;
import com.amazonaws.services.lambda.runtime.events.APIGatewayProxyRequestEvent;
import com.amazonaws.services.lambda.runtime.events.APIGatewayProxyResponseEvent;

import org.crac.Core;
import org.crac.Resource;

public class App implements RequestHandler<APIGatewayProxyRequestEvent, APIGatewayProxyResponseEvent>, Resource {

    static final String MAC_ADDR_FILE_PATH = "/tmp/macaddr.txt";

    private static ArrayList<String> getNicInfos() throws SocketException {

        ArrayList<String> nicInfos = new ArrayList<>();
        for (NetworkInterface networkInterface : Collections.list(NetworkInterface.getNetworkInterfaces())) {
            byte[] macAddr = networkInterface.getHardwareAddress();
            nicInfos.add(networkInterface.getName() + ":" + macAddrToStr(macAddr));
        }

        return nicInfos;
    }

    private static String macAddrToStr(byte[] mac) {

        if (mac == null) {
            return "";
        }

        StringBuilder sb = new StringBuilder();
        for (int i = 0; i < mac.length; i++) {
            sb.append(String.format("%02X%s", mac[i], (i < mac.length - 1) ? "-" : ""));
        }
        return sb.toString();
    }

    public App() {
        Core.getGlobalContext().register(this);
    }

    private void postRequest(String macAddresses) throws InterruptedException, IOException {

        HttpClient client = HttpClient.newHttpClient();
        HttpRequest req = HttpRequest.newBuilder()
                .uri(URI.create("<ログ出力用API GWのエンドポイント>"))
                .POST(HttpRequest.BodyPublishers.ofString(macAddresses))
                .build();
        client.send(req, HttpResponse.BodyHandlers.ofByteArray());

    }


    @Override
    public void beforeCheckpoint(org.crac.Context<? extends Resource> context) {
        System.out.println("チェックポイント前のフックポイント");
        try{
            List<String> nicInfos = getNicInfos();
            File file = new File(MAC_ADDR_FILE_PATH);
            try(BufferedWriter bw = new BufferedWriter(new FileWriter(file))) {
                for(String nic : nicInfos){
                    bw.write(nic);
                    bw.newLine();
                }
            }
            //  System.out.println(Files.readString(Paths.get(MAC_ADDR_FILE_PATH)));
            String macAddresses = Files.readString(Paths.get(MAC_ADDR_FILE_PATH));
            this.postRequest(macAddresses);

        } catch (Exception ex){
            System.out.println(ex);
        }
    }

    @Override
    public void afterRestore(org.crac.Context<? extends Resource> context) {
        System.out.println("リストア後のフックポイント");
        System.out.println("ファイルから読み込んだNicの情報");
        try {
            System.out.println(Files.readString(Paths.get(MAC_ADDR_FILE_PATH)));

            List<String> nicInfos = getNicInfos();
            System.out.println("リストア後に再取得したNicの情報");
            nicInfos.forEach(s-> System.out.println(s));

            String macAddresses = Files.readString(Paths.get(MAC_ADDR_FILE_PATH));
            this.postRequest(macAddresses);

        } catch (Exception ex){
            System.out.println(ex);
        }
    }

    public APIGatewayProxyResponseEvent handleRequest(final APIGatewayProxyRequestEvent input, final Context context) {

        APIGatewayProxyResponseEvent response = new APIGatewayProxyResponseEvent();
        System.out.println("handler処理");
        System.out.println("ファイルから読み込んだNicの情報");

        try {
            System.out.println(Files.readString(Paths.get(MAC_ADDR_FILE_PATH)));
            List<String> nicInfos = getNicInfos();
            System.out.println("Handler内で再取得したNicの情報");
            nicInfos.forEach(s-> System.out.println(s));

            String macAddresses = Files.readString(Paths.get(MAC_ADDR_FILE_PATH));
            this.postRequest(macAddresses);

            Thread.sleep(2000);

            return response
                    .withStatusCode(200)
                    .withBody("{}");
        }
        catch (Exception e) {
            System.out.println(e);
            return response
                    .withBody("{}")
                    .withStatusCode(500);
        }
    }
}

スナップショットを作成してみる

コードが準備できたのでデプロイ&新しいバージョンを発行し、スナップショットを作成します。スナップショットの作成完了後、ログ出力用Lambdaのログを分析してみました。

fields @timestamp
| filter not ispresent(@type)
| parse body "*\n*\nlo:" as telemetry, vinternal
| parse telemetry "*:*" as _telemetry, telemetryaMacAddr
| parse vinternal "*:*" as _vinternal1, venvMacAddr
| sort @timestamp

結果は以下の通りで、ログ出力用のLambdaが15回呼び出されていました。

telemetry1_sbのMACアドレス	vinternal_1のMACアドレス
6A-3C-47-07-C1-D8	C6-A7-02-99-C8-1C
E6-6F-DD-67-1B-AB	CE-84-05-32-DF-F1
06-17-16-B5-03-79	EA-76-45-1E-48-B4
3E-15-E8-90-0A-9B	72-62-7A-DB-3E-BB
BE-AF-90-97-6E-85	5E-AB-38-62-3D-E7
96-0C-D6-98-34-C7	26-02-49-49-76-8F
CE-20-DD-8A-E2-35	E2-41-8F-8A-00-1C
46-66-1D-70-89-54	76-84-F7-7E-FA-B1
EA-D4-23-36-3E-86	EE-F4-5B-09-6A-B0
66-6E-07-01-FA-8D	3A-6F-A8-62-5A-F5
CE-7A-8B-FF-8D-81	8A-28-F4-C4-08-B7
0E-33-8B-A4-90-32	22-6E-93-97-DC-02
3E-9E-CE-15-BA-4B	B2-84-0A-08-CB-9E
2E-AB-55-F8-AA-BB	E6-47-53-73-54-78
1A-48-CB-DE-6F-C7	3A-AB-72-B7-23-68

あれ？前回の検証の時はInit処理のログは10件しか出力されていなかったような....？？

せっかくなのでログ出力用API GWへのアクセス元IP = スナップショット作成を実行していたLambda実行環境がインターネットに抜ける際に利用していたIPアドレスも調べておきましょう。

fields requestContext.identity.sourceIp
| filter not ispresent(@type)
| stats count(*) by requestContext.identity.sourceIp
| sort requestContext.identity.sourceIp

結果は以下の通りでアクセス元のIPアドレスはバラバラでした。

requestContext.identity.sourceIp	count(*)
3.88.200.76	1
3.231.163.163	1
3.236.217.44	1
3.238.254.248	1
23.20.98.251	1
34.227.76.104	1
35.175.149.115	1
35.175.249.234	1
44.197.231.190	1
44.201.32.102	1
44.211.77.223	1
52.202.73.135	1
54.158.37.200	1
54.197.174.35	1
54.236.32.197	1

今回検証用のLambdaはバージニアリージョンにデプロイしていたのですが、アクセス元のIPはバージニアリージョンのEC2が使うIPアドレス帯になっていそうです。LambdaはEC2上で動いているので、これは妥当な結果でしょう。

続いてSnapStartを設定したLambdaの方でも改めてCW Logsに出力されたログを確認してみましょう。以下がログの全文です。

INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
INIT_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
INIT_REPORT Init Duration: 4728.76 ms
INIT_REPORT Init Duration: 4666.12 ms
INIT_REPORT Init Duration: 4532.07 ms
INIT_REPORT Init Duration: 4506.06 ms
INIT_REPORT Init Duration: 4544.22 ms
INIT_REPORT Init Duration: 4510.54 ms
INIT_REPORT Init Duration: 4698.84 ms
INIT_REPORT Init Duration: 4694.31 ms
INIT_REPORT Init Duration: 4769.99 ms
INIT_REPORT Init Duration: 4979.66 ms

このログを分析すると

INIT_STARTのログは12行出力
チェックポイント前のフックポイントのログは11行出力
INIT_REPORTのログは10行出力

という結果でした。ログ出力用のLambdaに出力されたログの件数15件よりも少ないですし、ログの内容別の件数が一致しないのもおかしいです。このことから。どうもCW Logsに出力されたログが欠落していると考えて良さそうです。

スナップショットからLambdaを実行してみる

スナップショットの準備ができたのでLambdaを実行してみましょう。

出力されたログは以下の通りでした。

RESTORE_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
リストア後のフックポイント
ファイルから読み込んだNicの情報
telemetry1_sb:2E-AB-55-F8-AA-BB
vinternal_1:E6-47-53-73-54-78
lo:
リストア後に再取得したNicの情報
telemetry1_sb:2E-AB-55-F8-AA-BB
vinternal_1:E6-47-53-73-54-78
lo:
RESTORE_REPORT Restore Duration: 1403.72 ms
START RequestId: 76eb0396-0cae-4dc5-9854-62d7edc7324f Version: 13
handler処理
ファイルから読み込んだNicの情報
telemetry1_sb:2E-AB-55-F8-AA-BB
vinternal_1:E6-47-53-73-54-78
lo:
Handler内で再取得したNicの情報
telemetry1_sb:2E-AB-55-F8-AA-BB
vinternal_1:E6-47-53-73-54-78
lo:
END RequestId: 76eb0396-0cae-4dc5-9854-62d7edc7324f
REPORT RequestId: 76eb0396-0cae-4dc5-9854-62d7edc7324f	Duration: 2567.56 ms	Billed Duration: 3870 ms	Memory Size: 1024 MB	Max Memory Used: 123 MB	Restore Duration: 1403.72 ms

いずれのログについてもインターフェース名とMACアドレスは以下のようになりました

telemetry1_sb: 2E-AB-55-F8-AA-BB
vinternal_1: E6-47-53-73-54-78

このMACアドレスのペアをログ出力用Lambdaのログから検索すると...見事にヒットしました！

前回の検証でLambda実行時に出力されたMACアドレスがInit処理実行時のログに存在しなかったのは、Init処理実行時のログが欠落していたことが原因と考えられそうです。

まとめ

これまでの検証結果をまとめると以下の結論に落ち着きました。

スナップショットを作成するためにLambdaのInit処理を実行するログは欠落するケースがある
SnapStartでリストアされたLambda実行環境はスナップショット取得時と同じMACアドレスを利用する

スナップショットからリストア時する際にMACアドレスが再生成されないので、同一のスナップショットから起動したLambda実行環境は全て同じMACアドレスを利用すると考えられます。実際前回の検証結果でも複数のLambda実行環境を並列起動させた際に、複数のLambda実行環境が同じMACアドレスを利用していることを確認しています。

Lambdaの処理内でUUIDv1などを使う場合は注意が必要ですね。