Truncarea marcajului de timp: o poveste Ruby on Rails ActiveRecord

Testele ar trebui să ajute la prevenirea erorilor aplicațiilor. Dar, din când în când, testele în sine pot deveni scazute – chiar și cele mai simple. Iată cum ne-am aruncat într-un test problematic pe o aplicație Ruby on Rails susținută de PostgreSQL și ce am descoperit.

Am vrut să verificăm că o anumită logică de afaceri (numită printr-o metodă perform ) nu modifică un model de calendar (o instanță de Calendar , o clasă de model Ruby on Rails ActiveRecord) așa că am scris:

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

Acest lucru trecea într-un singur mediu de dezvoltare (MacOS), dar aproape întotdeauna eșua în CI (Linux).

Din fericire, am reușit să-l reproducem pe alt mediu de dezvoltare (Linux), unde a eșuat cu un mesaj:

 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}

Vezi ceva de pește?

Investigatia

La o examinare mai atentă, am observat că marcajele de timp created_at și updated_at au fost ușor modificate în blocul 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}

Partea fracțională a secundelor a fost trunchiată astfel încât 13:36:22.459149334 a devenit 13:36:22.459149000 .

Eram încrezători că perform nu actualizează obiectul calendar , așa că am format o ipoteză că marcajele temporale erau trunchiate de baza de date. Pentru a testa acest lucru, am folosit cea mai avansată tehnică de depanare cunoscută, adică pune depanarea:

 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

Dar trunchierea nu a fost vizibilă în rezultat:

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

Acest lucru a fost destul de surprinzător – accesoriul #created_at ar fi trebuit să aibă aceeași valoare ca și valoarea hash a atributului a attributes['created_at'] . Pentru a fi siguri că tipărim aceeași valoare folosită în aserțiune, am schimbat modul în care am accesat created_at .

În loc să folosim accesoriul calendar.created_at.to_f , am trecut la preluarea lui direct din hash-ul atributelor: calendar.attributes['created_at'].to_f . Suspiciunile noastre față de calendar.reload au fost confirmate!

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

După cum puteți vedea, apelarea perform nu s-a schimbat created_at , dar reload s-a schimbat.

Pentru a ne asigura că modificarea nu a avut loc într-o altă instanță a calendar și apoi a fost salvată, am mai efectuat un experiment. Am reîncărcat calendar înainte de test:

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

Asta a făcut testul verde.

Fix

Știind că baza de date este cea care trunchează marcajele noastre temporale și care eșuează testele noastre, am decis să prevenim trunchierea. Am generat un obiect DateTime și l-am rotunjit la secunde întregi. Apoi, am folosit acest obiect pentru a seta în mod explicit marcajele de timp pentru înregistrarea activă a lui Rails. Această modificare a fixat și stabilizat testele:

 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

Cauza

De ce s-a întâmplat asta? Marcajele de timp Active Record sunt setate de modulul ActiveRecord::Timestamp al Rails folosind Time.now . Precizia Time depinde de sistemul de operare și, după cum arată documentele, poate include fracții de secunde .

Am testat rezoluția Time.now pe MacOS și Linux cu un script care numără frecvențele lungimii părților fracționale:

 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}

După cum puteți vedea, aproximativ 70% dintre marcajele de timp pe Linux aveau șapte cifre de precizie după zecimală, în timp ce pe MacOS doar 25% aveau. Acesta este motivul pentru care testele au trecut de cele mai multe ori pe MacOS și au eșuat de cele mai multe ori pe Linux. Poate ați observat că rezultatul de testare avea o precizie de nouă cifre - asta pentru că RSpec folosește Time#nsec pentru a formata ieșirea de timp.

Când modelele Rails sunt salvate în baza de date, toate marcajele de timp pe care le au sunt stocate folosind un tip în PostgreSQL numit timestamp without time zone , care are rezoluție de microsecunde, adică șase cifre după zecimală. Deci, atunci când 1577987974.6472975 este trimis la PostgreSQL, acesta trunchiază ultima cifră a părții fracționale și în schimb salvează 1577987974.647297 .

Întrebările

Există încă întrebarea de ce calendar.created_at nu a fost reîncărcat când am apelat calendar.reload , chiar dacă calendar.attributes['created_at'] a fost reîncărcat.

De asemenea, rezultatele testului de precizie Time sunt puțin surprinzătoare. Ne așteptam ca pe MacOS, precizia maximă să fie șase. Nu știm de ce are uneori șapte cifre. Ceea ce ne-a surprins mai mult a fost distribuția valorii ultimelor 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}

După cum puteți vedea, a șaptea cifră pe MacOS este întotdeauna 1, 2, 8 sau 9.

Dacă știți răspunsul la oricare dintre aceste întrebări, vă rugăm să ne împărtășiți o explicație.

Viitorul

Faptul că marcajele de timp pentru înregistrarea activă a lui Ruby on Rails sunt generate în partea aplicației, de asemenea, poate dăuna atunci când acele marcaje de timp sunt utilizate pentru ordonarea fiabilă și precisă a evenimentelor salvate în baza de date. Deoarece ceasurile serverului de aplicații pot fi desincronizate, evenimentele ordonate de created_at pot apărea într-o altă ordine decât au avut loc în realitate. Pentru a obține un comportament mai fiabil, ar fi mai bine să lăsați serverul bazei de date să gestioneze marcajele de timp (de exemplu, PostgreSQL's now() ).

Aceasta, însă, este o poveste care merită un alt articol.

Mulțumiri speciale lui Gabriele Renzi pentru că a ajutat la crearea acestui articol.