Diagnostik i Durable Functions i Azure

Det finns flera alternativ för att diagnostisera problem med Durable Functions. Vissa av dessa alternativ är desamma för vanliga funktioner medan andra är unika för Durable Functions.

Programinsikter

Application Insights är det rekommenderade sättet att utföra diagnostik och övervakning i Azure Functions. Samma sak gäller för Durable Functions. För en översikt över hur du använder Application Insights i din funktionsapp, se Övervaka Azure Functions.

Azure Functions Durable Extension genererar även spårningshändelser som gör att du kan spåra hela körningen av en orkestrering. Dessa spårningshändelser kan hittas och frågas med hjälp av verktyget Application Insights Analytics i Azure Portal.

Spårningsdata

Varje livscykelhändelse för en orkestreringsinstans gör att en spårningshändelse skrivs till spårningssamlingen i Application Insights. Den här händelsen innehåller en customDimensions-last med flera fält. Fältnamn föregås alla av prop__.

• hubName: Namnet på aktivitetshubben där dina orkestreringar körs.
• appName: Namnet på funktionsappen. Det här fältet är användbart när du har flera funktionsappar som delar samma Application Insights-instans.
• slotName: Distributionsplatsen där den aktuella funktionsappen körs. Det här fältet är användbart när du använder distributionsluckor för att versionshantera dina orkestreringar.
• functionName: Namnet på orkestrerings- eller aktivitetsfunktionen.
• functionType: Funktionens typ, till exempel Orchestrator eller Activity.
• instanceId: Det unika ID:t för orkestreringsinstansen.
• tillstånd: Exekveringstillståndet för instansens livscykel. Giltiga värden är:
  • Schemalagd: Funktionen har schemalagts för körning men har inte börjat köras än.
  • Startade: Funktionen började köras men har ännu inte avvaktat eller slutförts.
  • Väntar: Orkestratorn har schemalagt en del arbete och väntar på att det ska slutföras.
  • Lyssnar: Orchestratorn lyssnar efter en extern händelsenotifikation.
  • Slutförd: Funktionen slutfördes framgångsrikt.
  • Misslyckades: Funktionen misslyckades med ett fel.
• orsak: Ytterligare data som är associerade med spårningshändelsen. Om en instans till exempel väntar på ett externt händelsemeddelande anger det här fältet namnet på den händelse som den väntar på. Om en funktion misslyckas innehåller det här fältet felinformationen.
• isReplay: Booleskt värde som anger om spårningshändelsen ska köras igen.
• extensionVersion: Versionen av tillägget Durable Task. Versionsinformationen är särskilt viktig när du rapporterar eventuella buggar i tillägget. Långvariga instanser kan rapportera flera versioner om en uppdatering sker medan den körs.
• sequenceNumber: Körningssekvensnummer för en händelse. Genom att kombinera med tidsstämpeln hjälper det att sortera händelserna efter exekveringstid. Observera att det här numret återställs till noll om värden startar om medan instansen körs, så det är viktigt att alltid sortera efter tidsstämpel först och sedan sekvensnummer.

Utförligheten för spårningsdata som överförs till Application Insights kan konfigureras i avsnittet logger (Functions 1.x) eller logging (Functions 2.0) i filen host.json.

Funktioner 1.0

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

Funktioner 2.0

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

Som standard genereras alla icke-replay spårningshändelser. Datavolymen kan minskas genom att ange Host.Triggers.DurableTask till "Warning" eller "Error" i vilket fall 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 konfigurationsfilen host.json .

Indata och utdata från orkestrerings-, aktivitets- och entitetsfunktioner loggas inte som standard. Det här standardbeteendet 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 i stället för de faktiska nyttolasterna som standard. Om du vill att Durable Functions-tillägget ska logga de fullständiga in- och utdatanyttolasterna anger du traceInputsAndOutputs egenskapen till true i konfigurationsfilen host.json .

Enskild instansfråga

Följande fråga visar historiska spårningsdata för en enda instans av Hello Sequence-funktionsorkestreringen . Den skrivs med hjälp av Kusto-frågespråk. Den filtrerar bort återupprepning så att endast den logiska körningsvägen visas. Händelser kan ordnas genom sortering efter timestamp och sequenceNumber som visas i frågan nedan:

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.

Durable Task Framework-loggning

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 består av två komponenter: kärnmotorn för sändning (DurableTask.Core) och en av många lagringsproviders som stöds (Durable Functions använder DurableTask.AzureStorage som standard, men andra alternativ är tillgängliga).

• DurableTask.Core: Grundläggande orkestreringskörning och schemaläggningsloggar på låg nivå och telemetri.
• DurableTask.AzureStorage: Serverdelsloggar som är specifika för Azure Storage-tillståndsprovidern. Dessa loggar omfattar detaljerade interaktioner med interna köer, blobbar och lagringstabeller som används för att lagra och hämta internt orkestreringstillstånd.
• DurableTask.Netherite: Serverdelsloggar som är specifika för Netherite-lagringsprovidern, om de är aktiverade.
• DurableTask.SqlServer: Serverdelsloggar som är specifika för Microsoft SQL-lagringsprovidern (MSSQL) om de är aktiverade.

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 det 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 för Durable Task Framework på GitHub.

Applogg

Det är viktigt att ha orkestratorns uppspelningsbeteende i åtanke när du skriver loggar direkt från en orkestratorfunktion. Tänk till exempel på följande orchestrator-funktion:

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

De resulterande loggdata kommer att se ut ungefär som i följande exempelutdata:

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

Om du bara vill skriva loggar på icke-repriskörningar kan du skriva ett villkorsuttryck för att logga endast om flaggan "spelas upp" är false. Tänk på exemplet ovan, men den här gången med repriskontroller.

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

Med de tidigare nämnda ändringarna är loggutdata följande:

Calling F1.
Calling F2.
Calling F3.
Done!

Anpassad status

Med anpassad orkestreringsstatus kan du ange ett anpassat statusvärde för orkestreringsfunktionen. Den här anpassade statusen visas sedan för externa klienter via HTTP-statusfrågans API eller via språkspecifika API-anrop. Den anpassade orkestreringsstatusen möjliggör bättre övervakning av orkestreringsfunktioner. Till exempel kan orchestrator-funktionskoden anropa API:et "set custom status" för att uppdatera förloppet för en långvarig åtgärd. En klient, till exempel en webbsida eller ett annat externt system, kan sedan regelbundet fråga HTTP-statusfrågans API:er för mer detaljerad förloppsinformation. Exempelkod för att ange ett anpassat statusvärde i en orchestrator-funktion finns nedan:

[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...
}

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

Distribuerad spårning

Distribuerad spårning spårar begäranden och visar hur olika tjänster interagerar med varandra. I Durable Functions korrelerar den även orkestreringar, entiteter och aktiviteter tillsammans. Det här är användbart för att förstå hur mycket tid stegen i orkestreringen tar i förhållande till hela orkestreringen. Det är också användbart att förstå var ett program har ett problem eller var ett undantag utlöstes. Den här funktionen stöds i Application Insights för alla språk och lagringsleverantörer.

Konfigurera distribuerad spårning

Om du vill konfigurera distribuerad spårning uppdaterar du host.json och konfigurerar en Application Insights-resurs.

host.json

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

Programinsikter

Om funktionsappen inte har konfigurerats med en Application Insights-resurs konfigurerar du den enligt anvisningarna här.

Inspektera spårningarna

I Application Insights-resursen går du till Transaktionssökning. I resultatet söker du efter Request och Dependency händelser som börjar med Durable Functions-specifika prefix (t.ex. orchestration:, activity:osv.). Om du väljer en av dessa händelser öppnas ett Gantt-schema som visar distribuerad spårning från slutpunkt till slutpunkt.

Felsökning

Om du inte ser spårningarna i Application Insights måste du vänta ungefär fem minuter efter att programmet har körts för att säkerställa att alla data sprids till Application Insights-resursen.

Felsökning

Azure Functions stöder felsökning av funktionskod direkt, och samma stöd vidarebefordras till Durable Functions, oavsett om det körs i Azure eller lokalt. Det finns dock några beteenden att känna till vid felsökning:

• Återuppspelning: Orchestrator-funktioner körs regelbundet igen när nya inmatningar tas emot. Det här beteendet innebär att en enda logisk körning av en orkestreringsfunktion kan resultera i att samma brytpunkt uppnås flera gånger, särskilt om den anges tidigt i funktionskoden.
• Väntar: Varje gång en await påträffas i en orkestreringsfunktion lämnar den tillbaka kontrollen till Durable Task Framework-dispatchern. 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 kliva över väntan (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 internt kömeddelanden för att köra orkestrerings-, aktivitets- och entitetsfunktioner. Om du bryter dig in i felsökningen under längre tidsperioder i en miljö med flera virtuella datorer kan det leda till att en annan virtuell dator hämtar meddelandet, vilket resulterar i duplicerad körning. Det här beteendet finns även för vanliga köutlösarfunktioner, men är viktigt att påpeka i den här kontexten 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. Det här beteendet kan vara förvirrande när det inte förväntas. Att använda en ny aktivitetshubb eller rensa innehållet i aktivitetshubben mellan felsökningssessioner är en teknik för att undvika det här beteendet.

Förvaring

Durable Functions lagrar som standard tillståndet i Azure Storage. Det här beteendet innebär att du kan kontrollera orkestreringarnas tillstånd med hjälp av verktyg som Microsoft Azure Storage Explorer.

Detta är användbart för felsökning eftersom du ser exakt vilket tillstånd en orkestrering kan vara i. Meddelanden i köerna kan också undersökas för att lära sig vilket arbete som väntar (eller fastnar i vissa fall).

Varaktiga funktioners övervakare

Durable Functions Monitor är ett grafiskt verktyg för övervakning, hantering och felsökning av orkestrering och entitetsinstanser. Det är tillgängligt som ett Visual Studio Code-tillägg eller en fristående app. Information om konfiguration och en lista över funktioner finns i den här wikin.

Felsökningsguide för Durable Functions

Information om hur du felsöker vanliga problem, till exempel orkestreringar som fastnar, misslyckas med att starta, köra långsamt osv. finns i den här felsökningsguiden.

Nästa steg