Durable Functionsの診断について

Durable Functionsに関する問題を診断するには、いくつかのオプションがあります。 これらのオプションの一部は通常の関数で同じであり、一部はDurable Functionsに固有です。 この記事では、オーケストレーションのトラブルシューティングに使用できる診断ツールと手法について説明します。

Application Insights

Application Insights は、Azure Functionsで診断と監視を行うための推奨される方法です。 同じことがDurable Functionsにも当てはまります。 Azure Functions Durable Extension は追跡イベントを出力し、オーケストレーションのエンドツーエンドの実行をトレースできます。 これらの追跡イベントの検索とクエリは、Azure ポータルの Application Insights Analytics ツールを使用して実行できます。

トラッキングデータ

すべてのオーケストレーション インスタンスは、ライフサイクルを進むにつれて追跡イベントを生成します。 各ライフサイクル イベントには、複数のフィールドを含む customDimensions ペイロードが含まれています。 フィールド名は、いずれも で始まります。

プラットフォームのログ記録構成を使用して、Application Insights に出力される追跡データの詳細度を構成できます。

{
    "logging": {
        "logLevel": {
            "Host.Triggers.DurableTask": "Information",
        },
    }
}

{
    "logger": {
        "categoryFilter": {
            "categoryLevels": {
                "Host.Triggers.DurableTask": "Information"
            }
        }
    }
}

既定では、すべての "再生以外" の追跡イベントが出力されます。 をまたはに設定することで、データの量を減らすことができます。つまり、追跡イベントは例外的な状況でのみ生成されます。 オーケストレーションの詳細な再生イベントの出力を有効にするには、host.json 構成ファイル内で を に設定します。

既定では、オーケストレーター、アクティビティ、エンティティ関数の入力と出力はログに記録されません。 入力と出力をログに記録すると Application Insights のコストが増加する可能性があるため、この方法をお勧めします。 関数の入力および出力ペイロードには、機密情報も含まれる場合があります。 代わりに、関数の入力と出力のバイト数がログに記録されます。 Durable Functions拡張機能で完全な入力ペイロードと出力ペイロードをログに記録する場合は、traceInputsAndOutputs プロパティを true 構成ファイルの に設定します。

シングル インスタンス クエリ

次のクエリでは、Hello シーケンス関数オーケストレーションの単一インスタンスに関する履歴追跡データが表示されます。 これは Kusto クエリ言語を使用して記述されています。 再生実行を除外して、論理実行パスだけを表示するためです。 次のクエリに示すように、 と で並べ替えることで、イベントを並べ替えることができます。

let targetInstanceId = "ddd1aaa685034059b545eb004b15d4eb";
let start = datetime(2018-03-25T09:20:00);
traces
| where timestamp > start and timestamp < start + 30m
| where customDimensions.Category == "Host.Triggers.DurableTask"
| extend functionName = customDimensions["prop__functionName"]
| extend instanceId = customDimensions["prop__instanceId"]
| extend state = customDimensions["prop__state"]
| extend isReplay = tobool(tolower(customDimensions["prop__isReplay"]))
| extend sequenceNumber = tolong(customDimensions["prop__sequenceNumber"])
| where isReplay != true
| where instanceId == targetInstanceId
| sort by timestamp asc, sequenceNumber asc
| project timestamp, functionName, state, instanceId, sequenceNumber, appName = cloud_RoleName

結果では、実行時刻の昇順に並べ替えられたアクティビティ関数など、オーケストレーションの実行パスを示す追跡イベントが一覧表示されます。

単一インスタンスの順序付けされたクエリ結果と追跡イベントを示す Application Insights のスクリーンショット。

インスタンス概要クエリ

次のクエリでは、指定した時間範囲内で実行されたすべてのオーケストレーション インスタンスの状態が表示されます。

let start = datetime(2017-09-30T04:30:00);
traces
| where timestamp > start and timestamp < start + 1h
| where customDimensions.Category == "Host.Triggers.DurableTask"
| extend functionName = tostring(customDimensions["prop__functionName"])
| extend instanceId = tostring(customDimensions["prop__instanceId"])
| extend state = tostring(customDimensions["prop__state"])
| extend isReplay = tobool(tolower(customDimensions["prop__isReplay"]))
| extend output = tostring(customDimensions["prop__output"])
| where isReplay != true
| summarize arg_max(timestamp, *) by instanceId
| project timestamp, instanceId, functionName, state, output, appName = cloud_RoleName
| order by timestamp asc

結果では、インスタンス ID とその現在の実行状態が一覧表示されます。

インスタンス ID と状態を含む単一インスタンスの概要クエリ結果を示す Application Insights のスクリーンショット。

Durable Task Framework のログ記録

Durable 拡張機能のログは、オーケストレーション ロジックの動作を理解するのに役立ちます。 ただし、これらのログには、フレームワークレベルのパフォーマンスと信頼性の問題をデバッグするのに十分な情報が必ず含まれているわけではありません。 Durable 拡張機能の v 2.3.0 以降では、基になる Durable Task Framework (DTFx) によって出力されたログもコレクションに使用できます。

DTFx によって出力されるログを確認するときは、DTFx エンジンにコア ディスパッチ エンジン () と サポートされている多くのストレージ プロバイダーの 1 つという 2 つのコンポーネントがあることを理解しておくことが重要です。

これらのログを有効にするには、関数アプリの ファイルの セクションを更新します。 次の例は、 と の両方からの警告とエラーのログを有効にする方法を示しています。

{
  "version": "2.0",
  "logging": {
    "logLevel": {
      "DurableTask.AzureStorage": "Warning",
      "DurableTask.Core": "Warning"
    }
  }
}

Application Insights が有効になっている場合、これらのログは コレクションに自動的に追加されます。 Kusto クエリを使用して他の ログを検索するのと同じ方法で検索できます。

次の Kusto クエリは DTFx ログのクエリを実行する方法を示しています。 クエリの最も重要な部分は です。これは、結果をフィルター処理し、 と の各カテゴリのログに分類するからです。

traces
| where customDimensions.Category startswith "DurableTask"
| project
    timestamp,
    severityLevel,
    Category = customDimensions.Category,
    EventId = customDimensions.EventId,
    message,
    customDimensions
| order by timestamp asc 

結果は、Durable Task Framework ログ プロバイダーによって書き込まれたログのセットになります。

Durable Task Framework ログを含む DTFx クエリの結果を示す Application Insights のスクリーンショット。

使用できるログ イベントの詳細については、GitHub の Durable Task Framework 構造化ログに関するドキュメントを参照してください。

アプリのログ記録

オーケストレーター関数から直接ログを書き込む場合は、オーケストレーターの再生動作に注意してください。 たとえば次のオーケストレーター関数について考えてみます。

[FunctionName("FunctionChain")]
public static async Task Run(
    [OrchestrationTrigger] IDurableOrchestrationContext context,
    ILogger log)
{
    log.LogInformation("Calling F1.");
    await context.CallActivityAsync("F1");
    log.LogInformation("Calling F2.");
    await context.CallActivityAsync("F2");
    log.LogInformation("Calling F3");
    await context.CallActivityAsync("F3");
    log.LogInformation("Done!");
}

[Function("FunctionChain")]
public static async Task Run(
    [OrchestrationTrigger] TaskOrchestrationContext context,
    FunctionContext executionContext)
{
    ILogger log = executionContext.GetLogger("FunctionChain");
    log.LogInformation("Calling F1.");
    await context.CallActivityAsync("F1");
    log.LogInformation("Calling F2.");
    await context.CallActivityAsync("F2");
    log.LogInformation("Calling F3");
    await context.CallActivityAsync("F3");
    log.LogInformation("Done!");
}

const df = require("durable-functions");

module.exports = df.orchestrator(function*(context){
    context.log("Calling F1.");
    yield context.df.callActivity("F1");
    context.log("Calling F2.");
    yield context.df.callActivity("F2");
    context.log("Calling F3.");
    yield context.df.callActivity("F3");
    context.log("Done!");
});

import logging
import azure.functions as func
import azure.durable_functions as df

def orchestrator_function(context: df.DurableOrchestrationContext):
    logging.info("Calling F1.")
    yield context.call_activity("F1")
    logging.info("Calling F2.")
    yield context.call_activity("F2")
    logging.info("Calling F3.")
    yield context.call_activity("F3")
    return None

main = df.Orchestrator.create(orchestrator_function)

@FunctionName("FunctionChain")
public void functionChain(
        @DurableOrchestrationTrigger(name = "ctx") TaskOrchestrationContext ctx,
        ExecutionContext functionContext) {
    Logger log = functionContext.getLogger();
    log.info("Calling F1.");
    ctx.callActivity("F1").await();
    log.info("Calling F2.");
    ctx.callActivity("F2").await();
    log.info("Calling F3.");
    ctx.callActivity("F3").await();
    log.info("Done!");
}

結果のログ データは、次の出力例のようになります。

Calling F1.
Calling F1.
Calling F2.
Calling F1.
Calling F2.
Calling F3.
Calling F1.
Calling F2.
Calling F3.
Done!

再生以外の実行だけをログに記録する場合は、"is replaying" フラグが である場合にのみログを記録する条件式を記述できます。 上記の例を考えてみましょう。ただし、今回はリプレイチェック付きで。

[FunctionName("FunctionChain")]
public static async Task Run(
    [OrchestrationTrigger] IDurableOrchestrationContext context,
    ILogger log)
{
    if (!context.IsReplaying) log.LogInformation("Calling F1.");
    await context.CallActivityAsync("F1");
    if (!context.IsReplaying) log.LogInformation("Calling F2.");
    await context.CallActivityAsync("F2");
    if (!context.IsReplaying) log.LogInformation("Calling F3");
    await context.CallActivityAsync("F3");
    log.LogInformation("Done!");
}

[FunctionName("FunctionChain")]
public static async Task Run(
    [OrchestrationTrigger] IDurableOrchestrationContext context,
    ILogger log)
{
    log = context.CreateReplaySafeLogger(log);
    log.LogInformation("Calling F1.");
    await context.CallActivityAsync("F1");
    log.LogInformation("Calling F2.");
    await context.CallActivityAsync("F2");
    log.LogInformation("Calling F3");
    await context.CallActivityAsync("F3");
    log.LogInformation("Done!");
}

[Function("FunctionChain")]
public static async Task Run([OrchestrationTrigger] TaskOrchestrationContext context)
{
    ILogger log = context.CreateReplaySafeLogger("FunctionChain");
    log.LogInformation("Calling F1.");
    await context.CallActivityAsync("F1");
    log.LogInformation("Calling F2.");
    await context.CallActivityAsync("F2");
    log.LogInformation("Calling F3");
    await context.CallActivityAsync("F3");
    log.LogInformation("Done!");
}

const df = require("durable-functions");

module.exports = df.orchestrator(function*(context){
    if (!context.df.isReplaying) context.log("Calling F1.");
    yield context.df.callActivity("F1");
    if (!context.df.isReplaying) context.log("Calling F2.");
    yield context.df.callActivity("F2");
    if (!context.df.isReplaying) context.log("Calling F3.");
    yield context.df.callActivity("F3");
    context.log("Done!");
});

import logging
import azure.functions as func
import azure.durable_functions as df

def orchestrator_function(context: df.DurableOrchestrationContext):
    if not context.is_replaying:
        logging.info("Calling F1.")
    yield context.call_activity("F1")
    if not context.is_replaying:
        logging.info("Calling F2.")
    yield context.call_activity("F2")
    if not context.is_replaying:
        logging.info("Calling F3.")
    yield context.call_activity("F3")
    logging.info("Done!")
    return None

main = df.Orchestrator.create(orchestrator_function)

@FunctionName("FunctionChain")
public void functionChain(
        @DurableOrchestrationTrigger(name = "ctx") TaskOrchestrationContext ctx,
        ExecutionContext functionContext) {
    Logger log = functionContext.getLogger();
    if (!ctx.getIsReplaying()) log.info("Calling F1.");
    ctx.callActivity("F1").await();
    if (!ctx.getIsReplaying()) log.info("Calling F2.");
    ctx.callActivity("F2").await();
    if (!ctx.getIsReplaying()) log.info("Calling F3.");
    ctx.callActivity("F3").await();
    log.info("Done!");
}

これらの変更により、ログ出力は次のようになります。

Calling F1.
Calling F2.
Calling F3.
Done!

カスタムの状態

カスタムオーケストレーションの状態を使用すると、オーケストレーター関数のカスタム状態値を設定できます。 外部クライアントは、 HTTP 状態クエリ API または言語固有の API 呼び出しを使用してカスタム状態を表示できます。 カスタム オーケストレーションの状態により、オーケストレーター関数の監視が充実します。 たとえば、オーケストレーター関数コードで "set custom status" API を呼び出して、実行時間の長い操作の進行状況を更新できます。 Web ページや外部システムなどのクライアントは、HTTP 状態クエリ API に定期的にクエリを実行して進行状況情報を取得できます。 次のコードは、オーケストレーター関数でカスタム状態値を設定する方法を示しています。

[FunctionName("SetStatusTest")]
public static async Task SetStatusTest([OrchestrationTrigger] IDurableOrchestrationContext context)
{
    // ...do work...

    // update the status of the orchestration with some arbitrary data
    var customStatus = new { completionPercentage = 90.0, status = "Updating database records" };
    context.SetCustomStatus(customStatus);

    // ...do more work...
}

[Function("SetStatusTest")]
public static async Task SetStatusTest([OrchestrationTrigger] TaskOrchestrationContext context)
{
    // ...do work...

    // update the status of the orchestration with some arbitrary data
    var customStatus = new { completionPercentage = 90.0, status = "Updating database records" };
    context.SetCustomStatus(customStatus);

    // ...do more work...
}

const df = require("durable-functions");

module.exports = df.orchestrator(function*(context) {
    // ...do work...

    // update the status of the orchestration with some arbitrary data
    const customStatus = { completionPercentage: 90.0, status: "Updating database records", };
    context.df.setCustomStatus(customStatus);

    // ...do more work...
});

import logging
import azure.functions as func
import azure.durable_functions as df

def orchestrator_function(context: df.DurableOrchestrationContext):
    # ...do work...

    # update the status of the orchestration with some arbitrary data
    custom_status = {'completionPercentage': 90.0, 'status': 'Updating database records'}
    context.set_custom_status(custom_status)
    # ...do more work...

    return None

main = df.Orchestrator.create(orchestrator_function)

@FunctionName("SetStatusTest")
public void setStatusTest(
        @DurableOrchestrationTrigger(name = "ctx") TaskOrchestrationContext ctx) {
    // ...do work...

    // update the status of the orchestration with some arbitrary data
    ctx.setCustomStatus(new Object() {
        public final double completionPercentage = 90.0;
        public final String status = "Updating database records";
    });

    // ...do more work...
}

オーケストレーションの実行中に、外部クライアントはこのカスタム状態を取り込むことができます:

GET /runtime/webhooks/durabletask/instances/instance123?code=XYZ

クライアントは次の応答を受け取ります。

{
  "runtimeStatus": "Running",
  "input": null,
  "customStatus": { "completionPercentage": 90.0, "status": "Updating database records" },
  "output": null,
  "createdTime": "2017-10-06T18:30:24Z",
  "lastUpdatedTime": "2017-10-06T19:40:30Z"
}

分散トレース

分散トレースは、要求を追跡し、さまざまなサービスが相互に対話する方法を示します。 Durable Functionsでは、オーケストレーション、エンティティ、およびアクティビティが相互に関連付けられます。 分散トレースは、オーケストレーション全体に対する各オーケストレーション ステップの実行時間を示し、問題または例外が発生する場所を識別します。 この機能は、すべての言語とストレージ プロバイダーの Application Insights でサポートされています。

分散トレースの設定

分散トレースを構成するには、 を更新し、Application Insights リソースを設定します。

host.json

{
   "extensions": {
     "durableTask": {
       "tracing": {
         "distributedTracingEnabled": true,
         "version": "V2"
       }
     }
   }
 }

Application Insights

Application Insights リソースを使用して関数アプリを構成します。

トレースの検査

分散トレースを設定したら、オーケストレーション フローを視覚化できます。 Application Insights リソースで、[ トランザクション検索] に移動します。 結果の中で、 と、Durable 特有の接頭辞 (たとえば、、など)で始まるイベントを探します。 これらのイベントのいずれかを選択すると、エンドツーエンドの分散トレースを示すガント チャートが開きます。

オーケストレーションとアクティビティのタイムラインを含む Application Insights 分散トレースを示すガント チャートのスクリーンショット。

デバッグ

Azure Functionsは関数コードのデバッグを直接サポートし、同じサポートがAzureで実行されているかローカルで実行されているかに関係なく、Durable Functionsに転送されます。 ただし、デバッグ時に知っておくべきいくつかの動作があります。

• 再生： オーケストレーター関数は、新しい入力を受信すると定期的に 再生 されます。 オーケストレーター関数を 1 回 論理 実行すると、同じブレークポイントに複数回ヒットする可能性があります(特に、関数コードの早い段階で設定されている場合)。

• 待機: オーケストレーター関数内で に到達した場合は常に、Durable Task Framework ディスパッチャーに制御が戻されます。 特定の が初めて発生した場合、関連付けられているタスクは再開 されません 。 タスクが再開しないため、await をステップオーバー (Visual Studio の F10) することはできません。 ステップ オーバーが機能するのは、タスクが再生されているときだけです。

• メッセージングタイムアウト: Durable Functions は、内部的にキューメッセージを使用して、オーケストレーター、アクティビティ、およびエンティティ関数の実行を制御します。 マルチ VM 環境では、拡張デバッグ セッションによって別の VM がメッセージを処理し、その結果、実行が重複する可能性があります。 この動作は通常のキュー トリガー関数にも存在しますが、キューは実装の詳細であるため、このコンテキストを強調することが重要です。

• Stopping と starting: Durable Functions 内のメッセージはデバッグ セッション間で保持されます。 永続関数の実行中にデバッグを停止し、ローカル ホスト プロセスを終了すると、その関数は将来のデバッグ セッションで自動的に再実行される可能性があります。 予期しない再実行を回避するには、 新しいタスク ハブ を使用するか、デバッグ セッション間でタスク ハブの内容をクリアします。

Storage

既定では、Durable Functionsは状態をAzure Storageに格納します。 Microsoft Azure Storage Explorer。

Durable Functions モニター

Durable Functions Monitor は、オーケストレーションインスタンスとエンティティ インスタンスを監視、管理、デバッグするためのグラフィカル ツールです。 Visual Studio Code拡張機能またはスタンドアロン アプリとして使用できます。 セットアップ手順と機能の一覧については、Durable Functions Monitor Wikiを参照してください。

Azure ポータルの診断

Azure ポータルには、関数アプリ用の組み込みの診断ツールが用意されています。

問題の診断と解決

Azure Function App Diagnostics は、アプリケーションの潜在的な問題の監視と診断に役立つリソースです。 診断に基づく問題の解決に役立つ提案も提供されます。 詳細については、「Azure Function App Diagnostics」を参照してください。

オーケストレーション トレース

Azure ポータルには、各オーケストレーション インスタンスの状態を理解し、エンドツーエンドの実行をトレースするのに役立つオーケストレーション トレースの詳細が用意されています。 Azure Functions アプリ内の関数の一覧を表示すると、トレースへのリンクを含む Monitor 列が表示されます。 この情報にアクセスするには、アプリで Application Insights を有効にする必要があります。

Roslyn アナライザー

Durable Functions Roslyn Analyzer は、C# 開発者が Durable Functions 固有のコード制約に従うよう誘導するリアルタイムコードアナライザーです。 Visual StudioおよびVisual Studio Codeで有効にする方法については、「Durable Functions Roslyn Analyzerを参照してください。

トラブルシューティング

オーケストレーションの停止、開始の失敗、実行速度の低下などの一般的な問題のトラブルシューティングを行うには、Durable Functionsトラブルシューティング ガイドを参照してください。

次のステップ