トップ > New Relic > Windowsのエラーログを使ったトラブルシューティング方法

Windowsのエラーログを使ったトラブルシューティング方法

New Relic Windows トラブルシューティング
記事タイトルとURLをコピーする

みなさんこんにちは。マネージドサービス部MSS課の塩野（正）です。

9月に入ってもう１週間とちょっと経ち、そろそろ少しは涼しくなってくれてもいいのにと思っていますが、まだ昼間は35度を超える日がちらほらあるので秋がとても待ち遠しい今日この頃です。

トラブル発生時にエラーログを確認することは、きっと空気を吸うがごとく当たり前のようにご対応されていることと推測していますが、このエラーログはインターネットでエラー内容を検索をしても「的を得た答えがねぇ」ってパターンもきっと多いのではないかと思います。今回はNew Relicを使っていてそんなパターンに出くわしたけど、こんな感じで対応したよという記事になります。

どちらかといえばレアケースになりますのであまり参考にならないかもしれませんが、ひとつの対応事例として取り上げさせていただきました。

対象者

  • Windowsをお使いの方
  • エラーログを含め、一般的なトラブル対応の切り分け方法を知りたい方

エラーログ調査の進めかた

エラーログ調査の進め方は色々あるかと思いますが、私の観点でお話させていただくとログ調査を含めた調査対応の際は、どのような環境で発生しているのか、どのくらいの頻度で発生しているのか、他に同様の事象が発生しているものはないかなどの環境や共通する項目を整理するところから始めています。おそらくこの記事を読まれている皆様方も同じように調査されていることと推測しています。こういった整理できる情報を整理した上で、どういう状況なら事象が発生する可能性があり、どういう状況なら事象が発生しない可能性があるかというのを仮説を立てながら調査していき、この仮説の場合は事象が発生する可能性がある、この仮説の場合は事象が発生しない可能性があるというのを見極めていくのが基本的な流れとなります。

基本的には仮説検証の段階で、ここまでは大丈夫（事象が起こらない）、ここはダメ（事象が再現する）のどちらかの条件を満たすことが確認できれば、それをベースにじゃ、ここは大丈夫？ダメ？を積み重ねていって最終的にこれじゃね？ってのを推測するのを一連の流れとしていますが、こういった調査方法を記事にされているケースって私の感覚ではあまりないように感じています（たくさんあったらごめんなさい）。そのため、こういった調査の考慮事項でここは足りないんじゃない？とか、もっとこうした方がいいよなどという部分があればご指摘いただけると嬉しいですし、私もこういう観点でこのように調査しているよ？というのをブログなどで発信していただけると、同じような悩みを持っている他の方にとってもとても有益ではないかと考えています。

さて余談な話はここまでにして、本題に入りましょう。

エラーログ「DLL "C:\Windows\System32\bitsperf.dll" のサービス "BITS" の Open プロシージャは、エラー コード 内部エラーが発生しました。 で失敗しました。」の調査

今回のエラーログの情報を整理すると、以下のような状況が見えてきました。

  • 発生している環境：Windows
  • OSバージョン：不明（いくつかあるっぽい）
  • 関連するアプリケーション：New Relic Infrastructure Agent
  • エラーメッセージ
    • DLL "C:\Windows\System32\bitsperf.dll" のサービス "BITS" の Open プロシージャは、エラー コード 内部エラーが発生しました。 で失敗しました。このサービスのパフォーマンス データは使用できません。

とはいえ、情報が色々と不足している点は追加で確認するとして、一番重要なエラーメッセージからもう少し情報が拾えそうなので、メッセージを分解してキーワードを拾ってみましょう。

ここで拾えるキーワードとしては、「bitsperf.dll」、「サービス "BITS" 」、「Open プロシージャ」、「内部エラーが発生」、「サービスのパフォーマンス データは使用できません」くらいでしょうか。次に拾ったキーワードを組み立てなおして、何が起こったか推測します。この時点ではしっかりした仮説までは不要で、ざっくりした分析ができればOKです。まず、「bitsperf.dll」は「BITS」サービスと関連しているモジュールである可能性が高そう、「BITS」サービスでプロシージャをオープンにしようとしたときに何か発生した可能性が高そう、発生した何かが「内部エラー」としてエラーログ検知された可能性がありそう、その結果サービスのパフォーマンス データは使用できない状況にある可能性が考えられそう、といったレベルに分解してみました。ここまで分解すると、ここから先で「BITS」サービスとは何か？というのを調査する必要がありそうというのがなんとなく見えてきました。それでは「BITS」サービスとは何かを調査したものを次にまとめ直してみましょう。

Background Intelligent Transfer Service（BITS）についての調査

Background Intelligent Transfer Service（BITS）とは

そもそもBITSとは何というと、正式名称がBackground Intelligent Transfer Service（略称BITS）というサービスで、Microsoftが開発したWindowsの重要なシステムサービスのうちの一つです。このサービスは、Windowsがネットワークを通じてファイルを効率的に転送することを目的としたサービスになります。

Background Intelligent Transfer Service（BITS）の主な特徴

Background Intelligent Transfer Service（BITS）は以下のような特徴を持つサービスになります。

  1. Background Intelligent Transfer Service（BITS）は、ネットワークの空き帯域幅を利用してファイル転送をおこなう。他のアプリケーションがネットワークを使用している場合、Background Intelligent Transfer Service（BITS）が自動的に転送速度を調整する。
  2. Background Intelligent Transfer Service（BITS）はジョブの中でネットワーク接続を監視しており、ネットワーク接続が切断された場合には転送を一時停止し、ネットワーク接続が復旧したら自動的に再開する。
  3. 転送ジョブに優先順位を設定することができ、重要なファイルを先に転送することが可能。

あまり意識をすることがないサービスですが、大きなサイズのファイルをやり取りする際にとても有益で重要なサービスであるということがわかりました。

一般的にBackground Intelligent Transfer Service（BITS）が使用されるシーン

Background Intelligent Transfer Service（BITS）は主に以下のような場面で使用されます。

  1. Windows Update時のシステムの更新プログラムのダウンロードに利用される
  2. Microsoft Officeなどのアプリケーションのアップデートに利用される
  3. 社内用のアップデートサーバーWindows Server Update Services（WSUS）との通信で利用される

そのため、Background Intelligent Transfer Service（BITS）と一緒に使用されるサービスには以下のようなものがあります。

  • Windows Update（Microsoft Update）
  • Windows Server Update Services（WSUS）

※WSUSサーバ自身がMicrosoftからパッチをダウンロードする場合にもBackground Intelligent Transfer Service（BITS）が使用されます。

Background Intelligent Transfer Service（BITS）が停止した場合の影響

では、Background Intelligent Transfer Service（BITS）が停止した場合の影響はどのようなものがあるのでしょうか。調査の結果、以下のような影響が出る可能性があるようです。

  1. システムの更新プログラムがダウンロードできなくなり、OSやアプリケーションなどの重要なセキュリティパッチが適用されない可能性が考えられる。
  2. Background Intelligent Transfer Service（BITS）を使用しているアプリケーションでファイル転送が行えなくなる可能性がある。

割と重要なサービスであることがわかりましたが、このサービスのもうひとつの特徴として、Background Intelligent Transfer Service（BITS）のサービスが起動していない場合でも、通常はジョブが開始されるタイミングで自動的に起動します。ただし、サービスのスタートアップが無効で設定されている場合は自動起動できませんので、こうした場合に何らかのエラーとなってメッセージが出る可能性は少なくとも考えられそうです。

また、通信するジョブがない場合で、スタートアップの種類が手動の場合、サービスが自動停止されることもあります。そのため、サービスが停止して問題が出るような環境の場合は、サービスのスタートアップの設定を自動、または自動（遅延起動）にすることをオススメいたします。

仮説を立てる

エラーログが発生した環境の整理とざっくりとした分解、関連するサービスについての調査が終わりましたので、次にどのような状況下だったらエラーが発生する可能性があるか仮説を立てて、仮説通りのシナリオで同様の事象が発生するか検証していきたいと思います。上記、停止した場合の影響の項に簡単に記載しましたが、サービスのスタートアップが無効になっているときにサービスが自動起動できない場合に何らかのエラーメッセージとなって表れる可能性が考えられそうというのが、ここで立てることができるひとつの仮説になりそうです。それでは、その仮説に基づいて動作を確認してみましょう。

仮説検証をおこなう

仮説検証をおこなう上で最も大事なのが、「事象が再発する環境の条件を確認すること」です。今回、事象再現のためのキーワードとして、「Background Intelligent Transfer Service（BITS）の停止」以外で関連するアプリケーションとして「New Relic Infrastructure Agent」が使用されていました。そのため、「Background Intelligent Transfer Service（BITS）の停止」で事象が再現しない場合は、「New Relic Infrastructure Agent」も含めての確認が必要になることに留意が必要になります。

仮説検証の環境構築

バックグラウンドで転送を行うサービスとなりますので、何かしらファイルを転送するジョブを作成してファイル転送をおこなうことで事象の確認を行います。

  • 検証環境
    • 共有フォルダの作成
      • ①新しく検証用のフォルダ作成し共有フォルダとして設定する
      • ②新規作成したフォルダを右クリックして、プロパティの共有タブから共有設定をおこなう
    • テストファイルの作成
      • ①BITSジョブとして転送設定をおこなうためのテスト用のファイルを作成する
      • ②fsutilコマンドで1GB程度のテストファイルを作成する

テストファイルの作成は下記コマンドを使用しました。

fsutil file createnew testfile.dat 1073741824
  • 検証方法
    • デスクトップに保存してあるファイルを、\\localhost\testfolder にpowershellを使用してコピーする
      • powershell.exe -executionpolicy bypass .\testcopy.ps1
テスト用スクリプト(testcopy.ps1)
# 必要なモジュールのインポート
Import-Module BitsTransfer

# 転送元と転送先のパスを設定
$sourcePath = "$env:USERPROFILE\Desktop\testfile.dat"
$destinationPath = "\\localhost\testfolder\testfile.dat"

# 10回繰り返す
for ($i = 1; $i -le 10; $i++) {
    Write-Host "処理回数: $i"

    # 転送先のファイル削除
    if (Test-Path $destinationPath) {
        Remove-Item $destinationPath -Force
        Write-Host "転送先のファイルを削除しました: $destinationPath"
    } else {
        Write-Host "転送先にファイルが存在しません: $destinationPath"
    }

    # ファイル転送
    $job = Start-BitsTransfer -Source $sourcePath -Destination $destinationPath -Asynchronous

    # 転送状況の監視
    while (($job.JobState -eq "Transferring") -or ($job.JobState -eq "Connecting")) {
        $percentComplete = [math]::Round(($job.BytesTransferred / $job.BytesTotal) * 100, 2)
        Write-Host "転送状況: $percentComplete% 完了"
        Start-Sleep -Seconds 2
    }

    # ジョブの完了処理
    switch ($job.JobState) {
        "Transferred" {
            Complete-BitsTransfer -BitsJob $job
            Write-Host "転送が正常に完了しました"
        }
        "Error" {
            Write-Host "転送中にエラーが発生しました: $($job.ErrorDescription)"
            Remove-BitsTransfer -BitsJob $job
        }
        default {
            Write-Host "予期しない状態: $($job.JobState)"
            Remove-BitsTransfer -BitsJob $job
        }
    }

    Write-Host "----------------------------"
    Start-Sleep -Seconds 5  # 次の処理までの待機時間
}

仮説検証の結果

Background Intelligent Transfer Service（BITS）サービスが起動している状況下では下記のようにBackground Intelligent Transfer Service（BITS）サービスを使用したファイル転送は実施できたものの、Background Intelligent Transfer Service（BITS）サービスを停止するとスクリプトがエラーとなってコケてしまうため、この方法で検証を進めることは叶いませんでした。

成功時（サービス起動時）

処理回数: 1
転送先のファイルを削除しました: \\localhost\test\testfile.dat
転送状況: 0% 完了
転送状況: 18.75% 完了
転送状況: 31.35% 完了
転送状況: 43.95% 完了
転送状況: 56.54% 完了
転送状況: 69.14% 完了
転送状況: 81.74% 完了
転送状況: 94.34% 完了
転送が正常に完了しました
----------------------------
処理回数: 2
転送先のファイルを削除しました: \\localhost\test\testfile.dat
転送状況: 0% 完了
転送状況: 17.87% 完了
転送状況: 30.47% 完了
転送状況: 43.07% 完了
転送状況: 55.37% 完了
転送状況: 67.97% 完了
転送状況: 79.1% 完了
転送状況: 91.41% 完了
転送が正常に完了しました
　　：
失敗時（サービス無効時）

処理回数: 1
転送先のファイルを削除しました: \\localhost\test\testfile.dat
Start-BitsTransfer : 指定されたサービスは無効であるか、または有効なデバイスが関連付けられていないため、開始できません。
指定されたサービスは無効であるか、または有効なデバイスが関連付けられていないため、開始できません。
発生場所 C:\Users\Administrator\Desktop\kensho_01.ps1:21 文字:12
+     $job = Start-BitsTransfer -Source $sourcePath -Destination $desti ...
+            ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (:) [Start-BitsTransfer]、COMException
    + FullyQualifiedErrorId : StartBitsTransferCOMException,Microsoft.BackgroundIntelligentTransfer.Management.NewBitsTransferCommand
 
Start-BitsTransfer : オブジェクト参照がオブジェクト インスタンスに設定されていません。
発生場所 C:\Users\Administrator\Desktop\kensho_01.ps1:21 文字:12
+     $job = Start-BitsTransfer -Source $sourcePath -Destination $desti ...
+            ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Start-BitsTransfer], NullReferenceException
    + FullyQualifiedErrorId : System.NullReferenceException,Microsoft.BackgroundIntelligentTransfer.Management.NewBitsTransferCommand
 
予期しない状態: 
Remove-BitsTransfer : 指定されたサービスは無効であるか、または有効なデバイスが関連付けられていないため、開始できません。
指定されたサービスは無効であるか、または有効なデバイスが関連付けられていないため、開始できません。
発生場所 C:\Users\Administrator\Desktop\kensho_01.ps1:42 文字:13
+             Remove-BitsTransfer -BitsJob $job
+             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : InvalidOperation: (:) [Remove-BitsTransfer]、COMException
    + FullyQualifiedErrorId : RemoveBitsTransferCOMException,Microsoft.BackgroundIntelligentTransfer.Management.ClearBitsTransferCommand
 
Remove-BitsTransfer : オブジェクト参照がオブジェクト インスタンスに設定されていません。
発生場所 C:\Users\Administrator\Desktop\kensho_01.ps1:42 文字:13
+             Remove-BitsTransfer -BitsJob $job
+             ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
    + CategoryInfo          : NotSpecified: (:) [Remove-BitsTransfer], NullReferenceException
    + FullyQualifiedErrorId : System.NullReferenceException,Microsoft.BackgroundIntelligentTransfer.Management.ClearBitsTransferCommand
 
----------------------------
処理回数: 2
　　：

Powershellから強制的にbitsperf.dllのプロシージャをオープンすることは難しそうという事が分かりましたので、この方法は断念しBackground Intelligent Transfer Service（BITS）サービスを無効／停止にした状態でNew Relic Infrastructure Agentを起動し放置して状況が変わるか確認してみました。

事象は再現しましたが１日１回程度発生している状況ということで、再現時の頻度はあまり高くはないことが確認できました。また再現時の頻度もおおよそ判明しましたので、この情報を以ってBackground Intelligent Transfer Service（BITS）サービスを自動／起動状態で放置し、事象が発生しないことを確認する逆サイドの検証を実施します。これは特定の設定変更した場合に、本当にその仮説検証の内容って正しいんだよね？というのを確認するために行う検証になります。そして１日１回程度発生している事象が発生しないことが確認できたので、ざっくりとした仮説検証はこれで完了となります。

仮説検証のまとめ

ざっくりとまとめなおすと、下記のような状況が見えてきました。 ここから推測されることは、当事象は複合要因で発生している可能性が高いと推測され、エージェントが何らかのチェックの際にBITSをOpenにしてそれがエラーの原因となっている可能性が高そうという状況でした。

  • Background Intelligent Transfer Service（BITS）サービスが停止していること
  • New Relic Infrastructure Agentが起動していること
  • 検証環境では1日1回程度の低い頻度で事象が発生していたこと

まとめ

ちょうど面白そうな内容であまり事例のブログも見当たらなかったことから、私がよくやるトラブルなどが発生した際にどのような観点でどのように調査をしているか、その調査方法を記事にまとめてみました。私の観点で不足しているところや至らないところもあるとは思いますが、切り分け時の考え方をなるべく汎用化できるようにまとめてみましたので、もし同じようなトラブル時の調査を行わなければいけないといった状況になった際に頭の片隅から思い出していただければ嬉しいです。

◆　塩野　正人
◆　マネージドサービス部　所属
◆　X（Twitter）：@shioccii
◆　過去記事はこちら

前職ではオンプレミスで仮想化基盤の構築や運用に従事。現在は運用部隊でNew Relicを使ってサービス改善に奮闘中。