Add heisenbug logging that prints to STDOUT in the cases we know of

That way, we can get a little more information when these tests fail on Travis, which appears to be the only place they ever fail. See notes in Issue hotsh#479.

test/acceptance/acceptance_helper.rb

@@ -142,4 +142,37 @@ def search_for(query)
     fill_in "search", :with => query
     click_button "Search"
   end
+
+  def heisenbug_log
+    old_rails_logger = Rails.logger
+    old_action_controller_logger = ActionController::Base.logger
+
+    logfile = 'log/heisenbug.log'
+    new_logger = Logger.new(logfile)
+    new_logger.level = Logger::DEBUG
+
+    Rails.logger = new_logger
+    ActionController::Base.logger = new_logger
+
+    begin
+      yield
+    rescue Heisenbug
+      puts
+      puts "Start of Heisenbug logging ======================================"
+      puts File.read logfile
+      puts "================"
+      puts body
+      puts "End of Heisenbug logging ========================================"
+      puts
+      puts "Congratulations!! You've seen an incidence of a HEISENBUG we're"
+      puts "tracking. Please copy the output from Start to End and paste it"
+      puts "in a comment on https://github.com/hotsh/rstat.us/issues/479"
+    ensure
+      File.delete logfile
+      Rails::logger = old_rails_logger
+      ActionController::Base.logger = old_action_controller_logger
+    end
+  end
 end
+
+class Heisenbug < StandardError; end

test/acceptance/following_test.rb

@@ -30,18 +30,25 @@
     end
 
     it "unfollows another user" do
-      log_in_as_some_user
+      heisenbug_log do
+        log_in_as_some_user
 
-      u2 = Fabricate(:user)
-      a2 = Fabricate(:authorization, :user => u2)
+        u2 = Fabricate(:user)
+        a2 = Fabricate(:authorization, :user => u2)
 
-      @u.follow! u2.feed
+        @u.follow! u2.feed
 
-      visit "/users/#{@u.username}/following"
-      click_button "unfollow-#{u2.feed.id}"
+        visit "/users/#{@u.username}/following"
+
+        if has_button? "unfollow-#{u2.feed.id}"
+          click_button "unfollow-#{u2.feed.id}"
+        else
+          raise Heisenbug
+        end
 
-      within flash do
-        assert has_content? "No longer following #{u2.username}"
+        within flash do
+          assert has_content? "No longer following #{u2.username}"
+        end
       end
     end
   end

test/acceptance/profile_test.rb

@@ -20,20 +20,26 @@
   end
 
   it "has the user's updates on the page in reverse chronological order" do
-    u = Fabricate(:user)
-    update1 = Fabricate(:update,
-                      :text       => "This is a message posted yesterday",
-                      :author     => u.author,
-                      :created_at => 1.day.ago)
-    update2 = Fabricate(:update,
-                      :text       => "This is a message posted last week",
-                      :author     => u.author,
-                      :created_at => 1.week.ago)
-    u.feed.updates << update1
-    u.feed.updates << update2
-
-    visit "/users/#{u.username}"
-    assert_match /#{update1.text}.*#{update2.text}/m, page.body
+    heisenbug_log do
+      u = Fabricate(:user)
+      update1 = Fabricate(:update,
+                        :text       => "This is a message posted yesterday",
+                        :author     => u.author,
+                        :created_at => 1.day.ago)
+      update2 = Fabricate(:update,
+                        :text       => "This is a message posted last week",
+                        :author     => u.author,
+                        :created_at => 1.week.ago)
+      u.feed.updates << update1
+      u.feed.updates << update2
+
+      visit "/users/#{u.username}"
+      if page.body.match /#{update1.text}.*#{update2.text}/m
+        assert_match /#{update1.text}.*#{update2.text}/m, page.body
+      else
+        raise Heisenbug
+      end
+    end
   end
 
   it "responds with HTML by default if Accept header is */*" do

test/acceptance/update_test.rb

@@ -125,24 +125,36 @@
     end
 
     it "destroys own update" do
-      visit "/users/#{@u.username}"
-      click_button "I Regret This"
-
-      within 'div.flash' do
-        assert has_content? "Update Deleted!"
+      heisenbug_log do
+        visit "/users/#{@u.username}"
+        if has_button? "I Regret This"
+          click_button "I Regret This"
+        else
+          raise Heisenbug
+        end
+
+        within 'div.flash' do
+          assert has_content? "Update Deleted!"
+        end
       end
     end
 
     it "doesn't destroy not own update" do
-      author = Fabricate(:author)
-      visit "/users/#{@u.username}"
+      heisenbug_log do
+        author = Fabricate(:author)
+        visit "/users/#{@u.username}"
 
-      Update.any_instance.stubs(:author).returns(author)
+        Update.any_instance.stubs(:author).returns(author)
 
-      click_button "I Regret This"
+        if has_button? "I Regret This"
+          click_button "I Regret This"
+        else
+          raise Heisenbug
+        end
 
-      within 'div.flash' do
-        assert has_content? "I'm afraid I can't let you do that, #{@u.username}."
+        within 'div.flash' do
+          assert has_content? "I'm afraid I can't let you do that, #{@u.username}."
+        end
       end
     end
   end
@@ -156,17 +168,33 @@
     end
 
     it "clicks the reply link from update on a user's page" do
-      visit "/users/#{@u2.username}"
-      click_link "reply"
-      assert_match "What's Going On?", page.body
-      assert_match "foo", page.body
+      heisenbug_log do
+        visit "/users/#{@u2.username}"
+
+        if has_link? "reply"
+          click_link "reply"
+        else
+          raise Heisenbug
+        end
+
+        assert_match "What's Going On?", page.body
+        assert_match "foo", page.body
+      end
     end
 
     it "clicks the share link from update on a user's page" do
-      visit "/users/#{@u2.username}"
-      click_link "share"
-      assert_match "What's Going On?", page.body
-      assert_match "RS @#{@u2.username}: #{@u2.feed.updates.last.text}", page.body
+      heisenbug_log do
+        visit "/users/#{@u2.username}"
+
+        if has_link? "share"
+          click_link "share"
+        else
+          raise Heisenbug
+        end
+
+        assert_match "What's Going On?", page.body
+        assert_match "RS @#{@u2.username}: #{@u2.feed.updates.last.text}", page.body
+      end
     end
   end