Flaky specs in score calculator: FloatDomainError: NaN

[javierm]

Failure

Travis failed builds:

• Build 27778, job 2
• Build 28333, job 2
• Madrid's Travis build 11397, job 4
• Madrid's Travis build 11359, job 9
• Build 31193, job 3

Messages:

1) Admin comments Action links remember the pagination setting and the filter
     Failure/Error: (votes_score.to_f / period).round
     FloatDomainError:
       NaN
     # ./lib/score_calculator.rb:16:in `round'
     # ./lib/score_calculator.rb:16:in `hot_score'
     # ./app/models/debate.rb:133:in `calculate_hot_score'
     # ./app/models/debate.rb:129:in `after_commented'
     # ./app/models/comment.rb:116:in `call_after_commented'
     # ./spec/features/admin/comments_spec.rb:130:in `block (3 levels) in <top (required)>'
     # ./spec/features/admin/comments_spec.rb:130:in `times'
     # ./spec/features/admin/comments_spec.rb:130:in `block (2 levels) in <top (required)>'

Another similar error:

 1) Moderate comments /moderation/ screen moderate in bulk remembering page, filter and order
     Failure/Error: (votes_score.to_f / period).round
     FloatDomainError:
       NaN
     # ./lib/score_calculator.rb:16:in `round'
     # ./lib/score_calculator.rb:16:in `hot_score'
     # ./app/models/debate.rb:133:in `calculate_hot_score'
     # ./app/models/debate.rb:129:in `after_commented'
     # ./app/models/comment.rb:116:in `call_after_commented'
     # ./spec/features/moderation/comments_spec.rb:129:in `block (4 levels) in <top (required)>'

And another one:

1) Proposal#editable? is false if proposal has more than limit votes
     Failure/Error: (votes_score.to_f / period).round
     FloatDomainError:
       Infinity
     # ./lib/score_calculator.rb:16:in `round'
     # ./lib/score_calculator.rb:16:in `hot_score'
     # ./app/models/proposal.rb:179:in `calculate_hot_score'
     # ./spec/factories/votes.rb:7:in `block (3 levels) in <top (required)>'
     # ./spec/models/proposal_spec.rb:164:in `block (3 levels) in <top (required)>'

And another one more:

  1) Proposals Search Reorder results maintaing search
     Failure/Error: (votes_score.to_f / period).round
     FloatDomainError:
       NaN
     # ./lib/score_calculator.rb:16:in `round'
     # ./lib/score_calculator.rb:16:in `hot_score'
     # ./app/models/proposal.rb:199:in `calculate_hot_score'
     # ./spec/features/proposals_spec.rb:1442:in `block (3 levels) in <top (required)>'

Cause

The failure is caused by a division by zero. In some tests, the numerator is also 0.0, causing a NaN error, and in some other tests, the numerator is another number, causing an Infinity error.

The lines causing the period to be zero are:

period = [
  Setting["hot_score_period_in_days"].to_i,
  ((Time.current - resource.created_at) / 1.day).ceil
].min

The tests fail because sometimes Time.current - resource.created_at returns a negative value.

Debugging process

The following test might reproduce the failure if run enough times (while debugging it failed about once every 500 attempts on Travis):

it "doesn't crash" do
  create_list(:comment, 300)

  expect(true).to be
end

After adding some code to debug the failure:

time_difference = Time.current - resource.created_at

period = [
  Setting["hot_score_period_in_days"].to_i,
  (time_difference / 1.day).ceil
].min

# ...
unless period > 0
  puts "Setting is #{Setting["hot_score_period_in_days"]}"
  puts "Time difference is #{time_difference}"
end

We've found out these results in some failures:

Setting is 31
Time difference is -0.364678007

Setting is 31
Time difference is -0.171019892

Further debugging in javierm's build 529 showing the exact time (converting created_at.to_f) debates and comments are created during the failure:

Time difference is -0.20597154
# ...
Debate with id 36683 was created at 1562825865.416807 and its comment 36683 was created at 1562825865.438333
Debate with id 36684 was created at 1562825865.467227 and its comment 36684 was created at 1562825865.487892
Debate with id 36685 was created at 1562825865.5160089 and its comment 36685 was created at 1562825865.537945
Debate with id 36686 was created at 1562825865.566915 and its comment 36686 was created at 1562825865.58828
Debate with id 36687 was created at 1562825865.616801 and its comment 36687 was created at 1562825865.637271
Debate with id 36688 was created at 1562825865.66457 and its comment 36688 was created at 1562825865.4558022

# The line calculating the period was executed at 1562825865.4585986

Si it looks like between the moment the debate is created and the moment the comment is created, the system goes back in time a couple of tenths of a second.

[javierm]

These tests haven't failed for months and I can't reproduce them locally. For now I'll assume the problem is solved by either commit db6ed47 (which fixes potential issues when freezing time), pull request #3564 (which changes code related to settings), or any other changes we've done in the last few months. This is just a guess, so feel free to reopen if they fail again.

[javierm]

Failed again in Build 31193, job 3. I've updated the issue.