[ERROR] info_requests#index (RuntimeError) internal error, last_event_forming_initial_request

[garethrees]

Like https://github.com/mysociety/alaveteli/issues/3131#issuecomment-219404742, the request loads now.

I think what's happened is that the request has appeared in the dashboard before the batch has managed to finish sending.

A RuntimeError occurred in info_requests#index:

internal error, last_event_forming_initial_request gets nil for request 577145 outgoing messages count 1 all events: ---
- !ruby/object:InfoRequestEvent
raw_attributes:
info_request_id: '577145'
described_state:
event_type: set_embargo
id: '4574119'
params_yaml: |
---
:embargo_id: 33162
created_at: '2019-05-17 14:33:59.925658'
calculated_state:
last_described_at:
incoming_message_id:
outgoing_message_id:
comment_id:
updated_at: '2019-05-17 14:33:59.925658'
attributes: !ruby/object:ActiveRecord::AttributeSet
attributes: !ruby/object:ActiveRecord::LazyAttributeHash
types:
id: &1 !ruby/object:ActiveRecord::ConnectionAdapters::PostgreSQL::OID::Integer
precision:
scale:
limit:
range: !ruby/range
begin: -2147483648
end: 2147483648
excl: true
info_request_id: *1
event_type: &2 !ruby/object:ActiveRecord::Type::Text
precision:
scale:
limit:
params_yaml: *2
created_at: &5 !ruby/object:ActiveRecord::AttributeMethods::TimeZoneConversion::TimeZoneConverter
subtype: &4 !ruby/object:ActiveRecord::ConnectionAdapters::PostgreSQL::OID::DateTime
precision:
scale:
limit:
described_state: &3 !ruby/object:ActiveRecord::Type::String
precision:
scale:
limit: 255
calculated_state: *3
last_described_at: &6 !ruby/object:ActiveRecord::AttributeMethods::TimeZoneConversion::TimeZoneConverter
subtype: *4
incoming_message_id: *1
outgoing_message_id: *1
comment_id: *1
updated_at: &7 !ruby/object:ActiveRecord::AttributeMethods::TimeZoneConversion::TimeZoneConverter
subtype: *4
values:
id: '4574119'
info_request_id: '577145'
event_type: set_embargo
params_yaml: |
---
:embargo_id: 33162
created_at: '2019-05-17 14:33:59.925658'
described_state:
calculated_state:
last_described_at:
incoming_message_id:
outgoing_message_id:
comment_id:
updated_at: '2019-05-17 14:33:59.925658'
additional_types: {}
materialized: true
delegate_hash:
info_request_id: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: info_request_id
value_before_type_cast: '577145'
type: *1
value: 577145
described_state: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: described_state
value_before_type_cast:
type: *3
value:
event_type: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: event_type
value_before_type_cast: set_embargo
type: *2
value: set_embargo
id: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: id
value_before_type_cast: '4574119'
type: *1
params_yaml: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: params_yaml
value_before_type_cast: |
---
:embargo_id: 33162
type: *2
created_at: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: created_at
value_before_type_cast: '2019-05-17 14:33:59.925658'
type: *5
calculated_state: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: calculated_state
value_before_type_cast:
type: *3
last_described_at: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: last_described_at
value_before_type_cast:
type: *6
incoming_message_id: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: incoming_message_id
value_before_type_cast:
type: *1
outgoing_message_id: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: outgoing_message_id
value_before_type_cast:
type: *1
comment_id: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: comment_id
value_before_type_cast:
type: *1
updated_at: !ruby/object:ActiveRecord::Attribute::FromDatabase
name: updated_at
value_before_type_cast: '2019-05-17 14:33:59.925658'
type: *7
new_record: false
active_record_yaml_version: 0

app/models/info_request.rb:1098:in `last_event_forming_initial_request'

-------------------------------
Request:
-------------------------------

* URL : https://www.whatdotheyknow.com/alaveteli_pro/info_requests
* HTTP Method: GET
* Parameters : {"controller"=>"alaveteli_pro/info_requests", "action"=>"index"}
* Timestamp : 2019-05-17 15:34:00 +0100
* Rails root : /REDACTED/alaveteli-2019-05-07T08-58-21

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

app/models/info_request.rb:1098:in `last_event_forming_initial_request'
app/models/info_request.rb:1168:in `calculate_date_initial_request_last_sent_at'
app/models/info_request.rb:1162:in `date_initial_request_last_sent_at'
app/models/info_request.rb:1199:in `calculate_date_very_overdue_after'
app/models/info_request.rb:1195:in `date_very_overdue_after'
app/models/info_request.rb:1022:in `base_calculate_status'
app/models/info_request.rb:1014:in `calculate_status'
app/models/info_request/state/calculator.rb:14:in `phase'
app/models/info_request/state/calculator.rb:103:in `summarised_phase'
app/views/alaveteli_pro/info_request_batches/_info_request.html.erb:9:in `_app_views_alaveteli_pro_info_request_batches__info_request_html_erb__2000388208106578224_70324026593740'
app/views/alaveteli_pro/info_request_batches/_info_request_batch.html.erb:20:in `_app_views_alaveteli_pro_info_request_batches__info_request_batch_html_erb__139939177881176916_70324126047080'
app/views/alaveteli_pro/info_requests/_request_list.html.erb:53:in `_app_views_alaveteli_pro_info_requests__request_list_html_erb__4426499032876188932_70324030008220'
app/views/alaveteli_pro/info_requests/index.html.erb:20:in `_app_views_alaveteli_pro_info_requests_index_html_erb___4501357434823318732_70324046772280'
app/controllers/application_controller.rb:115:in `record_memory'
lib/strip_empty_sessions.rb:13:in `call'

[garethrees]

Had another of these

[gbp]

Seeing this in Sweden

[gbp]

Steps to attempt a manual resend:

# find request
info_request = InfoRequest.find(id)

# find outgoing message
outgoing_message = info_request.outgoing_messages.first

# create mail
mail_message = OutgoingMailer.initial_request(
  outgoing_message.info_request,
  outgoing_message
)

# deliver mail
mail_message.deliver_now

# record delivery
outgoing_message.record_email_delivery(
  mail_message.to_addrs.join(', '),
  mail_message.message_id
)

[gbp]

We experienced an issue with a deploy yesterday which prevented mails from being sent.

unsent_requests = InfoRequest.where(created_at: (Date.yesterday...)).reject { |r| r.last_event_forming_initial_request rescue false }
unsent_requests.count #=> 15

unsent_requests.each do |info_request|
  # find outgoing message
  outgoing_message = info_request.outgoing_messages.first

  # create mail
  mail_message = OutgoingMailer.initial_request(
    outgoing_message.info_request,
    outgoing_message
  )

  # deliver mail
  mail_message.deliver_now

  # record delivery
  outgoing_message.record_email_delivery(
    mail_message.to_addrs.join(', '),
    mail_message.message_id
  )
end