The pipeline runtime it's negative.

[beatrizaantunes]

Mandatory informations:

There are customers are directly impacted by this bug? Which?

Directly, no.

Bug Category

• [ ] Connection Manager
• [ ] Connection Test
• [ ] Creating Pipeline
• [x] Executing Pipeline
• [ ] Cataloging Data Asset
• [ ] Other

Describe the bug

The pipeline runtime it's negative. That is, the time that its execution ends is earlier than its creation time.

Pipelines

https://app.dadosfera.ai/en-US/collect/pipelines/91d0d9a2-1326-4f91-9e20-65bb70d9fcdb https://app.dadosfera.ai/en-US/collect/pipelines/36c8bd30-0485-4983-88e4-828cf1acb135

---

This bug impact any demo or a sales?

No

Dadosfera Customer:

Dadosfera, PRD

[beatrizaantunes]

@andersonmfjr already identified what is happening. Can you describe this here, please man?

[andersonmfjr]

The updated_at field (of pipeline run status endpoint) has a date smaller than the created_at field.

[rafaelsantanaep]

@andersonmfjr any further details on this issue? We cannot replicate this on the Platform's side even by running the same pipeline that had the field update_at greater than the created_at.

Currently, the created_at and updated_at fields are managed by SQLAlchemy as seen in the picture below:

class PipelineRun(Base):
    __tablename__ = "pipeline_run"

    id = Column(Integer, primary_key=True, autoincrement=True)
    pipeline_run_id = Column(String, unique=True)
    pipeline_id_fk = ForeignKey('pipeline.pipeline_id', ondelete="cascade", onupdate="cascade")
    pipeline_id = Column(String, pipeline_id_fk, nullable=False)
    last_status = Column(String)
    created_at = Column(TIMESTAMP(timezone=True), server_default=func.now())
    updated_at = Column(TIMESTAMP(timezone=True), server_default=func.now(), onupdate=func.now())
    trace = Column(Text, nullable=True)

    def __repr__(self):
        return f"PipelineRun(id={self.id}, \
               pipeline_run_id={self.pipeline_run_id}, \
               pipeline_id={self.pipeline_id}, \
               last_status={self.last_status}, \
               created_at={self.created_at}, \
               updated_at={self.updated_at}, \
               trace={self.trace}"

[andersonmfjr]

Weird... If you open the links that Beatriz sent, and look at the requests, you'll see the following:

In the first run, the created_at became smaller than the updated_at. In others runs it normalized.

[samirleao]

Depois de algumas investigações chegamos à conclusão de que provavelmente está ocorrendo algum problema com a função now() do postgres. Possivelmente questão de cache. Toda vez que a pipeline_run é atualizada o novo valor de updated_at é renderizado em tempo de query usando a própria função now() do Postgres. Verifiquei este comportamento estranho fazendo um SELECT now() no banco de produção, onde ele mostrou uma timestamp errada e a manteve assim por algum tempo.

Infelizmente não consegui reproduzir o problema, que parece ser esporádico, aleatório. Fiz um código de simulação para criar, simular execução de pipeline e atualizar vários pipeline_runs, mas mesmo assim não consegui reproduzir. Foram encontrados 9 casos em PRD, dos quais o mais antigo data de 05/12/2022 com a pipeline df2b11e7_c49f_45a0_bb3c_1f49108b33d5.

Tentarei uma abordagem de tirar a função do postgres em tempo de query para o updated_at e passarei a usar uma função dentro do próprio código python. Isso provavelmente deverá resolver o problema. Já que não conseguimos reproduzir o problema com simulação, irei aplicar essa modificação e observar as próximas pipeline_runs. O caso mais recente ocorreu no dia 20/12/2022.

Abaixo temos todos os casos até o momento:

Abaixo temos a anomalia quando executei o SELECT now() e o banco me trouxe um valor de timestamp completamente estranho (observe a hora do relógio e lembre também que o postgres está exibindo horários em outra timezone). O campo dos minutos nessa timestamp que o banco trouxe está completamente errado.

[samirleao]

PR com a possível correção: https://github.com/dadosfera/platform-api/pull/266

Foi modificada forma como é calculado tanto o campo de created_at quanto de updated_at das pipeline_runs. Nos testes realizados em beta as timestamps agora batem 100% com as timestamps das tasks do Airflow, diferente do método anterior onde ocorriam diferenças no created_at e no updated_at. Agora não é mais usada a função now() do banco de dados e sim uma função datetime do próprio Python.

[samirleao]

Já está lançado em PRD e irei continuar monitorando as pipeline_runs no banco. Até o presente momento o caso não ocorreu novamente. Para as pipeline_runs que estão com o updated_at menor do que o created_at, elas continuarão assim.

[beatrizaantunes]

Parece que não ocorreu novamente mesmo não.