SnapStartでリストアされたLambda実行環境のMACアドレスが再生成されるか確認したら不思議な結果になった話

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

LambdaのSnapStart機能を使う際にはRuntime hookと呼ばれるフックポイントを利用することで、スナップショットの取得前やリストア時に任意の処理を追加で実行できます。このフックポイントを利用し、スナップショット取得前のLambda実行環境のMACアドレスとスナップショットからリストアした後のLambda実行環境のMACアドレスが別のものになっていることを確認しようとしたところ...

なんとも不思議な結果になりました。

Runtime hookの実装方法

まずRuntime hookの実装方法について簡単に解説しておきます。

まずRuntime hookの実装にはorg.cracパッケージを利用します。Lambdaの依存関係にこのパッケージを含めるようにして下さい。mavenで管理している場合は以下のようになります。

...略
<dependencies>
        <dependency>
            <groupId>com.amazonaws</groupId>
            <artifactId>aws-lambda-java-core</artifactId>
            <version>1.2.1</version>
        </dependency>
        <dependency>
          <groupId>com.amazonaws</groupId>
          <artifactId>aws-lambda-java-events</artifactId>
          <version>3.11.0</version>
        </dependency>
        <dependency>
            <groupId>io.github.crac</groupId>
            <artifactId>org-crac</artifactId>
            <version>0.1.3</version>
        </dependency>
...略

Javaのコードの方ではorg.crac.Resourceインターフェースを実装したクラスでbeforeCheckpointとafterRestoreをオーバーライドしつつ、ランタイムが管理するContextにこのクラスを登録するというのがざっくりの流れになります。公式ドキュメントに記載されている以下のコードを見ていただくとイメージがつきやすいと思います。

...
  import org.crac.Resource;
  import org.crac.Core;
  ... 
public class CRaCDemo implements RequestStreamHandler, Resource {
    public CRaCDemo() {
      Core.getGlobalContext().register(this);
    }
    public String handleRequest(String name, Context context) throws IOException {
      System.out.println("Handler execution");
      return "Hello " + name;
    }
    @Override
    public void beforeCheckpoint(org.crac.Context<? extends Resource> context)
        throws Exception {
      System.out.println("Before checkpoint");
    }
    @Override
    public void afterRestore(org.crac.Context<? extends Resource> context)
        throws Exception {
      System.out.println("After restore");

今回はこのRuntime hookのbeforeCheckpointを使い、スナップショット取得前の時点におけるLambda実行環境のMACアドレスを/tmp/ディレクトリ配下のテキストファイルに書き出しておき、スナップショットリストア後に改めてLambda実行環境のMACアドレスを取得、先程作成したテキストファイルの情報と一致するかを確かめてみます。

Lambdaの実装

ではさっそくLambdaを実装していきましょう。コード全体は以下の様になりました。

※ちょっとした検証目的なので例外制御などが適当なのはご了承下さい。

package helloworld;

import java.io.BufferedWriter;
import java.io.File;
import java.io.FileWriter;
import java.net.NetworkInterface;
import java.net.SocketException;
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);
    }

    @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)));
        } 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));

        } 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));

            Thread.sleep(2000);

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

ポイントをいくつか解説します。まずスナップショット取得前に実行されるbeforeCheckpointの処理です。

ここで/tmp/macaddr.txtというファイルにLambda実行環境のMACアドレスを書き出した後、ファイルに書き出した内容をそのままログに出力しています。

    @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)));
        } catch (Exception ex){
            System.out.println(ex);
        }
    }

続いてafterRestoreです。スナップショット取得前に書き出された/tmp/macaddr.txtというファイルの内容をログに出力した後、改めてLambda実行環境のMACアドレスを取得してログに出力します。スナップショットから起動したLambda実行環境のMACアドレスはスナップショット取得前から変わっているだろうと予想しての実装です。

    @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));

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

一応handlerにもafterRestoreと同等のMACアドレス比較処理を実装しておきます。

    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));

            Thread.sleep(2000);

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

やってみる

コードの準備ができたので実際に試していきましょう。

Lambdaのデプロイとバージョン発行

まずLambdaのデプロイとバージョン発行を行います。SnapStartが有効なLambdaの新しいバージョンを発行すると、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
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
telemetry1_sb:D2-B7-A5-18-A6-08
vinternal_1:1A-A7-38-DD-C9-B3
lo:
telemetry1_sb:56-CF-FB-ED-4E-64
vinternal_1:62-91-75-B8-FF-28
lo:
チェックポイント前のフックポイント
チェックポイント前のフックポイント
チェックポイント前のフックポイント
INIT_REPORT Init Duration: 841.67 ms
...略

お？LambdaのInit処理実行が1回だけ実行されてスナップショットを生成するものとばかり思っていましたが、どうも複数回(ログを集計して調べたところ10回)実行されるようです。AZごとに実行するにしても10回は多すぎますし、裏側はどうなってるんでしょうね？

バージョン発行完了後にログを集計した結果は以下のようになりました。※ループバックアドレスの情報は不要なので除外しています。

Init処理が10回も起動するのは予想外でしたが、MACアドレスは10(Init実行回数) × 2(ループバックアドレスアドレスを除くインターフェース数)で20種類のMACアドレスの情報が出力されました。これらのMACアドレスはこれから起動するLambda実行環境のいわば「祖先」が使用していたMACアドレスということになります。この祖先(スナップショット)から派生して起動したLambda実行環境のMACアドレスはどうなるのか？というのがこの検証の趣旨です。

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

準備ができたので、先程発行したLambdaのバージョンをテスト実行してログを確認してみましょう。ログは以下のようになりました。

RESTORE_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
リストア後のフックポイント
ファイルから読み込んだNicの情報
telemetry1_sb:52-CF-5C-CF-D5-46
vinternal_1:4E-E3-B5-37-A8-D6
lo:
リストア後に再取得したNicの情報
telemetry1_sb:52-CF-5C-CF-D5-46
vinternal_1:4E-E3-B5-37-A8-D6
lo:
RESTORE_REPORT Restore Duration: 326.41 ms
START RequestId: 19d678c9-04da-4443-a5a6-347dc839c85f Version: 12
handler処理
ファイルから読み込んだNicの情報
telemetry1_sb:52-CF-5C-CF-D5-46
vinternal_1:4E-E3-B5-37-A8-D6
lo:
Handler内で再取得したNicの情報
telemetry1_sb:52-CF-5C-CF-D5-46
vinternal_1:4E-E3-B5-37-A8-D6
lo:
END RequestId: 19d678c9-04da-4443-a5a6-347dc839c85f
REPORT RequestId: 19d678c9-04da-4443-a5a6-347dc839c85f	Duration: 2050.47 ms	Billed Duration: 2282 ms	Memory Size: 1024 MB	Max Memory Used: 82 MB	Restore Duration: 326.41 ms

結果をまとめると以下のようになります。

telemetry1_sb、vinternal_1ともにファイルから読み込んだMACアドレス...つまり祖先となるLambda実行環境のMACアドレスと、スナップショットから復元されたLambda実行環境から取得したMACアドレスが同一になりました。

これだけならスナップショットから復元されたLambda実行環境はスナップショット取得時点のLambda実行環境と同じMACアドレスを使い続けると結論づけてしまうのですが、よく見るとこの52-CF-5C-CF-D5-46というMACアドレスと4E-E3-B5-37-A8-D6というMACアドレスは両方ともLambdaのバージョン発行時に出力されたログの中には存在しないMACアドレスなのです。

ん？？？ということはスナップショット取得前に書き出していたファイル/tmp/macaddr.txtの中身がスナップショット復元時に書き換えられたということでしょうか？？とでも考えないとこの検証結果の説明が付かないですよね？とはいったものの、仮にLambda実行環境の方で/tmp/macaddr.txtの中身を書き換えているとした場合、どうやって書き換え対象のファイルを追跡しているんだ？という疑問が残ります。Lambda実行環境のシステムコールを監視すれば、そういったことも可能なのかな？と思ったりしましたが、/tmp/macaddr.txtに書き込んだ内容がMACアドレスで、どういう値に書き換えるべきかという判定はさすがに不可能なように思います。いったいこれはどういうことでしょう？？本当に謎です。

ちなみにこの検証用のLambdaですが、最初はテキストファイルを使わずstatic変数でMACアドレスの情報を保存/読み込みしていました。その実装の時もスナップショット取得前にstatic変数に保存したMACアドレスの情報とスナップショットからリストア後にLambda実行環境から取得したMACアドレスは一致しており、かつこのMACアドレスはInit処理実行時のログには出力されていないMACアドレスでした。

うーん。謎ですね。

さらに時間を開けてスナップショットからLambdaを実行してみる

先程起動したLambda実行環境が破棄されるまで十分な時間を空けてから再度Lambdaを実行してみました。

RESTORE_START Runtime Version: java:11.v15	Runtime Version ARN: arn:aws:lambda:us-east-1::runtime:0a25e3e7a1cc9ce404bc435eeb2ad358d8fa64338e618d0c224fe509403583ca
リストア後のフックポイント
ファイルから読み込んだNicの情報
telemetry1_sb:52-CF-5C-CF-D5-46
vinternal_1:4E-E3-B5-37-A8-D6
lo:
リストア後に再取得したNicの情報
telemetry1_sb:52-CF-5C-CF-D5-46
vinternal_1:4E-E3-B5-37-A8-D6
lo:
RESTORE_REPORT Restore Duration: 132.29 ms
START RequestId: 9f9c2725-e5c1-47b0-b11f-c7b8e28b231d Version: 12
handler処理
ファイルから読み込んだNicの情報
telemetry1_sb:52-CF-5C-CF-D5-46
vinternal_1:4E-E3-B5-37-A8-D6
lo:
Handler内で再取得したNicの情報
telemetry1_sb:52-CF-5C-CF-D5-46
vinternal_1:4E-E3-B5-37-A8-D6
lo:
END RequestId: 9f9c2725-e5c1-47b0-b11f-c7b8e28b231d
REPORT RequestId: 9f9c2725-e5c1-47b0-b11f-c7b8e28b231d	Duration: 2025.87 ms	Billed Duration: 2074 ms	Memory Size: 1024 MB	Max Memory Used: 82 MB	Restore Duration: 132.29 ms

フックポイントのログが出力されており、REOPRTにRestore Durationという表示があることからもコールドスタートが発生し、Lambda実行環境がスナップショットから復元されたことが分かります。ログに出力されたMACアドレスは先程のLambda初回実行時と同一のMACアドレスでした。

この実行結果から考えると、スナップショットリストア時にMACアドレスの再生成のような処理は実行されず、あくまでスナップショット取得時点のMACアドレスを使い回すということでしょうか？

ただし、依然としてInit処理のログに出力されたMACアドレスが利用されていないことの説明が付きません。うーんん。謎だ。。。

Lambdaを並列実行して複数の実行環境をコールドスタートさせてみる

ここまでの検証はLambdaを1回づつテスト実行してログを確認するという手順を踏んでいました。今度はLambdaを並列実行して複数のLambda実行環境を生成、これらのLambda実行環境が利用するMACアドレスがどうなるかを確認してみましょう。LambdaをAPI GWのバックに紐付けた後、以下のコマンドを実行しAPI GWのエンドポイントに30並列でアクセスします。

ab -c 30 -n 30  https://APIGWのエンドポイント

これで大体コールドスタートが30回発生...つまりスナップショットからリストアされたLambda実行環境が30個ほど生成されるのが期待値です。

CW Logs InsightsからLambdaのログを確認してみましょう

fields @timestamp, @message
| filter (@message  like /RESTORE_REPORT/ )
| stats count(*)

スナップショットからのリストア(コールドスタート)は29回発生していました。ほぼ期待通りの結果です。

続いてログに出力されたMACアドレスの情報を集計してみます。

fields @timestamp, @message
| filter (@message  like /telemetry1_sb/ or @message like /vinternal_1/)
| parse @message "*:*" as nicName, macAddr
| stats count(*) by nicName, macAddr
| sort nicName, macAddr

結果は以下のようになりました。

Lambdaのロジック的にコールドスタート時はMACアドレスの情報が8回、ウォームスタート時には4回ログに出力されるので先程のコールドスタート29回という結果から計算すると 29 * 8 + 4 = 236で集計結果の合計236件と一致していますね。MACアドレスは10種類出力されているので、これをLambda実行環境のNIC数2で割ると5となります。今回の検証結果では5パターンのMACアドレスを利用していると考えられますが、作成されたLambda実行環境の数はコールドスタートの回数である29となり、複数のLambda実行環境で同一のMACアドレスを利用していることが分かります。

さらにこの出力されたMACアドレスですが、いずれのMACアドレスもInit処理実行時のログには存在しないMACアドレスとなります。一体なぜ...

Init処理実行時に利用していたMACアドレスは一体どこに行ったんだ...

まとめ

この現象についてなにか思い当たる点がある方いれば是非教えて下さい。

参考

• Runtime hooks for Lambda SnapStart