Obcinanie znacznika czasu: opowieść o Ruby on Rails ActiveRecord

Testy mają pomóc w zapobieganiu łamliwości aplikacji. Ale od czasu do czasu same testy mogą stać się niestabilne — nawet te najprostsze. Oto jak zagłębiliśmy się w problematyczny test aplikacji Ruby on Rails wspieranej przez PostgreSQL i co odkryliśmy.

Chcieliśmy sprawdzić, czy pewna logika biznesowa (wywoływana przez metodę perform ) nie zmienia modelu calendar (instancja Calendar , klasa modelu Ruby on Rails ActiveRecord), więc napisaliśmy:

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

To przechodziło w jednym środowisku programistycznym (MacOS), ale prawie zawsze zawodziło w CI (Linux).

Na szczęście udało nam się go odtworzyć na innym środowisku programistycznym (Linux), gdzie zawiódł z komunikatem:

 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}

Widzisz coś podejrzanego?

Dochodzenie

Przy bliższym przyjrzeniu się zauważyliśmy, że znaczniki czasu created_at i updated_at zostały nieznacznie zmienione wewnątrz bloku 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}

Część ułamkowa sekund została obcięta tak, że 13:36:22.459149334 stało się 13:36:22.459149000 .

Byliśmy pewni, że perform nie aktualizuje obiektu calendar , więc postawiliśmy hipotezę, że sygnatury czasowe są obcinane przez bazę danych. Aby to przetestować, wykorzystaliśmy najbardziej zaawansowaną znaną technikę debugowania, tj. debugowanie puts:

 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

Ale obcięcie nie było widoczne w danych wyjściowych:

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

To było dość zaskakujące — akcesor #created_at powinien mieć taką samą wartość, jak wartość skrótu attributes['created_at'] . Aby mieć pewność, że wyświetlamy tę samą wartość, co w asercji, zmieniliśmy sposób uzyskiwania dostępu do created_at .

Zamiast używać akcesora calendar.created_at.to_f , przeszliśmy na pobieranie go bezpośrednio z hasha atrybutów: calendar.attributes['created_at'].to_f . Nasze podejrzenia co do calendar.reload potwierdziły się!

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

Jak widać, wywołanie perform nie zmieniło created_at , ale reload tak.

Aby mieć pewność, że zmiana nie nastąpi w innym wystąpieniu calendar , a następnie nie zostanie zapisana, przeprowadziliśmy jeszcze jeden eksperyment. Przeładowaliśmy calendar przed testem:

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

To sprawiło, że test był zielony.

Poprawka

Wiedząc, że to baza danych obcina nasze znaczniki czasu i nie przechodzi naszych testów, postanowiliśmy zapobiec obcinaniu. Wygenerowaliśmy obiekt DateTime i zaokrągliliśmy go do pełnych sekund. Następnie użyliśmy tego obiektu do jawnego ustawienia znaczników czasu Active Record w Railsach. Ta zmiana naprawiła i ustabilizowała testy:

 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

Powód

Dlaczego się to stało? Znaczniki czasu Active Record są ustawiane przez moduł ActiveRecord::Timestamp Railsów przy użyciu Time.now . Dokładność Time jest zależna od systemu operacyjnego i zgodnie ze stanem w dokumentacji może obejmować ułamki sekund .

Przetestowaliśmy rozdzielczość Time.now na MacOS i Linux za pomocą skryptu, który zlicza częstotliwości ułamkowej długości części:

 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}

Jak widać, około 70% znaczników czasu w systemie Linux miało siedem cyfr precyzji po przecinku, podczas gdy w systemie MacOS miało to tylko 25%. To jest powód, dla którego testy w większości przypadków kończyły się niepowodzeniem w systemie MacOS i w większości przypadków nie w systemie Linux. Być może zauważyłeś, że wynik testu ma dziewięciocyfrową precyzję — to dlatego, że RSpec używa Time#nsec do formatowania czasu.

Kiedy modele Railsów są zapisywane w bazie danych, wszelkie posiadane przez nie znaczniki czasu są przechowywane przy użyciu typu w PostgreSQL zwanego timestamp without time zone , który ma rozdzielczość w mikrosekundach, tj. sześć cyfr po przecinku. Więc kiedy 1577987974.6472975 jest wysyłany do PostgreSQL, obcina ostatnią cyfrę części ułamkowej i zamiast tego zapisuje 1577987974.647297 .

Pytania

Nadal pozostaje pytanie, dlaczego calendar.created_at nie został ponownie załadowany, gdy wywołaliśmy calendar.reload , mimo że calendar.attributes['created_at'] został ponownie załadowany.

Nieco zaskakujące są również wyniki testu precyzji Time . Spodziewaliśmy się, że na MacOS maksymalna precyzja to sześć. Nie wiemy, dlaczego czasami ma siedem cyfr. Bardziej zaskoczył nas rozkład wartości ostatnich cyfr:

 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}

Jak widać, siódma cyfra w systemie MacOS to zawsze 1, 2, 8 lub 9.

Jeśli znasz odpowiedź na którekolwiek z tych pytań, podziel się z nami wyjaśnieniem.

Przyszłość

Fakt, że znaczniki czasu Active Record Ruby on Rails są generowane po stronie aplikacji, może również zaszkodzić, gdy te znaczniki czasu są używane do niezawodnego i precyzyjnego porządkowania zdarzeń zapisanych w bazie danych. Ponieważ zegary serwera aplikacji mogą być zdesynchronizowane, zdarzenia uporządkowane przez created_at mogą pojawiać się w innej kolejności niż w rzeczywistości. Aby uzyskać bardziej niezawodne zachowanie, lepiej byłoby pozwolić serwerowi bazy danych na obsługę znaczników czasu (np. now() w PostgreSQL).

To jednak historia warta kolejnego artykułu.

Specjalne podziękowania dla Gabriele Renzi za pomoc w tworzeniu tego artykułu.