Troncature d'horodatage : une histoire Ruby on Rails ActiveRecord

Les tests sont censés aider à empêcher les applications d'être floconneuses. Mais de temps en temps, les tests eux-mêmes peuvent devenir instables, même les plus simples. Voici comment nous avons plongé dans un test problématique sur une application Ruby on Rails soutenue par PostgreSQL, et ce que nous avons découvert.

Nous voulions vérifier que certaines logiques métier (appelées par une méthode perform ) ne modifient pas un modèle de calendar (une instance de Calendar , une classe de modèle Ruby on Rails ActiveRecord), nous avons donc écrit :

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

Cela passait dans un environnement de développement (MacOS), mais cela échouait presque toujours dans CI (Linux).

Heureusement, nous avons réussi à le reproduire sur un autre environnement de développement (Linux), où il a échoué avec un message :

 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}

Vous voyez quelque chose de louche ?

L'enquête

En y regardant de plus près, nous avons remarqué que les horodatages created_at et updated_at ont été légèrement modifiés à l'intérieur du bloc 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 partie fractionnaire des secondes a été tronquée de sorte que 13:36:22.459149334 est devenu 13:36:22.459149000 .

Nous étions convaincus que perform ne mettait pas à jour l'objet calendar , nous avons donc émis l'hypothèse que les horodatages étaient tronqués par la base de données. Pour tester cela, nous avons utilisé la technique de débogage la plus avancée connue, c'est-à-dire met le débogage :

 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

Mais la troncation n'était pas visible dans la sortie :

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

C'était assez surprenant - l'accesseur #created_at aurait dû avoir la même valeur que la valeur de hachage de l' attributes['created_at'] . Pour être sûr que nous imprimions la même valeur utilisée dans l'assertion, nous avons changé la façon dont nous avons accédé à created_at .

Au lieu d'utiliser l'accesseur calendar.created_at.to_f , nous sommes passés à le récupérer directement à partir du hachage des attributs : calendar.attributes['created_at'].to_f . Nos soupçons envers calendar.reload ont été confirmés !

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

Comme vous pouvez le voir, l'appel à perform n'a pas changé created_at , mais reload l'a fait.

Pour nous assurer que le changement ne se produisait pas sur une autre instance de calendar et qu'il était ensuite enregistré, nous avons effectué une autre expérience. Nous avons rechargé le calendar avant le test :

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

Cela a rendu le test vert.

Le correctif

Sachant que c'est la base de données qui tronque nos horodatages et échoue à nos tests, nous avons décidé d'empêcher la troncation de se produire. Nous avons généré un objet DateTime et l'avons arrondi à des secondes entières. Ensuite, nous avons utilisé cet objet pour définir explicitement les horodatages Active Record de Rails. Ce changement a corrigé et stabilisé les tests :

 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 cause

Pourquoi est-ce arrivé? Les horodatages Active Record sont définis par le module ActiveRecord::Timestamp de Rails à l'aide Time.now . La précision Time dépend du système d'exploitation et, comme l'indique la documentation, peut inclure des fractions de seconde .

Nous avons testé la résolution Time.now sur MacOS et Linux avec un script qui compte les fréquences des longueurs fractionnaires :

 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}

Comme vous pouvez le voir, environ 70 % des horodatages sous Linux avaient sept chiffres de précision après la décimale, alors que sous MacOS, seuls 25 % en avaient. C'est la raison pour laquelle les tests ont réussi la plupart du temps sur MacOS et échoué la plupart du temps sur Linux. Vous avez peut-être remarqué que la sortie de test avait une précision à neuf chiffres, car RSpec utilise Time#nsec pour formater la sortie de l'heure.

Lorsque les modèles Rails sont enregistrés dans la base de données, tous les horodatages dont ils disposent sont stockés à l'aide d'un type dans PostgreSQL appelé timestamp without time zone , qui a une résolution en microsecondes, c'est-à-dire six chiffres après la décimale. Ainsi, lorsque 1577987974.6472975 est envoyé à PostgreSQL, il tronque le dernier chiffre de la partie fractionnaire et enregistre à la place 1577987974.647297 .

Questions

Il y a toujours la question de savoir pourquoi calendar.created_at n'a pas été rechargé lorsque nous avons appelé calendar.reload , même si calendar.attributes['created_at'] a été rechargé.

De plus, les résultats du test de précision du Time sont un peu surprenants. Nous nous attendions à ce que sur MacOS, la précision maximale soit de six. Nous ne savons pas pourquoi il a parfois sept chiffres. Ce qui nous a le plus surpris, c'est la distribution de la valeur des derniers chiffres :

 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}

Comme vous pouvez le voir, le septième chiffre sur MacOS est toujours 1, 2, 8 ou 9.

Si vous connaissez la réponse à l'une de ces questions, veuillez partager une explication avec nous.

L'avenir

Le fait que les horodatages Active Record de Ruby on Rails soient générés du côté de l'application peut également nuire lorsque ces horodatages sont utilisés pour un ordre fiable et précis des événements enregistrés dans la base de données. Comme les horloges des serveurs d'application peuvent être désynchronisées, les événements classés par created_at peuvent apparaître dans un ordre différent de celui dans lequel ils se sont réellement produits. Pour obtenir un comportement plus fiable, il serait préférable de laisser le serveur de base de données gérer les horodatages (par exemple, now() de PostgreSQL).

Cela, cependant, est une histoire qui vaut un autre article.

Un merci spécial à Gabriele Renzi pour avoir aidé à créer cet article.