🎉

EB から ECS にワーカーを移行したら、RequestStore が想定外の動作をしたので調査した

2023/10/18に公開

Rails

tl;dr

RequestStore はスレッドセーフで HTTP リクエスト間で分離される
ElasticBeanstalk の Worker 環境では SQS キューは HTTP リクエストの枠組みで処理される
ジョブワーカーでは、スレッドローカル変数の取り扱いに注意する

おきたこと

ElasticBeanstalk(EB) で起動しているアプリケーションを ElasticContainerService(ECS) に移行した
- EB の Worker 環境で起動していたワーカーでは Active Job のアダプターとして active-elastic-job を利用
- ECS のワーカーでは Active Job のアダプターとして aws-sdk-rails を利用
ECS で worker タスクを実行したら RequestStore に保持しているデータの混線が起きはじめた
ローカルの docker 環境でも起きてるっぽい
EB の環境では起きてなかった
- エラーの検知の仕組みにもひっかかってないし、データ面でも異常がなかった

データ混線に気付くまで

コンテナで実行される Ralis のログを目視で追うことになった
エラー発生したコンテナで実行されているジョブを時系列で把握する必要があり Athena でもクエリしきれなかった
- コンテナ ID がロギングされるので、同じコンテナ(ECS タスク)が実行した処理をおいかけた
→ RequestStore に保持した内容がジョブ間で混線しているとあたりをつけた

RequestStore

Gem が解決すること

リクエストグローバルな変数の保持
- 参考：リクエスト単位でグローバルな参照を持たせて Audit ログをスッキリ実装したい
- 参考：RequestStore の使い方まとめ

Gem の動作

上掲参考サイトにもあるが RequestStore はリクエストをまたいで共有がおこらないようクリア処理がある

上記が発動するのは call されたときだけ
- 逆に言えば call を通らないパスで RequestStore.store に読み書きをしてスレッドの使い回しがおきた場合、変数の混同が起きる、と想定できる。
call がかかるのは ActionDispatch でのリクエストが起きたとき。
- 参考：ActionDispatch ってなんだろう？ - 広島・岡山 Ruby 交流会 01

例えば rails console をすることでも RequestStore::Middleware#initialize の実行は観測できるが、他方で RequestStore::Middleware#call の実行は観測できない。

ElasticBeanstalk の Worker 環境での動作

結論として Worker 環境では、SQS にキューイングされたメッセージが http の POST リクエストとして Rails に送られる。このため RequestStore 組み込みの clear が発動する

Elastic Beanstalk worker environments

Elastic Beanstalk worker environments simplify this process by managing the Amazon SQS queue and running a daemon process on each instance that reads from the queue for you. When the daemon pulls an item from the queue, it sends an HTTP POST request locally to http://localhost/ on port 80 with the contents of the queue message in the body. All that your application needs to do is perform the long-running task in response to the POST. You can configure the daemon to post to a different path, use a MIME type other than application/JSON, connect to an existing queue, or customize connections (maximum concurrent requests), timeouts, and retries.

[Procfile]がない状況での動作確認

Procfile を配置していなかったので ElasticBeanstalk のデフォルト設定で動作している
デフォルト設定のドキュメントが確認できなかったので動作環境にて確認した

起動しているサービスの確認

systemctl で起動しているサービスのリストから web.service が起動していることを確認できる

[ec2-user@ip-172-31-0-0 ~]$ systemctl list-unit-files -t service | grep enabled
# ... snip ...
sqsd.service                                  enabled
# ... snip ...
web.service                                   enabled
# ... snip ...

ジャーナルログの確認

web.service のジャーナルログから puma が起動していること確認できる

[ec2-user@ip-172-31-0-0 ~]$ journalctl -u web
-- Logs begin at 月 2023-10-16 22:30:54 UTC, end at *** --
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal systemd[1]: Starting This is web daemon...
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal systemd[1]: Started This is web daemon.
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] Puma starting in cluster mode...
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] * Puma version: 5.6.2 (ruby 2.7.5-p203) ("Birdie's Version")
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] *  Min threads: 8
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] *  Max threads: 32
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] *  Environment: production
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] *   Master PID: 8849
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] *      Workers: 4
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] *     Restarts: (✔) hot (✔) phased
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] * Listening on unix:///var/run/puma/my_app.sock
10月 16 22:36:54 ip-172-31-0-0.ap-northeast-1.compute.internal web[8849]: [8849] Use Ctrl-C to stop
[ec2-user@ip-172-31-0-0 ~]$ journalctl -u nginx
-- Logs begin at 月 2023-10-16 22:30:54 UTC, end at *** --
10月 16 22:36:55 ip-172-31-0-0.ap-northeast-1.compute.internal systemd[1]: Starting The nginx HTTP and reverse proxy server...
10月 16 22:36:55 ip-172-31-0-0.ap-northeast-1.compute.internal nginx[8914]: nginx: the configuration file /etc/nginx/nginx.conf syntax is ok
10月 16 22:36:55 ip-172-31-0-0.ap-northeast-1.compute.internal nginx[8914]: nginx: configuration file /etc/nginx/nginx.conf test is successful
10月 16 22:36:55 ip-172-31-0-0.ap-northeast-1.compute.internal systemd[1]: Started The nginx HTTP and reverse proxy server.
[ec2-user@ip-172-31-0-0 ~]$ journalctl -u sqsd
-- Logs begin at 月 2023-10-16 22:30:54 UTC, end at *** --
10月 16 22:36:55 ip-172-31-0-0.ap-northeast-1.compute.internal systemd[1]: Starting This is sqsd daemon...
10月 16 22:36:57 ip-172-31-0-0.ap-northeast-1.compute.internal sqsd[8931]: Version 2 of the Ruby SDK will enter maintenance mode as of November 20, 2020. To continue receiving ser
10月 16 22:37:10 ip-172-31-0-0.ap-northeast-1.compute.internal sqsd[8931]: daemon is running with pid 9006...
10月 16 22:37:10 ip-172-31-0-0.ap-northeast-1.compute.internal systemd[1]: Started This is sqsd daemon.

socket を listen しているので nginx の設定も確認した

Web のサービス設定の確認

systemd での設定を確認

[ec2-user@ip-172-31-0-0 ~]$ cat /etc/systemd/system/web.service
[Unit]
Description=This is web daemon
PartOf=eb-app.target

[Service]
User=webapp
Type=simple

ExecStart=/bin/sh -c "puma -C /opt/elasticbeanstalk/config/private/pumaconf.rb"

ExecStartPost=/bin/sh -c "systemctl show -p MainPID web.service | cut -d= -f2 > /var/pids/web.pid"
ExecStopPost=/bin/sh -c "rm -f /var/pids/web.pid"
ExecStopPost=/bin/sh -c ""
Restart=always

EnvironmentFile=/opt/elasticbeanstalk/deployment/env

StandardOutput=syslog
StandardError=syslog
SyslogIdentifier=web
WorkingDirectory=/var/app/current/

[Install]
WantedBy=multi-user.target

nginx の設定の確認

nginx.conf とそこから読み込まれる設定ファイルの確認

nginx.conf

[ec2-user@ip-172-31-0-0 ~]$ cat /etc/nginx/nginx.conf
#Elastic Beanstalk Nginx Configuration File

user nginx;
error_log /var/log/nginx/error.log warn;
pid /var/run/nginx.pid;
worker_processes auto;
worker_rlimit_nofile 200000;

events {
worker_connections 1024;
}

http {
include /etc/nginx/mime.types;
default_type application/octet-stream;

    log_format  main  '$remote_addr - $remote_user [$time_local] "$request" '
                      '$status $body_bytes_sent "$http_referer" '
                      '"$http_user_agent" "$http_x_forwarded_for"';

    include       conf.d/*.conf;

    map $http_upgrade $connection_upgrade {
        default     "upgrade";
    }

    server {
        listen        80 default_server;
        access_log    /var/log/nginx/access.log main;

        client_header_timeout 60;
        client_body_timeout   60;
        keepalive_timeout     60;
        gzip                  off;
        gzip_comp_level       4;
        gzip_types text/plain text/css application/json application/javascript application/x-javascript text/xml application/xml application/xml+rss text/javascript;

        # Include the Elastic Beanstalk generated locations
        include conf.d/elasticbeanstalk/*.conf;
    }

}

conf.d 配下の設定ファイルの列挙と確認

[ec2-user@ip-172-31-0-0 ~]$ ls -r /etc/nginx/conf.d/*.conf;
/etc/nginx/conf.d/healthd_logformat.conf /etc/nginx/conf.d/elasticbeanstalk-nginx-ruby-upstream.conf /etc/nginx/conf.d/custom.conf
[ec2-user@ip-172-31-0-0 ~]$ cat /etc/nginx/conf.d/healthd_logformat.conf
log_format healthd '$msec"$uri"'
'$status"$request_time"$upstream_response_time"'
                    '$http_x_forwarded_for';
[ec2-user@ip-172-31-0-0 ~]$ cat /etc/nginx/conf.d/elasticbeanstalk-nginx-ruby-upstream.conf
upstream my_app {
server unix:///var/run/puma/my_app.sock;
[ec2-user@ip-172-31-0-0 ~]$ cat /etc/nginx/conf.d/custom.conf
# ユーザ定義のため割愛

conf.d/elasticbeanstalk 配下の設定ファイルの列挙と確認

[ec2-user@ip-172-31-0-0 ~]$ ls -r /etc/nginx/conf.d/elasticbeanstalk/*.conf
/etc/nginx/conf.d/elasticbeanstalk/webapp.conf /etc/nginx/conf.d/elasticbeanstalk/healthd.conf
[ec2-user@ip-172-31-0-0 ~]$ cat /etc/nginx/conf.d/elasticbeanstalk/webapp.conf
server*name * localhost; # need to listen to localhost for worker tier

location / {
root /var/app/current/public;
try_files $uri @proxy;
}

location @proxy {
proxy_pass http://my_app; # match the name of upstream directive which is defined above
proxy_set_header Host $host;
proxy_set_header X-Forwarded-For $proxy_add_x_forwarded_for;
}

location /assets {
alias /var/app/current/public/assets;
gzip_static on;
gzip on;
expires max;
add_header Cache-Control public;
}

location /public {
alias /var/app/current/public;
gzip_static on;
gzip on;
expires max;
add_header Cache-Control public;
}
[ec2-user@ip-172-31-0-0 ~]$ cat /etc/nginx/conf.d/elasticbeanstalk/healthd.conf
if ($time_iso8601 ~ "^(\d{4})-(\d{2})-(\d{2})T(\d{2})") {
set $year $1;
set $month $2;
set $day $3;
set $hour $4;
}

access_log /var/log/nginx/healthd/application.log.$year-$month-$day-$hour healthd;

ActiveElasticJob

SqsMessageConsumer は POST 送信されてきた request を横取りして処理する

SqsMessageConsumer 自体は Railtie によって middleware に登録される

$ bundle exec rake middleware
use ActionDispatch::HostAuthorization
use Rack::Sendfile
# ... snip ...
use ActiveElasticJob::Rack::SqsMessageConsumer
# ... snip ...
run {RailsApplication}::Application.routes

ECS での動作

設定状況

キューの処理として aws-sdk-rails を利用

config.active_job.queue_adapter = :amazon_sqs

起動コマンド

bundle exec aws_sqs_active_job --queue {キュー名}

amazon_sqs アダプターの動作

README の記述(Running workers - polling for jobs)のとおり、ポーリングをして、アダプターが直接ジョブを実行する構成となっている。
従って ActiveDispatch::Request が介在しない。

bin/aws_sqs_active_job は Poller を起動する

Poller のイニシャライズと実行

Executer の実行

JobRunner の実行

余談

amazon_sqs も active_elastic_job のように HTTP リクエストを処理する仕組みをもっている
- Elastic Beanstalk workers: processing activejobs using worker environments

まとめ

RequestStore はスレッドセーフ
- Thread.current を使う
RequestStore は HTTP ベースのリクエストの場合には、リクエスト間で、変数の共有が起きない仕組みを持つ
ElasticBeanstalk の Worker 環境では SQS のメッセージは HTTP リクエストとしてアプリケーショに送信される
- active_elastic_job の gem は HTTP リクエストを横取りして job 実行する
aws-sdk-rails の amazon_sqs ジョブアダプターは、SQS キューをポーリングして自前でジョブを起動する
Gem を変更したときアーキテクチャレベルの変更がないか要確認
- 効果的なテスト設計も大事