LoginSignup
11
6

More than 5 years have passed since last update.

@t__nabe(t__nabe)

RailsでCarrierwaveの意図しない動きの原因を調べるためにGemのソースコードを読む

Last updated at Posted at 2017-09-23

概要

Carrierwaveの画像アップロードで意図しない動きをしたので原因をみつけて解決するためにGemのソースコードを読んでいくことになりました。今回はそのログを残します。

目的

プログラミング初心者が未経験でこの業界に入って学習を始めて6ヵ月。そしてRailsの勉強を始めて4ヵ月程がたちました。Gemのソースコードを読むことにまだまだ敷居の高さを感じていたものの、2日間悩んで問題に取り組んでいるうちにソースコードを追ってどこで自分の意図しない動きをしたのかはっきりさせるしかないということになりました。
Carrierwaveの本来の使い方(READMEに書いてあるような)から外れてしまったため情報も少なく、そのような状況の中取り組んだソースコードリーディングから得られるものが多くありました。

今回は自分と同じようなRailsを学習して間もない方々への共有と自分自身の備忘録を目的としてソースコードを読んでいった過程を残していきます。

開発の環境

問題が起きるまで

画像アップロードしてもらい位置情報を取得します。その後確認画面にリダイレクトして取得した位置情報を元にフォームの初期値に位置情報を入れて問題がなければフォームから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にキャッシュ先ディレクトリの画像を定期削除するスケジュールを組んでいました。

cron の設定ガイド

1日ごとに行うつもりだったので自分のミスで1分ごとに行われていました。checkアクション後のリダイレクト先で詳細情報のフォームを1分以上かけて入力していたり、実行のタイミングが偶然フォームの編集中に行われた時に画像が削除されstore!メソッドが実行されていなかったことがわかりました。

まとめ

原因は自分の単純なミスでした。しかし今まで開発をしてきた中でGemの中のソースコードを読む機会がなく、まだまだ自分のレベルでは読めるはずがないと思っていたのを後悔するぐらいソースコードを追って学べることが多く、結果的に良かったなと今では思っています。

以上で終わりになりますが、pryやbyebugを使えばもっと簡単にデバッグが出来るようなので今度ソースコードを見る時に使ってみたいです。また、プログラミングの経験が浅いこともあり誤りや非効率なコードがあるかと思います。何かお気づきの際はコメントにてご指摘お願いします。

11
6
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
11
6