Error in my_thread_global_end() : 1 threads didn't exitというエラーが発生

[cs-sonar]

mod_process_securityインストール後、Apacheのエラーログに

Error in my_thread_global_end() : 1 threads didn't exit

というエラーが表示されるようになりました。

詳細を確認していた所、
どうやらApache経由でPHP->MySQLと接続したページを表示すると
このエラーが出るようです。
また、特にサービスが停止しているという状況はありません。

エラー内容からMySQLで出ているエラーのようですので
MySQLやPHP側のバグの可能性もありますが、
mod_process_securityインストール後に発生した為、
バグとして報告させて頂きます。

以下の環境にて発生致しました。

Debian Wheezy 64bit
php5.4.19 (ソースインストール)
mysql5.6.13 (公式のビルド済パッケージを展開)
apache2.2.25 (ソースインストール)

Debian Squeeze 64bit
php5.4.12 (ソースインストール)
mysql5.5.25 (公式のビルド済パッケージを展開)
apache2.2.22 (ソースインストール)

また、以下の環境では発生しておりません。

Debian Lenny 32bit
php5.2.14 (ソースインストール)
mysql5.1.40 (公式のビルド済パッケージを展開)
apache2.2.20 (ソースインストール)

宜しくお願い致します。

[matsumotory]

@cs-sonar さん

報告ありがとうございます。ざっと見てみました。

my_thread_global_end()のエラーをphpのコードとaprのコードを追いながら調査したところ、
どうやら、phpを組み込んだApache(mod_php)でmysqlを使っている場合、Apacheの停止処理時に、
mysql接続時に起動したスレッドのメモリ解放のために、mysql_thread_end()を実行している
ようでした。phpの下記コード部分です。

 622 /* {{{ PHP_RSHUTDOWN_FUNCTION
 623  */
 624 PHP_RSHUTDOWN_FUNCTION(mysql)
 625 {
 626 #if !defined(MYSQL_USE_MYSQLND) && defined(ZTS) && MYSQL_VERSION_ID >= 40000
 627     mysql_thread_end();
 628 #endif
 629 

しかし、このmysql_thread_endは、pthred_exitを呼ぶ前に実行する必要がありますが、
mod_process_security上で先にapr_thread_exitを呼んでいるために、その内部で呼ばれ
ているpthread_exitの後に、Apache停止時にmysql_thread_endが呼ばれ、該当のエラー
が発生していたようです。

そこで、本サーバに下記コマンドでmysqlのライブラリをインストールし、

yum install --enablerepo=remi mysql-devel

mod_process_security.cのapr_thread_exit（内部でpthread_exitが呼ばれている）の前に、
暫定でmysql_thread_endを呼ぶようにしてみました。

    302 static void * APR_THREAD_FUNC process_security_thread_handler(apr_thread_t *thread, void *data)
    303 {
    304     request_rec *r = (request_rec *) data;
    305     int result;
    306 
    307     thread_on = 1;
    308 
    309     if (process_security_set_cap(r) < 0) {
    310         mysql_thread_end();
    311         apr_thread_exit(thread, HTTP_INTERNAL_SERVER_ERROR);
    312     }
    313 
    314     result = ap_run_handler(r);
    315 
    316     if (result == DECLINED)
    317         result = HTTP_INTERNAL_SERVER_ERROR;
    318 
    319     mysql_thread_end();     //ここに追記
    320     apr_thread_exit(thread, result);
    321 
    322     return NULL;
    323 }

そして、下記のようにモジュールをビルドし、

apxs -i -c -L /usr/lib64/mysql/ -lcap -lmysqlclient mod_process_security.c

Apacheを再起動すると、該当のエラーが出なくなりました。

mysqlを使っていないようなアクセス、例えば、index.php等にもアクセスして
みましたが、エラーのようなものは見られず、とりあえずは動作しているよう
に思われます。

abコマンドで同時接続数100、総接続数100000の負荷をindex.phpにかけてみま
したが、segfault等のエラーはでていないので、大体いけるんじゃないかと思って
います。

Concurrency Level:      100
Time taken for tests:   16.461 seconds
Complete requests:      100000
Failed requests:        0
Write errors:           0
Total transferred:      90030600 bytes
HTML transferred:       71424276 bytes
Requests per second:    6075.06 [#/sec] (mean)
Time per request:       16.461 [ms] (mean)
Time per request:       0.165 [ms] (mean, across all concurrent requests)
Transfer rate:          5341.22 [Kbytes/sec] received

本来は、phpのmysqlを使っている場合のみ、mod_process_security上で
mysql_thread_endを実行すべきですが、そこまでの実装はまだできていま
せん。

他にこの問題を解決する良いアイデアはないだろうか...

[cs-sonar]

いち利用者としての報告に対応して下さり、ありがとうございます。

少し難しくて理解できていない部分があるかもしれませんが、頂いた返信内容を元に僕の環境でも設定してみましたが、エラーは出なくなりました。
僕の方でも他に不具合は発生していないように思います。

[matsumotory]

@cs-sonar さん

この記述の通り、サーバ停止時にログが出力されだす、という認識でよいですか？MySQLにアクセスするようなPHPスクリプトを実行した時ではなく。

[cs-sonar]

言葉足らずですいません。

MySQLにアクセスするようなPHPスクリプトを実行した時にエラーが出力されます。
厳密にはブラウザでアクセスした後、1分ほど後にApacheエラーログへ出力されます。
運用中、ご連絡させて頂いたエラーでエラーログが埋まるくらい出力されていましたが、WEBサービス自体に不具合は出ていませんでした。
サーバの起動や停止時には特にエラーは発生していません。

[matsumotory]

@cs-sonar さん

そうでしたか、ではMySQLにアクセス後にmysql_thread_endが実行されていそうですね。いずれにせよ、process_security上でthread_endして問題なさそうならマージしようと思います。

[phsm]

Hi,
@matsumoto-r , your module works like a charm: even highly loaded sites don't produce more server load with mod_process_security enabled. But I'm facing the issue too.
I don't know Japanese, so using Google Translator I've figured out that the issue is caused by mod_php which don't close mysqlclient threads correctly or somewhat like that.

Could you be so nice and describe the source of it in English?
Thank you.

UPD: It seems I managed to fix this issue to myself, thanks!

UPD2: Nope, I had'nt. I've tried to add mysql_thread_end(); just before execution of apr_thread_exit():

diff --git a/mod_process_security.c b/mod_process_security.c
index b91d6e4..815de5c 100644
--- a/mod_process_security.c
+++ b/mod_process_security.c
@@ -46,6 +46,7 @@
 #include <sys/prctl.h>
 #include <sys/capability.h>
 #include <limits.h>
+#include <mysql/mysql.h>

 #define MODULE_NAME "mod_process_security"
 #define MODULE_VERSION "1.1.4"
@@ -428,13 +429,17 @@ static void *APR_THREAD_FUNC process_security_thread_handler(apr_thread_t *threa

   thread_on = 1;

-  if (process_security_set_cap(r) < 0)
+  if (process_security_set_cap(r) < 0) {
+    mysql_thread_end();
     apr_thread_exit(thread, HTTP_INTERNAL_SERVER_ERROR);
+  }

   if (conf->keep_open_enable == ON) {
     fd = open(r->filename, O_RDONLY);
-    if (fd == -1)
+    if (fd == -1) {
+      mysql_thread_end();
       apr_thread_exit(thread, HTTP_INTERNAL_SERVER_ERROR);
+    }
   }

   result = ap_run_handler(r);
@@ -446,6 +451,7 @@ static void *APR_THREAD_FUNC process_security_thread_handler(apr_thread_t *threa
   if (result == DECLINED)
     result = HTTP_INTERNAL_SERVER_ERROR;

+  mysql_thread_end();
   apr_thread_exit(thread, result);

   return NULL;

It seems to be working for Apache instances with low load (tried on the Apache with MaxRequestPerChild 10 and test it with ab).
But if I run it on the Apache 2.2.16 with php 5.3 (on Debian squeeze) which is serving ~300 requests/sec I get following log:

Error in my_thread_global_end(): 2106 threads didn't exit
Error in my_thread_global_end(): 439 threads didn't exit
Error in my_thread_global_end(): 455 threads didn't exit
[Fri Nov 06 14:16:49 2015] [warn] (99)Cannot assign requested address: connect to listener on 127.0.0.1:80
[Fri Nov 06 14:16:50 2015] [warn] (99)Cannot assign requested address: connect to listener on 127.0.0.1:80 (my apache listens at that socket)
Error in my_thread_global_end(): 472 threads didn't exit
Error in my_thread_global_end(): 2070 threads didn't exit

Any tips will be much appreciated.

[matsumotory]

@phsm Thank you for your reports. This issue is the same which you have. So, I also think mod_process_security run mysql_thread_end before apr_thread_exit for MySQL connection pool.

[phsm]

@matsumoto-r but how can I possibly run mysql_thread_end for MySQL connection pool? I have looked into the MySQL C API reference - there is no function which may help with that.

Also, could you explain how it happens? I thought it is a mod_php's task to finish its mysqlclient threads gracefully, not mod_process_security's..

[matsumotory]

@phsm
ref: https://dev.mysql.com/doc/refman/5.7/en/mysql-thread-end.html

mysql_thread_end() is not invoked automatically by the client library. Before MySQL 5.7.9, it must be called for each mysql_thread_init() call to avoid a memory leak. As of MySQL 5.7.9, C API internals were reimplemented to reduce the amount of information allocated by mysql_thread_init() that must be freed by mysql_thread_end(): For release/production builds without debugging support enabled, mysql_thread_end() need not be called.

So, you should build your mysql client library for not calling mysql_thread_end() in the thread.

It's a specification of mod_process_security, not a bug.