Encontramos um bug referente à Observabilidade do Smartlink. Segue mensagem enviada pelo Jamir em 04/07:

Boa tarde, pessoal.

Estou analisando um caso estranho que aconteceu com três batches

28178b60c65843018775bab27dce293a-protheus-1720025407
28178b60c65843018775bab27dce293a-protheus-1720022044
28178b60c65843018775bab27dce293a-protheus-1719951056

Nesses batches tivemos erros no calculo na hora de comparar a quantidade de dados gerados vs enviados.
Em outras palavras, comparar o valores de um do CarolPipelineExecutionSummary vs CarolDataModelSubscriptionSent.

Vou citar um exemplo do caso mais extremo que ocorreu no batchId 28178b60c65843018775bab27dce293a-protheus-1720022044 na DataModel contasreceberrealizado:

Para essa DataModel recebemos no evento CarolPipelineExecutionSummary os valores GoldenRecordCount=0, RejectedRecordCout=0, GoldenRecordVersionCount=0, RejectedRecordVersionCount=0
Porem a contagem pelo CarolDataModelSubscriptionSent temos GoldenRecordCount=468, RejectedRecordCout=0, GoldenRecordVersionCount=960, RejectedRecordVersionCount=0.

Recebemos os dados dessa DataModel na subscription 06a697e2832948ca976048d27db19ee0. Para o caso acime recebemos duas mensagens de ids 11652777048946071 e 11652930090393872 nas datas 03/07/2024 14:48:19 e 03/07/2024 16:06:44

Isso tem haver com aquela questão de um batch provocar um pipeline a rodar e ele gerar registros de um batch que já havia finalizado? se sim, como é possível que batch finalizou gerando zero registro começar e gerar registros nesse caso?

anotações iniciais da análise - desatualizadas

Durante a pré-análise com o @Renan Fernando Schroeder e o @Reinaldo Oliveira Machado Junior identificamos os seguintes problemas:

1. Dados foram salvos na batch_process_record_audit (BigQuery) depois que o evento de observabilidade CarolPipelinesExecutionSummary já tinha sido enviado ao Smartlink.
2. O batch 28178b60c65843018775bab27dce293a-protheus-1720022044 recebeu cerca de 20.886 registros nas tabelas ct1, ctt, sa1, sa6, se1 e sed do connector protheus_carol entre às 2024-07-03 15:52:51.552 e 2024-07-03 16:44:34.503.
3. A task 5926528c6bc044bf9b22978b03173e73 executou às 2024-07-03 17:00:14.471 e, segundo o task logs, não considerou haver novos dados para serem processados.
4. A query de consolidação do Summary no BigQuery foi executada pelo job os-c7bb4f4281994987b68979f0f4a5946e-imp às 17:40 (UTC).
5. Porém o primeiro registro para o Data Model contasreceberrealizado foi salvo as 17:48 (UTC) na tabela batch_process_record_audit.

Reconstrução dos eventos - linha do tempo

Query

select
    min(created),
    max(created),
    batch_id,
    event_type
from observability_event
where created between '2024-07-03' and '2024-07-04'
    and (batch_id = '28178b60c65843018775bab27dce293a-protheus-1720025407'
             or  batch_id = '28178b60c65843018775bab27dce293a-protheus-1720022044')
    and (event_type != 'CarolIntakeReceived'
              or payload ->> 'stagingTable' in ('sev', 'sez', 'sa6', 'cto', 'se1', 'fka', 'ctt',
                                                'sa1', 'ct1', 'protheus_sharing', 'fk1', 'fk7', 
                                                'sed', 'fk5', 'sx5'))
     and (event_type not in ('CarolPipelineExecuted', 'CarolDataModelSubscriptionSent')
          or payload ->> 'dataModelName' = 'contasreceberrealizado')
group by batch_id, event_type
order by min(created) asc

+--------------------------+--------------------------+----------------------------------------------------+------------------------------+
|min                       |max                       |batch_id                                            |event_type                    |
+--------------------------+--------------------------+----------------------------------------------------+------------------------------+
|2024-07-03 15:52:51.552174|2024-07-03 16:44:34.503449|28178b60c65843018775bab27dce293a-protheus-1720022044|CarolIntakeReceived           |
|2024-07-03 16:48:30.091368|2024-07-03 16:48:30.091368|28178b60c65843018775bab27dce293a-protheus-1720022044|CarolSummaryValidated         |
|2024-07-03 16:59:01.126389|2024-07-03 17:26:47.441486|28178b60c65843018775bab27dce293a-protheus-1720025407|CarolIntakeReceived           |
|2024-07-03 17:08:49.522855|2024-07-03 17:08:49.522855|28178b60c65843018775bab27dce293a-protheus-1720022044|CarolPipelineExecuted         |
|2024-07-03 17:35:00.099756|2024-07-03 17:35:00.099756|28178b60c65843018775bab27dce293a-protheus-1720025407|CarolSummaryValidated         |
|2024-07-03 17:48:16.695519|2024-07-03 17:48:16.695519|28178b60c65843018775bab27dce293a-protheus-1720025407|CarolPipelineExecuted         |
|2024-07-03 17:48:19.157569|2024-07-03 19:06:44.842536|28178b60c65843018775bab27dce293a-protheus-1720022044|CarolDataModelSubscriptionSent|
|2024-07-03 17:51:09.292695|2024-07-03 17:51:09.292695|28178b60c65843018775bab27dce293a-protheus-1720022044|CarolPipelinesExecutionSummary|
|2024-07-03 18:31:10.095359|2024-07-03 18:31:10.095359|28178b60c65843018775bab27dce293a-protheus-1720025407|CarolPipelinesExecutionSummary|
+--------------------------+--------------------------+----------------------------------------------------+------------------------------+

• 15:52 - recebido primeiro intake do batch 28178b60c65843018775bab27dce293a-protheus-1720022044;
• 16:44 - recebido último intake do batch 28178b60c65843018775bab27dce293a-protheus-1720022044 que é usado na pipeline do datamodel contasreceberrealizado;
• 16:47 - recebido último intake do batch 28178b60c65843018775bab27dce293a-protheus-1720022044 (outros stagings), totalizando 205 intakes com 68.943 staging records ao todo;
• 16:48 - recebido summary do batch 28178b60c65843018775bab27dce293a-protheus-1720022044
• 16:59 - recebido primeiro intake do batch 28178b60c65843018775bab27dce293a-protheus-1720025407;
• 17:08 - executada a pipeline de processamento para o datamodel contasreceberrealizado, referindo ao batch 28178b60c65843018775bab27dce293a-protheus-1720022044
  • task id 5926528c6bc044bf9b22978b03173e73
  • gerou 0 golden records
  • não disparou nenhuma subscription;
• 17:26 - recebido último intake do batch 28178b60c65843018775bab27dce293a-protheus-1720025407;
• 17:35 - recebido summary do batch 28178b60c65843018775bab27dce293a-protheus-1720025407;
• 17:48 - executada a pipeline de processamento para o datamodel contasreceberrealizado, referindo ao batch 28178b60c65843018775bab27dce293a-protheus-1720025407;
  • task id 4f0befb3177a4f3f8e9eb151046b63ff
  • gerou 480 golden records para o batch anterior 28178b60c65843018775bab27dce293a-protheus-1720022044, além dos golden records do barch 28178b60c65843018775bab27dce293a-protheus-1720025407;
• 17:48 - enviadas as subscriptions referentes ao último processamento executado, para ambos os batches;
• 17:51 - enviado o execution summary do batch 28178b60c65843018775bab27dce293a-protheus-1720022044
  • contagem de 0 golden records para o datamodel contasreceberrealizado;
• 18:31 - enviado o execution summary do batch 28178b60c65843018775bab27dce293a-protheus-1720025407
  • contagem de 0 golden records para o datamodel contasreceberrealizado;

mdmData das tasks

task 5926528c6bc044bf9b22978b03173e73 {
  saveCds: false,
  clearCds: false,
  tenantId: '2c6cfec783354114b7b188f36b787638',
  copyJobId: '',
  deltaMillis: 0,
  carolAppName: 'gesplanappefficiency',
  pipelineName: 'contasreceberrealizado',
  processJobId: 'ddd943d2-c848-4f08-aee2-656312a7aed2',
  saveBigQuery: true,
  sendRealtime: false,
  clearBigQuery: false,
  clearRealtime: false,
  hasBatchReady: true,
  processAllData: false,
  ScheduledTaskId: '650ccc880bfd466ae32806b841c978e5',
  mdmLastTaskTime: 1720021863428,
  pipelineCommitId: '1817c9f4cb91a86878e93b666a0360c5b1855763',
  processedRecords: 0,
  pipelineTriggered: false,
  entityTemplateName: 'contasreceberrealizado',
  overlapDeltaMillis: 3600000,
  sendToSubscriptions: true,
  checkExistsDataToProcess: false,
  tempTableRetentionPeriod: null
}

task 4f0befb3177a4f3f8e9eb151046b63ff {
  saveCds: false,
  clearCds: false,
  tenantId: '2c6cfec783354114b7b188f36b787638',
  copyJobId: '',
  deltaMillis: 0,
  carolAppName: 'gesplanappefficiency',
  pipelineName: 'contasreceberrealizado',
  processJobId: '66011483-1a24-4c71-9a1c-7848cc83d46f',
  saveBigQuery: true,
  sendRealtime: false,
  clearBigQuery: false,
  clearRealtime: false,
  hasBatchReady: true,
  isDataflowJob: false,
  createdRecords: 480,
  processAllData: false,
  ScheduledTaskId: '650ccc880bfd466ae32806b841c978e5',
  mdmLastTaskTime: 1720025464112,
  pipelineCommitId: '1817c9f4cb91a86878e93b666a0360c5b1855763',
  processedRecords: '480',
  pipelineTriggered: true,
  entityTemplateName: 'contasreceberrealizado',
  overlapDeltaMillis: 3600000,
  temporaryTableName: 'tt_temp_task_contasreceberrealizado_2024-07-03_4f0befb3177a4f3f8e9eb151046b63ff',
  customerTenantsSize: 0,
  sendToSubscriptions: true,
  processedSizeInBytes: '297136.0',
  pipelineEligibleToRun: true,
  checkExistsDataToProcess: false,
  tempTableRetentionPeriod: null
}

Resumo da timeline

1. O batch 28178b60c65843018775bab27dce293a-protheus-1720022044 chegou antes do 28178b60c65843018775bab27dce293a-protheus-1720025407 e foi processado gerando zero golden records;
2. Não enviou notificação de subscriptions para o batch 28178b60c65843018775bab27dce293a-protheus-1720022044 já que não houve golden records;
3. Não foi enviado um execution summary neste momento;
4. Posteriormente o 28178b60c65843018775bab27dce293a-protheus-1720025407 chegou e foi processado, porém gerou golden recrods para o batch A além dos seus próprios;
5. As respectivas notificações de subscription (do último processamento) foram enviadas para ambos os batches;
6. Por fim dois execution summaries foram enviados (um para cada batch), porém com a contagem zerada para o datamodel contasreceberrealizado;

Conclusões

BE

Precisamos entender:

1. Por que o execution summary do batch 28178b60c65843018775bab27dce293a-protheus-1720022044 não foi enviado logo após o primeiro processamento, mas foi enviado depois do segundo processamento;
2. Por que os execution summaries enviados estão ambos com a contagem de golden records do datamodel contasreceberrealizado zerada.

Resolvido:

1 - apenas demorou para enviar, está ok

2 - enviou o summary com base no segundo lote, que foi zerado mesmo, ajuste já está mapeado neste PR

DE

Precisamos validar o seguinte cenário:

Se pipeline SQL do cliente está de tal forma que os dados de um batch A podem podem alterar o resultado do processamento os dados de um batch B, de tal forma que, quando apenas o batch A estiver disponível para processamento, um número X de registros (golden) é gerado, enquanto que, quando o batch B está presente, um número diferente Y de registros é gerado, que seja maior que a soma dos resultados dos processamentos individuais de A e B.

Exemplo: processamento dos dados de um primeiro batch A não gera nenhum golden record. Num segundo momento, com os dados de ambos os batches A e B, são gerados golden records para o batch A. Ou seja, o segundo batch influencia os resultados do primeiro.

Se esta afirmação for verdadeira para a query do cliente, então entendemos que o sistema se comportou corretamente. Porém devemos revisitar alguns cálculos que eles estão fazendo para contagem e retomarmos o tema do card

CAPL-6101: [Observabilidade] As contagens não estão batendo entre o CarolPipelinesExecut...Done

Caso não for verdadeira, implica uma de duas possibilidades:

1. Processamento do primeiro batch 28178b60c65843018775bab27dce293a-protheus-1720022044 deveria ter produzido golden records mas produziu zero, e então foram produzidos corretamente apenas nos demais processamentos (em anexo, planilha que mostra que os dados do batch com final 44 só foram gerados por tasks de outros batches)
2. Processamento dos demais batches, em tese, não deveria ter produzido golden records para o primeiro (final 44), mas produziu (bug)?