Goのデバッグ用ロガーの開発を通して得た デバッグとgoパッケージに関する知見/Knowledge by given implementation of logger for debug

[Elevator Pitch]

Goでデバッグをする場合, 基本的にはDelve, GDB, ロギングの3択になります. DelveやGDBによるデバッグは便利ですが複数の変数情報を高速に得ることは困難であり, この用途にはロギングが適しています. しかし, デバッグ用に追加したロギング用のコードを消し忘れ, 実行速度の低下や業務用のコードにおける機密情報のログ出力等の問題を引き起こす可能性があります. これらの問題に対処するべく, 私はGoの静的解析および動的解析によって変数情報等を表示可能で, コミット時に自動的に削除されるデバッグ用のロガーdlを開発しました. 本セッションでは, 前述したGoにおける3種類のデバッグ方法の利点および欠点ならびにdlの開発を通して得たgo/ast等のgoパッケージに関する知見をご紹介します.

[Main Description]

開発において, 想定外の挙動をした際にデバッグをした経験がある方は多いのではないでしょうか? Goでデバッグをする場合, 基本的にはDelve[1], GDB[2], ロギングの3択になります. Delve[1]はサードパーティー製のGo用デバッガであり, 実行時の変数やスタック情報の表示や上書き, goroutineの情報取得等ができます. また, リモードデバッグを有効にすることで, VS CodeやGoLandなどのエディタやIDEに組み込んでGUI上でデバッグすることもできるため, 開発時に重宝します. GDB[2]はDelve[1]と似たデバッガで, gef[5]やpeda[4], pwndbg[6]等のGDBスクリプトにより, 低レイヤを対象としたデバッグを円滑に行うことができます. しかし, Go Blogの記事[3]に記載されているように, Goプログラムの構造を理解していないため誤った結果を表示する場合もあります. また, Delve[1]やGDB[2]はある1点の状態を詳しく得ることは得意ですが, 複数の変数情報等をまとめて高速に得ることは不得手です. したがって, 手軽に複数の変数情報等をまとめて高速に得る用途にはロギングが適しています.

Goのロギングには, builtinパッケージのpanic, print, println, fmtパッケージやlogパッケージの各種関数およびメソッド, サードパーティー製のglog[7], Logrus[8], zap[9]等のロガーが利用できます. また, logr[10]が提供するinterfaceを満たすロガーを利用することで, それぞれのロガーを手軽に切り替えることもできます. これにより, Delve[1]やGDB[2]と違い, 複数の変数情報等をまとめて高速に得ることができます. しかし, デバッグ用に追加したロギング用のコードを消し忘れ, 実行速度の低下や業務用のコードにおける機密情報のログ出力等の問題を引き起こす可能性があります. 実際に, 私もインターンシップ先のリポジトリに対して余分なロギング用のコードを追加し, レビュー漏れで本番コードに紛れ込んでしまった経験があります．

そこで, 私はGoの静的解析と動的解析によって変数情報等を表示でき，コミット時に自動的に削除されるデバッグ用のロガーdl( https://github.com/task4233/dl )を開発しました. Design Docsはこちら( http://bit.ly/3XGdtyF )です. dlは変数とその型情報, 変数が利用されているコードの行数を表示する機能とコミット時に自動的に削除される機能を提供します. これらの機能は, Goのgo/token, go/parser, go/astパッケージ等を用いた静的解析やruntimeパッケージを用いた動的解析を活用することで実現しています. また, dlは前述したlogrのinterfaceを満たしているロガーであればラップすることができ, 既存のロガーを変更することなく容易に導入することができます. 私が調査した中では, これらの機能を全て備えたロガーは他に存在しませんでした(2023/01/30現在).

本セッションでは, 前述したGoにおける3種類のデバッグ方法の利点および欠点ならびにdlの開発を通して得たgo/ast等のgoパッケージに関する知見をご紹介します. 過去のGo ConferenceでGDB[2]に関する講演[11]がありましたが, これとは異なる切り口の内容なので差分はあると考えています.

[1] go-delve/delve: https://github.com/go-delve/delve

[2] GDB: The GNU Project Debugger: https://www.sourceware.org/gdb/

[3] Debugging Go Code with GDB: https://go.dev/doc/gdb

[4] hugsy/gef: https://github.com/hugsy/gef

[5] longld/peda: https://github.com/longld/peda

[6] pwndbg/pwndbg: https://github.com/pwndbg/pwndbg

[7] golang/glog: https://github.com/golang/glog

[8] Sirupsen/logrus: https://github.com/Sirupsen/logrus

[9] uber-go/zap: https://github.com/uber-go/zap/

[10] go-logr/logr: https://github.com/go-logr/logr

[11] Debugging Go Code with GDB:https://speakerdeck.com/kaneshin/debugging-go-code-with-gdb

Transcript

1. Goのデバッグ用ロガーの開発を通して得た
   デバッグとgoパッケージに関する知見
   Go Conference 2023
   2023/06/02
   Takashi Mima(@task4233)
   

   View Slide

2. Takashi Mima(@task4233)
   所属
   ・株式会社メルカリ(Identity Platform)
   興味分野
   ・バックエンド
   　・Go(Contribution/Go Conference)
   ・セキュリティ
   　・CTF(SECCON Beginners)
   　・セキュリティ・ミニキャンプ in 三重 2023 講師
   ほか
   ・Twitter: @task4233
   ・Portfolio: task4233.dev
   2
   

   View Slide

3. Goでデバッグする際に
   何を使いますか？👀
   3
   

   View Slide

4. Delve?GDB?ロギング？
   他の何か？🧐
   4
   

   View Slide

5. 本発表で共有する2つのこと
   1. Goにおける3種類のデバッグ方法
   2. 自作したロガーの開発に用いられているgoパッケージ
   ・デバッガの詳しい使い方
   ・GODEBUG等の環境変数を用いたデバッグ
   5
   本発表で共有しないこと
   

   View Slide

6. 3種類のデバッグ方法
   Delve GDB ロギング
   👍 ・大半のGoプログラム
   　のデバッグに利用可能
   ・Goに特化しており、
   　GDBよりも正確な結果
   　が得られる
   ・Cgoやランタイムの
   　デバッグに利用可能
   ・機能拡張が豊富
   ・Pythonスクリプトで
   　処理を自動化可能
   ・手軽(学習コスト低)
   ・複数の変数の状態を
   　まとめて確認可能
   ・手動のデバッガ操作
   　よりも高速
   🤔 ・単一の状態でしか情報
   　を取得できない
   ・単一の状態でしか情報
   　を取得できない
   ・ビルド時のフラグを
   　設定する必要がある
   ・ログの埋め込み/
   　消し忘れが起き得る
   ・実行速度の低下
   6
   

   View Slide

7. Delve: Goに特化したサードパーティー製のデバッガ
   目標
   ・Go用のシンプルでフル機能を備えたデバッグツールの提供
   Delveが適する場面
   ・ビルドされたGoプログラムをデバッグする場合の大半
   ・Goのランタイムやデータ構造、式を理解しているため
   実装
   ・github.com/go-delve/delve
   7
   

   View Slide

8. Goクイズ: 次のプログラム実行時に表示されるのは？🤔
   package main
   import "fmt"
   type T struct{ N int }
   func main() {
   ts := []T{{N: 1}, {N: 3}, {N: 5}}
   minT := &T{N: 10000}
   for _, t := range ts {
   if t.N < minT.N {
   minT = &t
   }
   }
   fmt.Println(minT.N)
   } 8
   1⃣ 1
   2⃣ 5
   3⃣ 10000
   4⃣ 未定義
   Playground:
   go.dev/play/p/rkeWSeUx4pm
   

   View Slide

9. Goクイズ: 次のプログラム実行時に表示されるのは？🤔
   package main
   import "fmt"
   type T struct{ N int }
   func main() {
   ts := []T{{N: 1}, {N: 3}, {N: 5}}
   minT := &T{N: 10000}
   for _, t := range ts {
   if t.N < minT.N {
   minT = &t
   }
   }
   fmt.Println(minT.N)
   } 9
   1⃣ 1
   2⃣ 5
   3⃣ 10000
   4⃣ 未定義
   Playground:
   go.dev/play/p/rkeWSeUx4pm
   

   View Slide

10. GDB: Goに限らず普遍的に使えるデバッガ
    用途
    ・プログラム実行中の内部情報の把握
    ・クラッシュした際のメモリやスタックの状態の把握
    GDBが適する場面
    ・Cgoコードやランタイム自体のデバッグをする場合
    参考リンク
    ・https://sourceware.org/git/binutils-gdb.git
    ・https://go.dev/doc/gdb
    10
    

    View Slide

11. GDB: 低レイヤのデバッグ
    拡張スクリプト
    ・Go用拡張: go/src/runtime/runtime-gdb.py
    ・peda: https://github.com/longld/peda
    ・gef: https://github.com/hugsy/gef
    11
    

    View Slide

12. ロギング: プログラムの変数等の情報出力
    ロギングが適する場面
    ・複数の変数情報を手軽にまとめて出力したい場合
    利用できるもの
    ・builtin関数のpanic, print, println
    ・fmt, log, x/exp/slog
    ・glog, logrus, zap
    ・logr.Logger interface
    12
    

    View Slide

13. 3種類のデバッグ方法
    Delve GDB ロギング
    👍 ・大半のGoプログラム
    　のデバッグに利用可能
    ・Goに特化しており、
    　GDBよりも正確な結果
    　が得られる
    ・Cgoやランタイムの
    　デバッグに利用可能
    ・機能拡張が豊富
    ・Pythonスクリプトで
    　処理を自動化可能
    ・手軽(学習コスト低)
    ・複数の変数の状態を
    　まとめて確認可能
    ・手動のデバッガ操作
    　よりも高速
    🤔 ・単一の状態でしか情報
    　を取得できない
    ・単一の状態でしか情報
    　を取得できない
    ・ビルド時のフラグを
    　設定する必要がある
    ・ログの埋め込み/
    　消し忘れが起き得る
    ・実行速度の低下
    13
    

    View Slide

14. 3種類のデバッグ方法
    Delve GDB ロギング
    👍 ・大半のGoプログラム
    　のデバッグに利用可能
    ・Goに特化しており、
    　GDBよりも正確な結果
    　が得られる
    ・Cgoやランタイムの
    　デバッグに利用可能
    ・機能拡張が豊富
    ・Pythonスクリプトで
    　処理を自動化可能
    ・手軽(学習コスト低)
    ・複数の変数の状態を
    　まとめて確認可能
    ・手動のデバッガ操作
    　よりも高速
    🤔 ・単一の状態でしか情報
    　を取得できない
    ・単一の状態でしか情報
    　を取得できない
    ・ビルド時のフラグを
    　設定する必要がある
    ・ログの埋め込み/
    　消し忘れが起き得る
    ・実行速度の低下
    14
    

    View Slide

15. こんな経験はありませんか？
    ・テストがうまく動かない...
    ・プログラムが謎の挙動をする
    → ログを仕込む！
    ・対象変数の値は何？
    　log.Printf(“%#v”, targetVariable)
    ・対象変数の型は何？
    　log.Printf(“%T”, targetVariable)
    ・そもそも、その箇所は実行されている？
    　log.Printf(“passed!”)
    → 仕込んだログを消し忘れて commit & push (& release)...
    15
    

    View Slide

16. 人はデバッグ時に余計なことを考えたくない
    ・デバッグ後、ログを仕込んだ場所を忘れがち
    →コミット時にロギング部分を全て消すロガーを開発すれば
    　良いのでは？🤔
    16
    

    View Slide

17. デバッグ用ロガーのdlを開発しました
    仕組み
    ・コミット前後のGit Hooksでロギング部分を削除・復元
    ・ロガーの削除・復元はGoの静的解析により実現
    実装
    ・https://github.com/task4233/dl
    紹介記事
    ・Git にコミットされない魔法のデバッグ用ロガーを開発
    　してきた - Qiita
    17
    

    View Slide

18. バグらせずにロガー部分を削除する技術
    静的解析をする
    ・プログラムを実行せずにGoのコードを解析すること
    ・詳しくは tenntennさんの14. 静的解析とコード生成 に
    字句解析→構文解析→型チェックの順に行われる
    ・今回、型情報は必要ないので構文解析のフェーズまで(コード)
    ・構文解析までするとAST(抽象構文木)が得られる
    ・型チェックまですると型情報が得られる
    18
    

    View Slide

19. AST(抽象構文木)とは
    言語の意味に関係のある情報のみを取り出した木
    ・return 1, nil は Return Statements
    19
    ReturnStmt
    Expr
    (1)
    Expr
    (nil)
    Results
    ＝
    

    View Slide

20. dlで利用されているgoパッケージと用途
    20
    パッケージ名 用途 該当部分
    go/token 字句解析(Go Code→tokens) コード
    go/parser 構文解析(tokens→AST) コード
    (x/tools/)
    go/ast
    ASTの関連操作 コード
    go/format AST操作後の整形 コード
    

    View Slide

21. ASTからロガーの呼び出しを削除するために
    言語仕様に沿って呼び出され得る箇所を考える
    ・ロガーの定義は func Info[T any](v T) (int, error)
    　→Expression
    Expressionが入る場所は？
    ・Expression Statements(例: dl.Info(1) )
    ・Assignment Statements(例: n, err := dl.Info(1) )
    ・Return Statements(例: return dl.Info(1) )
    など
    21
    

    View Slide

22. ASTからロガーの呼び出しを削除するために
    該当部分をASTから発見する
    ・Expression Statementsを見つけたい時は以下のように
    ・見つけた後に、該当部分を削除する
    22
    

    View Slide

23. まとめ
    3種類のデバッグ方法(Delve, GDB, ロギング)
    ・得手不得手がある
    ・目的にあった方法を選択できると良い
    goパッケージ(go/ast, go/tokenなど)
    ・静的解析のためのパッケージ
    ・ASTや型情報等を得ることができる
    ・興味のある方はツール自作も！
    23
    ありがとうございました！
    

    View Slide