Review usage of `context` property in errors (Excessive logs)

naz commented 5 years ago

Reason

With a new format improvements in Ignition the context property is mean to provide: any info we have about why or how this happened .

Problem

Errors that are produced by Ghost use context inconsistently and need to be reviewed. A good example of incorrect usage is the error thrown by theme check in themese service:

return Promise.reject(new common.errors.ThemeValidationError({
    message: common.i18n.t('errors.api.themes.invalidTheme'),
    errorDetails: checkedTheme.results.error,
    context: checkedTheme
}));

checkedTheme - contains all the information on checked theme, which is way too much and makes console output unreadable.

Solution

All usages of context property should be reviewed and substituted with usefull information on why/how the error happened. Good example of context usage:

return next(new common.errors.TooManyRequestsError({
    message: `Too many attempts try again in ${moment(nextValidRequestDate).fromNow(true)}`,
    context: common.i18n.t('errors.middleware.spamprevention.forgottenPasswordIp.error',
        {rfa: spamGlobalBlock.freeRetries + 1 || 5, rfp: spamGlobalBlock.lifetime || 60 * 60}),
    help: common.i18n.t('errors.middleware.spamprevention.tooManyAttempts')
}));

To be changed

[x] Theme validation context
- what is passed in errorDetails is enough (maybe even too much if the theme contains too many errors). Current message is: "Theme is not compatible or contains errors.", context can be removed and help added instead with words (to be reviewed) Please check and correct detected errors
[x] Collision detection context
- passes in all changes done to a post which could contain a lot of data. possibly was designed to be able to preserve in some way the information that is lost if the user decides to refresh the page?
- the context should become errorDetails instead so that correct object formatting is applied to the fields
[x] Import error context
- should become help and possibly moved to translations?
[x] Theme activation controller (here and here)
- context is not useful at all in this situation as it happens only in a single scenario

Errors lacking context

[ ] Password reset both v0.1 and v2 APIs: https://github.com/TryGhost/Ghost/blob/506d013/core/server/api/v0.1/authentication.js#L302 (review usages of errors.api.users.userNotFound')
[ ] Session creation API v2: https://github.com/TryGhost/Ghost/blob/ae71f2d/core/server/api/v2/session.js#L19
[ ] Image uploader validation - needs review based on https://forum.ghost.org/t/cant-upload-publication-icon/6136

kirrg001 commented 5 years ago

If a collision detection error occurs, we output this format currently:

ERROR [2019-03-11 08:58:50] "PUT /ghost/api/v2/admin/posts/5c8619df4e14141182cbeb49/" 409 129ms

Saving failed! Someone else is editing this post.

{"clientUpdatedAt":"2019-03-11T08:20:21.000Z","serverUpdatedAt":"2019-03-11T08:58:47.000Z","changed":{"mobiledoc":"{\"version\":\"0.3.1\",\"atoms\":[],\"cards\":[],\"markups\":[[\"strong\"],[\"a\",[\"href\",\"https://ghost.org/downloads/\"]],[\"a\",[\"href\",\"https://ghost.org/pricing\"]],[\"a\",[\"href\",\"https://github.com/TryGhost\"]],[\"a\",[\"href\",\"/the-editor/\"]],[\"em\"]],\"sections\":[[1,\"p\",[[0,[],0,\"👋 Welcome, it's great to have you here.\"]]],[1,\"p\",[[0,[],0,\"We know that first impressions are important, so we've populategregred your new site with some initial \"],[0,[0],1,\"getting started\"],[0,[],0,\" posts that will help you get familiar with everything in no time. This is the first one!\"]]],[1,\"p\",[[0,[0],1,\"A few things you should know upfront\"],[0,[],0,\":\"]]],[3,\"ol\",[[[0,[],0,\"Ghost is designed for ambitious, professional publishers who want to actively build a business around their content. That's who it works best for. \"]],[[0,[],0,\"The entire platform can be modified and customised to suit your needs. It's very powerful, but does require some knowledge of code. Ghost is not necessarily a good platform for beginners or people who just want a simple personal blog. \"]],[[0,[],0,\"For the best experience we recommend downloading the \"],[0,[1],1,\"Ghost Desktop App\"],[0,[],0,\" for your computer, which is the best way to access your Ghost site on a desktop device. \"]]]],[1,\"p\",[[0,[],0,\"Ghost is made by an independent non-profit organisation called the Ghost Foundation. We are 100% self funded by revenue from our \"],[0,[2],1,\"Ghost(Pro)\"],[0,[],0,\" service, and every penny we make is re-invested into funding further development of free, open source technology for modern publishing.\"]]],[1,\"p\",[[0,[],0,\"The version of Ghost you are looking at right now would not have been made possible without generous contributions from the open source \"],[0,[3],1,\"community\"],[0,[],0,\".\"]]],[1,\"h2\",[[0,[],0,\"Next up, the editor\"]]],[1,\"p\",[[0,[],0,\"The main thing you'll want to read about next is probably: \"],[0,[4],1,\"the Ghost editor\"],[0,[],0,\". This is where the good stuff happens.\"]]],[1,\"blockquote\",[[0,[5],0,\"By the way, once you're done reading, you can simply delete the default \"],[0,[0],1,\"Ghost\"],[0,[],1,\" user from your team to remove all of these introductory posts! \"]]]]}"}}

Error ID:
    e33263e0-43db-11e9-856c-33988f222ce4

Error Code:
    UPDATE_COLLISION

----------------------------------------

UpdateCollisionError: Saving failed! Someone else is editing this post.

We need to review what we pass into the context object for this case and other cases.
Looks like the logger is unable to format the context?

naz commented 5 years ago

Looks like the logger is unable to format the context?

It is outputting stringified object at the moment because most usages are passing in a string describing in what context the error happened (e.g. context: common.i18n.t('errors.api.users.noPermissionToDestroyUser')). A similar expectation is with help field.

Think by reviewing usages of context and help we should eliminate cases where we pass in an object (that could go into errorDetails if needed). Alternatively, we could pass these fields through prettyjson (just like errorDetails) and output them in yaml format.

kevinansfield commented 5 years ago

A couple of missing context values I noticed today:

POST /authentication/passwordreset/ with unknown email {message: "User not found.", context: null}
POST /authentication/session/ with unknown email {message: "Access denied.", context: null}

The unknown e-mail when signing in should be surfaced rather than saying "Access denied". In v0.1 we erred on the side of user-friendliness but it seems that got changed with v2.

kirrg001 commented 5 years ago

In v0.1 we erred on the side of user-friendliness but it seems that got changed with v2.

Model layer still returns this message. I guess the caller just overrides or inherits the correct error message.

ErisDS commented 5 years ago

I think this issue is being used to represent two different problems:

Too much information is getting output into the logs
Some error messages are missing critical context

Examples of both:

Too much info in logs:
- Every PUT & POST to posts endpoint logs the entire post object. I assume it's the same for all endpoints. This is way too much info for logs.
Error messages missing context:
- Those listed above
- https://forum.ghost.org/t/cant-upload-publication-icon/6136/3
- not sure if it's still happening for missing cookie header?

For 2, it's unlikely we'll get chance right away to do a full audit, and it's bigger than a Monday. For the time being, any broken error messages that we see reported in Support, forum, etc should be added here and fixed one-at-a-time as these are very Monday-possible tasks :)

pysysops commented 5 years ago

@ErisDS I'm going to add a GELF Stream to Ignition tomorrow so we can send logs over UDP to a centralised logging solution and do away with logging to files on shared storage.

Just to be clear the issue on Ghost Pro isn't the volume of logs. It was the volume of file renames that were being sent to the Gluster client on each apps server at file rollover. The reason that I've dropped to warn logging is so that we can reduce log rollover to once per week. Looking at the difference in IOPS at rollover time, we'd probably be okay re-enabling INFO logging, rolling daily and only keeping 1 or 2 previous logs?

naz commented 5 years ago

Regarding points raised in https://github.com/TryGhost/Ghost/issues/10571#issuecomment-471456706:

We need to review what we pass into the context object for this case and other cases.

Have reviewed all usages of context in the codebase and updated main issue with suggested changes.

Looks like the logger is unable to format the context?

We should not be passing JSON into context as the logger is expecting this field to be just a string, instead errorDetails should be used to log any JSON.

The above partially address the issue of "Too much information is getting output into the logs" (https://github.com/TryGhost/Ghost/issues/10571#issuecomment-480604010)

Regarding:

Every PUT & POST to posts endpoint logs the entire post object. I assume it's the same for all endpoints. This is way too much info for logs.

We currently log whole bodies in case of error during a request to all endpoints. The formatting happens here and the middleware that is responsible for the call is here. Agree that logging whole body is way too much, enough information should be provided when throwing an error. Suggest we remove body from the Ignition formatter, and in case it's needed we could add it behind the debug flag later?

ErisDS commented 5 years ago

@gargol the last thing is the most important change - we need to reduce the logging output.

naz commented 5 years ago

@ErisDS removed body serialization into Ignition with 457541806647adea6f01443b1cb0863198030789 and couple other optimizations ready here - https://github.com/TryGhost/Ghost/pull/10669.

The context in theme validation will need a closer look next Monday, as we have a logic elsewhere in the code that depends on this property in the error (details are in PR above).

stale[bot] commented 5 years ago

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs. Thank you for your contributions.

TryGhost / Ghost