おもしろwebサービス開発日記

Ruby や Rails を中心に、web技術について書いています

失敗したテストのログだけを出力するぞ

表題の通りのことができるgem、CiLoggerが便利ですよという話です。

私達は大量のテストをCI上で実行しています。テスト結果を見れば失敗理由が自明なものもありますが、E2Eテストなどでよく起きる「たまに失敗するテスト」の調査はログやスクリーンショットなど、可能な限りの情報を集めないと根本原因がつかめないことが多いです。

そんなときに、特に考えずRailsデフォルトの設定(config.log_level #=> :debug)のままにしておくと、膨大なログの中から該当するテストに関連する行を探し当てる作業が必要になります。これは事前の準備なしではほぼ不可能です。

事前の準備として簡単に思いつく方法は、テスト前後で「どのテストが開始/終了したか」をログに出力することです。

config.around do |example|
  Rails.logger.debug("start example at #{example.location}")
  example.run
  Rails.logger.debug("finish example at #{example.location}")
end

これで頑張れば失敗したテストに関連するログを探せるようになりました。が、やってみるとわかるのですが大量のログから該当行を探し当てるのは面倒です。それでも他の方法がなかったので長い間これで運用を続けていました。

そんな折ふと「そもそもCIでほしいのは失敗したテストのログだけであり、他は不要では?」と思いついたのでCiLoggerを作ってみました。このgemの内部ではloggerへの書き込みをいったんメモリ上に保持しておき、テストが失敗したらファイルに書き出す、という処理を行っています。これでしばらく運用してみて、仮説(失敗したログだけあれば良い)が正しそうであることを実感しています。

また、GitHub ActionsやCircleCIなどはArtifactの容量によって課金されるので、CiLoggerを使うとそれらの料金を抑えられるのもメリットです。よければ使ってみてください。

注意点

現時点(v0.3.0)ではRSpecのみに対応しています。minitestで使いたい人はPRお願いします :pray:

余談

開発当初は、CiLoggerを使うとログファイルへの書き込み量が減るので速度改善効果もあるだろうと想定していたのですが、少なくとも僕が測定した限りでは優位な速度差が出ませんでした。CiLoggerを使わずにlog_level:errorにしても速度差が出なかったので、計測方法が悪いのかなにか見落としがあるのか…。知見ある人いたら教えて下さい><

iCARE Dev Meetup #34で登壇しました

【iCARE Dev Meetup #34】10年続くRailsアプリ開発のために大事なこと - connpass

所感

長期間アプリケーションを無理なく運用していくには内部品質を一定以上に保つ必要があり、それに注力するためには発表で話した「ふつうのこと」に対するエンジニアをはじめとした会社全体の理解が大事なので僕たちは頑張ってコミュニケーションとっていきましょう、そしてふつうを普通にやっていきましょうということが言いたかったのですが、それだけだとRails風味が0なのと抽象的かつ実現が困難な話に終止してしまうので、推しgem(ViewComponent)の紹介を追加して具体的なRails味を出してみました。

どの会社の発表も、みんな泥臭く汗をかいて頑張っているんだな、というのが伝わり自分もやっていくぞ!という気持ちが高まる良い発表でした!今日もやっていきます(\( ⁰⊖⁰)/)

`Thread.current[:hoge]`はスレッドローカル変数を参照していると思いきや実際はファイバーローカル変数だった

このエントリはSmartHR Advent Calendar 2021の23日目の記事です。

SmartHRでは毎週「Rubyist@SmartHR(仮)」という名の定例ミーティング*1が行われています。このミーティングはバックエンドエンジニアが集まり、チームをまたいだ情報共有や相談をすることを目的としています。その中では僕がTipsなどを共有する「willnetさんのありがたいお言葉」というコーナーが常設されています。

このエントリでは、そのコーナーで共有した内容をひとつ紹介します*2

Thread#[]で取得できる値はファイバーローカル変数なのだった

アプリケーションのコードではあまり見かけませんが、ライブラリ中でスレッドセーフを意識している設定を読むと

Thread.current[:locale] = :ja

のようになっているのをよく見かけます。それで僕はThread#[]はスレッドローカル変数を返すのだな、と長年思いこんでいたのですがそれは大きな勘違いでした。Thread#[]=で設定した値はファイバーを切り替えると参照できなくなってしまいます。

検証用コード

require 'fiber'

f = Fiber.new do
  Thread.current[:locale] = :ja
  puts 'in another fiber'
  puts "locale: #{Thread.current[:locale]}"
end

f.resume

puts 'in main fiber'
puts "locale: #{Thread.current[:locale]}"

実行結果

in another fiber
locale: ja
in main fiber
locale: 

ではファイバーを切り替えても同一スレッドであれば同じ値を返すようにしたいときにはどうすればよいでしょうか?

スレッドローカル変数を扱いたいときは別のメソッドを使う

Thread#thread_variable_getThread#thread_variable_setを使います。

検証用コード

require 'fiber'

f = Fiber.new do
  Thread.current.thread_variable_set(:locale, :ja)
  puts 'in another fiber'
  puts "locale: #{Thread.current.thread_variable_get(:locale)}"
end

f.resume

puts 'in main fiber'
puts "locale: #{Thread.current.thread_variable_get(:locale)}"

実行結果

in another fiber
locale: ja
in main fiber
locale: ja

よく読むとるりまにもちゃんと書いてありますね…。

Thread#[]Thread#[]= を用いたスレッド固有の変数は Fiber を切り替えると異なる変数を返す事に注意してください。

それがどうしたんですか?

Rails6.1までは、恐らくスレッドローカル変数のつもりでファイバーローカル変数(Thread#[], Thread#[]=)が使われている箇所がありました。例えばCurrentAttributesの設定値はファイバーローカル変数を使っています。

rails/current_attributes.rb at f0506126cb98616444b359162361d2aaaa329f46 · rails/rails

これは、たとえばpumaのようなスレッドベースのアプリケーションサーバのどこかで複数のファイバーを使っていると問題になります。ファイバーAで設定したファイバーローカル変数は(当たり前ですが)ファイバーBでは見えません。これは期待している挙動ではないでしょう。

いまどきのよくあるRailsアプリケーションでは明示的に複数ファイバーを使うことはあまりなさそうに思えます。が、例えば内部でファイバーを使っているgemに依存性があるかもしれません。また、明示的にファイバーを使わなくてもEnumeratorで外部イテレータを使っているところではファイバーが使われています(参考: class Enumerator (Ruby 3.0.0 リファレンスマニュアル) )。外部イテレータもいまどきのよくあるRailsアプリケーションで明示的に使われることは少なそうですが、これも依存しているgemで採用されている可能性はあります。

下記のコードは外部イテレータでファイバーローカル変数とスレッドローカル変数をアサインしたあとに参照したサンプルコードです。アサインしたはずのファイバーローカル変数が参照できていない事がわかります。

o = Object.new
def o.each
  yield Thread.current[:fiber_local] = 'hi'
  yield Thread.current.thread_variable_set(:thread_local, 'hihi')
end

e = o.to_enum
e.next #=> 'hi'
e.next #=> 'hihi'
Thread.current[:fiber_local] #=> nil
Thread.current.thread_variable_get(:thread_local) #=> 'hihi'

まれに問題になりそうなのはわかったけど…それで?

素直に考えるとRailsの内部でファイバーローカル変数を使っている箇所をスレッドローカル変数に変更すれば良いように思えます。が、みんながスレッドベースのアプリケーションサーバを使っているとは限らないのでした。falconなどのファイバーベースのアプリケーションサーバを使いたい人たちにとってはファイバーローカル変数でないと困ります。

そこで、Rails7.0からは、設定としてスレッドローカル変数を使うかファイバーローカル変数を使うか選択できるようになりました。

Introduce ActiveSupport::IsolatedExecutionState for internal use · rails/rails@540d2f4

デフォルトでは:threadが設定されているので、pumaなどのスレッドベースのサーバを使っている人はRails7.0に上げれば問題は起きなくなりそうです。falconを使いたい人は下記のように明示的にfiberを使うようにする必要があります。

Rails.application.config.active_support.isolation_level = :fiber

そんなすぐRails7.0にあげられないぞ、という人はそれっぽい問題が起きたときにこのことを思い出せるようにしておいてください。そして早く7.0にできるように頑張りましょう。

まとめ

  • Rubyでのスレッドローカル変数とファイバーローカル変数の違い
  • 関連したRailsでの問題と解決の事例

について書きました。

Rails本体に関してはRails7.0以降は問題が起きなさそうですが、他のgemでスレッドローカル変数を意図してThread.current#[]=を使っていそうなところがちらほらあり、ちゃんと考えると何らかの対応(ex: Railsのように設定でスレッドローカルとファイバーローカルを切り替える)をしないといけないんだろうなーという気がしています(が、全てのgemで対応するのはなかなか難しそうですね…)。

*1:バックエンドミーティングやバックエンド定例とも呼ばれています

*2:ちなみに去年のアドベントカレンダーも同じように同じようにありがたいお言葉コーナーからの切り出し記事でした https://blog.willnet.in/entry/2020/12/11/100000

Rack::RuntimeがRailsのデフォルトRackミドルウェアから削除された

Rack::RuntimeというRackミドルウェアがあります。これはリクエストを処理するのにかかった時間を"X-Runtime"というレスポンスヘッダに含める、というものです。コードはこれ↓

rack/runtime.rb at master · rack/rack

これはRailsのデフォルトのRackミドルウェアであり、特に何もしない限り有効になっています。

このX-Runtimeが、タイミング攻撃で使われている事例があったとのことで、デフォルトから削除になりました。

Remove Rack::Runtime and deprecate referencing it · rails/rails@7bfcf4b

これにより、明示的にRack::Runtimeをミドルウェアで使う宣言をしない限りはRack::Runtimeは使えなくなります(Rails7.0から)。

実際にはX-Runtimeの値を見なくても、レスポンスが帰ってくる時間を計測すれば(ネットワークを経由することによる多少の誤差はありつつも)タイミング攻撃はできてしまうのでRack::Runtimeの削除の効果は限定的です。しかし普段の開発で使ってないならRails7.0を待たずに削除しておくのがいいんじゃないかな、と個人的には思っています。↓のコードでデフォルトRackミドルウェアから消せるので、消したい方はこれで消してみてください。

# config/application.rb

config.middleware.delete Rack::Runtime

追記

削除のコミットがrevertされたので結局Rails7.0でも使えます。revertされたのは上の方で書いた

レスポンスが帰ってくる時間を計測すれば(ネットワークを経由することによる多少の誤差はありつつも)タイミング攻撃はできてしまうのでRack::Runtimeの削除の効果は限定的です

が理由のようです

Add back Rack::Runtime to the default middleware stack. · rails/rails@4ace047

Gimeiのバージョン1.0.0をリリースした

から、そろそろ1.0.0にしてもいいんじゃないかな、という気持ちになり1.0.0のリリースに踏み切りました。

ランダムで名前を返す、というコアな機能は最初のリリースからほぼ変わってないのですが

  • 住所も返せる(ex: Gimei.address)
  • テスト内でユニークな名前が返ることが保証できる記法がある(ex: Gimei.unique.name)
  • 名前と住所のデータを遅延読み込みするようになった

などなど、8年で地味に着実に改善が進んでいます。どうぞご利用ください。

willnet/gimei: random Japanese name and address generator

iCARE Dev MeetupでHotwireについて話した

僕がお手伝いしているiCAREさん主催のミートアップ、iCARE Dev Meetupで、最近発表されたBasecamp社製jsフレームワークであるHotwireについて話しました。

【iCARE Dev Meetup #18】技術顧問が語る、Ruby on Rails実践開発 - connpass

動画も公開されているので気になる方は探してみてください*1

所感

弊社サービスであるsavanna.ioはHotwireを使って作っています。Hotwireはつい最近発表されましたが、その前身となるフレームワークであるturbolinksStimulusの組み合わせで数年間開発していました。

なので「サーバサイドはHTMLを返し、jsは最小限」というスタイルが少人数で開発するチームにとてもマッチすることは身を持って体験しています。Vue.jsやReactを採用していたら機能を開発するスピードはもっと遅かったに違いありません。

もちろん適材適所なのでHotwireが適さない分野もありますが、Hotwireが適しているのに無理して他のjsライブラリを使っているプロジェクトはたくさんあるんじゃないかなあ…と推測しています。この発表でちょっとでもそんなプロジェクトが減りみんながハッピーになると嬉しいです(\( ⁰⊖⁰)/)

*1:恥ずかしいのでリンクは貼らない

TurbolinksからTurboへの移行

弊社サービスである savanna.io はずっとTurbolinksStimulusで開発してきたのですが、この度 Hotwireがリリースされた*1のでTurbolinks部分をTurboに置き換えてみました。その際のやったことやハマったことのメモを残しておきます。メモ書きなので雑なのはご容赦ください。

前提

webpackerを使ってます。assets pipeline派や素のwebpackを利用している人は適宜読み替えてください

TurbolinksのアンインストールとTurboのインストール

  • turbo-railsをGemfileに追加してbundle install
  • ./bin/rails turbo:installをする

で問題なくいけるのであればそれで。turbo:installが失敗したらturbo-rails/turbo_with_webpacker.rb と同等のことを手動でやればOKです。savanna.io ではTypeScriptを利用しているためうまくいきませんでした(turbo:install はapp/javascript/application.jsがあることを前提としている)。

turbolinksをturboに置換する

document.addEventListener('turbolinks:load', ...のようにしている箇所をdocument.addEventListener('turbo:load', ...に置換します。

turbolinks-cache-controlなどは、Turboのドキュメントには書いてありませんがTurboのコードをみたらturbolinksの箇所をturboに書き換えるだけで問題なさそうだったのでそのようにしたら動作しました。多分turbolinksでできることはturboのドキュメントに書いてなくてもできるんじゃないかな…(未確認)。

OAuthログインの対応

savanna.ioはOAuthによるログインに対応しています。omniauthのCSRF脆弱性に対応できるように、しばらく前から次のようにPOSTを利用するようにしていました。

= link_to 'twitterにログイン', '/auth/twitter', method: :post

このコードで生成したリンクにアクセスするとうまく遷移できません。これは、Turboからはformも非同期対象になったのが原因です。twitterのログイン用URLをfetchしようとしてpreflightリクエストでエラーになっていました。

Turboはdata-turbo=false属性をつけることで特定のリンクやformをTurbo非対応にすることができます。

しかし、上記のlink_toにmethodオプションをつけたものについてはうまくdata-turbo=false属性をつけることができません。methodオプションがついているリンクをクリックするとrails-ujsが自動的にformを作りsubmitする、という実装になっています。つまり自動で生成されるformに対してdata-turbo=falseを付ける必要があるのですが、これを行うためのAPIがありません。

なのでlink_toをbutton_toに変更して対応しました。

= button_to('/auth/twitter') { 'Twitterでログイン'  }

バリデーションエラー時の対応

TurboはTurbolinksでは未対応だったformのsubmitに対応しています。data-remote=trueなformでなくとも自動でfetchを使い非同期でPOSTします。

バリデーションエラー時に422などのステータスコードを返すと、URLはそのままの状態で画面の差し替えが行われます。つまり普通に(scaffoldで生成したようなアクションの形で)バリデーションエラーのメッセージを含む画面を描画できるようになりました。

Turbo方式とTurbolinks方式を混在させる

savanna.io では ajax_error_rendererというgemを使いSJRでエラーメッセージを差し込む、ということをやっているのでそれを普通のエラーメッセージ用のHTMLを返すように変更する必要があります。

すべてのアクションを一気に変更するのは大変なので、徐々に切り替えられるように、Turbo方式とTurbolinks方式を混在させられるような仕組みを作りました。

Turbolinksはrails-ujsによるajaxでPOSTをする想定です。そのときredirectをしたらTurbolinks.visit()を実行するようにサーバからレスポンスを返します。これをturbolinks-railsというgemが実現していました。次のコードは、turbolinks-railsと同等のことをTurboで実現するようにしています。このように書くと、data-remote=trueなformからPOSTしたときはturbolinksの挙動で、それ以外はTurboの挙動になります。

# ApplicationController
  def redirect_to(...)
    super.tap do
      visit_location_with_turbo(location) if request.xhr? && !request.get? && !request.format.turbo_stream?
    end
  end

  def visit_location_with_turbo(location)
    visit_options = { action: 'replace' }

    script = []
    script << 'Turbo.clearCache()'
    script << "Turbo.visit(#{location.to_json}, #{visit_options.to_json})"

    self.status = 200
    self.response_body = script.join("\n")
    response.content_type = 'text/javascript'
    response.headers['X-Xhr-Redirect'] = location
  end

request.format.turbo_stream?がtrueのときはTurboからのリクエスト経由のリダイレクトなのでなにもしない(通常のredirect_to)ようにしています。

// application.ts
import { Turbo } from '@hotwired/turbo-rails'
window.Turbo = Turbo

Turboはwebpack環境ではglobalではないので明示的にglobal変数として扱えるようにする必要があります。

Turboではバリデーションエラー時にturbo:loadが発火しない

これであとは頑張ってバリデーションエラー時の処理を置き換えていくだけ…と思いきやそんなことはありません><バリデーションエラー時にturbo:loadが発火しないという現象に遭遇しました。https://github.com/hotwired/turbo/issues/85 を見た限りこれは仕様とのことです…。

savanna.ioではturbo:loadがすべてのページ表示のタイミングで発火するのを期待しているコードがあったので、検討した結果、上記の「Turbo方式とTurbolinks方式を混在させる」で書いたやり方は不採用にしました*2

結局、turbo-streamを利用するとajax_error_rendererと使用感がほぼ同じになるのでturbo-streamでエラーメッセージを差し込むようにしました。次のようにしてrender_errors_by_turbo_streamを呼び出すと<div id="erorr"></div>にエラーメッセージが差し込まれます。

  def render_errors_by_turbo_stream(model:)
    render turbo_stream: turbo_stream.update(:error, partial: 'errors', locals: { model: model }),
           status: :unprocessable_entity
  end
- unless model.errors.empty?
  #error_explanation.alert.alert-danger.error-messages
    %ul
      - model.errors.full_messages.each do |msg|
        %li= msg

[コラム]バリデーションエラー時のリロードの処理

バリデーションエラー時にブラウザをリロードしたときの挙動はTurbo使用時とそうでないときとで違いがあります。Turbo使用時はformのページがリロードされます。Turbo未使用時は「フォームの内容を再送しますか?」といったダイアログが表示されます。

これはHistroy APIを利用している以上仕方がない*3ですが、Turbolinksのときと比べるとだいぶ改善された感じがあります。Turbolinks利用時かつdata-remote=trueなしなフォームのときは、newアクションのformにいるはずがリロードするとindexアクションにアクセスしてしまう、という事が起きていました。

参考: Turbolinks5でPOSTするときはajax経由のほうが良いのかも - おもしろwebサービス開発日記チラシの裏

data-disable-withに対応する

turbo-streamを使うと動的にエラーメッセージを差し込むことができてめでたしめでたし、かと思いきや、バリデーションエラー時にsubmitボタンがdisableのまま、という状況に遭遇しました。

form_withなどでajaxを利用してPOSTしたとき、ajax終了時に自動でdisable状態を解除するようにrails-ujsで定義されています。turboはrails-ujsを利用していないので、独自で対応する必要があります。次のように、フォームsubmit後のバリデーションエラーで、rails-ujsのdisable状態を解除するためのメソッドを呼び出すようにしました。

document.addEventListener('turbo:submit-end', (event: Event) => {
  if (!event.detail.success) {
    Rails.enableElement(event.detail.formSubmission.formElement)
  }
})

assets precompileの対象から外す

turbo-railsは今のところassets precompileできるなら、turboをその対象として自動で挿入するという仕様になっています。savanna.io は基本webpackerなのですがassetsを使っているgem(administrate)があるのでassets pipelineはオフにしていません。そしてturbo-railsが提供しているjsはES6の書き方なので、本番デプロイ時にuglifierによる圧縮処理で失敗しました。そもそもassetsとして提供されているjsは使わないので、次のようにして対処しました。

# config/application.rb

config.after_initialize do
  config.assets.precompile -= ['turbo']
end

その他turbolinksやrails-ujsに依存している処理を書き換える

あとは細かい変更なので概要だけ書いておきます。

  • turbolinks化でgoogle-analyticsを使うために google-analytics-turbolinkというgemを使っていたのをやめた
  • 「保存されていない変更があります。移動してよろしいですか?」を実装するためにrails-ujsのイベントをhookしていたのをturboのイベントにフックするようにした

まとめ

  • ここまで見てきたように、TurbolinksからTurboの移行に関してはそれなりにハマりどころがあります
  • ただ明らかにTurbolinks時代から改善が進んでいて体験が良くなっているので、気になっている人は一度試してみるのをおすすめします

*1:厳密には現時点で7.0.0-beta.4です

*2:便利に使う人もいるかと思うので書き残しています

*3:History APIはGETしか対応していない