Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: support tracing for untranspiled async/await in Node 8+ #775

Merged
merged 1 commit into from
Jun 28, 2018
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
7 changes: 0 additions & 7 deletions .circleci/config.yml
Original file line number Diff line number Diff line change
Expand Up @@ -4,8 +4,6 @@
node_modules_cache_key: &node_modules_cache_key node-modules-cache-{{ .Environment.CIRCLE_JOB }}-{{ arch }}-{{ checksum "package.json" }}-{{ checksum "package-lock.json" }}
test_fixtures_cache_key: &test_fixtures_cache_key test-fixtures-cache-{{ .Environment.CIRCLE_JOB }}-{{ arch }}-{{ checksum "test/fixtures/plugin-fixtures.json" }}
plugin_types_cache_key: &plugin_types_cache_key plugin-types-cache-{{ .Environment.CIRCLE_JOB }}-{{ arch }}-{{ checksum "src/plugins/types/index.d.ts" }}
test_env: &test_env
GCLOUD_TRACE_NEW_CONTEXT: 1
release_tags: &release_tags
tags:
only: /^v\d+(\.\d+){2}(-.*)?$/
Expand Down Expand Up @@ -126,7 +124,6 @@ jobs:
node4:
docker:
- image: node:4
environment: *test_env
- *mongo_service
- *redis_service
- *postgres_service
Expand All @@ -135,7 +132,6 @@ jobs:
node6:
docker:
- image: node:6
environment: *test_env
- *mongo_service
- *redis_service
- *postgres_service
Expand All @@ -144,7 +140,6 @@ jobs:
node8:
docker:
- image: node:8
environment: *test_env
- *mongo_service
- *redis_service
- *postgres_service
Expand All @@ -153,7 +148,6 @@ jobs:
node9:
docker:
- image: node:9
environment: *test_env
- *mongo_service
- *redis_service
- *postgres_service
Expand All @@ -162,7 +156,6 @@ jobs:
node10:
docker:
- image: node:10
environment: *test_env
- *mongo_service
- *redis_service
- *postgres_service
Expand Down
1 change: 0 additions & 1 deletion CONTRIBUTING.md
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,6 @@ The command `npm test` tests code the same way that our CI will test it. This is

There are a couple of environmental variables to note:

- Setting `GCLOUD_TRACE_NEW_CONTEXT` (to any string) activates `async_hooks`-based tracing on Node 8+. On versions of Node where `async_hooks` is available, tests should pass whether this variable is set or not.
- Setting `TRACE_TEST_EXCLUDE_INTEGRATION` (to any string) disables plugin tests when the command `npm run unit-test` is run. This is recommended for changes that do not affect plugins.
- Some integration tests depend on locally running database services. On Unix, you can use `./bin/docker-trace.sh start` to start these services.

Expand Down
19 changes: 5 additions & 14 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -120,23 +120,14 @@ A fully detailed overview of the `TraceApi` object is available [here](doc/trace

## How does automatic tracing work?

The Trace Agent automatically patches well-known modules to insert calls to functions that start, label, and end spans to measure latency of RPCs (such as mysql, redis, etc.) and incoming requests (such as express, hapi, etc.). As each RPC is typically performed on behalf of an incoming request, we must make sure that this association is accurately reflected in span data. To provide a uniform, generalized way of keeping track of which RPC belongs to which incoming request, we rely on the [`continuation-local-storage`][continuation-local-storage] module to keep track of the "trace context" across asynchronous boundaries.
The Trace Agent automatically patches well-known modules to insert calls to functions that start, label, and end spans to measure latency of RPCs (such as mysql, redis, etc.) and incoming requests (such as express, hapi, etc.). As each RPC is typically performed on behalf of an incoming request, we must make sure that this association is accurately reflected in span data. To provide a uniform, generalized way of keeping track of which RPC belongs to which incoming request, we rely on the following mechanisms to keep track of the "trace context" across asynchronous boundaries:
* [`continuation-local-storage`][continuation-local-storage] (which relies on [`async-listener`][async-listener]) in Node 6
* [`async_hooks`][async-hooks] in Node 8+

`continuation-local-storage`, which relies on [`async-listener`][async-listener] to preserve continuations over asynchronous boundaries, works great in most cases. However, it does have some limitations that can prevent us from being able to properly propagate trace context:
These mechanisms work great in most cases. However, they do have some limitations that can prevent us from being able to properly propagate trace context:

* It is possible that a module does its own queuing of callback functions – effectively merging asynchronous execution contexts. For example, one may write an http request buffering library that queues requests and then performs them in a batch in one shot. In such a case, when all the callbacks fire, they will execute in the context which flushed the queue instead of the context which added the callbacks to the queue. This problem is called the pooling problem or the [user-space queuing problem][queuing-problem], and is a fundamental limitation of JavaScript. If your application uses such code, you will notice that RPCs from many requests are showing up under a single trace, or that certain portions of your outbound RPCs do not get traced. In such cases we try to work around the problem through monkey patching, or by working with the library authors to fix the code to properly propagate context. However, finding problematic code is not always trivial.
* Presently, it is not possible for `async-listener` to keep track of transitions across `await`-ed lines in ES7 [`async` functions][async-await-docs] that are available with Node 7.6+. If your application uses untranspiled `async` functions, we will not be properly track RPCs.

### Tracing with `async/await`

Starting in module version 2.2, the Trace Agent ships with an experimental implementation (using the Node 8 `async_hooks` API) that supports `async`/`await`. To enable this implementation, run your application with the environmental variable `GCLOUD_TRACE_NEW_CONTEXT` set:

```bash
# Requires Node 8+
$ GCLOUD_TRACE_NEW_CONTEXT=1 npm start
```

We are actively looking for feedback on this new implementation. Please file an issue if you encounter unexpected or unwanted behavior.
* If your application uses untranspiled `async` functions, you must use Node 8+. (Untranspiled `async` functions are supported from Node 7.6 onward, but we do not support tracing these functions in Node 7.)

## Contributing changes

Expand Down
1 change: 0 additions & 1 deletion appveyor.yml
Original file line number Diff line number Diff line change
Expand Up @@ -16,7 +16,6 @@ install:
# Get the latest stable version of Node.js or io.js
- ps: Install-Product node $env:nodejs_version
- SET GCLOUD_PROJECT=0
- SET GCLOUD_TRACE_NEW_CONTEXT=1
- SET TRACE_TEST_EXCLUDE_INTEGRATION=1

# Post-install test scripts.
Expand Down
3 changes: 1 addition & 2 deletions src/config.ts
Original file line number Diff line number Diff line change
Expand Up @@ -32,8 +32,7 @@ export interface Config {
* Node binary version requirements are not met.
* - 'async-listener' uses an implementation of CLS on top of the
* `continuation-local-storage` module.
* - 'auto' behaves like 'async-hooks' on Node 8+ when the
* GCLOUD_TRACE_NEW_CONTEXT env variable is set, and 'async-listener'
* - 'auto' behaves like 'async-hooks' on Node 8+, and 'async-listener'
* otherwise.
* - 'none' disables CLS completely.
* - 'singular' allows one root span to exist at a time. This option is meant
Expand Down
3 changes: 1 addition & 2 deletions src/index.ts
Original file line number Diff line number Diff line change
Expand Up @@ -79,8 +79,7 @@ function initConfig(projectConfig: Forceable<Config>):

// If the CLS mechanism is set to auto-determined, decide now what it should
// be.
const ahAvailable = semver.satisfies(process.version, '>=8') &&
process.env.GCLOUD_TRACE_NEW_CONTEXT;
const ahAvailable = semver.satisfies(process.version, '>=8');
if (config.clsMechanism === 'auto') {
config.clsMechanism = ahAvailable ? 'async-hooks' : 'async-listener';
}
Expand Down
3 changes: 1 addition & 2 deletions system-test/trace-express.js
Original file line number Diff line number Diff line change
Expand Up @@ -42,8 +42,7 @@ const queryString = require('querystring');
const uuid = require('uuid');
const semver = require('semver');

const usingAsyncHooks = semver.satisfies(process.version, '>=8') &&
!!process.env.GCLOUD_TRACE_NEW_CONTEXT;
const usingAsyncHooks = semver.satisfies(process.version, '>=8');
console.log(`Running system test with usingAsyncHooks=${usingAsyncHooks}`);

// TODO(ofrobots): this code should be moved to a better location. Perhaps
Expand Down
2 changes: 1 addition & 1 deletion test/plugins/common.ts
Original file line number Diff line number Diff line change
Expand Up @@ -35,7 +35,7 @@ var semver = require('semver');

var logger = require('@google-cloud/common').logger;
var trace = require('../../..');
if (semver.satisfies(process.version, '>=8') && process.env.GCLOUD_TRACE_NEW_CONTEXT) {
if (semver.satisfies(process.version, '>=8')) {
// Monkeypatch Mocha's it() to create a fresh context with each test case.
var oldIt = global.it;
global.it = Object.assign(function it(title, fn) {
Expand Down
3 changes: 1 addition & 2 deletions test/test-config-cls.ts
Original file line number Diff line number Diff line change
Expand Up @@ -24,8 +24,7 @@ import {TraceCLSConfig, TraceCLSMechanism} from '../src/cls';
import * as testTraceModule from './trace';

describe('Behavior set by config for context propagation mechanism', () => {
const useAH = semver.satisfies(process.version, '>=8') &&
!!process.env.GCLOUD_TRACE_NEW_CONTEXT;
const useAH = semver.satisfies(process.version, '>=8');
const autoMechanism =
useAH ? TraceCLSMechanism.ASYNC_HOOKS : TraceCLSMechanism.ASYNC_LISTENER;
let capturedConfig: TraceCLSConfig|null;
Expand Down