Truncamento de carimbo de data/hora: um conto do ActiveRecord do Ruby on Rails

Os testes devem ajudar a evitar que os aplicativos sejam esquisitos. Mas, de vez em quando, os próprios testes podem se tornar esquisitos – mesmo os mais diretos. Veja como mergulhamos em um teste problemático em um aplicativo Ruby on Rails apoiado pelo PostgreSQL e o que descobrimos.

Queríamos verificar se certa lógica de negócios (chamada por um método perform ) não altera um modelo de calendar (uma instância de Calendar , uma classe de modelo ActiveRecord do Ruby on Rails), então escrevemos:

 let(:calendar) { create(:calendar) } specify do expect do perform # call the business action calendar.reload end .not_to change(calendar, :attributes) end

Isso estava passando em um ambiente de desenvolvimento (MacOS), mas quase sempre falhava no CI (Linux).

Felizmente, conseguimos reproduzi-lo em outro ambiente de desenvolvimento (Linux), onde falhou com uma mensagem:

 expected `Calendar#attributes` not to have changed, but did change from {"calendar_auth_id"=>8, "created_at"=>2020-01-02 13:36:22.459149334 +0000, "enabled"=>false, "events_...t_sync_token"=>nil, "title"=>nil, "updated_at"=>2020-01-02 13:36:22.459149334 +0000, "user_id"=>100} to { "calendar_auth_id"=>8, "created_at"=>2020-01-02 13:36:22.459149000 +0000, "enabled"=>false, "events_...t_sync_token"=>nil, "title"=>nil, "updated_at"=>2020-01-02 13:36:22.459149000 +0000, "user_id"=>100}

Vê algo suspeito?

A investigação

Em um exame mais detalhado, notamos que os timestamps created_at e updated_at foram ligeiramente alterados dentro do bloco expect :

 {"created_at"=>2020-01-02 13:36:22.459149334 +0000, "updated_at"=>2020-01-02 13:36:22.459149334 +0000} {"created_at"=>2020-01-02 13:36:22.459149000 +0000, "updated_at"=>2020-01-02 13:36:22.459149000 +0000}

A parte fracionária dos segundos foi truncada para que 13:36:22.459149334 se tornasse 13:36:22.459149000 .

Estávamos confiantes de que perform não estava atualizando o objeto calendar , então formamos uma hipótese de que os timestamps estavam sendo truncados pelo banco de dados. Para testar isso, usamos a técnica de depuração mais avançada conhecida, ou seja, puts debugging:

 let(:calendar) { create(:calendar) } specify do expect do puts "before perform: #{calendar.created_at.to_f}" perform puts "after perform: #{calendar.created_at.to_f}" calendar.reload puts "after reload: #{calendar.created_at.to_f}" end .not_to change(calendar, :attributes) end

Mas o truncamento não era visível na saída:

 before perform: 1577983568.550754 after perform: 1577983568.550754 after reload: 1577983568.550754

Isso foi bastante surpreendente - o acessador #created_at deveria ter o mesmo valor que o valor de hash do atributo de attributes['created_at'] . Para ter certeza de que estávamos imprimindo o mesmo valor usado na asserção, alteramos a maneira como created_at .

Em vez de usar o acessador calendar.created_at.to_f , mudamos para buscá-lo diretamente do hash de atributos: calendar.attributes['created_at'].to_f . Nossas suspeitas em relação ao calendar.reload foram confirmadas!

 before perform: 1577985089.0547702 after perform: 1577985089.0547702 after reload: 1577985089.05477

Como você pode ver, chamar perform não mudou created_at , mas reload sim.

Para garantir que a alteração não estivesse acontecendo em outra instância da calendar e fosse salva, realizamos mais uma experiência. Recarregamos o calendar antes do teste:

 let(:calendar) { create(:calendar).reload } specify do expect do perform calendar.reload end .not_to change(calendar, :attributes) end

Isso tornou o teste verde.

O conserto

Sabendo que é o banco de dados que trunca nossos timestamps e falha em nossos testes, decidimos evitar que o truncamento acontecesse. Geramos um objeto DateTime e o arredondamos para segundos inteiros. Então, usamos este objeto para definir explicitamente os timestamps do Active Record do Rails. Essa mudança corrigiu e estabilizou os testes:

 let(:time) { 1.day.ago.round } let(:calendar) { create(:calendar, created_at: time, updated_at: time) } specify do expect do perform calendar.reload end .not_to change(calendar, :attributes) end

A causa

Por quê isso aconteceu? Os timestamps do Active Record são definidos pelo módulo ActiveRecord::Timestamp do Rails usando Time.now . A precisão do Time depende do sistema operacional e, conforme o estado dos documentos, pode incluir segundos fracionários .

Testamos a resolução Time.now no MacOS e Linux com um script que conta as frequências de comprimentos fracionários:

 pry> 10000.times.map { Time.now.to_f.to_s.match(/\.(\d+)/)[1].size }.group_by{|a| a}.map{|k, v| [k, v.count]}.to_h # MacOS => {6=>6581, 7=>2682, 5=>662, 4=>67, 3=>7, 2=>1} # Linux => {6=>2399, 7=>7300, 5=>266, 4=>32, 3=>3}

Como você pode ver, cerca de 70% dos timestamps no Linux tinham sete dígitos de precisão após o decimal, enquanto no MacOS apenas 25% tinham. Esta é a razão pela qual os testes passaram na maioria das vezes no MacOS e falharam na maioria das vezes no Linux. Você deve ter notado que a saída de teste tinha precisão de nove dígitos — isso porque RSpec usa Time#nsec para formatar a saída de hora.

Quando os modelos Rails são salvos no banco de dados, todos os timestamps que eles possuem são armazenados usando um tipo no PostgreSQL chamado timestamp without time zone , que tem resolução de microssegundos—ou seja, seis dígitos após o decimal. Assim, quando 1577987974.6472975 é enviado ao PostgreSQL, ele trunca o último dígito da parte fracionária e salva 1577987974.647297 .

As questões

Ainda há a questão de por que calendar.created_at não foi recarregado quando chamamos calendar.reload , mesmo que calendar.attributes['created_at'] tenha sido recarregado.

Além disso, os resultados do teste de precisão de Time são um pouco surpreendentes. Esperávamos que no MacOS, a precisão máxima fosse seis. Não sabemos por que às vezes tem sete dígitos. O que mais nos surpreendeu foi a distribuição do valor dos últimos dígitos:

 pry> 10000.times.map { Time.now}.map{|t| t.to_f.to_s.match(/\.(\d+)/)[1] }.select{|s| s.size == 7}.group_by{|e| e[-1]}.map{|k, v| [k, v.size]}.to_h # MacOS => {"9"=>536, "1"=>555, "2"=>778, "8"=>807} # Linux => {"5"=>981, "1"=>311, "3"=>1039, "9"=>309, "8"=>989, "6"=>1031, "2"=>979, "7"=>966, "4"=>978}

Como você pode ver, o sétimo dígito no MacOS é sempre 1, 2, 8 ou 9.

Se você souber a resposta para qualquer uma dessas perguntas, compartilhe uma explicação conosco.

O futuro

O fato de os timestamps do Active Record do Ruby on Rails serem gerados no lado do aplicativo também pode prejudicar quando esses timestamps são usados ​​para ordenação confiável e precisa de eventos salvos no banco de dados. Como os relógios do servidor de aplicativos podem ser dessincronizados, os eventos ordenados por created_at podem aparecer em uma ordem diferente da que realmente ocorreram. Para obter um comportamento mais confiável, seria melhor deixar o servidor de banco de dados lidar com timestamps (por exemplo, now() do PostgreSQL).

Isso, no entanto, é uma história que vale outro artigo.

Agradecimentos especiais a Gabriele Renzi por ajudar a criar este artigo.