From d3db19dee3f23fd11753dc65faf80a3cfd20851f Mon Sep 17 00:00:00 2001 From: Phoenix Eliot Date: Tue, 9 Aug 2016 12:53:53 -0700 Subject: [PATCH 1/2] Report timeout problems, and fix retries Fix getting model URLs --- app/lib/LevelLoader.coffee | 25 +++++++++++++++++++++++++ app/models/SuperModel.coffee | 3 ++- 2 files changed, 27 insertions(+), 1 deletion(-) diff --git a/app/lib/LevelLoader.coffee b/app/lib/LevelLoader.coffee index 6d5acbeca..e35af2996 100644 --- a/app/lib/LevelLoader.coffee +++ b/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 @@ -73,6 +77,25 @@ module.exports = class LevelLoader extends CocoClass else @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') @@ -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() diff --git a/app/models/SuperModel.coffee b/app/models/SuperModel.coffee index 22e500c66..ba20290f0 100644 --- a/app/models/SuperModel.coffee +++ b/app/models/SuperModel.coffee @@ -309,8 +309,9 @@ 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] From a4f48bbc17da53a5531cdbfc11c28607a53e25f7 Mon Sep 17 00:00:00 2001 From: Phoenix Eliot Date: Wed, 10 Aug 2016 14:03:17 -0700 Subject: [PATCH 2/2] Add tests for SuperModel load retrying Clear timeouts after each test --- app/models/SuperModel.coffee | 4 +- app/views/TestView.coffee | 3 ++ test/app/models/SuperModel.spec.coffee | 57 ++++++++++++++++++++++++++ 3 files changed, 63 insertions(+), 1 deletion(-) diff --git a/app/models/SuperModel.coffee b/app/models/SuperModel.coffee index ba20290f0..4637db757 100644 --- a/app/models/SuperModel.coffee +++ b/app/models/SuperModel.coffee @@ -299,7 +299,7 @@ class ModelResource extends Resource load: -> # TODO: Track progress on requests and don't retry if progress was made recently. - # Probably use _.debounce and attach event listeners to xhr objects. + # Probably use _.debounce and attach event listeners to xhr objects. # This logic is for handling failed responses for level loading. timeToWait = 5000 @@ -318,6 +318,8 @@ class ModelResource extends Resource clearTimeout(@timeoutID) clearTimeout(@timeoutID) if @timeoutID @timeoutID = setTimeout(tryLoad, timeToWait) + if application.testing + application.timeoutsToClear?.push(@timeoutID) @loadsAttempted += 1 timeToWait *= 1.5 tryLoad() diff --git a/app/views/TestView.coffee b/app/views/TestView.coffee index 14f91a545..4fa08b26a 100644 --- a/app/views/TestView.coffee +++ b/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 diff --git a/test/app/models/SuperModel.spec.coffee b/test/app/models/SuperModel.spec.coffee index d4d5affa3..c4c615727 100644 --- a/test/app/models/SuperModel.spec.coffee +++ b/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()