Future Tech Blog
フューチャー技術ブログ

新米エンジニアが1か月のトラブルシューティングで学んだこと


まえがき

はじめまして。TIG DXチームにアルバイトとして参加させていただいている本田直樹と申します。
昨年12月にAtCoder Jobs経由でアルバイト採用していただき、今月でちょうど半年になります。普段は文系大学生をしています。

採用後のアルバイトの作業は、

に携わらせていただいております。

今回は、アルバイト業務でシステム開発するにあたり、ProxyやDNSなどのネットワーク周りで一か月強も溶かしてしまったので、その過程で学んだトラブルとの向き合い方についてまとめます。

トラブルの内容

環境

  • WSL (Ubuntu 18.04)
  • Go言語(go1.14.2 linux/amd64)

※ VPN経由インターネットに接続する際は社内の認証付きプロキシサーバーを経由する。
VPNを経由しない場合は、認証なしでプロキシサーバーを経由する

エラーメッセージ

Go言語では、テストを走らせる(go test)際に、ソースコードでimportしている依存パッケージがローカルに存在するか確認し、ないものについてはgo get(適切なパスにgit cloneでパッケージをダウンロード)して、テストのための準備を自動でしてくれます。

今回のエラーは、go testの際に行われるgo getの部分で発生しました。エラーメッセージは以下の通りです。

1
2
3
4
5
$ go test
go: {パッケージ名}: unrecognized import path "{パッケージ名}"
(https fetch: Get https://{パッケージURL}?go-get=1:
proxyconnect tcp: dial tcp:
lookup http on {DNSサーバーのIPアドレス}:53: server misbehaving)

この事象はリモート環境の時のみ見られ、現在の出社できない状況(※フューチャーは2020/05/26時点では原則出社NG)ではこれを解決しないと開発に取り組めない状況でした。

コマンドプロンプトでの実行結果

全く同様の環境変数、git configgo envの設定で、コマンドプロンプトで実行したエラーメッセージは以下の通りです。

1
2
3
4
5
$ go test
go: {パッケージ名}: unrecognized import path "{パッケージ名}"
(https fetch: Get https://{パッケージURL}?go-get=1:
proxyconnect tcp: dial tcp: 52.206.222.245:443: connectex:
An attempt was made to access a socket in a way forbidden by its access permissions.

エラーメッセージが異なるので、別物の原因があるのかと思われましたが、結果的には同じ原因によって発生してることが後述の内容で分かります。

原因

プロキシの認証用に設定していたユーザー名、パスワードにURLで使用不可とされる(使う際にURLエンコードを必要とする)記号が含まれていて、go getコマンドの実行時にプロキシサーバのURLのパースに失敗していた。

解決に向けて行ったこと

0:原因の切り分けと仮説検証

この部分が最も自分が勉強になった部分で、他のケースでも参考になる部分だと思います。
こちらの記事も参考にさせていただきました。

問題が発生したときに、とるべき手順として、

1. トラブルの内容や起こった状況を明確にする
2. 原因となる可能性のある分野の切り分けを行う
3. 切り分けた内容からエラーの原因についての推測/仮説を立てる
4. 仮説を検証する
5. 検証結果から、新たな仮説に派生する場合はそれをエラー原因の候補に入れる
6. 解決していない場合は、追加の情報をもとに 2. から見直す

というように表現できるかと思います。

今回行った仮説の例としては

エラーメッセージにあるポート番号が53なので、DNSでつまずいてると仮定して/etc/resolv.confをいじってみる。
(nameserver 8.8.8.8の追記など)

などがあります。

また、この過程で試したことについてのログ(仮説の内容、検証の準備のための環境変数の設定、検証結果など)を記録していくことがとても大切です。ログにある過去の検証結果と照らし合わせて、原因となりうる候補を絞れたり、過去に試したことを再度行うような無駄を省くことができ、トラブルシュートに時間をかければかけるほど解決に近づいていきます。

1: 環境設定

go getでエラーが出ていることから、go getの挙動に影響を与えるような環境設定を列挙してみました。

  • 環境変数
  • git config
  • go env

同じく会社支給のマシンを使っていて、WSL環境、Windows DOS環境で同様のテストを成功している方々にご協力いただき、すべての環境設定を反映させてみました。

この検証から分かったことは以下の通りです。

  • ping, dig, nslookup などでのgo getの目的の名前解決は成功している
  • go get実行時にはDNSサーバーのmisbehavingのエラーが出る(先述のエラーと変化なし)
  • 別ディレクトリでgo getを実行すると
    • github.com/...で始まるパッケージは問題なく終了
    • 上記以外(golang.org/...など)のパッケージで上記のエラー

digで名前解決が成功しているにもかかわらず、go getではDNSサーバーでのエラーが引き続き出ていることから、より低いレイヤで何が起きているのかを知るためにWiresharkでパケット解析することにしました。

2: Wireshark

Wiresharkとは、ネットワークでやり取りするパケットを解析することができるツールです。
Wiresharkでキャプチャしながらgo testを走らせ、まずは自分のマシンからどこまでの通信が届いているのかを確認し、以下のような簡単な図にまとめました(IPアドレスなどは一例です)。

すると、以下のことが分かりました。

  • DNSの名前解決の時点で滞っている
  • httpというドメイン名をDNSサーバーに探していた。(リクエストの不正)
  • そのようなドメイン名は存在しないため、名前解決に失敗していた。

先述のエラーメッセージを振り返って見ると、

1
lookup http on {DNSサーバーのIPアドレス}:53: server misbehaving)

とありますが、これは文字通りhttpというドメイン名を名前解決しようとしていて、DNSに存在しないドメイン名を名前解決できずにエラーを返しているということが後から分かりました。

まさかhttpという文字列を見て、それを(プロトコルではなく)ドメイン名だとは思わなかったので、Wiresharkでやっとエラーの内容を正確に把握できました。

(小話)WSLとエラーメッセージが異なった理由

ちなみにですが、WSLなどlinux環境では、ドメイン名を探しに行くときに、DNSの設定ファイルである/etc/resolv.conf内にsearchの記述があれば、それをサフィックスとして探したいドメイン名の後にくっつけたパターンのドメイン名の名前解決も試してくれます。参考

Windows DOSの方の環境ではそれと同様の設定はいじっていなかったのですが、どうやらデフォルトで.co.jpというサフィックスをつけて探してくれていたので、たまたまそのドメイン名であるhttp.co.jpが実在し、名前解決に成功していました。ドメイン名のネーミングセンスが良くて感動しました。

結果として、ホストであるhttp.co.jpが許可していないポートへの接続を試みようとしてしまい、そのエラーが帰ってきていました。
それがWSL環境とのエラーメッセージが異なる理由でした。

3: URLエンコード

ある日、このトラブルが発生するより以前に、ポート番号が不正というエラーを見たことをふと思い出しました。そのエラーメッセージ内ポート番号は、数字ではなく自分の認証付きプロキシのパスワードでした。
認証付きプロキシの設定をみてみると、パスワードもポート番号も、:以降に位置します。

1
export HTTP_PROXY=http://${user}:${pass}@proxy.example.com:${port}/

このことから、プロキシ設定のパース処理で手こずっているのではという仮説を立てました。

プロキシ設定はURLなので、パース処理で問題が発生するとすればURLエンコーディングをすれば良いのではというのは妥当な思考かと思います。実際、自分のパスワードにはURLに使用不可とされるような記号を含んでいたため、それをエンコードしてあげた設定を環境変数に再設定し、go getが通ることを確認することができました。

4. その他の寄り道

解決までの道のりを簡潔に述べるために、解決に繋がることのなかった様々なトライアンドエラーを端折りました。しかし、冒頭に1か月と述べた通り、その期間の試行錯誤の中にはうまくいかない、もしくは結果的に意味をなさなかったものもありました。

泥臭い失敗の部分も残しておきたいので、上記以外にどのようなことを試したかを以下に残します。

  • DNSを8.8.8.8に変更
  • go env -w GO111MODULE-off
  • 別ディレクトリでの目的のgo getの実行
  • git confighttp.proxyなどの編集
  • GitHubのプロトコル切り替え(http <-> ssh)
  • …etc

振り返り

振り返ってみると、今まで集めた情報でここにたどり着ける可能性のあるヒントとして以下の3つがあります。

リモートでしかエラーが発生しない

出社時は認証なしのプロキシ、リモート時は認証付きのプロキシであることから、認証の部分に問題がある可能性は大いにある

1: 環境設定で自分以外はgo testを成功させていた

  • go test(およびgo get)に影響を与えるような環境設定は、列挙された3つしかないと仮定すると
  • go test に成功していた方々の環境設定を忠実に再現しても解決しなかった。
  • 環境設定でまだ個人差が出る可能性があるとすれば、個人に紐づけられたクレデンシャル
  • github.com/...で始まるパッケージは問題なく終了
  • これらのパッケージはローカルPCでキャッシュされていた可能性
  • キャッシュを消すか、キャッシュを利用しない設定にすればもっと早く原因がわかった?

結果論にはなりますが、もう少し仮説を考え抜いていたら、もっと早く解決できたかもしれません。

原因の切り分けや、仮説/推測を考えるような 手を動かさない時間 によって、それだけWiresharkでパケット解析をしたりするような時間を削減することができたことが分かります。

学んだこと

0:原因の切り分けと仮説検証について

私は、最初はログをとらず試行錯誤のみを(1か月の半分程度)していたので、以前にも試したことを再度試すなど無駄が非常に多かったです。自分は永遠にこのトラブルと戦わなきゃいけないのではないかと感じるほど進歩を感じませんでした。

手を動かす前に状況整理し、Educated Guess(知識や経験に基づいた推測)をしていくことや、ログをとって過去の検証結果と現在の結果を照らし合わせて情報を集めていくことは、暗闇の中を歩くようなトラブルシューティングを、階段を上るように一歩ずつ確実に進んでいくものに変えてくれると思いました。

原因の候補となりえる要素が有限であるという極めて現実的な仮定の下では、そのような姿勢で取り組むことは、どんなに可能性の薄い推測の検証をし続けていても、いつか必ず解決することができるということになります。

その他の仮説検証について

トラブルシューティングでは、様々なことを学ぶことができると思います。今回の経験から、プロキシやDNSなどについて自分の知識を深められたと思います。また、パケットの解析をする方法なども学ぶことができました。

おわりに

経験豊富であれば、トラブルシュートに数か月といった単位で消耗することはないかと思いますが、新米の自分でも今回のようなトラブルと正しく向き合う経験を積んでいくことで、その場しのぎでアドホックなものでない、学びや経験に結び付く有意義なトラブルシューティングをすることができると感じました。

今後トラブルに直面した時も、手を動かしたい気持ちを一旦抑えて、まずは状況を明確にして仮説をたて原因を切り分けていくところから始めて習慣づけていきたいと思います。

長文になりましたが、読んでくださった方が初心を思い出せる、また自分と同じような新人の方にとっては実りのあるものになれば幸いです。

読んでいただきありがとうございました。