Diagnosticar e resolver problemas em Funções Duráveis

O Durable Functions fornece várias ferramentas de diagnóstico para resolução de problemas em orquestrações. Este artigo aborda como configurar o rastreamento e o registo de eventos, escrever código seguro para reexecução, inspecionar rastreamentos distribuídos e depurar localmente.

Neste artigo, você aprenderá a:

Configurar o rastreio do Application Insights

Application Insights é a forma recomendada de monitorizar Funções Duradouras. A extensão Durable emite eventos de rastreio que permitem rastrear a execução de ponta a ponta de uma orquestração. Pode encontrar e consultar estes eventos de rastreio usando a ferramenta Application Insights Analytics no portal Azure.

Configuração do nível de log

Configure a verbosidade dos dados de rastreio emitidos para o Application Insights no seu ficheiro host.json.

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

Por padrão, todos os eventos de rastreamento sem repetição são emitidos. Pode reduzir o volume de dados definindo Host.Triggers.DurableTask para "Warning" ou "Error", o que significa que os eventos de rastreio são emitidos apenas para situações excecionais. Para permitir a emissão dos eventos de repetição detalhados de orquestração, defina logReplayEvents como true no ficheiro de configuração host.json.

Registo de entrada e saída

Por defeito, as entradas e saídas do orquestrador, atividade e entidade não são registadas. Esta abordagem é recomendada porque registar entradas e saídas pode aumentar os custos do Application Insights. Os conteúdos de entrada e saída de função também podem conter informações confidenciais. Em vez disso, regista-se o número de bytes para entradas e saídas de funções. Se quiseres que a extensão Durable Functions registre todas as cargas úteis de entrada e saída, define a propriedade traceInputsAndOutputs para true no ficheiro de configuração host.json.

Consultar instâncias de orquestração

Utilize as seguintes consultas Kusto no Application Insights Analytics para inspecionar instâncias de orquestração.

Consulta de instância única

A consulta a seguir mostra dados históricos de acompanhamento para uma única instância da função de orquestração Hello Sequence. Ele filtra a execução de repetição para que apenas o caminho de execução lógica seja mostrado. Pode ordenar os eventos ordenando por timestamp e sequenceNumber conforme mostrado na seguinte consulta:

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

O resultado é uma lista de eventos de rastreamento que mostra o caminho de execução da orquestração, incluindo quaisquer funções de atividade ordenadas pelo tempo de execução em ordem crescente.

Consulta de resumo da instância

A consulta a seguir exibe o status de todas as instâncias de orquestração que foram executadas em um intervalo de tempo especificado.

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

O resultado é uma lista de IDs de instância e seu status de tempo de execução atual.

Referência de dados de rastreio

Cada instância de orquestração gera eventos de rastreamento à medida que avança no seu ciclo de vida. Cada evento do ciclo de vida contém uma carga útil customDimensions com vários campos. Os nomes dos campos são todos precedidos de prop__.

Registo do Quadro de Tarefas Duráveis (DTFx)

Os logs da extensão Durable são úteis para entender o comportamento da lógica de orquestração. No entanto, esses logs nem sempre contêm informações suficientes para depurar problemas de desempenho e confiabilidade no nível da estrutura. A partir da v2.3.0 da extensão Durável, os logs emitidos pelo DTFx (Durable Task Framework) subjacente também estão disponíveis para coleta.

Ao analisar os registos emitidos pelo DTFx, é importante perceber que o motor DTFx tem dois componentes: o motor central de despacho (DurableTask.Core) e um dos muitos fornecedores de armazenamento suportados.

Você pode ativar esses logs atualizando a logging/logLevel seção do ficheiro host.json da sua aplicação de funções. O exemplo a seguir mostra como ativar logs de aviso e erro de ambos DurableTask.Core e DurableTask.AzureStorage.

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

Se você tiver o Application Insights habilitado, esses logs serão adicionados automaticamente à trace coleção. Podes pesquisar neles da mesma forma que procuras outros trace registos usando consultas Kusto.

A seguinte consulta Kusto mostra como consultar os registos DTFx. A parte mais importante da consulta é where customerDimensions.Category startswith "DurableTask", uma vez que filtra os resultados para logs nas categorias 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 

O resultado é um conjunto de logs gravados pelos provedores de log do Durable Task Framework.

Para mais informações sobre que eventos de registo estão disponíveis, consulte a documentação de registo estruturado do Durable Task Framework sobre GitHub.

Rastreio distribuído

O rastreio distribuído acompanha pedidos e mostra como diferentes serviços interagem entre si. Em Durable Functions, correlaciona orquestrações, entidades e atividades entre si. O rastreamento distribuído mostra o tempo de execução para cada passo de orquestração relativamente a toda a orquestração e identifica onde ocorrem problemas ou exceções. Esse recurso é suportado no Application Insights para todos os idiomas e provedores de armazenamento.

Pré-requisitos

O rastreio distribuído requer versões mínimas específicas de extensão:

• Para .NET Isolated apps, Microsoft.Azure.Functions.Worker.Extensions.DurableTask>= v1.4.0.
• Para aplicações não .NET, siga estas instruções para instalar manualmente Microsoft.Azure. WebJobs.Extensions.DurableTask>= v3.2.0 por agora. O rastreamento distribuído estará disponível em pacotes de extensão >v4.24.x.

Configuração do rastreio distribuído

Para configurar o rastreamento distribuído, atualize o host.json e configure um recurso do Application Insights.

host.json

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

Application Insights

Configure a sua aplicação de funções com um recurso Application Insights.

Inspecionar os vestígios

No seu recurso Application Insights, navegue para Pesquisa de Transações. Nos resultados, procure por eventos Request e Dependency que comecem com prefixos específicos de Durable (por exemplo, orchestration:, activity:, etc.). Selecionar um destes eventos abre um gráfico de Gantt que mostra o traço distribuído de ponta a ponta. O gráfico mostra cada passo de orquestração como uma barra horizontal, com chamadas de atividade e suborquestração aninhadas sob a orquestração principal. O comprimento da barra representa a duração do relógio de parede de cada passo, facilitando a identificação de gargalos ou atividades inesperadamente lentas.

Registo seguro de repetição nas funções do orquestrador

As funções do orquestrador repetem-se sempre que é recebida nova entrada, o que significa que qualquer instrução log num orquestrador é executada várias vezes para uma única execução lógica. Por exemplo, uma função com três chamadas de atividade produz saída logarítmica como esta durante a reprodução:

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

Para evitar linhas de registo duplicadas, verifique o indicador "está em repetição" para garantir que os registos só sejam executados na primeira passagem, que não é de repetição. Os exemplos seguintes mostram registos seguros para replay em cada linguagem.

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

Com registo seguro para reprodução, a saída do registo é:

Calling F1.
Calling F2.
Calling F3.
Done!

Status de orquestração personalizada

Use o estado de orquestração personalizado para reportar o progresso do fluxo de trabalho a clientes externos. Padrões comuns incluem percentagens de conclusão, descrições de passos e resumos de erros. Os clientes externos podem visualizar o estado personalizado através da API de consulta HTTP de estado ou chamadas de API específicas da língua.

O código seguinte mostra como definir um valor de estado personalizado numa função de orquestrador:

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

Enquanto a orquestração está em execução, os clientes externos podem obter este status personalizado:

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

Os clientes obtêm a seguinte resposta:

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

Debugging

O Funções do Azure permite depurar o código da função diretamente, e esse mesmo suporte é aplicável às Funções Duráveis, quer estejam a ser executadas no Azure quer localmente. Utilize o seguinte fluxo de trabalho para obter a melhor experiência de depuração:

1. Inicie uma nova sessão de depuração com um novo hub de tarefas ou limpe o conteúdo do hub entre sessões. Mensagens remanescentes de execuções anteriores podem causar novas execuções inesperadas.

2. Define pontos de interrupção no teu orquestrador ou nas funções de atividade. Para funções de orquestrador, use um ponto de interrupção condicional que só se interrompa quando o valor false "está a ser reproduzido" para evitar atingir o mesmo ponto de interrupção várias vezes durante a repetição.

3. Execute o seu código passo a passo normalmente. Tenha em mente os seguintes comportamentos:

   • Repetição:
     As funções do Orchestrator reproduzem-se regularmente quando são recebidas novas entradas. Uma única execução lógica de uma função de orquestrador pode resultar em atingir o mesmo ponto de interrupção várias vezes, especialmente se for definido cedo no código da função.

   • Aguarde:
     Sempre que um await é encontrado numa função orquestradora, devolve o controlo ao despachador do Durable Task Framework. Se for a primeira vez que um determinado await é encontrado, a tarefa associada nunca é retomada. Como a tarefa nunca recomeça, passar sobre o await (F10 em Visual Studio) não é viável. Passar por cima só funciona quando uma tarefa está sendo repetida.

   • Tempos limite de mensagens:
     As Funções Duráveis usam internamente mensagens de fila para gerir a execução das funções de orquestrador, atividade e entidade. Num ambiente multi-VM, sessões prolongadas de depuração podem fazer com que outra VM processe a mensagem, resultando numa execução duplicada. Embora este comportamento também exista para funções regulares de disparo de fila, este contexto é importante de destacar porque as filas são um detalhe de implementação.

   • Parar e arrancar:
     As mensagens em Funções Duráveis persistem entre as sessões de depuração. Se interromper a depuração e encerrar o processo host local enquanto uma função durável está a ser executada, essa função pode ser reexecutada automaticamente numa futura sessão de debug.

Ferramentas adicionais

Inspecionar o estado de armazenamento

Por padrão, as Funções Duráveis armazenam o estado no Armazenamento do Azure. Pode inspecionar o estado da orquestração e as mensagens usando ferramentas como o Microsoft Explorador de Armazenamento do Azure.

Monitor de Funções Duráveis

Durable Functions Monitor é uma ferramenta gráfica para monitorizar, gerir e depurar instâncias de orquestração e entidades. Está disponível como uma extensão do Visual Studio Code ou uma aplicação autónoma. Para instruções de configuração e uma lista de funcionalidades, consulte a Wiki do Monitor Durable Functions.

Diagnósticos do portal Azure

O portal Azure fornece ferramentas de diagnóstico integradas para as suas aplicações funcionais.

Diagnosticar e resolver problemas: O Azure Function App Diagnostics é um recurso útil para monitorizar e diagnosticar potenciais problemas na sua aplicação. Também fornece sugestões para ajudar a resolver problemas com base no diagnóstico. Para mais informações, consulte Diagnósticos de Aplicações de Funções no Azure.

Registos de orquestração: O portal da Azure fornece detalhes dos registos de orquestração para o ajudar a compreender o estado de cada instância de orquestração e a rastrear a execução de ponta a ponta. Ao ver a lista de funções dentro da sua aplicação Funções do Azure, vê uma coluna Monitor com links para os registos. Precisa de ter o Application Insights ativado para a sua aplicação aceder a esta informação.

Analisador Roslyn

O Durable Functions Roslyn Analyzer é um analisador de código em tempo real que orienta os programadores de C# a seguir as restrições específicas de código do Durable Functions. Para instruções sobre como o ativar em Visual Studio e Visual Studio Code, veja Durable Functions Roslyn Analyzer.

Troubleshooting

Para resolver problemas comuns, como orquestrações que ficam presas, falhas ao iniciar ou execução lenta, consulte o guia de resolução de problemas Durable Functions.

Passos seguintes