この記事は公開されてから1年以上経過しています。情報が古い可能性がありますので、ご注意ください。
はじめに
以前の記事でセンサーデータを取得する Lambda コンポーネントを作成しました。もしこれを本番環境で動かす場合「Lambda コンポーネントが途中でエラーになったらどうなるの?」という疑問が起こりました。
ということで、今回は Lambda コンポーネントの異常発生時の動作について確認してみました。
想定する環境は下記の通りです。これまで試した内容と変わらず Modbus-RTU 対応の温湿度トランスミッターから温湿度データを取得します。
この構成に対して、Lambda コンポーネントのプロセスを手動で( kill
コマンドで)強制停止して、コンポーネントの動作を観察してみることにしました。
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回プロセスを停止してみました。すると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
横の数字は何回目なのかを記載したものです)
リカバリ処理に関する補足
Lambda コンポーネントを実行する場合、依存関係で下記のコンポーネントもデプロイされます。
- ラムダランチャーコンポーネント
- ラムダマネージャコンポーネント
- ラムダランタイムコンポーネント
greengrass.log
を見る限りでは、ラムダマネージャコンポーネントがリカバリ処理を実行しているように見受けられましたが、ドキュメント上では記載を見つけられませんでした。
また、Greengrass V2 では一部が OSS としてコードが公開されていますが、Lambda 関連のコンポーネントはいずれも非公開だったので、ソースコードからリカバリ処理の詳細を確認することもできなかったので、上記はログからの推測になります。
また、独自のライフサイクルとしてリカバリスクリプトの追加を試してみました。実際に下記の設定をマージ更新として追加してみましたが、コンポーネントのプロセスを止めてもリカバリ処理は実行されませんでした。
(ログにも該当しそうなものは出力されず、無効な設定として処理されているようです。もし可能であればご指摘ください。)
{
"Manifests": [
{
"Lifecycle": {
"Recover": {
"requiresPrivilege": true,
"Script": "echo RecoverTest > /tmp/recover.txt"
}
}
}
]
}
自動復旧するまでの時間
以上のとおり、Lambda コンポーネントは2回目までは自動で復旧しますが、復旧するまでの時間はバラツキがありました。
早い場合は数十秒で復旧しましたが、遅い場合は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
の状態の表示になります。
ステータス表示にマウスのポインタを置くと簡単な説明が表示されます。
コンポーネントの場合は修正方法も表示されて助かりますね。
最後に
今回は Lambda コンポーネントの異常終了時の動作を確認してみました。
カスタムコンポーネントによるリカバリスクリプトや異常発生の検知方法など確認したいことも出てきたので、改めて検証してご紹介できればと思います。
以上です。