あるシステム管理者の日常 このページをアンテナに追加 RSSフィード

2018-10-26 Zabbix agent on hostname is unreachable for 5 minites

Zabbix agent on hostname is unreachable for 5 minites

| 14:51 | Zabbix agent on hostname is unreachable for 5 minitesを含むブックマーク

この一ヶ月ほど、Zabbixで監視しているすべてのサーバ上記エラーがでるようになりました。ずっと出るわけではなく、時々発生。

でもってzabbix serverプロセス再起動すると何事もなく動作する。

現象を整理

現象が発生したときに実際にzabbixサーバとzabbix agent間で通信ができなくなっているかというと全くそういうことはなく、ちゃんと通信はできている。

telnetで10050ポートをつつくとちゃんと返答が帰ってくるし、zabbix_getでagentに値を要求してもちゃんと答えが帰ってくる。

$ zabbix_get -s 172.18.1.57 -p 10050 -k agent.version
3.0.7

ではサーバ側のログになにか出ているかというと全くエラーっぽいものは出ておらず、それどころかagentとの通信ログが順調に積み上がっている。

つまりまったくunreachableではない模様。

じゃあ、誤検知なのか

誤検知だったらいいんですが、上記エラー状態になったときには実際にagentから帰ってくるデータが全く蓄積されない。グラフをみると障害発生時間帯がちょん切れる感じ。通信できていないわけじゃないけど、データは取れてませんよってことですね。

このエラーはどのトリガーで発生しているのか

このトリガーとそのもとになっているアイテムはTemplate App Zabbix Agentというテンプレートに含まれています。アイテム名は"Agent Ping"でキーは

agent.ping

という簡単なもの。トリガーはこれが最新の5分間NGになったときにキックされるようになっています。

https://www.miraclelinux.com/tech-blog/835fku

ここの情報によれば、本トリガーが判定されるのは、

  • アイテムのデータを取得した後、HistoryCacheからDBへ書き込むとき
  • タイマー(本例の様に5分間とか)判定があるときは、30秒に一度

とのこと。

上の条件でデータが取れていてもDBへの投入ができなければトリガが判定されるということです。

agentから集めてきたデータをいちどHistoryCacheへ投入、DBSyncerプロセスでバックエンドDBへ投入終了後ようやくトリガとしてはOKになる。

つまりagentとは通信できているけど、DBへのinertが追いついてないよってことですね。

障害が発生しているまでのCahce状態はこんな感じ。

f:id:rougeref:20181026142620p:image

じゃあDBの性能をチューニングしよう

ってことでいろいろやってみたんです。

  • InnnoDBテーブル単位にする(前からそうでしたが)
  • innodb_read_io_threads,innodb_write_io_threadsを増やす
  • innodb_old_block_timeを増やす
  • innodb_io_capacityを800にする。
  • sync_binlog=0
  • query_cache_size=0, query_cache_type=0
  • sort_buffer_size, join_buffer_size, read_rnd_buffer_size を調整

全部 https://www.percona.com/blog/2014/11/14/optimizing-mysql-zabbix/ に書いていることですけど。

あと、バックエンドのMySQLをzabbix serverからもっと高性能なDBサーバへ移したりしんだですが、全部ムダでした。

多少は障害が派生する頻度はへるもののそのうち、HistoryCacheがいっぱいになって停止。

どんなSQLが原因なんだろう

zabbixのDBでhistoryやhistory_logのテーブルに入ってくるデータってそんなにおおきなものじゃないのに、なんでそんなに時間がかかるんだろう。

ということで現象(障害)が発生しているときにZabbix Serverを停止してみる。そうすると、HistoryCacheに溜まっているデータをDBSyncerが一生懸命DBへ吐き出そうとします。これがまぁ遅いこと。zabbix_serverのログをみていると進捗が出てくるんですがこんなんですよ。

zabbix_server.log: 14466:20181024:094716.374 syncing history data... 0.000868%
zabbix_server.log: 14466:20181024:094734.958 syncing history data... 0.002083%
zabbix_server.log: 14466:20181024:094744.395 syncing history data... 0.002690%
zabbix_server.log: 14466:20181024:094812.096 syncing history data... 0.003905%
zabbix_server.log: 14466:20181024:094830.815 syncing history data... 0.005120%
zabbix_server.log: 14466:20181024:094857.605 syncing history data... 0.006335%

その間にMySQL一般クエリのログを取れるようにして再起動

#General log
general_log = 1
log_output = FILE
general_log_file = /var/lib/mysql/mysqld-general.log

でもってこのログを眺める。だいたいはselectなんですが、ときおりなにやら妙な文字列がhistory_logにinsertされているのを観測しました。

どんなデータかというと、こんな感じ。これ、Windowsセキュリティログですね。

 
オブジェクトに対して操作が実行されました。

サブジェクト:
        セキュリティ ID:                S-1-5-21-1446844220-300872527-1797055100-40755
        アカウント名:           ict_logrev
        アカウント ドメイン:            HOGE
        ログオン ID:            0x5BBA054C0

オブジェクト:
        オブジェクト サーバー:          DS
        オブジェクトの種類:             %{bf967a8b-0de6-11d0-a285-00aa003049e2}
        オブジェクト名:         %{b8c85098-76be-444b-a007-6d33f04ddb58}
        ハンドル ID:            0x0

操作:
        操作の種類:             Object Access
        アクセス:               プロパティの読み取り

        アクセス マスク:                0x10
        プロパティ:             プロパティの読み取り
                {e48d0154-bcf8-11d1-8702-00c04fb96050}
                        {bf9679e4-0de6-11d0-a285-00aa003049e2}
        {bf967a8b-0de6-11d0-a285-00aa003049e2}


追加情報:
        パラメーター 1:         -
        パラメーター 2:                                                                                                                                                                                                                                                                         

とこんな文字列を延々とinsertしようとしている。おそらくだけどhistory_logのvalueカラムって数値が入ってくることを前提としているので、こんなデカイ文字列が入ってくると途端にパフォーマンスがおちちゃんだろうなぁと。

別にログをチェックするのは悪いことじゃないけど、全部zabbixに送ってくる必要なないよなぁ。

対処

上記アイテムはTemplate Log Check Windowsというテンプレートに含まれています。Eventlog Securityという名前。キーは

eventlog[Security]

全部かよ。どうせみないでしょうってことでこれを無効にしました。危ういのをチェックしたいんだったら、フィルタをかけるのがいいかと。こんな感じで、

evnetlog[Security,,"Error|Critical"]

結果は

上記対処をして48時間立ちましたが、どうやらヒットだった模様。HistoryCacheの値はいろいろ調べている過程で上限の2GBまで増やしてみましが、512MBまで削減。それでも100%で安定しています。すらすらと書いていますが、この結論と対処をするまで結構悩みました。

トラックバック - http://d.hatena.ne.jp/rougeref/20181026

2018-10-25 /var/log/messagesに ”Removed slice User Slice of hoge.”や”Sto

/var/log/messagesに "Removed slice User Slice of hoge.”や"Stopping User Slice of hoge."とか

| 08:59 | /var/log/messagesに "Removed slice User Slice of hoge.”や"Stopping User Slice of hoge."とかを含むブックマーク

zabbixのmessageチェックに警告。実際のデータを参照してみると、タイトルのようなログが大量にでています。

Oct 25 08:51:01 dcvsvweb01 systemd: Starting Session 144578 of user hoge.
Oct 25 08:51:01 dcvsvweb01 systemd: Removed slice User Slice of hoge.
Oct 25 08:51:01 dcvsvweb01 systemd: Stopping User Slice of hoge.

Google先生に聞いてみると、それはそれで正常らしい。以下の記事を参照。

https://access.redhat.com/ja/solutions/2601461

うざければフィルターかけてねとのこと。

/etc/rsyslog.d/ignore-systemd-session-slice.conf を以下のようにして、

if $programname == "systemd" and
        ($msg contains "Starting Session" or
         $msg contains "Started Session" or
         $msg contains "Created slice" or
         $msg contains "Starting user-" or
         $msg contains "Starting User Slice of" or
         $msg contains "Removed session" or
         $msg contains "Removed slice User Slice of" or
         $msg contains "Stopping User Slice of")
then stop

syslog再起動

# systemctl restart rsyslog
トラックバック - http://d.hatena.ne.jp/rougeref/20181025

2018-10-24 apache2.4.37

apache2.4.37

| 15:15 | apache2.4.37を含むブックマーク

Apahceの2.4.37がリリースされていました。早速ウェブサーバインストール。いままで入っていたのが 2.4.35でした。割と頻繁にチェックしていますが、2.4.36は気が付きませんでした。CHANGESをみると、OpenSSL1.1.1対応とかmod_sslとかabとかとかの変更。

いつもapacheビルドインストールまでchefで実施しているんですが、chef soloの文法をいつも忘れてしまうのでメモしておきます。

$ knife solo cook hostanme -o recipe_name
トラックバック - http://d.hatena.ne.jp/rougeref/20181024

2018-10-23 審判関連の打ち合わせ

審判関連打ち合わせ

| 15:08 | 審判関連打ち合わせを含むブックマーク

某氏の呼び出されて審判関連の打ち合わせでJBA事務所。エラい人と小一時間ほどお話をしました。

非公式な打ち合わせなのであまり詳しいことは書きませんが、来年度に向けていい話ができたと思います。

日高屋で食事してからこの日はおとなしく電車で帰宅。 

トラックバック - http://d.hatena.ne.jp/rougeref/20181023

2018-10-22 大田区割当て

大田区割当て

| 15:04 | 大田区割当てを含むブックマーク

月曜日は大田区割当てで大森SC。今大会の最終日です。

男子二部、一部の決勝。女子決勝と入れ替え戦が行われました。

女子の入れ替え戦は今季からかな。前の大会ではやってなかったような気がします。

男子決勝で破れはしたものの準優勝の某チーム。ちょっと前までは大田区では無敵だったチームでしたが、順調な高齢化に伴ないこのところ優勝からは遠ざかっていましたが、新規メンバも増えて復活の兆しです。コートの外でチームを支えている人がいるチームは強いですね。

トラックバック - http://d.hatena.ne.jp/rougeref/20181022