hapijs / good

hapi process monitoring
Other
525 stars 161 forks source link

Unable to get original error message #576

Closed BigWillie closed 5 years ago

BigWillie commented 6 years ago

Not sure if this is an issue or a feature. Good 8.0.0-rc1.

My good config is:

`const goodOptions = {
  reporters: {
    fileReporter: [{
      module: 'good-squeeze',
      name: 'Squeeze',
      args: [
        { log: '*', response: '*', error: '*' }
      ]
    }, {
      module: 'good-squeeze',
      name: 'SafeJson',
      args: [
        null,
        { separator: ',' }
    ]
    }, 
    {
      module: 'good-file',
      args: ['./logs/serverlog']
  },
    /* {
      module: 'rotating-file-stream',
      args: [
        "serverlog",
        {
          size: "1M",
          path: "./logs"
        }
      ]
    } */
  ]    
  }
};`

Errors are being logged - however, they're not as expected. This is what was written to my file:

`{
  "event": "error",
  "timestamp": 1515097276312,
  "url": {
    "protocol": null,
    "slashes": null,
    "auth": null,
    "host": null,
    "port": null,
    "hostname": null,
    "hash": null,
    "search": null,
    "query": {

    },
    "pathname": "/products/01423",
    "path": "/products/01423",
    "href": "/products/01423"
  },
  "method": "get",
  "pid": 25118,
  "error": "An internal server error occurred",
  "config": {

  }
},`

I expected to see the full 500 error information as logged in my console (I know Hapi obscures this on when sent to the client/browser). Is this intended behaviour?

corbinu commented 6 years ago

@BigWillie This is a change in how error logging works in hapi 17. See "Changes to internal logging" here: https://github.com/hapijs/hapi/issues/3658

There maybe a way to get the original error message back. I don't have much free time at the moment but if you can dig around and find out if the data is passed from a hapi event would be happy to take a look at getting it back in.

BigWillie commented 6 years ago

@corbinu thanks. So, I tried the following inside the onPreResponse lifecycle hook...

`      server.ext('onPreResponse', function(request, h) {
        var response = request.response;
        // isServer indicates status code >= 500
       //  if error, pass it through server.log
        if (response && response.isBoom && response.isServer) {
          const error = response.error || response.message;
          server.log([ 'error' ], error);
        }
        return h.continue;
      });
`

and I now have errors as they are in my console, appearing in my log file - while still showing up with the standard 500 message in the browser.

At first glance, this appears to be working as intended. I get the actual error logged to the log file, userland just sees a

{"message":"An internal server error occurred","statusCode":500,"error":"Internal Server Error"}

Is the above a sane way to do it? From the Hapi 17 documentation (and I'm probably confusing myself here) I don't think I should be able to do this - as I think by the time onPreResponse is hit, the error should have changed?

corbinu commented 6 years ago

@BigWillie Great! I will see about changing the error handler to onPreResponse

Honestly the docs may just be wrong if it works I am happy with it

BigWillie commented 6 years ago

I just realised - while it renders the error, it doesn't give me all the other info so as page etc.. probably because the event is recorded as a 'log' and not an error

eg - my logged error...

`{
  "event": "log",
  "timestamp": 1515108396814,
  "tags": [
    "error"
  ],
  "data": "$filter is not defined",
  "pid": 26697
},

Error generated before OnPre stuff

{
  "event": "error",
  "timestamp": 1515108396575,
  "url": {
    "protocol": null,
    "slashes": null,
    "auth": null,
    "host": null,
    "port": null,
    "hostname": null,
    "hash": null,
    "search": null,
    "query": {

    },
    "pathname": "/products/02053",
    "path": "/products/02053",
    "href": "/products/02053"
  },
  "method": "get",
  "pid": 26697,
  "error": "An internal server error occurred",
  "config": {

  }
},`

Thanks!

corbinu commented 6 years ago

@BigWillie I am sorry but I am not going to be able to work on this project any longer. Just wanted to let everybody know in case somebody else wants to pick this up

rankida commented 6 years ago

I have just bumped into a similar issue. With the new hapi17 implementation I see the toJSON method of RequestError deliberately hides the source error.

    toJSON() {

        const result = Object.assign({}, this, {
            error: this.error.output.payload.message
        });
        return result;
    }

https://github.com/hapijs/good/pull/572/files#diff-50e3aa130a4f97a42ee2cf111c7b1d9dR47

While it makes sense for hapi to obfuscate the source error I wonder if good shouldn't be doing it as for logging it is very useful (essential?) to see the source error.

erfanio commented 6 years ago

I agree with @rankida Good should not be obfuscating the errors. Errors will be essensial to figure out problems later, and most ways of storing logs involve json (which removes the original errors in good).

rankida commented 6 years ago

In the end I added this into our good logging stream to strip out the RequestError prototype.

class RequestErrorScrubber extends Stream.Transform {
    constructor(options) {
        super(Object.assign({}, options, { objectMode: true }));
    }

    _transform(data, enc, next) {
        if (data instanceof RequestError) {
            data = Object.assign({}, data);
        }
        return next(null, data);
    }
}
lock[bot] commented 4 years ago

This thread has been automatically locked due to inactivity. Please open a new issue for related bugs or questions following the new issue template instructions.