Abschneiden von Zeitstempeln: Eine Geschichte von Ruby on Rails ActiveRecord

Tests sollen dazu beitragen, dass Apps nicht flockig werden. Aber hin und wieder können Tests selbst unzuverlässig werden – selbst die einfachsten. So sind wir in einen problematischen Test einer von PostgreSQL unterstützten Ruby on Rails-App eingetaucht und was wir dabei herausgefunden haben.

Wir wollten überprüfen, ob eine bestimmte Geschäftslogik (aufgerufen von einer Methode perform ) ein calendar (eine Instanz von Calendar , eine ActiveRecord-Modellklasse von Ruby on Rails) nicht ändert, also schrieben wir:

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

Dies bestand in einer Entwicklungsumgebung (MacOS), schlug jedoch fast immer in CI (Linux) fehl.

Glücklicherweise gelang es uns, es auf einer anderen Entwicklungsumgebung (Linux) zu reproduzieren, wo es mit einer Meldung fehlschlug:

 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}

Sehen Sie etwas faul?

Die Ermittlung

Bei näherer Betrachtung ist uns aufgefallen, dass die Zeitstempel „ created_at und updated_at innerhalb des expect -Blocks leicht verändert wurden:

 {"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}

Der Bruchteil der Sekunden wurde abgeschnitten, sodass 13:36:22.459149334 zu 13:36:22.459149000 wurde.

Wir waren uns sicher, dass perform das calendar nicht aktualisiert, also stellten wir die Hypothese auf, dass die Zeitstempel von der Datenbank abgeschnitten wurden. Um dies zu testen, haben wir die fortschrittlichste bekannte Debugging-Technik verwendet, dh 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

Aber die Kürzung war in der Ausgabe nicht sichtbar:

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

Das war ziemlich überraschend – der Accessor #created_at hätte denselben Wert haben sollen wie der Attribut-Hash-Wert von attributes['created_at'] . Um sicherzustellen, dass wir denselben Wert ausgeben, der in der Assertion verwendet wurde, haben wir die Art und Weise geändert, wie wir auf created_at zugegriffen haben.

Anstatt den Accessor „ calendar.created_at.to_f “ zu verwenden, sind wir dazu übergegangen, ihn direkt aus dem Attribute-Hash abzurufen: calendar.attributes['created_at'].to_f . Unser Verdacht gegenüber calendar.reload wurde bestätigt!

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

Wie Sie sehen können, hat der Aufruf von perform reload nicht geändert, created_at jedoch.

Um sicherzustellen, dass die Änderung nicht auf einer anderen Instanz des calendar vorgenommen und dann gespeichert wurde, haben wir ein weiteres Experiment durchgeführt. Wir haben den calendar vor dem Test neu geladen:

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

Das machte den Test grün.

Die Reparatur

Da wir wissen, dass es die Datenbank ist, die unsere Zeitstempel abschneidet und unsere Tests nicht besteht, haben wir uns entschieden, das Abschneiden zu verhindern. Wir haben ein DateTime Objekt generiert und es auf ganze Sekunden gerundet. Dann haben wir dieses Objekt verwendet, um die Active Record-Zeitstempel von Rails explizit festzulegen. Diese Änderung hat die Tests korrigiert und stabilisiert:

 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

Die Ursache

Warum ist das passiert? ActiveRecord-Zeitstempel werden vom ActiveRecord ActiveRecord::Timestamp -Modul von Rails mit Time.now . Time ist vom Betriebssystem abhängig und kann, wie in der Dokumentation angegeben, Sekundenbruchteile enthalten .

Wir haben die Time.now Auflösung unter MacOS und Linux mit einem Skript getestet, das die Häufigkeiten von Bruchteillängen zählt:

 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}

Wie Sie sehen können, hatten etwa 70 % der Zeitstempel unter Linux eine Genauigkeit von sieben Nachkommastellen, während dies unter MacOS nur für 25 % der Fall war. Aus diesem Grund haben die Tests unter MacOS die meiste Zeit bestanden und unter Linux die meiste Zeit fehlgeschlagen. Sie haben vielleicht bemerkt, dass die Testausgabe eine neunstellige Genauigkeit hatte – das liegt daran, dass RSpec Time#nsec verwendet, um die Zeitausgabe zu formatieren.

Wenn Rails-Modelle in der Datenbank gespeichert werden, werden alle Zeitstempel, die sie haben, unter Verwendung eines Typs in PostgreSQL namens timestamp without time zone gespeichert, der eine Auflösung von Mikrosekunden hat, dh sechs Stellen nach dem Dezimalkomma. Wenn also 1577987974.6472975 an PostgreSQL gesendet wird, wird die letzte Ziffer des Bruchteils abgeschnitten und stattdessen 1577987974.647297 .

Die Fragen

Es stellt sich immer noch die Frage, warum „ calendar.created_at “ nicht neu geladen wurde, als wir „ calendar.reload “ aufgerufen haben, obwohl calendar.attributes['created_at'] neu geladen wurde.

Etwas überraschend sind auch die Ergebnisse des Time Precision Tests. Wir hatten erwartet, dass unter MacOS die maximale Genauigkeit sechs ist. Wir wissen nicht, warum es manchmal sieben Ziffern hat. Was uns mehr überrascht hat, war die Verteilung des Werts der letzten Ziffern:

 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}

Wie Sie sehen können, ist die siebte Ziffer unter MacOS immer 1, 2, 8 oder 9.

Wenn Sie die Antwort auf eine dieser Fragen kennen, teilen Sie uns bitte eine Erklärung mit.

Die Zukunft

Die Tatsache, dass Active Record-Zeitstempel von Ruby on Rails auf der Anwendungsseite generiert werden, kann auch schaden, wenn diese Zeitstempel für eine zuverlässige und präzise Reihenfolge der in der Datenbank gespeicherten Ereignisse verwendet werden. Da die Uhren des Anwendungsservers desynchronisiert sein können, können von created_at geordnete Ereignisse in einer anderen Reihenfolge erscheinen, als sie tatsächlich aufgetreten sind. Um ein zuverlässigeres Verhalten zu erzielen, wäre es besser, den Datenbankserver Zeitstempel verarbeiten zu lassen (z. B. now() von PostgreSQL).

Das ist jedoch eine Geschichte, die einen weiteren Artikel wert ist.

Besonderer Dank geht an Gabriele Renzi für die Hilfe bei der Erstellung dieses Artikels.