Error 500 - undefined method `in_time_zone' for nil:NilClass

[schlos]

Actual behavior

[ERROR] [imamopravoznati.org] admin_general#index (NoMethodError) "undefined method `in_time_zone' for nil:NilClass"

A NoMethodError occurred in admin_general#index:

undefined method in_time_zone' for nil:NilClass app/helpers/date_time_helper.rb:39:insimple_date_html'

Backtrace:

  app/helpers/date_time_helper.rb:39:in `simple_date_html'
  app/helpers/date_time_helper.rb:26:in `simple_date'
  app/views/admin_general/_to_do_list.html.erb:41:in `block in _app_views_admin_general__to_do_list_html_erb__3946089989046291787_101897260'
  app/views/admin_general/_to_do_list.html.erb:15:in `_app_views_admin_general__to_do_list_html_erb__3946089989046291787_101897260'
  app/views/admin_general/index.html.erb:47:in `_app_views_admin_general_index_html_erb___1884788421399620715_101831480'
  app/controllers/application_controller.rb:120:in `record_memory'
  lib/strip_empty_sessions.rb:13:in `call'

Steps to reproduce

Open http://imamopravoznati.org/admin

Expected behavior

[garethrees]

https://github.com/mysociety/alaveteli/issues/4326

[schlos]

@garethrees @gbp Could you give me some more guidance how to resolve this?

I have tried by executing step in https://github.com/mysociety/alaveteli/issues/4326#issuecomment-521192751 but I got this:

$ bundle exec rails console
Loading production environment (Rails 4.2.11.1)
irb(main):001:0> Comment.where(attention_requested: true)
=> #<ActiveRecord::Relation []>
irb(main):002:0> Comment.where(attention_requested:true)
=> #<ActiveRecord::Relation []>

Thank you!

[garethrees]

Hey @schlos – sorry, completely missed this as notification came through to personal email rather than work.

What version of Alaveteli did this happen under?

At 0.33.0.0 (your current version), the stack trace doesn't point at lines of code that look like this problem.

1. app/views/admin_general/index.html.erb:47
2. app/views/admin_general/_to_do_list.html.erb:15
3. app/views/admin_general/_to_do_list.html.erb:41

[schlos]

Hi @garethrees It was detected on v0.30 - when trying to open http://imamopravoznati.org/admin.

On v0.33 I still cannot open http://imamopravoznati.org/admin but error handling has been changes, so instead of error 500 I see on a screen that error has been detected so I assumed it's same error as I didn't apply any fix with 0.30.

I've sent you new stack trace error for v0.33 directly to your email (mysociety).

Thanks!

[garethrees]

From the updated backtrace:

-------------------------------
Backtrace:
-------------------------------

app/helpers/date_time_helper.rb:39:in `simple_date_html'
app/helpers/date_time_helper.rb:26:in `simple_date'
app/views/admin_general/_to_do_list.html.erb:82:in `block in _app_views/admin_general__to_do_list_html_erb___548627704506515938_47059181074700'
app/views/admin_general/_to_do_list.html.erb:16:in `_app_views_admin_general__to_do_list_html_erb___548627704506515938_47059181074700'
app/views/admin_general/index.html.erb:30:in `_app_views_admin_general_index_html_erb__3933620253354528553_47059180686420'
app/controllers/application_controller.rb:120:in `record_memory'
lib/strip_empty_sessions.rb:13:in `call'

1. app/views/admin_general/index.html.erb:30: We're rendering "requests reported by users as requiring administrator attention"
2. app/views/admin_general/_to_do_list.html.erb:16: Iterating through each item
3. app/views/admin_general/_to_do_list.html.erb:82: Trying to render the Info Request's last_event_time, but simple_date is failing because it's being passed nil.

InfoRequest#last_event_time is a database attribute, so should be easy to locate the problem request:

InfoRequest.where(last_event_time: nil)

Now, why it's missing a last_event_time is interesting.

Might be similar to https://github.com/mysociety/alaveteli/issues/4326, but the line numbers don't match so could be a subtly different problem.

Assuming the above query only returns one request, perhaps paste the output of the following:

info_request = InfoRequest.where(last_event_time: nil).first

info_request.described_sate

info_request.info_request_events.pluck(:event_type)

[schlos]

Hi @garethrees it looks there could be multiple requests with this issue:

Loading production environment (Rails 4.2.11.1)
irb(main):001:0> InfoRequest.where(last_event_time: nil)
=> #<ActiveRecord::Relation [#<InfoRequest id: 561, title: "Popis imovine Grada Zagreba", user_id: 7, public_body_id: 12573, created_at: "2015-07-21 07:26:57", updated_at: "2019-11-06 22:28:54", described_state: "rejected", awaiting_description: false, prominence: "normal", url_title: "popis_imovine_grada_zagreba", law_used: "foi", allow_new_responses_from: "nobody", handle_rejected_responses: "bounce", idhash: "11834bf2", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: "2015-08-26 12:34:08", reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 1167, title: "Test-ing", user_id: 1, public_body_id: 33716, created_at: "2016-04-28 22:41:20", updated_at: "2016-05-08 21:28:01", described_state: "user_withdrawn", awaiting_description: false, prominence: "hidden", url_title: "test_ing_2", law_used: "foi", allow_new_responses_from: "nobody", handle_rejected_responses: "bounce", idhash: "dd206ed5", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: nil, reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 1146, title: "Broj turista u 2015.", user_id: 8, public_body_id: 12580, created_at: "2016-04-15 22:40:14", updated_at: "2016-04-18 20:20:30", described_state: "successful", awaiting_description: false, prominence: "normal", url_title: "broj_turista_u_2015", law_used: "foi", allow_new_responses_from: "nobody", handle_rejected_responses: "bounce", idhash: "58032124", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: "2016-04-18 06:41:09", reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 6374, title: "Kontrola odvezenog otpada", user_id: 544, public_body_id: 31037, created_at: "2018-02-04 09:00:19", updated_at: "2018-02-04 09:00:20", described_state: "waiting_response", awaiting_description: false, prominence: "normal", url_title: "kontrola_odvezenog_otpada_3", law_used: "foi", allow_new_responses_from: "authority_only", handle_rejected_responses: "bounce", idhash: "717c430e", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: 29, last_public_response_at: nil, reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 1166, title: "Test", user_id: 1, public_body_id: 33716, created_at: "2016-04-27 06:36:22", updated_at: "2016-05-08 21:28:24", described_state: "not_held", awaiting_description: false, prominence: "hidden", url_title: "test", law_used: "foi", allow_new_responses_from: "nobody", handle_rejected_responses: "bounce", idhash: "5ba15e56", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: "2016-04-27 06:43:11", reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 1009, title: "Ugovor za sustav za automatku naplatu prijevoza - ...", user_id: 7, public_body_id: 12941, created_at: "2016-02-04 09:32:16", updated_at: "2017-11-11 10:43:05", described_state: "successful", awaiting_description: false, prominence: "normal", url_title: "ugovor_za_sustav_za_automatku_na", law_used: "foi", allow_new_responses_from: "authority_only", handle_rejected_responses: "holding_pen", idhash: "e43a1f4b", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: "2017-11-09 09:47:03", reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 1005, title: "Popis Turističkih Agencija", user_id: 222, public_body_id: 12574, created_at: "2016-01-31 17:23:03", updated_at: "2016-03-09 10:39:19", described_state: "rejected", awaiting_description: false, prominence: "normal", url_title: "popis_turistickih_agencija", law_used: "foi", allow_new_responses_from: "nobody", handle_rejected_responses: "bounce", idhash: "31ad3521", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: "2016-02-16 19:40:24", reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 1011, title: "Ugovor za nadogradnju fare on aplikacije", user_id: 7, public_body_id: 12941, created_at: "2016-02-04 09:35:25", updated_at: "2017-11-11 10:43:31", described_state: "successful", awaiting_description: false, prominence: "normal", url_title: "ugovor_za_nadogradnju_fare_on_ap", law_used: "foi", allow_new_responses_from: "authority_only", handle_rejected_responses: "bounce", idhash: "226269f4", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: "2016-02-12 14:35:19", reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 3659, title: "Kapacitet i popunjenost vrtića", user_id: 313, public_body_id: 29105, created_at: "2017-03-26 12:01:44", updated_at: "2017-03-26 12:11:26", described_state: "waiting_response", awaiting_description: false, prominence: "normal", url_title: "kapacitet_i_popunjenost_vrtica_428", law_used: "foi", allow_new_responses_from: "nobody", handle_rejected_responses: "bounce", idhash: "85dc2c8f", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: 19, last_public_response_at: nil, reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, #<InfoRequest id: 493, title: "Isplata jednokratnih sredstava za samozapošljavanj...", user_id: 87, public_body_id: 30181, created_at: "2015-06-11 12:05:37", updated_at: "2015-07-09 19:06:46", described_state: "successful", awaiting_description: false, prominence: "normal", url_title: "isplata_jednokratnih_sredstava_z", law_used: "foi", allow_new_responses_from: "nobody", handle_rejected_responses: "bounce", idhash: "d2c4b7b6", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: "2015-06-16 08:41:57", reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>, ...]>

Here is the first one:

irb(main):002:0> info_request = InfoRequest.where(last_event_time: nil).first
=> #<InfoRequest id: 13, title: "Broj turista u 2014. godini", user_id: 8, public_body_id: 12848, created_at: "2015-04-11 23:42:42", updated_at: "2019-11-06 22:22:40", described_state: "user_withdrawn", awaiting_description: false, prominence: "normal", url_title: "broj_turista_u_2014_godini", law_used: "foi", allow_new_responses_from: "nobody", handle_rejected_responses: "bounce", idhash: "5ac703d1", external_user_name: nil, external_url: nil, attention_requested: false, comments_allowed: true, info_request_batch_id: nil, last_public_response_at: "2015-04-11 23:42:48", reject_incoming_at_mta: false, rejected_incoming_count: 0, date_initial_request_last_sent_at: nil, date_response_required_by: nil, date_very_overdue_after: nil, last_event_forming_initial_request_id: nil, use_notifications: false, last_event_time: nil, incoming_messages_count: 0>

irb(main):004:0> info_request.described_state
=> "user_withdrawn"

irb(main):005:0> info_request.info_request_events.pluck(:event_type)
=> ["sent", "response", "status_update", "edit_incoming", "resent", "edit_incoming", "status_update", "resent", "status_update", "followup_sent", "edit", "edit"]

[garethrees]

That's pretty strange. I can't see why you'd have a request with all sorts of events, and yet not have a last_event_time set on the request.

I guess what you could do here is just manually set the last_event_time for requests with events, and see what you're left with:

InfoRequest.where(last_event_time: nil).each do |info_request|
  next if info_request.info_request_events.count.zero?
  info_request.update_column(:last_event_time, info_request.info_request_events.last.created_at)
end

[schlos]

Fixed, so closing. Not reproducible with v0.39.x.x.