先日私の環境で起きた Vim に関する問題を調査した際の記録。一例なので汎用的に使える手法ではないけど、こういう感じのことをしているよというのを書き留めておきます。
結果的に無駄だった工程も書いています。1 本道で調査が進むことの方が珍しく、だいたい回り道します。
問題
「cgn で検索のマッチ対象を別のキーワードに置き換えたあと . で繰り返すと、Bell が発生する。」
cgn は c + gn で、gn は検索にマッチした範囲です。つまり検索にマッチした内容を c で書き換え、. で次のマッチ対象にも同様の変更を行います。1 つずつ確認しながら置換したい場合などによく使われる操作です。
問題について
Vim では不正な操作をした場合など様々な場面で警告としてベルを鳴らします。 例えばノーマルモードでそれ以上移動できない方向に移動しようとした場合など、割と些細なことでも鳴ったりします。
人によっては煩わしくて鳴らないように設定している人もいると思います。プラグインの利用者であればそれも良いかと思います。無効にしてしまえば今回の問題は解決します。
しかし、ベルを無効にすることはコンパイラの警告を全て無視しているようなものです。私は Vim プラグインの開発をしているので、些細な問題にも気付けるようにベルは有効にしています。
調査
ベルの厄介なところは、「何か問題が起きた」ということしかわからないところです。メッセージすらない…ハードモードです。
何由来のベルか調べてみる
ベルは 'belloff' オプションを使うことで種類ごとに抑制できます。これを使えば何の操作でのベルか絞れるかも…? と思って設定してみることに。
たぶんこれかな…と思い最初に error を設定してみると、見事エラーは抑制されました。
error は「その他のエラー」。何もわからないということがわかった…1。結果的にこの調査は完全に無意味でした。そういうこともある。
キーマッピングを確認する
. でエラーが起きるので、. に何か機能が割り当てられていないか確認。repeat.vim をインストールしていたのでこの辺りかもしれないと睨みました。
しかし実際に nmap . で設定を調べてみると、何も割り当てられておらず。repeat.vim にはいくつか派生バージョンがありますが、私が使っているものは repeat#set() が呼ばれるまでキーマッピングの設定をしないようです。
またもあてが外れましたが、徐々に絞れてきています。
autocmd を確認する
. がデフォルトのままだとすると、そこでエラーが起きるとすれば autocmd の発動によるものである可能性が高いです。
. で起きるイベントとなると…たぶん TextChanged かな? ということで TextChanged について調べることに。
:autocmd TextChanged
--- Auto-Commands ---
ALERunOnTextChangedGroup TextChanged
* call ale#Queue(g:ale_lint_delay)
anzu TextChanged
* call anzu#clear_search_cache()
vimconsole TextChanged
* :call <sid>text_changed()
plugin-wtrans TextChanged
wtrans://source/*
call wtrans#buffer#translate(expand('<amatch>'))
neosnippet TextChanged
* call neosnippet#handlers#_restore_unnamed_register()
plugin-unite TextChanged
<buffer=2>
call unite#handlers#_on_text_changed()
内容は記事執筆時点で再現のために出したものなので調査時とは少し違うかもしれません。
ともあれこの中に原因があると踏んで、1 つずつイベントを削除して、問題が再現するか確認します。ただし plugin-wtrans と plugin-unite はパターン的に発動しないことが明確なので最初から除外可能です。
:autocmd! ALERunOnTextChangedGroup TextChanged
1 つずつ消して、問題が再現するか試していきます。しかし全部消してもエラーは出続けました。むむむ。
実際に起きている autocmd を確認する
ざっくり雑に TextChanged かな、と疑ってみましたが、そもそもこの予想が外れていそうです。実際に起きているイベントを確認してみることに。
こういう場合は 'verbosefile' を使うと便利です。
:set verbosefile=/home/thinca/log.txt :8verbose normal . :set verbosefile=
起きたイベントがファイルに記録されます。ログレベル2をもっと上げれば、実行された全てのスクリプトの行が記録されるので、それを使うこともありますが…今回はベル。ベルは記録されていないので、全てのログを出してもどこで問題が起きたかはわかりません。そこで今回はイベントだけ出します。
と言うわけで実行してみた結果(一部抜粋):
InsertEnter Auto commands for "*" を実行しています InsertLeave Auto commands for "*" を実行しています
InsertEnter と InsertLeave でした！そもそも TextChanged は実行されてなかった。
考えてみれば cgn は一旦挿入モードに入ってテキストを変更するので、. でリピートしたとしてもそこは変わらないわけですね。
というわけで今度こそ。
InsertEnter のイベントを確認する
先ほどやったように 1 つずつイベントを消して、再現するかどうか確認します。すると、以下の箇所で問題が発生していることがわかりました。
neocomplete InsertEnter
* call neocomplete#handler#_do_auto_complete('InsertEnter')
ここまでわかればあとは該当コードを追っていけば良さそうです。
該当コードを追ってみる
この先はおまけ。該当コードは以下のようなもの。
function! neocomplete#handler#_do_auto_complete(event) abort "{{{ if s:check_in_do_auto_complete(a:event) return endif if g:neocomplete#auto_complete_delay > 0 && has('timers') \ && (!has('gui_macvim') || has('patch-8.0.95')) if exists('s:timer') call timer_stop(s:timer.id) endif if a:event !=# 'Manual' let s:timer = { 'event': a:event } let s:timer.id = timer_start( \ g:neocomplete#auto_complete_delay, \ function('s:complete_delay')) return endif endif return s:do_auto_complete(a:event) endfunction"}}}
+timer が利用可能な場合に少し待ったのちに s:complete_delay() を呼び出しています。s:complete_delay() 内では、補完処理を行っています。
ここで実際に起きている処理を思い出して見ます。cgn を . で繰り返すと、一瞬挿入モードに入ってすぐに抜けるのでした。つまり s:complete_delay() が呼び出される頃にはすでに挿入モードを抜けています。今回の問題は、ノーマルモードで補完処理を行おうとして起きていたものでした。
ちなみに、この問題はすでに修正してもらえました。Shougo さん、ありがとうございます！
まとめ
Vim で問題が起きた際の調査の一例でした。
今回の例は再現率が 100 % だったのでなんとかなりました。トリガーがわからないとその分難しくなります。
他に汎用的な手法として、プラグインを少しずつ無効にしていってどのプラグインが原因か調べる方法もあります。プラグイン数が多いと大変ですが、確実性は高いです。問題を起こしているプラグインさえ特定できれば、最悪原因がわからなくても最小構成での再現を作ることでバグレポートを出すこともできます。
バグ調査は地道な作業ですが、快適な編集環境のためにできることからやっていきましょう。
