Azureの小ネタ (改)

~Azureネタを中心に、色々とその他の技術的なことなどを~

JavaからAzure Application Insightsを使う(2)

昨日に引き続きApplication Insightsネタです。

前回に引き続きJavaからApplication Insightsを使う際の備忘録です。今回はWebアプリケーションのリクエストをApplication Insightsに記録したいと思います。またWebアプリといっても様々なものがあるのですが、ここではSpring Boot を対象です(それが一番楽だから)

プロジェクトの用意

Spring Initializr を使ってひな形を作成しましょう。最近は、Visual Studio Codeから仕える拡張もあるので、そちらから利用してみるのも良いかもしれません。

f:id:StateMachine:20200731102118p:plain
Generate spring boot application

このとき、後で必要な依存を含められるのですが、それは手動でやってきます。

依存

Spring Boot向けに、 Azure Application Insights Spring Boot Starter が用意されているのでこれを利用します。適宜Bootアプリ向けの設定を行ってくれます。

Maven Repository: com.microsoft.azure » applicationinsights-spring-boot-starter » 2.6.1

<dependency>
    <groupId>com.microsoft.azure</groupId>
    <artifactId>applicationinsights-spring-boot-starter</artifactId>
    <version>2.6.1</version>
</dependency>

実はこの依存元になる applicationinsights-web ライブラリがあるのですが、このstarter は Spring Boot ラッパーだと思っていただければ良いと思います。ApplicationInsights.xml での設定ではなく、application.yaml (properties) などで設定可能になっています。

したがって、Bootアプリでなければ上記への依存とApplication.xmlの設定で同じようにテレメトリが取得出来ると思います。(Bootアプリでもstarter使わずwebを使えます)

設定

src/main/resources/application.yamlに以下の設定します。インストルメンテーションキー以外に spring.application.nameを設定しておくと、テレメトリのCloud Role Name プロパティにアプリ名が記録されます。

spring:
    application:
        name: MyWebApplication
azure:
    application-insights:
        instrumentation-key: インストルメンテーションキー

ソース

適当にリクエストを受け付けられるように修正します。 取りあえず文字列を返すだけの簡単なAPIです。ログへの記録とかは必要なく、リクエストがApplication Insightsにリクエストテレメトリとして記録されます。

package com.example.web.sample;

import org.springframework.boot.SpringApplication;
import org.springframework.boot.autoconfigure.SpringBootApplication;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@SpringBootApplication
@RestController
public class Application {
    public static void main(String[] args) {
        SpringApplication.run(Application.class, args);
    }

    @RequestMapping("/")
    public String home() {
        return "Hello Application Insights World";
    }
}
mvn clean package spring-boot:run

で実行して、localhost:8080/に何度かアクセスしてみてください。記録されるまで数分の遅延があるので注意してください(前回言ってなかった気がする)

Azure ポータルでの確認

localhostからのリクエストが記録されているとおもいます。展開すると詳しい記録を見ることが出来ます。

f:id:StateMachine:20200731102217p:plain
request

このように、とくにプログラムに手を入れることなくいくつかのテレメトリを自動で収集できるようになります。

ログ出力

上記の設定のみですと、前回のようなログがApplication Insightsに記録されません。同じ設定(依存とlogback.xml)をすればちゃんとログが飛びます。 ただし、 logbac.xml の中にインストルメンテーションキーの設定はしなくてもよいです。別のを設定するとどういう挙動をするのかは知らないです

内部実装

SDKの実装的な話をすると、以下のあたりでリクエスト、レスポンスのフィルター処理をしています。内部実装が気になる方は参考にしてください。

リクエストテレメトリにカスタムプロパティを追加する

テレメトリにはカスタムプロパティを追加できるのですが、そのコンテキストでの該当テレメトリインスタンスを取得する方法を紹介します。例えば、独自ヘッダやなどを一緒に記録したい場合に役立つかもしれません。

ApplicationInsights SDK が用意するThreadContextクラスにリクエストテレメトリを取得する静的メソッドがあるので、順次取り出していきます。getPropertyでカスタムプロパティが取り出せますのでputで設定するだけす。ここでは、リクエストを受けるメソッドで直接やっていますが、定型処理ならばSpringの機能であるインターセプターの仕組みで常に記録するのがいいかもしれません。

@RestController
public class HomeController {

    private final Logger log = LoggerFactory.getLogger(HomeController.class);

    @RequestMapping("/")
    public String home() {
        log.info("info message");

        var telemetory = ThreadContext.getRequestTelemetryContext().getHttpRequestTelemetry();
        telemetory.getProperties().put("Some Cusome Property", (new Date().toString()));

        return "Hello Application Insights World";
    }
}

f:id:StateMachine:20200731102313p:plain
custom property

まとめと参考

前回も説明したとおり2.6.x系 と 3.0 previewがあるのですが、ぶっちゃけ3.0 から完全なエージェント方式っぽくなるようで、いずれ2.6.x系は廃れていくのかもしれません(不正確)とはいえ、自分でテレメトリ弄りたい場合もあるだろうし。

つづく...

JavaからAzure Application Insightsを使う(1)

JavaからApplication Insightsを使うための備忘録です。執筆時点で、2.6.x 系と 3.0 Preview がありますが、順に記録しておきたいと思います。

いくつかのユースケースはありますが、今回は単にプレーンなログをApplication Insightsに転送したい場合についてで、メトリクスとかは無視し、最小構成かつ2.6.x 系を使用して話をすすめます。

ライブラリ

2.6.x系では、Application Insights用へログを吐くためのライブラリにはいくつかあって、これはJavaのログ周りの話に関連しており、結果以下の3つ (logback/log4j2/log4j) があります。

好みに応じて使い分けてもらえれば良いと思います。実際に依存をつければあとは、slf4jから扱えると思います。

ここらの関係性は、ここをご一読ください。SLF4J、Logback、Log4Jの関係を挙動とともに整理する - Qiita

Application Insightsの用意

PortalからApplication Insightsを作成し、インストルメンテーションキーを用意します。

プロジェクトの準備

適当にプロジェクトを作って、 applicationinsights-logging-logback に依存を通しましょう。お好きなビルドツールを使えば良いと思いますが、ここでは mavenで進めます。

以下をpom.xmlに追加します。

<dependency>
    <groupId>com.microsoft.azure</groupId>
    <artifactId>applicationinsights-logging-logback</artifactId>
    <version>2.6.1</version>
</dependency>

これで必要なライブラリは以上です。 applicationinsights-core や他のlogbackslf4jへの依存は含まれています。

logbackの設定

logbackの設定は、src/main/resource/logback.xml に行います。以下はまるっとConsoleAppenderとApplication Insights Appenderのサンプルです。

インストルメンテーションキーは <instrumentationKey> に設定します。

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE logback>
<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="aiAppender" class="com.microsoft.applicationinsights.logback.ApplicationInsightsAppender">
        <instrumentationKey>インストルメンテーションキー</instrumentationKey>
    </appender>
    <root level="info">
        <appender-ref ref="aiAppender"/>
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

ログ出力

ログの出力はフレームワークのロギングの作法に従って出力すれば、Application Insights に飛ばされます。HTTP/HTTPSを通してAzure上に転送されるので、Proxy環境化の場合は注意してください。

以下は、debug/info/war/errorとメッセージを繰り返し出力するだけのサンプルです。errorのみ例外をキャッチして引数に指定しています。例外を引数に与えない場合はトレーステレメトリに、例外がある場合は例外テレメトリに飛ばされます(これはSDKがそういう実装になっているというだけの話)。

Application Insightのデータモデルについては以下を参考にしてください。 Azure Application Insights Telemetry のデータ モデル - Azure Monitor | Microsoft Docs

package com.example;

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Paths;

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class App {

    private static Logger log = LoggerFactory.getLogger(App.class);

    public static void main(String[] args) throws InterruptedException {

        System.out.println("Hello Application Insights World!");

        for (int i = 0; i < 10; i++) {

            log.debug("Debug");
            log.info("Info");
            log.warn("Warn");

            try {
                var content = Files.readString(Paths.get("c:\\notexists"));
                System.out.println(content);
            } catch (IOException e) {
                log.error("error", e);
                log.error("non exception error");
            }
            Thread.sleep(500);
        }
    }
}

実行結果です。debugが出てないのは、info以上に設定しているためです。

15:11:21.526 [main] INFO  com.example.App - Info
15:11:21.527 [main] WARN  com.example.App - Warn
15:11:21.529 [main] ERROR com.example.App - error
java.nio.file.NoSuchFileException: c:\notexists
        at java.base/sun.nio.fs.WindowsException.translateToIOException(WindowsException.java:85)
        at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:103)
        at java.base/sun.nio.fs.WindowsException.rethrowAsIOException(WindowsException.java:108)
        at java.base/sun.nio.fs.WindowsFileSystemProvider.newByteChannel(WindowsFileSystemProvider.java:235)
        at java.base/java.nio.file.Files.newByteChannel(Files.java:370)
        at java.base/java.nio.file.Files.newByteChannel(Files.java:421)
        at java.base/java.nio.file.Files.readAllBytes(Files.java:3205)
        at java.base/java.nio.file.Files.readString(Files.java:3283)
        at java.base/java.nio.file.Files.readString(Files.java:3242)
        at com.example.App.main(App.java:24)

Application Insights SDK のTelemetryクラスを使って飛ばす方法もありますが、単なるログについては既存のフレームワークの作法に従った方が問題が少ないと思います。

Azure ポータルでの確認

Application Insightsから検索メニューを開くと、ざっくり直近のログが確認できます。もっと高度なことがしたい場合はログから色々なクエリが実行できます。

f:id:StateMachine:20200730153052p:plain

次回はWebアプリのあたりを(つづく)。

ASP.NET Core の Request body を記録する

例のごとく備忘録メモ。

よくあるリクエストボディを記録したいというお話で、ググると同様の話題は沢山でてきますが、これといってフレームワークで決まったお作法があるわけではない感じです。

よくある記録先

よくある記録先としては2つ。

  • ILogger
  • Application Insights

Application Insightsへの記録は、ILogger経由でも問題ありませんが、Request Telemetryに記録したい場合などです。

同様の話題、Application InsightへIssueの投稿は繰り返されるらしく、最新のOpenしているIssueはOptionally log POST request body · Issue #1880 · microsoft/ApplicationInsights-dotnet · GitHub これみたいです。

ただ内容通り、 今年はサポートする予定はなく、ILoggerで書いてねと言われています。

Unfortunately, this is not going to be supported by the ApplicationInsights SDK in this year.

将来的にフレームワーク側でサポートを期待したいところです。

ASP.NET Coreとしての問題

リクエストボディの再読み出しはあまりデフォルトではできなくて、あまりお勧めもされていない(と思われます)

Close済みのIssueでMSの人が言及しています。 Telemetry Initializer to add request body content from .net core MVC app to request telemetry properties not working · Issue #686 · microsoft/ApplicationInsights-aspnetcore · GitHub

It is not possible to read the Post/Put body stream twice - so attempting to read it in TelemetryInitializer is not recommended and will fail.

そしてそのサンプルは以下の通りで、Controllerで記録すれば的な感じでコードサンプルが提示されています。

       [HttpPost]
        public IActionResult Create([FromBody] TodoItem item)
        {
            if (item == null)
            {
                return BadRequest();
            }

            RequestTelemetry requestTelemetry = HttpContext.Features.Get<RequestTelemetry>();
            requestTelemetry.Properties.Add("cijokey", item.Name);

            _context.TodoItems.Add(item);
            _context.SaveChanges();

            return CreatedAtRoute("GetTodo", new { id = item.Id }, item);
        }

とはいえ、毎回Controllerの入り口にコレを書くのも面倒ですので、ミドルウェアで処理するのが簡単そうです。

ミドルウェアでの処理

ILoggerを使う場合、InvokeAsyncからILoggerインスタンスが取れますから、適宜記録すればしかるべきところに記録されるでしょう。(コンストラクタインジェクションではないので注意)

        public async Task InvokeAsync(HttpContext context, ILogger<RequestMiddleware> logger)
        {
           ...
        }

今回は、ReqestTelemetryに記録したいのでInvokeAsyncの中に以下のように書きます。

        var requestTelemetry = context.Features.Get<RequestTelemetry>();
        if (requestTelemetry != null)
        {
            var requestBodyString = Encoding.UTF8.GetString(body);
            requestTelemetry.Properties.Add("RequestBody", requestBodyString);
       }

context.Features.Get から RequestTelemetryが取れるようです。これでわざわざITelemetryInitializer を使う必要も無く記録できそうです。

以下がApplication Insgihtに記録した例です。RequestBodyが記録されているの確認できます。

f:id:StateMachine:20200623225850p:plain

こうすることで、RequestTelemetryに記録を統合できる感じになりました。

ILogger経由で trace telemetoryに記録してもいいんですが、ケースバイケースということで。

以上