Azureの小ネタ (改)

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

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に記録してもいいんですが、ケースバイケースということで。

以上

Azure Devops の bash で envしたときの値

タイトル通りの備忘録、vmImage は、 ubuntu-latest です。

##[section]Starting: Bash
==============================================================================
Task         : Bash
Description  : Run a Bash script on macOS, Linux, or Windows
Version      : 3.151.3
Author       : Microsoft Corporation
Help         : https://docs.microsoft.com/azure/devops/pipelines/tasks/utility/bash
==============================================================================
Generating script.
========================== Starting Command Output ===========================
[command]/bin/bash --noprofile --norc /home/vsts/work/_temp/e71081de-9d69-489d-b250-e78785b008ac.sh
BUILD_SOURCEBRANCH=refs/heads/master
SYSTEM_TEAMFOUNDATIONCOLLECTIONURI=https://dev.azure.com/hogehoge/
SYSTEM_TASKDEFINITIONSURI=https://dev.azure.com/hogehoge/
SYSTEM_JOBATTEMPT=1
AGENT_VERSION=2.155.1
LEIN_HOME=/usr/local/lib/lein
BUILD_QUEUEDBY=Microsoft.VisualStudio.Services.TFS
SYSTEM_COLLECTIONURI=https://dev.azure.com/hogehoge/
SYSTEM_HOSTTYPE=build
GOROOT_1_11_X64=/usr/local/go1.11
SYSTEM_JOBPARALLELISMTAG=Private
BUILD_REPOSITORY_GIT_SUBMODULECHECKOUT=False
ANDROID_HOME=/usr/local/lib/android/sdk
GOROOT_1_9_X64=/usr/local/go1.9
BUILD_STAGINGDIRECTORY=/home/vsts/work/1/a
RUNNER_TOOLSDIRECTORY=/opt/hostedtoolcache
AGENT_MACHINENAME=fv-az103
KEY_SECUREFILEPATH=/home/vsts/work/_temp/0DBA5D69E52A419E6EEC62AD51B1CF407F55ECC2.asc
SYSTEM_WORKFOLDER=/home/vsts/work
COMMON_TESTRESULTSDIRECTORY=/home/vsts/work/1/TestResults
GRADLE_HOME=/usr/share/gradle
AGENT_JOBNAME=Test_Build
ANDROID_SDK_ROOT=/usr/local/lib/android/sdk
MSDEPLOY_HTTP_USER_AGENT=VSTS_2978d119-f2d9-4265-b996-67b5d046d383_build_3_0
JAVA_HOME_8_X64=/usr/lib/jvm/zulu-8-azure-amd64
AGENT_OSARCHITECTURE=X64
BUILD_SOURCEVERSIONAUTHOR=foo bar
BUILD_REQUESTEDFOREMAIL=hoge@example.com
GENT_ACCEPTTEEEULA=True
SYSTEM_STAGEATTEMPT=1
ANT_HOME=/usr/share/ant
GIT_TERMINAL_PROMPT=0
SYSTEM_DEFINITIONNAME=test-project-build
SYSTEM_CULTURE=en-US
JAVA_HOME_11_X64=/usr/lib/jvm/zulu-11-azure-amd64
AGENT_TEMPDIRECTORY=/home/vsts/work/_temp
BUILD_REPOSITORY_CLEAN=False
BUILD_REPOSITORY_PROVIDER=TfsGit
BUILD_SOURCEBRANCHNAME=master
USER=vsts
SYSTEM_JOBIDENTIFIER=Build.Test_Build.__default
SYSTEM_TEAMFOUNDATIONSERVERURI=https://dev.azure.com/hogehoge/
TF_BUILD=True
SYSTEM_TASKDISPLAYNAME=Bash
AZURE_HTTP_USER_AGENT=VSTS_2978d119-f2d9-4265-b996-67b5d046d383_build_3_0
BUILD_QUEUEDBYID=00000002-0000-8888-8000-000000000000
SYSTEM_STAGENAME=Build
ImageVersion=157.1
AGENT_DISABLELOGPLUGIN_TESTRESULTLOGPLUGIN=true
AGENT_ROOTDIRECTORY=/home/vsts/work
VSTS_PROCESS_LOOKUP_ID=vsts_cb8bf79f-6a51-484b-96bc-c52beebf5333
SYSTEM_TEAMPROJECTID=e4548d85-1016-40fb-bf68-213e2fcce2e6
AGENT_HOMEDIRECTORY=/home/vsts/agents/2.155.1
SYSTEM_TEAMPROJECT=test-project
AGENT_TOOLSDIRECTORY=/opt/hostedtoolcache
BUILD_SOURCEVERSIONMESSAGE=Update azure-pipelines.yml for Azure Pipelines
BUILD_REPOSITORY_ID=8b48d9e0-132e-40ed-a795-0c28536e6cb5
agent.jobstatus=Succeeded
BUILD_REPOSITORY_LOCALPATH=/home/vsts/work/1/s
SYSTEM_JOBDISPLAYNAME=Test_Build
BUILD_REASON=IndividualCI
SYSTEM=build
AGENT_BUILDDIRECTORY=/home/vsts/work/1
SYSTEM_PIPELINESTARTTIME=2019-08-30 02:08:22+00:00
BUILD_SOURCESDIRECTORY=/home/vsts/work/1/s
AGENT_OS=Linux
DOTNET_SKIP_FIRST_TIME_EXPERIENCE=1
PATH=/usr/share/rust/.cargo/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/snap/bin
SYSTEM_PHASEATTEMPT=1
LEIN_JAR=/usr/local/lib/lein/self-installs/leiningen-2.9.1-standalone.jar
SYSTEM_ISSCHEDULED=False
VSTS_AGENT_PERFLOG=/home/vsts/perflog
PWD=/home/vsts/work/1/s
BUILD_BUILDURI=vstfs:///Build/Build/73
SYSTEM_PULLREQUEST_ISFORK=False
INPUT_ARGUMENTS=
CONDA=/usr/share/miniconda
GOROOT_1_10_X64=/usr/local/go1.10
SYSTEM_DEFINITIONID=3
JAVA_HOME=/usr/lib/jvm/zulu-8-azure-amd64
AGENT_DISABLELOGPLUGIN_TESTFILEPUBLISHERPLUGIN=true
SYSTEM_STAGEID=6884a131-87da-5381-61f3-d7acc3b91d76
VCPKG_INSTALLATION_ROOT=/usr/local/share/vcpkg
JAVA_HOME_7_X64=/usr/lib/jvm/zulu-7-azure-amd64
JAVA_HOME_12_X64=/usr/lib/jvm/zulu-12-azure-amd64
SYSTEM_ENABLEACCESSTOKEN=SecretVariable
LANG=en_US.UTF-8
SYSTEM_TASKINSTANCENAME=Bash
SYSTEM_PHASEDISPLAYNAME=Test_Build
SYSTEM_SERVERTYPE=Hosted
BUILD_REPOSITORY_NAME=test-project
GOROOT_1_12_X64=/usr/local/go1.12
BUILD_REPOSITORY_URI=https://hogehoge@dev.azure.com/hogehoge/test-project/_git/test-project
PIPELINE_WORKSPACE=/home/vsts/work/1
AGENT_WORKFOLDER=/home/vsts/work
BUILD_DEFINITIONNAME=test-project-build
SYSTEM_JOBNAME=__default
BUILD_REQUESTEDFOR=foo bar
SYSTEM_ARTIFACTSDIRECTORY=/home/vsts/work/1/a
SYSTEM_TIMELINEID=06e8a6f5-c63c-4215-9467-2157ead94a3a
SHLVL=1
AGENT_ID=8
M2_HOME=/usr/share/apache-maven-3.6.1
BOOST_ROOT_1_69_0=/usr/local/share/boost/1.69.0
HOME=/home/vsts
GOROOT=/usr/local/go1.12
AGENT_RETAINDEFAULTENCODING=false
JDKVERSIONOPTION=1.8
SYSTEM_JOBPOSITIONINPHASE=1
BUILD_REQUESTEDFORID=8c49f8fe-d3e4-4ef7-8054-a6556f864dc4
BUILD_BINARIESDIRECTORY=/home/vsts/work/1/b
BUILD_ARTIFACTSTAGINGDIRECTORY=/home/vsts/work/1/a
BUILD_BUILDID=73
SYSTEM_TASKINSTANCEID=19971af4-fe77-501e-3b0e-49e78c139014
BUILD_SOURCEVERSION=aead9c9fa1a6f6e7b0978e9a9992566f2eda4a34
CHROME_BIN=/usr/bin/google-chrome
BOOST_ROOT=/usr/local/share/boost/1.69.0
SYSTEM_DEFAULTWORKINGDIRECTORY=/home/vsts/work/1/s
SYSTEM_JOBID=e4da4a28-3e47-5b33-a32e-48e227b26997
SYSTEM_TOTALJOBSINPHASE=1
AGENT_NAME=Hosted Agent
SYSTEM_STAGEDISPLAYNAME=Build
SYSTEM_PLANID=06e8a6f5-c63c-4215-9467-2157ead94a3a
BUILD_DEFINITIONVERSION=2
SYSTEM_PHASEID=5a5c60a4-7e04-5ed9-3b32-2033c226d379
SYSTEM_COLLECTIONID=2978d119-f2d9-4265-b996-67b5d046d383
AGENT_JOBSTATUS=Succeeded
TASK_DISPLAYNAME=Bash
ENDPOINT_URL_SYSTEMVSSCONNECTION=https://dev.azure.com/hogehoge/
XML_SECUREFILEPATH=/home/vsts/work/_temp/settings.xml
BUILD_BUILDNUMBER=20190830.7
SYSTEM_PHASENAME=Test_Build
BUILD_CONTAINERID=2861896
ISGITHUBTAG=False
_=/usr/bin/env