🐞

あなたの先輩がやたらデバッグが早いからくり

2020/11/24に公開

誰しもこんな経験があると思うの

「エラーが出てしまった...2時間くらいコード読んでるのだけどどこが悪いかわからない...」
「ちょっと見せてー、んー、この辺じゃねーかな、あぁこれだよ」
「な...秒...だと...」

って

あるよね

あったあった
人外に見えたなー

ベテランともなると歴戦の勘でいともたやすく🐞を見つけてしまうのです
仙人クラスになるとエラーメッセージからコンピュータの気持ちがわかるものです

なんてのは当然違います

テキトーにやってる様に見えるデバッグも、ちゃんとロジックツリーがあるのです

とある一例

エンジニアくんと先輩に出てきてもらいます

どうやらエンジニアくんがどんなにコードを読んでみても2時間くらいずっとエラーが解決できないみたいです

(実際にはもっともっと込み入った問題でしたが、簡略化してアレンジしてあります)

テストを書いたのだけれど、通らなくてエラーになっているらしい

こんなコードとテストです

何かの商品のうち、現在時刻で判断して現在有効なものだけを参照するロジックの様です

src/main の仮想実装
function List<Item> findActives(userId) {
    check = validation(userId)
    if !check { throw XxxException(...) }

    records = fetch(userId)
    items = records.map(record -> toItem(record))
    return items.filter(item -> isActive(item, Clock.now))  // テスト時は 2018/01
}

function Item toItem(record) {
    return Item(record.id, record.user_id, ...)
}

function bool isActive(item, datetime) {
    return item.start <= datetime && datetime <= item.expire
}

function List<Record> fetch(userId) {
    sql1 = "select * from user where id = $userId"
    user = sql1.selectOne()
    if bigbigbigPrivateCheckMethod1(user) { throw XxxException(...) }

    sql2 = "select * from item where fk = $userId"
    items = sql2.selectAll()
    if bigbigbigPrivateCheckMethod2(items) { throw XxxException(...) }

    return items
}

private function bool bigbigbigPrivateCheckMethod1(user) {
    bla bla bla
    bla bla bla
    bla bla bla
}

private function bool bigbigbigPrivateCheckMethod2(user) {
    bla bla bla
    bla bla bla
    bla bla bla
}

src/test の仮想実装

setup {
    db.insert(
        ITEM_TABLE,
        { 'id': 1, 'user_id': '0001', 'start': 2016/01, 'expire': 2018/01 },
        { 'id': 2, 'user_id': '0002', 'start': 2015/12, 'expire': null },
    )
}

suite {
    found = findActives(userId)

    assert(found == [Item(1, "0001", 2016/01 - 2018/01)])
}

仮想のエラーメッセージ

assertion failed. expected [Item(...)] but actual is [].

どうやらリストの中身が1つのはずが空っぽになってしまった様です

この時点で先輩はまだコードを見てませんが、聞いた話からこんなロジックツリーが瞬時に出来上がっています

.oO「リストの中身の数が合わないなんてのは、最初から違うか途中で減ったかのどっちかだろ」
.oO「最初から違うなら取り損ね、もしくは入れ忘れ」
.oO「途中で減るなら大体は filter / flatMap / reduce あたりだろ」


「ちょっと見せてー」

乗りかかった船で協力することにした先輩は、ちょっと見てみることにしました

エディタを見るとどうもそのプロジェクトは若手に任せてあるやつで、まだまだ不慣れな人たちが作っているプロダクトでした

また、不慣れながらもユニットテストはちゃんと書いていて、問題の箇所も「findAllとかの他ケースは通ってるけどこれだけ想定通りにならない」とのこと

それを聞いた先輩の脳内ロジックツリーが更新されました

.oO「このプロダクトだと flatMap / reduce は使ってないだろうな」
.oO「使うなら自信あるんだろう、それでも疑うならじっくり読むからハイコストローリタンだな」
.oO「他にもテストケースがあるなら、テストデータのセットアップし忘れは考えづらいな」
.oO「テストデータが使い回しなら、外部キーを0001ではなくて1で作ったとかもないだろう」


先輩はここでいくつか指示を出して、文字やファイルを検索させました

「んー」

.oO「満期のテストなのに、いくらなんでも満期設定をし忘れはしないだろう、後回し」
.oO「.filter は1つあったけど、isActiveのユニットテストはちゃんと存在した、後回し」
.oO「ついでに .flatMap / .reduce も軽く探したけど、やっぱ使ってなかった」

軽い検証作業をして、また脳内ロジックツリーが更新されました


.oO「二択か...長時間悩んでるなら何度も境界値チェックはしただろう」
.oO「テストクロックの設定漏れからチェックしてみるか」

ということで、先輩はあるファイルを開きました

「この辺じゃねーかな」

思った通り、テストコード(データ)は現在時刻を 2018 年と想定したテストでしたがテスト用クロックをちゃんと設定していなかったので、2020 年として動いていたのでした

「あぁこれだよ」

無事解決

それにしてもこの先輩は考えてる量に対して口数が少ないですね

「ちょっと見せてー」

「んー」

「この辺じゃねーかな」

「あ、これだよ」

見た箇所も 2~3 箇所であれば、勘でやってたまたま当たった様に見えてもおかしくないですね

二人のアプローチの違い

エンジニアくんは findActives からコードの中を全て辿ってくまなく読み、脳内で全部の変数も想像していた みたいです

対して先輩は戻り値の型がListの箇所のreturnに直接影響するものと、.filterの箇所くらいしか読みませんでした

先輩にはこんな感じで 関係ないところはグレーに見えていた し、「user.id0001のはずで...」なんて 穴埋めもしてません でした

// function List<Item> findActives(userId) {
    // check = validation(userId)
    // if !check { throw XxxException(...) }

    // records = fetch(userId)
    // items = records.map(record -> toItem(record))
    return items.filter(item -> isActive(item, Clock.now))  // テスト時は 2018/01
// }

// function Item toItem(record) {
    // return Item(record.id, record.user_id, ...)
// }

// function bool isActive(item, datetime) {
    return item.start <= datetime && datetime <= item.expire
// }

function List<Record> fetch(userId) {
    // sql1 = "select * from user where id = $userId"
    // user = sql1.selectOne()
    // if bigbigbigPrivateCheckMethod1(user) { throw XxxException(...) }

    sql2 = "select * from item where fk = $userId"
    // items = sql2.selectAll()
    // if bigbigbigPrivateCheckMethod2(items) { throw XxxException(...) }

    // return items
}

// private function bool bigbigbigPrivateCheckMethod1(user) {
//     bla bla bla
//     bla bla bla
//     bla bla bla
// }

// private function bool bigbigbigPrivateCheckMethod2(user) {
//     bla bla bla
//     bla bla bla
//     bla bla bla
// }

ただ 仮説を検証できる箇所だけが気になった ので、数カ所で済んだのでした

たまたま上手くはまるストーリだったわけではないよ

商用環境で「通信エラーが出た」と聞けば、こんなロジックツリーを瞬時に描き

ユーザから「金額が合わない」と問い合わせを受ければ、こんなロジックツリーを瞬時に描くことができます

バグが見つかればデバッガでも print デバッグでもログチェックでもなんでも良いのだけど、常に🐞と真っ向勝負だと 腕が上がらない し、良いツールも 無駄撃ち してしまいます

たった一言から どれだけの仮説と検証方法を出す ことが出来るか、それに可能性やコストから 優先順位を付ける ことが出来るかが、腕の見せ所です

まとめ

エラーメッセージからロジックツリーが作れるかどうかは、そう訓練しないと出来る様にはずっとなりません

🐞に真正面から立ち向かわずに退路を一つずつ潰す様に普段から考えてみると良いと思います

本当の虫と違って🐞は移動しないので、頭を使ってちゃんとやれば必ずやれます

おまけ デバッグ時のコードリーディングのコツ

デバッグ時は「これ変数いらないのでは...」とか「英語変だろ...」とか「ここいずれバグりそう...」とか「え、なにこのメソッド名、中はどういう実装なんだろ」とかは一切考えてはいけません

今のあなたの仕事には関係ありません

デバッグとリファクタは分けて考えましょう

バグ調査は往往にして残念コードに向かい合うことになりますが、あちこち見てると脳内もエディタで開いたファイルもスタックが増えて調査の質が下がるし、時間もかかります
なにより残念コードを正面から見るとメンタルがやられます

集中して躱して躱して、ロジカルに一直線に愛しの🐞の元にたどり着きましょう

僕も前は調査をしながら「クソだろこれ」とか口に出してキレ散らかしながらやってましたが、周りにも自分にも結果にも良いことは一つもありませんでしたw

気になったことは一息ついてから「ところでさ」と切り出すのが良いですw

Discussion