OSSのバグに遭遇したときのトラブルシューティングのノウハウ
はじめに
本記事は、OSSのバグに遭遇したときのトラブルシューティングのノウハウについて、実例を基にして、ストーリー仕立てでなるべく具体的に書きました。このようなときの対処に不慣れな人に、実際のデバッグ、バグレポート、および修正案の提出までの流れを掴んでもらうことが目的です。
バグに遭遇
筆者も参加していたLinux Advent Calendar 2016に、ある日シェルスクリプト（Bash）で作るTwitterクライアントという記事が投稿されました。twitter APIの認証に使われているOAuth1.0aとshell芸に興味があったことより、この記事を読んでみることにしました。
そこで紹介されているtweet.shというbash製twitterクライアントを試そうとしたところ、出力は次のようになりました。
$ ./tweet.sh showme
�VMo�6�+��umZ_����b��4E
���F2�tH*�wHY�?�=�P֛7����>��<M� XE�<以下省略>$
いきなり何かがおかしいです。自分のtwitterアカウントに関するJSON形式のデータが返ってくるはずが、実際に返ってきたのは意味不明なバイナリデータでした。
その時、たまたま土地勘の無い分野の技術への関心が高かったのと[1]、それなりに自由な時間があったことより、デバッグしてみることにしました。
再現性の確認
デバッグでは同じ問題を簡単に再現できるかどうかが非常に重要です。ひとくちにバグと言っても、いつでもどこでも簡単な手順によって必ず再現できるものもありますし、数年に一回だけ不定期に発生する悪魔のようなものもあります。
幸いなことに、今回遭遇した問題の再現性は100%でした。
問題箇所の絞り込み
続いて、具体的にスクリプトのどの箇所で何が起きたのかを絞り込みました。無策でソースをいきなり見たりするのは手間暇がかかりますし、効率も悪いのです。
bashには、実行ログを表示する-xというオプションがあるので、それを使って問題発生箇所を特定することにしました。
$ bash -x ./tweet.sh showme
<省略>
++ curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json
^_<8B>^H^@^@^@^@^@^@^@<AC>VMo<E3>6^P<FD>+<82><AE>umZ_<96>^D<F4><D0><ED>b<8F><BD>4E<省略>$
curlコマンドでtwitter APIにリクエストを発行する際に問題が発生していることがわかりしました。
続いて、上記コマンドを単独で実行しても同じ問題が発生するかを確認しました。
$ curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json
^_<8B>^H^@^@^@^@^@^@^@<AC>VMo<E3>6^P<FD>+<82><AE>umZ_<96>^D<F4><D0><ED>b<8F><BD>4E<省略>$
発生しました。これで再現プログラムをcurlの実行１つだけに絞り込めました。
続いてバイナリデータが何者かを、わかる範囲で調べました。こういう時に役立つのがfileコマンドです。
$ ../tmp/bin/curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json | file -
/dev/stdin: gzip compressed data, from FAT filesystem (MS-DOS, OS/2, NT)
どうやら出力はgzipで圧縮されたデータのようでした。展開してみましょう。
$ curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json | gunzip
{"id":<略>}$
展開した結果はJSON形式のデータでした。これが本来得たかった出力です。なんとなくhttpの仕様にある、コンテンツボディの圧縮が関係していそうです。
別環境での再現性の確認
前節における確認と前後して、その時たまたまチャットをしていた同業者の友人に問題の再現依頼をしました。すると、友人の環境では問題が再現しないことがわかりました。これは問題の切り分けに非常に有用です。
次に、私と友人の環境の比較をするために、バージョンを確認しました。
私の環境(Debian testing(stretch))では次の通り。
$ curl --version
curl 7.50.1 (x86_64-pc-linux-gnu) libcurl/7.50.1 GnuTLS/3.5.7 zlib/1.2.8 libidn/1.33 libssh2/1.7.0 nghttp2/1.17.0 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp scp sftp smb smbs smtp smtps telnet tftp
Features: AsynchDNS IDN IPv6 Largefile GSS-API Kerberos SPNEGO NTLM NTLM_WB SSL libz TLS-SRP HTTP2 UnixSockets
$
友人の環境(Ubuntu14.04)では次の通り。
$ curl --version
curl 7.35.0 (x86_64-pc-linux-gnu) libcurl/7.35.0 OpenSSL/1.0.1f zlib/1.2.8 libidn/1.28 librtmp/2.3
Protocols: dict file ftp ftps gopher http https imap imaps ldap ldaps pop3 pop3s rtmp rtsp smtp smtps telnet tftp
Features: AsynchDNS GSS-Negotiate IDN IPv6 Largefile NTLM NTLM_WB SSL libz TLS-SRP
$
細かい違いはありますが、ここではバージョン名がそもそも違っていることに注目しました。友人をデバッグに付き合わせ続けるのは悪いので、自分の環境でも同じことが起きるかを確認しました。その際、upstreamのバージョン7.35.0をビルドして使いました。ビルドやインストールの手順は本筋ではないので省きます。
$ ../tmp/curl --version | head -1
curl 7.34.1-DEV (x86_64-pc-linux-gnu) libcurl/7.50.1-DEV OpenSSL/1.1.0c zlib/1.2.8 libidn/1.33 libssh2/1.7.0 nghttp2/1.17.0 librtmp/2.3
$ ../tmp/bin/curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json
{"id":...}$
正しくJSON形式のデータが返ってきました。
続いてupstreamの最新版で同じ問題が発生するかどうかを確かめました。
$ ../tmp/bin/curl --version | head -1
curl 7.52.2-DEV (x86_64-pc-linux-gnu) libcurl/7.52.2-DEV OpenSSL/1.1.0c zlib/1.2.8 libssh2/1.7.0 nghttp2/1.17.0 librtmp/2.3
$ ../tmp/bin/curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json
^_<8B>^H^@^@^@^@^@^@^@<AC>VMo<E3>6^P<FD>+<82><AE>umZ_<96>^D<F4><D0><ED>b<8F><BD>4E<省略>$
想定通り、問題が再現しました。
再現/非再現環境の差分を採取
再現/非再現環境が整ったので、両者の差分を比較しました。失敗時の出力はgzipで圧縮されていたことより、何となくhttpヘッダの違いが関係していそうという当たりがつけられました。curlには、リクエスト/レスポンスに付加されたhttpヘッダなどの詳細情報を出力できる-vというオプションがあるので、これを使うことにしました。
$ ../tmp/bin/curl --get --header 'Authorization: OAuth <省略>' --data '' --silent https://api.twitter.com/1.1/account/verify_credentials.json -v >/dev/null
両バージョンにおける上記コマンドを発行した際の出力を比較したものを示します。
$ diff -urNp ../out.{good,bad}
<省略>
+* Using HTTP2, server supports multi-use
+* Connection state changed (HTTP/2 confirmed)
+* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
<省略>
-> User-Agent: curl/7.34.1-DEV
+> User-Agent: curl/7.52.2-DEV
-< HTTP/1.1 200 OK
<省略>
+< HTTP/2 200
<省略>
+< content-encoding: gzip
この差分を表にまとめると次のようになります。
| バージョン | twitter APIへのアクセスプロトコル | curlが許容するエンコーディング形式(Accept-Encodingヘッダ) | レスポンスボディのエンコーディング形式(Content-Encodingヘッダ) |
|---|---|---|---|
| 7.35.0 | http1.1 | 未指定 | 未指定(生のJSON形式データであることを示す) |
| 最新版 | http2 | 未指定 | gzip |
これによって次のことがわかります。
- curlは7.35.0より後のいつの時点からか、twitter APIに対してデフォルトではhttp1.1ではなくhttp2によってアクセスするようになった
- twitter APIはhttp1.1によってAccept-Encodingヘッダ無しでアクセスされると無圧縮のレスポンスボディを返す
- 同http2によってAccept-Encodingヘッダ無しでアクセスされるとgzipで圧縮されたボディを返す
再現プログラムのさらなる簡略化
問題の再現に認証は関係無さそうなので、次のように認証なしで(Authorization タグ無しで)アクセスしても問題が再現するかを試しました。
以下7.35.0の場合。
$ ../tmp/bin/curl --get --silent https://api.twitter.com/1.1/account/verify_credentials.json | file -
/dev/stdin: ASCII text, with no line terminators
$
以下最新版の場合。
$ ../tmp/bin/curl --get --silent https://api.twitter.com/1.1/account/verify_credentials.json | file -
/dev/stdin: gzip compressed data, from FAT filesystem (MS-DOS, OS/2, NT)
$
これまでの再現プログラムの場合と同様、前者はテキスト形式、後者はgzip形式になりました。ここでは省略しますが、-vオプションを付加して得られるヘッダなどの出力の違いも、これまでの再現プログラムと同様です。また、前者の出力はJSON形式であり、後者の出力をgunzipにかけると前者と同じものが得られます。
仕様かバグか
httpヘッダの話に戻ります。Accept-Encodingヘッダを指定していないのにgzip圧縮されたデータを返すのは直感的には妙に思います。その直感が正しいのかどうかは仕様を読むことによって確認します。自分の思い込みをもとにして正否を判断してバグ報告したりすると会話にならずに撃沈必至です。
Accept-EncodingヘッダとContent-EncodingヘッダはそれぞれRFC7231 5.3.4とRFC7231 3.1.2.2において定義されています。
Accept-Encodingヘッダの項目には次のようなことが書かれています。
<省略>
A request without an Accept-Encoding header field implies
that the user agent has no preferences regarding content-codings.
Although this allows the server to use any content-coding in a response,
it does not imply that the user agent will be
able to correctly process all encodings.
<省略>
意訳すると「ユーザエージェントがAccept-Encodingヘッダを指定してなければサーバはボディをどんなふうにエンコーディングしてもいい。しかし、その場合ユーザエージェントは正しくデコード出来ないかもしれない」です。要するにAccept-Encodingヘッダを指定しなかった場合にgzipで圧縮されたボディを返すのは仕様違反ではないようです。
続いて、最新版を使って、下記のように圧縮を一切許さないようにリクエストを出すとどうなるかを確認しました。
$ curl --get --silent --header "Accept-Encoding: identity;q=1.0,*;q=0" https://api.twitter.com/1.1/account/verify_credentials.json | file -
/dev/stdin: gzip compressed data, from FAT filesystem (MS-DOS, OS/2, NT)
それでも出力は圧縮されていました。これは問題です。
バグレポートと修正
今回の問題のレポート先はtwitter developers forum[2]とtweet.shのgithubの2つです。
根本原因は１つなのですが、それぞれの場所に訴える内容は微妙に違います。これを間違えると、受け手にとっては「この場所でそんなこと言われても…」となるので注意が必要です。ではそれぞれについて具体的に何をしたのか見てみましょう。
twitter developers forumへの報告
ここには「twitter APIにhttp2で圧縮を許可せずにアクセスしても圧縮したレスポンスボディが返ってくることが問題である」と報告します。
報告前にはforumの過去ログを漁って、既存の問題かどうかを確認します。すると、vimやらGoやらで色々有名なmattn_jpさんがすでに報告していました。
自分の持っている情報に何も新規性が無ければここで撤退しますが、今回の場合は
Twitter API doesn't treat "Accept-Encoding: identity".
I'm guessing many twitter client that doesn't use browser may not work."
という記載があったので、curlで問題を再現できたことを追記しました。
このとき、どんな環境で何をしたら本来どうあるべきなのに、実際はこうなった、というのを簡潔に記載する必要があります。「なんだかわからないけどとにかくうまく動かなかった」とかいう報告では人は動かせません。
twitter APIについてはバグ報告者にこれ以上できることはありません。何らかの返信があるまで待ちです。ソースが公開されていないので、実装に踏み込んだ解析はできませんし、修正案の提示もできません。
2017年1月4日に公式スタッフの人から"I will share it with the team"という返信が来ていましたが、その後この問題はしばらく放置されることになります。続きは本記事の後のほうに書いています。
tweet.shのgithubへの報告
ここには「最近のcurlを使っているとtweet.shがうまく動作しないという問題がある」と報告します。twitter APIと異なりtweet.shはOSSなので、実装に踏み込んだ解析と修正案の提示ができます(提示した修正案を受け入れるかどうかは作者次第ですが)。今回はここまでやってみました。
まずは報告前に既存の報告および修正案があるかどうか、issueとpull requestの一覧を見ました。今回は該当無しでした。
修正については、やりかたは色々あるのですが、今回は、過去のcurlのようにhttp1.1を使ってtwitter APIにアクセスするという回避策を提案しました。以下がそのpull requestです。
このpull requestはなんと一時間以内にマージされました。それを知った時は、これこそOSSのダイナミズムだ、という思いがしました。OSSって本当にいいものですね(ステマ)。ここまでで、本筋はおしまいです。
余談ですが、このpull requestはバグの内容だけについて触れており、肝心の修正方法の説明が一切書いてません。これは書き忘れです。下書きには
Although this problem comes from twitter API's problem,
it wouldn't be fixed for a while (forever?).
Accessing to twitter API via http1.1 can be a workaround.
というような文言があったのですが、いつの間にか消えていました。大ポカですね、すいません。
twitterにようやく修正が入る
わたしがこの問題に気づいてから約1年後、元のmattn_jpさんの報告からさかのぼると約2年後の2018年1月3日に、この問題が修正されたとのアナウンスがtwitter社から、ようやく出ました。再現試験を実施したところ、たしかに修正されていました。
$ ./curl --get --http2 https://api.twitter.com/1.1/account/verify_credentials.json
{"errors":[{"code":215,"message":"Bad Authentication data."}]}
チケットも数日後にmattn_jpさんからの問い合わせをきっかけとして、closeされました。これにて根本原因であるtwitterの問題も解決しました。めでたしめでたし。
おわりに
本記事で述べたようなことを毎回やる必要はありません。やる気と時間を天秤にかけて、自分がどこまでやるのかを決めるとよいかと思います。飽きたら途中でやめてもいいんです。フィードバックは義務ではなく、あくまで任意であり、自分が楽しむことが最優先です。筆者も修正作成までは滅多にやりません。だいたいは、他にもっとやりたいことがあるからです。
もう一点。筆者が畑違いということもあり、上記のデバッグ方法は恐らく最適なものではありません[3]。それでも、そのような人が実際に問題に遭遇した際にどのような試行錯誤したのかというライブ感を大事にするために、あえて実際の手順をほぼそのまま記載しました。
Discussion