説明するまでもない、次世代の統合監視を担うオープンソースの代表格であるZabbix。ちょっと調査をする必要があったので、色々APIを試したりしていたときに発見した現象。
同時にZabbixAPIを叩きに行ったさいに、apacheとMySQLが高負荷状態に。その状態でWEBブラウザから他のクライアントがログインを試みてもタイムアウトになる。なんだーなんだーと思って調査してみたら、ログイン時にログを残す時のログID取得処理でバグがあった。
調査の内容は以下。
例えば、APIのクライアントから同時にZabbixAPIを叩きにいくと(zabbix-host-status-test.plは自分自身の監視を有効化したり無効化したりするスクリプト)
./zabbix-host-status-test.pl -m on & ./zabbix-host-status-test.pl -m on &
すると、API側のapache＋mysqlがループに入り高負荷になる。
その時のプロセストレースログ
9729 write(12, "Y\0\0\0\3SELECT nextid FROM ids WHER"..., 93) = 93
9729 read(12, "\1\0\0\1\1.\0\0\2\3def\6zabbix\3ids\3ids\6nex"..., 16384) = 85
9729 gettimeofday({1281007016, 213197}, {4294966756, 0}) = 0
9729 gettimeofday({1281007016, 213400}, {4294966756, 0}) = 0
9729 poll([{fd=12, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
9729 write(12, "Y\0\0\0\3SELECT nextid FROM ids WHER"..., 93) = 93
9729 read(12, "\1\0\0\1\1.\0\0\2\3def\6zabbix\3ids\3ids\6nex"..., 16384) = 85
9729 gettimeofday({1281007016, 241365}, {4294966756, 0}) = 0
9729 gettimeofday({1281007016, 241434}, {4294966756, 0}) = 0
9729 poll([{fd=12, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
9729 write(12, "a\0\0\0\3UPDATE ids SET nextid=nexti"..., 101) = 101
9729 read(12, "0\0\0\1\0\1\0\2\0\0\0(Rows matched: 1 ?Cha"..., 16384) = 52
9729 gettimeofday({1281007016, 355179}, {4294966756, 0}) = 0
9729 gettimeofday({1281007016, 355232}, {4294966756, 0}) = 0
9729 poll([{fd=12, events=POLLIN|POLLPRI}], 1, 0) = 0 (Timeout)
・・・・延々と続く
そこでトレースログに残っているテーブルが実際にどう変化しているのかを見るため、ZabbixのDBの値を見てみた。
nodeid table_name field_name nextid
0 actions actionid 8
0 applications applicationid 1940
0 auditlog auditid 1419454 ← ここがループに入る
0 auditlog_details auditdetailid 21220
0 conditions conditionid 136
0 events eventid 728954
0 functions functionid 22983
0 graphs graphid 1445
0 graphs_items gitemid 5712
0 groups groupid 40
0 hostmacro hostmacroid 3
0 hosts hostid 10228
0 hosts_groups hostgroupid 428
0 hosts_templates hosttemplateid 296
0 housekeeper housekeeperid 14730
0 httpstep httpstepid 118
0 httpstepitem httpstepitemid 855
0 httptest httptestid 23
0 httptestitem httptestitemid 126
0 images imageid 45
0 items itemid 31054
0 items_applications itemappid 13220
0 maintenances maintenanceid 12
0 maintenances_hosts maintenance_hostid 140
0 maintenances_windows maintenance_timeperiodid 23
0 media mediaid 12
0 media_type mediatypeid 5
0 operations operationid 71
0 opmediatypes opmediatypeid 41
0 profiles profileid 3679
0 rights rightid 784
0 screens screenid 16
この時、APIでもう一度現象を再現してみると、ログイン認証時のauditlogのカウントがループしているようだ。本来は、ログイン時に1カウントしかされない（1413688→1413689）はずなのに、実際試して みると、同時にログインを試みた場合カウンター値が8000くらいカウントされている。(1413689→1421667→1421668)
1421667と1421668はループ後二つのAPIログインがカウンタされている。
| 1413656 | 0 | 1281072157 | 3 | 0 | Correct login [api-admin] | 127.0.0.1 | 0 |
| 1413688 | 0 | 1281072165 | 3 | 0 | Correct login [api-admin] | 127.0.0.1 | 0 |
| 1413689 | 0 | 1281072165 | 3 | 0 | Correct login [api-admin] | 127.0.0.1 | 0 |
| 1421667 | 0 | 1281072303 | 3 | 0 | Correct login [api-admin] | 127.0.0.1 | 0 |
| 1421668 | 0 | 1281072303 | 3 | 0 | Correct login [api-admin] | 127.0.0.1 | 0 |
そこで、ログイン認証時に呼ばれるfunctionのadd_audit()を見てみた。
function add_audit($action,$resourcetype,$details){
global $USER_DETAILS;
if(!isset($USER_DETAILS['userid'])) check_authorisation();
$auditid = get_dbid('auditlog','auditid');
if(zbx_strlen($details) > 128)
$details = substr($details, 0, 125).'...';
$ip = (isset($_SERVER['HTTP_X_FORWARDED_FOR']) && !empty($_SERVER['HTTP_X_FORWARDED_FOR']))?$_SERVER['HTTP_X_FORWARDED_FOR']:$_SERVER['REMOTE_ADDR'];
if(($result = DBexecute('INSERT INTO auditlog (auditid,userid,clock,action,resourcetype,details,ip) '.' VALUES ('.$auditid.','.$USER_DETAILS['userid'].','.time().','.$action.','.$resourcetype.','.zbx_dbstr($details).','.zbx_dbstr($ip).')'))){
$result = $auditid;
}
return $result;
}
add_audit内でauditlogの次のカウンター値をもらうのは、4行目のget_dbidファンクション。 ここで値がループしてるのでは？と推測。そこでget_dbid()を見てみる。
function get_dbid($table,$field){
// PGSQL on transaction failure on all queries returns false..
global $DB, $ZBX_LOCALNODEID;
if(($DB['TYPE'] == 'POSTGRESQL') && $DB['TRANSACTIONS'] && !$DB['TRANSACTION_STATE']) return 0;
//------ $nodeid = get_current_nodeid(false);
$found = false;
do{
$min=bcadd(bcmul($nodeid,'100000000000000'),bcmul($ZBX_LOCALNODEID,'100000000000'));
$max=bcadd(bcadd(bcmul($nodeid,'100000000000000'),bcmul($ZBX_LOCALNODEID,'100000000000')),'99999999999');
$row = DBfetch(DBselect('SELECT nextid FROM ids WHERE nodeid='.$nodeid .' AND table_name='.zbx_dbstr($table).' AND field_name='.zbx_dbstr($field)));
if(!$row){
$row = DBfetch(DBselect('SELECT max('.$field.') AS id FROM '.$table.' WHERE '.$field.'>='.$min.' AND '.$field.'<='.$max));
if(!$row || is_null($row['id'])){
DBexecute("INSERT INTO ids (nodeid,table_name,field_name,nextid) VALUES ($nodeid,'$table','$field',$min)");
}
else{
/*
$ret1 = $row["id"];
if($ret1 >= $max) {
"Maximum number of id's was exceeded"
}
//*/
DBexecute("INSERT INTO ids (nodeid,table_name,field_name,nextid) VALUES ($nodeid,'$table','$field',".$row['id'].')');
}
continue;
}
else{
$ret1 = $row['nextid'];
if((bccomp($ret1,$min) < 0) || !(bccomp($ret1,$max) < 0)) {
DBexecute('DELETE FROM ids WHERE nodeid='.$nodeid.' AND table_name='.zbx_dbstr($table).' AND field_name='.zbx_dbstr($field));
continue;
}
$sql = 'UPDATE ids SET nextid=nextid+1 WHERE nodeid='.$nodeid.' AND table_name='.zbx_dbstr($table).' AND field_name='.zbx_dbstr($field);
DBexecute($sql);
$row = DBfetch(DBselect('SELECT nextid FROM ids WHERE nodeid='.$nodeid.' AND table_name='.zbx_dbstr($table).' AND field_name='.zbx_dbstr($field)));
if(!$row || is_null($row["nextid"])){
// Should never be here
continue;
}
else{
$ret2 = $row["nextid"];
if(bccomp(bcadd($ret1,1),$ret2) == 0){
$found = true;
}
}
}
}
while(false == $found);
return $ret2;
}
do whileの中をループして8000くらいカウント値を増やしてしまってる模様だ。プロセストレースログから、10行目33行目35行目の三つのsqlがループに入っていると思われる。ということは、
- 1つ目のsqlで現在のカウント取得
- 2つ目のsqlで次のカウントを作成
- 3つ目で次のカウントを取得
している。
そして、最後に、
if(!$row || is_null($row["nextid"])){
// Should never be here
continue;}
else{
$ret2 = $row["nextid"];
if(bccomp(bcadd($ret1,1),$ret2) == 0){
$found = true;
}
}
ここで、現在のカウントに1プラスしたものが次のカウントになっているかを確認して、OKならループを抜ける。しかし、同時にAPIでログインしてしまった場合、三つ目のsqlで次のカウントを取得した時、別のセッションでカウントをプラスされていた場合、もう一度カウンター値を探しにいってしまう。それらが並行して動いてしまうと、ループするようだ。 なので、処理が重なった時にカウンター値をずらせるように以下の処理を追記。
--- db.inc.php.org 2010-03-30 02:22:45.000000000 +0900
+++ db.inc.php 2010-08-09 14:23:41.000000000 +0900
@@ -786,6 +786,12 @@
if(bccomp(bcadd($ret1,1),$ret2) == 0){
$found = true;
}
+// start written by matsumoto_r in 2010/08/09
+ else{
+ $rand_sleep = mt_rand(0,100000);
+ usleep($rand_sleep);
+ }
+// finish written by matsumoto_r in 2010/08/09
}
}
}
処理が重なった場合は、0から0.1msの間で乱数を発生させ、その値の間だけマイクロsleepする。これでいけるか試してみたらいけました。Zabbix1.8.3系のソースを見ても、まだ改善されていなかったので 、しばらくはこのパッチを当てることになりそう。これって、APIにかかわらず、同時にログインが発生しちゃうと起きる現象なので、どうにかしとかないとまずいよね。