Support hapi@17

[kjin]

This issue tracks support for hapi 17 tracing.

[BenCrux]

@kjin anything I can do to help with this effort?

[kjin]

@BenCrux Yes! A PR would be greatly appreciated. The Hapi tracing plugin currently goes up to 16.

As hapi 17 types aren't released yet (tracking issue), you can modify plugin-hapi.ts, and remove this line to prevent strict type checking for that file. (If you feel compelled to use the WIP type definitions mentioned in the issue -- let me know, I can open a PR for my work to enable type definitions for multiple versions of the same module.)

The relevant unit tests are a little bit in flux so don't worry about them for now -- I'll update this issue when the new unit tests for web frameworks are landed.

edit: I'm working on this now (2018-02-20)

[BenCrux]

Thanks @kjin! I started looking at this and do have it working in a handcrafted way. One thing that I had to do was change the AsyncHooksNamespace (cls-ah.js) not to reset 'current' in runAndReturn. I didn't really understand why it was doing that. Since runAndReturn is used in the runInRootSpan and that's when the root span is saved to cls, so it never gets persisted and you can never create child spans (because the root span can't be found). What am I missing here?

[kjin]

Great! I've actually started work to change the plugin system to allows multiple plugins for a single module, which should help (because that way we can use different type definitions for different plugins).

It's true that the root span is associated with current, which gets unset when runAndReturn is done running. This is OK since we would expect the code that runs in runAndReturn to start doing asynchronous work. When async work is started, the init hook is run, and when the async work finishes, the before hook is run immediately before the continuing callback starts. In the code, you can see that init saves current and before restores it.

I'm more than happy to dive into more details if you need -- since I'm not sure how familiar you are with async_hooks as an API.

If it helps, while working on it feel free to modify plugin-hapi.ts at will (instead of trying to preserve existing code for previous versions) -- we can sort that out later in a PR, given that my pre-requisite work is still in progress.

[BenCrux]

Ah ok - makes sense, thanks! I think the problem I'm butting up against is that I'm using a lifecycle method in hapi; server.ext('onRequest', ... this just returns and the initial request continues processing, so no async code is run with in the function passed to runInRootSpan. Now I think about it, the method naming makes sense for what it's doing. Given that - is there a better way to start and end a root span when the async code won't get started in the method you pass into runInRootSpan?

[kjin]

If I understand the lifecycle flow in Hapi correctly, what you're saying is that you'd be specifying multiple handlers for a single request, and the handler in which asynchronous work is being done may not be in the 'onRequest' ext handler which is patched to be run in a root span -- is my understanding correct?

The existing model for ending root spans is to find the raw response.end function somewhere in the request object passed to the handle and wrap it -- this is the current usage in other web framework tracing plugins.

As for starting async work outside of the 'onRequest' handler, I would expect that any additional handlers are called with a common Request parameter. You'd likely have to store some data on this parameter -- let me play with this a little more and get back to you.

[BenCrux]

Yes that's correct. It's my understanding that the onRequest ext handler it just a lifecycle method - ie, it get's called when a request is made, does it's thing and then returns control to hapi to actualy service the request. Therefor, no actual async processing is started from there - with the exception of registering an endSpan call on response.end. Storing data on the request parameter seems reasonable, but it's not immediately obvious to me what I'd store that'd get me anywhere - when creating a child span it always seems to rely on the cls mechanism to lookup the root span and so is something I can't specify.

[kjin]

You can store a bound function on the request object as follows:

const assert = require('assert');
const trace = require('@google-cloud/trace-agent').start();
const kBind = Symbol();

function preWork(request) {
  trace.runInRootSpan({ name: 'parent' }, (span) => {
    request[kBind] = trace.wrap(fn => trace.wrap(fn));
  });
}

const request = {};
preWork(request);
const work = request[kBind](() => {
  const span = trace.createChildSpan({ name: 'child' });
  console.log(span); // not null
});
work();

This might seem a bit of a hack, but I believe it may only be possible to do away with storing an extra property on the request object if we're monkeypatching at a lower level where the request object is actually being passed to these functions (just a thought -- it might not be worth the extra brittleness of doing so)

[kjin]

Hi @BenCrux, do you have an update on this?

If you've been busy but have any partial work done I'd be happy to take it from there 😁

[BenCrux]

Hi @kjin - yeah we got it I think working, happy to share what we did - I'm not sure it's 100% correct. We are basically monkey patching the hander.execute method in a hapi plugin:

// Ported from Google's HAPI plugin:
// https://github.com/GoogleCloudPlatform/cloud-trace-nodejs/blob/54dd734/src/plugins/plugin-hapi.ts
const traceApi = require('@google-cloud/trace-agent').get();
const urlParse = require('url').parse;
const handler = require('hapi/lib/handler');


function getFirstHeader(req, key) {
  let headerValue = req.headers[key] || null;
  if (headerValue && typeof headerValue !== 'string') {
    headerValue = headerValue[0];
  }
  return headerValue;
}

exports.plugin = {
  register: async (server, options) => {
    const oldExecute = handler.execute;

    handler.execute = async (request) => {

      const req = request.raw.req;
      const res = request.raw.res;
      const options = {
        name: req.url ? (urlParse(req.url).pathname || '') : '',
        url: req.url,
        traceContext:
          getFirstHeader(req, traceApi.constants.TRACE_CONTEXT_HEADER_NAME),
        skipFrames: 3
      };

      let rootSpanResponse = traceApi.runInRootSpan(options, async (root) => {
        let oldExecuteResponse = await oldExecute(request);
        if (root) {
          const responseTraceContext = traceApi.getResponseTraceContext(options.traceContext || null, !!root);
          if (responseTraceContext) {
            res.setHeader(
              traceApi.constants.TRACE_CONTEXT_HEADER_NAME, responseTraceContext);
          }
          traceApi.wrapEmitter(req);
          traceApi.wrapEmitter(res);

          const url = `${req.headers['X-Forwarded-Proto'] || 'http'}://${
            req.headers.host}${req.url}`;

          // we use the path part of the url as the span name and add the full
          // url as a label
          // req.path would be more desirable but is not set at the time our
          // middleware runs.
          root.addLabel(traceApi.labels.HTTP_METHOD_LABEL_KEY, req.method);
          root.addLabel(traceApi.labels.HTTP_URL_LABEL_KEY, url);
          root.addLabel(traceApi.labels.HTTP_SOURCE_IP, req.connection.remoteAddress);

          // wrap end
          let originalEnd = res.end;
          res.end = function () {
            res.end = originalEnd;
            const returned = res.end.apply(this, arguments);

            if (request.route && request.route.path) {
              root.addLabel('hapi/request.route.path', request.route.path);
            }
            root.addLabel(traceApi.labels.HTTP_RESPONSE_CODE_LABEL_KEY, res.statusCode);
            root.endSpan();

            return returned;
          };

          // if the event is aborted, end the span (as res.end will not be called)
          request.events.once('disconnect', () => {
            root.addLabel(traceApi.labels.ERROR_DETAILS_NAME, 'aborted');
            root.addLabel(
              traceApi.labels.ERROR_DETAILS_MESSAGE, 'client aborted the request');
            root.endSpan();
          });
        }
        return oldExecuteResponse;
      });
      return rootSpanResponse;
    }
  },
  name: "stackdriverTracing"
};

Would be great to get your feedback on the correctness of this etc. We think we might be miss-attributing sub-traces sometimes.

[ofrobots]

@BenCrux would you mind opening a PR with what you have? We can add onto the PR, but having a PR will ensure that the commit gets credited back to you and also to ensure we have the right CLAs in place to accept your contribution.

[BenCrux]

@ofrobots so this is just a hapi plugin we wrote and then inject into the server, so it doesn't really fit into the existing code base anywhere (I think?); it's also not typescript. If you give me a directory to check this file in, then happy do to that - although we don't care about attribution, most of this is a copy of the existing code with some minor tweaks.

[kjin]

Hapi 17 tracing support has been officially added in 2.7.0. Please file a new issue if there are any problems with it!

Important You'll need to enable async_hooks tracing with env var GCLOUD_TRACE_NEW_CONTEXT=1.

/cc @BenCrux