突貫工事で、複数人が入力したデータを、CSV形式でファイルダウンロードするWebアプリケーションをリリースしました。
利用したのは以下のOSSです。
- Spring Boot 2.2.4.RELEASE
- 組み込みのTomcat 9.0.30
- Chrome 79.0.3945.130
運用開始当日は特に問題がなく、退社して友達と飲んでたら、何やら自分のスマホが騒がしい。。。着信に出てみると「ダウンロードができない」との連絡が。詳細を確認すると「3時間前まではダウンロードを行うとCSVファイルが出力されていたのに、突然、ブラウザ上にCSVが表示されるようになった」とのこと。
友人に誤り、飲みを切り上げ、原因の調査を開始。一応、こう修正すれば動くというが判ったので、まずはサービス優先でリリースしました。しかし、原理が不明なままなので、継続調査を実施しました。
修正の内容
以下は、今回の問題となったダウンロード処理の簡略化したコードと、修正後のコードです。
- 修正前
@PostMapping
fun export(response: HttpServletResponse) {
/**
* CSVをresponse.outputStreamに書き込む。
*/
response.contentType = "text/csv"
response.setHeader("Content-Disposition", "attachment; filename=export.csv")
response.outputStream.flush()
}
- 修正後
@PostMapping
fun export(response: HttpServletResponse) {
response.contentType = "text/csv"
response.setHeader("Content-Disposition", "attachment; filename=export.csv")
/**
* CSVをresponse.outputStreamに書き込む。
*/
response.outputStream.flush()
}
要はContent-TypeとContent-Dispositionが、outputStreamへの書き込みの後か前かです。
その後の調査ではContent-Dispositionが前にあれば、ファイルダウンロードされることが判りました。
なぜoutputStreamへの書き込みの後にContent-Dispositionの設定を行ったかと言えば、たまたま参考にした記事がこうだったのと、ヘッダの設定とボディ（ストリーム）への書き込みは独立した処理だと思っていたという理由です。
原因調査
ただ、outputStreamへの書き込みの後にContent-Dispositionを設定しても、しばらくは正常にファイルダウンロードができていたので、CSV出力のサイズが影響していることが推測できます。そこで画面にデータサイズを入力し、そのサイズのCSV出力を行う再現プログラムを作成してみました。
@PostMapping
fun export(@RequestParam size: Int, response: HttpServletResponse) {
(1..size).forEach {
response.outputStream.print("a")
}
response.contentType = "text/csv"
response.setHeader("Content-Disposition", "attachment; filename=export.csv")
response.outputStream.flush()
}
すると、サイズが8KByteだとChromeの開発者ツールで確認した応答ヘッダは
Connection: keep-alive
Content-Disposition: attachment; filename=export.csv
Content-Type: text/csv
Date: Sat, 08 Feb 2020 10:26:07 GMT
Keep-Alive: timeout=60
Transfer-Encoding: chunked
でしたが9KByteだと
Connection: keep-alive
Date: Sat, 08 Feb 2020 10:27:48 GMT
Keep-Alive: timeout=60
Transfer-Encoding: chunked
のようにContent-Dispositionが消えてしまうではありませんか！突き詰めて行くと8191byteだと前者で、8192byteだと後者になります。
2の累乗である8192が設定された何かを超えたことが影響していると思います。
考察
おそらくは以下のようなことがTomcatで発生しているのだと考えています。
- HTTPボディへの出力が8191byte以下ならHTTPヘッダと一緒にデータを送り出せる。
- けど、HTTPボディへの出力が8192byte以上になると、そこまでのHTTPヘッダ情報を送信してから、8191byte単位にHTTPボディを送信する。
- なのでHTTPボディへの出力後に、HTTPヘッダの設定を行っても、既にHTTPヘッダが送信済みなために、その設定は破棄されてしまった。
原因調査2
そこで手っ取り早くtcpdumpでパケットを監視しながら、デバッガで8190byteから1byteずつ書き込みをステップ実行してみたところ、8192byteを書き込んだところでブラウザにHTTPヘッダとボディが送信されていることが確認できました。
ついでに、8192byteを書き込時にステップインしていくと、以下のコードがありました。
public void append(byte src[], int off, int len) throws IOException {
if (bb.remaining() == 0) {
appendByteArray(src, off, len);
} else {
int n = transfer(src, off, len, bb);
len = len - n;
off = off + n;
if (isFull(bb)) {
flushByteBuffer();
appendByteArray(src, off, len);
}
}
}
bbはByteBuffer型のメンバ変数で、appendByteArrayおよびtransferメソッド内でbbに送信データを蓄積しています。
isFullメソッドではbbに蓄積されたサイズが許容量に達するとtrueになり、flushByteBufferメソッドでブラウザへ送信します。
flushByteBufferメソッドの中を更に追うと、
@Override
public int doWrite(ByteBuffer chunk) throws IOException {
if (!response.isCommitted()) {
// Send the connector a request for commit. The connector should
// then validate the headers, send them (using sendHeaders) and
// set the filters accordingly.
response.action(ActionCode.COMMIT, null);
}
if (lastActiveFilter == -1) {
return outputStreamOutputBuffer.doWrite(chunk);
} else {
return activeFilters[lastActiveFilter].doWrite(chunk);
}
}
コミット済みでなければ、コミット処理を行う中でHTTPヘッダを送信して、コミット済みフラグをセットします。
それ以降は、HTTPボディの書き込みが行われます。
考察2
ということで安易に作ってしまったコードが、たまたま意図した動作をしていたから気づかずにリリースしてしまいましたが、さまざまなサイズの処理を行うTomcat側の苦労を考えれば当然の実装で、そこにわざわざハマりにいってしまったというお話でした。
(2020/2/8) 投稿。
(2020/2/9) 原因調査で事象が前後で切り替わるサイズの誤記を修正。原因調査2と考察を追記。