Diagnostics in Durable Functions in Azure (Diagnósticos no Durable Functions no Azure)

Existem várias opções para diagnosticar problemas com funções duráveis. Algumas destas opções são iguais às das funções normais e outras são exclusivas do Durable Functions.

Application Insights

O Application Insights é a maneira recomendada de fazer diagnósticos e monitoramento no Azure Functions. O mesmo se aplica às funções duráveis. Para obter uma visão geral de como aproveitar o Application Insights em seu aplicativo de função, consulte Monitorar o Azure Functions.

A Extensão Durável do Azure Functions também emite eventos de controle que permitem rastrear a execução de ponta a ponta de uma orquestração. Esses eventos de acompanhamento podem ser encontrados e consultados usando a ferramenta Application Insights Analytics no portal do Azure.

Dados de rastreamento

Cada evento do ciclo de vida de uma instância de orquestração faz com que um evento de rastreamento seja gravado na coleção de rastreamentos no Application Insights. Este evento contém uma carga customDimensions com vários campos. Os nomes dos campos são todos precedidos de prop__.

• hubName: O nome do hub de tarefas no qual suas orquestrações estão sendo executadas.
• appName: O nome do aplicativo de função. Esse campo é útil quando você tem vários aplicativos funcionais compartilhando a mesma instância do Application Insights.
• slotName: O slot de implantação no qual o aplicativo de função atual está sendo executado. Este campo é útil quando você usa slots de implantação para fazer a versão de suas orquestrações.
• functionName: O nome do orquestrador ou função de atividade.
• functionType: O tipo da função, como Orchestrator ou Activity.
• instanceId: A ID exclusiva da instância de orquestração.
• state: O estado de execução do ciclo de vida da instância. Os valores válidos incluem:
  • Agendado: A função estava programada para execução, mas ainda não começou a ser executada.
  • Iniciado: A função começou a ser executada, mas ainda não foi aguardada ou concluída.
  • Aguardado: O orquestrador agendou alguns trabalhos e aguarda a sua conclusão.
  • Audição: O orquestrador está a ouvir uma notificação de evento externo.
  • Concluído: A função foi concluída com êxito.
  • Falha: A função falhou com um erro.
• motivo: dados adicionais associados ao evento de rastreamento. Por exemplo, se uma instância estiver aguardando uma notificação de evento externo, esse campo indicará o nome do evento pelo qual está aguardando. Se uma função tiver falhado, este campo conterá os detalhes do erro.
• isReplay: valor booleano que indica se o evento de rastreamento é para execução repetida.
• extensionVersion: A versão da extensão Durable Task. As informações de versão são dados especialmente importantes ao relatar possíveis bugs na extensão. Instâncias de longa execução podem relatar várias versões se ocorrer uma atualização durante a execução.
• sequenceNumber: Número de sequência de execução de um evento. Combinado com o carimbo de data/hora ajuda a ordenar os eventos por tempo de execução. Observe que esse número será redefinido para zero se o host for reiniciado enquanto a instância estiver em execução, por isso é importante sempre classificar por carimbo de data/hora primeiro e, em seguida, sequenceNumber.

A detalhamento dos dados de rastreamento emitidos para o Application Insights pode ser configurada logger na seção (Funções 1.x) ou logging (Funções 2.0) do host.json arquivo.

Funções 1.0

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

Funções 2.0

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

Por padrão, todos os eventos de rastreamento sem repetição são emitidos. O volume de dados pode ser reduzido definindo Host.Triggers.DurableTask para "Warning" ou "Error" , nesse caso, os eventos de rastreamento só serão emitidos para situações excecionais. Para habilitar a emissão dos eventos de repetição de orquestração detalhada, defina o logReplayEvents como true no arquivo de configuração host.json .

As entradas e saídas das funções de orquestrador, atividade e entidade não são registradas por padrão. Esse comportamento padrão é recomendado porque o registro de entradas e saídas pode aumentar os custos do Application Insights. As cargas úteis de entrada e saída de função também podem conter informações confidenciais. Em vez disso, o número de bytes para entradas e saídas de função é registrado em vez das cargas úteis reais por padrão. Se desejar que a extensão Durable Functions registre todas as cargas úteis de entrada e saída, defina a traceInputsAndOutputs propriedade como true no arquivo de configuração host.json .

Consulta de instância única

A consulta a seguir mostra dados históricos de acompanhamento para uma única instância da orquestração da função Hello Sequence . Ele é escrito usando a Kusto Query Language. Ele filtra a execução de repetição para que apenas o caminho de execução lógico seja mostrado. Os eventos podem ser ordenados classificando por timestamp e sequenceNumber como mostrado na consulta abaixo:

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.

Registro em log durável da estrutura de tarefas

Os logs de extensão duráveis 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 logs emitidos pelo DTFx, é importante entender que o mecanismo DTFx é composto por dois componentes: o mecanismo de despacho principal (DurableTask.Core) e um dos muitos provedores de armazenamento suportados (Durable Functions usa DurableTask.AzureStorage por padrão, mas outras opções estão disponíveis).

• DurableTask.Core: execução de orquestração de núcleo e logs de agendamento e telemetria de baixo nível.
• DurableTask.AzureStorage: logs de back-end específicos para o provedor de estado do Armazenamento do Azure. Esses logs incluem interações detalhadas com as filas internas, blobs e tabelas de armazenamento usadas para armazenar e buscar o estado de orquestração interna.
• DurableTask.Netherite: logs de back-end específicos para o provedor de armazenamento Netherite, se habilitado.
• DurableTask.SqlServer: logs de back-end específicos para o provedor de armazenamento Microsoft SQL (MSSQL), se habilitado.

Você pode habilitar esses logs atualizando a logging/logLevel seção do arquivo de host.json do seu aplicativo de função. O exemplo a seguir mostra como habilitar logs de aviso e erro de ambos e DurableTask.Core 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. Você pode pesquisá-los da mesma forma que você procura outros trace logs usando consultas Kusto.

A consulta Kusto a seguir mostra como consultar logs DTFx. A parte mais importante da consulta é where customerDimensions.Category startswith "DurableTask" uma vez que filtra os resultados para logs nas DurableTask.Core categorias 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 obter mais informações sobre quais eventos de log estão disponíveis, consulte a documentação de log estruturado do Durable Task Framework no GitHub.

Registo de Aplicações

É importante ter em mente o comportamento de repetição do orquestrador ao escrever logs diretamente de uma função do orquestrador. Por exemplo, considere a seguinte função de orquestrador:

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

Os dados de log resultantes serão parecidos com a seguinte saída de exemplo:

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

Se você quiser gravar somente logs em execuções que não sejam de repetição, poderá escrever uma expressão condicional para registrar somente se o sinalizador "está reproduzindo" for false. Considere o exemplo acima, mas desta vez com verificações de replay.

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

Com as alterações mencionadas anteriormente, a saída do log é a seguinte:

Calling F1.
Calling F2.
Calling F3.
Done!

Estado Personalizado

O status de orquestração personalizado permite definir um valor de status personalizado para sua função de orquestrador. Esse status personalizado é então visível para clientes externos por meio da API de consulta de status HTTP ou por meio de chamadas de API específicas do idioma. O status de orquestração personalizado permite um monitoramento mais rico para as funções do orquestrador. Por exemplo, o código da função orchestrator pode invocar a API "set custom status" para atualizar o progresso de uma operação de longa duração. Um cliente, como uma página da Web ou outro sistema externo, pode consultar periodicamente as APIs de consulta de status HTTP para obter informações de progresso mais avançadas. O código de exemplo para definir um valor de status personalizado em uma função orchestrator é fornecido abaixo:

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

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 receberão 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"
}

Rastreamento distribuído

O Rastreamento Distribuído rastreia solicitações e mostra como diferentes serviços interagem entre si. Em Funções Duráveis, também correlaciona orquestrações e atividades juntas. Isso é útil para entender quanto tempo as etapas da orquestração levam em relação a toda a orquestração. Também é útil entender onde um aplicativo está tendo um problema ou onde uma exceção foi lançada. Esse recurso é compatível com todos os idiomas e provedores de armazenamento.

Configurando o rastreamento distribuído

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

host.json

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

Application Insights

Se o aplicativo Function não estiver configurado com um recurso do Application Insights, configure-o seguindo as instruções aqui.

Inspecionar os vestígios

No recurso Application Insights, navegue até Pesquisa de transações. Nos resultados, verifique Request se há eventos que Dependency começam com prefixos específicos de Funções Duráveis (por exemplo orchestration:, , activity:etc.). A seleção de um desses eventos abrirá um gráfico de Gantt que mostrará o rastreamento distribuído de ponta a ponta.

Resolução de Problemas

Se você não vir os rastreamentos no Application Insights, aguarde cerca de cinco minutos após a execução do aplicativo para garantir que todos os dados sejam propagados para o recurso do Application Insights.

Depuração

O Azure Functions dá suporte ao código de função de depuração diretamente, e esse mesmo suporte é transferido para Funções Duráveis, seja em execução no Azure ou localmente. No entanto, existem alguns comportamentos a ter em conta ao depurar:

• Replay: As funções do Orchestrator são repetidas regularmente quando novas entradas são recebidas. Esse comportamento significa que uma única execução lógica de uma função orquestradora pode resultar em atingir o mesmo ponto de interrupção várias vezes, especialmente se ela for definida no início do código da função.
• Aguardar: Sempre que um await é encontrado em uma função de orquestrador, ele devolve o controle ao dispatcher do Durable Task Framework. Se for a primeira vez que um particular await é encontrado, a tarefa associada nunca é retomada. Como a tarefa nunca é retomada, passar por cima da espera (F10 no Visual Studio) não é possível. Passar por cima só funciona quando uma tarefa está sendo repetida.
• Tempos limite de mensagens: o Durable Functions usa internamente mensagens de fila para impulsionar a execução de funções de orquestrador, atividade e entidade. Em um ambiente multi-VM, invadir a depuração por longos períodos de tempo pode fazer com que outra VM pegue a mensagem, resultando em execução duplicada. Esse comportamento também existe para funções regulares de gatilho de fila, mas é importante ressaltar nesse contexto, já que as filas são um detalhe de implementação.
• Parando e iniciando: as mensagens nas funções duráveis persistem entre as sessões de depuração. Se você parar de depurar e encerrar o processo de host local enquanto uma função durável estiver em execução, essa função poderá ser reexecutada automaticamente em uma sessão de depuração futura. Esse comportamento pode ser confuso quando não esperado. Usar um novo hub de tarefas ou limpar o conteúdo do hub de tarefas entre sessões de depuração é uma técnica para evitar esse comportamento.

Armazenamento

Por padrão, as Funções Duráveis armazenam o estado no Armazenamento do Azure. Esse comportamento significa que você pode inspecionar o estado de suas orquestrações usando ferramentas como o Gerenciador de Armazenamento do Microsoft Azure.

Isso é útil para depuração porque você vê exatamente em que estado uma orquestração pode estar. As mensagens nas filas também podem ser examinadas para saber qual trabalho está pendente (ou preso em alguns casos).

Monitor de funções duráveis

O Durable Functions Monitor é uma ferramenta gráfica para monitorar, gerenciar e depurar instâncias de orquestração e entidade. Ele está disponível como uma extensão do Visual Studio Code ou um aplicativo autônomo. Informações sobre configuração e uma lista de recursos podem ser encontradas neste Wiki.

Guia de solução de problemas do Durable Functions

Para solucionar problemas comuns, como orquestrações bloqueadas, falha ao iniciar, execução lenta, etc., consulte este guia de solução de problemas.

Próximos passos