search

elastic / apm-agent-nodejs

https://www.elastic.co/guide/en/apm/agent/nodejs/current/index.html
BSD 2-Clause "Simplified" License
582 stars 224 forks source link

Agent not sending timeline spans for self-calls #363

Closed jdelman closed 6 years ago

jdelman commented 6 years ago

Describe the bug Timeline spans do not show up for requests made to an API server from itself.

To Reproduce Steps to reproduce the behavior:

  1. Make a call to Node server in request, i.e. 
    app.get('/test', (req, res) => request('http://localhost:3000/somethingelse').pipe(res));

Expected behavior Expected to see the timeline spans in APM/Kibana.

Environment

How are you starting the agent? (please tick one of the boxes)

Additional context We're using an AWS ELB and some other proxies in between the server and the internet. Direct calls to the API don't have this problem.

Agent config options

Click to expand ``` { serviceName: 'antares', maxQueueSize: 50, flushInterval: 5, active: NODE_ENV === 'production' && APM_SERVER_URL, serverUrl: APM_SERVER_URL, captureErrorLogStackTraces: 'always', captureExceptions: true, } ```

package.json dependencies

Click to expand ``` { "@snaps/data-helpers": "^1.7.0", "@snaps/eslint-config-snaps": "^1.0.0", "@snaps/sails-mongo": "^0.12.4", "JSV": "^4.0.2", "abbrev": "^1.0.7", "accepts": "^1.3.3", "after": "^0.8.1", "align-text": "^0.1.4", "ambi": "^2.5.0", "amdefine": "^1.0.0", "anchor": "^0.11.2", "ansi-regex": "^0.2.1", "ansi-styles": "^1.0.0", "ap": "^0.2.0", "apn": "^2.2.0", "argparse": "^0.1.16", "array-find-index": "^1.0.1", "arraybuffer.slice": "^0.0.6", "asap": "^1.0.0", "asn1": "^0.2.3", "assert-plus": "^0.2.0", "async": "^2.1.4", "aws-sdk": "^2.5.2", "aws-sign2": "^0.6.0", "aws4": "^1.4.1", "backo2": "^1.0.2", "balanced-match": "^0.4.1", "barrels": "^1.6.4", "base64-arraybuffer": "^0.1.2", "base64-url": "^1.2.1", "base64id": "^0.1.0", "basic-auth": "^1.0.4", "basic-auth-connect": "^1.0.0", "batch": "^0.5.3", "bcrypt": "^0.8.6", "benchmark": "^1.0.0", "better-assert": "^1.0.2", "bindings": "^1.2.1", "bl": "^1.1.2", "blob": "^0.0.4", "bluebird": "^2.11.0", "body-parser": "^1.13.3", "boom": "^2.10.1", "brace-expansion": "^1.1.4", "browserify-zlib": "^0.1.4", "bson": "^0.4.23", "bson-objectid": "^1.1.5", "buffer-writer": "^1.0.1", "builtin-modules": "^1.1.1", "bytes": "^2.3.0", "callsite": "^1.0.0", "camelcase": "^2.1.1", "camelcase-keys": "^2.1.0", "captains-log": "^0.11.11", "caseless": "^0.11.0", "center-align": "^0.1.3", "chai": "^3.5.0", "chai-http": "^3.0.0", "chalk": "^0.4.0", "cheerio": "^1.0.0-rc.2", "clean-css": "^2.1.8", "cliui": "^2.1.0", "coffee-script": "^1.10.0", "colors": "latest", "combined-stream": "^1.0.5", "commander": "^2.1.0", "component-bind": "^1.0.0", "component-emitter": "^1.1.2", "component-inherit": "^0.0.3", "compressible": "^2.0.8", "compression": "^1.6.2", "concat-map": "^0.0.1", "concat-stream": "^1.4.10", "connect": "^2.30.0", "connect-flash": "^0.1.1", "connect-mongo": "1.0.2", "connect-timeout": "^1.6.2", "consolidate": "^0.12.1", "content-disposition": "^0.5.0", "content-type": "^1.0.2", "convert-to-ecmascript-compatible-varname": "^0.1.5", "cookie": "^0.1.2", "cookie-parser": "^1.3.5", "cookie-signature": "^1.0.6", "core-util-is": "^1.0.2", "crc": "^3.3.0", "cron": "^1.1.0", "cross-spawn": "^0.2.9", "cross-spawn-async": "^2.2.2", "cryptiles": "^2.0.5", "csextends": "^1.0.3", "csrf": "^3.0.1", "csurf": "^1.8.3", "csv-parse": "^1.1.7", "csv-write-stream": "^2.0.0", "cycle": "^1.0.3", "dargs": "^4.1.0", "dashdash": "^1.13.1", "dateformat": "^1.0.2-1.2.3", "debug": "^2.2.0", "decamelize": "^1.2.0", "deep-diff": "^0.3.3", "deep-equal": "^0.0.0", "deep-extend": "^0.2.11", "define-properties": "^1.1.2", "defined": "^0.0.0", "delayed-stream": "^1.0.0", "depd": "^1.0.1", "destroy": "^1.0.4", "dist-exiftool": "^10.33.0", "dot-access": "^1.0.0", "dotenv": "^5.0.1", "dynasty": "^0.2.4", "eachr": "^2.0.4", "ecc-jsbn": "^0.1.1", "editions": "^1.1.1", "ee-first": "^1.1.1", "ejs": "^2.5.7", "ejs-locals": "^1.0.2", "elastic-apm-node": "^1.5.1", "elasticlunr": "^0.9.5", "engine.io": "^1.6.9", "engine.io-client": "^1.6.9", "engine.io-parser": "^1.2.4", "errno": "^0.1.4", "error-ex": "^1.3.0", "errorhandler": "^1.4.3", "es6-promise": "^3.0.2", "escape-html": "^1.0.3", "escape-string-regexp": "^1.0.5", "esprima": "^1.0.4", "etag": "^1.7.0", "eventemitter2": "^0.4.14", "exit": "^0.1.2", "express": "^3.21.2", "express-csv": "^0.6.0", "express-handlebars": "^3.0.0", "express-session": "^1.12.1", "extend": "^3.0.0", "extendr": "^2.1.0", "extract-opts": "^2.2.0", "extsprintf": "^1.0.2", "eyes": "^0.1.8", "fast-levenshtein": "^2.0.6", "faye-websocket": "^0.4.4", "feedparser": "^2.2.1", "figures": "^1.6.0", "file-type": "^4.0.0", "finalhandler": "^0.4.0", "find-up": "^1.1.2", "findup-sync": "^0.1.3", "flat": "^2.0.1", "foreach": "^2.0.5", "foreachasync": "^3.0.0", "forever": "^0.15.3", "forever-agent": "^0.6.1", "form-data": "^1.0.0-rc4", "forwarded": "^0.1.0", "fresh": "^0.3.0", "fs-extra": "^4.0.1", "function-bind": "^1.1.0", "gaze": "^0.4.3", "generate-function": "^2.0.0", "generate-object-property": "^1.2.0", "generic-pool": "^2.1.1", "geojsonhint": "^1.1.0", "get-stdin": "^4.0.1", "getobject": "^0.1.0", "getpass": "^0.1.6", "glob": "^3.1.21", "globule": "^0.1.0", "graceful-fs": "^1.2.3", "graceful-readlink": "^1.0.1", "grunt": "0.4.5", "grunt-cli": "^0.1.13", "grunt-contrib-clean": "0.6.0", "grunt-contrib-coffee": "0.13.0", "grunt-contrib-concat": "0.5.1", "grunt-contrib-copy": "0.5.0", "grunt-contrib-cssmin": "0.9.0", "grunt-contrib-jst": "0.6.0", "grunt-contrib-less": "1.1.0", "grunt-contrib-sass": "^1.0.0", "grunt-contrib-uglify": "0.7.0", "grunt-contrib-watch": "0.5.3", "grunt-legacy-log": "^0.1.3", "grunt-legacy-log-utils": "^0.1.1", "grunt-legacy-util": "^0.2.0", "grunt-lib-contrib": "^0.7.1", "grunt-sails-linker": "^0.10.1", "grunt-sync": "0.2.4", "gzip-size": "^0.1.1", "handlebars": "^4.0.5", "har-validator": "^2.0.6", "has-ansi": "^0.1.0", "has-binary": "^0.1.7", "has-color": "^0.1.7", "has-cors": "^1.1.0", "hawk": "^3.1.3", "hoek": "^2.16.3", "hooker": "^0.2.3", "hosted-git-info": "^2.1.4", "http-errors": "^1.3.1", "http-signature": "^1.1.1", "i": "^0.3.5", "i18n": "^0.8.1", "ical-generator": "^0.2.9", "iconv-lite": "^0.2.11", "ignorefs": "^1.1.1", "ignorepatterns": "^1.1.0", "image-size": "^0.3.5", "include-all": "^0.1.6", "indent-string": "^2.1.0", "indexof": "^0.0.1", "inflight": "^1.0.4", "inherits": "^2.0.1", "ini": "^1.3.4", "ip": "^1.1.5", "ipaddr.js": "^1.0.5", "is-absolute": "^0.1.7", "is-arrayish": "^0.2.1", "is-buffer": "^1.1.3", "is-builtin-module": "^1.0.0", "is-finite": "^1.0.1", "is-my-json-valid": "^2.13.1", "is-property": "^1.0.2", "is-relative": "^0.1.3", "is-typedarray": "^1.0.0", "is-utf8": "^0.2.1", "isarray": "^0.0.1", "isexe": "^1.1.2", "isstream": "^0.1.2", "istanbul": "^0.4.5", "jmespath": "^0.15.0", "jodid25519": "^1.0.2", "js-yaml": "^2.0.5", "json-schema": "^0.2.2", "json-stringify-safe": "^5.0.1", "json2csv": "^3.7.3", "json3": "^3.2.6", "jsonfile": "^2.3.1", "jsonify": "^0.0.0", "jsonlint-lines": "^1.6.0", "jsonpointer": "^2.0.0", "jsonwebtoken": "^7.1.9", "jsprim": "^1.2.2", "jszip": "^3.1.2", "jwk-to-pem": "^1.2.6", "jwt-simple": "^0.5.0", "kerberos": "0.0.21", "kind-of": "^3.0.3", "lazy-cache": "^1.0.4", "less": "^2.5.3", "load-json-file": "^1.1.0", "lodash": "^4.12.0", "lodash.isarray": "^3.0.4", "lodash.iserror": "^3.1.1", "lodash.isfunction": "^3.0.8", "lodash.isnull": "^3.0.0", "lodash.isobject": "^3.0.2", "lodash.isregexp": "^3.0.5", "lodash.isstring": "^3.0.1", "lodash.isundefined": "^3.0.1", "longest": "^1.0.1", "loud-rejection": "^1.3.0", "lru-cache": "^2.7.3", "machine": "^4.1.1", "machinepack-urls": "^3.1.1", "mailcomposer": "^3.10.0", "mailparser": "^2.0.5", "make-plural": "^3.0.5", "map-obj": "^1.0.1", "math-interval-parser": "^1.1.0", "maxmin": "^0.1.0", "md5": "^2.2.1", "media-typer": "^0.3.0", "meow": "^3.7.0", "merge-defaults": "^0.2.1", "merge-descriptors": "^1.0.0", "messageformat": "^0.3.1", "method-override": "^2.3.5", "methods": "^1.1.2", "mime": "^1.3.4", "mime-db": "^1.23.0", "mime-types": "^2.1.11", "minimatch": "^0.2.14", "minimist": "^1.1.1", "mkdirp": "^0.5.1", "mocha": "^3.0.2", "mock-req": "^0.2.0", "mock-res": "^0.3.0", "moment": "^2.21.0", "moment-range": "^2.2.0", "moment-timezone": "^0.5.13", "mongodb": "^2.2.26", "mongodb-core": "^2.1.10", "morgan": "^1.6.1", "ms": "^0.7.1", "multiparty": "^3.3.2", "mustache": "^2.2.1", "mute-stream": "^0.0.6", "nan": "^2.2.1", "native-or-bluebird": "^1.1.2", "ncp": "^0.4.2", "negotiator": "^0.6.1", "newrelic": "^1.27.2", "node-gcm": "^0.14.3", "node-uuid": "^1.4.7", "nomnom": "^1.8.1", "nopt": "^1.0.10", "noptify": "^0.0.3", "normalize-package-data": "^2.3.5", "number-is-nan": "^1.0.0", "oauth-sign": "^0.8.2", "object-assign": "^4.1.0", "object-component": "^0.0.3", "object-hash": "^0.3.0", "object-keys": "^1.0.9", "object.assign": "^4.0.3", "on-finished": "^2.3.0", "on-headers": "^1.0.1", "once": "^1.3.3", "optimist": "^0.6.1", "options": "^0.0.6", "packet-reader": "^0.2.0", "pako": "^0.2.8", "parse-json": "^2.2.0", "parsejson": "^0.0.1", "parseqs": "^0.0.2", "parseuri": "^0.0.4", "parseurl": "^1.3.1", "path-exists": "^2.1.0", "path-is-absolute": "^1.0.0", "path-type": "^1.1.0", "pause": "^0.0.1", "pem": "^1.9.7", "pg": "^6.4.0", "pg-connection-string": "^0.1.3", "pg-escape": "^0.2.0", "pg-types": "^1.11.0", "pgpass": "^0.0.3", "pify": "^2.3.0", "pinkie": "^2.0.4", "pinkie-promise": "^2.0.1", "pkginfo": "^0.4.0", "pluralize": "^1.2.1", "postgres-array": "^1.0.0", "postgres-bytea": "^1.0.0", "postgres-date": "^1.0.1", "postgres-interval": "^1.0.2", "pretty-bytes": "^0.1.2", "process-nextick-args": "^1.0.7", "promise": "^6.1.0", "promised-io": "^0.3.3", "prompt": "^0.2.14", "proxy-addr": "^1.0.10", "prr": "^0.0.0", "pseudomap": "^1.0.2", "puppeteer": "^1.1.1", "qs": "^6.1.0", "random-bytes": "^1.0.0", "range-parser": "^1.0.3", "raven": "^2.5.0", "raw-body": "^2.1.6", "rc": "1.0.1", "read": "^1.0.7", "read-pkg": "^1.1.0", "read-pkg-up": "^1.0.1", "readable-stream": "^1.1.14", "redent": "^1.0.0", "redis": "^2.7.1", "redis-notifier": "^1.0.0", "repeat-string": "^1.5.4", "repeating": "^2.0.1", "reportback": "^0.1.9", "request": "^2.72.0", "request-promise": "^4.2.1", "require-directory": "^2.1.1", "resolve": "^0.3.1", "response-time": "^2.3.1", "revalidator": "^0.1.8", "right-align": "^0.1.3", "rimraf": "^2.2.8", "rndm": "^1.2.0", "rrule": "^2.1.0", "rttc": "^9.3.3", "s3-policy": "^0.2.0", "safefs": "^3.2.2", "sails": "^0.12.3", "sails-build-dictionary": "^0.10.1", "sails-disk": "^0.10.9", "sails-generate": "^0.13.0", "sails-generate-adapter": "^0.10.5", "sails-generate-api": "^0.10.0", "sails-generate-backend": "^0.12.6", "sails-generate-controller": "^0.10.9", "sails-generate-frontend": "^0.12.1", "sails-generate-generator": "^0.10.11", "sails-generate-gruntfile": "^0.10.10", "sails-generate-model": "^0.10.12", "sails-generate-new": "^0.10.27", "sails-generate-sails.io.js": "^0.13.3", "sails-generate-views": "^0.10.8", "sails-generate-views-jade": "^0.10.4", "sails-hook-email": "^0.12.1", "sails-hook-orm": "^1.0.6", "sails-hook-sockets": "^0.13.7", "sails-mongo": "^0.12.2", "sails-stringfile": "^0.3.2", "sails-util": "^0.11.0", "sails.io.js-dist": "^0.13.7", "sandcastle": "^1.3.3", "sax": "^1.1.5", "scandirectory": "^2.5.0", "scmp": "^1.0.0", "semver": "^5.1.0", "send": "^0.13.1", "serve-favicon": "^2.3.0", "serve-index": "^1.7.3", "serve-static": "^1.10.2", "shortid": "^2.2.8", "should": "^11.1.0", "sigmund": "^1.0.1", "signal-exit": "^2.1.2", "skipper": "^0.5.9", "skipper-disk": "^0.5.4", "skipper-s3": "^0.5.6", "sntp": "^1.0.9", "socket.io": "^1.4.6", "socket.io-adapter": "^0.4.0", "socket.io-client": "^1.4.6", "socket.io-emitter": "^2.0.0", "socket.io-parser": "^2.2.6", "source-map": "^0.3.0", "spdx-correct": "^1.0.2", "spdx-exceptions": "^1.0.4", "spdx-expression-parse": "^1.0.2", "spdx-license-ids": "^1.2.1", "split": "^0.3.3", "sprintf-js": "^1.0.3", "squel": "^5.11.1", "sshpk": "^1.8.3", "stack-trace": "^0.0.9", "statuses": "^1.2.1", "stream-counter": "^0.2.0", "string-template": "^1.0.0", "string_decoder": "^0.10.31", "stringstream": "^0.0.5", "strip-ansi": "^0.1.1", "strip-bom": "^2.0.0", "strip-indent": "^1.0.1", "strip-json-comments": "^0.1.3", "strip-path": "^0.1.1", "supports-color": "^0.2.0", "switchback": "^1.1.3", "tape": "^0.2.2", "taskgroup": "^4.3.1", "through": "^2.3.8", "tiny-lr": "^0.0.4", "to-array": "^0.1.4", "tough-cookie": "^2.2.2", "trim-newlines": "^1.0.0", "tunnel-agent": "^0.4.3", "tweetnacl": "^0.13.3", "type-is": "^1.6.12", "typechecker": "^2.1.0", "typedarray": "^0.0.6", "uglify-js": "^2.6.2", "uglify-to-browserify": "^1.0.2", "uid-safe": "^1.1.0", "uid2": "^0.0.3", "ultron": "^1.0.2", "underscore": "^1.6.0", "underscore.string": "^2.2.1", "unpipe": "^1.0.0", "uri-path": "^0.0.2", "user-agent-parse": "^0.1.8", "utf8": "^2.1.0", "util-deprecate": "^1.0.2", "utile": "^0.2.1", "utils-merge": "^1.0.0", "validate-npm-package-license": "^3.0.1", "validator": "^5.2.0", "vary": "^1.1.0", "verror": "^1.3.6", "vhost": "^3.0.2", "walk": "^2.3.9", "watchr": "^2.4.13", "waterline": "^0.11.2", "waterline-criteria": "^1.0.0", "waterline-cursor": "^0.0.6", "waterline-errors": "^0.10.1", "waterline-schema": "^0.2.0", "watson-developer-cloud": "^2.37.0", "which": "^1.0.9", "window-size": "^0.1.0", "winston": "^2.3.0", "winston-papertrail": "^1.0.2", "wordwrap": "^0.0.3", "wrappy": "^1.0.1", "ws": "^1.0.1", "xml2js": "^0.4.15", "xmlbuilder": "^2.6.2", "xmlhttprequest-ssl": "^1.5.1", "xregexp": "^2.0.0", "xtend": "^4.0.1", "xxhash": "^0.2.4", "yallist": "^2.0.0", "yargs": "^3.10.0", "yeast": "^0.1.2", "yui-lint": "^0.2.0", "zlib-browserify": "^0.0.3" } ```
jdelman commented 6 years ago

It seems like we’re hitting this codepath: https://github.com/elastic/apm-agent-nodejs/blob/master/lib/instrumentation/transaction.js#L259

But it’s not clear why

watson commented 6 years ago

This is most likely because that one of your dependencies contains a so called "user-land callback queue" or calls out to custom C/C++ code, both of which can mess with our ability to keep track of which transaction is active at any given time.

If that's the case we can't trust any of the spans collected for the given transaction and so we drop them instead of showing potential wrong information.

Since you've provided your dependencies (thank you 😃), we might be able to reproduce and track down what's causing this. But because this can be very tricky for us to reproduce it might take time.

In the meantime, if you discover anything new that might help us in the investigation, please let us know.

watson commented 6 years ago

This is now fixed in master and will be included in the next release

watson commented 6 years ago

This have now been released in v1.7.0