unable to read data from frontend

ErogameScapeではpgpoolを使って冗長構成をとっています。
2つのサーバーマシンのそれぞれにApache、pgpool、PostgreSQLを動かしています。

構成

通常は192.168.0.14に接続するようにしています。
pgpoolを使い始めたころから原因不明で、192.168.0.13がちょいちょい切り離される事象が発生していました。
192.168.0.013のPostgreSQLは問題なく動いていて、keepalivedも切れていないので、pgpoolの問題だと思っていたのですが、切り離された場合のログを見ても、いきなり切れたようにしか見えませんでした。
pgpoolのVerがあがって、PostgreSQLからの応答がない…と判断するまでの時間をかえることができるようになったので、そのパラメータを十分大きくしてみたのですが、NGでした。

切り離される際のpgpoolのログは以下の通りです。

2016-12-27 03:31:33: pid 28889: LOG:  received degenerate backend request for node_id: 1 from pid [28889]
2016-12-27 03:31:33: pid 28889: WARNING:  write on backend 1 failed with error :"Success"
2016-12-27 03:31:33: pid 28889: DETAIL:  while trying to write data from offset: 0 wlen: 5
2016-12-27 03:31:33: pid 13031: LOG:  starting degeneration. shutdown host erogamescape13(5432)
2016-12-27 03:31:33: pid 19938: ERROR:  unable to read data from frontend
2016-12-27 03:31:33: pid 19938: DETAIL:  socket read failed with an error "Connection reset by peer"
2016-12-27 03:31:33: pid 30138: ERROR:  unable to read data from frontend
2016-12-27 03:31:33: pid 30138: DETAIL:  EOF encountered with frontend
2016-12-27 03:31:34: pid 13031: LOG:  Restart all children
2016-12-27 03:31:34: pid 16765: LOG:  child process received shutdown request signal 3
2016-12-27 03:31:34: pid 18712: LOG:  child process received shutdown request signal 3
2016-12-27 03:31:34: pid 18047: LOG:  child process received shutdown request signal 3
2016-12-27 03:31:34: pid 19036: LOG:  child process received shutdown request signal 3
2016-12-27 03:31:34: pid 13031: LOG:  failover: set new primary node: -1
2016-12-27 03:31:34: pid 13031: LOG:  failover: set new master node: 0
たいていこの時間あたりに切り離されるので、朝起きた時に気がついて、復帰させるということをしていました。
この3時30分頃、何が起こっているのか?と思って調べたところ、ログのローテーションの時間なことが分かりました。
そのログの中でもapacheのログのローテートの時間であることも分かりました。
ErogameScapeのApacheのログは1日で350MBくらいなのですが、このログを切り替えてapacheを再起動する際に、pgpoolが他のサーバーマシンで動いているPostgreSQLを切り離すようでした。
※単純にapacheを再起動するだけでは切り離されることはありませんでした。

そこで、Apacheのログが350MBの1/3くらいになるような時間にApacheのログをローテーションすることにしました。
それから2週間…pgpoolが他のサーバーマシンで動いているPostgreSQLを切り離すことはなくなりました…

なぜpgpoolがApacheの350MB程度のログをローテーションする際に、gpoolが他のサーバーマシンで動いているPostgreSQLを作成させて切り離すことがあるのか分からないのが、もやっとしますが、とりあえず切り離されなくなってよかったかなと…





2017年の年始からErogameScapeに接続しづらくなった件の原因について

2016の年末から2017年の年始にかけてPHPを7.1にあげました。
そのタイミングと同時にErogameScapeに接続しづらくなる事象が発生しました。
結論から書くと、PHPのVerUPは関係なく、サーバーを収容しているスイッチのPPPoE向けポートの障害だったことが分かりました。
最終的な切り分け結果を以下に示します。

被疑箇所図
悩まされたのが、開発用から現用系へのpingはOKですが、http接続はOKだったりNGだったりすることでした。
http接続が完全にOKでしたら、スイッチのPPPoE向けポートが悪いと断言できるのですが、微妙にNGになるのです…

被疑箇所のポートに刺さっていたLANケーブルを別のポートに接続したところ事象が発生しなくなったので、おそらくこのポートが被疑だと思います。

PHPのVerを7.1にあげた際に事象が発生したことと、サーバーへのpingはOKとなることから、PHPとApacheを被疑として調査していたのですが、当たり前ですが悪い箇所は見当たらず、しかしApacheを再起動すると直ることが多く(直らないこともありました)、現象は5分程度で自然回復するため、切り分けに時間がかかってしまいました。

調査の対象に「サーバーからPPPoEルータ向けにping」を追加していれば、もっと早く分かった気がいたします。ここの区間は疑っていませんでした。

大きなデータの転送に失敗する

ある日、何回やってもpg_basebackupが失敗する事象が発生しました。
結論から書くと、PPPoEルータの再起動で回復しました。

pg_basebackupは-Pと-vのオプションをつけると、今、どのファイルを送っているのかを見ることができます。
今回の事象は、途中でファイルの転送が止まる…というものでした。

転送が止まった時のメッセージは以下のとおりです。
トランザクションログの開始ポイント: タイムライン18上の35/CE053750
  617773/12835829 kB (4%), 0/1 テーブル空間 (...ive_log/0000001200000035000000B4)
トランザクションログの開始ポイント: タイムライン18上の35/C9000028
3803779/12753907 kB (29%), 0/1 テーブル空間 (...gsql/9.6/data/base/16390/18342.1)
何回かpg_basebackupを試してみたのですが、同じファイルで転送が失敗するわけではありませんでした。
最初は快調にデータを送るのですが、ピタッと転送が止まります。

ErogameScapeは自宅サーバーなので、いつもそこそこの量のパケットをPPPoEルータは処理をしています。
サービス影響は見えなかったので、バックアップ先を疑ってみたり、バックアップ先までのネットワークで大量のデータを送ったときにパケットを阻止している…可能性を疑って、別のサーバーにバックアップを試したり、プロバイダを変更したりしましたがNGでした。

pg_basebackupは-X sオプションをつけると、トランザクションログをストリームするのですが、面白いことにselect * from pg_stat_replicationを見ると、backupの接続は切れるのに、streamの接続は切れずに、淡々と送り続けていました。
これを見て、ネットワークは繋がっいてデータは転送できるのに、backupの接続だけ切れるようにみえて…実際にそうなのですが…pg_basebackupだけを疑って切り分けをしていました。

ちなみにpg_basebackupに-X sオプションをつけて実行した際の、select * from pg_stat_replicationは以下のようになります。2つ接続が開かれているのが分かります。
# select * from pg_stat_replication;
  pid  | usesysid |     usename      | application_name |  client_addr    | client_hostname | client_port |         backend_st
art         | backend_xmin |   state   | sent_location | write_location   | flush_location | replay_location | sync_priority |
 sync_state
-------+----------+------------------+------------------+-----------------+-----------------+-------------+-------------------
------------+--------------+-----------+---------------+----------------+----------------+-----------------+---------------+
------------
 12737 |    16389 | replication_user | pg_basebackup    | ***.***.***.*** |                 |       36151 | 2017-02-12 21:28:1
9.644764+09 |              | backup    |               |                |                |                 |             0 |
 async
 12836 |    16389 | replication_user | pg_basebackup    | ***.***.***.*** |                 |       36152 | 2017-02-12 21:29:2
4.968719+09 |              | streaming | 35/C022FB60   | 35/C022E9C0    | 35/C0000000    |                 |             0 |
 async
(2 行)



その後、大量データをインターネットの向こうにあるサーバーに送ると途中で転送が止まることが分かり、pg_basebackupの問題ではないことが分かりました。

ErogameScapeに使用しているPPPoEルータとは別のPPPoEルータを介してバックアップ先にデータを転送するとOKだったので、ErogameScapeに使用しているPPPoEルータを疑って再起動したところ回復しました。

ああ…こういう不具合が起きることもあるんだなあ…と思った次第です。
ネットワーク機器は、思いもよらない壊れ方をします…

no server suitable for synchronization found

ある日、ntpdが時刻を上位サーバーから取れていないことが分かりました。
ErogameScapeではntpdの様子をmuninで監視しています。
以下に当時のmuninのグラフを示します。

ntp_offset-week

グラフの線があるところが上位のNTPサーバーから時刻を取得出来ているところ、線がないところは取得出来ていないところです。

ntpqコマンドの実行結果は以下の通りでした。
$ /usr/sbin/ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 ntp01.****.**.j ***.***.***.***  2 u  13h  512    0   43.504   -8.250   0.000
 ntp02.****.**.j ***.***.***.***  2 u  10h 1024    0   16.760    0.650   0.000
 ntp03.****.**.j ***.***.***.***  2 u  11h  512    0   23.520   -0.850   0.000
あるべき姿は、いずれかの行の先頭に*があることです。
正常な場合のコマンドの結果は以下の通りです。
$ /usr/sbin/ntpp -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
+ntp01.****.**.j ***.***.***.***  2 u  139   64  144   10.949  -294.17  46.238
*ntp02.****.**.j ***.***.***.***  2 u  334   64  140   11.410  -292.78  14.636
 ntp03.****.**.j ***.***.***.***  2 u  330   64  140   15.319  -275.40  20.041

とりあえず、ntpサーバーを再起動すると、INITのままで、だいぶ時間がたっても、3つすべてINITのままとなるか、やっと1つだけ繋がる状態でした。
# /usr/sbin/ntpq -p
     remote           refid      st t when poll reach   delay   offset  jitter
==============================================================================
 ntp01.****.**.j .INIT.          16 u    -   64    0    0.000    0.000   0.000
*ntp02.****.**.j ***.***.***.***  2 u   49   64    1    9.308    0.609   0.000
 ntp03.****.**.j .INIT.          16 u    -   64    0    0.000    0.000   0.000
通常はすぐにすべてrefidの部分はINITでなくなるはずなのです…
ntpdを止めて、ntpdateを実行してみると以下のようになりました。
# /usr/sbin/ntpdate -b ntp01.****.**.jp
 2 Feb 22:17:44 ntpdate[32505]: no server suitable for synchronization found
ntpdateもntpdもUDPの123番ポートを使ってNTPサーバーに問い合わせに行きます。
宛先ポートも123番、送信元ポートも123番です。

ntpdateコマンドは-uオプションをつけると非特権ポート…1024番以降のポートを送信元として問い合わせを実施します。-uオプションを使ってntpdateを実行すると、時刻が取れました。
# /usr/sbin/ntpdate -b -u ntp01.****.**.jp
 2 Feb 22:17:36 ntpdate[32493]: step time server ***.***.***.*** offset -0.007014 sec
自身のNW機器は特に変更していないので…一応、NW機器が悪さをしている可能性もあるので、PPPoEルータを再起動しましたが、疎通はNG、iptablesも外してみましたが疎通はNGでした。
おそらくになるのですが、プロバイダからこちらのNW向けのUDPの123番ポートが微妙に閉じられている…微妙というのは、グラフを見る限りたまに繋がったりしているので、動的に123番ポートが閉じたり開いたりしているのかもしれません。

ntpdは自身が使用するポート番号を変更できない…ソースを変更してコンパイルすれば出来るようなのですが、それはしたくないなあ…と思いました。

ntpdのかわりにchronydというNTPサーバーがあり、こちらは自身のポートは123番ポートを使用しない…おそらく非特権ポートを使うので、乗り換えることにしました。

chronydについては以下のドキュメントがいいかなと思います。
chronydを使って無事時刻を取得できるようになりました。

ちなみに、ntpdateのデバッグモードである-dオプションをつけると、ちゃんと時刻が取得できるように見えてしまうので、とても悩みました。
おそらく-dオプションをつけた場合、送信元ポートは123番ではなく、非特権ポートを使うのかな…と思います。
# /usr/sbin/ntpdate -d time1.google.com
 1 Feb 20:52:36 ntpdate[17925]: ntpdate 4.2.6p5@1.2349-o Tue May 31 10:09:22 UTC 2016 (1)
Looking for host time1.google.com and service ntp
host found : time1.google.com
transmit(216.239.35.0)
receive(216.239.35.0)
transmit(216.239.35.0)
receive(216.239.35.0)
transmit(216.239.35.0)
receive(216.239.35.0)
transmit(216.239.35.0)
receive(216.239.35.0)
server 216.239.35.0, port 123
stratum 2, precision -20, leap 00, trust 000
refid [216.239.35.0], delay 0.20763, dispersion 0.00116
transmitted 4, in filter 4
reference time:    dc3c4a85.949cfffe  Wed, Feb  1 2017 20:52:37.580
originate timestamp: dc3c4a85.949d0001  Wed, Feb  1 2017 20:52:37.580
transmit timestamp:  dc3c4a85.76b5b1f9  Wed, Feb  1 2017 20:52:37.463
filter delay:  0.21288  0.21077  0.20763  0.21376 
         0.00000  0.00000  0.00000  0.00000 
filter offset: 0.022838 0.025773 0.025351 0.022737
         0.000000 0.000000 0.000000 0.000000
delay 0.20763, dispersion 0.00116
offset 0.025351

 1 Feb 20:52:37 ntpdate[17925]: adjust time server 216.239.35.0 offset 0.025351 sec

php7.1で複数のRedisサーバーをsession.save_handlerに設定しても冗長構成にはならない

原因は分からないのですが、待機系サーバーのmemcashedの動作がおかしい気がする…ので、session.save_handlerとして使っているmemcashedの別の候補として、PHP7.1において、session.save_handlerとして、Redisを使用したいと思いました。

session.save_pathには複数のRedisサーバーを設定すれば、Redisサーバーが1つ落ちてもサービスを継続できるかな…と思いましたが出来ませんでした。

環境は以下の通りです。
  • CentOS6および7
  • PHP 7.1.0
  • Redis server version 2.4.10
  • phpredis 3.1.1RC2
RedisをSession handlerとして使うには以下の設定が必要です。

/etc/php.iniに以下を記述
session.save_handler = redis
session.save_path = "tcp://localhost:6379"
extension=redis.so

さて、PhpRedisにREADMEによるとsession.save_pathには複数のサーバーを指定できるようになっています。
https://github.com/phpredis/phpredis/blob/develop/README.markdown#user-content-php-session-handler

そこで以下のように記述すれば1つサーバーが落ちてもサービスを継続できると思いました。
session.save_path = "tcp://localhost:6379, tcp://192.168.0.14:6379"

localhostと192.168.0.14にRedisで起動 → 192.168.0.14にセッションの情報が記録されることを確認
localhostのみRedisを起動 → NG、以下のエラーメッセージが出る

Warning: session_start(): connect() failed: Connection refused
Warning: session_start(): Failed to read session data: redis (path: tcp://localhost:6379, tcp://192.168.0.14:6379)

ちなみにsession.save_path = "tcp://localhost:6379"と書くと、localhostにセッションの情報が記録されるのでlocalhostの設定は問題ありません。

振り分けロジックは分からないのですが、逆のケースもNGです。

localhostと192.168.0.14にRedisで起動 → localhostにセッションの情報が記録されることを確認
192.168.0.14のみRedisを起動 → NG


memcashedとmemcasheの場合、session.save_pathに複数のサーバーを記述すれば、すべてのサーバーに同じ情報を書き込むため、サーバーが1台落ちても問題ないのですが、PhpRedisの場合はsession.save_pathに複数サーバーを書くと負荷分散するだけで、サーバーが落ちた場合の対処は別に仕組みを整えないといけないです。
具体的にどうするかというと以下のドキュメントにいろいろな構成が書いてあります。
http://tech.gmo-media.jp/post/48748908427/introduce-redis-sentinel

お手軽に冗長構成をとれたらいいなあ…と思っていたのですが、どの構成もそこそこ手間がかかって、ここまでして冗長構成を取る必要も無いかなあ…と思ったのでRedisは導入を見送ろうと思いました。
記事検索