Diagnostica in Durable Functions in Azure

Per la diagnostica dei problemi con Funzioni permanenti sono disponibili diverse opzioni. Alcune opzioni sono le stesse disponibili per le funzioni normali e alcune sono specifiche di Funzioni permanenti.

Application Insights

Per eseguire la diagnostica e il monitoraggio in Funzioni di Azure, è consigliabile usare Application Insights. Lo stesso consiglio vale per Funzioni permanenti. Per una panoramica su come usare Application Insights nell'app per le funzioni, vedere Monitorare Funzioni di Azure.

L'estensione Funzioni permanenti di Funzioni di Azure genera anche eventi di rilevamento che consentono di tenere traccia dell'esecuzione end-to-end di un'orchestrazione. È possibile individuare e sottoporre a query questi eventi di rilevamento usando lo strumento Application Insights Analytics nel portale di Azure.

Dati di rilevamento

Ogni evento del ciclo di vita di un'istanza di orchestrazione genera la scrittura di un evento di rilevamento nella raccolta traces in Application Insights. Questo evento contiene un payload customDimensions con diversi campi. Ai nomi dei campi viene anteposta la stringa prop__.

• hubName: il nome dell'hub attività in cui vengono eseguite le orchestrazioni.
• appName: il nome dell'app per le funzioni. Questo campo è utile quando più app per le funzioni condividono la stessa istanza di Application Insights.
• slotName: slot di distribuzione in cui è in esecuzione l'app per le funzioni corrente. Questo campo è utile quando si usano slot di distribuzione per controllare le versioni delle orchestrazioni.
• functionName: il nome della funzione dell'agente di orchestrazione o di attività.
• functionType: il tipo di funzione, ad esempio agente di orchestrazione o attività.
• instanceId: l'ID univoco dell'istanza di orchestrazione.
• state: lo stato di esecuzione del ciclo di vita dell'istanza. I valori validi includono:
  • Scheduled: la funzione è stata pianificata per l'esecuzione, ma non è stata ancora avviata.
  • Started: la funzione è stata avviata, ma non è ancora in stato di attesa o non è stata completata.
  • Awaited: l'agente di orchestrazione ha pianificato un lavoro ed è in attesa del completamento.
  • Listening: l'agente di orchestrazione è in ascolto di una notifica degli eventi esterni.
  • Completed: la funzione è stata completata.
  • Failed: la funzione ha avuto esito negativo generando un errore.
• reason: dati aggiuntivi associati all'evento di rilevamento. Ad esempio, se un'istanza è in attesa di una notifica degli eventi esterni, questo campo indica il nome dell'evento di cui è in attesa. Se una funzione ha avuto esito negativo, il campo contiene i dettagli dell'errore.
• isReplay: valore booleano che indica se per l'evento di rilevamento è prevista la riesecuzione.
• extensionVersion: la versione dell'estensione Durable Task. Questi dati sono particolarmente importanti quando si segnalano possibili bug nell'estensione. Le istanze con esecuzione prolungata possono segnalare più versioni, se si verifica un aggiornamento durante l'esecuzione.
• sequenceNumber: numero di sequenza di esecuzione per un evento. In combinazione con il timestamp consente di ordinare gli eventi per ora di esecuzione. Si noti che questo numero verrà reimpostato su zero se l'host viene riavviato durante l'esecuzione dell'istanza. È quindi importante eseguire sempre l'ordinamento prima per timestamp e quindi per sequenceNumber.

Il livello di dettaglio dei dati di rilevamento generati ad Application Insights può essere configurato nella sezione logger (Funzioni 1.x) o logging (Funzioni 2.0) del file host.json.

Funzioni 1.0

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

Funzioni 2.0

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

Per impostazione predefinita vengono generati tutti gli eventi di rilevamento senza riesecuzione. Il volume dei dati può essere ridotto impostando Host.Triggers.DurableTask su "Warning" o "Error"; in questo caso gli eventi di rilevamento verranno generati solo per le situazioni eccezionali. Per abilitare l'emissione degli eventi di riproduzione dell'orchestrazione dettagliata, impostare logReplayEvents su true nel file di configurazione host.json.

Gli input e gli output dell'agente di orchestrazione, dell'attività e delle funzioni di entità non vengono registrati per impostazione predefinita. Questo comportamento predefinito è consigliato perché la registrazione di input e output potrebbe aumentare i costi di Application Insights. I payload di input e output delle funzioni possono contenere anche informazioni riservate. Al contrario, viene registrato il numero di byte per gli input e gli output della funzione anziché i payload effettivi per impostazione predefinita. Perché l'estensione Durable Functions registri i payload di input e output completi, impostare la proprietà traceInputsAndOutputs su true nel file di configurazione host.json.

Query per singola istanza

La query seguente mostra i dati di rilevamento cronologici per una singola istanza di orchestrazione della funzione Hello Sequence. Viene scritta usando il linguaggio di query Kusto. Esclude la riesecuzione in modo da mostrare solo il percorso di esecuzione logico. Gli eventi possono essere ordinati per timestamp e sequenceNumber, come illustrato nella query seguente:

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

Il risultato è un elenco di eventi di traccia che mostrano il percorso di esecuzione dell'orchestrazione, incluse eventuali funzioni di attività ordinate per ora di esecuzione in ordine ascendente.

Query di riepilogo dell'istanza

La query seguente mostra lo stato di tutte le istanze di orchestrazione eseguite in un intervallo di tempo specificato.

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

Il risultato è un elenco di ID istanza e dello stato di runtime corrente.

Registrazione di Durable Task Framework

I log delle estensioni permanenti sono utili per comprendere il comportamento della logica di orchestrazione. Tuttavia, questi log non contengono sempre informazioni sufficienti per eseguire il debug di problemi di affidabilità e prestazioni a livello di framework. A partire dalla versione 2.3.0 dell'estensione Durable, per la raccolta sono disponibili anche i log generati da Durable Task Framework (DTFx) sottostante.

Quando si esaminano i log generati da DTFx, è importante comprendere che il motore DTFx è composto da due componenti: il motore di distribuzione principale (DurableTask.Core) e uno dei molti provider di archiviazione supportati (Durable Functions usa DurableTask.AzureStorage per impostazione predefinita, ma sono disponibili altre opzioni).

• DurableTask.Core: esecuzione dell'orchestrazione principale e log di pianificazione di basso livello e dati di telemetria.
• DurableTask.AzureStorage: log back-end specifici del provider di stato di Archiviazione di Azure. Questi log includono interazioni dettagliate con le code interne, i BLOB e le tabelle di archiviazione usate per archiviare e recuperare lo stato di orchestrazione interna.
• DurableTask.Netherite: log back-end specifici del provider di archiviazione Netherite, se abilitato.
• DurableTask.SqlServer: log back-end specifici del provider di archiviazione Microsoft SQL (MSSQL), se abilitato.

È possibile abilitare questi log aggiornando la sezione logging/logLevel del file dell'app per le funzioni host.json. Nell'esempio seguente viene illustrato come abilitare i log degli avvisi e degli errori da DurableTask.Core e DurableTask.AzureStorage:

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

Se Application Insights è abilitato, questi log verranno aggiunti automaticamente alla raccolta trace. È possibile cercarli nello stesso modo in cui si cercano altri log trace usando query Kusto.

La query Kusto seguente illustra come eseguire query per i log DTFx. La parte più importante della query è where customerDimensions.Category startswith "DurableTask" che filtra i risultati per i log nelle categorie DurableTask.Core e DurableTask.AzureStorage.

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

Il risultato è un set di log scritti dai provider di log Durable Task Framework.

Per altre informazioni sugli eventi di log disponibili, vedere la documentazione sulla registrazione strutturata di Durable Task Framework in GitHub.

Registrazione dell'app

È importante tenere presente il comportamento di riesecuzione dell'agente di orchestrazione quando si scrivono i log direttamente da una funzione dell'agente di orchestrazione. Ad esempio, si consideri la seguente funzione dell'agente di orchestrazione:

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

I dati di log risultanti appariranno simili all'output di esempio seguente:

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

Per scrivere solo i log nelle esecuzioni non di riproduzione, è possibile scrivere un'espressione condizionale per registrare solo se il flag "is replaying" è false. Si consideri l'esempio precedente, ma questa volta con i controlli di riesecuzione.

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

Con le modifiche indicate in precedenza, l'output del log è il seguente:

Calling F1.
Calling F2.
Calling F3.
Done!

Stato personalizzato

Lo stato dell'orchestrazione personalizzato consente di impostare un valore di stato per la funzione dell'agente di orchestrazione. Questo stato personalizzato è quindi visibile ai client esterni tramite l'API di query sullo stato HTTP o tramite chiamate API specifiche del linguaggio. Lo stato di un'orchestrazione personalizzato consente di eseguire il monitoraggio in modo più completo per le funzioni dell'agente di orchestrazione. Ad esempio, il codice della funzione dell'agente di orchestrazione può richiamare l'API "imposta stato personalizzato" per aggiornare lo stato di avanzamento per un'operazione a esecuzione prolungata. Un client, ad esempio una pagina Web o un sistema esterno, può eseguire una query periodicamente sulle API di query dello stato HTTP per ottenere informazioni più dettagliate. Di seguito è riportato il codice di esempio per l'impostazione di un valore di stato personalizzato in una funzione dell'agente di orchestrazione:

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

Mentre l'orchestrazione è in esecuzione, i client esterni possono recuperare questo stato personalizzato:

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

I client visualizzano la risposta seguente:

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

Traccia distribuita

La traccia distribuita monitora le richieste e mostra in che modo i diversi servizi interagiscono tra loro. In Durable Functions mette in correlazione anche le orchestrazioni e le attività insieme. Ciò è utile per comprendere il tempo necessario per l'orchestrazione rispetto all'intera orchestrazione. È anche utile comprendere dove un'applicazione presenta un problema o dove è stata generata un'eccezione. Questa funzionalità è supportata per tutti i linguaggi e i provider di archiviazione.

Configurazione della traccia distribuita

Per configurare la traccia distribuita, aggiornare il file host.json e configurare una risorsa di Application Insights.

host.json

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

Application Insights

Se l'app per le funzioni non è configurata con una risorsa di Application Insights, configurarla seguendo le istruzioni riportate qui.

Controllo delle tracce

Nella risorsa di Application Insights passare a Ricerca transazioni. Nei risultati, verificare la presenza di eventi Request e Dependency che iniziano con prefissi specifici di Durable Functions (ad esempio orchestration:, activity: e così via). Se si seleziona uno di questi eventi, verrà aperto un diagramma di Gantt che mostrerà la traccia distribuita end-to-end.

Risoluzione dei problemi

Se non vengono visualizzate le tracce in Application Insights, assicurarsi di attendere circa cinque minuti dopo l'esecuzione dell'applicazione per garantire che tutti i dati vengano propagati alla risorsa di Application Insights.

Debug

Funzioni di Azure supporta direttamente il debug del codice della funzione e lo stesso supporto si estende a Funzioni permanenti, in esecuzione in Azure o in locale. Quando si esegue il debug, è tuttavia opportuno conoscere alcuni comportamenti:

• Replay: le funzioni dell'agente di orchestrazione vengono rieseguite regolarmente alla ricezione di nuovi input. Questo comportamento implica che una singola esecuzione logica di una funzione dell'agente di orchestrazione può comportare l'accesso più volte allo stesso punto di interruzione, soprattutto se è impostata all'inizio del codice della funzione.
• Await: ogni volta che viene rilevato un oggetto await in una funzione dell'agente di orchestrazione, restituisce il controllo al dispatcher Durable Task Framework. Se è la prima volta che uno specifico await è stato rilevato, l'attività associata non viene ripresa mai. Poiché l'attività non viene ripresa mai, non è possibile eseguire lo step over per await (F10 in Visual Studio). Questa operazione funziona solo se un'attività è in corso di riesecuzione.
• Timeout di messaggistica: Durable Functions usa internamente i messaggi in coda per gestire l'esecuzione delle funzioni, di orchestrazione, attività ed entità. In un ambiente con più macchine virtuali, a causa dell'interruzione del debug per lunghi periodi di tempo è possibile che un'altra macchina virtuale prelevi il messaggio, generando un'esecuzione duplicata. Questo comportamento esiste anche per le normali funzioni attivate da coda, ma è importante sottolinearlo in questo contesto poiché le code sono un dettaglio dell'implementazione.
• Arresto e avvio: i messaggi nelle funzioni permanenti vengono mantenuti tra le sessioni di debug. Se si arresta il debug e si termina il processo host locale durante l'esecuzione di una funzione durevole, tale funzione può essere eseguita di nuovo automaticamente in una sessione di debug futura. Questo comportamento può generare confusione quando non previsto. L'uso di un nuovo hub attività o la cancellazione del contenuto dell'hub attività tra le sessioni di debug è una tecnica per evitare questo comportamento.

Storage

Per impostazione predefinita, Funzioni permanenti archivia lo stato in Archiviazione di Azure. Questo comportamento significa che è possibile esaminare lo stato delle orchestrazioni usando strumenti come Microsoft Azure Storage Explorer.

Risulta utile per il debug perché viene visualizzato esattamente lo stato in cui potrebbe trovarsi un'orchestrazione. È possibile esaminare i messaggi nelle code anche per individuare le attività in sospeso o, in alcuni casi, bloccate.

Durable Functions Monitor

Durable Functions Monitor è uno strumento grafico per il monitoraggio, la gestione e il debug di istanze di orchestrazione ed entità. È disponibile come estensione di Visual Studio Code o come app autonoma. Le informazioni sulla configurazione e un elenco di funzionalità sono disponibili in questo wiki.

Guida alla risoluzione dei problemi di Durable Functions

Per risolvere i sintomi comuni del problema, ad esempio orchestrazioni bloccate, mancata avvio, esecuzione lenta e così via, vedere questa guida alla risoluzione dei problemi.

Passaggi successivi