Troncamento timestamp: un racconto di Ruby on Rails ActiveRecord

I test dovrebbero aiutare a evitare che le app siano traballanti. Ma di tanto in tanto, i test stessi possono diventare traballanti, anche quelli più semplici. Ecco come ci siamo tuffati in un test problematico su un'app Ruby on Rails supportata da PostgreSQL e cosa abbiamo scoperto.

Volevamo verificare che una certa logica aziendale (chiamata da un metodo perform ) non modificasse un modello di calendar (un'istanza di Calendar , una classe del modello Ruby on Rails ActiveRecord), quindi abbiamo scritto:

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

Questo passava in un ambiente di sviluppo (MacOS), ma quasi sempre falliva in CI (Linux).

Fortunatamente, siamo riusciti a riprodurlo su un altro ambiente di sviluppo (Linux), dove ha fallito con un messaggio:

 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}

Vedi qualcosa di sospetto?

L'investigazione

A un esame più attento, abbiamo notato che i timestamp created_at e updated_at sono stati leggermente modificati all'interno del blocco 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}

La parte frazionaria dei secondi è stata troncata in modo che 13:36:22.459149334 diventasse 13:36:22.459149000 .

Eravamo certi che perform non stesse aggiornando l'oggetto calendar , quindi abbiamo ipotizzato che i timestamp fossero stati troncati dal database. Per testare questo, abbiamo utilizzato la tecnica di debug più avanzata conosciuta, ovvero mette il debug:

 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

Ma il troncamento non era visibile nell'output:

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

Questo è stato piuttosto sorprendente: l'accessor #created_at avrebbe dovuto avere lo stesso valore del valore hash dell'attributo degli attributes['created_at'] . Per essere sicuri di stampare lo stesso valore utilizzato nell'asserzione, abbiamo cambiato il modo in cui abbiamo eseguito l'accesso a created_at .

Invece di utilizzare l'accessor calendar.created_at.to_f , siamo passati al recupero direttamente dall'hash degli attributi: calendar.attributes['created_at'].to_f . I nostri sospetti verso calendar.reload sono stati confermati!

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

Come puoi vedere, la chiamata perform non è cambiata created_at , ma il reload lo ha fatto.

Per garantire che la modifica non avvenisse su un'altra istanza di calendar e quindi venisse salvata, abbiamo eseguito un altro esperimento. Abbiamo ricaricato il calendar prima del test:

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

Ciò ha reso il test verde.

La correzione

Sapendo che è il database che tronca i nostri timestamp e non supera i nostri test, abbiamo deciso di evitare che si verificasse il troncamento. Abbiamo generato un oggetto DateTime e lo abbiamo arrotondato a secondi interi. Quindi, abbiamo utilizzato questo oggetto per impostare esplicitamente i timestamp di Active Record di Rails. Questa modifica ha corretto e stabilizzato i test:

 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

La causa

Perché è successo? I timestamp di Active Record sono impostati dal modulo ActiveRecord::Timestamp di Rails utilizzando Time.now . La precisione del Time dipende dal sistema operativo e, come lo stato dei documenti, può includere frazioni di secondi .

Abbiamo testato la risoluzione di Time.now su MacOS e Linux con uno script che conta le frequenze delle lunghezze delle parti frazionarie:

 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}

Come puoi vedere, circa il 70% dei timestamp su Linux aveva sette cifre di precisione dopo il decimale, mentre su MacOS solo il 25%. Questo è il motivo per cui i test hanno superato la maggior parte delle volte su MacOS e la maggior parte delle volte hanno fallito su Linux. Potresti aver notato che l'output del test aveva una precisione di nove cifre, perché RSpec usa Time#nsec per formattare l'output dell'ora.

Quando i modelli Rails vengono salvati nel database, tutti i timestamp che hanno vengono archiviati utilizzando un tipo in PostgreSQL chiamato timestamp without time zone , che ha una risoluzione di microsecondi, ovvero sei cifre dopo il decimale. Quindi, quando 1577987974.6472975 viene inviato a PostgreSQL, tronca l'ultima cifra della parte frazionaria e salva invece 1577987974.647297 .

Le domande

C'è ancora la domanda sul perché calendar.created_at non è stato ricaricato quando abbiamo chiamato calendar.reload , anche se calendar.attributes['created_at'] è stato ricaricato.

Inoltre, i risultati del test di precisione del Time sono un po' sorprendenti. Ci aspettavamo che su MacOS la precisione massima fosse sei. Non sappiamo perché a volte ha sette cifre. Quello che ci ha sorpreso di più è stata la distribuzione del valore delle ultime cifre:

 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}

Come puoi vedere, la settima cifra su MacOS è sempre 1, 2, 8 o 9.

Se conosci la risposta a una di queste domande, condividi una spiegazione con noi.

Il futuro

Il fatto che i timestamp di Active Record di Ruby on Rails siano generati sul lato dell'applicazione può anche danneggiare quando quei timestamp vengono utilizzati per l'ordinamento affidabile e preciso degli eventi salvati nel database. Poiché gli orologi del server delle applicazioni possono essere desincronizzati, gli eventi ordinati da created_at possono apparire in un ordine diverso da quello in cui si sono verificati realmente. Per ottenere un comportamento più affidabile, sarebbe meglio lasciare che il server del database gestisca i timestamp (ad esempio PostgreSQL's now() ).

Questa, tuttavia, è una storia che vale un altro articolo.

Un ringraziamento speciale a Gabriele Renzi per aver contribuito a creare questo articolo.