Diagnostische gegevens in Durable Functions in Azure

Er zijn verschillende opties voor het diagnosticeren van problemen met Durable Functions. Sommige van deze opties zijn hetzelfde voor gewone functies en sommige zijn uniek voor Durable Functions.

Analyses van toepassingen

Application Insights is de aanbevolen manier om diagnostische gegevens en bewaking uit te voeren in Azure Functions. Hetzelfde geldt voor Durable Functions. Voor een overzicht van het gebruik van Application Insights in uw functie-app, zie Azure Functions monitoren.

De Durable Extension van Azure Functions verzendt ook traceringsgebeurtenissen waarmee u de end-to-end uitvoering van een orchestratie kunt volgen. Deze traceringsgebeurtenissen kunnen worden gevonden en opgevraagd met behulp van het Application Insights Analytics-hulpprogramma in Azure Portal.

Traceringsgegevens

Elke levenscyclusgebeurtenis van een orkestratie-exemplaar zorgt ervoor dat een traceringsevenement naar de traces-verzameling in Application Insights wordt geschreven. Deze gebeurtenis bevat een customDimensions payload met verschillende velden. Veldnamen worden allemaal voorafgegaan door prop__.

• hubName: de naam van de taakhub waarin uw orchestraties worden uitgevoerd.
• appName: de naam van de functie-app. Dit veld is handig wanneer u meerdere functie-apps hebt die hetzelfde Application Insights-exemplaar delen.
• slotName: de implementatiesite waarin de huidige functie-app wordt uitgevoerd. Dit veld is handig wanneer u implementatieslots gebruikt om uw orkestraties te versioneren.
• functionName: de naam van de orchestrator- of activiteitsfunctie.
• functionType: het type van de functie, zoals Orchestrator of Activity.
• instanceId: de unieke ID van het orkestratie-exemplaar.
• status: de uitvoeringsstatus van de levenscyclus van het exemplaar. Geldige waarden zijn:
  • Gepland: De functie is gepland voor uitvoering, maar is nog niet gestart.
  • Gestart: De functie is gestart, maar is nog niet in afwachting of voltooid.
  • In afwachting: De orchestrator heeft enkele taken gepland en wacht totdat het voltooid is.
  • Luisteren: De orchestrator luistert naar een melding van een externe gebeurtenis.
  • Voltooid: De functie is voltooid.
  • Mislukt: de functie is mislukt met een fout.
• reden: Aanvullende gegevens die zijn gekoppeld aan de tracerings gebeurtenis. Als een exemplaar bijvoorbeeld wacht op een melding van een externe gebeurtenis, geeft dit veld de naam aan van de gebeurtenis waarop wordt gewacht. Als een functie mislukt, bevat dit veld de foutdetails.
• isReplay: Booleaanse waarde die aangeeft of de traceringsgebeurtenis voor opnieuw afgespeelde uitvoering is.
• extensionVersion: de versie van de Durable Task-extensie. De versie-informatie is vooral belangrijke gegevens wanneer mogelijke fouten in de extensie worden gerapporteerd. Langlopende exemplaren kunnen meerdere versies rapporteren als er een update plaatsvindt terwijl deze wordt uitgevoerd.
• sequenceNumber: uitvoeringsreeksnummer voor een gebeurtenis. In combinatie met de tijdstempel kunt u de gebeurtenissen orden op uitvoeringstijd. Houd er rekening mee dat dit getal opnieuw wordt ingesteld op nul als de host opnieuw wordt opgestart terwijl het exemplaar wordt uitgevoerd, dus het is belangrijk om altijd eerst te sorteren op tijdstempel en vervolgens sequenceNumber.

De uitgebreidheid van traceringsgegevens die naar Application Insights worden verzonden, kan worden geconfigureerd in de logger sectie (Functions 1.x) of logging (Functions 2.0) van het host.json bestand.

Functions 1.0

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

Functions 2.0

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

Standaard worden alle niet-herhalingstraceringsgebeurtenissen verzonden. Het volume aan gegevens kan worden verminderd door Host.Triggers.DurableTask op "Warning" of "Error" in te stellen, in welk geval tracking events uitsluitend worden gegenereerd voor uitzonderlijke situaties. Als u het verzenden van de uitgebreide orkestratie-herhalingsgebeurtenissen wilt inschakelen, stelt u logReplayEvents in op true in het host.json configuratiebestand.

Invoer en uitvoer van orchestrator-, activiteits- en entiteitsfuncties worden niet standaard geregistreerd. Dit standaardgedrag wordt aanbevolen omdat logging van invoer en uitvoer de kosten van Application Insights kan verhogen. Functie-invoer- en uitvoerladingen kunnen ook gevoelige informatie bevatten. In plaats daarvan wordt standaard het aantal bytes voor functie-invoer en -uitvoer vastgelegd in plaats van de werkelijke pakketten. Als u wilt dat de Durable Functions-extensie de volledige gegevens voor invoer en uitvoer registreert, stelt u de traceInputsAndOutputs eigenschap in op true in het host.json configuratiebestand.

Query voor een enkele instantie

In de volgende query ziet u historische trackinggegevens voor een enkel exemplaar van de Hello Sequence functie-orkestratie. Het is geschreven met behulp van de Kusto-querytaal. Hiermee wordt de uitvoering van herhalingen gefilterd, zodat alleen het logische uitvoeringspad wordt weergegeven. Gebeurtenissen kunnen worden gesorteerd op timestamp en sequenceNumber zoals wordt weergegeven in de onderstaande query:

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

Het resultaat is een lijst met gebeurtenissen die het uitvoeringspad van de orchestratie weergeven, inclusief activiteitsfuncties die zijn gerangschikt in oplopende volgorde op uitvoeringstijd.

Samenvattingsquery exemplaar

De volgende query toont de status van alle orchestratie-instanties die binnen een opgegeven tijdsbestek zijn uitgevoerd.

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

Het resultaat is een lijst met exemplaar-id's en hun huidige runtimestatus.

Logboekregistratie van Durable Task Framework

De durable-extensielogboeken zijn handig om inzicht te krijgen in het gedrag van uw indelingslogica. Deze logboeken bevatten echter niet altijd voldoende informatie om prestatie- en betrouwbaarheidsproblemen op frameworkniveau op te sporen. Vanaf v2.3.0 van de Durable-extensie zijn logboeken die worden verzonden door het onderliggende Durable Task Framework (DTFx) ook beschikbaar voor verzameling.

Wanneer u logboeken bekijkt die door de DTFx worden verzonden, is het belangrijk om te begrijpen dat de DTFx-engine bestaat uit twee onderdelen: de kernverzendingsengine (DurableTask.Core) en een van de vele ondersteunde opslagproviders (Durable Functions maakt standaard gebruik DurableTask.AzureStorage van andere opties).

• DurableTask.Core: Uitvoering van kernindeling en planningslogboeken op laag niveau en telemetrie.
• DurableTask.AzureStorage: back-endlogboeken die specifiek zijn voor de Azure Storage-statusprovider. Deze logboeken bevatten gedetailleerde interacties met de interne wachtrijen, blobs, en opslagtabellen die worden gebruikt om de interne orchestratiestatus op te slaan en op te halen.
• DurableTask.Netherite: back-endlogboeken die specifiek zijn voor de Netherite-opslagprovider, indien ingeschakeld.
• DurableTask.SqlServer: back-endlogboeken die specifiek zijn voor de Microsoft SQL-opslagprovider (MSSQL), indien ingeschakeld.

U kunt deze logboeken inschakelen door de sectie van het logging/logLevel host.json-bestand van uw functie-app bij te werken. In het volgende voorbeeld ziet u hoe u waarschuwings- en foutlogboeken van zowel DurableTask.Core als DurableTask.AzureStorage kunt inschakelen.

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

Als Application Insights is ingeschakeld, worden deze logboeken automatisch toegevoegd aan de trace verzameling. U kunt ze op dezelfde manier doorzoeken als u andere trace logboeken zoekt met behulp van Kusto-query's.

De volgende Kusto-query laat zien hoe u query's kunt uitvoeren op DTFx-logboeken. Het belangrijkste onderdeel van de query is where customerDimensions.Category startswith "DurableTask" omdat het de resultaten filtert, waarbij alleen logboeken in de DurableTask.Core en DurableTask.AzureStorage categorieën worden weergegeven.

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

Het resultaat is een set logboeken die zijn geschreven door de Durable Task Framework-logboekproviders.

Zie de documentatie over gestructureerde logboekregistratie van Durable Task Framework op GitHub voor meer informatie over welke logboeken er beschikbaar zijn.

App-logboek

Het is belangrijk dat u het gedrag van de orchestratorherhaling in gedachten houdt wanneer u logboeken rechtstreeks vanuit een orchestratorfunctie schrijft. Denk bijvoorbeeld aan de volgende orchestratorfunctie:

[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 resulterende logboekgegevens zien er ongeveer als volgt uit:

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

Als u alleen logboeken wilt schrijven over uitvoeringen die niet opnieuw worden afgespeeld, kunt u een voorwaardelijke expressie schrijven om alleen te registreren als de vlag 'is opnieuw afspelen' is false. Bekijk het bovenstaande voorbeeld, maar deze keer met controles voor opnieuw afspelen.

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

Met de eerder genoemde wijzigingen is de logboekuitvoer als volgt:

Calling F1.
Calling F2.
Calling F3.
Done!

Aangepaste Status

Met de aangepaste orkestratiestatus kunt u een aangepaste statuswaarde instellen voor uw orchestrator-functie. Deze aangepaste status is vervolgens zichtbaar voor externe clients via de HTTP-statusquery-API of via taalspecifieke API-aanroepen. De aangepaste orchestratiestatus maakt uitgebreidere bewaking mogelijk voor orchestratiefuncties. De orchestratorfunctiecode kan bijvoorbeeld de API 'Aangepaste status instellen' aanroepen om de voortgang voor een langdurige bewerking bij te werken. Een client, zoals een webpagina of een ander extern systeem, kan vervolgens periodiek query's uitvoeren op de HTTP-statusquery-API's voor uitgebreidere voortgangsinformatie. Hieronder vindt u voorbeeldcode voor het instellen van een aangepaste statuswaarde in een orchestrator-functie:

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

Terwijl de orkestratie wordt uitgevoerd, kunnen externe cliënten deze aangepaste status ophalen.

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

Clients krijgen het volgende antwoord:

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

Gedistribueerde tracering

Gedistribueerde tracering houdt aanvragen bij en laat zien hoe verschillende services met elkaar communiceren. In Durable Functions correleert het ook orkestraties, entiteiten en activiteiten. Dit is nuttig om te begrijpen hoeveel tijd de verschillende stappen van de orkestratie in beslag nemen ten opzichte van de volledige orkestratie. Het is ook handig om te begrijpen waar een toepassing een probleem heeft of waar een uitzondering is opgetreden. Deze functie wordt ondersteund in Application Insights voor alle talen en opslagproviders.

Gedistribueerde tracering instellen

Als u gedistribueerde tracering wilt instellen, werkt u de host.json bij en stelt u een Application Insights-resource in.

host.json

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

Analyses van toepassingen

Als de functie-app niet is geconfigureerd met een Application Insights-resource, configureert u deze volgens de instructies hier.

De traceringen inspecteren

Navigeer in de Application Insights-resource naar Transaction Search. Controleer in de resultaten op Request- en Dependency-gebeurtenissen die beginnen met specifieke voorvoegsels van Durable Functions, bijvoorbeeld orchestration:, activity:, enzovoort. Als u een van deze gebeurtenissen selecteert, wordt een Gantt-diagram geopend waarin de end-to-end gedistribueerde tracering wordt weergegeven.

Probleemoplossing

Als u de traceringen niet ziet in Application Insights, moet u ongeveer vijf minuten wachten nadat u de toepassing hebt uitgevoerd om ervoor te zorgen dat alle gegevens worden doorgegeven aan de Application Insights-resource.

Foutopsporing

Azure Functions biedt rechtstreeks ondersteuning voor het debuggen van functiecode, en dezelfde ondersteuning is van toepassing op Durable Functions, ongeacht of deze wordt uitgevoerd in Azure of lokaal. Er zijn echter enkele gedragingen waar u rekening mee moet houden bij het opsporen van fouten:

• Opnieuw afspelen: Orchestrator-functies worden regelmatig opnieuw afgespeeld wanneer nieuwe invoer wordt ontvangen. Dit gedrag betekent dat één logische uitvoering van een orchestratorfunctie meerdere keren hetzelfde onderbrekingspunt kan bereiken, vooral als deze vroeg in de functiecode is ingesteld.
• Wacht op: Wanneer er een await optreedt in een orchestatorfunctie, wordt de controle teruggegeven aan de dispatcher van het Durable Task Framework. Als het de eerste keer is dat een bepaalde await taak is aangetroffen, wordt de bijbehorende taak nooit hervat. Omdat de taak nooit wordt hervat, is het niet mogelijk om over de await te stappen (F10 in Visual Studio). Stappen werkt alleen wanneer een taak opnieuw wordt afgespeeld.
• Time-outs voor berichten: Durable Functions maakt intern gebruik van wachtrijberichten om de uitvoering van orchestrator-, activiteits- en entiteitsfuncties aan te sturen. In een omgeving met meerdere VM's kan het inbreken van de foutopsporing gedurende langere tijd ertoe leiden dat een andere VIRTUELE machine het bericht ophaalt, wat resulteert in dubbele uitvoering. Dit gedrag bestaat ook voor reguliere wachtrijtriggerfuncties, maar is belangrijk om in deze context te wijzen omdat de wachtrijen een implementatiedetails zijn.
• Stoppen en starten: Berichten in Durable Functions blijven behouden tussen foutopsporingssessies. Als u de foutopsporing stopt en het lokale hostproces beëindigt terwijl een duurzame functie wordt uitgevoerd, kan die functie automatisch opnieuw worden uitgevoerd in een toekomstige foutopsporingssessie. Dit gedrag kan verwarrend zijn wanneer dit niet wordt verwacht. Het gebruik van een nieuwe taakhub of het wissen van de inhoud van de taakhub tussen foutopsporingssessies is één techniek om dit gedrag te voorkomen.

Opslag

Durable Functions slaat standaard de status op in Azure Storage. Dit gedrag betekent dat u de status van uw indelingen kunt inspecteren met behulp van hulpprogramma's zoals Microsoft Azure Storage Explorer.

Dit is handig voor foutopsporing, omdat u precies ziet in welke staat een orkestratie zich bevindt. Berichten in de wachtrijen kunnen ook worden onderzocht om te zien wat er in behandeling is (of in bepaalde gevallen vastzit).

Monitor voor duurzame functies

Durable Functions Monitor is een grafisch hulpprogramma voor het bewaken, beheren en debuggen van orchestratie- en entiteitsinstanties. Het is beschikbaar als een Visual Studio Code-extensie of een zelfstandige app. Informatie over het instellen en een lijst met functies vindt u in deze wiki.

Gids voor het oplossen van problemen met Durable Functions

Raadpleeg deze probleemoplossingsgids om veelvoorkomende symptomen van problemen aan te pakken, zoals orkestraties die vastlopen, niet opstarten, langzaam uitvoeren, enzovoort.

Volgende stappen