【Greengrass V2】Lambda コンポーネントのプロセスが異常終了した時の動作を確認してみた

【Greengrass V2】Lambda コンポーネントのプロセスが異常終了した時の動作を確認してみた

Greengrass V2 の Lambda コンポーネントの異常発生時の動作を検証してみました。
#Greengrass V2
#AWS IoT Greengrass
#AWS IoT
#AWS
市田善久

市田善久

facebook logohatena logotwitter logo
Clock Icon2021.08.25

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

はじめに

以前の記事でセンサーデータを取得する Lambda コンポーネントを作成しました。もしこれを本番環境で動かす場合「Lambda コンポーネントが途中でエラーになったらどうなるの？」という疑問が起こりました。

ということで、今回は Lambda コンポーネントの異常発生時の動作について確認してみました。

想定する環境は下記の通りです。これまで試した内容と変わらず Modbus-RTU 対応の温湿度トランスミッターから温湿度データを取得します。

10-dialog-healthy

この構成に対して、Lambda コンポーネントのプロセスを手動で( kill コマンドで)強制停止して、コンポーネントの動作を観察してみることにしました。

11-kill-Lambda

Lambda ソースコード

検証対象の Lambda コンポーネントのコードは下記になります。以前の記事のように Lambda コンポーネントの環境変数にセンサーデータの出力先を指定したものになります。

from pymodbus.client.sync import ModbusSerialClient as ModbusClient
import datetime
import time
import os

def run_sync_client():
    client = ModbusClient(baudrate=9600, port="/dev/ttyUSB0", method="rtu")
    client.connect()
    FilePath = os.environ["FilePath"] # Lambda の環境変数からデータ出力ファイルのパスを取得
    rr = client.read_input_registers(address=1, count=2, unit=0x1)
    temperature = rr.registers[0]/10
    humidity  = rr.registers[1]/10

    # Append the message to the log file.
    with open(FilePath, 'a') as f:
        print(f"{str(datetime.datetime.now())}\tTemperatur:\t{temperature} ℃", file=f)
        print(f"{str(datetime.datetime.now())}\tHumidity:\t{humidity} %", file=f)

    client.close()

while True:
    run_sync_client()
    time.sleep(10)


def lambda_handler(event, context):
    return

この Lambda は 「存続期間の長い Lambda （Long-Lived Lambda）」としてデプロイされているものとします。

プロセスを落としてみる

事前にこのコンポーネントのプロセス ID (PID) を psコマンドで確認しておきます。

ggc_user  3982  0.0  0.3  29952 14604 ?        Sl   13:36   0:02 /usr/bin/python3.7 -u /greengrass/v2/work/modbus-sensor-lambda-component--HelloWorldFunction/work/worker/0/runtime/python/lambda_runtime.py --handler=app.lambda_handler

プロセス ID が分かったので、早速そのプロセスを落とします。

$ sudo kill 3982

下記はセンサーデータの出力先(/tmp/Greengrass_modbus_sensor_lambda.log)の内容です。下記の通り「14:41:04 〜14:42:12」の間の「1分8秒」程度の間データ取得できていませんが自動的に復旧していることが分かります。

2021-08-25 14:41:04.800778	Temperatur:	28.2 ℃
2021-08-25 14:41:04.800875	Humidity:	51.7 %
2021-08-25 14:42:12.730125	Temperatur:	28.2 ℃
2021-08-25 14:42:12.730184	Humidity:	50.6 %

プロセスを確認しても先程と同様のプロセスが起動していることが分かりました。

ログから詳細を確認する

Lambda コンポーネントに何か問題があった時、自動で復旧することが分かりました。それでは詳細を更に確認していきましょう。

コンポーネントのログを確認する

まずはコンポーネントのログを確認します。/greengrass/v2/logディレクトリに各コンポーネント単位でログが出力されています。

下記はプロセスを止めた直後のコンポーネントのログですが、SIGTERMという終了シグナルを受け取っていることが分かります。（見やすくするため一部省略しています）

2021-08-25T05:41:14.374Z [INFO] modbus-sensor-lambda-component: lambda_runtime.py:370,Caught signal 15. Stopping runtime.. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=RUNNING}

しばらくすると次のようなログが出力されています。各ログのタイムスタンプはデータ出力が止まっていた時間帯と整合しています。(Greengrass のログ時間は UTC で出力されています）

2021-08-25T05:42:11.844Z [INFO] modbus-sensor-lambda-component: shell-runner-start. {scriptName=services.modbus-sensor-lambda-component--HelloWorldFunction.lifecycle.shutdown.script, serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=STOPPING
2021-08-25T05:42:12.297Z [INFO] modbus-sensor-lambda-component: shell-runner-start. {scriptName=services.modbus-sensor-lambda-component.lifecycle.startup.script, serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=STARTING
2021-08-25T05:42:12.402Z [INFO] modbus-sensor-lambda-component: stdout. Started process: 6128. {scriptName=services.modbus-sensor-lambda-component.lifecycle.startup.script, serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=STARTING}
2021-08-25T05:42:12.407Z [INFO] modbus-sensor-lambda-component: Startup script exited. {exitCode=0, serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=STARTING}
2021-08-25T05:42:12.650Z [INFO] modbus-sensor-lambda-component: lambda_runtime.py:402,Status thread started. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=RUNNING}

このログを見ると下記のようにコンポーネントのステータスが遷移している事がわかります。

STOPPING
 ↓
STARTING
 ↓
RUNNING

それぞれのステータスは下記ドキュメントにある「コンポーネントのライフサイクル」にあるステータスになります。

Greengrassのログを確認する

次に別のログである/greengrass/v2/log/greengrass.logを見てみます。
Lambda マネージャー というコンポーネントのエラーが記録されています。内容としては「プロセスを止めたので該当するコンポーネントのステータス情報がタイムアウトで取得できない」というエラーのようです。
（見やすくするため一部省略しています）

2021-08-25T05:42:11.802Z [ERROR] com.aws.greengrass.lambdamanager.UserLambdaService: service-errored. {serviceName=modbus-sensor-lambda-component, currentState=RUNNING}
com.aws.greengrass.lambdamanager.StatusTimeoutException: Lambda status not received within timeout
        at com.aws.greengrass.lambdamanager.Lambda.lambda$createInstanceKeepAliveTask$5(Lambda.java:266)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
        at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)

さらに次のようなログも出力されていました。（見やすくするため一部省略しています）

2021-08-25T05:42:11.813Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component,  currentState=RUNNING, newState=ERRORED}
2021-08-25T05:42:11.815Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-set-state. {serviceName=modbus-sensor-lambda-component, currentState=RUNNING, newState=ERRORED}
2021-08-25T05:42:11.822Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=ERRORED, newState=STOPPING}
2021-08-25T05:42:11.823Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-set-state. {serviceName=modbus-sensor-lambda-component, currentState=ERRORED, newState=STOPPING}
2021-08-25T05:42:12.245Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=STOPPING, newState=INSTALLED}
2021-08-25T05:42:12.247Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceName=modbus-sensor-lambda-component, currentState=INSTALLED, newState=STARTING}
2021-08-25T05:42:12.247Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-set-state. {serviceName=modbus-sensor-lambda-component, currentState=INSTALLED, newState=STARTING}
2021-08-25T05:42:12.407Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=STARTING, newState=RUNNING}
2021-08-25T05:42:12.408Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-set-state. {serviceName=modbus-sensor-lambda-component, currentState=STARTING, newState=RUNNING}

こちらのログでは更に詳細な情報として、Lambda マネージャーが「停止した Lambda コンポーネントのステータス」を下記の通り遷移させていることが分かります。

RUNNING
 ↓
ERRORED
 ↓
STOPPING
 ↓
INSTALLED
 ↓
STARTING
 ↓
RUNNING

プロセス停止を繰り返してみる

続けてもう一度プロセスを停止してみたところ、先程と同様に自動的に復旧しました。ログの内容は先程と同様でした。

さらにもう一度止めて計3回プロセスを停止してみました。すると３回目は「Lambda コンポーネントのログ」に下記のメッセージが出力されて自動復旧は行われませんでした。ステータスがBROKENに変わったことが分かります。

2021-08-25T06:35:00.745Z [INFO] modbus-sensor-lambda-component: shell-runner-start. {scriptName=services.modbus-sensor-lambda-component.lifecycle.shutdown.script, serviceName=modbus-sensor-lambda-component, currentState=BROKEN

greengrass.logの方も同様にBROKENのログが発生していました。

2021-08-25T06:35:00.711Z [ERROR] com.aws.greengrass.lambdamanager.UserLambdaService: service-errored. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=RUNNING}
com.aws.greengrass.lambdamanager.StatusTimeoutException: Lambda status not received within timeout
	at com.aws.greengrass.lambdamanager.Lambda.lambda$createInstanceKeepAliveTask$5(Lambda.java:266)
	at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
	at java.base/java.util.concurrent.FutureTask.runAndReset(FutureTask.java:305)
	at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
2021-08-25T06:35:00.712Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-report-state. {serviceInstance=0, serviceName=modbus-sensor-lambda-component, currentState=RUNNING, newState=ERRORED}
2021-08-25T06:35:00.714Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: service-set-state. {serviceName=modbus-sensor-lambda-component, currentState=RUNNING, newState=BROKEN}
2021-08-25T06:35:00.743Z [INFO] com.aws.greengrass.lambdamanager.UserLambdaService: Shutdown initiated. {serviceName=modbus-sensor-lambda-component, currentState=BROKEN}

上記のログからはステータスが下記のように遷移していることが分かります。

RUNNING
 ↓
ERRORED
 ↓
BROKEN

BROKEN 状態からの復旧方法

BROKENになったコンポーネントは再度デプロイしないと復旧しないので、同じバージョンでデプロイし直して復旧させます。
（コードに問題がある場合は、コードを修正した新バージョンで更新します）

なお、今回は単にプロセスを停止しただけなので、デバイス（Raspberry Pi）自体を再起動するだけでも復旧しましたが、デバイスを再起動せずコンポーネントの再起動（greengrass-cli component restartコマンド）だけでは復旧しませんでした。（復旧には再デプロイが必要な為です）

Lambda コンポーネント自動復旧の流れ

先程のドキュメントの記載を参考にすると、エラー発生時の挙動は下記のようになります。

  • ステータスがERRORED になるとリカバリスクリプトが実行されてコンポーネントが再起動する
  • ステータスがERROREDに3回変わるとコンポーネントのステータスがBROKENになる
  • ステータスがBROKENになるとコンポーネントを再度デプロイして復旧させる

上記にある「リカバリスクリプト」とはコンポーネントのレシピで指定するもので、エラー発生時（ERROREDになった時）に実行したい処理を記載します。

Lambda コンポーネントの場合、レシピに独自のライフサイクル処理は追加できないので上記にある「リカバリスクリプト」を定義することができません。また、デプロイ済みの Lambda コンポーネントのレシピを見てもリカバリスクリプトの記載は無く、Lambda コンポーネントのエラー発生時の復旧処理の詳細は把握できませんでした。
下記は対象の Lambda コンポーネントのレシピの内容です。リカバリスクリプトの記載が無いことが分かります。

{
  "RecipeFormatVersion": "2020-01-25",
  "ComponentName": "modbus-sensor-lambda-component",
  "ComponentVersion": "1.0.3",
  "ComponentType": "aws.greengrass.lambda",
  "ComponentDescription": "",
  "ComponentPublisher": "AWS Lambda",
  "ComponentSource": "arn:aws:lambda:ap-northeast-1:xxxxxxxxxxxx:function:modbus-sensor-lambda-component:5",
  "ComponentConfiguration": {
    "DefaultConfiguration": {
      "lambdaExecutionParameters": {
        "EnvironmentVariables": {}
      },
      "containerParams": {
        "memorySize": 16000,
        "mountROSysfs": false,
        "volumes": {},
        "devices": {}
      },
      "containerMode": "NoContainer",
      "timeoutInSeconds": 3,
      "maxInstancesCount": 100,
      "inputPayloadEncodingType": "json",
      "maxQueueSize": 1000,
      "pinned": true,
      "maxIdleTimeInSeconds": 60,
      "statusTimeoutInSeconds": 60,
      "pubsubTopics": {}
    }
  },
  "ComponentDependencies": {
    "aws.greengrass.LambdaLauncher": {
      "VersionRequirement": ">=2.0.0 <3.0.0",
      "DependencyType": "HARD"
    },
    "aws.greengrass.TokenExchangeService": {
      "VersionRequirement": ">=2.0.0 <3.0.0",
      "DependencyType": "HARD"
    },
    "aws.greengrass.LambdaRuntimes": {
      "VersionRequirement": ">=2.0.0 <3.0.0",
      "DependencyType": "SOFT"
    }
  },
  "Manifests": [
    {
      "Platform": {},
      "Lifecycle": {},
      "Artifacts": [
        {
          "Uri": "greengrass:lambda-artifact.zip",
          "Digest": "xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx",
          "Algorithm": "SHA-256",
          "Unarchive": "ZIP",
          "Permission": {
            "Read": "OWNER",
            "Execute": "NONE"
          }
        }
      ]
    }
  ],
  "Lifecycle": {
    "startup": {
      "requiresPrivilege": true,
      "script": "{aws.greengrass.LambdaLauncher:artifacts:path}/lambda-launcher start"
    },
    "setenv": {
      "AWS_GREENGRASS_LAMBDA_CONTAINER_MODE": "{configuration:/containerMode}",
      "AWS_GREENGRASS_LAMBDA_ARN": "arn:aws:lambda:ap-northeast-1:xxxxxxxxxxxx:function:modbus-sensor-lambda-component:5",
      "AWS_GREENGRASS_LAMBDA_FUNCTION_HANDLER": "app.lambda_handler",
      "AWS_GREENGRASS_LAMBDA_ARTIFACT_PATH": "{artifacts:decompressedPath}/lambda-artifact",
      "AWS_GREENGRASS_LAMBDA_CONTAINER_PARAMS": "{configuration:/containerParams}",
      "AWS_GREENGRASS_LAMBDA_STATUS_TIMEOUT_SECONDS": "{configuration:/statusTimeoutInSeconds}",
      "AWS_GREENGRASS_LAMBDA_ENCODING_TYPE": "{configuration:/inputPayloadEncodingType}",
      "AWS_GREENGRASS_LAMBDA_PARAMS": "{configuration:/lambdaExecutionParameters}",
      "AWS_GREENGRASS_LAMBDA_RUNTIME_PATH": "{aws.greengrass.LambdaRuntimes:artifacts:decompressedPath}/runtime/",
      "AWS_GREENGRASS_LAMBDA_EXEC_ARGS": "[\"python3.7\",\"-u\",\"/runtime/python/lambda_runtime.py\",\"--handler=app.lambda_handler\"]",
      "AWS_GREENGRASS_LAMBDA_RUNTIME": "python3.7"
    },
    "shutdown": {
      "requiresPrivilege": true,
      "script": "{aws.greengrass.LambdaLauncher:artifacts:path}/lambda-launcher stop; {aws.greengrass.LambdaLauncher:artifacts:path}/lambda-launcher clean"
    }
  }
}

レシピには書かれていませんが、先に見たように各種ログの内容から Lambda 関連のマネージドコンポーネント（ラムダマネージャコンポーネント等）によるリカバリ処理が実行されているのでは？ と考えられます。

また、これまで確認したログの内容と全体の流れを図にしてみると Lambda コンポーネントのステータスが3回ERROREDに変化したタイミングでBROKENになっていたことが分かります。リカバリスクリプトの実態までは確認できませんでしたが、Lambda コンポーネントにおいても「コンポーネントのライフサイクル」通りの動作であることが分かりました。
（図中のBROKEN横の数字は何回目なのかを記載したものです）

00-lambda-component-status

リカバリ処理に関する補足

Lambda コンポーネントを実行する場合、依存関係で下記のコンポーネントもデプロイされます。

  • ラムダランチャーコンポーネント
  • ラムダマネージャコンポーネント
  • ラムダランタイムコンポーネント

greengrass.logを見る限りでは、ラムダマネージャコンポーネントがリカバリ処理を実行しているように見受けられましたが、ドキュメント上では記載を見つけられませんでした。 また、Greengrass V2 では一部が OSS としてコードが公開されていますが、Lambda 関連のコンポーネントはいずれも非公開だったので、ソースコードからリカバリ処理の詳細を確認することもできなかったので、上記はログからの推測になります。

また、独自のライフサイクルとしてリカバリスクリプトの追加を試してみました。実際に下記の設定をマージ更新として追加してみましたが、コンポーネントのプロセスを止めてもリカバリ処理は実行されませんでした。
（ログにも該当しそうなものは出力されず、無効な設定として処理されているようです。もし可能であればご指摘ください。）

{
    "Manifests": [
        {
            "Lifecycle": {
                "Recover": {
                    "requiresPrivilege": true,
                    "Script": "echo RecoverTest > /tmp/recover.txt"
                }
            }
        }
     ]
}

自動復旧するまでの時間

以上のとおり、Lambda コンポーネントは２回目までは自動で復旧しますが、復旧するまでの時間はバラツキがありました。
早い場合は数十秒で復旧しましたが、遅い場合は2分ほどかかる場合もありました。このあたりは何に起因するものなのかは判明できませんでした。（確認不足かもしれないので引き続き調査したいと思います）

ステータスの取得

ログの他に各コンポーネントのステータスは ListInstalledComponentsというAPI で取得することが可能です。

AWS CLI の場合は下記の様に、ステータスを取得したい対象の Greengrass Core デバイスの Thing 名を指定します。

% aws greengrassv2 list-installed-components \
  --core-device-thing-name <YourGreengrassCoreDeviceName>
{
    "installedComponents": [
        {
            "componentName": "modbus-sensor-lambda-component",
            "componentVersion": "1.0.3",
            "lifecycleState": "RUNNING",
            "isRoot": true
        },
        {
            "componentName": "aws.greengrass.Cli",
            "componentVersion": "2.4.0",
            "lifecycleState": "RUNNING",
            "isRoot": true
        }
    ]
}

コンソールの表示は下記の様になります。これはコンポーネントがBROKENの状態の表示になります。

01-component-status-broken

ステータス表示にマウスのポインタを置くと簡単な説明が表示されます。

02-console-message-thing-status

コンポーネントの場合は修正方法も表示されて助かりますね。

03-console-message-component-status

最後に

今回は Lambda コンポーネントの異常終了時の動作を確認してみました。
カスタムコンポーネントによるリカバリスクリプトや異常発生の検知方法など確認したいことも出てきたので、改めて検証してご紹介できればと思います。

以上です。

Share this article

facebook logohatena logotwitter logo

関連記事

SiteWise Edge ゲートウェイのデータ処理パックのアップデートと失敗時の対処方法

SiteWise Edge ゲートウェイのデータ処理パックのアップデートと失敗時の対処方法

User avatar
市田善久
2024.06.06
AWS IoT Greengrass V2 の使い方の基本 〜 Greengrass のインストールからコンポーネントのデプロイまで

AWS IoT Greengrass V2 の使い方の基本 〜 Greengrass のインストールからコンポーネントのデプロイまで

User avatar
市田善久
2023.12.20
DevelopersIO 2023 大阪にて「AWS IoT Greengrass V2で始めるデバイスアプリケーションの継続的開発」というタイトルで発表しました #devio2023

DevelopersIO 2023 大阪にて「AWS IoT Greengrass V2で始めるデバイスアプリケーションの継続的開発」というタイトルで発表しました #devio2023

User avatar
市田善久
2023.07.19
[AWS IoT Greengrass] awslabsで提供されている「AWS Greengrass Labs Certificate Rotator」を使用して証明書のローテーションを試してみました

[AWS IoT Greengrass] awslabsで提供されている「AWS Greengrass Labs Certificate Rotator」を使用して証明書のローテーションを試してみました

User avatar
SIN
2023.07.03
Classmethod's white logo
Facebook's logo
X's logo
YouTube's logo

© Classmethod, Inc. All rights reserved.