Varnish4.0.3がリリースされました。
今回のリリースは公式で行ってる通り多くのfixがありますが重要なバグフィックスを含みます。
比較的遭遇しやすいRaceコンディションに起因するpanicが修正されています。
アップデート時の注意事項はありますが、基本的にアップデートをおすすめします。
変更内容から幾つか抜粋して紹介します。
バグフィックス
1650 – 複数のXFFヘッダがあった場合は折りたたむように修正しました
1620 – スレッドプールに空きが無い場合にclientスレッドを使うのを辞めました
空きが無いためbackgroundスレッドを作成出来ない場合にclientスレッドを使っていたのを辞めました。
また、フェッチするためにスレッドがない場合にカウントアップするカウンタfetch_no_threadが追加されました。
これがもし増えるような状況であればスレッド周りのパラメータ調整を行うと良いでしょう。
1566 – VCL中の「?」をエスケープするようにしました
1660 – SynthではRangeリクエストを無視するようになりました。
Synthでレスポンスを返すパスでrangeリクエストを受け付けた場合にassertしていたためです。
1637 – VEP(ESI処理)のコールバックが失敗した際にpanicしていたのをフェッチ失敗(503)として扱うようにしました
1665 – リクエストのタイムアウト計算をドキュメントに合わせました
リクエストのタイムアウトを計算する際にアイドルタイムを基準に計算していましたが
リクエストの最初のバイトを受け取った時間を基準に変更しました。
1672 – バックエンドが意図しない304をレスポンスしてきた場合にpanicしたのを修正しました
バックエンドに対してINM/IMSリクエストをしていないのに304をレスポンスしてきた場合にpanicしたのを修正しました。
1539 – lookupしようとしたオブジェクトがちょうどオブジェクトを開放していくスレッドに変更された際にpanicしてたのを修正しました
感覚的にですが、割と踏む確率が高かったバグです。
1349 – varnishadm:backend.set_healthyのマッチを修正しました
1623 – varnishhist:-dオプション使用時にsegfaultするのを修正しました
1378 – varnishncsa:印字不可能な文字をエスケープして出力するようにしました
1462 – varnishncsa:URLなどリクエストに関わる値は最初のエントリを利用しステータスコードなどレスポンスに関わるものは最後の値を使うように変更しました
いまいちわかりづらいのでIMSリクエストを送った場合のログで例をあげます
■4.0.2/varnishncsa
192.168.1.31 - - [19/Feb/2015:01:47:49 +0900] "GET http://192.168.1.37:6081/x.html HTTP/1.1" 200 0 "-" "Mozilla/5.0 (Windows NT 6.3; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0"
■4.0.3/varnishncsa
192.168.1.31 - - [19/Feb/2015:01:47:16 +0900] "GET http://192.168.1.37:6083/x.html HTTP/1.1" 304 0 "-" "Mozilla/5.0 (Windows NT 6.3; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0"
■4.0.2/varnishlog -graw -c
6 Begin c sess 0 HTTP/1
6 SessOpen c 192.168.1.31 59552 :6081 192.168.1.37 6081 1424279850.057539 15
6 Link c req 7 rxreq
7 Begin c req 6 rxreq
7 Timestamp c Start: 1424279850.057624 0.000000 0.000000
7 Timestamp c Req: 1424279850.057624 0.000000 0.000000
7 ReqStart c 192.168.1.31 59552
7 ReqMethod c GET
7 ReqURL c /x.html
7 ReqProtocol c HTTP/1.1
7 ReqHeader c Host: 192.168.1.37:6081
7 ReqHeader c User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0
7 ReqHeader c Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
7 ReqHeader c Accept-Language: ja,en-us;q=0.7,en;q=0.3
7 ReqHeader c Accept-Encoding: gzip, deflate
7 ReqHeader c Connection: keep-alive
7 ReqHeader c If-Modified-Since: Wed, 18 Feb 2015 16:43:37 GMT
7 ReqHeader c If-None-Match: "280ea4-b-50f5f855c1b9e"
7 ReqHeader c Cache-Control: max-age=0
7 ReqHeader c X-Forwarded-For: 192.168.1.31
7 VCL_call c RECV
7 VCL_return c hash
7 ReqUnset c Accept-Encoding: gzip, deflate
7 ReqHeader c Accept-Encoding: gzip
7 VCL_call c HASH
7 VCL_return c lookup
7 Debug c "XXXX MISS"
7 VCL_call c MISS
7 VCL_return c fetch
7 Link c bereq 8 fetch
7 Timestamp c Fetch: 1424279850.058979 0.001355 0.001355
7 RespProtocol c HTTP/1.1
7 RespStatus c 200★←これが使われた
7 RespReason c OK
7 RespHeader c Date: Wed, 18 Feb 2015 17:17:30 GMT
7 RespHeader c Server: Apache/2.2.22 (Ubuntu)
7 RespHeader c Last-Modified: Wed, 18 Feb 2015 16:43:37 GMT
7 RespHeader c ETag: "280ea4-b-50f5f855c1b9e"
7 RespHeader c Vary: Accept-Encoding
7 RespHeader c Content-Encoding: gzip
7 RespHeader c Content-Type: text/html
7 RespHeader c X-Varnish: 7
7 RespHeader c Age: 0
7 RespHeader c Via: 1.1 varnish-v4
7 VCL_call c DELIVER
7 VCL_return c deliver
7 Timestamp c Process: 1424279850.059049 0.001425 0.000070
7 RespProtocol c HTTP/1.1
7 RespStatus c 304★←本当はこれを使ってほしい
7 RespReason c Not Modified
7 RespReason c Not Modified
7 Debug c "RES_MODE 0"
7 RespHeader c Connection: keep-alive
7 Timestamp c Resp: 1424279850.059136 0.001513 0.000087
7 Debug c "XXX REF 2"
7 ReqAcct c 423 0 423 315 0 315
7 End c
■4.0.3/varnishlog -graw -c
32774 Begin c sess 0 HTTP/1
32774 SessOpen c 192.168.1.31 59586 :6083 192.168.1.37 6083 1424279998.331551 15
32774 Link c req 32775 rxreq
32775 Begin c req 32774 rxreq
32775 Timestamp c Start: 1424279998.331637 0.000000 0.000000
32775 Timestamp c Req: 1424279998.331637 0.000000 0.000000
32775 ReqStart c 192.168.1.31 59586
32775 ReqMethod c GET
32775 ReqURL c /x.html
32775 ReqProtocol c HTTP/1.1
32775 ReqHeader c Host: 192.168.1.37:6083
32775 ReqHeader c User-Agent: Mozilla/5.0 (Windows NT 6.3; WOW64; rv:35.0) Gecko/20100101 Firefox/35.0
32775 ReqHeader c Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
32775 ReqHeader c Accept-Language: ja,en-us;q=0.7,en;q=0.3
32775 ReqHeader c Accept-Encoding: gzip, deflate
32775 ReqHeader c Connection: keep-alive
32775 ReqHeader c If-Modified-Since: Wed, 18 Feb 2015 16:43:37 GMT
32775 ReqHeader c If-None-Match: "280ea4-b-50f5f855c1b9e"
32775 ReqHeader c Cache-Control: max-age=0
32775 ReqHeader c X-Forwarded-For: 192.168.1.31
32775 VCL_call c RECV
32775 VCL_return c hash
32775 ReqUnset c Accept-Encoding: gzip, deflate
32775 ReqHeader c Accept-Encoding: gzip
32775 VCL_call c HASH
32775 VCL_return c lookup
32775 Debug c "XXXX MISS"
32775 VCL_call c MISS
32775 VCL_return c fetch
32775 Link c bereq 32776 fetch
32775 Timestamp c Fetch: 1424279998.333049 0.001412 0.001412
32775 RespProtocol c HTTP/1.1
32775 RespStatus c 200
32775 RespReason c OK
32775 RespHeader c Date: Wed, 18 Feb 2015 17:19:58 GMT
32775 RespHeader c Server: Apache/2.2.22 (Ubuntu)
32775 RespHeader c Last-Modified: Wed, 18 Feb 2015 16:43:37 GMT
32775 RespHeader c ETag: "280ea4-b-50f5f855c1b9e"
32775 RespHeader c Vary: Accept-Encoding
32775 RespHeader c Content-Encoding: gzip
32775 RespHeader c Content-Length: 31
32775 RespHeader c Content-Type: text/html
32775 RespHeader c X-Varnish: 32775
32775 RespHeader c Age: 0
32775 RespHeader c Via: 1.1 varnish-v4
32775 VCL_call c DELIVER
32775 VCL_return c deliver
32775 Timestamp c Process: 1424279998.333124 0.001487 0.000075
32775 RespProtocol c HTTP/1.1
32775 RespStatus c 304★←これを使った（最後のエントリ）
32775 RespReason c Not Modified
32775 RespReason c Not Modified
32775 RespUnset c Content-Length: 31
32775 Debug c "RES_MODE 0"
32775 RespHeader c Connection: keep-alive
32775 Timestamp c Resp: 1424279998.333257 0.001620 0.000133
32775 Debug c "XXX REF 2"
32775 ReqAcct c 423 0 423 319 0 319
32775 End c
4.0.2の場合はステータス200でLength:0で帰ってきています。
これは最初に現れたRespStatusを利用したためです
期待しているのはdeliverする直前、つまり最後の値なわけで4.0.3では最後のRespStatusの304を出力するようになっています。
機能追加
vmod_std: VOID std.cache_req_body(BYTES)が追加されました
使い方については以前書いたこちらの記事を参照してください（Varnishでテストコードを書こう！～実践編～＋Bodyを読もう！）
vmod_std: TIME std.time(STRING,TIME)が追加されました
//VCL
std.log(""+now);
std.log(""+std.time("hogehoge",now));//無効な文字列を指定すると第二引数が使われる
std.log(""+std.time("Sun, 22 Feb 2015 00:0:00 GMT",now));
//結果
//- VCL_Log Sun, 22 Feb 2015 01:21:31 GMT
//- VCL_Log Sun, 22 Feb 2015 01:21:31 GMT
//- VCL_Log Sun, 22 Feb 2015 00:00:00 GMT
使用可能なフォーマットは
"Sun, 06 Nov 1994 08:49:37 GMT" "Sunday, 06-Nov-94 08:49:37 GMT" "Sun Nov 6 08:49:37 1994" "1994-11-06T08:49:37" "784111777.00" "784111777"
です
VCL変更
bereq.uncacheableがread-onlyになりました
obj.uncacheableがvcl_hitではなくvcl_deliverで使えるようになりました
パラメータ変更
fetch_chunksizeが128KBから16KBに変更されました
アップデート時の注意
fileストレージを利用している場合で空き容量が指定サイズを上回っている場合に
「larger than file system」と出て起動に失敗します。（関係するコミット）
Varnishのfileストレージを利用する場合にフラグメントを防ぐためにddで先にファイルを作っておく事を公式でも推奨していますが
既に確保しているサイズを考慮していないため、ddで事前確保しようとするとディスクサイズの50%以下しか使用できません。
一旦消してしまえば問題なく起動しますが注意が必要です。
また、この問題は当然ですが4.0.3にアップデートしたあとにrestartを行っても起きるので注意してください。(reloadは問題なしです)
あとでチケットきろうかなと思います。
