え! セッションログがS3バケットに出力されていない!
こんにちは、のんピ(@non____97)です。
皆さんはSSMセッションマネージャーのセッションログがS3バケットに出力されていないと経験をしたことはありますか? 私はあります。
SSMセッションマネージャーのセッションログはS3バケットやCloudWatch Logsに出力することが可能です。具体的な出力方法は以下記事をご覧ください。
CloudWatch Logsにログ出力をすると、以下のようにJSON形式のログが出力されます。
{
"eventVersion": "1.0",
"eventTime": "2023-07-18T10:24:19Z",
"awsRegion": "us-east-1",
"target": {
"id": "i-0db2e26bb837c93b1"
},
"userIdentity": {
"arn": "arn:aws:sts::<AWSアカウントID>:assumed-role/<IAMロール名>/<IAMユーザー名>"
},
"runAsUser": "ec2-user",
"sessionId": "<IAMロール名>-05ba181f37a0fb8d2",
"sessionData": [
"\u001b[?2004l\u001b]0;@ip-10-0-1-11:~\u0007\u001b[?2004h[ec2-user@ip-10-0-1-11 ~]$ sudo dnf install httpd"
]
}
{
"eventVersion": "1.0",
"eventTime": "2023-07-18T10:24:20Z",
"awsRegion": "us-east-1",
"target": {
"id": "i-0db2e26bb837c93b1"
},
"userIdentity": {
"arn": "arn:aws:sts::<AWSアカウントID>:assumed-role/<IAMロール名>/<IAMユーザー名>"
},
"runAsUser": "ec2-user",
"sessionId": "<IAMロール名>-05ba181f37a0fb8d2",
"sessionData": [
"Last metadata expiration check: 0:22:49 ago on Tue Jul 18 10:01:30 2023.",
"Dependencies resolved.",
"================================================================================================================================================================================================",
" Package Architecture Version Repository Size",
"================================================================================================================================================================================================",
"Installing:",
" \u001b[1m\u001b[32mhttpd \u001b(B\u001b[m x86_64 2.4.56-1.amzn2023 amazonlinux 48 k",
"Installing dependencies:",
" \u001b[1m\u001b[32mapr \u001b(B\u001b[m x86_64 1.7.2-2.amzn2023.0.2 amazonlinux 129 k",
" \u001b[1m\u001b[32mapr-util \u001b(B\u001b[m x86_64 1.6.3-1.amzn2023.0.1 amazonlinux 98 k",
" \u001b[1m\u001b[32mgeneric-logos-httpd \u001b(B\u001b[m noarch 18.0.0-12.amzn2023.0.3 amazonlinux 19 k",
" \u001b[1m\u001b[32mhttpd-core \u001b(B\u001b[m x86_64 2.4.56-1.amzn2023 amazonlinux 1.4 M",
" \u001b[1m\u001b[32mhttpd-filesystem \u001b(B\u001b[m noarch 2.4.56-1.amzn2023 amazonlinux 15 k",
" \u001b[1m\u001b[32mhttpd-tools \u001b(B\u001b[m x86_64 2.4.56-1.amzn2023 amazonlinux 82 k",
" \u001b[1m\u001b[32mlibbrotli \u001b(B\u001b[m x86_64 1.0.9-4.amzn2023.0.2 amazonlinux 315 k",
" \u001b[1m\u001b[32mmailcap \u001b(B\u001b[m noarch 2.1.49-3.amzn2023.0.3 amazonlinux 33 k",
"Installing weak dependencies:",
" \u001b[1m\u001b[32mapr-util-openssl \u001b(B\u001b[m x86_64 1.6.3-1.amzn2023.0.1 amazonlinux 17 k",
" \u001b[1m\u001b[32mmod_http2 \u001b(B\u001b[m x86_64 2.0.11-2.amzn2023 amazonlinux 150 k",
" \u001b[1m\u001b[32mmod_lua \u001b(B\u001b[m x86_64 2.4.56-1.amzn2023 amazonlinux 62 k",
"",
"Transaction Summary",
"================================================================================================================================================================================================",
"Install 12 Packages",
"",
"Total download size: 2.3 M",
"Installed size: 6.9 M"
]
}
{
"eventVersion": "1.0",
"eventTime": "2023-07-18T10:24:34Z",
"awsRegion": "us-east-1",
"target": {
"id": "i-0db2e26bb837c93b1"
},
"userIdentity": {
"arn": "arn:aws:sts::<AWSアカウントID>:assumed-role/<IAMロール名>/<IAMユーザー名>"
},
"runAsUser": "ec2-user",
"sessionId": "<IAMロール名>-05ba181f37a0fb8d2",
"sessionData": [
"Is this ok [y/N]: N",
"Operation aborted."
]
}コマンド実行及び何か出力がある都度、このようなJSONが出力されるとなると結構なログ量になることが予想されます。加えて、CloudWatch Logsのログ取り込み料金が気になるところです。
そのため、個人的にはS3バケットへのログ出力をしたいところです。リアルタイムにログを確認したい場面もあまり考えにくいです。
そんな折、ふとS3バケット上のセッションログを確認すると一部ログファイルが出力されていないではありませんか。
なぜ、このような事象が発生したのか調査してみたので紹介します。
いきなりまとめ
- EC2インスタンスを再起動した場合は、SSMセッションマネージャーのセッションログがS3バケットに出力できない
- SSM Agentや
ssm-session-workerが停止した場合はセッションログをS3バケットに出力できる- ただし強制終了された場合は、セッションログをS3バケットに出力することはできない
- セッションログの完全性が求められるのであれば、CloudWatch Logsにセッションログをストリーミングすることとなる
- ただし対話型コマンドではセッションデータのストリーミングはサポートされていない
- S3バケットへのログ出力をする場合は、上述のログ欠損のリスクを理解した上で設定する
SSM Agentのソースコードを眺めてみる
まず、S3バケットにセッションログが出力されるのはSSMセッションマネージャーのセッションが切断されたタイミングです。
出力されたセッションログの中身を確認してみましょう。
Script started on 2023-07-21 06:46:19+00:00 [<not executed on terminal>]
/bin/bash
cd /home/ec2-user
[?2004hsh-5.2$ /bin/bash
[?2004l
]0;@ip-10-0-1-11:/usr/bin[?2004h[ec2-user@ip-10-0-1-11 bin]$ cd /home/ec2-user
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[K
[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ ls -l
[?2004l
total 0
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ cat /etc/os-release
[?2004l
NAME="Amazon Linux"
VERSION="2023"
ID="amzn"
ID_LIKE="fedora"
VERSION_ID="2023"
PLATFORM_ID="platform:al2023"
PRETTY_NAME="Amazon Linux 2023"
ANSI_COLOR="0;33"
CPE_NAME="cpe:2.3:o:amazon:amazon_linux:2023"
HOME_URL="https://aws.amazon.com/linux/"
BUG_REPORT_URL="https://github.com/amazonlinux/amazon-linux-2023"
SUPPORT_END="2028-03-01"
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ exit
[?2004l
exit
[?2004hsh-5.2$ exit
[?2004l
exit
Script done on 2023-07-21 06:46:19+00:00 [COMMAND_EXIT_CODE="0"]scriptコマンドが裏で動いていそうですね。
ということでSSM Agentのソースコードを覗いて、scriptコマンドを叩いているところを確認します。
気合いでgrepすると、sciptを見つけました。
amazon-ssm-agent/agent/session/shell/shell_unix.go
const (
termEnvVariable = "TERM=xterm-256color"
langEnvVariable = "LANG=C.UTF-8"
langEnvVariableKey = "LANG"
startRecordSessionCmd = "script"
newLineCharacter = "\n"
catCmd = "cat"
scriptFlag = "-c"
groupsIdentifier = "groups="
)こちらのscriptの変数startRecordSessionCmdを使っている箇所を探し出します。
amazon-ssm-agent/agent/session/shell/shell_unix.go
// generateLogData generates a log file with the executed commands.
func (p *ShellPlugin) generateLogData(log log.T, config agentContracts.Configuration) error {
var flagStderr bytes.Buffer
loggerCmd := fmt.Sprintf("%s %s", catCmd, p.logger.ipcFilePath)
// Sixty minutes is the maximum amount of time before the command is cancelled
// If a command is running this long it is most likely a stuck process
ctx, cancel := context.WithTimeout(context.Background(), 60*time.Minute)
defer cancel()
cmdWithFlag := exec.CommandContext(ctx, startRecordSessionCmd, p.logger.logFilePath, scriptFlag, loggerCmd)
cmdWithFlag.Stderr = &flagStderr
flagErr := cmdWithFlag.Run()
if flagErr != nil {
log.Debugf("Failed to generate transcript with -c flag: %v: %s", flagErr, flagStderr.String())
var noFlagStderr bytes.Buffer
// some versions of "script" does not take a -c flag when passing in commands.
cmdWithoutFlag := exec.CommandContext(ctx, startRecordSessionCmd, p.logger.logFilePath, catCmd, p.logger.ipcFilePath)
cmdWithoutFlag.Stderr = &noFlagStderr
noFlagErr := cmdWithoutFlag.Run()
if noFlagErr != nil {
log.Debugf("Failed to generate transcript without -c flag: %v: %s", noFlagErr, noFlagStderr.String())
return fmt.Errorf("Failed to generate transcript with the following errors:\n%v: %s\n%v:%s", flagErr, flagStderr.String(), noFlagErr, noFlagStderr.String())
}
}
return nil
}generateLogData()といういかにもな関数が見つかりました。
ここで、generateLogData()の構造体ShellPluginが何者か気になったので確認します。
amazon-ssm-agent/agent/session/shell/shell.go
// Plugin is the type for the plugin.
type ShellPlugin struct {
context context.T
name string
stdin *os.File
stdout *os.File
stdoutPipe io.Reader
stderrPipe io.Reader
execCmd execcmd.IExecCmd
runAsUser string
dataChannel datachannel.IDataChannel
logger logger
separateOutput bool
stdoutPrefix string
stderrPrefix string
}
// logger is used for storing the information related to logging of session data to S3/CW
type logger struct {
ipcFilePath string
logFilePath string
logFileName string
transcriptDirPath string
ptyTerminated chan bool
cloudWatchStreamingFinished chan bool
streamLogsToCloudWatch bool
s3Util s3util.IAmazonS3Util
cwl cloudwatchlogsinterface.ICloudWatchLogsService
}コメントからセッションログをS3バケットやCloudWatch Logsに出力する時に使いそうなのが伝わってきますね。
generateLogData()を呼び出している場所を探します。
amazon-ssm-agent/agent/session/shell/shell.go
// finishLogging generates and uploads logs to S3/CW, terminates streaming to CW if enabled
func (p *ShellPlugin) finishLogging(
config agentContracts.Configuration,
output iohandler.IOHandler,
sessionPluginResultOutput mgsContracts.SessionPluginResultOutput,
ipcFile *os.File) {
log := p.context.Log()
// Generate log data only if customer has either enabled S3 logging or CW logging with streaming disabled
if config.OutputS3BucketName != "" || (config.CloudWatchLogGroup != "" && !config.CloudWatchStreamingEnabled) {
log.Debugf("Creating log file for shell session id %s at %s", config.SessionId, p.logger.logFilePath)
if err := p.generateLogData(log, config); err != nil {
errorString := fmt.Errorf("unable to generate log data: %s", err)
log.Error(errorString)
output.MarkAsFailed(errorString)
return
}
if config.OutputS3BucketName != "" {
log.Debug("Starting S3 logging")
s3KeyPrefix := fileutil.BuildS3Path(config.OutputS3KeyPrefix, p.logger.logFileName)
p.uploadShellSessionLogsToS3(log, p.logger.s3Util, config, s3KeyPrefix)
sessionPluginResultOutput.S3Bucket = config.OutputS3BucketName
sessionPluginResultOutput.S3UrlSuffix = s3KeyPrefix
}
if config.CloudWatchLogGroup != "" && !config.CloudWatchStreamingEnabled {
log.Debug("Starting CloudWatch logging")
p.logger.cwl.StreamData(
config.CloudWatchLogGroup,
config.SessionId,
p.logger.logFilePath,
true,
false,
p.logger.ptyTerminated,
false,
false)
}
}
// End streaming of logs since pty is terminated
if p.logger.streamLogsToCloudWatch {
p.logger.ptyTerminated <- true
log.Debug("Waiting for streaming to finish")
<-p.logger.cloudWatchStreamingFinished
log.Debug("Streaming done, proceed to close session worker")
p.cleanupLogFile(log, ipcFile)
}
// Populate CW log group information
if config.CloudWatchLogGroup != "" {
sessionPluginResultOutput.CwlGroup = config.CloudWatchLogGroup
sessionPluginResultOutput.CwlStream = config.SessionId
}
output.SetOutput(sessionPluginResultOutput)
}finishLogging()でログの生成とアップロードをしていそうですね。
finishLogging()を呼び出している場所を探します。
amazon-ssm-agent/agent/session/shell/shell.go
// execute starts command execution.
// It reads incoming message from data channel and executes it by either writing to pty.stdin or relying on exec.Cmd.
// It reads message from pty.stdout and writes to data channel.
func (p *ShellPlugin) execute(config agentContracts.Configuration,
cancelFlag task.CancelFlag,
output iohandler.IOHandler,
shellProps mgsContracts.ShellProperties) {
// Initialization
log := p.context.Log()
sessionPluginResultOutput := mgsContracts.SessionPluginResultOutput{}
p.initializeLogger(log, config)
// Validate session configuration before starting
if err := p.validate(config); err != nil {
output.SetExitCode(appconfig.ErrorExitCode)
output.SetStatus(agentContracts.ResultStatusFailed)
sessionPluginResultOutput.Output = err.Error()
output.SetOutput(sessionPluginResultOutput)
log.Errorf("Validation failed, err: %s", err)
return
}
if appconfig.PluginNameNonInteractiveCommands == p.name {
if err := p.setSeparateOutputStreamProperties(shellProps); err != nil {
output.SetExitCode(appconfig.ErrorExitCode)
output.SetStatus(agentContracts.ResultStatusFailed)
sessionPluginResultOutput.Output = err.Error()
output.SetOutput(sessionPluginResultOutput)
log.Errorf("SeparateOutputStream properties validation failed, err: %s", err)
return
}
}
// Catch signals and send a signal to the "sigs" chan if it triggers
sigs := make(chan os.Signal, 1)
signal.Notify(sigs, syscall.SIGINT, syscall.SIGHUP, syscall.SIGTERM, syscall.SIGQUIT)
// Setup cancellation flag for accepting TerminateSession requests and idle session timeout scenarios
cancelled := make(chan bool, 1)
go func() {
sig := <-sigs
log.Infof("caught signal to terminate: %v", sig)
cancelled <- true
}()
// Get the command executor, which is either pseudo terminal or exec.Cmd depending on the plugin type
if err := getCommandExecutor(log, shellProps, false, config, p); err != nil {
errorString := fmt.Errorf("Unable to start command: %s\n", err)
log.Error(errorString)
time.Sleep(2 * time.Second)
if appconfig.PluginNameNonInteractiveCommands == p.name {
// Error started before exec.cmd starts needs to be explicitly propagated to data channel.
p.sendErrorToDataChannel(log, errorString.Error())
}
output.MarkAsFailed(errorString)
return
}
// Create ipcFile used for logging session data temporarily on disk
ipcFile, err := os.Create(p.logger.ipcFilePath)
if err != nil {
errorString := fmt.Errorf("encountered an error while creating file %s: %s", p.logger.ipcFilePath, err)
log.Error(errorString)
output.MarkAsFailed(errorString)
return
}
defer func() {
if closeErr := ipcFile.Close(); closeErr != nil {
log.Warnf("error occurred while closing ipcFile, %v", closeErr)
}
}()
go func() {
cancelState := cancelFlag.Wait()
if cancelFlag.Canceled() {
cancelled <- true
log.Debug("Cancel flag set to cancelled in session")
}
log.Debugf("Cancel flag set to %v in session", cancelState)
}()
if appconfig.PluginNameNonInteractiveCommands == p.name {
p.executeCommandsWithExec(config, cancelled, cancelFlag, output, ipcFile)
} else {
p.executeCommandsWithPty(config, cancelled, cancelFlag, output, ipcFile)
}
// Finish logger activity like uploading logs to S3/CW
p.finishLogging(config, output, sessionPluginResultOutput, ipcFile)
log.Debug("Shell session execution complete")
}標準出力を読み込むexecute()から呼び出しているようです。
execute()を呼び出している場所を探します。
amazon-ssm-agent/agent/session/shell/shell.go
// Execute starts pseudo terminal.
// It reads incoming message from data channel and writes to pty.stdin.
// It reads message from pty.stdout and writes to data channel
func (p *ShellPlugin) Execute(
config agentContracts.Configuration,
cancelFlag task.CancelFlag,
output iohandler.IOHandler,
dataChannel datachannel.IDataChannel,
shellProps mgsContracts.ShellProperties) {
log := p.context.Log()
p.dataChannel = dataChannel
defer func() {
if err := p.stop(log); err != nil {
log.Errorf("Error occurred while closing pty: %v", err)
}
if err := recover(); err != nil {
log.Errorf("Error occurred while executing plugin %s: \n%v", p.name, err)
log.Errorf("Stacktrace:\n%s", debug.Stack())
log.Flush()
os.Exit(1)
}
}()
if cancelFlag.ShutDown() {
output.MarkAsShutdown()
} else if cancelFlag.Canceled() {
output.MarkAsCancelled()
} else {
p.execute(config, cancelFlag, output, shellProps)
}
}Execute()から呼び出しているようです。
Execute()の呼び出し先を探してみたのですが、私のGo力では見つけることはできませんでした...
ただ、取り敢えず何かをトリガーにscriptコマンドを実行してS3バケットにログをアップロードすることが分かりました。
他にもログを読み取るamazon-ssm-agent/agent/session/logging/main.goも眺めてみると、真相が分かる気がします。
amazon-ssm-agent/agent/session/logging/main.go
// Copyright 2018 Amazon.com, Inc. or its affiliates. All Rights Reserved.
//
// Licensed under the Apache License, Version 2.0 (the "License"). You may not
// use this file except in compliance with the License. A copy of the
// License is located at
//
// http://aws.amazon.com/apache2.0/
//
// or in the "license" file accompanying this file. This file is distributed
// on an "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND,
// either express or implied. See the License for the specific language governing
// permissions and limitations under the License.
// Package logging reads byte data from the log file and prints it on the console.
package main
import (
"bufio"
"os"
"strconv"
"github.com/aws/amazon-ssm-agent/agent/appconfig"
"github.com/aws/amazon-ssm-agent/agent/context"
"github.com/aws/amazon-ssm-agent/agent/log/ssmlog"
"github.com/aws/amazon-ssm-agent/agent/session/logging/console"
"github.com/aws/amazon-ssm-agent/agent/version"
)
const totalArguments = 2
const defaultSessionLoggerContextName = "[ssm-session-logger]"
func main() {
args := os.Args
argsLen := len(args) - 1
logger := initializeLogger()
log := logger.Log()
log.Infof("ssm-session-logger - %v", version.String())
// We need two arguments here.
// First one is the name of the log file to read from.
// Second one tells us whether to enable virtual terminal processing for newer versions of Windows.
if argsLen != totalArguments {
log.Error("Invalid number of arguments received while initializing session logger.")
return
}
file, err := os.Open(args[1])
if err != nil {
log.Errorf("Failed to open log file %s", args[1])
return
}
defer func() {
if closeErr := file.Close(); closeErr != nil {
log.Warnf("error occurred while closing file, %v", closeErr)
}
}()
enableVirtualTerminalProcessingForWindows, err := strconv.ParseBool(args[2])
if err != nil {
log.Errorf("Invalid argument type received while initializing session logger %s", args[2])
return
}
if enableVirtualTerminalProcessingForWindows {
if err := console.InitDisplayMode(); err != nil {
log.Errorf("Encountered an error while initializing console: %v", err)
return
}
}
scanner := bufio.NewScanner(file)
scanner.Split(bufio.ScanBytes)
for scanner.Scan() {
os.Stdout.Write(scanner.Bytes())
}
}
// initializeLogger initializes context logging for ssm session logger.
func initializeLogger() context.T {
// initialize a light weight logger, use the default seelog config logger
logger := ssmlog.SSMLogger(false)
// initialize appconfig, use default config
config := appconfig.DefaultConfig()
// agentIdentity is nil because session-logger does not use instanceId/Region/Credentials
return context.Default(logger, config, nil).With(defaultSessionLoggerContextName)
}セッションログが正しくS3バケットに出力される条件を探ってみる
EC2インスタンスをマネジメントコンソールから再起動
結局SSM Agentのソースコードを読んでも確認しが持てなかったので、セッションログが正しくS3バケットに出力される条件を実際に動作確認して探ってみます。
まず、SSMセッションマネージャー接続中に、EC2インスタンスをマネジメントコンソールから再起動をした場合にセッションログが出力されるか確認します。
再起動して数分経つと、セッション履歴にこちらのセッションが表示されました。ステータスは終了済みで、出力場所にS3へのリンクがありました。
こちらのリンクをクリックしても、「そんなオブジェクトはない」と怒られてしまいました。
EC2インスタンスをマネジメントコンソールから再起動する場合はS3バケットにログ出力できないようです。
EC2インスタンスをOS内から再起動
続いて、SMセッションマネージャー接続中に、OSから再起動をした場合にセッションログが出力されるか確認します。
結果は、先ほどと同じでS3バケットにログ出力されていませんでした。
SSM Agentを再起動
続いて、SSMセッションマネージャー接続中に、SSM Agentを再起動をした場合にセッションログが出力されるか確認します。
# SSM Agentのステータス確認
$ systemctl status amazon-ssm-agent.service
● amazon-ssm-agent.service - amazon-ssm-agent
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)
Active: active (running) since Fri 2023-07-21 08:31:08 UTC; 2min 28s ago
Main PID: 1478 (amazon-ssm-agen)
Tasks: 34 (limit: 1061)
Memory: 88.6M
CPU: 1.003s
CGroup: /system.slice/amazon-ssm-agent.service
├─1478 /usr/bin/amazon-ssm-agent
├─1523 /usr/bin/ssm-agent-worker
├─1616 /usr/bin/ssm-session-worker <IAMロール名>-018f2151098de1933
├─1629 sh
├─1630 /bin/bash
├─1798 systemctl status amazon-ssm-agent.service
└─1799 less
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [EC2Identity] Checking disk for registration info
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [EC2Identity] Registration info found for ec2 instance
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [amazon-ssm-agent] Registration attempted. Resuming core agent startup.
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [CredentialRefresher] credentialRefresher has started
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [CredentialRefresher] Credentials ready
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [CredentialRefresher] Starting credentials refresher loop
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [CredentialRefresher] Next credential rotation will be in 13.057146873516666 minutes
Jul 21 08:31:09 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:09 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker is not running, starting worker process
Jul 21 08:31:09 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:09 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker (pid:1523) started
Jul 21 08:31:09 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:09 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] Monitor long running worker health every 60 seconds
# SSM Agentの再起動
$ sudo systemctl restart amazon-ssm-agent.service
# セッションの切断
$ exit
$ exitセッション切断後、S3バケットを確認すると、以下のようなセッションログが出力されていました。
Script started on 2023-07-21 08:35:03+00:00 [<not executed on terminal>]
/bin/bash
cd /home/ec2-user
[?2004hsh-5.2$ /bin/bash
[?2004l
]0;@ip-10-0-1-11:/usr/bin[?2004h[ec2-user@ip-10-0-1-11 bin]$ cd /home/ec2-user
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[K
[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ ssm [K[K[K[Ksystemctl s[K[C[1@s[1@u[1@d[1@o[1@ [C[C[C[C[C[C[C[C[C[C[K[K[K[K[K[Kl[Ksu[K[Ksystemctl status ssm-agent
[?2004l
[?1h=
Unit ssm-agent.service could not be found.[m
[K[?1l>]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ systemctl status ssm-agent.ser[Kre[K[K[K[K[K[K[K[K[K[K[K[K[K[K[K ss
sshd-keygen.service sshd-keygen@rsa.service sssd-autofs.socket sssd-nss.socket sssd-pam.service sssd-sudo.service
sshd-keygen.target sshd.service sssd-kcm.service sssd-pac.service sssd-pam.socket sssd-sudo.socket
sshd-keygen@ecdsa.service sshd.socket sssd-kcm.socket sssd-pac.socket sssd-ssh.service sssd.service
sshd-keygen@ed25519.service sssd-autofs.service sssd-nss.service sssd-pam-priv.socket sssd-ssh.socket
[ec2-user@ip-10-0-1-11 ~]$ systemctl status ssm-[K[K[K[Kamazon-ssm-agent.service
[?2004l
[?1h=
● amazon-ssm-agent.service - amazon-ssm-agent[m
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)[m
Active: active (running) since Fri 2023-07-21 08:31:08 UTC; 2min 28s ago[m
Main PID: 1478 (amazon-ssm-agen)[m
Tasks: 34 (limit: 1061)[m
Memory: 88.6M[m
CPU: 1.003s[m
CGroup: /system.slice/amazon-ssm-agent.service[m
├─1478 /usr/bin/amazon-ssm-agent[m
├─1523 /usr/bin/ssm-agent-worker[m
├─1616 /usr/bin/ssm-session-worker <IAMロール名>-018f2151098de1933[m
├─1629 sh[m
├─1630 /bin/bash[m
├─1798 systemctl status amazon-ssm-agent.service[m
└─1799 less[m
[m
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [EC2Identity] Checking disk for registration info[m
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [EC2Identity] Registration info found for ec2 instance[m
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [amazon-ssm-agent] Registration attempted. Resuming core agent startup.[m
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [CredentialRefresher] credentialRefresher has started[m
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [CredentialRefresher] Credentials ready[m
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [CredentialRefresher] Starting credentials refresher loop[m
Jul 21 08:31:08 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:08 INFO [CredentialRefresher] Next credential rotation will be in 13.057146873516666 minutes[m
Jul 21 08:31:09 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:09 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker is not running, starting worker process[m
Jul 21 08:31:09 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:09 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker (pid:1523) started[m
Jul 21 08:31:09 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1478]: 2023-07-21 08:31:09 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] Monitor long running worker health every 60 seconds[m
[K[?1l>]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ systemctl status amazon-ssm-agent.service [C[1P[1P[1P[1P[1P[1P[1@r[1@e[1@s[1@t[1@a[1@r[1@t[C[1@s[1@u[1@d[1@o[1@
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ exit
[?2004l
exit
[?2004hsh-5.2$ exit
[?2004l
exit
Script done on 2023-07-21 08:35:03+00:00 [COMMAND_EXIT_CODE="0"]SSM Agentを停止
続いて、SSMセッションマネージャー接続中に、SSM Agentを停止した場合にセッションログが出力されるか確認します。
$ systemctl status amazon-ssm-agent
● amazon-ssm-agent.service - amazon-ssm-agent
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)
Active: active (running) since Fri 2023-07-21 08:34:40 UTC; 6min ago
Main PID: 1873 (amazon-ssm-agen)
Tasks: 32 (limit: 1061)
Memory: 89.0M
CPU: 615ms
CGroup: /system.slice/amazon-ssm-agent.service
├─1873 /usr/bin/amazon-ssm-agent
├─1882 /usr/bin/ssm-agent-worker
├─2077 /usr/bin/ssm-session-worker <IAMロール名>-074476b4c740e445f
├─2090 sh
├─2091 /bin/bash
├─2110 systemctl status amazon-ssm-agent
└─2111 less
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [EC2Identity] Checking disk for registration info
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [EC2Identity] Registration info found for ec2 instance
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [amazon-ssm-agent] Registration attempted. Resuming core agent startup.
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [CredentialRefresher] credentialRefresher has started
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [CredentialRefresher] Credentials ready
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [CredentialRefresher] Starting credentials refresher loop
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [CredentialRefresher] Next credential rotation will be in 9.527221276283333 minutes
Jul 21 08:34:41 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:41 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker is not running, starting worker process
Jul 21 08:34:41 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:41 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker (pid:1882) started
Jul 21 08:34:41 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:41 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] Monitor long running worker health every 60 seconds
$ sudo systemctl stop amazon-ssm-agent.service
$ systemctl status amazon-ssm-agent
○ amazon-ssm-agent.service - amazon-ssm-agent
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)
Active: inactive (dead) since Fri 2023-07-21 08:41:46 UTC; 9s ago
Duration: 6min 59.574s
Process: 1873 ExecStart=/usr/bin/amazon-ssm-agent (code=exited, status=0/SUCCESS)
Main PID: 1873 (code=exited, status=0/SUCCESS)
Tasks: 13 (limit: 1061)
Memory: 68.9M
CPU: 908ms
CGroup: /system.slice/amazon-ssm-agent.service
├─2077 /usr/bin/ssm-session-worker <IAMロール名>-074476b4c740e445f
├─2090 sh
├─2091 /bin/bash
├─2203 systemctl status amazon-ssm-agent
└─2204 less
Jul 21 08:41:39 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:39 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] Receiving stop signal, stop worker monitor
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:46 INFO [CredentialRefresher] Sending credential refresher stop signal
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:46 INFO [Registrar] Registrar is already stopped
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:46 INFO [amazon-ssm-agent] Bye.
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:46 INFO [CredentialRefresher] Stopping credentials refresher
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Deactivated successfully.
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 2077 (ssm-session-wor) remains running after unit stopped.
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 2090 (sh) remains running after unit stopped.
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 2091 (bash) remains running after unit stopped.
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: Stopped amazon-ssm-agent.service - amazon-ssm-agent.
# セッションの切断
$ exit
$ exitSSM Agentのサービスは停止していますが、ssm-session-workerのプロセスは動いているのでSSM Agent停止後も継続してSSMセッションマネージャーで接続できていました。
なお、SSMセッションマネージャー切断後は再接続できませんでした。SSM Agentのサービスが停止されており、新しくssm-session-workerのプロセスの起動ができないためと考えます。
S3バケットを確認すると、以下のようなセッションログが出力されていました。
Script started on 2023-07-21 08:42:24+00:00 [<not executed on terminal>]
/bin/bash
cd /home/ec2-user
[?2004hsh-5.2$ /bin/bash
[?2004l
]0;@ip-10-0-1-11:/usr/bin[?2004h[ec2-user@ip-10-0-1-11 bin]$ cd /home/ec2-user
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[K
[ec2-user@ip-10-0-1-11 ~]$ [7msystemctl status ssm[27msystemctl status ssm[K[K[K[7mamazon-ssm-agent[27mamazon-ssm-agent
[?2004l
[?1h=
● amazon-ssm-agent.service - amazon-ssm-agent[m
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)[m
Active: active (running) since Fri 2023-07-21 08:34:40 UTC; 6min ago[m
Main PID: 1873 (amazon-ssm-agen)[m
Tasks: 32 (limit: 1061)[m
Memory: 89.0M[m
CPU: 615ms[m
CGroup: /system.slice/amazon-ssm-agent.service[m
├─1873 /usr/bin/amazon-ssm-agent[m
├─1882 /usr/bin/ssm-agent-worker[m
├─2077 /usr/bin/ssm-session-worker <IAMロール名>-074476b4c740e445f[m
├─2090 sh[m
├─2091 /bin/bash[m
├─2110 systemctl status amazon-ssm-agent[m
└─2111 less[m
[m
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [EC2Identity] Checking disk for registration info[m
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [EC2Identity] Registration info found for ec2 instance[m
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [amazon-ssm-agent] Registration attempted. Resuming core agent startup.[m
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [CredentialRefresher] credentialRefresher has started[m
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [CredentialRefresher] Credentials ready[m
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [CredentialRefresher] Starting credentials refresher loop[m
Jul 21 08:34:40 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:40 INFO [CredentialRefresher] Next credential rotation will be in 9.527221276283333 minutes[m
Jul 21 08:34:41 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:41 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker is not running, starting worker process[m
Jul 21 08:34:41 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:41 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker (pid:1882) started[m
Jul 21 08:34:41 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:34:41 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] Monitor long running worker health every 60 seconds[m
[K[?1l>]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ s[Ks[Ksudo systemctl stp[Kop amazon-ssm-agent.service
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ sudo systemctl stop amazon-ssm-agent.service
[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[12Pystemctl status amazon-ssm-agent
[?2004l
[?1h=
○ amazon-ssm-agent.service - amazon-ssm-agent[m
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)[m
Active: inactive (dead) since Fri 2023-07-21 08:41:46 UTC; 9s ago[m
Duration: 6min 59.574s[m
Process: 1873 ExecStart=/usr/bin/amazon-ssm-agent (code=exited, status=0/SUCCESS)[m
Main PID: 1873 (code=exited, status=0/SUCCESS)[m
Tasks: 13 (limit: 1061)[m
Memory: 68.9M[m
CPU: 908ms[m
CGroup: /system.slice/amazon-ssm-agent.service[m
├─2077 /usr/bin/ssm-session-worker <IAMロール名>-074476b4c740e445f[m
├─2090 sh[m
├─2091 /bin/bash[m
├─2203 systemctl status amazon-ssm-agent[m
└─2204 less[m
[m
Jul 21 08:41:39 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:39 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] Receiving stop signal, stop worker monitor[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:46 INFO [CredentialRefresher] Sending credential refresher stop signal[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:46 INFO [Registrar] Registrar is already stopped[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:46 INFO [amazon-ssm-agent] Bye.[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1873]: 2023-07-21 08:41:46 INFO [CredentialRefresher] Stopping credentials refresher[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Deactivated successfully.[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 2077 (ssm-session-wor) remains running after unit stopped.[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 2090 (sh) remains running after unit stopped.[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 2091 (bash) remains running after unit stopped.[m
Jul 21 08:41:46 ip-10-0-1-11.ec2.internal systemd[1]: Stopped amazon-ssm-agent.service - amazon-ssm-agent.[m
[K[?1l>]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[K
[ec2-user@ip-10-0-1-11 ~]$
[K
[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ ls -[K[K[K[Kexit
[?2004l
exit
[?2004hsh-5.2$ exit
[?2004l
exit
Script done on 2023-07-21 08:42:24+00:00 [COMMAND_EXIT_CODE="0"]SSM Agentの子プロセスでセッションログをS3バケットにアップロードしていそうですね。
ssm-session-workerをKillした場合
次に、SSM Agent停止後にssm-session-workerをKillした場合の挙動を確認します。
sudo kill ssm-session-workerのPIDでssm-session-workerのプロセスを停止させます。
プロセス停止後10分ほどセッションは切れず、ログ出力されませんでした。
しょうがないので、EC2インスタンスを再起動します。
すると、以下のようなセッションログがS3バケットに出力されました。
Script started on 2023-07-21 08:49:28+00:00 [<not executed on terminal>]
/bin/bash
cd /home/ec2-user
[?2004hsh-5.2$ /bin/bash
[?2004l
]0;@ip-10-0-1-11:/usr/bin[?2004h[ec2-user@ip-10-0-1-11 bin]$ cd /home/ec2-user
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[K
[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ cd /home/ec2-userexit[K/bin/bash[5Pexitsystemctl status amazon-ssm-agent
[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[Cudo systemctl stop amazon-ssm-agent.service
[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[12Pystemctl status amazon-ssm-agent
[?2004l
[?1h=
● amazon-ssm-agent.service - amazon-ssm-agent[m
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)[m
Active: active (running) since Fri 2023-07-21 08:45:56 UTC; 1min 59s ago[m
Main PID: 1479 (amazon-ssm-agen)[m
Tasks: 32 (limit: 1061)[m
Memory: 125.2M[m
CPU: 2.067s[m
CGroup: /system.slice/amazon-ssm-agent.service[m
├─1479 /usr/bin/amazon-ssm-agent[m
├─1524 /usr/bin/ssm-agent-worker[m
├─1626 /usr/bin/ssm-session-worker <IAMロール名>-05fd2d85e2c60477e[m
├─1639 sh[m
├─1640 /bin/bash[m
├─1659 systemctl status amazon-ssm-agent[m
└─1660 less[m
[m
Jul 21 08:45:56 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:56 INFO [CredentialRefresher] credentialRefresher has started[m
Jul 21 08:45:56 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:56 INFO [CredentialRefresher] Credentials ready[m
Jul 21 08:45:56 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:56 INFO [CredentialRefresher] Starting credentials refresher loop[m
Jul 21 08:45:57 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:56 INFO [CredentialRefresher] Next credential rotation will be in -1.7492776498 minutes[m
Jul 21 08:45:57 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:56 INFO EC2RoleProvider Successfully connected with instance profile role credentials[m
Jul 21 08:45:57 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:56 INFO [CredentialRefresher] Credentials ready[m
Jul 21 08:45:57 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:56 INFO [CredentialRefresher] Next credential rotation will be in 29.999996065716665 minutes[m
Jul 21 08:45:57 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:57 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker is not running, starting worker process[m
Jul 21 08:45:58 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:57 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] [WorkerProvider] Worker ssm-agent-worker (pid:1524) started[m
Jul 21 08:45:58 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:45:57 INFO [amazon-ssm-agent] [LongRunningWorkerContainer] Monitor long running worker health every 60 seconds[m
[K[?1l>]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ systemctl status amazon-ssm-agent
[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[1P amazon-ssm-agent[1P amazon-ssm-agent[1P amazon-ssm-agent[1P amazon-ssm-agent[1P amazon-ssm-agentt amazon-ssm-agento amazon-ssm-agentp amazon-ssm-agent[C[1@s[1@u[1@d[1@o[1@ [C[C[C[C[C[C
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ sudo systemctl stop amazon-ssm-agent
[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[3Pystemctl status[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C[C
[?2004l
[?1h=
○ amazon-ssm-agent.service - amazon-ssm-agent[m
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)[m
Active: inactive (dead) since Fri 2023-07-21 08:48:18 UTC; 5s ago[m
Duration: 2min 15.126s[m
Process: 1479 ExecStart=/usr/bin/amazon-ssm-agent (code=exited, status=0/SUCCESS)[m
Main PID: 1479 (code=exited, status=0/SUCCESS)[m
Tasks: 13 (limit: 1061)[m
Memory: 102.3M[m
CPU: 2.245s[m
CGroup: /system.slice/amazon-ssm-agent.service[m
├─1626 /usr/bin/ssm-session-worker <IAMロール名>-05fd2d85e2c60477e[m
├─1639 sh[m
├─1640 /bin/bash[m
├─1735 systemctl status amazon-ssm-agent[m
└─1736 less[m
[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:48:18 INFO [CredentialRefresher] Sending credential refresher stop signal[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:48:18 INFO [CredentialRefresher] Stopping credentials refresher[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:48:18 INFO [Registrar] Registrar is already stopped[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1479]: 2023-07-21 08:48:18 INFO [amazon-ssm-agent] Bye.[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Deactivated successfully.[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 1626 (ssm-session-wor) remains running after unit stopped.[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 1639 (sh) remains running after unit stopped.[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 1640 (bash) remains running after unit stopped.[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal systemd[1]: Stopped amazon-ssm-agent.service - amazon-ssm-agent.[m
Jul 21 08:48:18 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Consumed 2.227s CPU time.[m
[K[?1l>]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$
[?2004l
]0;@ip-10-0-1-11:~[?2004h[ec2-user@ip-10-0-1-11 ~]$ sudo kill 172[K[K626
[?2004l
]0;@ip-10-0-1-11:~
Script done on 2023-07-21 08:49:28+00:00 [COMMAND_EXIT_CODE="0"]プロセスを停止させた際のログも出力されていますね。
ついでに、プロセスを強制停止させた場合の挙動も確認します。
$ sudo systemctl stop amazon-ssm-agent.service
$ systemctl status amazon-ssm-agent
○ amazon-ssm-agent.service - amazon-ssm-agent
Loaded: loaded (/etc/systemd/system/amazon-ssm-agent.service; enabled; preset: enabled)
Active: inactive (dead) since Mon 2023-07-24 00:43:46 UTC; 2s ago
Duration: 38.770s
Process: 1490 ExecStart=/usr/bin/amazon-ssm-agent (code=exited, status=0/SUCCESS)
Main PID: 1490 (code=exited, status=0/SUCCESS)
Tasks: 12 (limit: 1061)
Memory: 300.3M
CPU: 11.507s
CGroup: /system.slice/amazon-ssm-agent.service
├─1585 /usr/bin/ssm-session-worker <IAMロール名>-0be8a4ea273eb5792
├─1600 sh
├─1601 /bin/bash
├─1826 systemctl status amazon-ssm-agent
└─1827 less
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1490]: 2023-07-24 00:43:46 INFO [CredentialRefresher] Sending credential refresher stop signal
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1490]: 2023-07-24 00:43:46 INFO [Registrar] Registrar is already stopped
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1490]: 2023-07-24 00:43:46 INFO [amazon-ssm-agent] Bye.
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal amazon-ssm-agent[1490]: 2023-07-24 00:43:46 INFO [CredentialRefresher] Stopping credentials refresher
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Deactivated successfully.
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 1585 (ssm-session-wor) remains running after unit stopped.
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 1600 (sh) remains running after unit stopped.
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Unit process 1601 (bash) remains running after unit stopped.
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal systemd[1]: Stopped amazon-ssm-agent.service - amazon-ssm-agent.
Jul 24 00:43:46 ip-10-0-1-11.ec2.internal systemd[1]: amazon-ssm-agent.service: Consumed 11.493s CPU time.
$ sudo kill -9 1585こちらの場合もプロセスを強制停止させて20分近く経っても、セッションは切れませんでした。
SSMセッションマネージャーのコンソールからセッションを停止させてみます。20分ほど待ちましたが、SSMセッションマネージャーのセッションの状態も終了中のままです。
試しに一度EC2インスタンスを停止させてみます。
停止したタイミングではまだ、S3バケットにセッションログは出力されず、SSMセッションマネージャーのセッションの状態も終了中のままです。10分ほど待ちましたが変わらずです。
EC2インスタンスを起動させてみます。
起動したタイミングでセッションのステータスは終了済みになりましたがセッションログはS3バケットに出力されませんでした。
つまりはssm-agent-workerが正常に停止されなければならないようです。
セッションログの完全性が求められるのであれば、CloudWatch Logsにセッションログをストリーミングさせよう
SSMセッションマネージャー接続中にEC2インスタンスを停止させた場合、セッションログはS3バケットに出力されない事象を紹介しました。
S3バケットへのログ出力をする場合は、ログ欠損のリスクを理解した上で設定しましょう。
なお、CloudWatch Logsにはストリーミングでログ出力することが可能です。そのため、以下のようにOS停止をするコマンドを叩いた場合もログ出力されています。
{
"eventVersion": "1.0",
"eventTime": "2023-07-24T02:08:21Z",
"awsRegion": "us-east-1",
"target": {
"id": "i-0db2e26bb837c93b1"
},
"userIdentity": {
"arn": "arn:aws:sts::<AWSアカウントID>:assumed-role/<IAMロール名>/<IAMユーザー名>"
},
"runAsUser": "ec2-user",
"sessionId": "<IAMロール名>-034a918b79ad11968",
"sessionData": [
"\u001b[?2004l\u001b]0;@ip-10-0-1-11:~\u0007\u001b[?2004h[ec2-user@ip-10-0-1-11 ~]$ sudo systemctl \u001b[7mpoweroff\u001b[27m\b\b\b\b\b\b\b\bpoweroff",
"Terminated"
]
}ただし、対話型コマンドではセッションデータのストリーミングはサポートされていません。ドキュメントをよく確認した上で設定をしましょう。
この記事が誰かの助けになれば幸いです。
以上、AWS事業本部 コンサルティング部の のんピ(@non____97)でした!
8
