NoMethodError on nil DataPoint masks real failure in ResqueJobs::RunSimulateDataPoint#perform under load

[anchapin]

General Issue / Feature Information

Description

ResqueJobs::RunSimulateDataPoint#perform (server/app/jobs/resque_jobs/run_simulate_data_point.rb) assigns d = DataPoint.find(data_point_id) as the first statement inside the method body, then references d from every rescue clause to log the failure:

def self.perform(data_point_id, options = {})
  d = DataPoint.find(data_point_id)          # line 18
  statuses = d.get_statuses
  ...
rescue SignalException, Errno::ENOSPC, Resque::DirtyExit, Resque::TermException, Resque::PruneDeadWorkerDirtyExit => e
  d.add_to_rails_log("Worker Caught Exception: #{e.inspect}")   # line 38
  ...
rescue => e
  d.add_to_rails_log("Worker Caught Unhandled Exception: #{e.message}")  # line 43
  ...
end

If DataPoint.find itself raises (e.g. Mongoid::Errors::DocumentNotFound, or a transient Mongo timeout/connection-pool exhaustion under heavy concurrent load), d is never assigned and control jumps straight to the generic rescue => e clause. That clause immediately calls d.add_to_rails_log(...) on a nil d, raising a secondary NoMethodError: undefined method 'add_to_rails_log' for nil:NilClass. This secondary exception is what actually gets logged/propagated to Resque's failed queue — the original exception (the real root cause, e.g. the Mongo error) is silently swallowed and never recorded anywhere.

We hit this at scale on a Kubernetes deployment (openstudio-server-helm) running an autoscaled worker pool (KEDA, ~1,500-1,700 concurrent worker replicas hammering MongoDB with concurrent DataPoint.find calls during a large parametric run). The Resque failed queue accumulated a steadily growing number of NoMethodError: undefined method 'add_to_rails_log' for nil:NilClass entries (observed growing from 113 to 165+ over about 15 minutes while queue depth was ~11,000-13,000).

Because NoMethodError is not one of the transient-failure signatures typically whitelisted for automatic replay (only Resque::DirtyExit, Resque::PruneDeadWorkerDirtyExit, Resque::TermException are usually treated as safe-to-retry), any DataPoint that hits this path is permanently stuck in whatever status it was in when the job died (e.g. queued) — Resque removes the job from the working queue, records the masking NoMethodError, and nothing ever requeues it.

Reproduction steps:

1. Deploy openstudio-server with a large worker pool (dozens to thousands of concurrent Resque workers) against a single MongoDB instance/replica set.
2. Submit a batch analysis large enough that MongoDB experiences connection pressure/timeouts under concurrent DataPoint.find calls from ResqueJobs::RunSimulateDataPoint.perform (or artificially: stub/monkey-patch DataPoint.find to raise on the first call inside perform).
3. Watch the Resque failed queue: entries with NoMethodError: undefined method 'add_to_rails_log' for nil:NilClass, raised from run_simulate_data_point.rb's generic rescue => e clause, start to appear and accumulate.

Actual outcome:

• The rescue handler itself raises a NoMethodError because d is nil, masking the true root-cause exception.
• The DataPoint is left permanently in its pre-failure status (e.g. queued) with no log entry explaining why, since add_to_rails_log never ran.
• The Resque failed queue grows unbounded with these masking entries; they are not eligible for automatic replay (not one of the whitelisted transient-failure classes typically used by cleanup/replay tooling), so affected data points require manual detection/reset.

Expected outcome:

• The original exception (whatever caused DataPoint.find — or any other early statement — to raise) should be the one that's actually logged/surfaced, not a secondary NoMethodError from the rescue handler.
• At minimum, the rescue clauses should guard against d being nil (e.g. d&.add_to_rails_log(...)) and fall back to Rails.logger/puts with the data_point_id so the failure is still diagnosable.
• Ideally, DataPoint.find failures get their own explicit handling (e.g. rescue Mongoid::Errors::DocumentNotFound / Mongo timeout errors specifically, log with the raw data_point_id, and decide whether to retry or drop) rather than falling through to the generic handler at all.

Other information (i.e. issue is intermittent):

• Confirmed present, byte-for-byte identical logic, on develop (server/app/jobs/resque_jobs/run_simulate_data_point.rb, lines 17-47) as of commit 64f597f2bfbc9b3eb08dbc53e4d3bff0dc2f90cb — this is not specific to a downstream fork/branch.
• Intermittent and load-dependent: only observed under heavy concurrent worker load against MongoDB (large parametric batch runs with autoscaled worker pools); did not reproduce at low concurrency.
• Related: DjJobs::RunSimulateDataPoint#perform (server/app/jobs/dj_jobs/run_simulate_data_point.rb) has a similar d = DataPoint.find(...)-then-reference-d-in-rescue pattern worth auditing for the same masking hazard.
• Suggested minimal fix (happy to open a PR if useful):

  def self.perform(data_point_id, options = {})
    d = DataPoint.find(data_point_id)
    ...
  rescue SignalException, Errno::ENOSPC, Resque::DirtyExit, Resque::TermException, Resque::PruneDeadWorkerDirtyExit => e
    d&.add_to_rails_log("Worker Caught Exception: #{e.inspect}")
    puts "Worker Caught Exception: #{e.inspect} (data_point_id=#{data_point_id})"
  rescue => e
    d&.add_to_rails_log("Worker Caught Unhandled Exception: #{e.message}")
    puts "Worker Caught Unhandled Exception: #{e.message} (data_point_id=#{data_point_id})"
  end