save で例外が発生したらどうなる？

今回は save / update_attributes の中で例外が発生したときの挙動を実機確認してみます。

前回↓
[acts_as_votable の upvote_by / downvote_by はエラーハンドリングすべきか？](https://qiita.com/morikiyo/items/e606ba4f2b1b5bb7e4f6)

## TL; DR

例外がとんでくる。(ただし ActiveRecord::RecordInvalid を除く)
トランザクションは rollback される。

## 調査環境

* macOS Mojave 10.14.4
* Ruby 2.6.3
* Rails 5.2.3 + SQLite3

### テストコード

動作確認用に適当な scaffold を追加します。

```bash
$ bin/rails g scaffold post title:string body:text
```

コールバックの動作確認用に以下のコードを追加します。

<details><summary>追加したコード</summary><div>

```ruby:app/controllers/posts_controller.rb
  def test_clear
    @posts = Post.all
    if @posts.empty?
      flash[:notice] = 'posts is empty'
      return redirect_to posts_url
    end

    ActiveRecord::Base.transaction do
      @posts.each do |post|
        post.body = post.body.gsub(/\(TEST (SAVE|UPD_ATTR)!\)/, '').rstrip
        post.save!
      end
      flash[:notice] = 'test_clear was completed.'
    end

    redirect_to posts_url
  end

  def test_save
    @posts = Post.all
    if @posts.empty?
      flash[:notice] = 'posts is empty'
      return redirect_to posts_url
    end

    ActiveRecord::Base.transaction do
      @posts.each do |post|
        post.body += ' (TEST SAVE!)'
        unless post.save
          flash[:notice] = 'post.save returns false'
          raise ActiveRecord::Rollback
        end
      end

      flash[:notice] = 'test_save was completed.'
    end

    redirect_to posts_url
  end

  def test_update_attributes
    @posts = Post.all
    if @posts.empty?
      flash[:notice] = 'posts is empty'
      return redirect_to posts_url
    end

    ActiveRecord::Base.transaction do
      @posts.each do |post|
        new_body = post.body + ' (TEST UPD_ATTR!)'
        unless post.update_attributes({ body: new_body })
          flash[:notice] = 'post.update_attributes returns false'
          raise ActiveRecord::Rollback
        end
      end

      flash[:notice] = 'test_update_attributes was completed.'
    end

    redirect_to posts_url
  end
```

```erb:app/views/posts/index.html.erb
<hr>
<%= link_to 'TEST CLEAR', test_clear_posts_path, method: :post %> |
<%= link_to 'TEST SAVE', test_save_posts_path, method: :post %> |
<%= link_to 'TEST UPD ATTR', test_update_attributes_posts_path, method: :post %>
```

```ruby:config/routes.rb
 resources :posts do
   collection do
     post :test_clear
     post :test_save
     post :test_update_attributes
   end
 end
```
</div></details>

今回はトランザクションブロックの動きもあわせて確認したかったので、複数レコードの一括更新処理を行うアクションを追加しました。

適当なデータを追加しておきます。

<img width="752" alt="スクリーンショット 2019-05-22 17.48.48.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/54e69573-1531-2acb-c52b-973d96795d4b.png">

TEST SAVE リンクで `"(TEST SAVE!)"` が、TEST UPD ATTR リンクで `"(TEST UPD_ATTR!)"` が全データの body に追加されます。TEST CLEAR リンクで追加したテキストがクリアされます。

<details><summary>実行結果のスクリーンショット</summary><div>

<img width="752" alt="スクリーンショット 2019-05-22 17.49.15.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/8283fefc-094b-c381-c3dc-a6f3c5b9b5d4.png">
<img width="752" alt="スクリーンショット 2019-05-22 17.49.19.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/0d112d52-b20e-b992-beda-ca71ecea022a.png">
<img width="752" alt="スクリーンショット 2019-05-22 17.49.23.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/ee8de684-1f5e-9ba2-3d54-6cdb9e0ee420.png">

</div></details>


## 調査内容

### DB例外が発生したとき

SQLite ファイルに直接アクセスして更新対象のレコードをロックし、タイムアウトエラーを発生させてみます。

```sql
begin deferred transaction;
select * from posts; -- posts の全レコードが更新ロックされる
```

〜 実行結果 〜
<img width="752" alt="スクリーンショット 2019-05-22 18.00.33.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/136dfadb-5f78-2589-4627-892699a83dfb.png">
<details><summary>log/development.log</summary><div>

```shell-session
Started POST "/posts/test_save" for 127.0.0.1 at 2019-05-22 17:59:59 +0900
Processing by PostsController#test_save as HTML
  Parameters: {"authenticity_token"=>"A4jc+d8LfjFJgzJZYK7XjySuEq2s5MSoTJtWChKfMS
CRwUJmRNs1g1u2El0KKl+4zBaQtVR1l5DHlJ9KDmytGQ=="}
  Post Exists (0.3ms)  SELECT  1 AS one FROM "posts" LIMIT ?  [["LIMIT", 1]]
  ↳ app/controllers/posts_controller.rb:84
   (0.1ms)  begin transaction
  ↳ app/controllers/posts_controller.rb:89
  Post Load (0.1ms)  SELECT "posts".* FROM "posts"
  ↳ app/controllers/posts_controller.rb:90
  Post Update (0.3ms)  UPDATE "posts" SET "body" = ?, "updated_at" = ? WHERE "po
sts"."id" = ?  [["body", "aaa (TEST SAVE!)"], ["updated_at", "2019-05-22 08:59:5
9.286903"], ["id", 2]]
  ↳ app/controllers/posts_controller.rb:92
  Post Update (0.1ms)  UPDATE "posts" SET "body" = ?, "updated_at" = ? WHERE "po
sts"."id" = ?  [["body", "bbb (TEST SAVE!)"], ["updated_at", "2019-05-22 08:59:5
9.287876"], ["id", 3]]
  ↳ app/controllers/posts_controller.rb:92
  Post Update (0.1ms)  UPDATE "posts" SET "body" = ?, "updated_at" = ? WHERE "po
sts"."id" = ?  [["body", "ccc (TEST SAVE!)"], ["updated_at", "2019-05-22 08:59:5
9.288542"], ["id", 4]]
  ↳ app/controllers/posts_controller.rb:92
   (5136.4ms)  commit transaction
  ↳ app/controllers/posts_controller.rb:89
   (0.4ms)  rollback transaction
  ↳ app/controllers/posts_controller.rb:89
Completed 500 Internal Server Error in 5144ms (ActiveRecord: 5137.7ms)



ActiveRecord::StatementInvalid (SQLite3::BusyException: database is locked: comm
it transaction):

app/controllers/posts_controller.rb:89:in `test_save'
```

</div></details>

save / update_attributes どちらも同じ例外で、500 Internal Server Error となりました。

ログを見ると、UPDATE ステートメントが全レコード分処理されて commit が要求されたタイミングでDB例外が発生し rollback しているのがわかって興味深いです。

確認したらロックしたレコードを解放しておきます。

```sql
rollback;
```

### コールバックメソッドで例外が発生したとき

モデルに before_save コールバックメソッドを追加して、その中で例外をおこすようにしてみます。

```ruby:app/models/posts.rb
  before_save :test
  def test
    raise 'Test exception was raised.'
  end
```

〜 実行結果 〜
<img width="752" alt="スクリーンショット 2019-05-23 21.26.10.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/e4613a76-6501-a668-247a-2ff80e9c8890.png">
<details><summary>log/development.log</summary><div>

```shell-session
Started POST "/posts/test_save" for 127.0.0.1 at 2019-05-23 21:25:58 +0900
Processing by PostsController#test_save as HTML
  Parameters: {"authenticity_token"=>"uUwP5SQZYTEm138h/CxPM7hd8lyxfG3JEMyL0dugqvvH7S8VXB3ONwX29uGKPuIDVJBKnPUcCEl1uKFyXhZSGw=="}
  Post Exists (0.1ms)  SELECT  1 AS one FROM "posts" LIMIT ?  [["LIMIT", 1]]
  ↳ app/controllers/posts_controller.rb:84
   (0.1ms)  begin transaction
  ↳ app/controllers/posts_controller.rb:89
  Post Load (0.2ms)  SELECT "posts".* FROM "posts"
  ↳ app/controllers/posts_controller.rb:90
   (0.1ms)  rollback transaction
  ↳ app/controllers/posts_controller.rb:89
Completed 500 Internal Server Error in 19ms (ActiveRecord: 1.0ms)



RuntimeError (Test exception was raised.):

app/models/post.rb:4:in `test'
app/controllers/posts_controller.rb:92:in `block (2 levels) in test_save'
app/controllers/posts_controller.rb:90:in `block in test_save'
app/controllers/posts_controller.rb:89:in `test_save'
```
</div></details>

save / update_attributes どちらも同じ例外で、500 Internal Server Error となりました。

ちなみに ActiveRecord::RecordInvalid は rescue されて false が戻ります。

```ruby:app/models/posts.rb
  before_save :test
  def test
    raise ActiveRecord::RecordInvalid
  end
```

〜 実行結果 〜
<img width="752" alt="スクリーンショット 2019-05-23 21.30.02.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/664e5b73-35b8-455c-c5b1-3ee15ec9f6bd.png">
<details><summary>log/development.log</summary><div>

```shell-session
Started POST "/posts/test_save" for 127.0.0.1 at 2019-05-23 21:29:55 +0900
Processing by PostsController#test_save as HTML
  Parameters: {"authenticity_token"=>"uUwP5SQZYTEm138h/CxPM7hd8lyxfG3JEMyL0dugqvvH7S8VXB3ONwX29uGKPuIDVJBKnPUcCEl1uKFyXhZSGw=="}
  Post Exists (0.1ms)  SELECT  1 AS one FROM "posts" LIMIT ?  [["LIMIT", 1]]
  ↳ app/controllers/posts_controller.rb:84
   (0.0ms)  begin transaction
  ↳ app/controllers/posts_controller.rb:89
  Post Load (0.1ms)  SELECT "posts".* FROM "posts"
  ↳ app/controllers/posts_controller.rb:90
   (0.1ms)  rollback transaction
  ↳ app/controllers/posts_controller.rb:89
Redirected to http://localhost:3000/posts
Completed 302 Found in 22ms (ActiveRecord: 1.0ms)
```

</div></details>

save / update_attributes どちらも戻り値が false になりました。


### 蛇足: コールバックメソッドの throw(:abort) と return false

コールバックによる中断方法が Rails5 で変更されたようなので、ついでに試してみます。
(参考) [Railsアップグレードガイド - Rails ガイド](https://railsguides.jp/upgrading_ruby_on_rails.html#throw-abort-%E3%81%A7%E3%82%B3%E3%83%BC%E3%83%AB%E3%83%90%E3%83%83%E3%82%AF%E3%83%81%E3%82%A7%E3%83%BC%E3%83%B3%E3%82%92%E5%81%9C%E6%AD%A2%E3%81%99%E3%82%8B)

`throw(:abort)` の場合

```ruby:app/models/posts.rb
  before_save :test
  def test
    throw(:abort)
  end
```

〜 実行結果 〜
<img width="708" alt="スクリーンショット 2019-05-23 21.04.28.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/c3f1b749-9070-c235-fc13-4b63dfb2337e.png">

save / update_attributes どちらも戻り値は false になります。

`return false` の場合

```ruby:app/models/posts.rb
  before_save :test
  def test
    false
  end
```

〜 実行結果 〜
<img width="752" alt="スクリーンショット 2019-05-23 21.07.23.png" src="https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/341937/82c7fd18-9df0-f9d4-2d74-a7631ff8b84e.png">

save / update_attributes どちらも正常に更新処理が完了します。


## おわりに

予想していたとおりの結果になってホッとしました。実際に動かしてみると知識が深まって自信がつくので、やってみてよかったです。

ただ、結構時間がかかりました。active_record のソース読んでる時間と、この記事を書いてる時間が8割くらいですけど。もっとサクサクアウトプットできるといいなぁ。