Fix and test retrying logic, send error emails

app/lib/LevelLoader.coffee

@@ -11,6 +11,7 @@ AudioPlayer = require 'lib/AudioPlayer'
 app = require 'core/application'
 World = require 'lib/world/world'
 utils = require 'core/utils'
+{sendContactMessage} = require 'core/contact'
 
 LOG = false
 
@@ -25,6 +26,8 @@ LOG = false
 # LevelLoader depends on SuperModel retrying timed out requests, as these occasionally happen during play.
 # If LevelLoader ever moves away from SuperModel, it will have to manage its own retries.
 
+reportedLoadErrorAlready = false
+
 module.exports = class LevelLoader extends CocoClass
 
   constructor: (options) ->
@@ -52,6 +55,7 @@ module.exports = class LevelLoader extends CocoClass
     if @supermodel.finished()
       @onSupermodelLoaded()
     else
+      @loadTimeoutID = setTimeout @reportLoadError.bind(@), 30000
       @listenToOnce @supermodel, 'loaded-all', @onSupermodelLoaded
 
   # Supermodel (Level) Loading
@@ -74,6 +78,25 @@ module.exports = class LevelLoader extends CocoClass
       @level = @supermodel.loadModel(@level, 'level').model
       @listenToOnce @level, 'sync', @onLevelLoaded
   
+  reportLoadError: ->
+    return if me.isAdmin() or /dev=true/.test(window.location?.href ? '') or reportedLoadErrorAlready
+    reportedLoadErrorAlready = true
+    context = email: me.get('email')
+    context.message = """
+      Automatic Report - Unable to Load Level (LevelLoader timeout)
+      URL: #{window?.location?.toString()}
+      These models are marked as having not loaded:
+      #{JSON.stringify(@supermodel.report().map (m) -> _.result(m.model, 'url'))}
+      Object.keys(supermodel.models):
+      #{JSON.stringify(Object.keys(@supermodel.models))}
+    """
+    if $.browser
+      context.browser = "#{$.browser.platform} #{$.browser.name} #{$.browser.versionNumber}"
+    context.screenSize = "#{screen?.width ? $(window).width()} x #{screen?.height ? $(window).height()}"
+    context.subject = "Level Load Error: #{@work?.level?.name or 'Unknown Level'}"
+    context.levelSlug = @work?.level?.slug
+    sendContactMessage context
+
   onLevelLoaded: ->
     if not @sessionless and @level.isType('hero', 'hero-ladder', 'hero-coop', 'course')
       @sessionDependenciesRegistered = {}
@@ -355,6 +378,7 @@ module.exports = class LevelLoader extends CocoClass
     @onWorldNecessitiesLoaded() if @checkAllWorldNecessitiesRegisteredAndLoaded()
 
   onWorldNecessityLoadFailed: (event) ->
+    @reportLoadError()
     @trigger('world-necessity-load-failed', event)
 
   checkAllWorldNecessitiesRegisteredAndLoaded: ->
@@ -393,6 +417,7 @@ module.exports = class LevelLoader extends CocoClass
     @supermodel.loadModel(model, resourceName)
 
   onSupermodelLoaded: ->
+    clearTimeout @loadTimeoutID
     return if @destroyed
     console.log 'SuperModel for Level loaded in', new Date().getTime() - @t0, 'ms' if LOG
     @loadLevelSounds()

app/models/SuperModel.coffee

@@ -309,14 +309,17 @@ class ModelResource extends Resource
         @markFailed()
         return @
       @markLoading()
+      @model.loading = false # So fetchModel can run again
       if @loadsAttempted > 0
-        console.log "Didn't load model in #{timeToWait}ms (attempt ##{@loadsAttempted}), trying again: ", this
+        console.log "Didn't load model in #{timeToWait}ms (attempt ##{@loadsAttempted}), trying again: ", _.result(@model, 'url')
       @fetchModel()
       @listenTo @model, 'error', (levelComponent, request) ->
         if request.status not in [408, 504, 522, 524]
           clearTimeout(@timeoutID)
       clearTimeout(@timeoutID) if @timeoutID
       @timeoutID = setTimeout(tryLoad, timeToWait)
+      if application.testing
+        application.timeoutsToClear?.push(@timeoutID)
       @loadsAttempted += 1
       timeToWait *= 1.5
     tryLoad()

app/views/TestView.coffee

@@ -101,12 +101,15 @@ module.exports = TestView = class TestView extends RootView
       Backbone.Mediator.init()
       Backbone.Mediator.setValidationEnabled false
       spyOn(application.tracker, 'trackEvent')
+      application.timeoutsToClear = []
       # TODO Stubbify more things
       #   * document.location
       #   * firebase
       #   * all the services that load in main.html
 
     afterEach ->
+      application.timeoutsToClear?.forEach (timeoutID) ->
+        clearTimeout(timeoutID)
       # TODO Clean up more things
       #   * Events
 

test/app/models/SuperModel.spec.coffee

@@ -1,6 +1,7 @@
 SuperModel = require 'models/SuperModel'
 User = require 'models/User'
 ComponentsCollection = require 'collections/ComponentsCollection'
+factories = require 'test/app/factories'
 
 describe 'SuperModel', ->
   
@@ -57,6 +58,62 @@ describe 'SuperModel', ->
       request = jasmine.Ajax.requests.mostRecent()
       expect(request).toBeDefined()
 
+    describe 'timeout handling', ->
+      beforeEach ->
+        jasmine.clock().install()
+      afterEach ->
+        jasmine.clock().uninstall()
+
+      it 'automatically retries stalled requests', ->
+        s = new SuperModel()
+        m = new User({_id: '12345'})
+        s.loadModel(m)
+        timeUntilRetry = 5000
+
+        # Retry request 5 times
+        for timesTried in [1..5]
+          expect(s.failed).toBeFalsy()
+          expect(s.resources[1].loadsAttempted).toBe(timesTried)
+          expect(jasmine.Ajax.requests.all().length).toBe(timesTried)
+          jasmine.clock().tick(timeUntilRetry)
+          timeUntilRetry *= 1.5
+
+        # And then stop retrying
+        expect(s.resources[1].loadsAttempted).toBe(5)
+        expect(jasmine.Ajax.requests.all().length).toBe(5)
+        expect(s.failed).toBe(true)
+
+      it 'stops retrying once the model loads', (done) ->
+        s = new SuperModel()
+        m = new User({_id: '12345'})
+        s.loadModel(m)
+        timeUntilRetry = 5000
+        # Retry request 2 times
+        for timesTried in [1..2]
+          expect(s.failed).toBeFalsy()
+          expect(s.resources[1].loadsAttempted).toBe(timesTried)
+          expect(jasmine.Ajax.requests.all().length).toBe(timesTried)
+          jasmine.clock().tick(timeUntilRetry)
+          timeUntilRetry *= 1.5
+
+        # Respond to the third reqest
+        expect(s.finished()).toBeFalsy()
+        expect(s.failed).toBeFalsy()
+        request = jasmine.Ajax.requests.mostRecent()
+        request.respondWith({status: 200, responseText: JSON.stringify(factories.makeUser({ _id: '12345' }).attributes)})
+
+        _.defer ->
+          expect(s.finished()).toBe(true)
+          expect(s.failed).toBeFalsy()
+
+          # It shouldn't send any more requests after loading
+          expect(s.resources[1].loadsAttempted).toBe(3)
+          expect(jasmine.Ajax.requests.all().length).toBe(3)
+          jasmine.clock().tick(60000)
+          expect(s.resources[1].loadsAttempted).toBe(3)
+          expect(jasmine.Ajax.requests.all().length).toBe(3)
+          done()
+
   describe 'events', ->
     it 'triggers "loaded-all" when finished', (done) ->
       s = new SuperModel()