ActiveRecord::LogSubscriber#log_query_source（private）をElixir/Ectoに移植するぞ

## はじめに
昨日は @GKBRさんの[Liveviewでお手軽オンラインゲーム開発](https://qiita.com/GKBR/items/4f83cde368078572ad0d)でした！
LiveviewやHotwireといったServerエンジニアからのモダンなFrontendは、自分が普段Reactを使っている事もあってまだ試せていませんが、socket周りの興味は大きいので近々[昨日の記事を](https://qiita.com/GKBR/items/4f83cde368078572ad0d)参考に遊んでみたいと思います。

以下軽い自己紹介です。

普段はスタートアップでRailsを中心にインフラやらCMSやらの開発をしております。
最近の業務はRuby, MySQL, Elasticsearch, CircleCiの整備等、SREよりな業務が多いです。

エンジニアとして4年ほど経験を積み、そろそろもう一皮向けたいな、と思ってElixirを触り始めました。

今回は勉強ついでに、なにか目的が欲しく、慣れ親しんだRailsと絡めた挑戦を記事にまとめます。
CodeReadingや、localでのライブラリの開発環境を準備する辺りも経緯として記載させて頂きましたので、なにかの参考になりましたら嬉しいです。

（Elixirでのアウトプットは初めてです。よろしくお願い致します。）
※ この記事は [fukuoka.ex Elixir／Phoenix Advent Calendar 2021](https://qiita.com/advent-calendar/2021/fukuokaex)の22日の内容となります。
## ActiveRecord::LogSubscriber#log_query_source（private）とは？
```rb
    User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."id" = $1 LIMIT $2
  ↳ app/controllers/users_controller.rb:70:in `index'
```
↑ はRailsのActiveRecordが吐いてくれているログです。イケてますね。
この `↳ app/controllers/users_controller.rb:70:in 'index'`の部分の表示が `ActiveRecord::LogSubscriber#log_query_source`の挙動です。

元々は @joker1007 さんの [activerecord-cause](https://github.com/joker1007/activerecord-cause)というgemを入れていて同等な機能を享受していたのですが、いつの間にかRailsにも同じようなログが表示されるようになっていました。(多分Rails 5.2？)
今回は両方の実装を参考にしていこうと思います。

## ActiveRecord::LogSubscriber#log_query_sourceの実装はどうなっているか

[本物はこちら](https://github.com/rails/rails/blob/v7.0.0/activerecord/lib/active_record/log_subscriber.rb#L130)

```rb
  def log_query_source
    source = extract_query_source_location(caller)
    if source
      logger.debug("  ↳ #{source}")
    end
  end

  def extract_query_source_location(locations)
    backtrace_cleaner.clean(locations.lazy).first
  end
```
 1. log_query_sourceをdebugログ表示時にcall
 2. log_query_source内で[Kernel.#caller](https://docs.ruby-lang.org/ja/latest/method/Kernel/m/caller.html)を使ってstacktraceの一覧を抽出メソッドに渡す
 3. 抽出メソッド（extract_query_source_location） 内で `backtrace_cleaner`（`ActiveSupport::BacktraceCleaner`） を用いて不要traceを排除して、その中の先頭を表示させる

なるほど、callerが抽出の本体となっているようです。
さすがRails、`ActiveSupport::BacktraceCleaner`なんていうイケてるものも用意してくれちゃってるのですね。

https://api.rubyonrails.org/classes/ActiveSupport/BacktraceCleaner.html
 
## activerecord-causeの実装はどうなっているか
```rb
  # 参照: https://github.com/joker1007/activerecord-cause/blob/master/lib/activerecord/cause.rb
  def sql(event)
    return unless logger.debug?
    # 省略
    locations = get_locations
    # 省略
    if ActiveRecord::Cause.log_mode != :all
      locations = locations.take(1)
    end
    locations.each do |loc|
       # 省略
       name = name_with_color(payload[:name])
       sql = sql_with_color(payload[:sql])
       cause = color(loc.to_s, nil, true)
       output =
         if ActiveRecord::Cause.log_with_sql
           "  #{name}  #{sql}#{binds} caused by #{cause}"
         else
           "  #{name}  caused by #{cause}"
         end
       debug(output)
    end
  end

  def get_locations
    return [] if ActiveRecord::Cause.match_paths.empty?
    caller_locations.select do |l|
      ActiveRecord::Cause.match_paths.any? do |re|
        re.match(l.absolute_path)
      end
    end
  end

  ActiveSupport.on_load(:active_record) do
  if ActiveRecord.version >= Gem::Version.new("5.1.0")
    if ActiveRecord.version >= Gem::Version.new("5.1.5")
      ActiveRecord::Cause::LogSubscriberAR515.attach_to :active_record
    else
      ActiveRecord::Cause::LogSubscriberAR503.attach_to :active_record
    end
  # 省略
  else
    # 省略
    ActiveRecord::Cause::LogSubscriberAR4.attach_to :active_record
  end
end

```
 1. sqlというmethodを定義してdebugモード時にログを表示。`ActiveSupport.on_load(:active_record) do` 辺りで各Subscriberにattachしているので、そういうcallback的なものがあるのかも？もしくはoverride？
 2. #get_locationsでフレームを取得。内部的には [Kernel.#caller_locations](https://docs.ruby-lang.org/ja/latest/method/Kernel/m/caller_locations.html)の中で一致したものを選択 ※ defaultのmatch_pathsは `[/#{Regexp.quote(Rails.root.join("app").to_s)}/]` でした。
 3. 取得したlocationsをイイカンジに加工して `debug` で表示

こちらではcaller_locationsを使って取得しているようでした。
どちらもシンプルに、 `stacktraceを取得する => 整形する => 表示する`を順次行っているだけのようです。
なんだかできちゃう気がしてきました。 

## 実装方針
ActiveRecord::LogSubscriber#log_query_source, activerecord-causeで何をしているのかが見えてきたので、これを移植するにはどうしたらよいのか、実装方針に関してまとめます。

 1. [Kernel.#caller_location](https://docs.ruby-lang.org/ja/latest/method/Kernel/m/caller_locations.html)や[Kernel.#caller](https://docs.ruby-lang.org/ja/latest/method/Kernel/m/caller.html)の代わりとなるようなElixirのfunctionを探す
 2. Phoenixでの QUERY logはどこに実装があるのかを探す
 3. 実装してみる
 5. local環境で動かす
 6. PRを出す

## 1. [Kernel.#caller_location](https://docs.ruby-lang.org/ja/latest/method/Kernel/m/caller_locations.html)や[Kernel.#caller](https://docs.ruby-lang.org/ja/latest/method/Kernel/m/caller.html)の代わりとなるようなElixirのfunctionを探す
とりあえず `Elixir caller_locations` でググってみたのですが、なかなか該当のmethodは出てきませんでした。

はて、どうしたものか、
[ElixirSlackのbeginnersチャンネル](https://elixir-slackin.herokuapp.com/)で質問したところ、[Process.info(self(), :current_stacktrace)](https://til.hashrocket.com/posts/f9enjuhned-print-the-current-stacktrace-in-elixir) で取得出来るということを教えて頂きました。

```exs
iex(1)> Process.info(self(), :current_stacktrace)
{:current_stacktrace,
 [
   {Process, :info, 2, [file: 'lib/process.ex', line: 769]},
   {:erl_eval, :do_apply, 6, [file: 'erl_eval.erl', line: 685]},
   {:elixir, :recur_eval, 3, [file: 'src/elixir.erl', line: 289]},
   {:elixir, :eval_forms, 3, [file: 'src/elixir.erl', line: 274]},
   {IEx.Evaluator, :handle_eval, 3, [file: 'lib/iex/evaluator.ex', line: 310]},
   {IEx.Evaluator, :do_eval, 3, [file: 'lib/iex/evaluator.ex', line: 285]},
   {IEx.Evaluator, :eval, 3, [file: 'lib/iex/evaluator.ex', line: 274]},
   {IEx.Evaluator, :loop, 1, [file: 'lib/iex/evaluator.ex', line: 169]}
 ]}
```
iex上での動作確認です。なんだかこれで行けそうな気がします。

hexdocにも一応 `Process.info(self(), :current_stacktrace)` に関しての記述があるのですが、`Kernel.SpecialForms.html#__STACKTRACE__/0` の項目で、おまけ程度の記載しかありませんでした。

https://hexdocs.pm/elixir/1.12/Kernel.SpecialForms.html#__STACKTRACE__/0

```exs
 # __STACKTRACE__での取得はrescue or catchの中でのみ可能
iex(2)> try do
...(2)>   raise "Oh no!"
...(2)> rescue
...(2)>  _ ->  __STACKTRACE__
...(2)> end
[
  {:erl_eval, :do_apply, 6,
   [file: 'erl_eval.erl', line: 685, error_info: %{module: Exception}]},
  {:erl_eval, :try_clauses, 8, [file: 'erl_eval.erl', line: 919]},
  {:elixir, :recur_eval, 3, [file: 'src/elixir.erl', line: 289]},
  {:elixir, :eval_forms, 3, [file: 'src/elixir.erl', line: 274]},
  {IEx.Evaluator, :handle_eval, 3, [file: 'lib/iex/evaluator.ex', line: 310]},
  {IEx.Evaluator, :do_eval, 3, [file: 'lib/iex/evaluator.ex', line: 285]},
  {IEx.Evaluator, :eval, 3, [file: 'lib/iex/evaluator.ex', line: 274]},
  {IEx.Evaluator, :loop, 1, [file: 'lib/iex/evaluator.ex', line: 169]}
]
```

## 2. Phoenixでの `QUERY` logはどこに実装があるのかを探す
### とりあえずPhoenixから見ていこうと思います。
 1. `QUERY` のようなPhoenixで表示されているログをコピペしてgrepしてみました。
    - ノーヒット
 2. 次に `log` でファイル名検索
    - [いました](https://github.com/phoenixframework/phoenix/blob/d7c2e753cbb8d146ce6fa279460ec9f262ea2c8e/lib/phoenix/logger.ex)
    - 読んでみると、こちらはAPIやsocketでのConnection等のログ表示のようでした。
 3. ↑ のファイル内で [require Logger](https://hexdocs.pm/logger/Logger.html) されており、他にlogger系の情報は出て来ませんでした。Phoenix内での調査はここまでのようです。

### Ectoを探します。
 1. `QUERY` のようなPhoenixで表示され...
    - Getting startedのみ
 2. 次に `log` でファイル名検索
    - ノーヒット & 絶望
 3. Queryを流している部分を探す
    - [repo/queryable.ex](https://github.com/elixir-ecto/ecto/blob/v3.7.1/lib/ecto/repo/queryable.ex#L199)っぽいぞ
    - `adapter.execute(adapter_meta, query_meta, prepared, params, opts)` executeで大体実行されるのでこれを探そう
   
### adapterのexecute funcなので、`postgrex` を見る、`db_connection` も見る => ない
全然ない...logを場所を探してるのにconnectionの部分まで行ってるの絶対おかしい、、、
そもそもの探し方がおかしいのかもしれない、、、見落としてるかもしれないの、、、sampleのphoenixをちょい見てみよう、、、

```exs
  defp deps do
    [ 
      {:phoenix, "~> 1.6.2"},
      {:phoenix_ecto, "~> 4.4"},
      {:ecto_sql, path: "../ecto_sql"},
      {:postgrex, ">= 0.0.0"},
      # 省略
    ]
  end
```

あれ、`phoenix_ecto` と `ecto_sql` ってなんだ？ ectoのことdepsしてないじゃん。
### phoenix_ectoとは？
> Integrates Phoenix with Ecto.
> It implements many protocols that makes it easier to use
  Ecto with Phoenix either when working with HTML or JSON.

ectoとphoenixの間の便利なやつっぽい。
repoのstatusチェックとかもここでやってそう。logっぽい実装は見当たらず。
こいつがectoを持ってるらしい。

https://github.com/phoenixframework/phoenix_ecto

ログの実装は見当たらない

### ecto_sqlとは？
> Ecto SQL (documentation](https://hexdocs.pm/ecto_sql/index.html) provides building blocks for writing SQL adapters for Ecto.

各DBadapterでEctoを用いてSQLを使えるように切り出されたライブラリらしい。
migrationやらsandbox機能もこの子が提供している。
`QUERY`でgrepしたところ**[ここに実装がありました](https://github.com/elixir-ecto/ecto_sql/blob/v3.7.1/lib/ecto/adapters/sql.ex#L964)** 歓喜！！！

https://github.com/elixir-ecto/ecto_sql
## 3. ecto_sqlを拡張してみる

```exs
defp log_iodata(measurements, metadata) do # ①
  # 省略
  iodata = [
      "QUERY",
      ?\s,
      log_ok_error(result),
      log_ok_source(source),
      log_time("db", measurements, :query_time, true),
      log_time("decode", measurements, :decode_time, false),
      log_time("queue", measurements, :queue_time, false),
      log_time("idle", measurements, :idle_time, true),
      ?\n,
      query,
      ?\s,
      inspect(params, charlists: false)
    ]
    log_stacktrace_match_path = Keyword.get(opts, :log_stacktrace_match_path) || Keyword.get(opts, :otp_app) |> to_string()
    if current_stacktrace = log_current_stacktrace(log_stacktrace_match_path) do # ①-2
      ["  ↳ #{current_stacktrace |> inspect}" | [?\n |iodata]] |> Enum.reverse()
    else
      iodata
    end
  end

  defp log_current_stacktrace(stacktrace_match_path) do # ②
    case Regex.compile(stacktrace_match_path) do
      {:ok, regex_stacktrace_match_path} ->
        log_current_stacktrace(
          regex_stacktrace_match_path,
          Process.info(self(), :current_stacktrace) |> elem(1)
        )
      {:error, _} -> nil
    end
  end

  defp log_current_stacktrace(regex_stacktrace_match_path, [stacktrace | stacktraces]) do # ③
    log_current_stacktrace(regex_stacktrace_match_path, stacktraces, [elem(stacktrace, 3)])
  end

  defp log_current_stacktrace(regex_stacktrace_match_path, [stacktrace | stacktraces], stacktraces_for_log) do # ④
    log_current_stacktrace(regex_stacktrace_match_path, stacktraces, stacktraces_for_log ++ [elem(stacktrace, 3)])
  end

  defp log_current_stacktrace(regex_stacktrace_match_path, [], stacktraces_for_log) do  # ⑤
    stacktraces_for_log
    |> Enum.find(
      &(
        Enum.at(&1, 0)
        |> elem(1)
        |> to_string()
        |> String.match?(regex_stacktrace_match_path))
      )
  end
end
```

####  ①  :  表示するlog内容を定める `log_iodata` に対して処理を追加していく
#### ①-2:  `log_iodata` 内で `log_stacktrace_match_path` をデフォルト値`:otp_app` からの取得として設定`log_current_stacktrace`を呼び出す
#### ②,③,④,⑤  : `log_stacktrace_match_path` を複数定義してパターンマッチによって順次データ整形を行う

## 4. local環境で動かす
### localで動作していることを確認するために sampleで用意したphoenixアプリのecto_sqlをlocalpathからの参照にして動かしてみる
```exs
{:foobar, git: "https://github.com/elixir-lang/foobar.git", tag: "0.1"}
{:foobar, path: "path/to/foobar"}
```
こんな感じでlocalのライブラリをpathで指定することが出来ます。
詳しくはこちら

https://hexdocs.pm/mix/1.13.1/Mix.Tasks.Deps.html
 
### 折角なのでEarthlyを使ってecto_sqlのリポジトリ内でTestを動かしてみる

https://twitter.com/josevalim/status/1346404430275612683

我らが創造神が Earthly を押していたので触ってみました。
> ❤️ Makefile + Dockerfile = Earthfile
https://earthly.dev/

今回とは別件で自分で定義して使ってみたりもしたのですが、確かにどうせMakefile作りますし、使い回しも考えたらこれは便利かもしれません。
ちなみに僕は運良く gitinitしてるdirでearthlyを動かすと死ぬバグ（Path解決の関係）を踏んでしまったのですが、こちらは解消されています。
ただ、下手に使うとdocker-composeとearthfileとmakefileがあるようなレポジトリーになりかねないので、気をつけねばと思いました。

https://github.com/earthly/earthly/issues/1426

### 開発ではちょっと遅いので、適当にDBを立ててtestを追加していく
Earthlyで都度buildしてテストを確認しているのも時間が取られてしまうので、localに適当なdocker-composeを用意して、都度動かしながらテストを追加していきます。

OSSの開発やらdebugをする時はherokuで適当なadd-onと追加してDBだけ動かしたり、docker-composeで動かしたり、雑に使うことの出来るDB構築をよく行います。

こちらはよく使うdocker-composeです

```yml
version: "2"
services:
  postgresql:
    image: postgres:13.4
    container_name: postgresql
    ports:
      - 5432:5432
    volumes:
      - ./postgres/init:/docker-entrypoint-initdb.d
    environment:
      POSTGRES_USER: root
      POSTGRES_PASSWORD: root
      POSTGRES_INITDB_ARGS: "--encoding=UTF-8"
    hostname: postgres
    restart: always
    user: root
    volumes:
      - ./tmp/db:/var/lib/postgresql/data
    
  pgadmin4:
    image: dpage/pgadmin4:5.6
    container_name: pgadmin4
    ports:
      - 80:80
    volumes:
      - ./pgadmin:/var/lib/pgadmin/storage
    environment:
      PGADMIN_DEFAULT_EMAIL: root@example.com
      PGADMIN_DEFAULT_PASSWORD: root
    hostname: pgadmin4
    restart: always
```

## 5. PRを出す
長い道のりでしたが、ようやくPRを出せました。。。

https://github.com/elixir-ecto/ecto_sql/pull/363

Elixirのすごいところは、現在進行形で開発が盛んなため、今PRをだしてから確か **20分そこら** でメンションが帰ってきました。
ちょっと実装を直したあと、機能に関してのディスカッションを行い、結果 ecto側にも実装をいれてキレイにしましょうと提案とPRを頂きました。

https://github.com/elixir-ecto/ecto_sql/pull/366

## おわりに

今回の提案に関して雰囲気 [José Valim](https://github.com/josevalim)と[v0idpwn](https://github.com/v0idpwn)は機能自体には賛成してくれそうだったので、近々拡充されてくれないかと、とても楽しみにしです。

恐らく僕が出したPRに関しては改善点が多々あると思われるので、そこはこれからElixir力を鍛えていってカバーするしかないです。
個人的に、ここ数年はOSS頑張りたいと思っている気持ちが強いです。
CodeReadingやissues倒し等から初めていった来年のアドベントカレンダーでは取り込まれた報告が出来るように頑張っていきます。

明日は @im_miolab さんの **"技術コミュニティ運営を続けていく上で意識してること（kokura.exオーガナイザーとして）"** です！！ お楽しみに！