状況
環境は下記です。今回はあまり関係ないと思いますがフロントはreact nativeでスマホアプリです。
ruby: 3.0.3
rails: 6.1.4.4
carrierwave: 2.2.3
参考までにサーバーはさくらインターネットのVPSです。OSは標準のCentOS Stream 8 x86_64を利用してます。
carrierwaveの設定は下記の様な感じ。
config.fog_provider = 'fog/aws'
config.fog_credentials = {
provider: 'AWS',
aws_access_key_id: Rails.application.credentials.dig(:aws, :access_key_id),
aws_secret_access_key: Rails.application.credentials.dig(:aws, :secret_access_key),
region: 'ap-northeast-1',
}
config.storage = :fog
if Rails.env.production?
config.fog_directory = "prod-profit-#{ProFitName.normalize_to('-')}"
else
config.fog_directory = "dev-profit-#{ProFitName.normalize_to('-')}"
end
エラーログは下記の様な感じです。
I, [2023-01-22T05:23:31.521083 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Started PUT "/api/v1/jobs/2/" for 202.241.150.66 at 2023-01-22 05:23:31 +0900
I, [2023-01-22T05:23:31.544738 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Processing by API::V1::JobsController#update as HTML
I, [2023-01-22T05:23:31.544879 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Parameters: {"userId"=>"1", "secureCode"=>"****", "job"=>{"mainImage"=>#<ActionDispatch::Http::UploadedFile:0x0000000005a99a98 @tempfile=#<Tempfile:/tmp/RackMultipart20230122-7888-h3q0hr.jpg>, @original_filename="124B68E9-A2E7-4195-9CAD-8046C11AAF5B.jpg", @content_type="image/jpeg", @headers="content-disposition: form-data; name=\"job[mainImage]\"; filename=\"124B68E9-A2E7-4195-9CAD-8046C11AAF5B.jpg\"\r\ncontent-type: image/jpeg\r\n">}, "id"=>"2"}
D, [2023-01-22T05:23:31.546758 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] User Load (0.3ms) SELECT `users`.* FROM `users` WHERE `users`.`id` = 1 LIMIT 1
D, [2023-01-22T05:23:31.549101 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] UserSecurity Load (0.2ms) SELECT `user_securities`.* FROM `user_securities` WHERE `user_securities`.`user_id` = 1 AND `user_securities`.`code` = '****' LIMIT 1
D, [2023-01-22T05:23:31.550264 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Job Load (0.2ms) SELECT `jobs`.* FROM `jobs` WHERE `jobs`.`id` = 2 LIMIT 1
D, [2023-01-22T05:23:31.551645 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] JobUser Exists? (0.2ms) SELECT 1 AS one FROM `job_users` WHERE `job_users`.`job_id` = 2 AND `job_users`.`user_id` = 1 AND `job_users`.`role` = 1 LIMIT 1
D, [2023-01-22T05:23:32.126445 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] TRANSACTION (0.3ms) BEGIN
D, [2023-01-22T05:23:32.127519 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Job Update (0.9ms) UPDATE `jobs` SET `jobs`.`main_image` = '1728a43022.jpg', `jobs`.`updated_at` = '2023-01-22 05:23:32.123767' WHERE `jobs`.`id` = 2
D, [2023-01-22T05:23:32.130675 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] TRANSACTION (1.8ms) COMMIT
I, [2023-01-22T05:24:52.209200 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Completed 500 Internal Server Error in 80664ms (ActiveRecord: 3.9ms | Allocations: 9861)
F, [2023-01-22T05:24:52.211158 #7888] FATAL -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486]
[db679c33-cf22-4dc9-9ecf-4ced05a50486] Excon::Error::Socket (no address for dev-profit-beauty.s3.ap-northeast-1.amazonaws.com (Resolv::ResolvError)):
[db679c33-cf22-4dc9-9ecf-4ced05a50486]
[db679c33-cf22-4dc9-9ecf-4ced05a50486] app/controllers/api/v1/jobs_controller.rb:531:in `upadte_job'
[db679c33-cf22-4dc9-9ecf-4ced05a50486] app/controllers/api/v1/jobs_controller.rb:83:in `update'
I, [2023-01-22T05:24:52.213130 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Processing by ErrorsController#show as HTML
I, [2023-01-22T05:24:52.213361 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Parameters: {"userId"=>"1", "secureCode"=>"****", "job"=>{"mainImage"=>#<ActionDispatch::Http::UploadedFile:0x0000000005a99a98 @tempfile=#<Tempfile:/tmp/RackMultipart20230122-7888-h3q0hr.jpg>, @original_filename="124B68E9-A2E7-4195-9CAD-8046C11AAF5B.jpg", @content_type="image/jpeg", @headers="content-disposition: form-data; name=\"job[mainImage]\"; filename=\"124B68E9-A2E7-4195-9CAD-8046C11AAF5B.jpg\"\r\ncontent-type: image/jpeg\r\n">}, "id"=>"2"}
I, [2023-01-22T05:24:52.214088 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] no address for dev-profit-beauty.s3.ap-northeast-1.amazonaws.com (Resolv::ResolvError)
D, [2023-01-22T05:24:52.222160 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Rendering layout layouts/application.html.erb
D, [2023-01-22T05:24:52.222370 #7888] DEBUG -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Rendering errors/internal_server_error.html.erb within layouts/application
I, [2023-01-22T05:24:52.224244 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Rendered errors/internal_server_error.html.erb within layouts/application (Duration: 1.7ms | Allocations: 239)
I, [2023-01-22T05:24:52.234582 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Rendered layout layouts/application.html.erb (Duration: 12.3ms | Allocations: 1224)
I, [2023-01-22T05:24:52.234983 #7888] INFO -- : [db679c33-cf22-4dc9-9ecf-4ced05a50486] Completed 500 Internal Server Error in 22ms (Views: 19.9ms | ActiveRecord: 0.0ms | Allocations: 2517)
ローカルサーバーでは問題なくアップロードできますが、サーバーにデプロイしたらできなくなりました。ログのJob Update (0.9ms) UPDATE jobs SET jobs.main_image = '1728a43022.jpg',
のところでDBへのファイル名の登録が成功しているのですがファイルはaws上にアップされていません。その後60秒後くらいにExcon::Error::Socket
が発生します。
不思議なことに必ずこのエラーが起きるわけではありません。状況は3種類あります。
- このエラーが発生し画像がアップされていない。
- 画像はアップされているがこのエラーが発生しレスポンスが返ってこない。
- 正常にアップロードされ、レスポンスも返ってくる。
ただし、レスポンスが返る場合でも1分以上かかります(一度だけ瞬時に正しいレスポンスが返る時もありました)。
試したこと
- aws command-lineツールを使って対象のバケットにサーバーからアップロードしてみた。これはうまくできました。時間も一瞬です。
- サーバー側で保存(awsのアップロード)が走る前に画像を別の場所にコピーして、サーバまで画像が来ているか確認した。これはアップロードに失敗する時もちゃんとサーバーまでは来ていますね。
- DNSのエラーの様なのでサーバーからエラーログにあるs3のドメインをdigしてみたらちゃんと引けました。
最後に
何か思い当たることはありますでしょうか?あるいは他に試した方がいいことがあったらアドバイスお願いします。
これ書くのに色々調べてて一点気になったのはCentOS Stream 8な点ですね。バージョンが微妙に異なるのですがほぼ同じ構成で問題なくアップロードできるアプリケーションがあるのですが、そちらはCentOS Linux 8.2.2004なんですよね。同じCentOS8かと思ってあまり考えずに入れたんですけど、調べたら本家より先にパッチの入るOSみたいですね。他のOSをインストールし直して1から構築した方が手っ取り早そうな気もしてきましたが・・・
2023/01/25追加情報
StreamはCentOSの代替えにはならないということなので、AlmaLinux8をインストールしやり直してみましたが改善しませんでした。
検索しているエラー文をno address for s3.ap-northeast-1.amazonaws.com (Resolv::ResolvError)
に変えて検索してみたら同じようなエラーを見つけました。
https://gitlab.com/gitlab-org/charts/gitlab/-/issues/3303
ここで試してるようにRailsコンソールを開いて下記を実行すると・・・
Resolv.each_address('dev-profit-beauty.s3.ap-northeast-1.amazonaws.com'){|ip| puts ip }
下記の様にIPがサクッと取れる時もあるけど、60秒くらい待たされて配列のレスポンスが変える時があります。
irb(main):008:0> Resolv.each_address('dev-profit-beauty.s3.ap-northeast-1.amazonaws.com'){|ip| puts ip }
52.219.16.151
52.219.4.63
52.219.137.50
52.219.196.74
52.219.0.243
52.219.136.91
52.219.16.7
52.219.137.6
=> nil
irb(main):009:0> Resolv.each_address('dev-profit-beauty.s3.ap-northeast-1.amazonaws.com'){|ip| puts ip }
=>
[#<Resolv::Hosts:0x0000000003c42e28
@addr2name={"127.0.0.1"=>["localhost", "localhost.localdomain", "localhost4", "localhost4.localdomain4"]},
@filename="/etc/hosts",
@initialized=true,
@mutex=#<Thread::Mutex:0x0000000003c42d60>,
@name2addr={"localhost"=>["127.0.0.1"], "localhost.localdomain"=>["127.0.0.1"], "localhost4"=>["127.0.0.1"], "localhost4.localdomain4"=>["127.0.0.1"]}>,
#<Resolv::DNS:0x0000000003c42ce8
@config=
#<Resolv::DNS::Config:0x0000000003c42bf8
@config_info=nil,
@initialized=true,
@mutex=#<Thread::Mutex:0x0000000003c42b80>,
@nameserver_port=[["210.188.224.10", 53], ["210.188.224.11", 53]],
@ndots=1,
@search=[[#<Resolv::DNS::Label::Str app>]],
@timeouts=nil>,
@initialized=true,
@mutex=#<Thread::Mutex:0x0000000003c42c70>>]
irb(main):010:0>
2023/01/26追加情報
追加で試したことを追記します。
carrierwaveのバージョンを下げた
同じSakuraのサーバーからアップロードできている他のアプリと同じバージョンにしてみました。
carrierwave (1.2.3)
fog-aws (3.0.0)
fog-core (2.1.0)
これを動かすのにrubyのダウングレードが必要で2.7.7下げました。
これもダメでした。
URLをパス形式に変更した
@sayuri さんの提案で試してみました。
config.fog_provider = 'fog/aws'
config.fog_credentials = {
provider: 'AWS',
aws_access_key_id: Rails.application.credentials.dig(:aws, :access_key_id),
aws_secret_access_key: Rails.application.credentials.dig(:aws, :secret_access_key),
region: 'ap-northeast-1',
path_style: true # これを追加
}
config.storage = :fog
if Rails.env.production?
config.fog_directory = "prod-profit-#{ProFitName.normalize_to('-')}"
else
config.fog_directory = "dev-profit-#{ProFitName.normalize_to('-')}"
end
これもダメでした。
エラー文が下記の様に変わったのでちゃんとパス形式になってると思います。
Excon::Error::Socket (no address for s3.ap-northeast-1.amazonaws.com (Resolv::ResolvError))
sdkでアップロードしてみた
下記の純正SDKです。
https://docs.aws.amazon.com/sdk-for-ruby/v3/api/Aws/S3/Client.html
テストなので静的なローカルファイルをアップロードしてみました。
def aws_s3(name)
bucket_name = "prod-profit-#{ProFitName.normalize_to('-')}"
key = "test/#{name}.jpg"
region = 'ap-northeast-1'
s3_client = Aws::S3::Client.new(
region: region,
access_key_id: Rails.application.credentials.dig(:aws, :access_key_id),
secret_access_key: Rails.application.credentials.dig(:aws, :secret_access_key)
)
file = File.open('./data/images/main.jpg')
s3_client.put_object(
acl: 'public-read',
bucket: bucket_name,
key: key,
body: file,
content_type: MIME::Types.type_for(file.path)[0].to_s
)
end
10回ほどアップロードしてみましたが、全部瞬時にアップロードできました。SDKだと問題ない様です。