Zaman Damgası Kesmesi: Bir Ruby on Rails ActiveRecord Öyküsü

Testlerin, uygulamaların kesintiye uğramasını önlemeye yardımcı olması gerekiyor. Ancak arada bir, testlerin kendileri de belirsiz hale gelebilir - en basit olanlar bile. PostgreSQL tarafından desteklenen bir Ruby on Rails uygulamasında sorunlu bir teste şu şekilde daldık ve neleri ortaya çıkardık.

Belirli bir iş mantığının ( perform yöntemiyle çağrılır) bir calendar modelini (bir Calendar örneği, bir Ruby on Rails ActiveRecord model sınıfı) değiştirmediğini kontrol etmek istedik ve şunu yazdık:

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

Bu, bir geliştirme ortamından (MacOS) geçiyordu, ancak CI'de (Linux) neredeyse her zaman başarısız oluyordu.

Neyse ki, bir mesajla başarısız olduğu başka bir geliştirme ortamında (Linux) yeniden oluşturmayı başardık:

 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}

Balık gibi bir şey gördün mü?

Soruşturma

Daha yakından incelediğimizde, created_at ve updated_at zaman damgalarının expect bloğu içinde biraz değiştiğini fark ettik:

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

Saniyenin kesirli kısmı 13:36:22.459149334 13:36:22.459149000 .

perform'ın calendar nesnesini güncellemediğinden perform , bu yüzden zaman damgalarının veritabanı tarafından kesildiğine dair bir hipotez oluşturduk. Bunu test etmek için bilinen en gelişmiş hata ayıklama tekniğini kullandık, yani hata ayıklama koyar:

 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

Ancak çıktıda kesme görünmüyordu:

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

Bu oldukça şaşırtıcıydı; #created_at , attributes['created_at'] öznitelik karma değeriyle aynı değere sahip olması gerekirdi. İddiada kullanılanla aynı değeri yazdırdığımızdan emin olmak için created_at şeklimizi değiştirdik.

calendar.created_at.to_f erişimcisini kullanmak yerine, onu doğrudan hash özniteliklerinden getirmeye geçtik: calendar.attributes['created_at'].to_f . calendar.reload ile ilgili şüphelerimiz doğrulandı!

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

Gördüğünüz gibi, perform çağrısı created_at değiştirmedi, ancak reload yaptı.

Değişikliğin başka bir calendar örneğinde gerçekleşmediğinden ve ardından kaydedildiğinden emin olmak için bir deney daha gerçekleştirdik. Testten önce calendar yeniden yükledik:

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

Bu, testi yeşil yaptı.

Çözüm

Zaman damgalarımızı kesen ve testlerimizde başarısız olanın veritabanı olduğunu bilerek, bu kesintiyi önlemeye karar verdik. Bir DateTime nesnesi oluşturduk ve onu tam saniyeye yuvarladık. Ardından, Rails'in Aktif Kayıt zaman damgalarını açıkça ayarlamak için bu nesneyi kullandık. Bu değişiklik testleri düzeltti ve stabilize etti:

 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

Neden

Bu neden oldu? Aktif Kayıt zaman damgaları, Rails'in ActiveRecord::Timestamp modülü tarafından Time.now kullanılarak ayarlanır. Time kesinliği işletim sistemine bağlıdır ve belgelerin durumu olarak kesirli saniyeler içerebilir .

MacOS ve Linux'ta Time.now çözünürlüğünü kesirli parça uzunluklarının frekanslarını sayan bir komut dosyasıyla test ettik:

 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}

Gördüğünüz gibi, Linux'taki zaman damgalarının yaklaşık %70'i ondalık sayıdan sonra yedi basamaklı kesinliğe sahipken, MacOS'ta yalnızca %25'i vardı. Testlerin çoğu zaman MacOS'ta geçmesinin ve çoğu zaman Linux'ta başarısız olmasının nedeni budur. Test çıktısının dokuz basamaklı kesinliğe sahip olduğunu fark etmiş olabilirsiniz; bunun nedeni, RSpec'in zaman çıktısını biçimlendirmek için Time#nsec nsec kullanmasıdır.

Rails modelleri veritabanına kaydedildiğinde, sahip oldukları tüm zaman damgaları, PostgreSQL'de timestamp without time zone adı verilen ve mikrosaniye çözünürlüğe sahip, yani ondalıktan sonraki altı basamaklı bir tür kullanılarak depolanır. Dolayısıyla, 1577987974.6472975 PostgreSQL'e gönderildiğinde, kesirli kısmın son basamağını keser ve bunun yerine 1577987974.647297 kaydeder.

Sorular

calendar.attributes['created_at'] yeniden yüklenmiş olmasına rağmen, calendar.reload calendar.created_at yeniden yüklenmediği sorusu hala var.

Ayrıca, Time kesinliği testinin sonuçları biraz şaşırtıcı. MacOS'ta maksimum hassasiyetin altı olmasını bekliyorduk. Neden bazen yedi basamaklı olduğunu bilmiyoruz. Bizi daha çok şaşırtan, son hanelerin değerinin dağılımıydı:

 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}

Gördüğünüz gibi, MacOS'ta yedinci rakam her zaman 1, 2, 8 veya 9'dur.

Bu sorulardan herhangi birinin cevabını biliyorsanız, lütfen bizimle bir açıklama paylaşın.

Gelecek

Ruby on Rails'in Aktif Kayıt zaman damgalarının uygulama tarafında oluşturulması gerçeği, bu zaman damgaları veritabanına kaydedilen olayların güvenilir ve kesin sıralaması için kullanıldığında da zarar verebilir. Uygulama sunucusu saatlerinin senkronizasyonu bozulabileceğinden, created_at tarafından sıralanan olaylar, gerçekte meydana geldiklerinden farklı bir sırada görünebilir. Daha güvenilir davranış elde etmek için, veritabanı sunucusunun zaman damgalarını işlemesine izin vermek daha iyi olacaktır (örneğin, PostgreSQL's now() ).

Ancak bu, başka bir makaleye değer bir hikaye.

Bu makaleyi oluşturmaya yardımcı olduğu için Gabriele Renzi'ye özel teşekkürler.