auth-server sometimes thows Function.AppError.translate error

[vladikoff]

Found via Circle Ci tests

{"Timestamp":1479316630492000000,"Logger":"fxa-auth-server","Type":"request.summary","Severity":2,"Pid":20908,"EnvVersion":"2.0","Fields":{"op":"request.summary","code":500,"errno":999,"rid":"1479316624201:ip-172-31-44-29:20908:ive7x46b:50774","path":"/auth/v1/account/login","lang":"en-US,en;q=0.5","agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:40.0) Gecko/20100101 Firefox/40.0 FxATester/1.0","remoteAddressChain":"["54.160.105.139","172.31.41.87","127.0.0.1"]","t":6291,"uid":"00","service":"sync","reason":"signin","keys":"true","email":"sync0.6714192205108702@restmail.net","stack":"Error: An internal server error occurred
at Function.AppError.translate (/data/fxa-auth-server/lib/error.js:134:13)
at /data/fxa-auth-server/lib/server.js:288:26
at /data/fxa-auth-server/node_modules/hapi/lib/request.js:403:22
at iterate (/data/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:36:13)
at Object.exports.serial (/data/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:39:9)
at /data/fxa-auth-server/node_modules/hapi/lib/request.js:398:15
at internals.Protect.run.finish [as run] (/data/fxa-auth-server/node_modules/hapi/lib/protect.js:64:5)
at internals.Request.internals.Request._execute.internals.Request._lifecycle.internals.Request._invoke.callback._protect.run [as _invoke] (/data/fxa-auth-server/node_modules/hapi/lib/request.js:396:19)
at internals.Request.internals.Request._execute.internals.Request._lifecycle.internals.Request._invoke.internals.Request._reply.exit [as _reply] (/data/fxa-auth-server/node_modules/hapi/lib/request.js:455:10)
at /data/fxa-auth-server/node_modules/hapi/lib/request.js:389:21
at done (/data/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:31:25)
at internals.input.exports.response.postValidate (/data/fxa-auth-server/node_modules/hapi/lib/validation.js:163:16)
at each (/data/fxa-auth-server/node_modules/hapi/lib/request.js:384:16)
at iterate (/data/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:36:13)
at done (/data/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:28:25)
at finalize (/data/fxa-auth-server/node_modules/hapi/lib/handler.js:21:16)
at /data/fxa-auth-server/node_modules/hapi/lib/protect.js:52:16
at wrapped (/data/fxa-auth-server/node_modules/hapi/node_modules/hoek/lib/index.js:871:20)
at finalize (/data/fxa-auth-server/node_modules/hapi/lib/handler.js:82:20)
at Function.wrapped [as _next] (/data/fxa-auth-server/node_modules/hapi/node_modules/hoek/lib/index.js:871:20)
at Function.internals.Reply.interface.internals.response (/data/fxa-auth-server/node_modules/hapi/lib/reply.js:138:14)
at reply (/data/fxa-auth-server/node_modules/hapi/lib/reply.js:70:22)
at bound (domain.js:287:14)
at runBound (domain.js:300:12)
at tryCatcher (/data/fxa-auth-server/node_modules/bluebird/js/main/util.js:26:23)
at Promise._settlePromiseFromHandler (/data/fxa-auth-server/node_modules/bluebird/js/main/promise.js:507:31)
at Promise._settlePromiseAt (/data/fxa-auth-server/node_modules/bluebird/js/main/promise.js:581:18)
at Promise._settlePromises (/data/fxa-auth-server/node_modules/bluebird/js/main/promise.js:697:14)
at Async._drainQueue (/data/fxa-auth-server/node_modules/bluebird/js/main/async.js:123:16)
at Async._drainQueues (/data/fxa-auth-server/node_modules/bluebird/js/main/async.js:133:10)
at Immediate.Async.drainQueues [as _onImmediate] (/data/fxa-auth-server/node_modules/bluebird/js/main/async.js:15:14)
at processImmediate [as _immediateCallback] (timers.js:383:17)"}}

[vladikoff]

Only happens from Circle CI AFAIK for now.

[vbudhram]

@vladikoff Does Circle CI cache node modules? Possible that it is using the un-reverted fxa-auth-mysql-db? I was getting the Error: An internal server error occurred when using that version and logging in.

[vladikoff]

@vbudhram hm no, it uses a commit from Nov 11

[vladikoff]

@jrgm says it could be the customs server. (because it cannot connect)

[shane-tomlinson]

100% reproduction locally! After digging in last night, I saw that the AppError.translate errors occur directly after:

fxa-auth.log:Unhandled rejection EndpointError: 127.0.0.1:8000 error: request timed out
fxa-auth.log:Unhandled rejection EndpointError: 127.0.0.1:8000 error: request timed out
fxa-auth.log:Unhandled rejection EndpointError: 127.0.0.1:8000 error: request timed out
fxa-auth.log:Unhandled rejection EndpointError: 127.0.0.1:8000 error: request timed out
fxa-auth.log:Unhandled rejection EndpointError: 127.0.0.1:8000 error: request timed out

Requests to the DB were timing out.

So simple to reproduce locally! Kill the db-server, tail the logs for the key server, try to sign up.

auth-server key server PORT 9000-2 fxa-auth-server.ERROR: request.summary {"op":"request.summary","code":500,"errno":999,"rid":"1479462142081:Shanes-Retina-MBP.local:52050:ivmhmk81:10630","path":"/v1/account/create","lang":"en,es;q=0.8,de;q=0.7,ru;q=0.5,es-AR;q=0.3,en-US;q=0.2","agent":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:50.0) Gecko/20100101 Firefox/50.0","remoteAddressChain":["127.0.0.1"],"t":7,"uid":"00","email":"a@a.com","stack":"Error: An internal server error occurred\n at Function.AppError.translate (/Users/stomlinson/development/fxa-auth-server/lib/error.js:134:13)\n at /Users/stomlinson/development/fxa-auth-server/lib/server.js:288:26\n at /Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/request.js:403:22\n at iterate (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:36:13)\n at Object.exports.serial (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:39:9)\n at /Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/request.js:398:15\n at internals.Protect.run.finish as run\n at internals.Request.internals.Request._execute.internals.Request._lifecycle.internals.Request._invoke.callback._protect.run as _invoke\n at internals.Request.internals.Request._execute.internals.Request._lifecycle.internals.Request._invoke.internals.Request._reply.exit as _reply\n at /Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/request.js:389:21\n at done (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:31:25)\n at internals.input.exports.response.postValidate (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/validation.js:163:16)\n at each (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/request.js:384:16)\n at iterate (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:36:13)\n at done (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/node_modules/items/lib/index.js:28:25)\n at finalize (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/handler.js:21:16)\n at /Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/protect.js:52:16\n at wrapped (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/node_modules/hoek/lib/index.js:871:20)\n at finalize (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/handler.js:82:20)\n at Function.wrapped as _next\n at Function.internals.Reply.interface.internals.response (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/reply.js:138:14)\n at reply (/Users/stomlinson/development/fxa-auth-server/node_modules/hapi/lib/reply.js:70:22)\n at bound (domain.js:287:14)\n at runBound (domain.js:300:12)\n at tryCatcher (/Users/stomlinson/development/fxa-auth-server/node_modules/bluebird/js/main/util.js:26:23)\n at Promise._settlePromiseFromHandler (/Users/stomlinson/development/fxa-auth-server/node_modules/bluebird/js/main/promise.js:507:31)\n at Promise._settlePromiseAt (/Users/stomlinson/development/fxa-auth-server/node_modules/bluebird/js/main/promise.js:581:18)\n at Promise._settlePromises (/Users/stomlinson/development/fxa-auth-server/node_modules/bluebird/js/main/promise.js:697:14)\n at Async._drainQueue (/Users/stomlinson/development/fxa-auth-server/node_modules/bluebird/js/main/async.js:123:16)\n at Async._drainQueues (/Users/stomlinson/development/fxa-auth-server/node_modules/bluebird/js/main/async.js:133:10)\n at Immediate.Async.drainQueues as _onImmediate\n at processImmediate as _immediateCallback"}

[vladikoff]

@jrgm @jbuck could we take a look at why the database is timing out on fxa-dev boxes?

[vladikoff]

I had an issue with the following test (even when fxa-auth-mailer was turned off):

'blocked, valid code entered': function () {
      email = TestHelpers.createEmail('block{id}');

      return this.remote
        .then(setupTest({ blocked: true, preVerified: true }))

        .then(testElementExists('#fxa-signin-unblock-header'))
        .then(testElementTextInclude('.verification-email-message', email))
        .then(fillOutSignInUnblock(email, 0))

        .then(testIsBrowserNotifiedOfLogin(this.remote, email, { checkVerified: true }))
        // about:accounts will take over post-unblock, no transition
        .then(noPageTransition('#fxa-signin-unblock-header'));
    }

I got the Internal Server error on Circle.

[vladikoff]

Fixed via 3719437