概要
Carrierwaveの画像アップロードで意図しない動きをしたので原因をみつけて解決するためにGemのソースコードを読んでいくことになりました。今回はそのログを残します。
目的
プログラミング初心者が未経験でこの業界に入って学習を始めて6ヵ月。そしてRailsの勉強を始めて4ヵ月程がたちました。Gemのソースコードを読むことにまだまだ敷居の高さを感じていたものの、2日間悩んで問題に取り組んでいるうちにソースコードを追ってどこで自分の意図しない動きをしたのかはっきりさせるしかないということになりました。
Carrierwaveの本来の使い方(READMEに書いてあるような)から外れてしまったため情報も少なく、そのような状況の中取り組んだソースコードリーディングから得られるものが多くありました。
今回は自分と同じようなRailsを学習して間もない方々への共有と自分自身の備忘録を目的としてソースコードを読んでいった過程を残していきます。
開発の環境
- rails (5.1.2)
- ユーザーがアップロードした画像の位置情報を利用したWebサービスを開発中
- carrierwave (1.1.0)
- activerecord-mysql2spatial-adapter (0.5.0.nonrelease 3c0e871)
- rgeo (0.6.0)
- rgeo-activerecord (5.1.0)
- rmagick (2.16.0)
問題が起きるまで
画像アップロードしてもらい位置情報を取得します。その後確認画面にリダイレクトして取得した位置情報を元にフォームの初期値に位置情報を入れて問題がなければフォームからPOSTしてもらう形になっていました。画像のアップロードはCarrierwaveを通して行います。
本来であれば確認画面にリダイレクトするのでなく、画像を選択したらそのページでJavascriptやjQuerryを使って位置情報を取得してしまうのがよくあるパターンかと思います。しかし今回はCarrierwaveがデフォルトで行っているキャッシュ機能を使って、画像をディレクトリにsaveせずにリダイレクトさせました。その先でユーザーに追加の情報を入力してもらった後、データベースに画像の情報を設定したディレクトリにsaveします。
そして確認画面からPOST後に保存されたはずの画像をshow.html.erbで表示させると、不定期に画像が表示されませんでした。これが今回解決したかった不具合です。
callerメソッド
Rubyでバックトレースを取得することが出来るメソッドです。これを使ってメソッドが何処から呼び出されたのかを取得することが出来ます。
# hoge.rb
def hoge
hoge2
end
def hoge2
hoge3
end
def hoge3
hoge4
end
def hoge4
hoge5
end
def hoge5
hoge6
end
def hoge6
caller
end
p hoge
実行結果
["hoge.rb:18:in `hoge5'", "hoge.rb:14:in `hoge4'", "hoge.rb:10:in `hoge3'", "hoge.rb:6:in `hoge2'", "hoge.rb:2:in `hoge'", "hoge.rb:25:in `<main>'"]
callerメソッドを使うとメソッドの呼び出し状況を配列で返します。また、引数を与えて呼出しの深さを指定することが出来ます。
上のサンプルの場合深さは5つなのでcaller[0]からcaller[4]まで指定出来ます。
今回はこのcallerメソッドとlogger.debugを使ってエラーの直前の動きを追いかけていきました。
エラーが起きた周辺のコード
ルーティング
# routes.rb
# For admin
namespace :admin do
devise_for :admins, path: 'admins', as: :admin, singular: :admin, controllers: {
sessions: 'admin/sessions',
passwords: 'admin/passwords',
registrations: 'admin/registrations'
}
root 'pages#dashboard'
resources :admins
resources :users
resources :spots
resources :photos do
collection do
get 'detail/:image', :action => :detail
post 'detail' => 'photos#check'
end
end
end
コントローラ
# photos_controller.rb
def new
@photo = Photo.new
end
def check
# 画像を投稿せずにsubmitしたらやり直し
return redirect_to action: :new if photo_params[:image].blank?
@photo = Photo.new
begin
# 例外を起こしてエラー内容で分岐
@photo.image.cache!(photo_params[:image])
rescue => error_msg
# 拡張子のバリデーションのエラーのみtry catch
if error_msg.class == CarrierWave::IntegrityError
@extension_error_msg = "jpg jpeg png gifのみアップロード可能。 "
end
render 'new' and return
end
# paramsの末尾がjpgなためBase64エンコード
image_enc = Base64.encode64(@photo.image_cache)
redirect_to action: :detail, image: image_enc
end
def detail
# Base64デコード
@image_param = Base64.decode64(params[:image]).force_encoding("UTF-8")
@photo = Photo.new
# キャッシュした画像ファイルからインスタンスに
@photo.image.retrieve_from_cache!(@image_param)
# 緯度経度の取得とMap APIで使える形に変換するためのmagickインスタンス 独自メソッド
@param_exif = @photo.image.params
# 外部キーのドロップダウンリスト用のインスタンス
@spots = Spot.all
@users = User.all
@action_name = :create
end
def create
@photo = Photo.new(photo_params)
@photo.image.retrieve_from_cache!(params[:image_url])
if @photo.save
redirect_to admin_photos_path
else
# バリデーションエラーした後のrender先で必要な変数を定義
@spots = Spot.all
@users = User.all
@rendering_lat = params[:image_lat]
@rendering_lng = params[:image_lng]
@rendering_image = params[:image_url]
@action_name = :create
render 'detail'
end
end
フォーム画面
<%= form_for @photo,:url => {:action => actionname }, html: { multipart: true } do |f| %>
<% if @photo.errors.any? %>
<h3>入力した内容にエラーが<%= @photo.errors.count %>件あります。</h3>
<ul>
<% @photo.errors.full_messages.each do |msg| %>
<li><%= msg %></li>
<% end %>
<% end %>
<div class="form-group">
<%= f.label :user_id %>
<%= f.collection_select :user_id, @users, :id, :email, {prompt: "投稿するアカウント名を選択してください"}, class: "form-control" %><br>
<%= f.label :own_comment %>
<%= f.text_field :own_comment, class: "form-control", placeholder: "200文字以内" %><br>
<%= f.label :spot_id %>
<%= f.collection_select :spot_id, @spots, :id, :spot_name, {prompt: "観光地を選択してください"}, {class: "form-control"} %><br>
<%= f.label :location_info, value: "位置情報(変更は地図上の任意の地点をクリック)" %>
<%= f.text_field :location_info, id: 'photo_location_info', class: "form-control", readonly: true %>
<% if ['detail', 'create'].include?(controller.action_name) %>
<%= hidden_field_tag :image_url, @rendering_image || @image_param %>
<%= hidden_field_tag :image_lat, @rendering_lat || lat_calc(@param_exif) %>
<%= hidden_field_tag :image_lng, @rendering_lng || lng_calc(@param_exif) %>
<% end %>
</div>
<%= f.submit ['detail', 'create'].include?(controller.action_name) ? '決定' : '更新', class: 'btn btn-primary' %>
<% end %>
エラーの直前のメソッドを探す
new.html.erbからcheckアクションへPOSTして画像だけをキャッシュしてdetailアクションへリダイレクト。そこでキャッシュした画像をRmagickインスタンスに読み込ませて位置情報を取得し、その他の詳細情報をフォームに入力してもらった後にcreateアクションへPOSTしてindex.html.erbへリダイレクト。その後登録したレコードをshow.html.erbで表示すると不定期に画像が表示されません。
時間や保存する画像等の条件を合わせて何度も試行してみました。再現するための条件が何度やってもわかりません。そこで画像のアップロード用に導入したGemのメソッドを追いかけて処理が失敗している時と成功している時の違いを確認しようと思いました。
Carrierwaveのメソッドを手掛りに
今回画像の保存周りに使用したCarrierwaveのメソッドでぱっと思い浮かんだのが上記コードのコントローラ内のcheckアクションでのcache!メソッドでした。cacheするメソッドが定義されているソースコードがわかったらsaveするメソッドも近くのディレクトリにあるはずだと思い検索。
Module: CarrierWave::Uploader::Cache — Documentation for carrierwave (1.1.0)
このサイトでcacheメソッドの定義されているファイルに飛べました。bundler以下にあるcarrierwave内の同じファイルを開きます。
# /vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/cache.rb
def cache!(new_file = sanitized_file)
new_file = CarrierWave::SanitizedFile.new(new_file)
return if new_file.empty?
raise CarrierWave::FormNotMultipart if new_file.is_path? && ensure_multipart_form
self.cache_id = CarrierWave.generate_cache_id unless cache_id
@filename = new_file.filename
self.original_filename = new_file.filename
begin
# first, create a workfile on which we perform processings
if move_to_cache
@file = new_file.move_to(File.expand_path(workfile_path, root), permissions, directory_permissions)
else
@file = new_file.copy_to(File.expand_path(workfile_path, root), permissions, directory_permissions)
end
with_callbacks(:cache, @file) do
@file = cache_storage.cache!(@file)
end
ensure
FileUtils.rm_rf(workfile_path(''))
end
end
ありました。ただ今回調べたいのはキャッシュではなく本保存のメソッドです。ファイル名から想像するとおおまかな機能ごとにメソッドを定義するファイルを分けているようなので同じ階層を調べます。するとstore.rbというファイルが見つかりました。
# /vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/store.rb
def store!(new_file=nil)
cache!(new_file) if new_file && ((@cache_id != parent_cache_id) || @cache_id.nil?)
if !cache_only and @file and @cache_id
with_callbacks(:store, new_file) do
new_file = storage.store!(@file)
if delete_tmp_file_after_storage
@file.delete unless move_to_store
cache_storage.delete_dir!(cache_path(nil))
end
@file = new_file
@cache_id = nil
end
end
end
このメソッドのかならず読み込まれる行にcallerを入れてloggerで出力させてみます。
# 追加したコード
Rails.logger.debug 'callerログ出力'
Rails.logger.debug caller[0]
caller.each do |call|
Rails.logger.debug call
end
以下が出力です。
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/versions.rb:279:in `block in store_versions!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/versions.rb:279:in `block in store_versions!'
/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/versions.rb:279:in `each'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/versions.rb:279:in `store_versions!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/callbacks.rb:16:in `block in with_callbacks'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/callbacks.rb:16:in `each'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/callbacks.rb:16:in `with_callbacks'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/store.rb:79:in `store!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/mounter.rb:102:in `each'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/mounter.rb:102:in `store!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/mount.rb:395:in `store_image!'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:413:in `block in make_lambda'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:235:in `block in halting_and_conditional'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:511:in `block in invoke_after'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:511:in `each'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:511:in `invoke_after'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:132:in `run_callbacks'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:825:in `_run_save_callbacks'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/callbacks.rb:336:in `create_or_update'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/persistence.rb:129:in `save'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/validations.rb:44:in `save'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/attribute_methods/dirty.rb:35:in `save'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/transactions.rb:308:in `block (2 levels) in save'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/transactions.rb:384:in `block in with_transaction_returning_status'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:225:in `block in transaction'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/connection_adapters/abstract/transaction.rb:194:in `block in within_new_transaction'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/2.4.0/monitor.rb:214:in `mon_synchronize'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/connection_adapters/abstract/transaction.rb:191:in `within_new_transaction'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:225:in `transaction'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/transactions.rb:210:in `transaction'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/transactions.rb:381:in `with_transaction_returning_status'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/transactions.rb:308:in `block in save'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/transactions.rb:323:in `rollback_active_record_state!'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/transactions.rb:307:in `save'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/suppressor.rb:42:in `save'
/app/controllers/admin/photos_controller.rb:54:in `create'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_controller/metal/basic_implicit_render.rb:4:in `send_action'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/abstract_controller/base.rb:186:in `process_action'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_controller/metal/rendering.rb:30:in `process_action'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:131:in `run_callbacks'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/abstract_controller/callbacks.rb:19:in `process_action'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_controller/metal/rescue.rb:20:in `process_action'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
//vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/notifications.rb:166:in `block in instrument'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/notifications/instrumenter.rb:21:in `instrument'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/notifications.rb:166:in `instrument'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_controller/metal/params_wrapper.rb:252:in `process_action'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/railties/controller_runtime.rb:22:in `process_action'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/abstract_controller/base.rb:124:in `process'
/vendor/bundle/ruby/2.4.0/gems/actionview-5.1.2/lib/action_view/rendering.rb:30:in `process'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_controller/metal.rb:189:in `dispatch'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_controller/metal.rb:253:in `dispatch'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/routing/route_set.rb:49:in `dispatch'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/routing/route_set.rb:31:in `serve'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/journey/router.rb:46:in `block in serve'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/journey/router.rb:33:in `each'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/journey/router.rb:33:in `serve'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/routing/route_set.rb:832:in `call'
/vendor/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:36:in `block in call'
/vendor/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `catch'
/vendor/bundle/ruby/2.4.0/gems/warden-1.2.7/lib/warden/manager.rb:35:in `call'
/vendor/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/etag.rb:25:in `call'
/vendor/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/conditional_get.rb:38:in `call'
/vendor/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/head.rb:12:in `call'
/vendor/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:232:in `context'
/vendor/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/session/abstract/id.rb:226:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/cookies.rb:613:in `call'
/vendor/bundle/ruby/2.4.0/gems/activerecord-5.1.2/lib/active_record/migration.rb:556:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/callbacks.rb:26:in `block in call'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/callbacks.rb:97:in `run_callbacks'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/callbacks.rb:24:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/executor.rb:12:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/debug_exceptions.rb:59:in `call'
/vendor/bundle/ruby/2.4.0/gems/web-console-2.3.0/lib/web_console/middleware.rb:20:in `block in call'
/vendor/bundle/ruby/2.4.0/gems/web-console-2.3.0/lib/web_console/middleware.rb:18:in `catch'
/vendor/bundle/ruby/2.4.0/gems/web-console-2.3.0/lib/web_console/middleware.rb:18:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/show_exceptions.rb:31:in `call'
/vendor/bundle/ruby/2.4.0/gems/railties-5.1.2/lib/rails/rack/logger.rb:36:in `call_app'
/vendor/bundle/ruby/2.4.0/gems/railties-5.1.2/lib/rails/rack/logger.rb:24:in `block in call'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/tagged_logging.rb:69:in `block in tagged'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/tagged_logging.rb:26:in `tagged'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/tagged_logging.rb:69:in `tagged'
/vendor/bundle/ruby/2.4.0/gems/railties-5.1.2/lib/rails/rack/logger.rb:24:in `call'
/vendor/bundle/ruby/2.4.0/gems/sprockets-rails-3.2.0/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/remote_ip.rb:79:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/request_id.rb:25:in `call'
/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/method_override.rb:22:in `call'
/vendor/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/runtime.rb:22:in `call'
/vendor/bundle/ruby/2.4.0/gems/activesupport-5.1.2/lib/active_support/cache/strategy/local_cache_middleware.rb:27:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/executor.rb:12:in `call'
/vendor/bundle/ruby/2.4.0/gems/actionpack-5.1.2/lib/action_dispatch/middleware/static.rb:125:in `call'
/vendor/bundle/ruby/2.4.0/gems/rack-2.0.3/lib/rack/sendfile.rb:111:in `call'
/vendor/bundle/ruby/2.4.0/gems/railties-5.1.2/lib/rails/engine.rb:522:in `call'
/vendor/bundle/ruby/2.4.0/gems/unicorn-5.3.0/lib/unicorn/http_server.rb:606:in `process_client'
/vendor/bundle/ruby/2.4.0/gems/unicorn-5.3.0/lib/unicorn/http_server.rb:702:in `worker_loop'
/vendor/bundle/ruby/2.4.0/gems/unicorn-5.3.0/lib/unicorn/http_server.rb:549:in `spawn_missing_workers'
/vendor/bundle/ruby/2.4.0/gems/unicorn-5.3.0/lib/unicorn/http_server.rb:142:in `start'
/vendor/bundle/ruby/2.4.0/gems/unicorn-5.3.0/bin/unicorn_rails:209:in `<top (required)>'
/vendor/bundle/ruby/2.4.0/bin/unicorn_rails:22:in `load'
/vendor/bundle/ruby/2.4.0/bin/unicorn_rails:22:in `<top (required)>'
//.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/cli/exec.rb:74:in `load'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/cli/exec.rb:74:in `kernel_load'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/cli/exec.rb:27:in `run'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/cli.rb:365:in `exec'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/vendor/thor/lib/thor/invocation.rb:126:in `invoke_command'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/vendor/thor/lib/thor.rb:369:in `dispatch'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/cli.rb:22:in `dispatch'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/vendor/thor/lib/thor/base.rb:444:in `start'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/cli.rb:13:in `start'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/exe/bundle:30:in `block in <top (required)>'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/lib/bundler/friendly_errors.rb:121:in `with_friendly_errors'
/.anyenv/envs/rbenv/versions/2.4.1/lib/ruby/gems/2.4.0/gems/bundler-1.15.3/exe/bundle:22:in `<top (required)>'
/.anyenv/envs/rbenv/versions/2.4.1/bin/bundle:22:in `load'
/.anyenv/envs/rbenv/versions/2.4.1/bin/bundle:22:in `<main>'
この呼出し状況を見ているとactiverecordにsaveした後にstore!メソッドが呼び出されて画像の保存が行われるようです。この後callerに引数を与えてcarrierwave側の処理のみを出力してみました。
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/versions.rb:279:in `block in store_versions!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/versions.rb:279:in `block in store_versions!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/versions.rb:279:in `each'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/versions.rb:279:in `store_versions!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/callbacks.rb:16:in `block in with_callbacks'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/callbacks.rb:16:in `each'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/callbacks.rb:16:in `with_callbacks'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/uploader/store.rb:79:in `store!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/mounter.rb:102:in `each'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/mounter.rb:102:in `store!'
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/mount.rb:395:in `store_image!'
そしてcarrierwave側でactiverecordにレコードがsaveされた後初めに実行されたコードがstore_image!というメソッドでした。
/vendor/bundle/ruby/2.4.0/gems/carrierwave-1.1.0/lib/carrierwave/mount.rb:395:in `store_image!'
該当のコード
def store_#{column}!
_mounter(:#{column}).store!
end
Carrierwaveを使用する時の初期設定の時に、コマンドでアップローダをgenerateして、画像を扱いたいモデルにマウントする処理を書きます。mounterという単語を見てそのことが思い浮かびました。
class Photo < ApplicationRecord
# 画像アップローダのマウント
mount_uploader :image, ImageUploader
end
store_マウントしたモデルの画像を扱うカラム名!を実行して画像をstore!しているようなのでその次の呼び出し元のmounter.rbのstore!を確認します。
def store!
if remove?
remove!
else
# 成功、失敗に関わらずこちらの分岐へ
uploaders.each do |uploader|
end
# blankの
uploaders.reject(&:blank?).each(&:store!)
end
end
このif式の中にcallerやloggerを入れて成功する時と失敗する時の処理を比べてみました。
def store!
if remove?
remove!
else
uploaders.each do |uploader|
end
# uploaders.reject(&(:blank?)の中身の構造は全く同じ。
uploaders.reject(&:blank?).each(&:store!)
end
end
このメソッドを実行するまでの処理は同じで変数の中身の構造も同じ。それなのに実行後の処理が違います。失敗した方はこの後carrierwave/uploader/store.rbのstore!メソッドが実行されません。そこでreject(&:blank?)についてもう少し調べてみることにしました。
reject(&:blank?)の&って何のこと?
Rubyで "&" を使うと幸せになれるらしいよ (*´Д`)ノ - (゚∀゚)o彡 sasata299's blog
Rubyで使われる記号の意味(正規表現の複雑な記号は除く) (Ruby 2.2.0)
リンク先の記事によるとProcオブジェクトをブロックに変換してくれるみたいです。プログラミングを始めて間もない人なら同じ気持ちになったことがあると思いますが、わからないことがあって検索すると見つけたページでさらにわからなくなることがあります。今回も例に漏れずProcオブジェクトが何なのかわかりませんでした。
Procとは
レファレンスによると、
ブロックをコンテキスト(ローカル変数のスコープやスタックフ レーム)とともにオブジェクト化した手続きオブジェクトです。
class Proc (Ruby 2.4.0)
Procを調べる最中に参考になったリンク
Procを制する者がRubyを制す(嘘)
RubyのブロックとProcとlambdaとMethodについて - gaaamiiのブログ
class Proc (Ruby 2.4.0)
原因が判明
reject(&:blank?)のうち&はProc オブジェクトをブロックとして使うことがわかりました。rejectは要素の数分繰り返しブロックを実行してブロックの戻り値が真の要素を除いて新しい配列を作成して返すメソッドです。
hoges = ['hoge', 'hogehoge', 'hogehogehoge']
p hoges.reject {|item| item == 'hoge'}
# => ["hogehoge", "hogehogehoge"]
そのことから配列の各要素のいづれかがblankになった時にstore!が実行されずに画像も保存されないのではないかと考えました。そこでビューから画像をアップロードを再度繰り返し、配列に格納してある画像のキャッシュ先ディレクトリとstore!での保存先ディレクトリの両方に画像があるかどうか確認していきました。すると画像のアップロードが失敗する時、store!直前に画像がディレクトリからなくなっていることがわかりました。
通常Carrierwaveでは画像の保存の際にキャッシュ保存も行われ、保存に成功した時にキャッシュした先のディレクトリから画像が削除されます。しかし今回はキャッシュ機能のみを切り離して使っていたので、画像を定期的に削除しなければいけませんでした。
そのためにサーバー側でCronにキャッシュ先ディレクトリの画像を定期削除するスケジュールを組んでいました。
1日ごとに行うつもりだったので自分のミスで1分ごとに行われていました。checkアクション後のリダイレクト先で詳細情報のフォームを1分以上かけて入力していたり、実行のタイミングが偶然フォームの編集中に行われた時に画像が削除されstore!メソッドが実行されていなかったことがわかりました。
まとめ
原因は自分の単純なミスでした。しかし今まで開発をしてきた中でGemの中のソースコードを読む機会がなく、まだまだ自分のレベルでは読めるはずがないと思っていたのを後悔するぐらいソースコードを追って学べることが多く、結果的に良かったなと今では思っています。
以上で終わりになりますが、pryやbyebugを使えばもっと簡単にデバッグが出来るようなので今度ソースコードを見る時に使ってみたいです。また、プログラミングの経験が浅いこともあり誤りや非効率なコードがあるかと思います。何かお気づきの際はコメントにてご指摘お願いします。