"Something bad happened on the server" without error in the data field

[Fr33maan]

Hello,

I often get this as an answer :

{
  "code": "E_INTERNAL_SERVER_ERROR",
  "message": "Something bad happened on the server",
  "data": {}
}

If I manually log the error in the response file I can have the error but I'm surprised that I don't have it in the response in the data field.

I'm not sure if I understand correctly the _.assign method but I thought data would be in the response if it exists with the following code :

module.exports = function (data, config) {
  console.log('serverError : ')
  console.log(data)
  const response = _.assign({
    code: _.get(config, 'code', 'E_INTERNAL_SERVER_ERROR'),
    message: _.get(config, 'message', 'Something bad happened on the server'),
    data: data || {}
  }, _.get(config, 'root', {}));

  this.res.status(500);
  this.res.jsonx(response);
};

Thanks

[ghaiklor]

@prisonier _.assign() mixes objects (extend at previous versions of lodash\underscore\whatever). If data contains some information about error it should mix into the response object and respond to you.

[Fr33maan]

Thanks for the answer, it is clearly a bug as data contains some information.

[Fr33maan]

I guess that you already tried to reproduce it but this is how I make it happen :

  test_fb_post: function(req, res) {

    Video.find().then(videos => {
      console.log(test)
      return videos
    })

    .then(res.ok)
    .catch(res.serverError)
  },

The output in the console :

serverError :
[ReferenceError: test is not defined]

And the res.serverError and the data responded are exactly like in my first post.

[ghaiklor]

@prisonier oh, these type of errors you can't respond :)

[Fr33maan]

Absolutely, but I don't understand why the server act like this.

But I would like to have a debug flag somewhere in the config to respond them :)

[Fr33maan]

I also would like to have a stack trace with this kind of error but I can't figure how to do this. Do you have any idea ?

[ghaiklor]

@prisonier that's a bad idea to respond with stack trace or something. Better to log them into files with daily rotate, IMHO. You will have all the errors in log files and can investigate them.

[Fr33maan]

I totally understand your point of view for a production app, you shouldn't respond anything about server logic to a client. I would combine having errors in files and having them sent to slack with a winston transporter like this one

But for testing it is a pain to havn't access to errors or stack traces in responses or in the console.

[ghaiklor]

@prisonier could you send the whole stack trace of your case ? I wondering if Sails do something to simplify the stack trace. I do no magic in the generator to hide this.

[Fr33maan]

I thought you did something because I don't have any stack trace in this case. You have the whole information in my two posts. The only thing which is printed is the console.log(data) in the response file. I will try to reproduce it in a native sails app to see what happen.

[Fr33maan]

In a native sails app this is the stack trace I get with the controller code ONLY (no console.log(data) in the response) :

error: Sending 500 ("Server Error") response:
 ReferenceError: test is not defined
    at /home/libre/dev/test/api/controllers/TestController.js:14:18
    at wrapper (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/lodash/index.js:3592:19)
    at applyInOriginalCtx (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/waterline/lib/waterline/utils/normalize.js:417:80)
    at wrappedCallback (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/waterline/lib/waterline/utils/normalize.js:320:18)
    at callback.success (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/waterline/node_modules/switchback/lib/normalize.js:33:31)
    at _switch (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/waterline/node_modules/switchback/lib/factory.js:58:28)
    at returnResults (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/waterline/lib/waterline/query/finders/basic.js:392:9)
    at /home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/waterline/lib/waterline/query/finders/basic.js:272:16

    at /home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/waterline/lib/waterline/query/finders/operations.js:83:7
From previous event:
    at Deferred.then (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/waterline/lib/waterline/query/deferred.js:505:27)
    at Object.module.exports.test (/home/libre/dev/test/api/controllers/TestController.js:12:24)
    at wrapper (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/lodash/index.js:3095:19)
    at routeTargetFnWrapper (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/lib/router/bind.js:179:5)
    at callbacks (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:164:37)
    at param (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:138:11)
    at pass (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:145:5)
    at nextRoute (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:100:7)
    at callbacks (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:167:11)
    at /home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/lib/router/bind.js:187:7
    at alwaysAllow (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/lib/hooks/policies/index.js:158:11)
    at routeTargetFnWrapper (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/lib/router/bind.js:179:5)
    at callbacks (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:164:37)
    at param (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:138:11)
    at pass (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:145:5)
    at nextRoute (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:100:7)
    at callbacks (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/node_modules/express/lib/router/index.js:167:11)
    at /home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/lib/router/bind.js:187:7
    at module.exports (/home/libre/.nvm/versions/node/v4.3.1/lib/node_modules/sails/lib/hooks/cors/clear-headers.js:14:3) [ReferenceError: test is not defined]

This stack trace is really more exploitable than the one given with the scaffold as tehre is the explicit error and the incriminated line. I didn't precised that I'm working on Linux.

[ghaiklor]

@prisonier may it be because of different log levels in your configuration file ?

[Fr33maan]

No, the log level in the native sails app is higher than in the scaffolded :

native : info scaffolded: verbose

[ghaiklor]

@prisonier I have no idea why it's happening. Do you have some ideas ?

[Fr33maan]

Another information, I chossed winston as the logger. I guess that this behaviour comes from the logger implementation ?

[ghaiklor]

@prisonier try to disable winston hook in .sailsrc file. Good idea, can be because of that.

[Fr33maan]

How can I do that ?

Something like this ?

My actual .sailsrc

{
  "generators": {
    "modules": {
    }
  },
  "hooks": {
    "csrf": false,
    "grunt": false,
    "i18n": false,
    "pubsub": false,
    "session": false,
    "sockets": false,
    "views": false
  }
}

The new one ?

{
  "generators": {
    "modules": {
    }
  },
  "hooks": {
    "csrf": false,
    "grunt": false,
    "i18n": false,
    "pubsub": false,
    "session": false,
    "sockets": false,
    "views": false,
    "winston": false
  }
}

[ghaiklor]

@prisonier yep, you're right. Try to achieve default Sails logger. If it fixes the issue, problem in sails-hook-winston.

[Fr33maan]

@ghaiklor unfortunately it changed nothing but I'm not sure that winston has been disabled, how can I be sure which logger is used ?

[ghaiklor]

@prisonier you can enable silly mode in config/log.js and see which hooks are loading.

[Fr33maan]

Am I doing something wrong ? I still have a verbose logging level ...

"use strict";

/**
 * Winston Logger Configuration
 * For detailed information take a look here - https://github.com/Kikobeats/sails-hook-winston
 */

module.exports = {
  log: {
    /**
     * Winston logging level for the console transport
     * @type {String}
     */
    // level: 'verbose',
    level: 'silly',

    /**
     * Outputs the timestamp in the console transport
     * @type {Boolean}
     */
    timestamp: true,

    /**
     * Custom Winston transports
     * More information here - https://github.com/winstonjs/winston/blob/master/docs/transports.md
     * @example
     * transports: [{
     *   module: require('winston-mongodb').MongoDB,
     *   config: {}
     * }]
     */
    transports: []
  }
};

And the console :

info: Starting app...

verbose: logger hook loaded successfully.
verbose: request hook loaded successfully.
verbose: Loading the app's models and adapters...
verbose: Loading app models...
verbose: Loading app adapters...
verbose: Loading blueprint middleware...
verbose: blueprints hook loaded successfully.
verbose: responses hook loaded successfully.
verbose: controllers hook loaded successfully.
verbose: Loading policy modules from app...
verbose: Finished loading policy middleware logic.
verbose: policies hook loaded successfully.
verbose: services hook loaded successfully.

verbose: cors hook loaded successfully.
verbose: http hook loaded successfully.
verbose: counthook hook loaded successfully.
verbose: pluralizehook hook loaded successfully.
verbose: swagger hook loaded successfully.
verbose: Autoreload watching:  [ '/home/libre/dev/facetube/api/controllers',
  '/home/libre/dev/facetube/api/models',
  '/home/libre/dev/facetube/api/services',
  '/home/libre/dev/facetube/config/locales' ]
verbose: autoreload hook loaded successfully.
verbose: cron hook loaded successfully.
verbose: Loading adapter ( sails-mongo ) for channel  from `node_modules` directory...
verbose: Starting ORM...
verbose: orm hook loaded successfully.
verbose: Built-in hooks are ready.
verbose: Instantiating registry...
verbose: Loading router...
verbose: Policy-controller bindings complete!
verbose: All hooks were loaded successfully.
verbose: Starting app at /home/libre/dev/facetube...
verbose: Running the setup logic in `sails.config.bootstrap(cb)`...

Still in verbose so I do'nt have any information about the logger type

[Fr33maan]

And you can see that even if the timestamp parameter is set to true, there is no timestamp in the console

[ghaiklor]

@prisonier timestamp is for winston not for Sails logger. Log level is overridden in config/env folder.

[Fr33maan]

@ghaiklor I only have binding routes log when I activate silly log level, I don't have any information about the used logger. Wether I activate winston or not in the .sailsrc, I don't have timestamp

[ghaiklor]

@prisonier you see the list of loaded hooks in the console and there is no winston hook. As I said, timestamp only for winston hook. If you disable winston, timestamp has no effect.

[Fr33maan]

@ghaiklor I didn't disabled winston, this is what I don't understand

[ghaiklor]

@prisonier ok... Are you sure that you install sails-hook-winston or smth ?

[Fr33maan]

I chose winston as logger during installation. How can I check that winston has been installed or not ? As I don't have any information about the logger hook type when I lift sails is there another place to check ?

[ghaiklor]

@prisonier you can install sails-hook-winston via npm install for sure. I'm wondering what's happening :)

[Fr33maan]

Ok so now I've got the timestamp but still no stack trace ;)

[Fr33maan]

New behaviour detected : if I explicitely throw an error in a cron task then I will have the stack trace

The cron.js

module.exports = {
  cron: {
    publishJobFirst: {
      schedule: '0 0,20,40 * * * *', // Will try to publish a video every 20 minutes
      onTick: () => PublishService.publishProcess()
    }
  }
};

PublishService.js

  publishProcess: function() {

    if (this.isPublishTime()) {

     // Do something 

    }else{
      throw new Error('Current time is not a publish time')
    }
  },

And the output :

Fri Mar 04 2016 02:28:42 GMT+0100 (CET) verbose: Lowering sails...
Fri Mar 04 2016 02:28:42 GMT+0100 (CET) verbose: Shutting down HTTP server...
/home/libre/dev/facetube/api/services/PublishService.js:17
      throw new Error('Current time is not a publish time')
      ^

Error: Current time is not a publish time
    at Object.module.exports.publishProcess (/home/libre/dev/facetube/api/services/PublishService.js:17:13)
    at Object.bound [as publishProcess] (/home/libre/dev/facetube/node_modules/sails/node_modules/lodash/dist/lodash.js:729:21)
    at CronJob.module.exports.cron.publishJobFirst.onTick (/home/libre/dev/facetube/config/cron.js:34:36)
    at CronJob.fireOnTick (/home/libre/dev/facetube/node_modules/sails-hook-cron/node_modules/cron/lib/cron.js:392:22)
    at callbackWrapper [as _onTimeout] (/home/libre/dev/facetube/node_modules/sails-hook-cron/node_modules/cron/lib/cron.js:435:9)

    at Timer.listOnTimeout (timers.js:92:15)

If I throw an error in the first example (in a promise inside my controller), I don't get any stack trace. I don't understand why there is a different behaviour. Maybe there is a special wrapper for controller functions or for promises ? Like a try/catch which will avoid to shut down the server ? sails-rest-api uses Promise es6 but what sails native uses ?

[ghaiklor]

@prisonier OMFG, why don't you tell me that you are using promises :smiley_cat: Handling error in promises done with .catch() method. If you throw error - it works, otherwise it just silence the promise if it doesn't has a .catch() callback.

Read more here - http://www.html5rocks.com/en/tutorials/es6/promises/

[Fr33maan]

There is a catch method in my code ! If you look at my code in the previous message you will see then and catch method, why did you think it was something else than promise ? ;)

But it is not promise related. Look at this very simple code :

test : function(req, res){
    console.log(test)
    return res.ok()
}

In sails-rest-api NO stack trace is printed but in native sails a stack trace is printed. This is THIS behaviour which is buggy and should be fixed.