Diagnostisera och felsöka problem i Durable Functions

Durable Functions innehåller flera diagnostikverktyg för felsökning av orkestreringar. Den här artikeln beskriver hur du konfigurerar spårning och loggning, skriver kod som är säker på omspelning, inspekterar distribuerade spårningar och felsöker lokalt.

I den här artikeln lär du dig att:

Konfigurera Application Insights-spårning

Application Insights är det rekommenderade sättet att övervaka Durable Functions. Durable-tillägget genererar spårningshändelser som gör att du kan spåra körningen från slutpunkt till slutpunkt för en orkestrering. Du kan hitta och fråga efter dessa spårningshändelser med hjälp av verktyget Application Insights Analytics i Azure-portalen.

Konfiguration på loggnivå

Konfigurera utförligheten för spårningsdata som skickas till Application Insights i host.json -filen:

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

Som standard genereras alla icke-replay spårningshändelser. Du kan minska mängden data genom att ange Host.Triggers.DurableTask till eller "Warning", vilket innebär att "Error" spårningshändelser endast genereras för exceptionella situationer. Om du vill aktivera sändning av utförliga orkestreringsreprishändelser anger du logReplayEvents till true i konfigurationsfilenhost.json .

Loggning av indata och utdata

Som standard loggas inte orkestrering, aktivitet och entitetsfunktionsindata och utdata. Den här metoden rekommenderas eftersom loggning av indata och utdata kan öka Application Insights-kostnaderna. Funktionsindata och utdatanyttolaster kan också innehålla känslig information. I stället loggas antalet byte för funktionsindata och utdata. Om du vill att Durable Functions-tillägget ska logga alla nyttolaster för indata och utdata anger du egenskapen traceInputsAndOutputs till true i konfigurationsfilen host.json.

Frågeorkestreringsinstanser

Använd följande Kusto-frågor i Application Insights Analytics för att inspektera orkestreringsinstanser.

Enskild instansfråga

Följande fråga visar historiska spårningsdata för en enda instans av Hello Sequence-funktionsorkestreringen . Den filtrerar bort återupprepning så att endast den logiska körningsvägen visas. Du kan beställa händelser genom att sortera efter timestamp och sequenceNumber enligt följande fråga:

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

Resultatet är en lista med spårningshändelser som visar körvägen för orkestreringen, inklusive alla aktivitetsfunktioner som är ordnade efter körningstid i stigande ordning.

Fråga om instanssammanfattning

Följande fråga visar status för alla orkestreringsinstanser som kördes inom ett angivet tidsintervall.

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

Resultatet är en lista över instans-ID:er och deras aktuella körstatus.

Spårning av datareferens

Varje orkestreringsinstans genererar spårningshändelser under livscykeln. Varje livscykelhändelse innehåller ett customDimensions-payload med ett flertal fält. Fältnamn föregås alla av prop__.

Durable Task Framework loggning (DTFx)

Durable-tilläggsloggarna är användbara för att förstå hur orkestreringslogik fungerar. De här loggarna innehåller dock inte alltid tillräckligt med information för att felsöka prestanda- och tillförlitlighetsproblem på ramverksnivå. Från och med v2.3.0 i Durable-tillägget är loggar som genereras av det underliggande Durable Task Framework (DTFx) också tillgängliga för insamling.

När du tittar på loggar som genereras av DTFx är det viktigt att förstå att DTFx-motorn har två komponenter: kärnmotorn för sändning (DurableTask.Core) och en av många lagringsproviders som stöds.

Du kan aktivera loggarna genom att uppdatera logging/logLevel avsnittet i funktionsappens host.json fil. I följande exempel visas hur du aktiverar varnings- och felloggar från både DurableTask.Core och DurableTask.AzureStorage:

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

Om du har Application Insights aktiverat läggs dessa loggar automatiskt till i samlingen trace. Du kan söka efter dem på samma sätt som du söker efter andra trace loggar med hjälp av Kusto-frågor.

Följande Kusto-fråga visar hur du frågar efter DTFx-loggar. Den viktigaste delen av frågan är where customerDimensions.Category startswith "DurableTask" eftersom den filtrerar resultatet till loggar i DurableTask.Core kategorierna och DurableTask.AzureStorage .

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

Resultatet är en uppsättning loggar skrivna av Durable Task Framework-loggprovidrar.

Mer information om vilka logghändelser som är tillgängliga finns i den strukturerade loggningsdokumentationen Durable Task Framework på GitHub.

Distribuerad spårning

Distribuerad spårning spårar begäranden och visar hur olika tjänster interagerar med varandra. I Durable Functions korrelerar den orkestreringar, entiteter och aktiviteter tillsammans. Distribuerad spårning visar körningstiden för varje orkestreringssteg i förhållande till hela orkestreringen och identifierar var problem eller undantag inträffar. Den här funktionen stöds i Application Insights för alla språk och lagringsleverantörer.

Förutsättningar

Distribuerad spårning kräver specifika lägsta tilläggsversioner:

• För isolerade .NET-appar, Microsoft.Azure.Functions.Worker.Extensions.DurableTask>= v1.4.0.
• För appar som inte är .NET följ dessa instruktioner för att manuellt installera Microsoft.Azure.WebJobs.Extensions.DurableTask>= v3.2.0 för tillfället. Distribuerad spårning är tillgänglig i tilläggspaket >v4.24.x.

Konfigurera distribuerad spårning

Om du vill konfigurera distribuerad spårning, uppdatera host.json och sätt upp en Application Insights-resurs.

host.json

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

Programinsikter

Konfigurera funktionsappen med en Application Insights-resurs.

Inspektera spårningarna

Gå till Transaktionssökning i Application Insights-resursen. I resultaten letar du efter Request och Dependency händelser som börjar med för Durable-specifika förled, till exempel orchestration:, activity:, och så vidare. Om du väljer en av dessa händelser öppnas ett Gantt-schema som visar den distribuerade spårningen från slutpunkt till slutpunkt. Diagrammet visar varje orkestreringssteg som en vågrät stapel, med aktivitets- och underorkestreringsanrop kapslade under sin överordnade orkestrering. Stapellängden representerar varaktigheten på väggklockan för varje steg, vilket gör det enkelt att upptäcka flaskhalsar eller oväntat långsamma aktiviteter.

Omspelssäker loggning i orkestreringsfunktioner

Orchestrator-funktioner spelas upp varje gång ny indata tas emot, vilket innebär att alla loggningsinstruktioner i en orkestrator körs flera gånger under en enda logisk exekvering. En funktion med tre aktivitetsanrop genererar till exempel loggutdata så här under omspelningen:

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

För att förhindra dubbletter av loggposter, kontrollera flaggan "är repris" så att loggarna bara körs vid det första passet utan repris. I följande exempel visas återspelningssäker loggning på varje språk.

[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 * as df from "durable-functions";

df.app.orchestration("FunctionChain", 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!");
}

Med återspelningssäker loggning är loggutdata:

Calling F1.
Calling F2.
Calling F3.
Done!

Anpassad orkestreringsstatus

Använd anpassad orkestreringsstatus för att rapportera arbetsflödets förlopp till externa klienter. Vanliga mönster är slutförandeprocent, stegbeskrivningar och felsammanfattningar. Externa klienter kan visa den anpassade statusen via HTTP-statusfrågans API eller språkspecifika API-anrop.

Följande kod visar hur du anger ett anpassat statusvärde i en orchestrator-funktion:

[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 * as df from "durable-functions";

df.app.orchestration("SetStatusTest", 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...
}

Medan orkestreringen körs kan externa klienter hämta den här anpassade statusen:

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

Klienter får följande svar:

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

felsökning

Azure Functions har direkt stöd för felsökning av funktionskod, och samma stöd vidarebefordras till Durable Functions, oavsett om det körs i Azure eller lokalt. Använd följande arbetsflöde för bästa felsökningsupplevelse:

1. Starta en ny felsökningssession med en ny aktivitetshubb eller rensa innehållet i aktivitetshubben mellan sessioner. Överblivna meddelanden från tidigare körningar kan orsaka oväntad återexekvering.

2. Ange brytpunkter i orkestrerings- eller aktivitetsfunktionerna. För orkestreringsfunktioner använder du en villkorsstyrd brytpunkt som endast aktiveras när värdet för "återspelas" är false, för att undvika att träffa samma brytpunkt flera gånger under återuppspelningen.

3. Gå igenom koden som vanligt. Tänk på följande beteenden:

   • Replay:
     Orchestrator-funktioner körs regelbundet om när ny ingångsdata tas emot. En enda logisk körning av en orchestrator-funktion kan resultera i att samma brytpunkt uppnås flera gånger, särskilt om den anges tidigt i funktionskoden.

   • Väntar:
     När en await påträffas i en orkestreringsfunktion ger den kontroll tillbaka till Durable Task Framework-avsändaren. Om det är första gången en viss uppgift await påträffas återupptas aldrig den associerade aktiviteten. Eftersom uppgiften aldrig återupptas är det inte möjligt att stega over inväntningen (F10 i Visual Studio). Att kliva över fungerar bara när en uppgift spelas upp igen.

   • Tidsgränser för meddelanden:
     Durable Functions använder kömeddelanden internt för att köra orkestrerings-, aktivitets- och entitetsfunktioner. I en miljö med flera virtuella datorer kan utökade felsökningssessioner leda till att en annan virtuell dator bearbetar meddelandet, vilket resulterar i duplicerad körning. Även om det här beteendet också finns för vanliga köutlösarfunktioner är den här kontexten viktig att markera eftersom köerna är en implementeringsinformation.

   • Stoppa och starta:
     Meddelanden i Durable Functions sparas mellan felsökningssessioner. Om du slutar felsöka och avslutar den lokala värdprocessen medan en varaktig funktion körs kan den funktionen köras igen automatiskt i en framtida felsökningssession.

Ytterligare verktyg

Inspektera lagringstillstånd

Durable Functions lagrar som standard tillståndet i Azure Storage. Du kan inspektera orkestreringstillstånd och meddelanden med hjälp av verktyg som Microsoft Azure Storage Explorer.

Durable Functions Övervakare

Durable Functions Monitor är ett grafiskt verktyg för övervakning, hantering och felsökning av orkestrering och entitetsinstanser. Den är tillgänglig som ett Visual Studio Code-tillägg eller en fristående app. För installationsanvisningar och en lista över funktioner, se Durable Functions Monitor Wiki.

Azure portaldiagnostik

Azure-portalen innehåller inbyggda diagnostikverktyg för dina funktionsappar.

Diagnostisera och lösa problem: Azure Function App Diagnostics är en användbar resurs för att övervaka och diagnostisera potentiella problem i ditt program. Den innehåller också förslag som hjälper dig att lösa problem baserat på diagnosen. Mer information finns i Azure Funktionsapp-diagnostik.

Orkestreringsspårningar: Azure-portalen innehåller orkestreringsspårningsinformation som hjälper dig att förstå statusen för varje orkestreringsinstans och spåra körning från slutpunkt till slutpunkt. När du visar listan över funktioner i din Azure Functions app visas kolumnen Monitor som innehåller länkar till spårningarna. Du måste ha Application Insights aktiverat för att din app ska få åtkomst till den här informationen.

Roslyn-analysverktyg

Durable Functions Roslyn Analyzer är en livekodanalys som hjälper C#-utvecklare att följa Durable Functions specifika code-begränsningar. Anvisningar om hur du aktiverar den i Visual Studio och Visual Studio Code finns i Durable Functions Roslyn Analyzer.

Felsökning

Information om hur du felsöker vanliga problem som orkestrering som fastnar, misslyckas med att starta eller köra långsamt finns i felsökningsguiden Durable Functions.

Nästa steg