Zenn
🎉

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

2023/10/18に公開
Rails
Ruby
SQS
Elastic Beanstalk
#
activeelasticjob
tech

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 が解決すること

Gem の動作

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

https://github.com/steveklabnik/request_store/blob/e803059c0d5f328b4eddc8161a074ae85fb049b7/lib/request_store/middleware.rb#L16-L24

  • 上記が発動するのは call されたときだけ
    • 逆に言えば call を通らないパスで RequestStore.store に読み書きをしてスレッドの使い回しがおきた場合、変数の混同が起きる、と想定できる。
  • call がかかるのは ActionDispatch でのリクエストが起きたとき。

https://github.com/steveklabnik/request_store/blob/e803059c0d5f328b4eddc8161a074ae85fb049b7/lib/request_store/railtie.rb#L4-L8

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

ElasticBeanstalk の Worker 環境での動作

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

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 を横取りして処理する

https://github.com/active-elastic-job/active-elastic-job/blob/092a8102cd38cffd7203d408fa03998cdff9dc03/lib/active_elastic_job/rack/sqs_message_consumer.rb#L5-L8

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

https://github.com/active-elastic-job/active-elastic-job/blob/092a8102cd38cffd7203d408fa03998cdff9dc03/lib/active_elastic_job/railtie.rb#L15-L22

$ 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 を起動する

https://github.com/aws/aws-sdk-rails/blob/6f891009d91faa0582c60ea87c4bf94ead0b8adb/bin/aws_sqs_active_job#L4-L6

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

https://github.com/aws/aws-sdk-rails/blob/6f891009d91faa0582c60ea87c4bf94ead0b8adb/lib/aws/rails/sqs_active_job/poller.rb#L14-L55

https://github.com/aws/aws-sdk-rails/blob/6f891009d91faa0582c60ea87c4bf94ead0b8adb/lib/aws/rails/sqs_active_job/poller.rb#L63-L94

  • Executer の実行

https://github.com/aws/aws-sdk-rails/blob/6f891009d91faa0582c60ea87c4bf94ead0b8adb/lib/aws/rails/sqs_active_job/executor.rb#L24-L40

  • JobRunner の実行

https://github.com/aws/aws-sdk-rails/blob/6f891009d91faa0582c60ea87c4bf94ead0b8adb/lib/aws/rails/sqs_active_job/job_runner.rb#L9-L17

余談

https://github.com/aws/aws-sdk-rails/blob/6f891009d91faa0582c60ea87c4bf94ead0b8adb/lib/aws/rails/railtie.rb#L77-L88

https://github.com/aws/aws-sdk-rails/blob/6f891009d91faa0582c60ea87c4bf94ead0b8adb/lib/aws/rails/middleware/ebs_sqs_active_job_middleware.rb#L17-L33

まとめ

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

Discussion