[Dynatrace] Aras Innovator の IIS のログをパースして Request Processing Time を可視化したい

2024年ももうおしまい

早いもので、もう12月です。12月と言えば、そうです、QiitaさんのAdvent Calendarのシーズンです！パチパチパチ。今年からTech blogを書き始めていますが、なかなか続けられませんでした（一月に1回くらいのペースかな？）最後はキレイに着したく、このAdvent Calendarで締めくくりたいと思います。テーマは、Aras Innovator というPLM製品の監視についてです。Aras Innovatorは、IIS/.INET/MS SQLの組み合わせで動くPLM製品で、世界中でひろく利用されています。この製品のIISについて、今日はブログを書きたいと思います。

IISのログを見る化したい

Dynatrace の OneAgent は Aras のようなPLM製品でも、フルスタック監視が可能です。理由は、DynatraceのOneAgentがサポートする runtime technology で動作しているため、ソースコードの中身は全く分からなくても、deep monitoring できかつ、ログも自動的に拾ってくれます。Arasではいろいろなコンポーネントが動いていますが、そのなかでもフロントエンドの処理を司るIISは、OneAgentでサーバサイド側のモニタリングをしつつも、IISが出力するログも見えるかできると、IISのパフォーマンス向上に役立てられます。

早速IISのログをパースしてみよう

IISのログをパースできるようにするには、まずIISのログの出力の仕組みを正しく理解しておく必要があります。IISのログについては、Microsoft Learn Challenge サイトに丁寧にまとめてありますので、そちらを参考にして下さい。以下、そこからの抜粋です。

Date (date): the date on which the request occurred.
Time (time): the time, in Coordinated Universal Time (UTC), at which the request occurred.
Client IP Address (c-ip): the IP address of the client that made the request.
User Name (cs-username): the name of the authenticated user who accessed your server. Anonymous users are indicated by a hyphen.
Service Name (s-sitename): the site instance number that fulfilled the request.
Server Name (s-computername): the name of the server on which the log file entry was generated.
Server IP Address (s-ip): the IP address of the server on which the log file entry was generated.
Server Port (s-port): the server port number that is configured for the service.
Method (cs-method): the requested action, for example, a GET method.
URI Stem (cs-uri-stem): the Universal Resource Identifier, or target, of the action.
URI Query (cs-uri-query): the query, if any, that the client was trying to perform. A Universal Resource Identifier (URI) query is necessary only for dynamic pages.
Protocol Status (sc-status): the HTTP or FTP status code.
Protocol Sub-status (sc-substatus): the HTTP or FTP substatus code.
Win32 Status (sc-win32-status): the Windows status code.
Bytes Sent (sc-bytes): the number of bytes that the server sent.
Bytes Received (cs-bytes): the number of bytes that the server received.
Time Taken (time-taken): the length of time that the action took in milliseconds.
Protocol Version (cs-version): the protocol version that the client used.
Host (cs-host): the host name, if any.
User Agent (cs(UserAgent)): the browser type that the client used.
Cookie (cs(Cookie)): the content of the cookie sent or received, if any.
Referrer (cs(Referrer)): the site that the user last visited. This site provided a link to the current site.

まずここで、ログを出力フォーマットを正しく理解しておき、その次にDynatraceでログがパース、可視化できるようにしていきましょう。

ログの属性設定

IISのログをパースする前に、Dynatraceのダッシュボードやログ画面で、抽出したログの属性（上記、W3C fieldsのこと）のどれを可視化（ダッシュボードで）、フィルタ（ログ画面で）したいか決めておきます。ここでは、IISのログのキーとなる、4つの W3C fields をDynatraceが画面上で操作できるようにしたいと思います。

• URI Stem
• Protocl Status
• Protocl Sub-status
• Method
• Time Taken
  これらをIISログからパースしたあと、Dynatraceのログ画面でフィルタ操作できるよう「Log Monitoring > Custom attribues」でまず定義します。Attribute名は、それらがIISから取ったものだと分かるように、命名規則として「iis.XXX」に統一します。作成したAttributeをログ画面のフィルタ操作の対象とさせてたい場合は、「Show attribute values in side bar」を有効にしておきます。

「Show attribute values in side bar」を有効にするのは、ManagedのLog Monitoring Classicをご利用の場合のみです。「Logs on Grail」をご利用の場合は、デフォルトのままで構いません（ToggleをONにしない）

ログのパース処理設定

ここからが実際のログの処理ルールの定義になります。Dynatraceでは、DPL（Dynatrace Pattern Language）と呼ばれる言語を使いログのプロセッシング処理を行います。まず、IISのサンプルログを実際のログから抽出します。

2024-12-03 12:43:26 ::1 POST /InnovatorServer/Server/InnovatorServer.aspx - 80 - ::1 Mozilla/5.0+(Windows+NT+10.0;+Win64;+x64)+AppleWebKit/537.36+(KHTML,+like+Gecko)+Chrome/131.0.0.0+Safari/537.36+Edg/131.0.0.0 - 200 0 0 764

これを例にパースし、取り出した変数を先ほど設定した log attributes と紐付けていきます。先に答え合わせをすると、こんなルールを書くとキレイに各フィールドを整形できます。

PARSE(content,"
 STRING{10}:iis.date SPACE
 STRING{8}:iis.time SPACE
 IPADDR:iis.s_ip SPACE
 STRING:iis.cs_method SPACE
 STRING:iis.cs_uri_stem SPACE <<< log attribute
 LD:iis.cs_uri_query SPACE
 INT:iis.cs_port SPACE
 LD:iis.cs_username SPACE
 IPADDR:iis.c_ip SPACE
 LD:iis.cs_user_agent SPACE
 LD:iis.cs_referer SPACE
 INT:iis.cs_status SPACE <<< log attribute
 INT:iis.cs_substattus SPACE <<< log attribute
 INT:iis.cs_win32_status SPACE
 INT:iis.time_taken  <<< log attribute
 ")

IISの場合、パースしやすくできていますので、基本区切り文字は「SPACE」で行い、取り出したい文字列や数字はそれぞれが持っているデータの型を見て、INT（整数）、IPADDR（IPv4/IPv6アドレス）、LD（文字すべて）、STRING（長さの決まった文字列）を適切に選択して貰えれば、比較簡単に実現できると思います。
これをあとは、「Settings > Log Monitoring」>「Processing」に貼り付け、ルールを保存するだけです。保存する前には、必ず「Test the rule」ボタンをクリックし、意図した通りのパースができているか確認しましょう♪

• Rule name
  • ルールの名称なんで、分かりやすい名前を付けましょう
• Matcher
  • どういうログ条件下で、プロセッシング処理を行うか定義します。ここでは、全てのIISのログを対象に処理を行いたいので「log.source」属性がIISから生成されるものを指定します

• Run the test
  • 「Test the rule」ボタンを必ずクリックし、意図した通りにパースできているか、Attributeに値が格納されているか確認しましょう

Log分析画面で使ってみよう

ここからは先ほどバースしたAttributeを使ってIISログが見やすくなったか、みてみましょう。まずは、Attributeのフィルタを使ってフィルタできるか試しています。まずは、Methodでフィルタしてみます。Aras Innvotaorホストでは、OneAgentがフルスタックでインストールされているので、自動的にRUMが有効になっています。RUMが有効になっているとBF（Beacon Forwarder）と呼ばれるRUMのエージェントデータがIISに送られてくるため、IISのログにPOSTで沢山その情報が埋め尽くされてしまいます（下記画像で、黄色くハイライトした部分）

他のPOST情報もフィルタされてしまう欠点がありますが、まずはMETHODでフィルタできるか試してみます。Log分析画面のAttributeで「Other」の所にカスタマイズして登録したAttributeが表示されるので、そこから「iis.cs_method」を見つけ、GETだけ表示させてみます。いい感じでフィルタされました。

さらにLog分析画面で、今回追加したすべてのAttributeが画面右側部分にも表示させたい場合、「Format table」をクリックして、表示させたいAttributeを追加して下さい。そうすると、Table形式で見たいものが俯瞰できます。これもいい感じになりました。

やっぱり、Dashboardでまとめてみたい

でも、最後はダッシュボードでまとめてデータは見たいですよね？例えば「IISのWebリクエスト処理時間の遅い順番にならべ、それらをパス単位で分割したい」という、あるあるニーズに応えるにはどうすればよいでしょうか？そんな時には「Log metrics/Metrics extraction」を使いましょう。ログから抽出したAttributeをメトリクス化し、ダッシュボードに貼り付けられる（Data Explorerを経由して）機能です。「Settings」>「Log Monitoring」>「Metrics extraction」から、独自メトリクスを定義します。

• Metic key
  • 一意なメトリクスキーを定義します。「log.」で始まるログメトリクスを表すキーを必ず最初に付与します。今回は分かりやすく「log.iis.time_taken」というキーを付けています。
• Matcher
  • どういうログに対して、log metrics extractionを適用するか宣言。今回は「IIS」のログを対象にします。
• Metric measurement
  • Attributeのどれをメトリクス化するか定義。今回はIISのリクエスト処理時間を表す「iis.time_taken」をグラフ化したいので、それを指定します
• Dimensions
  • 「iis.time_taken」を何でSplitするか定義。今回はリクエストのPATH単位で処理時間の速い、遅いを見たいので、「iis.cs_uri.stem」をディメンションとして指定します。
    以上で、メトリクス化の設定は終了です。

早速、Data explorer で表示して、それをDashboardに貼り付けてみましょう。Top list 表記を選択すると、キレイにリクエストパス毎に処理の遅い順番が表示されました♪

で、これをダッシュボードに貼り付けて完成！

IISログ分析まとめ

いかがだったでしょうか？ログは取っているけど、いまいち活用できていないケースもあるように思えます。でも、一度こういうやりかたを覚えると、他にも活用できるケースは沢山でてくると思います。さきほどのログデータのメトリクス化も、閾値設定をすればAlert通知ができますし、プロブレムとしても通知できます。Davis AIはこれらのイベントの因果関係を自動的に紐付け分析してくれるので、いろいろなところからイベント情報をDynatraceに通知してあげるとよいと思います。
なお、今回の機能は、Managed、SaaSの両方で活用できますよ。

まだ、Dynatraceを触ったことがない方、このブログを見てやってみたいと思われた方は、下記フリートライアルにてお試し下さい。↓↓↓

Dynatraceフリートライアル → https://www.dynatrace.com/ja/trial/