From hibari.michiro ＠ lab.ntt.co.jp Wed Nov 26 13:08:44 2014 From: hibari.michiro ＠ lab.ntt.co.jp (Hibari Michiro) Date: Wed, 26 Nov 2014 13:08:44 +0900 Subject: [Ultramonkey-l7-develop 1079] Re: tmp_v3.1.2-1 upload In-Reply-To: <54748F02.5020309@iwao.net> References: <54110A0F.2050109@nttcom.co.jp> <5412ABDA.2070909@lab.ntt.co.jp> <541A68D6.8010904@nttcom.co.jp> <542BA4B0.8010802@nttcom.co.jp> <542BAA09.5090803@nttcom.co.jp> <542D25BC.9040201@lab.ntt.co.jp> <5433A024.2010300@nttcom.co.jp> <5434DF5C.9000003@nttcom.co.jp> <54748F02.5020309@iwao.net> Message-ID: <5475524C.30102@lab.ntt.co.jp> たるすぴ様 雲雀です。 詳細な解析ありがとうございます。 > https://sourceforge.jp/ticket/browse.php?group_id=1951&tid=34416 チケットに添付しているpatchですが、まだgitには 上がっていないので、適当にブランチを切ってそちらに pushしたいと思います。 (2014/11/25 23:15), Hiroaki Nakano wrote: > たるすぴです。 > > 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, > 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', > 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 = > (gdb) p is_operation_done > $11 = false > (gdb) p is_read_needed > $12 = > (gdb) p is_write_needed > $13 = false > (gdb) p is_shut_down_received > $15 = false > (gdb) p is_shut_down_sent > $16 = > > 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にするパッチを対処案とするのが > 現状では一番現実的な気がします。 > > (2014/10/08 15:53), Hiroaki Nakano wrote: >> 中野@幕張です。 >> >> man 3 SSL_shudwonを見ていると、以下の記述がありました。 >> >> ------ >> RETURN VALUES >> The following return values can occur: >> >> ...(snip) >> >> 3. -1 >> >> The shutdown was not successful because a fatal error occurred either >> at the protocol level or a connection failure occurred. It >> can also occur if action is need to continue the operation for non-blocking BIOs. >> Call SSL_get_error(3) with the return value ret to find out the reason. >> ------ >> >> ということは、まだBIOの中にデータが残っているうちにshutdownが走っちゃいましたかね。 >> >> しかしBIOの中に残した状態を再現するとなると、難しくて思いつかない・・・ >> >> boost的にはBIO_writeしたあとなんで処理は終わってるんだけど、 >> libsslの内部にあるBIOバッファからkernelのsocketシステムコールにはデータを >> 書き込めてない状態でSSL_shutdownが走らないといけないんだよね。 >> >> 環境だけで作るのむずい。 >> >> (2014/10/07 17:11), Hiroaki Nakano wrote: >>> 中野です。 >>> おつです。 >>> >>> なかなか再現環境が組めないですorz >>> 発見者はどんな環境で発生したんでしょう。。。 >>> >>> up_thread_client_disconnectが呼ばれているところを >>> ピックアップしてみました。 >>> >>> 呼び出し箇所： >>> up_thread_run >>> 　接続失敗時(L861) >>> up_thread_client_accept_fail_event >>> 　handshake_error_codeがtry_againじゃないとき(L1233) >>> up_thread_client_receive >>> 　recv_size<=0のとき(L1354) >>> 　ecがあってeofのとき(L1358) >>> 　ecがあってeofじゃなくてtry_againじゃないとき(L1379) >>> down_thread_client_disconnect >>> 　正常ルート冒頭(L3186) >>> up_thread_client_handle_async_read_some >>> 　errorがあってtry_againじゃないとき(L3711, L3713) >>> >>> このあたりが発生しそうな環境を作ったらいけるかな？ >>> 単純に高負荷掛けただけじゃ再現できませんでした。 >>> >>> 似たような事例を探してたら、TomcatのwriteのEAGAINでやっぱ >>> AGAINループになってたみたいです。 >>> https://issues.apache.org/bugzilla/show_bug.cgi?id=52856 >>> >>> こいつは対処でsleep入れてるなぁ・・・ >>> >>> 引き続き再現方法を探してみます。 >>> >>> (2014/10/02 19:15), Hibari Michiro wrote: >>>> 雲雀です。 >>>> >>>> v3.1.2のリリースですが、 >>>> もう一か所 直したい箇所があるので少々お待ちください。 >>>> >>>> その直したい箇所についてはチケット#34416で起票しました。 >>>> https://sourceforge.jp/ticket/browse.php?group_id=1951&tid=34416 >>>> >>>> 以上、取り急ぎ。 >>>> (2014/10/01 16:15), Hiroaki Nakano wrote: >>>>> 中野@幕張です。 >>>>> >>>>> コミュニティリーダーからストップかかったので >>>>> リリース遅らせます。 >>>>> すみません。 >>>>> >>>>> 詳細は別途。 >>>>> >>>>> (2014/10/01 15:52), Hiroaki Nakano wrote: >>>>>> 中野@幕張です。 >>>>>> こんにちは。 >>>>>> >>>>>> とくに反応ないのでリリースしますね。 >>>>>> >>>>>> >>>>>> (2014/09/18 14:08), Hiroaki Nakano wrote: >>>>>>> 中野@幕張です。 >>>>>>> こんにちは。 >>>>>>> >>>>>>> (2014/09/12 17:16), Hibari Michiro wrote: >>>>>>>> 中野様 >>>>>>>> >>>>>>>> 雲雀です。 >>>>>>>> お世話になっております。 >>>>>>>> >>>>>>>> v3.1.2-1のアップロードありがとうございました。 >>>>>>>> 手元環境でざっと動作させてみたところ、 >>>>>>>> 問題なく動作しているようでした。 >>>>>>>> >>>>>>>>>> 不具合等なかった場合、リリース前に太田さんに個別に >>>>>>>>>> 連絡して、事象が直っているか確認を取ろうと思います。 >>>>>>>> >>>>>>>> そうですね。 >>>>>>>> 何のため、太田様にもtmpに上げている >>>>>>>> バイナリを共有し、事象が改善されたか >>>>>>>> 確認していただくのが良いと思います。 >>>>>>> >>>>>>> 確認していただきました。事象が解消されたとのことです。 >>>>>>> >>>>>>> ということで、このバイナリをそのままv3.1.2-1として >>>>>>> リリースしたいと思うのですが、いいでしょうか。 >>>>>>> >>>>>>> あと、gitツリーのmasterのHEADに、v3.1.2-1のタグを設定する >>>>>>> つもりです。 >>>>>>> >>>>>>> # 個人的都合で、来週〜29日まで中野がrpmビルド環境を使えない >>>>>>> # ので、明日か、それを過ぎたら10月になります。 >>>>>>> >>>>>>> >>>>>>>> 以上、宜しくお願い致します。 >>>>>>>> >>>>>>>> (2014/09/11 11:33), Hiroaki Nakano wrote: >>>>>>>>> UM-L7 開発者のみなさん >>>>>>>>> >>>>>>>>> 中野@幕張です。 >>>>>>>>> こんにちは。 >>>>>>>>> >>>>>>>>> users MLで太田さんからご指摘のあった >>>>>>>>> v3.1.0リリースで#30300がデグレードした件について、 >>>>>>>>> 再度#30300の修正を入れなおしたv3.1.2-1版の >>>>>>>>> x86_64 rpmバイナリを以下に置きました。 >>>>>>>>> >>>>>>>>> http://ultramonkey-l7.sourceforge.jp/_tmp/tmp_uml7_3_1_2-1 >>>>>>>>> >>>>>>>>> 不具合等無いか、ご確認ください。 >>>>>>>>> >>>>>>>>> 不具合等なかった場合、リリース前に太田さんに個別に >>>>>>>>> 連絡して、事象が直っているか確認を取ろうと思います。 >>>>>>>>> >>>>>>>>> そのうえで、リリースという流れでいいでしょうか。 >>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>>> >>>>>>> >>>>>>> >>>>>> >>>>>> >>>>> >>>>> >>>> >>>> >>> >>> >> >> > > _______________________________________________ > Ultramonkey-l7-develop mailing list > Ultramonkey-l7-develop ＠ lists.sourceforge.jp > http://lists.sourceforge.jp/mailman/listinfo/ultramonkey-l7-develop > > -- 雲雀　路朗 (Michiro Hibari) MAIL: hibari.michiro ＠ lab.ntt.co.jp 所属: NTT OSSセンタ 基盤技術ユニット 高信頼担当 TEL : 03-5860-5135 / FAX: 03-5463-5490