spinosa commented 12 years ago

Need to log and investigate why this is happening...

Does this happen when this fiber has created the public roll?
Is the upvoted_roll_id correct?
Is the upvoted_roll_id even set?
Why doesn't this fail earlier? (maybe it's save==false and
Did we set the upvoted_roll_id or did that come from another fiber?
Is this a GET or a CREATE faux user? (my assumption was that this happens on faux user create and it's a timing thing)

Once we have this fixed, might want to remove the sleep that was put in to get_or_create_faux_user

[2012-07-20 06:20:32.173] FATAL  [Arnold Main Fiber] unhandled exception undefined method `public?' for nil:NilClass / BACKTRACE: 
/home/gt/shelby_gt/releases/20120718011734/lib/gt/user_manager.rb:214:in `ensure_users_special_rolls'
/home/gt/shelby_gt/releases/20120718011734/lib/gt/user_manager.rb:123:in `get_or_create_faux_user'
/home/gt/shelby_gt/releases/20120718011734/lib/gt/social_sorter.rb:115:in `get_or_create_posting_user_for'
/home/gt/shelby_gt/releases/20120718011734/lib/gt/social_sorter.rb:31:in `sort'
/home/gt/shelby_gt/releases/20120718011734/lib/gt/arnold/job_processor.rb:85:in `block (2 levels) in process_job'
/home/gt/shelby_gt/releases/20120718011734/lib/gt/arnold/job_processor.rb:85:in `each'
/home/gt/shelby_gt/releases/20120718011734/lib/gt/arnold/job_processor.rb:85:in `block in process_job'
/home/gt/shelby_gt/releases/20120718011734/lib/gt/arnold/job_processor.rb:18:in `each'
/home/gt/shelby_gt/releases/20120718011734/lib/gt/arnold/job_processor.rb:18:in `process_job'
./lib/gt/arnold/arnold_gt.rb:87:in `block (3 levels) in <main>'

spinosa commented 12 years ago

running test code on GT1 and GT2 (lots of extra logging at ERROR level)...

spinosa commented 12 years ago

Got one in action. This is illuminating, but I want more details. Going to make that happen now

WHAT HAPPENED:

User was created a long time ago, didn't have the upvoted roll (same for WL)
Ensure special rolls was called (save==true)
The upvoted roll should have been created and the user saved, but that didn't actually happen, so i'm running more tests with more logging in that area

[2012-07-20 17:11:37.540] ERROR  0.11651347346374363 get_or_create_faux_user 
    FOUND user 4f9dc64a88ba6b0d690003f4 (created at 2012-04-29 22:52:58 UTC) with upvoted_roll_id  and upvoted_roll  find retruns 
[2012-07-20 17:11:37.542] ERROR  0.11651347346374363 get_or_create_faux_user 
    did NOT reload user 4f9dc64a88ba6b0d690003f4 (created at 2012-04-29 22:52:58 UTC) with upvoted_roll_id  and upvoted_roll  find retruns 
[2012-07-20 17:11:37.583] FATAL  0.11651347346374363 get_or_create_faux_user 
    EXCEPTION thrown (re-raising) // user 4f9dc64a88ba6b0d690003f4 (created at 2012-04-29 22:52:58 UTC) with upvoted_roll_id  and upvoted_roll  find retruns 
[2012-07-20 17:11:37.583] FATAL  [GT::SocialSorter#get_or_create_posting_user_for] rescued but re-raising undefined method `public?' for nil:NilClass for message #<Message _id: BSON::ObjectId('50099149d1041229f4001ee9'), nickname: "hellogames", origin_id: "226363585138413570", origin_network: "twitter", origin_user_id: "57903424", public: true, realname: "Hello Games", text: "It's been raining a lot here, this makes us feel better about it : http://t.co/1otd4uS0", user_id: nil, user_image_url: "http://a0.twimg.com/profile_images/1691346410/Hello_normal.jpg">

[2012-07-20 17:11:37.583] FATAL  [Arnold Main Fiber] unhandled exception undefined method `public?' for nil:NilClass / BACKTRACE: 
/home/gt/shelby_gt/releases/20120720165637/lib/gt/user_manager.rb:235:in `ensure_users_special_rolls'
/home/gt/shelby_gt/releases/20120720165637/lib/gt/user_manager.rb:140:in `get_or_create_faux_user'
/home/gt/shelby_gt/releases/20120720165637/lib/gt/social_sorter.rb:115:in `get_or_create_posting_user_for'
/home/gt/shelby_gt/releases/20120720165637/lib/gt/social_sorter.rb:31:in `sort'
/home/gt/shelby_gt/releases/20120720165637/lib/gt/arnold/job_processor.rb:85:in `block (2 levels) in process_job'
/home/gt/shelby_gt/releases/20120720165637/lib/gt/arnold/job_processor.rb:85:in `each'
/home/gt/shelby_gt/releases/20120720165637/lib/gt/arnold/job_processor.rb:85:in `block in process_job'
/home/gt/shelby_gt/releases/20120720165637/lib/gt/arnold/job_processor.rb:18:in `each'
/home/gt/shelby_gt/releases/20120720165637/lib/gt/arnold/job_processor.rb:18:in `process_job'
./lib/gt/arnold/arnold_gt.rb:87:in `block (3 levels) in <main>'

spinosa commented 12 years ago

running even more logging on GT1,2,3 (want to grep for FATAL and probably print ~10 lines before and ~3 lines after)

spinosa commented 12 years ago

User's upvoted roll does get created, and the creator is the user, but it gets lost. That is, the user does not follow it, and user.upvoted_roll does not point to it. It's orphaned in the DB.

Based on these logs:


[2012-07-20 19:56:38.581] ERROR  0.19153786464006273 get_or_create_faux_user FOUND user 4f9cb8289a725b2879000468 (created at 2012-04-29 03:40:24 UTC) with upvoted_roll_id  and upvoted_roll  find retruns 
[2012-07-20 19:56:38.583] ERROR  0.19153786464006273 get_or_create_faux_user did NOT reload user 4f9cb8289a725b2879000468 (created at 2012-04-29 03:40:24 UTC) with upvoted_roll_id  and upvoted_roll  find retruns 

[2012-07-20 19:56:38.605] ERROR  ensure_users_special_rolls 
    BUILT UPVOTED ROLL for user 4f9cb8289a725b2879000468 (created at 2012-04-29 03:40:24 UTC) NOW upvoted_roll_id 5009b7f69a725b25350080c0 and upvoted_roll #<Roll:0x00000007332488> find retruns #<Roll:0x000000073555a0>
[2012-07-20 19:56:38.612] ERROR  ensure_users_special_rolls 
    saved user 4f9cb8289a725b2879000468 returned val: true
[2012-07-20 19:56:38.614] ERROR  ensure_users_special_rolls 
    SAVED USER for user 4f9cb8289a725b2879000468 (created at 2012-04-29 03:40:24 UTC) NOW upvoted_roll_id 5009b7f69a725b25350080c0 and upvoted_roll #<Roll:0x00000007332488> find retruns #<Roll:0x000000073a82f0>
[2012-07-20 19:56:38.620] ERROR  ensure_users_special_rolls 
    RELOADED USER for user 4f9cb8289a725b2879000468 (created at 2012-04-29 03:40:24 UTC) NOW upvoted_roll_id  and upvoted_roll  find retruns 

[2012-07-20 19:56:38.621] FATAL  0.19153786464006273 get_or_create_faux_user EXCEPTION thrown (re-raising) // user 4f9cb8289a725b2879000468 (created at 2012-04-29 03:40:24 UTC) with upvoted_roll_id  and upvoted_roll  find retruns 
[2012-07-20 19:56:38.622] FATAL  [GT::SocialSorter#get_or_create_posting_user_for] rescued but re-raising must supply roll or roll_id for message #<Message _id: BSON::ObjectId('5009b7f69a725b25350080c4'), nickname: "billynewport", origin_id: "226405270950125570", origin_network: "twitter", origin_user_id: "6879192", public: true, realname: "Billy Newport", text: "Fun summer writing this game when I was in college.
Amiga Shooters with Ash #5 Phantom Fighter: http://t.co/RL9zwAxm via @youtube", user_id: nil, user_image_url: "http://a0.twimg.com/profile_images/454130240/Billy_Photo_Crop_normal.jpg">

[2012-07-20 19:56:38.622] FATAL  [Arnold Main Fiber] unhandled exception must supply roll or roll_id / BACKTRACE:
 /home/gt/shelby_gt/releases/20120720155124/app/models/user.rb:161:in `following_roll?'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/user_manager.rb:239:in `ensure_users_special_rolls'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/user_manager.rb:140:in `get_or_create_faux_user'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/social_sorter.rb:115:in `get_or_create_posting_user_for'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/social_sorter.rb:31:in `sort'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/arnold/job_processor.rb:85:in `block (2 levels) in process_job'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/arnold/job_processor.rb:85:in `each'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/arnold/job_processor.rb:85:in `block in process_job'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/arnold/job_processor.rb:18:in `each'
/home/gt/shelby_gt/releases/20120720155124/lib/gt/arnold/job_processor.rb:18:in `process_job'
./lib/gt/arnold/arnold_gt.rb:87:in `block (3 levels) in <main>'

spinosa commented 12 years ago

Bug

Fiber A gets user U (with nil upvoted_roll_id)
Fiber B gets user U (with nil upvoted_roll_id)
Fiber B creates upvoted roll R, sets it on U, saves U
Fiber A saves U with nil upvoted_roll_id, overriding R
Fiber B reloads U (possibly via add_follower), expects R but find it's nil... BOOM!

Options To Fix

Version the user object
Only do updates of the user in Arnold, not full saves (difficult b/c mongo_mapper saves when we're not aware)
Ensure special rolls on all faux users; keep sleep + reload on user creation (simple, but not a general solution)
other?

ShelbyTV / shelby_gt

NPE in Arnold #124

Bug

Options To Fix