謎の通知メール

こんにちは くろねこです。

今回は昨年11月に起きたある事件について記載させていただきます。

f:id:kuronekofreedom:20220109174608j:plain

突然の通知メール

急激に寒くなった頃(2021年11月)、あるメールが届いた。

f:id:kuronekofreedom:20220108164045p:plain

ある日、届いたメール

このメールは、自宅インターネット接続のグローバルIPアドレスを通知するものです。
その時は、「あっ、アドレスが変わったんだぁ」と。
ルータやONUの再起動もしてないし、停電も聞いてないことから、「珍しいこともあるな~」とあまり気にしていませんでした。
しかし、数日後、再び、通知メールが届いた。

f:id:kuronekofreedom:20220108164149p:plain

再び届いたメール

「あれっ?」

メールの発信時刻は前回とほぼ同じ時刻です。

なんだろう???

軽く見てましたが、これが結構、果てしない旅になってしまいました。

ここで、我が家の、グローバルIPアドレス通知の仕組みについてちょっとだけ触れます。

グローバルIPアドレス通知の仕組み

我が家のインターネット接続環境は、固定IPアドレスではありません。
したがって、外部からアクセスする場合には、現在のグローバルIPアドレスを知る必要があるのです。

プロバイダが貸与する最近のBBルータやホームゲートウェイは、IPv4接続の場合にそれ自身がVPNサーバ(IPsec VPN)とすることができ、おまけにグローバルIPアドレスを通知してくれる機能(グローバルIPアドレスが変化した場合に指定の宛先にアドレスをメールしてくれる機能)を備えているものもあります。

この通知されたグローバルIPアドレスに対してVPN接続することで、外部から自宅のルータまでアクセスすることが可能となります。
もちろん、ルータの先(自宅の社内LAN上のファイルサーバなどのアクセス先)機器の電源が入っていることが前提です。

我が家のルータはNTTから貸与されているホームゲートウェイなんですが、ホームゲートウェイVPNサーバにしないとアドレス通知機能が利用できませんでした。

そこで、光回線をフレッツにする前に使用していた自前のプログラム(指定のURLにアクセス、レスポンスデータ内のHTMLデータから特定の条件(※)で取り出したグローバルIPアドレスをメール通知するもの)があるので、それを使うことで実現していました。今回、通知メールを送ってきたのはこの仕組みなんです。

※ URLの指定や、レスポンスデータ内の検索や、文字列取得の指示は、プログラム(GetWebPageData)に与えるパラメタファイルに記載する汎用的な仕組み
このプログラムとメールを送るプログラムをバッチファイルに記載し、タスクスケジューラで一定間隔に実行することでこの仕組みを実現しています。

問題点の整理(発生する現象の整理)

この謎の通知メールについて、
まず、発生している現象(事実)を整理します。

【現象】
毎週 月曜・木曜の3:00頃から11時過ぎまで、GetWebPageDataがエラーとなる。
エラーは、アクセス先からのレスポンスが一定時間内に無いというもの
その後、正常終了時に、アドレス通知メールが送信される。
(エラーからの復帰時にメール通知されるのは仕様である)
エラーが発生している状況はプログラムのログで確認

上記の「その後、正常終了時に」の時刻は決まって 11:10~11:30 前後です。

わかってる事実は、これだけ。

原因と思われるもの

問題発生の曜日と時刻に、規則性があることから、定期的に実行されるタスクが原因である可能性が高いと判断。
実行しているマシンで動作しているタスクを調査。

実行しているマシンは、ドメインコントローラ1号機(Active Directory)で、DNSサーバ、ファイルサーバ、プリントサーバ、VPNサーバでもあります。

ドメインコントローラ1号機は本来であれば、サーバ用のハードウェアがよいのですが、個人宅での運用なので、小型のデスクトップPCです。スペックは下記のとおりです。

f:id:kuronekofreedom:20220109172713p:plain

ドメインコントローラ1号機のスペック

定期的に実行されるタスクは下記の通り

【タスク1】 Windowsバックアップ
 ジョブの内容 :
  Windowsの状態バックアップ、ファイルバックアップ(約4TB)
 実行スケジュール : 毎週 月・木 2:30
 タスク終了時刻 : だいたい 実行日の11時過ぎ

【タスク2】 ドメインコントローラ2号機とのAD、DNSの複製
 ジョブの内容 :
  2台目のドメインコントローラ(以下、ドメコン)は Active Directory情報(以下、AD)のバックアップ用としての位置づけであり、
  ADの複製させるために定期的にサーバを起動する。
  サーバの起動は、タスクでマジックパケットを送付するプログラムを起動するのみ
 実行スケジュール : 毎週 日・木 20:00 (自動停止は、5:00)
 タスク終了時刻 : タスクはマジックパケット送付後、終了するが、2台目のドメコン自体のシャットダウンは5:00である。

ここに、これまでに通知メールが届いた日を重ねてみます。

f:id:kuronekofreedom:20220108164442p:plain

問題発生日とタスク実行日の関係

犯人は、Windowsバックアップ ですね。
状況証拠は揃いました。
あとは「ウラを取る」だけです。

原因の特定

11/16の夜、ウラとりします。

単純に、タスク1 Windowsバックアップ のスケジュールを変更します。
Windowsバックアップが原因であれば、問題発生日も変化するはずです。

変更後のスケジュール
【タスク1】 Windowsバックアップ
 実行スケジュール : 毎週 火 1:30

この時点で、しばらく様子見とします。(入院したため)

退院後、痛い腕で溜まっていた仕事を片付け、12/2 の夜,調査を再開しました。

f:id:kuronekofreedom:20220108164645p:plain

問題発生日とタスク実行日の関係
Windowsバックアップ実行日変更後)

これで、原因は、Windowsバックアップと特定しました。

対策検討

ここまでで、Windowsバックアップが原因であることが判明しました。更なる分析でプログラムの実行ログを確認すると
Windowsバックアップ実行時は、サーバ自体が高負荷(BUSY)状態であり、プログラムが実施しているWebアクセスがタイムアウトになっていることです。

グローバルIPアドレスの変化はいつ発生するかは不明で、半日程度かかるバックアップ時間帯に重なることは想定しなければなりません。
要するに、バックアップとグローバルIPアドレス通知は共存が大前提となります。となると・・・

  • タスクの優先度調整
  • 機能の分散

となります。
以下、それぞれについて検討します。

対策1 タスクの優先度調整

WindowsバックアップとグローバルIPアドレス通知のタスクの優先度を調整し、グローバルIPアドレス通知が正常に動作するようバックアップより高い優先度を設定する。

具体的には、タスクスケジューラに登録されているそれぞれのタスクの優先度を変更する。この場合、優先度の調整を実施しても結果が出ないケースも想定される。

それぞれのタスクの優先度を調整し、何回か動作させ、正常に動作する優先度を見つける。

ちょうどいい優先度が見つかるまで長期戦になる可能性もあるかも知れないが、ここで決着がつくのがベストである。

対策2 機能の分散

この対策は、グローバルIPアドレス通知をバックアップを実施していない別のサーバで実行する。

これを実現するためには、もう一台、常時動作しているマシンが必要となる。
しかし、グローバルIPアドレスを知るためにだけに、もう一台、マシンを準備するのもなぁ。。。

この対策は、最後の手段に取っておくこととした。

対策1の実施

2021年12月11日(土)、対策1 を実施する。

具体的には、グローバルIPアドレス通知 タスクの優先度を 7 から 6 に上げる。
もともとの優先度=7 はタスク登録時のデフォルトの優先度である。

優先度の変更方法は下記の手順で実施します。

  1. タスクスケジューラーで、対象ジョブをエクスポートする
  2. 対象ジョブを削除する
  3. エクスポートしたXMLファイル内の Priorityタグで記述されている部分の数値が優先度である。ここの値を 6 に変更し、ファイルを保存する
  4. 変更したXMLファイルをインポートし、タスク登録する

対策1の結果

対策1 実施後、最初の Windowsバックアップの実行日は、12/14(火)の未明に自動実行される

12/14の夜、早々に会社から帰宅し、後は寝るだけの状態

ちょっと期待しつつも恐る恐るサーバの画面ロックを外し、グローバルIPアドレス通知の GetWebPageData のログファイルを開いてみる。
問題の時間帯のログを見る。

バックアップジョブは、12/14 01:30 開始、同日 9:43 正常終了
その間、15分間隔で実行している グローバルIPアドレス通知プログラムはすべて正常終了
(PPPoE用ルータにWEBアクセスし、グローバルIPアドレス取得プログラム(※)は所定のスクリプトに従って検索し正常に取得できた。)

f:id:kuronekofreedom:20220108165104p:plain

GetWebPageDataはすべて正常終了

経過観察

対策1 実施で、問題解決したようであるが、しばらく運用を続け、必要であれば、優先度の再調整で何とかなりそうな感じである。
対策2は実施することはなさそうです。

まとめ

現在(2022年1月)まで、約一か月運用を続けてきましたが、今のところ、問題は発生していません。
おそらく、サーバの構成情報を大幅に変更しない限り問題は発生しないものと判断しています。一応、

これにて 一件落着!

とします。

ドメインコントローラ1号機は、企業向けのハードウェアではあるものの元々はクライアントPCとして販売されているものです。
それをドメインコントローラとして運用し、さらに役割を追加しているので、負荷が大きくなれば今回のような事態(一部の機能のレスポンス悪化や応答なしに陥る現象)はある意味、仕方ないものですね。

ではあるものの
今回、きれいなかたちで問題解決に至ったこと、自分自身に

「まだまだ捨てたもんじゃないな!」

しかし、こういうの めちゃめちゃ楽しかったです。
変態ですね(汗)

それでは、また。

 


くろねこ自由気ままな日記


ブログランキング・にほんブログ村へ
© 2020 くろねこ自由気ままな日記