Truncamiento de marca de tiempo: una historia de ActiveRecord de Ruby on Rails

Se supone que las pruebas ayudan a evitar que las aplicaciones sean inestables. Pero de vez en cuando, las pruebas en sí mismas pueden volverse inestables, incluso las más sencillas. Así es como nos sumergimos en una prueba problemática en una aplicación Ruby on Rails respaldada por PostgreSQL, y lo que descubrimos.

Queríamos verificar que cierta lógica de negocios (llamada por un método perform ) no cambia un modelo de calendar (una instancia de Calendar , una clase de modelo Ruby on Rails ActiveRecord) así que escribimos:

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

Esto pasaba en un entorno de desarrollo (MacOS), pero casi siempre fallaba en CI (Linux).

Afortunadamente, logramos reproducirlo en otro entorno de desarrollo (Linux), donde falló con un mensaje:

 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}

¿Ves algo sospechoso?

La investigación

En un examen más detallado, notamos que las marcas de tiempo created_at y updated_at se cambiaron ligeramente dentro del bloque de 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 parte fraccionaria de los segundos se truncó para que 13:36:22.459149334 se convirtiera en 13:36:22.459149000 .

Estábamos seguros de que perform no estaba actualizando el objeto de calendar , por lo que formulamos la hipótesis de que la base de datos estaba truncando las marcas de tiempo. Para probar esto, usamos la técnica de depuración más avanzada conocida, es decir, pone la depuración:

 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

Pero el truncamiento no era visible en la salida:

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

Esto fue bastante sorprendente: el descriptor de acceso #created_at debería haber tenido el mismo valor que el valor hash del atributo de attributes['created_at'] . Para asegurarnos de que estábamos imprimiendo el mismo valor utilizado en la aserción, cambiamos la forma en que accedíamos a created_at .

En lugar de usar el descriptor de acceso calendar.created_at.to_f , cambiamos a obtenerlo directamente del hash de atributos: calendar.attributes['created_at'].to_f . ¡Se confirmaron nuestras sospechas sobre calendar.reload !

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

Como puede ver, llamar a perform no cambió created_at , pero reload sí.

Para asegurarnos de que el cambio no sucediera en otra instancia del calendar y luego se guardara, realizamos un experimento más. Recargamos calendar antes de la prueba:

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

Eso hizo que la prueba fuera verde.

La solución

Sabiendo que es la base de datos la que trunca nuestras marcas de tiempo y falla nuestras pruebas, decidimos evitar que ocurra el truncamiento. Generamos un objeto DateTime y lo redondeamos a segundos enteros. Luego, usamos este objeto para establecer explícitamente las marcas de tiempo de Active Record de Rails. Este cambio arregló y estabilizó las pruebas:

 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 causa

¿Por qué pasó esto? Las marcas de tiempo de Active Record son establecidas por el módulo ActiveRecord::Timestamp de Rails usando Time.now . La precisión de Time depende del sistema operativo y, como indican los documentos, puede incluir fracciones de segundo .

Probamos la resolución de Time.now en MacOS y Linux con un script que cuenta frecuencias de longitudes fraccionarias:

 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}

Como puede ver, alrededor del 70 % de las marcas de tiempo en Linux tenían siete dígitos de precisión después del decimal, mientras que en MacOS solo el 25 %. Esta es la razón por la cual las pruebas pasaron la mayor parte del tiempo en MacOS y fallaron la mayor parte del tiempo en Linux. Es posible que haya notado que la salida de prueba tenía una precisión de nueve dígitos, eso se debe a que RSpec usa Time#nsec para formatear la salida de tiempo.

Cuando los modelos de Rails se guardan en la base de datos, cualquier marca de tiempo que tengan se almacena usando un tipo en PostgreSQL llamado timestamp without time zone , que tiene una resolución de microsegundos, es decir, seis dígitos después del decimal. Entonces, cuando se envía 1577987974.6472975 a PostgreSQL, trunca el último dígito de la parte fraccionaria y en su lugar guarda 1577987974.647297 .

Las preguntas

Todavía queda la pregunta de por qué calendar.created_at no se recargó cuando llamamos a calendar.reload , aunque se recargó calendar.attributes['created_at'] .

Además, los resultados de la prueba de precisión de Time son un poco sorprendentes. Esperábamos que en MacOS, la precisión máxima sea seis. No sabemos por qué a veces tiene siete dígitos. Lo que más nos sorprendió fue la distribución del valor de los últimos dígitos:

 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}

Como puede ver, el séptimo dígito en MacOS siempre es 1, 2, 8 o 9.

Si conoce la respuesta a cualquiera de estas preguntas, comparta una explicación con nosotros.

El futuro

El hecho de que las marcas de tiempo de Active Record de Ruby on Rails se generen en el lado de la aplicación también puede perjudicar cuando esas marcas de tiempo se usan para ordenar de manera confiable y precisa los eventos guardados en la base de datos. Como los relojes del servidor de aplicaciones pueden estar desincronizados, los eventos ordenados por created_at pueden aparecer en un orden diferente al que realmente ocurrieron. Para obtener un comportamiento más confiable, sería mejor dejar que el servidor de la base de datos maneje las marcas de tiempo (por ejemplo, now() de PostgreSQL).

Eso, sin embargo, es una historia que vale otro artículo.

Un agradecimiento especial a Gabriele Renzi por ayudar a crear este artículo.