Pemotongan stempel waktu: Kisah ActiveRecord Ruby on Rails

Pengujian seharusnya membantu menjaga aplikasi agar tidak terkelupas. Tapi sesekali, tes itu sendiri bisa menjadi tidak stabil—bahkan yang paling sederhana sekalipun. Inilah cara kami terjun ke dalam pengujian bermasalah pada aplikasi Ruby on Rails yang didukung oleh PostgreSQL, dan apa yang kami temukan.

Kami ingin memeriksa bahwa logika bisnis tertentu (disebut dengan metode perform ) tidak mengubah model calendar (contoh dari Calendar , kelas model Ruby on Rails ActiveRecord) jadi kami menulis:

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

Ini melewati satu lingkungan pengembangan (MacOS), tetapi hampir selalu gagal di CI (Linux).

Untungnya, kami berhasil mereproduksinya di lingkungan pengembangan lain (Linux), yang gagal dengan pesan:

 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}

Lihat sesuatu yang mencurigakan?

Investigasi

Pada pemeriksaan lebih dekat, kami melihat bahwa stempel waktu created_at dan updated_at diubah sedikit di dalam blok 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}

Bagian pecahan detik dipotong sehingga 13:36:22.459149334 menjadi 13:36:22.459149000 .

Kami yakin bahwa perform tidak memperbarui objek calendar , jadi kami membuat hipotesis bahwa stempel waktu sedang dipotong oleh database. Untuk menguji ini, kami menggunakan teknik debugging paling canggih yang dikenal, yaitu menempatkan 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

Tetapi pemotongan tidak terlihat di output:

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

Ini cukup mengejutkan—aksesor #created_at seharusnya memiliki nilai yang sama dengan nilai hash atribut dari attributes['created_at'] . Untuk memastikan kami mencetak nilai yang sama dengan yang digunakan dalam pernyataan, kami mengubah cara kami mengakses created_at .

Alih-alih menggunakan pengakses calendar.created_at.to_f , kami beralih untuk mengambilnya dari hash atribut secara langsung: calendar.attributes['created_at'].to_f . Kecurigaan kami terhadap calendar.reload terbukti!

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

Seperti yang Anda lihat, pemanggilan perform tidak mengubah created_at , tetapi reload berubah.

Untuk memastikan perubahan tidak terjadi pada contoh calendar lain dan kemudian disimpan, kami melakukan satu eksperimen lagi. Kami memuat ulang calendar sebelum ujian:

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

Itu membuat tes menjadi hijau.

Perbaikan

Mengetahui bahwa database yang memotong stempel waktu kami dan gagal dalam pengujian kami, kami memutuskan untuk mencegah pemotongan terjadi. Kami membuat objek DateTime dan membulatkannya menjadi detik penuh. Kemudian, kami menggunakan objek ini untuk mengatur stempel waktu Rekaman Aktif Rails secara eksplisit. Perubahan ini memperbaiki dan menstabilkan pengujian:

 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

Penyebab

Kenapa ini terjadi? Stempel waktu Rekaman Aktif diatur oleh modul ActiveRecord::Timestamp Rails menggunakan Time.now . Ketepatan Time bergantung pada OS, dan seperti yang dinyatakan dalam dokumen, dapat mencakup detik fraksional .

Kami menguji resolusi Time.now di MacOS dan Linux dengan skrip yang menghitung frekuensi panjang bagian pecahan:

 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}

Seperti yang Anda lihat, sekitar 70% stempel waktu di Linux memiliki tujuh digit presisi setelah desimal, sedangkan di MacOS hanya 25%. Inilah alasan mengapa sebagian besar waktu pengujian berlalu di MacOS dan gagal sebagian besar waktu di Linux. Anda mungkin telah memperhatikan bahwa keluaran pengujian memiliki presisi sembilan digit—itu karena RSpec menggunakan Time#nsec untuk memformat keluaran waktu.

Ketika model Rails disimpan ke database, setiap stempel waktu yang mereka miliki disimpan menggunakan tipe di PostgreSQL yang disebut timestamp without time zone , yang memiliki resolusi mikrodetik—yaitu, enam digit setelah desimal. Jadi, ketika 1577987974.6472975 dikirim ke PostgreSQL, digit terakhir dari bagian pecahan akan terpotong dan sebagai gantinya menyimpan 1577987974.647297 .

Pertanyaan-pertanyaan

Masih ada pertanyaan mengapa calendar.created_at tidak dimuat ulang ketika kami memanggil calendar.reload , meskipun calendar.attributes['created_at'] dimuat ulang.

Juga, hasil tes presisi Time agak mengejutkan. Kami mengharapkan bahwa pada MacOS, presisi maksimal adalah enam. Kami tidak tahu mengapa kadang- kadang memiliki tujuh digit. Yang lebih mengejutkan kami adalah distribusi nilai digit terakhir:

 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}

Seperti yang Anda lihat, digit ketujuh di MacOS selalu 1, 2, 8, atau 9.

Jika Anda tahu jawaban untuk salah satu dari pertanyaan ini, silakan berbagi penjelasan dengan kami.

Masa depan

Fakta bahwa stempel waktu Rekaman Aktif Ruby on Rails dihasilkan di sisi aplikasi juga dapat merugikan ketika stempel waktu tersebut digunakan untuk pemesanan peristiwa yang dapat diandalkan dan tepat yang disimpan ke database. Karena jam server aplikasi dapat disinkronkan, peristiwa yang diurutkan oleh created_at mungkin muncul dalam urutan yang berbeda dari yang sebenarnya terjadi. Untuk mendapatkan perilaku yang lebih andal, akan lebih baik untuk membiarkan server database menangani stempel waktu (mis., PostgreSQL now() ).

Namun, itu adalah cerita yang layak untuk artikel lain.

Terima kasih khusus kepada Gabriele Renzi untuk membantu membuat artikel ini.