SSL通信時、切断処理で例外が発生するとCPU使用率が上昇する
20141016_tcp_session.cpp.patch 20141016_tcp_session.h.patch 20141016_tcp_ssl_socket.h.patch
UltraMonkey-L7
Forkたるすぴです。
Windows7上のChromeでF5をキーリピートで連打させると再現しました。
ただし、後ろのWebサーバはKeepAlive Onにしないとだめで、
KeepAliveのタイムアウトを過ぎたりすると、症状が治まったり
しました。
そして、雲雀さんのパッチを適用したら再現しないことを確認しました。
(解析)
Cpuコアの一つがほぼ100%usedになったところで、core dump。
最初にifdef DEBUGを外したバイナリで実施すると、try_againの
中のdebug文用mallocのところでした。
ifdef DEBUGを復活させて再現させると、ecをとってくる手前の
ec取得メソッド呼び出しで、SSL_shutdownはread途中、Unwindの中
にいました。
(gdb) p {SSL }0x7ff40c709170
$1 = {
version = 769,
type = 8192,
method = 0x3261255840,
rbio = 0x7ff40c02c860,
wbio = 0x7ff40c02c860,
bbio = 0x0,
rwstate = 3,
in_handshake = 0,
handshake_func = 0x326101cd30 <ssl3_accept>,
server = 1,
new_session = 0,
quiet_shutdown = 0,
shutdown = 1,
state = 3,
rstate = 240,
init_buf = 0x0,
init_msg = 0x7ff40c73c1d4,
init_num = 0,
init_off = 0,
packet = 0x7ff40c145773 "\027\003\001\001@ET /favicon.ico
HTTP/1.1\r\nHost: 192.168.200.130\r\nConnection: keep-alive\r\nAccept:
*/*\r\nUser-Agent: Mozilla/5.0 (Windows NT 6.1; WOW64)
AppleWebKit/537.36 (KHTML, like Gecko) Chrome/38.0.2125.122 S"...,
packet_length = 0,
s2 = 0x0,
s3 = 0x7ff40c0d3260,
d1 = 0x0,
read_ahead = 0,
msg_callback = 0,
msg_callback_arg = 0x0,
hit = 1,
param = 0x7ff40c066120,
cipher_list = 0x0,
cipher_list_by_id = 0x0,
mac_flags = 0,
enc_read_ctx = 0x7ff40c18e400,
read_hash = 0x7ff40c018500,
expand = 0x0,
enc_write_ctx = 0x7ff40c4aa9a0,
write_hash = 0x7ff40c641300,
compress = 0x0,
cert = 0x7ff40c002320,
sid_ctx_length = 11,
sid_ctx = "ultramonkey", '\000' <repeats 20 times>,
session = 0x7ff40c72d770,
generate_session_id = 0,
verify_mode = 0,
verify_callback = 0,
info_callback = 0,
error = 0,
error_code = 0,
kssl_ctx = 0x7ff40c282b20,
psk_client_callback = 0,
psk_server_callback = 0,
ctx = 0x1c43e10,
debug = 0,
verify_result = 0,
ex_data = {
sk = 0x0,
dummy = 0
},
client_CA = 0x0,
references = 1,
options = 18446744071578849271,
mode = 3,
max_cert_list = 102400,
first_packet = 0,
client_version = 769,
max_send_fragment = 16384,
tlsext_debug_cb = 0,
tlsext_debug_arg = 0x0,
tlsext_hostname = 0x0,
servername_done = 0,
tlsext_status_type = -1,
tlsext_status_expected = 0,
tlsext_ocsp_ids = 0x0,
tlsext_ocsp_exts = 0x0,
tlsext_ocsp_resp = 0x0,
tlsext_ocsp_resplen = -1,
tlsext_ticket_expected = 0,
tlsext_opaque_prf_input = 0x0,
tlsext_opaque_prf_input_len = 0,
tlsext_session_ticket = 0x0,
tls_session_ticket_ext_cb = 0,
tls_session_ticket_ext_cb_arg = 0x0,
tls_session_secret_cb = 0,
tls_session_secret_cb_arg = 0x0,
initial_ctx = 0x1c43e10
(gdb) p sys_error_code
$10 = <value optimized out>
(gdb) p is_operation_done
$11 = false
(gdb) p is_read_needed
$12 = <value optimized out>
(gdb) p is_write_needed
$13 = false
(gdb) p is_shut_down_received
$15 = false
(gdb) p is_shut_down_sent
$16 = <value optimized out>
int start()
{
int rc = primitive_( session_ );
...
if (!is_operation_done && !is_write_needed)
{
// We may have left over data that we can pass to SSL immediately
if (recv_buf_.get_data_len() > 0) {
// Pass the buffered data to SSL
int written = ::BIO_write
(
ssl_bio_,
recv_buf_.get_data_start(),
recv_buf_.get_data_len()
);
if (written > 0)
{
if (!BIO_should_retry(ssl_bio_))
{
// Some serios error with BIO....
return handler_(boost::asio::error::no_recovery, 0);
}
}
return start(); }
else if (is_read_needed || (is_shut_down_sent &&
!is_shut_down_received))
{
=> return read_();
}
}
recv_buf_.get_data_len()が0以下でis_read_neededフラグがたつのが
ちょっと変ですが、まあ大まかには間違ってなさそう。
ハーフクローズのclose notifyはreadで受け取ることが可能・・・なはず。
shutdownのハーフクローズはrecvバッファとは関係ないので、本来なら
recvバッファが正かどうかとの排他にしちゃいかんとは思いますが。
さらに言うと、その前のis_operation_doneとis_write_neededの両方が
falseのときっていう条件がいまいちです。
read/writeはともかくshutdownでは関係ない・・・
どっちかがtrueだとハーフクローズでclose notifyを受け取ることがなくなる。
大体、is_operation_doneがtrueのときはwriteしようと思っても
SSLソケットは閉じちゃっててwrite出来ないと思う。
SSL_shutdownの返り値が1,0,-1の3値なのを、booleanのtrueとfalseの
2値に丸めちゃって、状態をカバーしきれてない感じです。
あと、read/writeとshutdownはかなりリカバリ処理違うのに、無理やり
同じメソッドにまとめようとして、結果としてメソッド内にif文で場合分け
してshutdownだけ別の処理を書くという・・・まるでconstractorに全処理を
書いちゃったかのような状態になっています。
いけてない・・・
このままclose notifyが失われて再送されてこないなら、asyncに
して待機させておくのがいいかもですね。
ということで、雲雀さんのasync_shutdownにするパッチを対処案とするのが
現状では一番現実的な気がします。
本件masterブランチにマージ済みのためクローズとします。
クライアントとの通信切断時、 tcp_session.cpp内のup_thread_client_disconnect() が呼ばれる。 この関数内のsslのソケットをshutdownする処理が 原因で表題の事象が発生する。 具体的な動作としては、tcp_session.cppの1500行目辺りで 次のようにshutdonw処理を行っているが、 client_ssl_socket.shutdown(ec); if (ec == boost::asio::error::try_again) { func_tag = UP_FUNC_CLIENT_DISCONNECT; } else if : shutdown処理が例外(try_again)を返した場合 UP_FUNC_CLIENT_DISCONNECT(up_thread_client_disconnect関数を指す)が 次の処理として指定され、try_againが返される間 shutdown処理が繰り返し実行される。 この際waitを入れずにshutdown処理を繰り返す作りとなっているため CPU使用率が上昇する。 現状の実装では上記の動作は設定等で回避できず、また 通常運用においても本事象が発生し得る。