Time-out on HTTP request causes server to exit

[puremourning]

Hi there,

According to the documentation, the timeout parameter should return an error when it is hit:

This document should be an object, with three optional fields, query, files, and timeout.

...

When the timeout field is set, it should contain a number, which is interpreted as the maximum amount of milliseconds to work (CPU work, ignoring I/O) on this request before returning with a timeout error.

I was expecting this would mean sending a 500 error response, or some such, which is nice and easy to handle in my REST client.

However, the behaviour I am seeing (when editing Tern's own bin/tern in this test case) is that the server exits with the following exception trace in its stderr log file:

/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:902
        throw new exports.TimedOut();
        ^
Error
    at Error.exports.TimedOut (/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:871:19)
    at withWorklist (/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:902:15)
    at Object.extend.addType (/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:84:20)
    at maybeAddPhantomObj (/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:1268:46)
    at /Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:1496:9
    at /Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:1355:15
    at infer (/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:1611:22)
    at Object.exports.inferWrapper.walk.make.Expression (/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/lib/infer.js:1620:7)
    at c (/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/node_modules/acorn/dist/walk.js:68:35)
    at Object.base.ExpressionStatement.base.ParenthesizedExpression (/Users/ben/.vim/bundle/YouCompleteMe/third_party/ycmd/third_party/tern/node_modules/acorn/dist/walk.js:186:10)

I'm using a fairly conservative 500ms time-out.

Is this the expected behaviour? If so, it's a little unfortunate, as I probably don't want to make it any more conservative, and handling the server going up and down all the while will lead to a bad user experience.
What do you think? I can look at a PR to catch the exception(s?) if you think this is something that would be accepted.

Many thanks,
Ben

PS Full log of request leading to above exception http://pastebin.com/vZ0FqP1K (the source is the current HEAD of tern on github).

[puremourning]

Spent some time looking at it. I think the issue occurs because exceptions raised by server.analyzeAll are not caught, particularly when they are raised asynchronously, such as by waitOnFetch's done function.

Rough sequence:

• request comes in and gets through to analyzeAll. this needs to fetch, so goes async and returns
• waitOnFetch re-calls analyzeAll which eventually times out and infer raises TimedOut

This causes the app to exit with the error attached to the original report.

I was able to fix this by simply wrapping the entirety of analyzeAll in a try/catch (e) { c(e.message); }.

This returns a 400 response with the text "Timed out" as the message, which is great.

HTH. Happy to send a PR for this fix.

[puremourning]

@marijnh Thanks for this patch. However, I've just tried this out and i'm still getting the same error, with a slightly different call stack.

Happens both with 0.17.0 and master. Can this be re-opened, or would you like me to raise a new issue?

stderr:

/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/lib/infer.js:907
        throw new exports.TimedOut();
        ^
Error
    at Error.exports.TimedOut (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/lib/infer.js:876:19)
    at withWorklist (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/lib/infer.js:907:15)
    at Object.extend.addType (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/lib/infer.js:84:20)
    at Object.exports.inferWrapper.walk.make.FunctionDeclaration (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/lib/infer.js:1633:35)
    at c (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/node_modules/acorn/dist/walk.js:68:35)
    at Object.exports.inferWrapper.walk.make.Statement (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/lib/infer.js:1637:7)
    at c (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/node_modules/acorn/dist/walk.js:68:35)
    at Object.base.Program.base.BlockStatement (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/node_modules/acorn/dist/walk.js:180:5)
    at c (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/node_modules/acorn/dist/walk.js:68:35)
    at Object.exports.inferWrapper.walk.make.Statement (/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/lib/infer.js:1637:7)

stdout:

Listening on port 60970
Request: {
  "files": [
    {
      "text": "#!/usr/bin/env node\n\n// HTTP server for desktop editors\n\n// Reads .tern-project files, wraps a Tern server in an HTTP wrapper\n// so that editor plug-ins can talk to it.\n\nvar tern = require(\"../lib/tern\");\nvar fs = require(\"fs\"), path = require(\"path\"), url = require(\"url\");\nvar glob = require(\"glob\"), minimatch = require(\"minimatch\");\n\nvar projectFileName = \".tern-project\", portFileName = \".tern-port\";\nvar maxIdleTime = 6e4 * 5; // Shut down after five minutes of inactivity\n\nvar persistent = process.argv.indexOf(\"--persistent\") > -1;\nvar stripCRs = process.argv.indexOf(\"--strip-crs\") > -1;\nvar disableLoadingLocal = process.argv.indexOf(\"--disable-loading-local\") > -1;\nvar verbose = process.argv.indexOf(\"--verbose\") > -1;\nvar debug = verbose || process.argv.indexOf(\"--debug\") > -1;\nvar noPortFile = process.argv.indexOf(\"--no-port-file\") > -1;\nvar host = \"127.0.0.1\";\nvar hostArg = process.argv.indexOf(\"--host\");\nif (hostArg > -1) {\n  host = process.argv[hostArg + 1];\n  if (host == \"null\" || host == \"any\") host = null;\n}\nvar port = 0;\nvar portArg = process.argv.indexOf(\"--port\");\nif (portArg > -1) {\n   port = Number(process.argv[portArg + 1]);\n   if (isNaN(port)) port = 0;\n}\n\nfunction findProjectDir() {\n  var dir = process.cwd();\n  for (;;) {\n    try {\n      if (fs.statSync(path.resolve(dir, projectFileName)).isFile()) return dir;\n    } catch(e) {}\n    console.\n    var shorter = path.dirname(dir);\n    if (shorter == dir) return null;\n    dir = shorter;\n  }\n}\n\nvar defaultConfig = {\n  libs: [],\n  loadEagerly: false,\n  plugins: {},\n  ecmaScript: true,\n  ecmaVersion: 6,\n  dependencyBudget: tern.defaultOptions.dependencyBudget\n};\nvar homeDir = process.env.HOME || process.env.USERPROFILE;\nif (homeDir && fs.existsSync(path.resolve(homeDir, \".tern-config\")))\n  defaultConfig = readProjectFile(path.resolve(homeDir, \".tern-config\"));\n\nfunction readJSON(fileName) {\n  var file = fs.readFileSync(fileName, \"utf8\");\n  try {\n    return JSON.parse(file);\n  } catch (e) {\n    console.error(\"Bad JSON in \" + fileName + \": \" + e.message);\n    process.exit(1);\n  }\n}\n\nfunction readProjectFile(fileName) {\n  var data = readJSON(fileName);\n  for (var option in defaultConfig) if (!data.hasOwnProperty(option))\n    data[option] = defaultConfig[option];\n  return data;\n}\n\nfunction findFile(file, projectDir, fallbackDir) {\n  var local = path.resolve(projectDir, file);\n  if (!disableLoadingLocal && fs.existsSync(local)) return local;\n  var shared = path.resolve(fallbackDir, file);\n  if (fs.existsSync(shared)) return shared;\n}\n\nvar distDir = path.resolve(__dirname, \"..\");\n\nfunction findDefs(projectDir, config) {\n  var defs = [], src = config.libs.slice();\n  if (config.ecmaScript) {\n    if (src.indexOf(\"ecma6\") == -1 && config.ecmaVersion >= 6) src.unshift(\"ecma6\")\n    if (src.indexOf(\"ecma5\") == -1) src.unshift(\"ecma5\")\n  }   \n  for (var i = 0; i < src.length; ++i) {\n    var file = src[i];\n    if (!/\\.json$/.test(file)) file = file + \".json\";\n    var found = findFile(file, projectDir, path.resolve(distDir, \"defs\"));\n    if (!found) {\n      try {\n        found = require.resolve(\"tern-\" + src[i]);\n      } catch (e) {\n        process.stderr.write(\"Failed to find library \" + src[i] + \".\\n\");\n        continue;\n      }\n    }\n    if (found) defs.push(readJSON(found));\n  }\n  return defs;\n}\n\nfunction defaultPlugins(config) {\n  var result = [\"doc_comment\"]\n  return result\n}\n\nfunction loadPlugins(projectDir, config) {\n  var plugins = config.plugins, options = {};\n  for (var plugin in plugins) {\n    var val = plugins[plugin];\n    if (!val) continue;\n    var found = findFile(plugin + \".js\", projectDir, path.resolve(distDir, \"plugin\"));\n    if (!found) {\n      try {\n        found = require.resolve(\"tern-\" + plugin);\n      } catch (e) {\n        process.stderr.write(\"Failed to find plugin \" + plugin + \".\\n\");\n        continue;\n      }\n    }\n    var mod = require(found);\n    if (mod.hasOwnProperty(\"initialize\")) mod.initialize(distDir);\n    options[path.basename(plugin)] = val;\n  }\n\n  defaultPlugins(config).forEach(function(name) {\n    if (!plugins.hasOwnProperty(name)) {\n      options[name] = true;\n      require(\"../plugin/\" + name);\n    }\n  });\n  return options;\n}\n\nvar projectDir = findProjectDir();\nif (projectDir) {\n  var config = readProjectFile(path.resolve(projectDir, projectFileName));\n} else {\n  projectDir = process.cwd();\n  var config = defaultConfig;\n}\n\nvar httpServer = require(\"http\").createServer(function(req, resp) {\n  clearTimeout(shutdown);\n  shutdown = setTimeout(doShutdown, maxIdleTime);\n\n  var target = url.parse(req.url, true);\n  if (target.pathname == \"/ping\") return respondSimple(resp, 200, \"pong\");\n  if (target.pathname != \"/\") return respondSimple(resp, 404, \"No service at \" + target.pathname);\n\n  if (req.method == \"POST\") {\n    var body = \"\";\n    req.on(\"data\", function (data) { body += data; });\n    req.on(\"end\", function() { respond(resp, body); });\n  } else if (req.method == \"GET\") {\n    if (target.query.doc) respond(resp, target.query.doc);\n    else respondSimple(resp, 400, \"Missing query document\");\n  }\n});\n\nvar server = startServer(projectDir, config, httpServer);\n\nfunction startServer(dir, config, httpServer) {\n  var defs = findDefs(dir, config);\n  var plugins = loadPlugins(dir, config);\n  var server = new tern.Server({\n    getFile: function(name, c) {\n      if (config.dontLoad && config.dontLoad.some(function(pat) {return minimatch(name, pat)}))\n        c(null, \"\");\n      else\n        fs.readFile(path.resolve(dir, name), \"utf8\", c);\n    },\n    normalizeFilename: function(name) {\n      var pt = path.resolve(dir, name)\n      try { pt = fs.realPathSync(path.resolve(dir, name), true) }\n      catch(e) {}\n      return path.relative(dir, pt)\n    },\n    async: true,\n    defs: defs,\n    plugins: plugins,\n    debug: debug,\n    projectDir: dir,\n    ecmaVersion: config.ecmaVersion,\n    dependencyBudget: config.dependencyBudget,\n    stripCRs: stripCRs,\n    parent: {httpServer: httpServer}\n  });\n\n  if (config.loadEagerly) config.loadEagerly.forEach(function(pat) {\n    glob.sync(pat, { cwd: dir }).forEach(function(file) {\n      server.addFile(file);\n    });\n  });\n  return server;\n}\n\nfunction doShutdown() {\n  if (persistent) return;\n  console.log(\"Was idle for \" + Math.floor(maxIdleTime / 6e4) + \" minutes. Shutting down.\");\n  process.exit();\n}\n\nvar shutdown = setTimeout(doShutdown, maxIdleTime);\n\nprocess.stdin.on(\"end\", function() { process.exit(); });\nprocess.stdin.resume();\n\nhttpServer.listen(port, host, function() {\n  var port = httpServer.address().port;\n  if (!noPortFile) {\n    var portFile = path.resolve(projectDir, portFileName);\n    fs.writeFileSync(portFile, String(port), \"utf8\");\n    process.on(\"exit\", function() {\n      try {\n        var cur = Number(fs.readFileSync(portFile, \"utf8\"));\n        if (cur == port) fs.unlinkSync(portFile);\n      } catch(e) {}\n    });\n  }\n  process.on(\"SIGINT\", function() { process.exit(); });\n  process.on(\"SIGTERM\", function() { process.exit(); });\n  console.log(\"Listening on port \" + port);\n});\n\nfunction respondSimple(resp, status, text) {\n  resp.writeHead(status, {\"content-type\": \"text/plain; charset=utf-8\"});\n  resp.end(text);\n  if (verbose) console.log(\"Response: \" + status + \" \" + text);\n}\n\nfunction respond(resp, doc) {\n  try { var doc = JSON.parse(doc); }\n  catch(e) { return respondSimple(resp, 400, \"JSON parse error: \" + e.message); }\n  if (verbose) console.log(\"Request: \" + JSON.stringify(doc, null, 2));\n\n  server.request(doc, function(err, data) {\n    if (err) return respondSimple(resp, 400, String(err));\n    resp.writeHead(200, {\"content-type\": \"application/json; charset=utf-8\"});\n    if (verbose) console.log(\"Response: \" + JSON.stringify(data, null, 2) + \"\\n\");\n    resp.end(JSON.stringify(data));\n  });\n}\n",
      "type": "full",
      "name": "/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/bin/tern"
    }
  ],
  "query": {
    "sort": false,
    "guess": false,
    "includeKeywords": false,
    "end": {
      "line": 39,
      "ch": 12
    },
    "file": "/Users/ben/.vim/bundle/YouCompleteMe-Clean/third_party/ycmd/third_party/tern/bin/tern",
    "docs": true,
    "lineCharPositions": true,
    "filter": false,
    "omitObjectPrototype": false,
    "expandWordForward": false,
    "caseInsensitive": true,
    "type": "completions",
    "types": true
  },
  "timeout": 500
}

Current commit:

(tests)Bens-MBP:tern ben$ git status
HEAD detached at origin/master
nothing to commit, working directory clean
(tests)Bens-MBP:tern ben$ git show HEAD
commit ddb2438867524e422a0baa807cb89cd7403b5622

[marijnh]

My bad. I handled only one source of timeout exceptions, but there's another. I think patch a6fe812 improves the situation.

[puremourning]

Thanks! I will check it out this evening.