Logging

goals

• full logging which outputs to stdout/stderr as we do now (and better!)
• ability to provide an adapter in future, to customise the destination/output of the logging system
• error levels
• application levels
• delete logic in errors/index.js

reasons why we have to change things

• we need a consistent way to a log into a file/stdout --> right now we use morgan to log requests and a custom logging (chalk and console.log) for errors
• we want to log more then just a single line GET URL StatusCode for requests (especially in development mode)
• what we want to achieve is printing all logs (request/response/errors) in the same format (which i think can be JSON)
• we need to tidy up (or remove) /errors/index.js, because it's doing more then it needs to do, is way to complicated in my opinion (we export ~15functions) and we want to differ the errors from a logging unit
• we want to create a real logging adapter (which can be replaced)
• this adapter can/should be used in each Ghost microservice
• we want to handle and tidy up context/help for errors
• we don't have proper levels (application levels, error levels, error codes)
• log into file has the background: if we log stdout into the process, the process will grow over time. if we log into a file, we can rotate on that log file an delete after x days (this is helpful for each blog running in production)
• remove the logger from migrations
• more reasoning/descriptions can be found in Discussion: Error handling, logging and debugging improvements #2001 and Epic: Server side error handling: codes, statuses, messaging & i18n #6526

bunyan vs. winston vs. debug

As already discussed, debug is a nice npm tool to get debug logs per file with auto-includes milliseconds between each debug log.
But our big goal is creating a logging unit, which can do more then just printing debug logs.
I've used winston in the past and we've switched to bunyan, because the bunyan API is easier to use, easier to read and it has the advantage of nice JSON prints. That's why i would go with bunyan.

create a default logging adapter

server/logging/default.js

Developers should easily add custom loggers, if they prefer a different logger.
It should provide functions like info, error, warn, and debug.

info

• with info you can just log a single line like "ghost server is starting"
• with info you can also log complex json objects like request/response

error

• accepts an error object and optional request/response object

warn

• accepts only a string

debug

• accepts a single JSON object
• accepts a single string

  var logging = require('/logging'); 
  logging.error({ err: err, req: req, res: res });
  logging.info('server starts now...'); 
  logging.info({ req: req, res: res }); 

output

Right now our server print looks like (only stdout):

GET / 200 140.121 ms - -
GET /assets/js/jquery.fitvids.js?v=4d853bd599 200 17.077 ms - -
GET /assets/js/index.js?v=4d853bd599 200 16.385 ms - -
GET /assets/css/screen.css?v=4d853bd599 200 19.621 ms - -

This print is managed by morgan, which is configured in middlewares/index.js. We will delete this.
Instead we will auto log requests/responses/errors.

  expressApp1.use(logging.utils.express);
  expressApp2.use(logging.utils.express);

function express
  res.once('finish', function() {
    if (req.err) {
      logging.error({ req: req, res: res, err: req.err });
    }
    else {
       logging.info({ req: req, res: res });
     }     
  });

   next();
});

Which can look like (transport: stdout)

Which can look like (transport: file)

We could extend our upcoming Ghost CLI to offer: ghost-cli log (which will prettify the .log file)

log into file

We should be able to configure the transport (file, stdout)
We can start defining the transport per env.

production
file only

staging
file only

development
stdout only

application levels

Every env is by default in level info.
You can either force starting it different mode (debug) by changing the config or using NODE_LEVEL.

error levels

Each error will be default in level "normal".
We can define an error as critical, which get's treated differently in Ghost(Pro).

time diffs

We can add time diffs between logs, like the npm module debug is offering. Not high prio.

ensure we don't log credentials

Filter attributes.

bring help/context into errors

Right now we pass context and help as different parameters.
We want to achieve having context and help as part of an error.

show debug logs in testing mode

NODE_LEVEL=debug grunt test or grunt test -d (--debug)
Should show print outs like errors.

TODO

• .gitkeep log Folder in content
• logging on windows
• add issue to ignition: source out logging middleware
• create issue: jsonapi format (need to solve together with Ghost-Admin)
• logging adapter to ignition
• design how to add custom loggers
• adapt express app handling for errors
• remove errors/index
• remove all errors and create GhostError to inherit from
• option pattern for errors
• ghost.log location
• care about info, warn and debug (they should all use the available logger)
• how many rotated files? (100 was suggested)
• use debug instead of logging.debug - one true way for now
• reconsider stdout pretty stream (show some other examples)
• add duration for requests
• show errors when running tests
• print into one file or print into multiple files?
• hide stack for html pages? (404, Maintenance & DatabaseVersion errors don't need a stack)
• add https://github.com/TryGhost/Ghost/compare/master...kirrg001:1.0.0-dev/error-creation?expand=1#diff-62c0cd82e9025a6fff595f2ce261aa2bR54
• config log file location configureabe
• individual ID to errors
• add unique request id
• decouple req.err?how?