Усечение метки времени: история Ruby on Rails ActiveRecord

Предполагается, что тесты помогают уберечь приложения от нестабильности. Но время от времени сами тесты могут стать ненадежными — даже самые простые. Вот как мы погрузились в проблематичный тест приложения Ruby on Rails, поддерживаемого PostgreSQL, и что мы обнаружили.

Мы хотели проверить, что определенная бизнес-логика (вызываемая методом perform ) не изменяет модель calendar (экземпляр Calendar , класс модели Ruby on Rails ActiveRecord), поэтому мы написали:

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

Это проходило в одной среде разработки (MacOS), но почти всегда давало сбой в CI (Linux).

К счастью, нам удалось воспроизвести его в другой среде разработки (Linux), где произошел сбой с сообщением:

 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}

Видишь что-то подозрительное?

Расследование

При ближайшем рассмотрении мы заметили, что временные метки created_at и updated_at были немного изменены внутри блока 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}

Дробная часть секунд была усечена, так что 13:36:22.459149334 стало 13:36:22.459149000 .

Мы были уверены, что perform не обновляет объект calendar , поэтому мы выдвинули гипотезу о том, что временные метки усекаются базой данных. Чтобы проверить это, мы использовали самую продвинутую из известных методик отладки, т. е. отладку 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

Но усечение не было видно в выводе:

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

Это было довольно неожиданно — метод доступа #created_at должен был иметь то же значение, что и хеш-значение attributes['created_at'] . Чтобы убедиться, что мы печатаем то же значение, что и в утверждении, мы изменили способ доступа к created_at .

Вместо использования метода доступа calendar.created_at.to_f мы переключились на получение его напрямую из хэша атрибутов: calendar.attributes['created_at'].to_f . Наши подозрения в отношении calendar.reload подтвердились!

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

Как видите, вызов perform не изменил created_at , но изменился reload .

Чтобы убедиться, что изменение не происходит в другом экземпляре calendar , а затем сохраняется, мы провели еще один эксперимент. Мы перезагрузили calendar перед тестом:

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

Это сделало тест зеленым.

Исправление

Зная, что именно база данных усекает наши временные метки и не проходит наши тесты, мы решили предотвратить усечение. Мы сгенерировали объект DateTime и округлили его до целых секунд. Затем мы использовали этот объект для явной установки временных меток Active Record в Rails. Это изменение исправило и стабилизировало тесты:

 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

Причина

Почему это случилось? Временные метки Active Record устанавливаются модулем Rails ActiveRecord::Timestamp с использованием Time.now . Точность Time зависит от ОС и, как указано в документации, может включать доли секунды .

Мы протестировали разрешение Time.now на MacOS и Linux с помощью скрипта, который подсчитывает частоты дробных частей длины:

 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}

Как вы можете видеть, около 70% меток времени в Linux имели точность до семи знаков после запятой, в то время как в MacOS только 25%. По этой причине тесты в большинстве случаев проходили на MacOS и чаще всего не удавались на Linux. Вы, возможно, заметили, что тестовый вывод имеет точность до девяти цифр — это потому, что RSpec использует Time#nsec для форматирования вывода времени.

Когда модели Rails сохраняются в базе данных, все временные метки, которые у них есть, сохраняются с использованием типа PostgreSQL, называемого timestamp without time zone , который имеет разрешение в микросекундах, т. е. шесть цифр после запятой. Поэтому, когда 1577987974.6472975 отправляется в PostgreSQL, он усекает последнюю цифру дробной части и вместо этого сохраняет 1577987974.647297 .

Вопросы

Остается вопрос, почему calendar.created_at не был перезагружен, когда мы вызвали calendar.reload , несмотря на то, что calendar.attributes['created_at'] был перезагружен.

Кроме того, результаты теста точности Time немного удивляют. Мы ожидали, что в MacOS максимальная точность равна шести. Мы не знаем, почему оно иногда имеет семь цифр. Больше всего нас удивило распределение значения последних цифр:

 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}

Как видите, седьмая цифра в MacOS всегда 1, 2, 8 или 9.

Если вы знаете ответ на любой из этих вопросов, пожалуйста, поделитесь с нами объяснением.

Будущее

Тот факт, что временные метки Active Record в Ruby on Rails генерируются на стороне приложения, также может повредить, когда эти временные метки используются для надежного и точного упорядочения событий, сохраняемых в базе данных. Поскольку часы сервера приложений могут быть рассинхронизированы, события, упорядоченные с помощью created_at , могут отображаться в другом порядке, чем они произошли на самом деле. Чтобы получить более надежное поведение, было бы лучше позволить серверу базы данных обрабатывать временные метки (например, now() в PostgreSQL).

Впрочем, это история, достойная отдельной статьи.

Особая благодарность Габриэле Ренци за помощь в создании этой статьи.