モンモンブログ

技術的な話など

rake task で bullet を使って N+1 問題を検出

N+1 問題を検出する bullet は、rake タスクではそのままでは動作しないです。

各 rake タスクの最初と最後に Bullet を開始・終了する記述を追加する必要があります。こんな風に。

$ vi lib/tasks/hoge.rake
namespace :hoge do
  task :hoge => :environment do |_task|
    # Bullet開始
    Bullet.start_request

    # rakeタスク本体 〜N+1問題を添えて〜
    Shop.limit(3).each do |shop|
      puts shop.items.map(&:name).to_s
    end

    # Bullet終了
    Bullet.perform_out_of_channel_notifications if Bullet.notification?
    Bullet.end_request
  end
end

こんなのいちいち全タスクに書きたくないですよね。

なので全タスクの開始時・終了時に呼ばれる hook を定義して、その中で Bullet を開始・終了させようと思います。

lib/tasks/hooks.rake(ファイル名はなんでもいいです)に、以下のような2つのタスクを定義します。それぞれ、rake タスク開始時と終了時に呼ばれる hook です。

$ vi lib/tasks/hooks.rake
desc 'rakeタスク開始時のhook'
task before_hook: :environment do
  # Bullet開始
  Bullet.start_request
end

desc 'rakeタスク終了時のhook'
task after_hook: :environment do
  at_exit do
    # Bullet終了
    Bullet.perform_out_of_channel_notifications if Bullet.notification?
    Bullet.end_request
  end
end

これらの hook を他の全タスクの開始時・終了時に呼ぶように Rakefile に追記します。

$ vi Rakefile
require_relative "config/application"

Rails.application.load_tasks

# ↓ここから追記

# タスク実行前後の共通処理を追加
Rake.application.tasks.each do |task|
  next if %w[before_hook after_hook environment].include?(task.name)
  task.enhance([:before_hook, :after_hook])
end

最初に載せた N+1 な rake タスクからは Bullet 開始・終了の記述を削除できます。

$ vi lib/tasks/hoge.rake
namespace :hoge do
  task :hoge => :environment do |_task|
    # rakeタスク本体 〜N+1問題を添えて〜
    Shop.limit(3).each do |shop|
      puts shop.items.map(&:name).to_s
    end
  end
end

この状態で実行してみましょう。

$ bundle exec rake hoge:hoge

↓のようにログが吐かれて、ちゃんと N+1 問題が検出できるようになりました。

$ tail -0f log/bullet.log
2023-03-30 07:18:41[WARN] user: root

USE eager loading detected
  Shop => [:items]
  Add to your query: .includes([:items])
Call stack
  /app/src/lib/tasks/hoge.rake:5:in `map'
  /app/src/lib/tasks/hoge.rake:5:in `block (3 levels) in <main>'
  /app/src/lib/tasks/hoge.rake:5:in `block (2 levels) in <main>'

やったね。

【シェルスクリプト】Ctrl-C で実行中のジョブを突然殺すことなく、ジョブの終了をちゃんと待ちたい

動画のエンコードのような「時間のかかる処理」をループ内で繰り返し実行するようなシェルスクリプトを書いた場合、

Ctrl-C でいきなり終了するのではなく、現在実行中の「時間のかかる処理」が終わってから終了するようにしたい、て場合があるかと思います。

trap コマンドで SIGINT (Ctrl-C) をトラップしてゴニョゴニョすればできそうですが、それだけだと「時間のかかる処理」は Ctrl-C を受け取って終了してしまいます。

じゃあどうするかというと、こう。

#!/usr/bin/env sh

# なにやら時間のかかる処理を定義
heavy_task () {
    sleep 3
}

# SIGINT (Ctrl-C) を受け取ったら interrupted 変数に値を代入
trap "echo "Ctrl-C をトラップ"; interrupted=1" INT

# ループ開始
while true; do
    echo "処理開始…"
    # なにやら時間のかかる処理を「バックグラウンドで」実行
    heavy_task &
    # バックグラウンドで起動したコマンドの終了を wait $! で待機。
    # なおかつ、wait コマンドがシグナルにより終了させられたらすかさず再wait
    while wait $!; [ $? -ge 128 ]; do
        :
    done
    # 時間のかかる処理が終了
    echo "終了!"
    # interrupted 変数に値が代入されてたらループを抜ける
    if [ -n "$interrupted" ]; then
        break
    fi
done
echo "bye!"

この中でポイントはここでしょうか。ちょっとブレークダウンして説明します。

    while wait $!; [ $? -ge 128 ]; do
        :
    done

$! は直前に起動したバックグラウンドプロセスのPID。wait $! とすることで、バックグラウンドジョブとして起動した heavy_task が終了するのを待機することになります。

待機中、もしユーザーが Ctrl-C をタイプすると wait がそれを受け取って終了してしまうのですが、その時の終了コードが 128 + SIGINTの番号 になります。これはシェルの仕様です。

$ man bash
…
    The return value of a simple command is its exit status, or 128+n if
    the command is terminated by signal n.

    ざっくり訳:コマンドがシグナル n により終了した場合、終了コードは 128 + n になる
…

wait の終了コード $? が 128 より大きいかチェックすれば ([ $? -ge 128 ] ) 、シグナルによる終了なのか、それとも単に heavy_task が無事完了した結果 wait が終了したのか、区別できるわけです。

シグナルによる終了だった場合は即 wait し直しているので、heavy_task が終わるまで待ち続けられます。

同時に、Ctrl-C を trap コマンドで検知して interrupted 変数に値を代入し、その内容をループの最後でチェックすることで、ループを抜けるべきか続けるべきか判断しています。

応用編:Ctrl-C 2回で強制終了

さらに拡張して、2回 Ctrl-C したら有無を言わさず強制終了するようにしたのがこちら。

#!/usr/bin/env sh

heavy_task () {
    sleep 3
}

# SIGINT (Ctrl-C) を受け取ったら1回目は interrupted 変数に、2回目以降は force_finish 変数に値を代入
function sigint_handler () {
    if [ -z "$interrupted" ]; then
        echo "実行中の処理の完了後に終了します(もう1度 ^C で強制終了)"
        interrupted=1
    else
        echo "強制終了!"
        force_finish=1
    fi
}
trap sigint_handler INT

while true; do
    echo "処理開始…"
    heavy_task &
    while wait $!; [ $? -ge 128 ]; do
        # trap により force_finish 変数に値が代入されていたら「強制終了」の指示とみなす
        if [ -n "$force_finish" ]; then
            # 実行中の heavy_task を kill
            if ps $! >/dev/null; then
                kill $!
            fi
            break
        fi
    done
    echo "終了!"
    if [ -n "$interrupted" ]; then
        break
    fi
done
echo "bye!"

便利!

Appium でスマホアプリを実機テストしてたらスマホのキーボードが使えなくなった

モバイルアプリの E2E テストフレームワークの Appium (https://appium.io/) で実機テストしてたら、キーボードが使えなくなるという問題にぶち当たりました。

スマホを再起動しても直りません。

再現条件までは調べられてないですが、同じ問題に遭遇した人の助けになればと思い記しておきます。

環境

スマホ: Google Pixel 5(128 GB、Just Black、SIM フリー版)
appium: 1.22.1

直し方

先に直し方。

Appium Settings というアプリがいつの間にかインストールされており、それをアンインストールしたら直りました。

f:id:ymdsmn:20220103145228p:plain
こんなアイコン

経緯

[React Native]Appiumを使ったE2Eテストをjestで動かす - Qiita

こちらの記事を参考に、開発機の MacBook Pro に実機の Pixel 5 をUSB接続してテストしていました。

テストはうまく動いたのですが、スマホを外していじってみると、キーボードが一切使えなくなってることに気づきました。

Chrome、LINE、Facebook、ツイッター、いろいろ試しましたがテキスト入力欄をタップしてもキーボードが表示されません。何も入力できません。いいね押すぐらいしか出来なくなっちゃいました。

わけも分からず設定をあれこれ調べているうちに気付きました。

f:id:ymdsmn:20220109150016p:plain

「システム」の「言語と入力」のところの "Appium IME" ってなんだ…?

f:id:ymdsmn:20220109150019p:plain

「言語と入力」→「画面キーボード」とタップしていくと、Appium のロゴの何かがある…。

f:id:ymdsmn:20220109150023p:plain

さらに「画面キーボードを管理」をタップすると、"Appium IME" とかいう項目が。トグルスイッチは最初からオフでした。

いや絶対こいつが犯人でしょ。

なにか変なアプリが入ってるのかなーと思ってアプリ一覧を探したら…

f:id:ymdsmn:20220109150026p:plain

い、いたー!

こいつをアンインストールしたら無事キーボードが使えるようになりました。

ただ、何度か再現を試みたのですが、"Appium Settings" はインストールされこそするものの、キーボードが使えないって状況は再現せず。タイミングか何か次第なんでしょうか。

誰かの助けになれば幸いです!

Rails でリクエストパラメータに Shift_JIS 文字列が渡されるとエラるので nkf で強制変換するモンキーパッチあてて回避

SendGrid 宛に届いたメールを Rails の Mailbox で受け取って、開発チームの Slack へ通知するようにしてるのですが、

メールの文字コードが Shift_JIS だった場合に ActionController::BadRequest エラーが発生してしまう問題に悩まされていました。エラーメッセージの冒頭はこんな感じ。

An ActionController::BadRequest occurred in inbound_emails#create:

  Invalid request parameters: Invalid encoding for parameter:
…

エラーは ApplicationMailbox に到達する以前、Rack Middleware のどこかで発生しているようで捕捉も難しかったのですが、exception_notification のエラーメールのバックトレースを頼りに解決しました。

環境

% bundle exec rails --version
Rails 6.1.4.1
% bundle info exception_notification
  * exception_notification (4.4.3)
        Summary: Exception notification for Rails apps
        Homepage: https://smartinez87.github.io/exception_notification/
        Path: /Users/monmon/ghq/github.com/mig-hld/shokutsu-api/vendor/bundle/ruby/2.7.0/gems/exception_notification-4.4.3

原因

exception_notification の Backtrace の項を見るとこんな感じ。

-------------------------------
Backtrace:
-------------------------------

  actionpack (6.1.4.1) lib/action_dispatch/request/utils.rb:39:in `check_param_encoding'
  actionpack (6.1.4.1) lib/action_dispatch/request/utils.rb:34:in `block in check_param_encoding'
  actionpack (6.1.4.1) lib/action_dispatch/request/utils.rb:34:in `each_value'
  actionpack (6.1.4.1) lib/action_dispatch/request/utils.rb:34:in `check_param_encoding'
  actionpack (6.1.4.1) lib/action_dispatch/http/request.rb:403:in `block in POST'
  rack (2.2.3) lib/rack/request.rb:69:in `fetch'
  rack (2.2.3) lib/rack/request.rb:69:in `fetch_header'
  actionpack (6.1.4.1) lib/action_dispatch/http/request.rb:398:in `POST'
  actionpack (6.1.4.1) lib/action_dispatch/http/parameters.rb:55:in `parameters'
  config/initializers/wrap_parameters.rb:11:in `process_action'
  actionpack (6.1.4.1) lib/abstract_controller/base.rb:165:in `process'
  …

check_param_encoding ってメソッドでエラー発生してるらしい。

該当箇所を見てみます。

 29       def self.check_param_encoding(params)
 30         case params
 31         when Array
 32           params.each { |element| check_param_encoding(element) }
 33         when Hash
 34           params.each_value { |value| check_param_encoding(value) }
 35         when String
                     # ↓これが false を返すために、
 36           unless params.valid_encoding?
 37             # Raise Rack::Utils::InvalidParameterError for consistency with Rack.
 38             # ActionDispatch::Request#GET will re-raise as a BadRequest error.
                # ↓ここで例外発生
 39             raise Rack::Utils::InvalidParameterError, "Invalid encoding for parameter: #{params.scrub}"
 40           end
 41         end
 42       end

リクエストパラメータ(foo=bar&baz=qux みたいな)の文字列ごとに String#valid_encoding? で文字コードをチェックするメソッドのようです。

ここに print デバッグや binding.pry を仕込んで調査した感じ、パラメータとして Shift_JIS 文字列が渡されてるのにも関わらずその String#encoding がなぜか #<Encoding:UTF-8> を返すために、上記コード中で String#valid_encoding? が文字コードの不一致とみなして false を返すようです。

なんでこうなのかはよく分からんけど、ええいままよ!(パパよ!)モンキーパッチを宛てて回避しちゃいました。あまりお行儀よくないかもしれないけど…

解決

先ほどの check_param_encoding をモンキーパッチで再定義します。

$ vi config/initializers/monkey_patch_action_dispatch_request_utils.rb
module ActionDispatch
  class Request
    class Utils
      def self.check_param_encoding(params)
        case params
        when Array
          params.each { |element| check_param_encoding(element) }
        when Hash
          params.each_value { |value| check_param_encoding(value) }
        when String
          # ↓↓↓追加↓↓↓
          params = NKF.nkf("--oc=UTF-8", params)
          # ↑↑↑追加↑↑↑
          unless params.valid_encoding?
            # Raise Rack::Utils::InvalidParameterError for consistency with Rack.
            # ActionDispatch::Request#GET will re-raise as a BadRequest error.
            raise Rack::Utils::InvalidParameterError, "Invalid encoding for parameter: #{params.scrub}"
          end
        end
      end
    end
  end
end

String#encode メソッドではうまく UTF-8 に変換できなかったりするらしいので、 NKF でパラメータを強制的に UTF-8 に変換してしまってます。(参考: RubyでUTF-8をShiftJISに変換するならnkfを使うべき - 動かざることバグの如し

テスト

どこか適当なパス (ここではテスト用に用意した /test) に、適当なパラメータ名(ここでは "hoe")で、Shift_JIS な文字列を送信してみます。

$ curl "http://localhost:3000/test?hoe=$(echo テスト | nkf --sjis)"

ログを確認

INFO -- : Started GET "/test?hoge=eXg" for 127.0.0.1 at 2021-12-11 16:18:32 +0900
log writing failed. "\x83" from ASCII-8BIT to UTF-8
INFO -- : Processing by TestController#index as */*
INFO -- :   Parameters: {"hoge"=>"\x83e\x83X\x83g"}
INFO -- : Completed 200 OK in 1ms (Allocations: 78)

確かにパラメータに Shift_JIS 文字列が渡されてるけど、例外は発生しませんでした。(なんか log writing failed とかってメッセージ出てるけど無視していいかな…)

やったね。