Preserve the current zone if there is one, on e.g. request.log

[cbastuck]

When using zone.js all reporters are invoked in the root zone (https://github.com/hapijs/good/blob/master/lib/monitor.js#L218) because this is the current zone when registering the async event listener (https://github.com/hapijs/good/blob/master/lib/monitor.js#L147).

This patch stores the current zone (if available) in the event data which is passed to the registered reporter. The reporter is then able to run correlated tasks inside of this zone.

[Marsup]

What the hell is that ???

[cbastuck]

The description came a bit later sorry, does it make more sense to you after reading it?

[Marsup]

This looks like it could as well be in your own transformer, couldn't it ?

[cbastuck]

By transformer you mean an instance of Stream.Transform (e.g. https://github.com/hapijs/good-console/blob/master/lib/index.js)? This would not help: the async call to _transform() runs in the same zone as _write().

But if you refer to a synchronous call, it sounds promising. Maybe you have a link to the API you refer to?

[arb]

You'll need to write your own transform stream to add this information to your logs. As it is, Zone is always undefined anyway.

[cbastuck]

@arb I should have given more context. The following example draws a bigger picture for the PR:

package.json:

{
  "name": "hapi_good_ai",
  "version": "1.0.0",
  "main": "index.js",
  "dependencies": {
    "applicationinsights": "^1.0.1",
    "good": "^7.3.0",
    "hapi": "^16.6"
  }
}

index.js:

const Hapi = require('hapi');
const Stream = require('stream');
const applicationinsights = require('applicationinsights');

function setupApplicationInsights() {
  const instrumentationKey = 'abcdefgh-ijkl-mnop-qrstuvwxyz12';
  const serviceName = 'test';
  applicationinsights
    .setup(instrumentationKey)
    .setAutoCollectConsole(true)
    .setAutoCollectExceptions(true)
    .setAutoCollectPerformance(true)
    .setAutoCollectRequests(true)
    .setAutoCollectDependencies(true)
    .setAutoDependencyCorrelation(true)
    .start();
  const client = applicationinsights.defaultClient;
  client.context.tags['ai.cloud.role'] = serviceName;
  return client;
}
const client = setupApplicationInsights();

class CustomGoodReporter extends Stream.Writable {
  constructor() {
    super({ objectMode: true });
  }

  _write(eventData, _, callback) {
    if (eventData.event === 'request') {
      console.log('Zone in reporter', Zone.current.name);
      client.trackTrace({ message: eventData.message });
    }
    callback(null);
  }
}

const options = {
  connection: {
    port: 8080,
    host: '0.0.0.0'
  },
  good: {
    reporters: {
        custom: [
            {
                module: CustomGoodReporter
            }
        ]
    }
  }
}

async function setupServer() {
  const server = new Hapi.Server();
  await server.connection(options.connection);
  await server.register(
    {
      register: require('good'),
      options: options.good
    }
  );

  server.route({
    method: 'GET',
    path: '/foo',
    handler: async (request, reply) => {
        console.log('Zone in handler', Zone.current.name);
        request.log('info', { message: 'This log should be reported in the zone of the request'});
        return reply({ success: true }).type('application/json');
    }
  });
  return server;
}

setupServer()
  .then(server => {
    server.start();
    console.log('Server running ...');
  });

The test server exposes endpoint /foo which writes a log message (correlated to the request) to a custom reporter. In this example the custom reporter forwards the logs to Application Insights, which uses Zone.js to track the context of different requests. The issue is not only related to AppInsights but to arbitrary dependencies that use Zone.js internally and are used via good likewise.

The produced output is:

Server running ...
Zone in handler AI-|7F4DDB92-F6C2-4908-9EAA-13B1068B064F.
Zone in reporter <root>

The output shows that we are losing the zone of the request. The initial PR description links the code responsible for this (I can provide more details if these are valuable to you).

Obviously the PR is a bit of a workaround. The ideal solution would run the reporter in the request's zone instead of just preserving it. IMO this is the smallest change to make good.js "zone-aware". What do you think given the repro and the broader context?

[arb]

This is extremely specific application logic so I really don't think it belongs inside the main good project. That being said, I don't think this is going to really solve your problem, you're always going to get the timezone the reporter is running on. You're be better served to try to look up the request's IP address and infer the timezone based on the geolocation.

[cbastuck]

There is a misconception about zone.js On the GitHub page you'll find a short intro video. It's more generic than application specific. (https://github.com/angular/zone.js)

The idea is to capture the execution context of async, consecutive/correlated tasks. This provides valuable information especially for error reporting (eg. async stack traces). Application Insights is using zonejs to correlate requests across microservices, e.g. WebApp > Service A > Service B > Service C

[cbastuck]

Please let me know if you are considering to re-open the PR?

[Marsup]

~Have you actually tried setting up a transform stream to see if it solves your problem ? I agree this doesn't belong in good, and you should exhaust all options before going that path.~

My bad, I see you did that in the comment above. We should find other ways to achieve this without including this code inside good.

[cbastuck]

I don't see a way of solving this issue without any code change in good: it's where the information is lost.

Example: if you log the current zone before that line you see the zone of the current request. Log again inside of the _write (or _transform) of the reporter and you see that the call runs in the root zone, because the async event listeners got registered inside of that root zone. Hence follow-up emits, also run inside of this zone. I posted a repro code in the previous comment

[Marsup]

I'm not saying good can't be modified, just that it's too specific, but I'm not going to be the one deciding how it's done.

[cbastuck]

To follow-up on the "how" I posted this question to the zone.js community: https://github.com/angular/zone.js/issues/976

It formalizes the root cause behind this issue in a good-agnostic form.

[cbastuck]

Until the issue has been addressed by the good.js team one workaround is restoring the original EventEmitter functionality before registering good. For example:

if (typeof Zone !== 'undefined') {
    EventEmitter.prototype.on = EventEmitter.prototype[Zone.__symbol__('addListener')];
    await hapiServer.register({ register: require('good'), options: options.good }); 
    EventEmitter.prototype.on = EventEmitter.prototype.addListener;
}

Note: zone.js patches on and addListener with the same function

[lock[bot]]

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.