2017年02月

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

記事検索