[hap2] LTS使用時に最新データを取得するとプラグインがクラッシュ。

[kz0817]

環境

• masterのHEAD (8259d3d)
• OS: Ubuntu server 14.04.03
• All in one (Hatohol server, Apache (WebUI), AMQP broker, hap2_zabbix_api.py)を同一マシン
• Hatohol serverとAMQP broker (RabbitMQ)間は非暗号化
• hap2_zabbix_api.pyとAMQP broker間をTLSで暗号化

結果

• Polling動作は正常
• WebUIから最新データを取得するとhap2_zabbix_api.pyがクラッシュする。以下その際のBackTrace

  INFO:hatohol.haplib:hap2_zabbix_api.py:Poller:haplib.py:1095:29641:LastStat: OK, NumSuccess: 3 (20160509073802.837583), NumFailure: 0 (): FailureReason:
  CRITICAL:hatohol.hap:hap2_zabbix_api.py:MainProcess:hap.py:98:29632:Got critical signal.
  Traceback (most recent call last):
  File "./hap2_zabbix_api.py", line 211, in 
    Hap2ZabbixAPI().run();
  File "/usr/lib/python2.7/dist-packages/hatohol/standardhap.py", line 131, in run
    self()
  File "/usr/lib/python2.7/dist-packages/hatohol/standardhap.py", line 139, in **call**
    exctype, value = hap.handle_exception(raises=raises)
  File "/usr/lib/python2.7/dist-packages/hatohol/standardhap.py", line 136, in **call**
    self.**run(args)
  File "/usr/lib/python2.7/dist-packages/hatohol/standardhap.py", line 215, in __run
    self.__main_plugin()
  File "/usr/lib/python2.7/dist-packages/hatohol/haplib.py", line 1010, in __call**
    procedure(_args)
  File "./hap2_zabbix_api.py", line 175, in hap_fetch_items
    self.collect_and_put_items(params.get("hostIds"), params["fetchId"])
  File "./hap2_zabbix_api.py", line 68, in collect_and_put_items
    fetch_id)
  File "/usr/lib/python2.7/dist-packages/hatohol/haplib.py", line 586, in divide_and_put_data
    put_func(chunk_contents, params, *args, *_kwargs)
  File "/usr/lib/python2.7/dist-packages/hatohol/haplib.py", line 548, in put_items
    self.__sender.request("putItems", params, request_id)
  File "/usr/lib/python2.7/dist-packages/hatohol/haplib.py", line 336, in request
    self.__connector.call(json.dumps(body))
  File "/usr/lib/python2.7/dist-packages/hatohol/rabbitmqconnector.py", line 112, in call
    self.__publish(msg)
  File "/usr/lib/python2.7/dist-packages/hatohol/rabbitmqconnector.py", line 137, in __publish
    raise hap.Signal(critical=True)
  hatohol.hap.Signal: 
  WARNING:hatohol.standardhap:hap2_zabbix_api.py:Poller:standardhap.py:165:29641:Got SIGTERM
  WARNING:hatohol.standardhap:hap2_zabbix_api.py:Dispatcher:standardhap.py:165:29635:Got SIGTERM
  WARNING:hatohol.standardhap:hap2_zabbix_api.py:Receiver:standardhap.py:165:29636:Got SIGTERM
  WARNING:hatohol.standardhap:hap2_zabbix_api.py:MainProcess:standardhap.py:155:29632:Got SIGCHLD
  WARNING:hatohol.standardhap:hap2_zabbix_api.py:MainProcess:standardhap.py:155:29632:Got SIGCHLD
  Error in sys.exitfunc:
  Traceback (most recent call last):
  File "/usr/lib/python2.7/atexit.py", line 24, in _run_exitfuncs
    func(_targs, *_kargs)
  WARNING:hatohol.standardhap:hap2_zabbix_api.py:MainProcess:standardhap.py:155:29632:Got SIGCHLD
  

また、/var/log/rabbitmqabbit@.logに
次のメッセージがありました。 bad record macが怪しい？

=INFO REPORT==== 9-May-2016::16:38:27 ===
accepting AMQP connection <0.374.0> (127.0.0.1:40488 -> 127.0.0.1:5672)

=INFO REPORT==== 9-May-2016::16:38:27 ===
closing AMQP connection <0.374.0> (127.0.0.1:40488 -> 127.0.0.1:5672)

=ERROR REPORT==== 9-May-2016::16:38:27 ===
SSL: connection: tls_record.erl:164:Fatal error: bad record mac

=ERROR REPORT==== 9-May-2016::16:38:27 ===
closing AMQP connection <0.341.0> (127.0.0.1:41490 -> 127.0.0.1:5671):
{inet_error,{tls_alert,"bad record mac"}}

=WARNING REPORT==== 9-May-2016::16:38:27 ===
closing AMQP connection <0.353.0> (127.0.0.1:41492 -> 127.0.0.1:5671):
connection_closed_abruptly

[kz0817]

MainPluginとPollerが別プロセスで動作しているので、
TLSのMAC (Message Authentication Code)のシーケンス番号が、
不正になっているのかもしれない。

現在ひとつのコネクションをforkした後も使いまわしているが、プロセスごとに
コネクションを持つようにしたら、改善されるか？

[masa0612]

RabbitMQのトラブルシューティングによると，一つのソケットを複数箇所で共有してしまった場合，
今回のようにbad record macが発生するそう。
現在の実装でいうと，pika.BlockingConnectionで確立，生成したチャンネル（これがソケット）を
（kzさんが言うように）MainとPollerが共有してるからbad record macでコネクションが切れる。

なのでMainとPollerで共有するのはチャンネル（正しくはチャンネルではなく，チャンネルのラッパであるSender）ではなく，
コネクションを共有し，それぞれのプロセスが別々のチャンネルを使うと良い（はず）。

修正の範囲が大きすぎる。
TLS接続の機能は16.01からあるがなぜ気づかなかったのか…不覚

[masa0612]

bad record macはここの一番下に書いてる
https://www.rabbitmq.com/troubleshooting-ssl.html

[masa0612]

チャンネルがソケットって２つ上のコメントに書いたけど，このトラブルシューティングに具体的に明示されてない。
違うかも。。。

[masa0612]

いやでも複数コネクションが効率的じゃないからチャンネルが存在するのに，
TLS通信するためにコネクション増えるってのはやっぱおかしい。
やっぱりトラブルシューティングに書いてるソケット＝チャンネルって認識でいい気がする。

[masa0612]

既存のコードの構造が悪すぎる（自分が書いた）。
RabbitMQConnector内にConnectionとChannelが同居しているから，ConnectionとChannelを切り離せない。
どうしたもんかなぁ…

[masa0612]

transporter名を引数で指定して，Factoryがそれを元にConnectorを作るという仕組みになっている以上，
どうやってもコネクションを１つにし，それを各所で共有 -> チャンネルを複数生成という流れを実現できない。
一番楽なのはコネクションを３つに増やすこと。（RabbitMQHapiConnectorのインスタンスを３つ用意する）

でも汚いんだよなぁ…

[kz0817]

けど、異なるプロセスは、独立してコネクションをもつ方がトラブルが少なくてよいと思いますよ。

[masa0612]

貧乏性だから，実装されている機能は出来る限り使いたいという謎のこだわりが。。。