Express-graphql: support graphql request metrics trace

[violet-day]

In graphql,all request is POST and in the same url.

Because of this,the server side can not distinguish which request is slow.

In below query,is there any way to get the TestQuery value before graphql execute so I can trace the query name and log it's cost time?

Query TestQuery{
  ping
}

[lacker]

I think right now you'd have to write a custom express middleware that extracts this.

It seems like it might be useful to have this data somewhere that's easily accessible from application code. In express itself the request object serves this purpose of exposing information about the transport layer - there's lots of fields like headers and ips and proxy information and so on, which mostly you can ignore, but occasionally you want to access. In express-graphql there is not really a logical place to put this sort of request-parsing-byproduct right now though.

[leebyron]

Perhaps koa's middleware model would be better for something like this at the moment since it lets you set up metadata that wraps the result of a lower middleware. Koa support isn't built in yet, but probably should be soon, in the meantime there are some koa plugins out there that would let you do this.

[richburdon]

Here's my solution (will send a PR if anyone thinks it's useful).

server.js

router.use(options.graphql, graphqlLogger());

logger.js

'use strict';

import _ from 'lodash';
import moment from 'moment';

const TS = 'hh:mm:ss.SSS';

const LEN = 80;
const HEADER = _.repeat('#', LEN - TS.length - 17);
const FOOTER = _.repeat('#', LEN);
const PRETTY_REQ = '\n### [REQ] ' + HEADER + ' [%s] ###\n%s\nvariables = %s\n' + FOOTER + '\n';
const PRETTY_RES = '\n### [RES] ' + HEADER + ' [%s] ###\n%s\n' + FOOTER + '\n';

/**
 * Debug logging middleware for graphqlExpress request/responses.
 *
 * @param options
 */
export const graphqlLogger = (options={ logging: true, pretty: true }) => {
  return (req, res, next) => {
    if (options.logging) {
      let stringify = options.pretty ?
        (json) => JSON.stringify(json, 0, 2) :
        (json) => JSON.stringify(json);

      let { operationName, query, variables } = req.body;

      if (options.pretty) {
        console.log(PRETTY_REQ, moment().format(TS), query, stringify(variables));
      } else {
        query = query.replace(/\s*\n\s*/g, ' ');
        console.log('### REQ ### %s %s', query, stringify(variables));
      }

      // Monkey patch.
      // https://github.com/axiomzen/express-interceptor/blob/master/index.js
      // http://stackoverflow.com/questions/19215042/express-logging-response-body
      let originalWrite = res.write;
      res.write = (data) => {
        switch (res.statusCode) {
          case 200:
            if (options.pretty) {
              console.log(PRETTY_RES, moment().format(TS), stringify(JSON.parse(data)));
            } else {
              console.log('### RES ### %s', data);
            }
            break;

          default:
            console.error(data);
        }

        return originalWrite.call(res, data);
      };
    }

    next();
  }
};