Milestones with wrong organization_id

[ttapers]

Mark, what happened between 03:00:37 and 03:02:55 (10:00:37pm and 10:02:55pm CST) last night?

Here's Chicago Urban League's Milestones:

<Milestone id: 640, time_unit_id: 71, created_at: "2014-10-01 00:17:27"> <Milestone id: 641, time_unit_id: 71, created_at: "2014-10-01 00:18:30"> <Milestone id: 642, time_unit_id: 71, created_at: "2014-10-01 00:18:57"> <Milestone id: 644, time_unit_id: 71, created_at: "2014-10-01 00:20:08"> <Milestone id: 643, time_unit_id: 71, created_at: "2014-10-01 00:19:58"> <Milestone id: 645, time_unit_id: 72, created_at: "2014-10-01 00:20:32"> <Milestone id: 646, time_unit_id: 72, created_at: "2014-10-01 00:20:55"> <Milestone id: 649, time_unit_id: 71, created_at: "2014-10-01 00:23:53"> <Milestone id: 651, time_unit_id: 71, created_at: "2014-10-01 00:25:56"> <Milestone id: 653, time_unit_id: 71, created_at: "2014-10-01 00:27:20"> <Milestone id: 654, time_unit_id: 71, created_at: "2014-10-01 00:27:57"> <Milestone id: 655, time_unit_id: 71, created_at: "2014-10-01 00:28:28"> <Milestone id: 656, time_unit_id: 71, created_at: "2014-10-01 00:29:02"> <Milestone id: 657, time_unit_id: 71, created_at: "2014-10-01 00:29:26"> <Milestone id: 662, time_unit_id: 71, created_at: "2014-10-01 00:34:06"> <Milestone id: 664, time_unit_id: 72, created_at: "2014-10-01 00:35:22"> <Milestone id: 666, time_unit_id: 72, created_at: "2014-10-01 00:36:23"> <Milestone id: 668, time_unit_id: 71, created_at: "2014-10-01 00:39:30"> <Milestone id: 669, time_unit_id: 71, created_at: "2014-10-01 00:40:06"> <Milestone id: 672, time_unit_id: 71, created_at: "2014-10-01 00:53:59"> <Milestone id: 648, time_unit_id: 71, created_at: "2014-10-01 00:23:05"> <Milestone id: 675, time_unit_id: 71, created_at: "2014-10-01 00:57:28"> <Milestone id: 661, time_unit_id: 72, created_at: "2014-10-01 00:33:14"> <Milestone id: 658, time_unit_id: 71, created_at: "2014-10-01 00:30:06"> <Milestone id: 660, time_unit_id: 72, created_at: "2014-10-01 00:32:18"> <Milestone id: 663, time_unit_id: 72, created_at: "2014-10-01 00:35:05"> <Milestone id: 665, time_unit_id: 72, created_at: "2014-10-01 00:35:40"> <Milestone id: 667, time_unit_id: 71, created_at: "2014-10-01 00:38:54"> <Milestone id: 670, time_unit_id: 71, created_at: "2014-10-01 00:40:48"> <Milestone id: 671, time_unit_id: 71, created_at: "2014-10-01 00:53:21"> <Milestone id: 647, time_unit_id: 71, created_at: "2014-10-01 00:21:53"> <Milestone id: 674, time_unit_id: 71, created_at: "2014-10-01 00:57:03"> <Milestone id: 676, time_unit_id: 71, created_at: "2014-10-01 00:57:57"> <Milestone id: 678, time_unit_id: 71, created_at: "2014-10-01 00:59:01"> <Milestone id: 681, time_unit_id: 71, created_at: "2014-10-01 01:00:21"> <Milestone id: 682, time_unit_id: 71, created_at: "2014-10-01 02:55:45"> <Milestone id: 683, time_unit_id: 71, created_at: "2014-10-01 02:57:08"> <Milestone id: 650, time_unit_id: 72, created_at: "2014-10-01 00:24:39"> <Milestone id: 659, time_unit_id: 72, created_at: "2014-10-01 00:30:53"> <Milestone id: 673, time_unit_id: 71, created_at: "2014-10-01 00:55:17"> <Milestone id: 679, time_unit_id: 71, created_at: "2014-10-01 00:59:26"> <Milestone id: 684, time_unit_id: 72, created_at: "2014-10-01 02:59:14"> <Milestone id: 677, time_unit_id: 71, created_at: "2014-10-01 00:58:26"> <Milestone id: 680, time_unit_id: 71, created_at: "2014-10-01 00:59:53"> <Milestone id: 685, time_unit_id: 72, created_at: "2014-10-01 03:00:37">

Here's the last few from Hoku: ...

<Milestone id: 350, time_unit_id: 15, created_at: "2014-08-18 22:02:49"> <Milestone id: 353, time_unit_id: 10, created_at: "2014-08-18 22:05:34"> <Milestone id: 351, time_unit_id: 9, created_at: "2014-08-18 22:04:02"> <Milestone id: 352, time_unit_id: 9, created_at: "2014-08-18 22:04:35"> <Milestone id: 354, time_unit_id: 10, created_at: "2014-08-18 22:06:13"> <Milestone id: 355, time_unit_id: 11, created_at: "2014-08-18 22:06:47"> <Milestone id: 356, time_unit_id: 11, created_at: "2014-08-18 22:07:16"> <Milestone id: 357, time_unit_id: 11, created_at: "2014-08-18 22:07:58"> <Milestone id: 687, time_unit_id: 72, created_at: "2014-10-01 03:03:56"> <Milestone id: 688, time_unit_id: 72, created_at: "2014-10-01 03:04:34"> <Milestone id: 690, time_unit_id: 72, created_at: "2014-10-01 03:05:28"> <Milestone id: 693, time_unit_id: 72, created_at: "2014-10-01 03:06:56"> <Milestone id: 686, time_unit_id: 72, created_at: "2014-10-01 03:02:55"> <Milestone id: 689, time_unit_id: 72, created_at: "2014-10-01 03:05:12"> <Milestone id: 691, time_unit_id: 72, created_at: "2014-10-01 03:05:55"> <Milestone id: 692, time_unit_id: 72, created_at: "2014-10-01 03:06:32">

[neelbhat88]

Yeah Mark, when we tell you to QA something you don't have to go and cause weird things like this to happen jeez

[neelbhat88]

Still no idea how this could have happened but I ran the following in prod DB and looks like its just those 8 that are in this state:

x = Milestone.includes(:time_unit) x.select {|x| x.organization_id != x.time_unit.organization_id}

If I did that right that will get all milestones joined to the TimeUnit table on milestone.time_unit_id = time_unit.id (the include might run the SQL statement slightly different depending on optimization) which gives us all milestones with all the associated time_unit columns all together. We can then loop over that list and find the ones where the milestone's org_id does not match the corresponding time_unit's org_id field. Good news: grand total = 8, and we can change those back. Bad news: Still no idea what could have caused that...

[neelbhat88]

This is interesting - here are the paper trail logs:

Sep 30 22:03:38 imua app/web.1: Started PUT "/api/v1/milestone/661" for 205.178.113.32 at 2014-10-01 03:03:38 +0000 Sep 30 22:03:38 imua app/web.1: Processing by Api::V1::MilestoneController#update_milestone as HTML Sep 30 22:03:38 imua app/web.1: Parameters: {"milestone"=>{"id"=>661, "title"=>"College Prep Goal", "description"=>"Description:", "module"=>"College_Prep", "submodule"=>"YesNo", "points"=>10, "value"=>"Submit a Copy of Scholarship Letter (From Each College or Other Sources) by 3/7", "icon"=>"/assets/PDU.jpg", "time_unit_id"=>72}, "id"=>"661"} --> A milestone that belongs in the correct org being edited Sep 30 22:03:38 imua app/web.1: Completed 200 OK in 26ms (Views: 0.4ms | ActiveRecord: 17.2ms) Sep 30 22:03:39 imua heroku/router: at=info method=HEAD path="/" host=www.myimua.org request_id=1d19e6ec-d638-460d-acb2-d049a026942c fwd="50.31.164.139" dyno=web.1 connect=1ms service=11ms status=200 bytes=745 Sep 30 22:03:39 imua app/web.1: Processing by StaticController#index as */*\ -> whaaaa? This looks like a login for some reason Sep 30 22:03:39 imua app/web.1: Started GET "/" for 50.31.164.139 at 2014-10-01 03:03:39 +0000 Sep 30 22:03:39 imua app/web.1: Rendered static/index.html.erb within layouts/application (0.0ms) Sep 30 22:03:39 imua app/web.1: Completed 200 OK in 4ms (Views: 1.8ms | ActiveRecord: 0.8ms) Sep 30 22:03:57 imua heroku/router: at=info method=POST path="/api/v1/milestone" host=www.myimua.org request_id=15c3453f-3be5-4fff-bca6-0182f92e8b54 fwd="205.178.113.32" dyno=web.1 connect=1ms service=19ms status=200 bytes=676 Sep 30 22:03:57 imua app/web.1: Started POST "/api/v1/milestone" for 205.178.113.32 at 2014-10-01 03:03:56 +0000** --> This is one of the ones that got set to the wrong org ID Sep 30 22:03:57 imua app/web.1: Processing by Api::V1::MilestoneController#create_milestone as HTML Sep 30 22:03:57 imua app/web.1: Parameters: {"milestone"=>{"id"=>nil, "module"=>"College_Prep", "submodule"=>"YesNo", "title"=>"College Prep Goal", "description"=>"Description:", "value"=>"Attend Workshop: Creating A College Budget on 3/7", "time_unit_id"=>72, "importance"=>1, "points"=>10, "icon"=>"/assets/PDU.jpg", "earned"=>false, "organization_id"=>nil, "is_default"=>false}} Sep 30 22:03:57 imua app/web.1: Completed 200 OK in 12ms (Views: 0.4ms | ActiveRecord: 6.3ms)

[neelbhat88]

Now Heroku did send out some emails early this morning around 5am (https://status.heroku.com/incidents/668) about some potential connectivity issues. The issue we saw happened at 10pm the night before but maybe it's related and Heroku noticed the issues later on? I'm not sure why it would re-login though since the session until this mornings prod push would never expire unless you deleted your cookies or you physically logged out. Maybe the last thing to do is look on NASA's site to see if there are any recordings of massive solar flares around 10pm last night..

[neelbhat88]

No go on that last theory: http://lmgtfy.com/?q=solar+flare+september+30+2014

[ttapers]

http://www.tesis.lebedev.ru/en/sun_flares.html?m=9&d=30&y=2014

Alright, I'm adding this to the list of graphs to check - right next to new relic.

On Oct 1, 2014, at 11:27 PM, neelbhat88 notifications@github.com wrote:

No go on that last theory: http://lmgtfy.com/?q=solar+flare+september+30+2014

— Reply to this email directly or view it on GitHub.

[ttapers]

Milestone creation has been fixed such that it shouldn't be possible to get in that state if this weird login thing ever happens again. Still need to repair the db entries in production - this command seemed to work fine for me on local:

x.select {|x| x.organization_id != x.time_unit.organization_id}.each {|m| m.update_attribute(:organization_id, m.time_unit.organization_id)}

[neelbhat88]

Updated the DB. Hopefully this doesn't show up again..