search

googleapis / cloud-trace-nodejs

Node.js agent for Cloud Trace: automatically gather latency data about your application
https://cloud.google.com/trace/
Apache License 2.0
278 stars 98 forks source link

WARN: Attempted to create child span without root. Anyone have any ideas? #502

Closed oshalygin closed 7 years ago

oshalygin commented 7 years ago

I'm seeing this in the logs recently, anyone have any idea what I may be missing??

WARN:@google-cloud/trace-agent: redis: Attempted to create child span without root

oshalygin commented 7 years ago

Looking at the source, looks like the rootSpan is null(or falsy)

https://github.com/GoogleCloudPlatform/cloud-trace-nodejs/blob/42de95aaa2f12f44b8956e9a16ebd5089cb69871/src/trace-api.js#L177


TraceApiImplementation.prototype.createChildSpan = function(options) {
  var rootSpan = cls.getRootContext();
  if (!rootSpan) {
    // Lost context
    this.logger_.warn(this.pluginName_ + ': Attempted to create child span ' +
      'without root');
    return null;
  } else if (rootSpan === nullSpan) {
    // Chose not to sample
    return null;
  } else {
    options = options || {};
    var childContext = this.agent_.startSpan(options.name, {},
      options.skipFrames ? options.skipFrames + 2 : 2);
    return new ChildSpan(this.agent_, childContext);
  }
};
matthewloring commented 7 years ago

@oshalygin Unfortunately, there are a few Javascript patterns which can interfere with our ability to correctly associated child spans with the correct root span. This is likely being caused by interference from another one of your dependencies. Would you be able to post a list of your dependencies (or email the list if you prefer)?

oshalygin commented 7 years ago

Don't judge :D, some of the devDependencies should be dependencies and vice versa. We are going through a bit of a refactor :)

"dependencies": {
    "@google-cloud/logging-winston": "^0.4.1",
    "@google-cloud/trace-agent": "2.0.0",
    "axios": "0.16.2",
    "babel-plugin-react-css-modules": "2.7.1",
    "babel-polyfill": "6.23.0",
    "babel-runtime": "6.23.0",
    "body-parser": "1.17.2",
    "cookie-parser": "1.4.3",
    "date-fns": "1.28.5",
    "express": "4.15.3",
    "express-stormpath": "stormpath/express-stormpath#mt-social",
    "express-winston": "2.4.0",
    "hsts": "2.0.0",
    "js-yaml": "3.8.4",
    "material-ui": "0.18.1",
    "object-assign": "4.1.1",
    "prop-types": "15.5.10",
    "react": "15.5.4",
    "react-dom": "15.5.4",
    "react-ga": "2.2.0",
    "react-google-maps": "6.3.0",
    "react-redux": "5.0.5",
    "react-redux-form": "1.12.0",
    "react-router": "3.0.5",
    "react-router-redux": "4.0.8",
    "react-stormpath": "1.3.5",
    "react-tap-event-plugin": "2.0.1",
    "redux": "3.6.0",
    "redux-thunk": "2.2.0",
    "winston": "2.3.1"
  },
  "devDependencies": {
    "babel-cli": "6.24.1",
    "babel-core": "6.24.1",
    "babel-eslint": "7.2.3",
    "babel-loader": "7.0.0",
    "babel-plugin-react-display-name": "2.0.0",
    "babel-plugin-transform-decorators-legacy": "1.3.4",
    "babel-plugin-transform-object-rest-spread": "6.23.0",
    "babel-plugin-transform-react-constant-elements": "6.23.0",
    "babel-plugin-transform-react-remove-prop-types": "0.4.5",
    "babel-plugin-transform-runtime": "6.23.0",
    "babel-preset-latest": "6.24.1",
    "babel-preset-react": "6.24.1",
    "babel-preset-react-hmre": "1.1.1",
    "babel-preset-stage-1": "6.24.1",
    "babel-regenerator-runtime": "6.5.0",
    "babel-register": "6.24.1",
    "babel-template": "6.24.1",
    "babel-types": "6.24.1",
    "babel-watch": "2.0.6",
    "chai": "4.0.2",
    "chalk": "1.1.3",
    "codacy-coverage": "2.0.2",
    "connect-history-api-fallback": "1.3.0",
    "cross-env": "5.0.0",
    "css-loader": "0.28.4",
    "css-modules-require-hook": "4.0.6",
    "enzyme": "2.8.2",
    "eslint": "3.19.0",
    "eslint-plugin-import": "2.3.0",
    "eslint-plugin-jest": "20.0.3",
    "eslint-plugin-jsx-a11y": "5.0.3",
    "eslint-plugin-react": "7.0.1",
    "extract-text-webpack-plugin": "2.1.0",
    "file-loader": "0.11.2",
    "html-webpack-plugin": "2.28.0",
    "identity-obj-proxy": "3.0.0",
    "jest": "20.0.4",
    "jsdom": "11.0.0",
    "jsdom-global": "3.0.2",
    "json-loader": "0.5.4",
    "moxios": "0.4.0",
    "npm-run-all": "4.0.2",
    "open": "0.0.5",
    "postcss": "6.0.1",
    "postcss-cssnext": "2.11.0",
    "postcss-import": "10.0.0",
    "postcss-loader": "2.0.5",
    "postcss-reporter": "3.0.0",
    "postcss-url": "7.0.0",
    "prompt": "1.0.0",
    "raw-loader": "0.5.1",
    "react-test-renderer": "15.5.4",
    "redux-immutable-state-invariant": "2.0.0",
    "redux-logger": "3.0.6",
    "redux-mock-store": "1.2.3",
    "replace": "0.3.0",
    "rimraf": "2.6.1",
    "sinon": "2.3.2",
    "style-loader": "0.18.2",
    "url-loader": "0.5.8",
    "uuid": "3.0.1",
    "wallaby-webpack": "0.0.38",
    "webpack": "2.6.1",
    "webpack-dev-middleware": "1.10.2",
    "webpack-hot-middleware": "2.18.0",
    "webpack-md5-hash": "0.0.5"
  },
oshalygin commented 7 years ago

After doing a bit of testing, the problem comes down to the fact that I'm running the application as such: "open:dist": "NODE_ENV=production babel-node server/application.production.js",

At the very start of application.production.js, I have a call to a trace.js file which contains the initialization configuration of the trace agent, namely: 


require('@google-cloud/trace-agent').start({

  // Log levels: 0-disabled,1-error,2-warn,3-info,4-debug
  // Default: 1
  logLevel: 2,

//.. More config

Updating the above such that trace.js runs sequentially BEFORE the above npm script and the warning goes away. I think its just best to initialize prior to running any other application code and exclude any transformations/etc.

matthewloring commented 7 years ago

Having modules loaded before the trace agent can also prevent it from tracing correctly. If the change you mentioned fixed the warnings you were seeing I'm going to close this for now. Feel free to reopen if you run into any additional problems.

gauravkul commented 7 years ago

I am having the same issue. trace agent is the first module getting loaded (otherwise it clearly complains that other modules were loaded before it). Still getting the following warning logs :

redis: Attempted to create child span without root

http: Attempted to create child span without root

grpc: Attempted to create child span without root

Please advice how to debug. I am writing all the application in typescript. Could that me be causing the issue ?

oshalygin commented 7 years ago

@gauravkul yeah Typescript is likely the problem because it transpiles to whatever target you point to(usually people configure it to poop out to es5), when that happens, the trace agent may not be the first import.

An alternative as been suggested in the past is to have an entryfile, index.js which is the root of your application and all it has is


//index.js
var agent = require('@google-cloud/trace-agent').start();
require('./application.js'); // <--your current entrypoint which can have transpiled code
matthewloring commented 7 years ago

If @oshalygin's suggestion doesn't work for you, it could also be a problem caused by one of your dependencies (https://github.com/GoogleCloudPlatform/cloud-trace-nodejs#how-does-automatic-tracing-work). If you're comfortable sharing your project dependencies, we'd be happy to take a look and see if anything stands out.

gauravkul commented 7 years ago

Thanks @matthewloring @oshalygin for your helpful answers. Sorry I was away on weekend and replying so late. I tried what @oshalygin suggested but no help .

My project dependencies are 

"devDependencies": {
    "@types/cheerio": "^0.22.1",      
    "@types/images": "^2.2.0",      
    "@types/jasmine": "^2.5.53",      
    "@types/jimp": "^0.2.1",      
    "@types/jquery": "^2.0.43",      
    "@types/lodash": "^4.14.61",    
    "@types/lorem-ipsum": "^1.0.2",    
    "@types/mime-types": "^2.1.0",    
    "@types/mkdirp": "^0.3.29",    
    "@types/node": "^7.0.12",    
    "@types/phantom": "^3.2.1",    
    "@types/redis": "^0.12.36",    
    "@types/reflect-metadata": "^0.0.5",    
    "@types/request": "^2.0.0",    
    "@types/semver": "^5.3.31",    
    "@types/uuid": "^3.0.0",    
    "@types/ws": "0.0.40",    
    "@types/xml2js": "0.0.33",    
    "jasmine": "^2.6.0",    
    "jasmine-core": "^2.6.4",    
    "jasmine-reporters": "^2.2.1",    
    "lorem-ipsum": "^1.0.4",    
    "nodemon": "^1.11.0",    
    "prompt": "^1.0.0",    
    "repl.history": "^0.1.4",    
    "ts-node": "^3.0.2",    
    "typescript": "^2.2.2"
  },    
  "dependencies": {
    "@google-cloud/bigquery": "^0.9.5",    
    "@google-cloud/datastore": "^1.0.2",    
    "@google-cloud/monitoring": "^0.2.3",    
    "@google-cloud/pubsub": "^0.13.0",    
    "@google-cloud/storage": "^1.1.1",    
    "@google-cloud/trace-agent": "^2.1.3",    
    "@google-cloud/vision": "^0.11.2",    
    "aylien_textapi": "^0.6.0",    
    "cheerio": "^0.22.0",    
    "colors": "^1.1.2",    
    "fcm-node": "^1.2.0",    
    "google-auth-library": "^0.10.0",    
    "googleapis": "^20.1.0",    
    "jimp": "^0.2.28",    
    "lodash": "^4.17.4",    
    "mime-types": "^2.1.15",    
    "phantom": "^4.0.3",    
    "posix": "^4.1.1",    
    "prompt": "^1.0.0",    
    "rdflib": "^0.15.0",    
    "redis": "^2.7.1",    
    "reflect-metadata": "^0.1.10",    
    "semver": "^5.3.0",    
    "twitter-node-client": "0.0.6",    
    "uuid": "^3.1.0",    
    "ws": "^2.3.1",    
    "xml2js": "^0.4.17",    
    "images": "^3.0.0"
  }

node --version v7.10.0 We are using clustering . Can that be main culprit ? Thanks for help.

matthewloring commented 7 years ago

I took a quick look at your dependencies and it looks like phantom encourages using async/await with its interface. Unfortunately, our module is currently broken by async/await (https://github.com/GoogleCloudPlatform/cloud-trace-nodejs#prerequisites). Are you using async functions anywhere in your code? Also, do you see any http, redis, or grpc spans showing up in the cloud console or are they all missing?