ローカルホストが突然全く反応しなくなります

Question

現象

GoでLocalhostを立て、そこにブラウザでアクセスする形式（同一マシン内）のアプリケーションを作成しているのですが、
ときどきローカルホストから全くレスポンスが返ってこなくなるという事象が生じており、非常に困っています。

たとえば以下のようになります。

1. しばらく正常に動作している
2. リクエスト1をおこなう　→すると突然レスポンスが返ってこない
3. このあと、リクエスト2、リクエスト3と続けてリクエストを出しても、全て無反応となる。

上記のように、ときどきローカルホストが全く無反応の状態になります。

ローカルホストが動作しているWindowsのdos窓を見ると、リクエスト1の時点でログの流れがストップしています。
しかしここでdos窓をクリックしてf5キーを押すと、突然ログが流れ始めます。そして、リクエスト1,2,3に対するレスポンスが一度に返ってきます。

環境などは以下です。

Win10 64bit
Go1.13
github.com/gorilla/mux を利用

r := mux.NewRouter()
r.HandleFunc("/path", Func).Methods("GET", "POST", "OPTIONS")  ...

srv := http.Server{
	Addr:              ":48000",
	Handler:           r,
	TLSConfig:         nil,
	ReadTimeout:       0,
	ReadHeaderTimeout: 0,
	WriteTimeout:      0,
	IdleTimeout:       0,
	MaxHeaderBytes:    0,
	TLSNextProto:      nil,
	ConnState:         nil,
	ErrorLog:          nil,
	BaseContext:       nil,
	ConnContext:       nil,
}
srv.SetKeepAlivesEnabled(false)  //keepaliveが悪影響を及ぼす場合があると聞いてオフにしてみた
err := srv.ListenAndServe()
if err != nil {
	log.Fatalf(err.Error())
}

条件、再現性など

上記停止現象の発生条件は分かりません。

メソッドはget のときも postのときもあります。
またlocalhost内でエラー（ロジックに由来するエラー）が起きているときもありますが、全く問題が無い（リクエストは所定の形式でなされており、ローカルホストでの処理中のエラーも起きていない）場合もあります。

リクエストはブラウザ(fetchを使用)から送る場合でも、ツール（postmanを使用）で送る場合でも発生します。
発生頻度はそれなりに高く、リクエスト数十回に1回くらい見かける印象です（プロダクトでこの頻度だと使い物にならないと思います）。

以上のような状況であるため、この場合にこうなるというのは見つかられていません。あるとき突然なるという認識です。
ただしその状態が生じた場合、「dos窓をクリックしてf5キー」によって確実に回復します。これは今のところ例外無しです。

試したこと

正直なにが起きているのかよく理解できていません。
F5キーで回復するというところに何か現象を理解するヒントがあるようには思えるのですが。
keepaliveが悪影響を及ぼす場合があるという情報を見かけたので、srv.SetKeepAlivesEnabled(false)としてみましたが改善しませんでした。

質問

以上のような状況ですが、どのように対処したらよいでしょうか。
アプリケーションの動作の根幹にかかわる部分で、かなり深刻なのですが、解決方法が分からず非常に困っています。
アドバイスいただければ幸いです。
よろしくお願いいたします。

追記：サンプルコード

ご指摘を受け、実際のプログラムの挙動に似せたものをサンプルコードとして作成してみました。

これを作っている過程で気づいたのですが、このプログラムはグローバル変数としてキャッシュを持っています。
そのキャッシュデータに対する同時アクセス制御（mutex）に問題があるのではないかと思い、mutexまわりをいくつか修正してみたところ、停止現象がかなり減った感じがしています。
そのため現時点ではグローバル変数への同時アクセスが影響しているのではないかと疑っています。
（ただし、それがF5で解消するというのもよく分からない話のように思え、この点の疑問は残っています）

実際のプログラムに似せるため、プログラム内にファイルシステムへのアクセスが存在します。ご注意お願いします。

package main

import (
	"bufio"
	"encoding/json"
	"io/ioutil"
	"log"
	"net/http"
	"os"
	"path"
	"strconv"
	"sync"

	"github.com/gorilla/mux"
)

var (
	DataCache = map[string]string{}
	Datapath  string
	mutex     sync.RWMutex
)

type res_ping struct {
	Msg string `json:"msg"`
}

func GetPing(w http.ResponseWriter, r *http.Request) {
	log.Println("GetPingStart")
	defer log.Println("GetPingEnd")

	res := res_ping{Msg: "server_alive"}
	b, _ := json.Marshal(res)
	w.Write(b)
}

type res_get struct {
	Msg string `json:"msg"`
}

func GetData(w http.ResponseWriter, r *http.Request) {
	log.Println("GetDataStart")
	defer log.Println("GetDataEnd")

	line, _ := mux.Vars(r)["line"]

	if line == "" {
		line = "0"
	}
	mutex.RLock()
	msg := DataCache[line]
	mutex.RUnlock()

	res := res_get{Msg: msg}
	b, _ := json.Marshal(res)
	w.Write(b)

}

type req_post struct {
	Data string `json:"data"`
}

type res_post struct {
	Msg string `json:"msg"`
}

func PostData(w http.ResponseWriter, r *http.Request) {
	log.Println("PostDataStart")
	defer log.Println("PostDataEnd")

	body := r.Body
	defer body.Close()
	b, _ := ioutil.ReadAll(body)
	req := req_post{}
	_ = json.Unmarshal(b, &req)
	data := req.Data

	mutex.Lock()
	defer mutex.Unlock()
	file, _ := os.OpenFile(Datapath, os.O_WRONLY|os.O_APPEND, 0666)
	defer file.Close()
	file.WriteString(data + "\n")
	file.Close()
	readdata()

	res := res_post{Msg: "OK"}
	rb, _ := json.Marshal(res)
	w.Write(rb)

}

func SetJsonheader(w http.ResponseWriter) {
	w.Header().Set("Content-Type", "application/json")
}

func Wrap(f func(w http.ResponseWriter, r *http.Request)) func(w http.ResponseWriter, r *http.Request) {
	return func(w http.ResponseWriter, r *http.Request) {
		EnableCors(&w)
		SetJsonheader(w)
		f(w, r)
	}
}

func EnableCors(w *http.ResponseWriter) {
	(*w).Header().Set("Access-Control-Allow-Origin", "http://localhost:8004")
	(*w).Header().Set("Access-Control-Allow-Methods", "POST, GET, OPTIONS, PUT, DELETE")
	(*w).Header().Set("Access-Control-Allow-Headers", "Accept, Content-Type, Content-Length, Accept-Encoding, X-CSRF-Token, Authorization")
}

func setup() {
	log.Println(Datapath)
	file, err := os.Create(Datapath)
	if err != nil {
		log.Fatal(err)
	}
	defer file.Close()
	// 実際の挙動に近づけるためにファイル書き込み（データ多め）をおこなっています。問題があれば適宜修正してください。
	for i := 0; i < 10000; i++ {
		_, _ = file.WriteString("data898999898989898998989ddddd\n")
	}
	file.Close()

	readdata()
	//DataCache["0"] = "data0"
	//DataCache["1"] = "data1"
	//DataCache["2"] = "data2"
}

func readdata() {
	file, _ := os.Open(Datapath)
	defer file.Close()
	sc := bufio.NewScanner(file)
	count := 0
	for sc.Scan() {
		DataCache[strconv.Itoa(count)] = sc.Text()
		count++
	}
}

func main() {

	datadir := os.TempDir()
	datapath := path.Join(datadir, "data_6f3eb709jlgq0w2h.txt")
	Datapath = datapath
	setup()
	defer os.Remove(datapath)

	r := mux.NewRouter()
	r.HandleFunc("/ping", Wrap(GetPing)).Methods("GET", "POST", "OPTIONS")
	r.HandleFunc("/data/{line}", Wrap(GetData)).Methods("GET", "OPTIONS")
	r.HandleFunc("/data", Wrap(GetData)).Methods("GET", "OPTIONS")
	r.HandleFunc("/data", Wrap(PostData)).Methods("POST", "OPTIONS")

	srv := http.Server{
		Addr:              ":48000",
		Handler:           r,
		TLSConfig:         nil,
		ReadTimeout:       0,
		ReadHeaderTimeout: 0,
		WriteTimeout:      0,
		IdleTimeout:       0,
		MaxHeaderBytes:    0,
		TLSNextProto:      nil,
		ConnState:         nil,
		ErrorLog:          nil,
		BaseContext:       nil,
		ConnContext:       nil,
	}
	log.Println("start")
	srv.SetKeepAlivesEnabled(false)
	err := srv.ListenAndServe()
	if err != nil {
		log.Fatalf(err.Error())
	}
}

Comments

[nobonobo]

セキュリティソフトにブロックされていないか確認してみてください。
また、パッと試せるよう動作可能なコードを貼ってもらえると回答しやすいです。
（問題が再現する最小のコードだとより助かります）

[nobonobo]

みれるコードをみてみたところおかしいところはなさそうです。(Windows10で問題なく動作することを確認しました)

[ryoyai]

ご回答ありがとうございます。サンプルコードを追加してみました。
そこにも書きましたが、mutex関連の問題があるのではないか？と現在考え中です。

[ryoyai]

なお、上記サンプルコードでは停止現象は再現できていません。（サンプルコードのmutex周りを悪いほうにいじって、現象を再現できたらおそらくヒットということになるかもしれません）

[nobonobo]

あ、*http.RequestのBodyはCloseしてはいけません。それが原因かはまだわかりませんが。

[nobonobo]

コネクション数の制御がおかしくなってる可能性は高いです。

[ryoyai]

！　Bodyの件、こちらですか。始めて知りました。ありがとうございます。

type Request
// Body is the request's body.
//
// For client requests, a nil body means the request has no
// body, such as a GET request. The HTTP Client's Transport
// is responsible for calling the Close method.
//
// For server requests, the Request Body is always non-nil
// but will return EOF immediately when no body is present.
// The Server will close the request body. The ServeHTTP
// Handler does not need to.
Body io.ReadCloser
https://golang.org/pkg/net/http/#Request

[ryoyai]

数日間問題が起きていないので、一応解決したということにして、まとめを投稿しました。ご丁寧に対応いただきありがとうございました。

Answer 1

数日間、停止現象は出ていません。完璧とは言えませんが、一応解決としたいと思います。
以下、知見を記します。

変数への同時読み書きに注意

GolangのLocalhostが特段のエラー表示も無く突然動作を停止する場合、変数に対する同時読み書き（以下、同時RW）が問題となっている可能性があります。
グローバル変数にキャッシュを持たせているような構成の場合には特に注意してください。

Goのサーバーは標準で並行処理を行います（goroutine）。サーバー内でグローバル変数を考え無しに利用すると、常に変数への同時RWのリスクが生じます。
手元の検証結果によれば、Mapへの同時RWはすぐにPanicを起こしますが、stringや構造体への同時RWはPanicを起こすとは限らないようです（検証範囲ではPanicが起きなかった）。そのため問題の発見が難しくなるかもしれません。

変数の同時RWを理解する上で、下記の記事が役に立ちました。注意則を抽出するならば、**「複数のプロセスから、対策無しに同じ変数を扱うことは、常に危険である」**と言えると思います。

Goでスレッド（goroutine）セーフなプログラムを書くために必ず注意しなければいけない点

Mutexの利用

変数の同時アクセスの制御には、sync.Mutexを利用します。（サンプルコード参照）
sync.Mutexはインスタンスごとにロックアンロックのスコープ？を持ちますので、変数A,B,Cについてそれぞれ別の制御をおこなうならば、3つのMutexをインスタンス化し、それをなんらかの方法で共有します（引数での受け渡しのほか、Mutex自体をグローバル変数として共有しても問題無いと理解しています）。

完全ではないものの、以上で一応の解決としたいと思います。

補足：サンプルコードの重要性

なお、途中でサンプルコードを作るようにという助言をいただきました。
掲載したサンプルコードを作るのに90分を要しましたが、作っている過程で上記の問題にすぐに気づくことができました。
また、その後、本番プロダクトでは難しい「実験」に利用することもできるようになって、利便性も感じています。
本質部分で本番コードと似たサンプルコードを作る、というのは、もちろん基本と言えると思いますが、あらためて有用性を理解しました。

Comments

[nobonobo]

全ての型の値について同時読み書きが不定な挙動を招くことはありません。
起こるとすれば正常に読み書きか、panicかの二択です。スライスは意図しないでデータセットになる可能性はありますが、勝手に処理が中断するようなことはありません。

[nobonobo]

停止したかのような挙動はデッドロックしたgoroutineが発生しているか、panicを捨てている処理があるはず（http.Serverはrecover処理で補足したpanicをErrorLogまたは標準ロガーで出力しようとします）