Azure での Durable Functions における診断

  • [アーティクル]

Durable Functions に関する問題の診断には、いくつかの方法があります。 その中には、通常の関数の場合と同じ方法もあれば、Durable Functions に固有の方法もあります。

Application Insights

Azure Functions の診断と監視には、Application Insights を使用する方法が推奨されています。 Durable Functions にもそれが当てはまります。 Application Insights を関数アプリで活用する方法の概要については、「Azure Functions を監視する」を参照してください。

また、Azure Functions Durable 拡張機能では "追跡イベント" が生成されます。このイベントを使って、オーケストレーションの実行をエンドツーエンドでトレースできます。 これらの追跡イベントは、Azure portal で Application Insights 分析ツールを使って検出および照会できます。

データの追跡

追跡イベントは、オーケストレーション インスタンスの各ライフサイクル イベントによって Application Insights の traces コレクションに出力されます。 このイベントに格納されている customDimensions ペイロードには、いくつかのフィールドがあります。 フィールド名は、いずれも prop__ で始まります。

  • hubName: オーケストレーションが実行されているタスク ハブの名前。
  • appName: Function App の名前。 このフィールドは、複数の関数アプリで同じ Application Insights インスタンスを共有しているときなどに使用できます。
  • slotName: 現在の関数アプリが実行されているデプロイ スロット。 このフィールドは、デプロイ スロットを使用してご自分のオーケストレーションのバージョン管理を行うときに便利です。
  • functionName: オーケストレーターまたはアクティビティ関数の名前。
  • functionType: 関数の種類 (オーケストレーターやアクティビティなど)。
  • instanceId: オーケストレーション インスタンスの一意の ID。
  • state: インスタンスのライフサイクルの実行状態。 有効な値は、次のとおりです。
    • Scheduled: 関数は実行をスケジュールされたが、まだ実行を開始していません。
    • Started: 関数は実行を開始したが、まだ待機中でも完了済みでもありません。
    • Awaited: オーケストレーターが何らかの作業をスケジュールし、その完了を待っています。
    • Listening: オーケストレーターが外部のイベント通知をリッスンしています。
    • Completed: 関数が正常に完了しました。
    • [失敗] : 関数がエラーで失敗しました。
  • reason: 追跡イベントに関連付けられている追加のデータ。 たとえば外部イベントの通知をインスタンスが待機している場合、待機しているイベントの名前がこのフィールドによって表されます。 関数が失敗した場合、このフィールドにはエラーの詳細が格納されます。
  • isReplay: 追跡イベントが再生された実行に対するものであるかどうかを示すブール値。
  • extensionVersion: Durable Task 拡張機能のバージョン。 このバージョン情報は、拡張機能にバグの可能性があることを報告するときに特に重要です。 長時間実行されるインスタンスでは、実行中に更新が生じた場合、複数のバージョンが報告されます。
  • sequenceNumber: イベントの実行シーケンス番号。 タイムスタンプと組み合わせると、イベントを実行時刻順に並べ替えるのに役立ちます。 "インスタンスの実行中にホストが再起動した場合、この番号はゼロにリセットされるので、常に、最初にタイムスタンプで並べ替えて、次に sequenceNumber で並べ替えることが重要です。 "

Application Insights に出力される追跡データの詳細レベルは、host.json ファイルの logger (Functions 1.x) または logging (Functions 2.0) セクションで構成できます。

Functions 1.0

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

Functions 2.0

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

既定では、すべての "再生以外" の追跡イベントが出力されます。 データのボリュームは、Host.Triggers.DurableTask を "Warning" または "Error" に設定し、追跡イベントの出力を例外的な状況に限定することで減らせます。 詳細なオーケストレーション再生イベントの生成を有効にするには、host.json 構成ファイルの logReplayEvents を true に設定します。

Note

既定では、データの出力頻度が高くなりすぎないよう、Azure Functions ランタイムによって Application Insights テレメトリがサンプリングされます。 そのため、短時間に多数のライフサイクル イベントが発生すると追跡情報が失われることがあります。 この動作を構成する方法については、Azure Functions の監視に関する記事で説明しています。

オーケストレーター関数、アクティビティ関数、エンティティ関数の入力と出力は既定ではログに記録されません。 入力と出力をログに記録すると Application Insights のコストが上がるため、この既定の動作が推奨されています。 関数の入力および出力ペイロードには、機密情報も含まれる場合があります。 既定では、実際のペイロードの代わりに、関数の入力と出力のバイト数がログに記録されます。 Durable Functions 拡張機能で入力と出力のペイロードをすべてログに記録する場合、host.json 構成ファイルの traceInputsAndOutputs プロパティを true に設定します。

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

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

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 single instance ordered query

インスタンス サマリー クエリ

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

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 とその現在の実行状態が一覧表示されます。

Application Insights single instance query

Durable Task Framework のログ

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

DTFx によって出力されるログを見るときは、DTFx エンジンが、コア ディスパッチ エンジン (DurableTask.Core) と、サポートされている多くの記憶域プロバイダーの 1 つ (Durable Functions は既定で DurableTask.AzureStorage を使用しますが他のオプションも利用できます) の 2 つのコンポーネントで構成されていることを理解しておくことが重要です。

  • DurableTask.Core: コア オーケストレーションの実行と詳細なスケジュール設定のログとテレメトリ。
  • DurableTask.AzureStorage: Azure Storage 状態プロバイダーに固有のバックエンド ログ。 これらのログには、内部オーケストレーション状態を格納およびフェッチするために使用される内部キュー、BLOB、およびストレージ テーブルとの詳細な対話が含まれます。
  • DurableTask.Netherite: Netherite 記憶域プロバイダーに固有のバックエンド ログ (有効な場合)。
  • DurableTask.SqlServer: Microsoft SQL (MSSQL) 記憶域プロバイダーに固有のバックエンド ログ (有効な場合)。

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

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

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

Note

運用環境のアプリケーションでは、"Warning" フィルターを使用して、DurableTask.Core および適切な記憶域プロバイダー (DurableTask.AzureStorage など) のログを有効にすることをお勧めします。 "Information" などの詳細度の高いフィルターは、パフォーマンスの問題をデバッグする場合に非常に便利です。 ただし、これらのログ イベントは大量になる可能性があるため、Application Insights のデータ ストレージ コストが大幅に増加する可能性があります。

次の Kusto クエリは DTFx ログのクエリを実行する方法を示しています。 クエリの最も重要な部分は where customerDimensions.Category startswith "DurableTask" です。これは、結果を DurableTask.Core および DurableTask.AzureStorage カテゴリのログにフィルター処理するためです。

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

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

Application Insights DTFx query results

使用できるログ イベントの詳細については、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!");
}

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

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

Note

このログを見ると F1、F2、F3 が呼び出されていることになっていますが、"実際には"、これらの関数は最初に到達したときにしか呼び出されません。 それ以降、再生中に生じた呼び出しはスキップされ、オーケストレーター ロジックには出力結果が再生されます。

再生以外の実行だけをログに記録する場合は、"is replaying" フラグが false である場合にのみログを記録する条件式を記述できます。 先ほどの例に再生の条件判定を加えます。

[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!");
}

Durable Functions 2.0 以降、.NET のオーケストレーター関数にも、再生中にログ ステートメントを自動的にフィルターで除外する ILogger を作成するオプションがあります。 この自動フィルター処理は、IDurableOrchestrationContext.CreateReplaySafeLogger(ILogger) API を使用して行われます。

[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!");
}

Note

前述の C# の例は Durable Functions 2.x 用です。 Durable Functions 1.x の場合、IDurableOrchestrationContext の代わりに DurableOrchestrationContext を使用する必要があります。 バージョン間の相違点の詳細については、Durable Functions のバージョンに関する記事を参照してください。

前述の変更により、ログ出力は次のようになります。

Calling F1.
Calling F2.
Calling F3.
Done!

カスタム状態

カスタムオーケストレーションの状態を使用すると、オーケストレーター関数のカスタム状態値を設定できます。 このカスタム ステータスは、HTTP 状態クエリ API または言語固有の API 呼び出しを介して外部クライアントから参照できます。 オーケストレーションのカスタム状態により、オーケストレーター関数のより充実した監視が可能になります。 たとえば、オーケストレーター関数コードで "set custom status" API を呼び出して、実行時間の長い操作の進行状況を更新できます。 クライアント (Web ページや他の外部システムなど) は、HTTP status query 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...
}

Note

前記の C# の例は Durable Functions 2.x 用です。 Durable Functions 1.x の場合、IDurableOrchestrationContext の代わりに DurableOrchestrationContext を使用する必要があります。 バージョン間の相違点の詳細については、Durable Functions のバージョンに関する記事を参照してください。

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

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"
}

警告

カスタム状態ペイロードは、Azure Table Storage の列に収まる必要があるため、16 KB の UTF-16 JSON テキストに制限されています。 これより大きなペイロードが必要な場合は、外部ストレージを使用できます。

分散トレース

分散トレースでは、要求を追跡し、さまざまなサービスが相互にどのように作用するかを示します。 Durable Functions では、オーケストレーションとアクティビティも相互に関連付けられます。 これは、オーケストレーション全体に対するオーケストレーションのステップにかかる時間を理解するのに役立ちます。 また、アプリケーションで問題が発生している場所や例外がスローされた場所を理解するのにも役立ちます。 この機能は、すべての言語とストレージ プロバイダーでサポートされています。

Note

分散トレース V2 には、Durable Functions v2.12.0 以降が必要です。 また、分散トレース V2 はプレビュー状態であるため、一部の Durable Functions パターンはインストルメント化されません。 たとえば、持続エンティティ操作はインストルメント化されず、トレースは Application Insights に表示されません。

分散トレースの設定

分散トレースを設定するために、host.json を更新し、Application Insights リソースを設定してください。

host.json

"durableTask": {
  "tracing": {
    "distributedTracingEnabled": true,
    "Version": "V2"
  }
}

Application Insights

関数アプリが Application Insights リソースで構成されていない場合は、こちらの手順に従って構成してください。

トレースの検査

Application Insights リソースで、[トランザクション検索] に移動します。 結果で、Durable Functions 固有のプレフィックス (orchestration: や activity: など) で始まる Request および Dependency イベントを確認します。 これらのイベントのいずれかを選択すると、エンド ツー エンドの分散トレースを表示するガント チャートが開きます。

Gantt Chart showing Application Insights Distributed Trace.

トラブルシューティング

Application Insights にトレースが表示されない場合は、アプリケーションを実行してから約 5 分待って、すべてのデータが確実に Application Insights リソースに伝達されるようにしてください。

デバッグ

Azure Functions ではデバッグ関数コードが直接サポートされており、それと同じ機能が Durable Functions でも利用できます。Azure 内で実行するか、ローカルで実行するかは関係ありません。 ただしデバッグの際は、いくつかの動作に注意してください。

  • 再生: オーケストレーター関数は、新しい入力を受信すると、定期的に再生されます。 この動作は、オーケストレーター関数の実行が論理上は 1 回でも、複数回、同じブレークポイントに到達する可能性があることを意味します。特に、関数コードの最初の方に設定されている場合、その可能性が強くなります。
  • 待機: オーケストレーター関数内で await に到達した場合は常に、Durable Task Framework ディスパッチャーに制御が戻されます。 特定の await に到達したのが初めてである場合、関連するタスクが再開されることはありません。 タスクが再開されない以上、await をステップ オーバー (Visual Studio では F10) することは不可能です。 ステップ オーバーが機能するのは、タスクが再生されているときだけです。
  • メッセージングのタイムアウト: Durable Functions は、オーケストレーター関数、アクティビティ関数、およびエンティティ関数の実行を開始するために、内部的にキュー メッセージを使用します。 マルチ VM 環境では、長時間デバッグにブレークインすると、別の VM によってメッセージが取り出され、二重実行となる可能性があります。 この動作は、キューによってトリガーされる通常の関数でも起こりますが、あえてこのコンテキストで指摘したのは、キューが実装の要となる動作であるためです。
  • 停止と開始: Durable Functions のメッセージは、デバッグ セッション間で保持されます。 持続的関数の実行中にデバッグを停止し、ローカル ホスト プロセスを終了すると、その関数は今後のデバッグ セッションで自動的に再実行される可能性があります。 この動作は、予期していない場合、混乱を招くことがあります。 新しいタスク ハブの使用、またはデバッグ セッション間でのタスク ハブの内容をクリアは、この動作を回避する方法の 1 つです。

ヒント

オーケストレーター関数にブレークポイントを設定するときに、再生以外の実行でのみ停止させる必要がある場合は、"is replaying" 値が false の場合にのみ停止させる条件付きブレークポイントを設定できます。

ストレージ

既定では、Durable Functions の状態が Azure Storage に格納されます。 この動作は、Microsoft Azure Storage Explorer などのツールを使用してご自分のオーケストレーションの状態を調査することができることを意味します。

Azure Storage Explorer screenshot

オーケストレーションの状態を正確に把握できるので、これはデバッグで役に立ちます。 また、キュー内のメッセージを調べることで、保留中になっている (場合によってはスタックしている) 処理を把握することも可能です。

警告

テーブル ストレージ内の実行履歴を確認できるのは便利ですが、このテーブルに依存することは避けてください。 Durable Functions 拡張機能の刷新に伴って変更される可能性があります。

Note

既定の Azure Storage プロバイダーの代わりに、その他の記憶域プロバイダーを構成することもできます。 アプリ用に構成されている記憶域プロバイダーによっては、基になる状態を検査するためにさまざまなツールを使用することが必要になる場合があります。 詳細については、Durable Functions 記憶域プロバイダーに関するドキュメントを参照してください。

Durable Functions トラブルシューティング ガイド

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

サード パーティ製のツール

Durable Functions コミュニティでは、デバッグ、診断、監視に役立つさまざまなツールが公開されています。 このようなツールの 1 つとしてオープン ソースの Durable Functions モニターがあり、これはオーケストレーション インスタンスの監視、管理、およびデバッグを行うためのグラフィカルなツールです。

次のステップ

Azure Functions での監視の詳細を学習する