Zabbix API 同時にログインしたらapache+MySQLがループするバグ

説明するまでもない、次世代の統合監視を担うオープンソースの代表格である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にかかわらず、同時にログインが発生しちゃうと起きる現象なので、どうにかしとかないとまずいよね。