Investigate flaky inspector/test-inspector #8669

mscdex · 2016-09-20T18:05:25Z

Version: master
Platform: Linux
Subsystem: inspector

https://ci.nodejs.org/job/node-test-commit-linux/5220/nodes=centos5-64/console

Output:

not ok 1174 inspector/test-inspector
# AssertionError: [object Object]
#     at Object.exports.fail (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-64/test/common.js:438:10)
#     at Timeout.setTimeout (/home/iojs/build/workspace/node-test-commit-linux/nodes/centos5-64/test/inspector/inspector-helper.js:200:16)
#     at tryOnTimeout (timers.js:232:11)
#     at Timer.listOnTimeout (timers.js:202:5)
# [err] Debugger listening on port 9229.
# [err] Warning: This is an experimental feature and could change at any time.
# [err] To start debugging, open the following URL in Chrome:
# [err]     chrome-devtools://devtools/remote/serve_file/@60cd6e859b9f557d2312f5bf532f6aec5f284980/inspector.html?experiments=true&v8only=true&ws=localhost:9229/node
# [err] 
# [test] Verifying debugger stops on start (--debug-brk option)
# [err] Debugger attached.
# [err] 
# [test] Setting a breakpoint and verifying it is hit
# [out] A message 5
# [out] 
# [test] Verify we can read current application state
  ---
  duration_ms: 15.691

The text was updated successfully, but these errors were encountered:

Trott · 2016-09-20T18:10:11Z

@eugeneo is actively investigating this issue.

eugeneo · 2016-09-20T18:16:33Z

I am currently looking into it. There's a chance that this is a genuine bug (looks like the server does not complete the shutdown once the frontend disconnects).

I have tried looping the test on Mac and Ubuntu64 instance but was not able to reproduce.

eugeneo · 2016-09-20T18:39:24Z

By expecting the code, I see one potential race condition (though I do not know how to trigger it) - this commit tries to avoid it: https://github.com/eugeneo/node/commit/2fc65bfdfd703010630879afcc4cc8b22bf28a39

Please try this on CI, if it works I will create a proper PR (will have to remove log statements, fix commit message, etc.)

mscdex · 2016-09-20T21:32:47Z

@eugeneo I just ran the branch that commit was on through the stress test job on centos5-64 and all but one of the runs still had the same output (one of them was missing the last line -- [test] Verify we can read current application state).

Stress test results are here (I stopped it once I saw it had failed 80 times).

eugeneo · 2016-09-20T21:49:33Z

@mscdex Interesting - this is a different failure from the one I've seen before (though it might have the same root cause). I've updated #8672 to output all messages sent/received - can you run it on a CI? Thanks!

mscdex · 2016-09-20T22:28:19Z

@eugeneo Ok, new stress test results containing new output: https://ci.nodejs.org/job/node-stress-single-test/928/nodes=centos5-64/console

Trott · 2016-09-20T22:42:56Z

not ok 1 inspector/test-inspector
# AssertionError: Messages without response:13, 14
#     at Object.exports.fail (/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/common.js:438:10)
#     at Timeout.setTimeout (/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/inspector/inspector-helper.js:202:16)
#     at tryOnTimeout (timers.js:232:11)
#     at Timer.listOnTimeout (timers.js:202:5)
# [err] Debugger listening on port 9229.
# [err] Warning: This is an experimental feature and could change at any time.
# [err] To start debugging, open the following URL in Chrome:
# [err]     chrome-devtools://devtools/remote/serve_file/@60cd6e859b9f557d2312f5bf532f6aec5f284980/inspector.html?experiments=true&v8only=true&ws=localhost:9229/node
# [err] 
# [test] Verifying debugger stops on start (--debug-brk option)
# [sent] {"method":"Runtime.enable","id":1}
# [sent] {"method":"Debugger.enable","id":2}
# [sent] {"method":"Debugger.setPauseOnExceptions","params":{"state":"none"},"id":3}
# [sent] {"method":"Debugger.setAsyncCallStackDepth","params":{"maxDepth":0},"id":4}
# [sent] {"method":"Profiler.enable","id":5}
# [sent] {"method":"Profiler.setSamplingInterval","params":{"interval":100},"id":6}
# [sent] {"method":"Debugger.setBlackboxPatterns","params":{"patterns":[]},"id":7}
# [sent] {"method":"Runtime.runIfWaitingForDebugger","id":8}
# [err] Debugger attached.
# [err] 
# [received] {"method":"Runtime.executionContextCreated","params":{"context":{"id":1,"origin":"","name":"NodeJS Main Context"}}}
# [received] {"id":1,"result":{}}
# [received] {"id":2,"result":{}}
# [received] {"id":3,"result":{}}
# [received] {"id":4,"result":{}}
# [received] {"id":5,"result":{}}
# [received] {"id":6,"result":{}}
# [received] {"id":7,"result":{}}
# [received] {"id":8,"result":{}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"39","url":"bootstrap_node.js","startLine":0,"startColumn":0,"endLine":499,"endColumn":0,"executionContextId":1,"hash":"EE6EC0B1583BCC2888D07608349DFF37ED676620","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"40","url":"events.js","startLine":0,"startColumn":0,"endLine":491,"endColumn":3,"executionContextId":1,"hash":"BC91FFB044951AD3E491B1A3ADE4BDF3405D5DD2","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"41","url":"util.js","startLine":0,"startColumn":0,"endLine":1054,"endColumn":3,"executionContextId":1,"hash":"8A305A7147E48DD328580C5697A1E618ACE923C0","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"42","url":"buffer.js","startLine":0,"startColumn":0,"endLine":1352,"endColumn":3,"executionContextId":1,"hash":"156B2C62C5AA3661C18A3107BA23BE96104455F4","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"43","url":"internal/util.js","startLine":0,"startColumn":0,"endLine":164,"endColumn":3,"executionContextId":1,"hash":"E0457ED0466647806EC88F129C0828D7E29C7526","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"44","url":"timers.js","startLine":0,"startColumn":0,"endLine":653,"endColumn":3,"executionContextId":1,"hash":"F8E324722698FFA45037E0130726CD087D6E0464","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"45","url":"internal/linkedlist.js","startLine":0,"startColumn":0,"endLine":72,"endColumn":3,"executionContextId":1,"hash":"3F59DE70E1048E34ED537E339E256D10A3FA0CE0","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"46","url":"assert.js","startLine":0,"startColumn":0,"endLine":372,"endColumn":3,"executionContextId":1,"hash":"CBAC7782F03628433FAF7EB49B2B45A4745166C3","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"47","url":"internal/process.js","startLine":0,"startColumn":0,"endLine":252,"endColumn":3,"executionContextId":1,"hash":"DDB54911DEFE90B7A7253AA1B0CA0C76A1984174","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"48","url":"internal/process/warning.js","startLine":0,"startColumn":0,"endLine":50,"endColumn":3,"executionContextId":1,"hash":"4B6375110733ADA2ECB6D77038CA865632CB5972","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"49","url":"internal/process/next_tick.js","startLine":0,"startColumn":0,"endLine":158,"endColumn":3,"executionContextId":1,"hash":"B8CBC4126F5C1951A454D4F64DC68E872ABA0E37","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"50","url":"internal/process/promises.js","startLine":0,"startColumn":0,"endLine":86,"endColumn":3,"executionContextId":1,"hash":"48F659A393B28602672AEF7670FA20420DF87A95","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"51","url":"internal/process/stdio.js","startLine":0,"startColumn":0,"endLine":176,"endColumn":3,"executionContextId":1,"hash":"0F168021325CD8E8198F71131D4D4B98CAEA8CB2","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"52","url":"path.js","startLine":0,"startColumn":0,"endLine":1596,"endColumn":3,"executionContextId":1,"hash":"B0A0AA50FA5927491BCB7A57BED9997552E972A1","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"53","url":"module.js","startLine":0,"startColumn":0,"endLine":658,"endColumn":3,"executionContextId":1,"hash":"36E04F60E0EE21540EF3FFE26B5DD27A2ECDFB63","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"54","url":"internal/module.js","startLine":0,"startColumn":0,"endLine":97,"endColumn":3,"executionContextId":1,"hash":"A799FB00D3EECEA0E36238210812CBD6D68533B6","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"55","url":"vm.js","startLine":0,"startColumn":0,"endLine":105,"endColumn":3,"executionContextId":1,"hash":"B4F6B9D140C54AC0002962F54D66A389D75DBAA0","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"56","url":"fs.js","startLine":0,"startColumn":0,"endLine":2159,"endColumn":3,"executionContextId":1,"hash":"4F2745D1BF65B907189DB0F263D95F169851E6E5","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"57","url":"stream.js","startLine":0,"startColumn":0,"endLine":108,"endColumn":3,"executionContextId":1,"hash":"4EA8A5B1EFFACB02F4F714F611015942BFA250B5","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"58","url":"_stream_readable.js","startLine":0,"startColumn":0,"endLine":977,"endColumn":3,"executionContextId":1,"hash":"FDC7CCE0038AE3D456948371BC723CD5347ABDF7","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"59","url":"internal/streams/BufferList.js","startLine":0,"startColumn":0,"endLine":73,"endColumn":3,"executionContextId":1,"hash":"A7683B52CD6F6299B8D6DF70EF9B54E9CAE2BC96","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"60","url":"_stream_writable.js","startLine":0,"startColumn":0,"endLine":531,"endColumn":3,"executionContextId":1,"hash":"07C00E722870B831A9E7B37412227B3A6AF6CF32","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"61","url":"_stream_duplex.js","startLine":0,"startColumn":0,"endLine":58,"endColumn":3,"executionContextId":1,"hash":"5E476583F40B11B912420FD1AC4295F8C71738F2","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"62","url":"_stream_transform.js","startLine":0,"startColumn":0,"endLine":196,"endColumn":3,"executionContextId":1,"hash":"1CBCD3D05370E66964CBA9739C6FCD299C238A80","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"63","url":"_stream_passthrough.js","startLine":0,"startColumn":0,"endLine":23,"endColumn":3,"executionContextId":1,"hash":"122E62B378B03CAABE23C6A421ED869B93DBE6E1","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"64","url":"internal/fs.js","startLine":0,"startColumn":0,"endLine":79,"endColumn":3,"executionContextId":1,"hash":"BF3179C147633676CADF8FE675A6D45B55E2A313","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"65","url":"/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/fixtures/loop.js","startLine":0,"startColumn":0,"endLine":11,"endColumn":3,"executionContextId":1,"hash":"FA06176330D419B8DE53894560B5511159281EA4","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.paused","params":{"callFrames":[{"callFrameId":"{\"ordinal\":0,\"injectedScriptId\":1}","functionName":"","functionLocation":{"scriptId":"65","lineNumber":0,"columnNumber":10},"location":{"scriptId":"65","lineNumber":0,"columnNumber":70},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":1}"},"startLocation":{"scriptId":"65","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"65","lineNumber":11,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":2}"}}],"this":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":3}"}},{"callFrameId":"{\"ordinal\":1,\"injectedScriptId\":1}","functionName":"Module._compile","functionLocation":{"scriptId":"53","lineNumber":499,"columnNumber":36},"location":{"scriptId":"53","lineNumber":559,"columnNumber":31},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":4}"},"name":"Module._compile","startLocation":{"scriptId":"53","lineNumber":499,"columnNumber":36},"endLocation":{"scriptId":"53","lineNumber":562,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":5}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":6}"}}],"this":{"type":"object","className":"Module","description":"Module","objectId":"{\"injectedScriptId\":1,\"id\":7}"}},{"callFrameId":"{\"ordinal\":2,\"injectedScriptId\":1}","functionName":"Module._extensions..js","functionLocation":{"scriptId":"53","lineNumber":566,"columnNumber":36},"location":{"scriptId":"53","lineNumber":568,"columnNumber":9},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":8}"},"name":"Module._extensions..js","startLocation":{"scriptId":"53","lineNumber":566,"columnNumber":36},"endLocation":{"scriptId":"53","lineNumber":569,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":9}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":10}"}}],"this":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":11}"}},{"callFrameId":"{\"ordinal\":3,\"injectedScriptId\":1}","functionName":"Module.load","functionLocation":{"scriptId":"53","lineNumber":467,"columnNumber":32},"location":{"scriptId":"53","lineNumber":476,"columnNumber":31},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":12}"},"name":"Module.load","startLocation":{"scriptId":"53","lineNumber":467,"columnNumber":32},"endLocation":{"scriptId":"53","lineNumber":478,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":13}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":14}"}}],"this":{"type":"object","className":"Module","description":"Module","objectId":"{\"injectedScriptId\":1,\"id\":15}"}},{"callFrameId":"{\"ordinal\":4,\"injectedScriptId\":1}","functionName":"tryModuleLoad","functionLocation":{"scriptId":"53","lineNumber":432,"columnNumber":22},"location":{"scriptId":"53","lineNumber":435,"columnNumber":11},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":16}"},"name":"tryModuleLoad","startLocation":{"scriptId":"53","lineNumber":432,"columnNumber":22},"endLocation":{"scriptId":"53","lineNumber":442,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":17}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":18}"}}],"this":{"type":"undefined"}},{"callFrameId":"{\"ordinal\":5,\"injectedScriptId\":1}","functionName":"Module._load","functionLocation":{"scriptId":"53","lineNumber":401,"columnNumber":23},"location":{"scriptId":"53","lineNumber":427,"columnNumber":2},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":19}"},"name":"Module._load","startLocation":{"scriptId":"53","lineNumber":401,"columnNumber":23},"endLocation":{"scriptId":"53","lineNumber":430,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":20}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":21}"}}],"this":{"type":"function","className":"Function","description":"function Module(id, parent) {\n  this.id = id;\n  this.exports = {};\n  this.parent = parent;\n  if (parent && parent.children) {\n    parent.children.push(this);\n  }\n\n  this.filename = null;\n  this.loaded = false;\n  this.children = [];\n}","objectId":"{\"injectedScriptId\":1,\"id\":22}"}},{"callFrameId":"{\"ordinal\":6,\"injectedScriptId\":1}","functionName":"Module.runMain","functionLocation":{"scriptId":"53","lineNumber":591,"columnNumber":25},"location":{"scriptId":"53","lineNumber":593,"columnNumber":9},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":23}"},"name":"Module.runMain","startLocation":{"scriptId":"53","lineNumber":591,"columnNumber":25},"endLocation":{"scriptId":"53","lineNumber":596,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":24}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":25}"}}],"this":{"type":"object","className":"Timeout","description":"Timeout","objectId":"{\"injectedScriptId\":1,\"id\":26}"}},{"callFrameId":"{\"ordinal\":7,\"injectedScriptId\":1}","functionName":"tryOnTimeout","functionLocation":{"scriptId":"44","lineNumber":227,"columnNumber":21},"location":{"scriptId":"44","lineNumber":231,"columnNumber":10},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":27}"},"name":"tryOnTimeout","startLocation":{"scriptId":"44","lineNumber":227,"columnNumber":21},"endLocation":{"scriptId":"44","lineNumber":245,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":28}"},"startLocation":{"scriptId":"44","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"44","lineNumber":653,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":29}"}}],"this":{"type":"undefined"}},{"callFrameId":"{\"ordinal\":8,\"injectedScriptId\":1}","functionName":"listOnTimeout","functionLocation":{"scriptId":"44","lineNumber":155,"columnNumber":22},"location":{"scriptId":"44","lineNumber":201,"columnNumber":4},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":30}"},"name":"listOnTimeout","startLocation":{"scriptId":"44","lineNumber":155,"columnNumber":22},"endLocation":{"scriptId":"44","lineNumber":222,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":31}"},"startLocation":{"scriptId":"44","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"44","lineNumber":653,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":32}"}}],"this":{"type":"object","className":"Timer","description":"Timer","objectId":"{\"injectedScriptId\":1,\"id\":33}"}}],"reason":"other","hitBreakpoints":[]}}
# [test] Setting a breakpoint and verifying it is hit
# [sent] {"method":"Debugger.setBreakpointByUrl","params":{"lineNumber":5,"url":"/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/fixtures/loop.js","columnNumber":0,"condition":""},"id":9}
# [sent] {"method":"Debugger.resume","id":10}
# [sent] {"method":"Debugger.getScriptSource","params":{"scriptId":"65"},"id":11}
# [received] {"id":9,"result":{"breakpointId":"/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/fixtures/loop.js:5:0","locations":[{"scriptId":"65","lineNumber":5,"columnNumber":4}]}}
# [received] {"id":10,"result":{}}
# [out] A message 5
# [out] 
# [received] {"id":11,"result":{"scriptSource":"(function (exports, require, module, __filename, __dirname) { var t = 1;\nvar k = 1;\nconsole.log('A message', 5);\nwhile (t > 0) {\n  if (t++ === 1000) {\n    t = 0;\n    console.log('Outputed message #' + k++);\n  }\n}\nprocess.exit(55);\n\n});"}}
# [received] {"method":"Debugger.resumed","params":{}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"68","url":"console.js","startLine":0,"startColumn":0,"endLine":102,"endColumn":3,"executionContextId":1,"hash":"BE35A29399416B56DF563D06725B82B7920B8564","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"69","url":"net.js","startLine":0,"startColumn":0,"endLine":1599,"endColumn":3,"executionContextId":1,"hash":"9C33E4B18F02E6D6E696D1E6B9C27C9C21808486","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Debugger.scriptParsed","params":{"scriptId":"70","url":"internal/net.js","startLine":0,"startColumn":0,"endLine":19,"endColumn":3,"executionContextId":1,"hash":"7C40D431006A622907A0F180581E9C5902F6E572","isLiveEdit":false,"sourceMapURL":"","hasSourceURL":false}}
# [received] {"method":"Runtime.consoleAPICalled","params":{"type":"log","args":[{"type":"string","value":"A message"},{"type":"number","value":5,"description":"5"}],"executionContextId":1,"timestamp":5228950040.192714,"stackTrace":{"callFrames":[{"functionName":"","scriptId":"65","url":"/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/fixtures/loop.js","lineNumber":2,"columnNumber":8},{"functionName":"Module._compile","scriptId":"53","url":"module.js","lineNumber":559,"columnNumber":31},{"functionName":"Module._extensions..js","scriptId":"53","url":"module.js","lineNumber":568,"columnNumber":9},{"functionName":"Module.load","scriptId":"53","url":"module.js","lineNumber":476,"columnNumber":31},{"functionName":"tryModuleLoad","scriptId":"53","url":"module.js","lineNumber":435,"columnNumber":11},{"functionName":"Module._load","scriptId":"53","url":"module.js","lineNumber":427,"columnNumber":2},{"functionName":"Module.runMain","scriptId":"53","url":"module.js","lineNumber":593,"columnNumber":9},{"functionName":"tryOnTimeout","scriptId":"44","url":"timers.js","lineNumber":231,"columnNumber":10},{"functionName":"listOnTimeout","scriptId":"44","url":"timers.js","lineNumber":201,"columnNumber":4}]}}}
# [received] {"method":"Debugger.paused","params":{"callFrames":[{"callFrameId":"{\"ordinal\":0,\"injectedScriptId\":1}","functionName":"","functionLocation":{"scriptId":"65","lineNumber":0,"columnNumber":10},"location":{"scriptId":"65","lineNumber":5,"columnNumber":4},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":34}"},"startLocation":{"scriptId":"65","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"65","lineNumber":11,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":35}"}}],"this":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":36}"}},{"callFrameId":"{\"ordinal\":1,\"injectedScriptId\":1}","functionName":"Module._compile","functionLocation":{"scriptId":"53","lineNumber":499,"columnNumber":36},"location":{"scriptId":"53","lineNumber":559,"columnNumber":31},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":37}"},"name":"Module._compile","startLocation":{"scriptId":"53","lineNumber":499,"columnNumber":36},"endLocation":{"scriptId":"53","lineNumber":562,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":38}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":39}"}}],"this":{"type":"object","className":"Module","description":"Module","objectId":"{\"injectedScriptId\":1,\"id\":40}"}},{"callFrameId":"{\"ordinal\":2,\"injectedScriptId\":1}","functionName":"Module._extensions..js","functionLocation":{"scriptId":"53","lineNumber":566,"columnNumber":36},"location":{"scriptId":"53","lineNumber":568,"columnNumber":9},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":41}"},"name":"Module._extensions..js","startLocation":{"scriptId":"53","lineNumber":566,"columnNumber":36},"endLocation":{"scriptId":"53","lineNumber":569,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":42}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":43}"}}],"this":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":44}"}},{"callFrameId":"{\"ordinal\":3,\"injectedScriptId\":1}","functionName":"Module.load","functionLocation":{"scriptId":"53","lineNumber":467,"columnNumber":32},"location":{"scriptId":"53","lineNumber":476,"columnNumber":31},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":45}"},"name":"Module.load","startLocation":{"scriptId":"53","lineNumber":467,"columnNumber":32},"endLocation":{"scriptId":"53","lineNumber":478,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":46}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":47}"}}],"this":{"type":"object","className":"Module","description":"Module","objectId":"{\"injectedScriptId\":1,\"id\":48}"}},{"callFrameId":"{\"ordinal\":4,\"injectedScriptId\":1}","functionName":"tryModuleLoad","functionLocation":{"scriptId":"53","lineNumber":432,"columnNumber":22},"location":{"scriptId":"53","lineNumber":435,"columnNumber":11},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":49}"},"name":"tryModuleLoad","startLocation":{"scriptId":"53","lineNumber":432,"columnNumber":22},"endLocation":{"scriptId":"53","lineNumber":442,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":50}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":51}"}}],"this":{"type":"undefined"}},{"callFrameId":"{\"ordinal\":5,\"injectedScriptId\":1}","functionName":"Module._load","functionLocation":{"scriptId":"53","lineNumber":401,"columnNumber":23},"location":{"scriptId":"53","lineNumber":427,"columnNumber":2},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":52}"},"name":"Module._load","startLocation":{"scriptId":"53","lineNumber":401,"columnNumber":23},"endLocation":{"scriptId":"53","lineNumber":430,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":53}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":54}"}}],"this":{"type":"function","className":"Function","description":"function Module(id, parent) {\n  this.id = id;\n  this.exports = {};\n  this.parent = parent;\n  if (parent && parent.children) {\n    parent.children.push(this);\n  }\n\n  this.filename = null;\n  this.loaded = false;\n  this.children = [];\n}","objectId":"{\"injectedScriptId\":1,\"id\":55}"}},{"callFrameId":"{\"ordinal\":6,\"injectedScriptId\":1}","functionName":"Module.runMain","functionLocation":{"scriptId":"53","lineNumber":591,"columnNumber":25},"location":{"scriptId":"53","lineNumber":593,"columnNumber":9},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":56}"},"name":"Module.runMain","startLocation":{"scriptId":"53","lineNumber":591,"columnNumber":25},"endLocation":{"scriptId":"53","lineNumber":596,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":57}"},"startLocation":{"scriptId":"53","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"53","lineNumber":658,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":58}"}}],"this":{"type":"object","className":"Timeout","description":"Timeout","objectId":"{\"injectedScriptId\":1,\"id\":59}"}},{"callFrameId":"{\"ordinal\":7,\"injectedScriptId\":1}","functionName":"tryOnTimeout","functionLocation":{"scriptId":"44","lineNumber":227,"columnNumber":21},"location":{"scriptId":"44","lineNumber":231,"columnNumber":10},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":60}"},"name":"tryOnTimeout","startLocation":{"scriptId":"44","lineNumber":227,"columnNumber":21},"endLocation":{"scriptId":"44","lineNumber":245,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":61}"},"startLocation":{"scriptId":"44","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"44","lineNumber":653,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":62}"}}],"this":{"type":"undefined"}},{"callFrameId":"{\"ordinal\":8,\"injectedScriptId\":1}","functionName":"listOnTimeout","functionLocation":{"scriptId":"44","lineNumber":155,"columnNumber":22},"location":{"scriptId":"44","lineNumber":201,"columnNumber":4},"scopeChain":[{"type":"local","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":63}"},"name":"listOnTimeout","startLocation":{"scriptId":"44","lineNumber":155,"columnNumber":22},"endLocation":{"scriptId":"44","lineNumber":222,"columnNumber":1}},{"type":"closure","object":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":64}"},"startLocation":{"scriptId":"44","lineNumber":0,"columnNumber":10},"endLocation":{"scriptId":"44","lineNumber":653,"columnNumber":1}},{"type":"global","object":{"type":"object","className":"global","description":"global","objectId":"{\"injectedScriptId\":1,\"id\":65}"}}],"this":{"type":"object","className":"Timer","description":"Timer","objectId":"{\"injectedScriptId\":1,\"id\":66}"}}],"reason":"other","hitBreakpoints":["/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/fixtures/loop.js:5:0"]}}
# [test] Verify we can read current application state
# [sent] {"method":"Runtime.getProperties","params":{"objectId":"{\"injectedScriptId\":1,\"id\":34}","ownProperties":false,"accessorPropertiesOnly":false,"generatePreview":true},"id":12}
# [sent] {"method":"Debugger.evaluateOnCallFrame","params":{"callFrameId":"{\"ordinal\":0,\"injectedScriptId\":1}","expression":"k + t","objectGroup":"console","includeCommandLineAPI":true,"silent":false,"returnByValue":false,"generatePreview":true},"id":13}
# [sent] {"method":"Runtime.evaluate","params":{"expression":"5 * 5"},"id":14}
# [received] {"id":12,"result":{"result":[{"name":"exports","value":{"type":"object","className":"Object","description":"Object","objectId":"{\"injectedScriptId\":1,\"id\":67}","preview":{"type":"object","description":"Object","overflow":false,"properties":[]}},"writable":true,"configurable":true,"enumerable":true,"isOwn":true},{"name":"require","value":{"type":"function","className":"Function","description":"function require(path) {\n    try {\n      exports.requireDepth += 1;\n      return self.require(path);\n    } finally {\n      exports.requireDepth -= 1;\n    }\n  }","objectId":"{\"injectedScriptId\":1,\"id\":68}"},"writable":true,"configurable":true,"enumerable":true,"isOwn":true},{"name":"module","value":{"type":"object","className":"Module","description":"Module","objectId":"{\"injectedScriptId\":1,\"id\":69}","preview":{"type":"object","description":"Module","overflow":true,"properties":[{"name":"id","type":"string","value":"."},{"name":"exports","type":"object","value":"Object"},{"name":"parent","type":"object","value":"null","subtype":"null"},{"name":"filename","type":"string","value":"/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/fixtures/loop.js"},{"name":"loaded","type":"boolean","value":"false"}]}},"writable":true,"configurable":true,"enumerable":true,"isOwn":true},{"name":"__filename","value":{"type":"string","value":"/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/fixtures/loop.js"},"writable":true,"configurable":true,"enumerable":true,"isOwn":true},{"name":"__dirname","value":{"type":"string","value":"/home/iojs/build/workspace/node-stress-single-test/nodes/centos5-64/test/fixtures"},"writable":true,"configurable":true,"enumerable":true,"isOwn":true},{"name":"t","value":{"type":"number","value":1001,"description":"1001"},"writable":true,"configurable":true,"enumerable":true,"isOwn":true},{"name":"k","value":{"type":"number","value":1,"description":"1"},"writable":true,"configurable":true,"enumerable":true,"isOwn":true}]}}

eugeneo · 2016-09-20T23:19:57Z

Thank you for your help.

CentOS5 32-bit failure seems to be gone now (there was a race condition in disconnect during Node shutdown, hopefully that was cause).

CentOS5 64 failure - I do not understand it yet, looks like child process stops responding for some reason (or the test fails to interpret the output). I have updated #8672 with different tracing (on the child process side this time) and would like to ask you do another CI run. It still runs on Ubuntu 64 without any problems...

Trott · 2016-09-20T23:41:46Z

CentOS5 64 test run: https://ci.nodejs.org/job/node-stress-single-test/929/nodes=centos5-64/console

eugeneo · 2016-09-21T18:18:59Z

Thanks. Test indicates that child process is not "seeing" some messages sent by a test process. I am looking into it, will update the PR once I have a fix ready.

Trott · 2016-09-21T18:45:44Z

FWIW, this test is also failing in CI on Raspberry Pi 1 devices:

not ok 164 inspector/test-inspector
# AssertionError: Have not terminated
#     at Object.exports.fail (/home/iojs/build/workspace/node-test-binary-arm/test/common.js:442:10)
#     at Timeout.setTimeout (/home/iojs/build/workspace/node-test-binary-arm/test/inspector/inspector-helper.js:102:34)
#     at tryOnTimeout (timers.js:232:11)
#     at Timer.listOnTimeout (timers.js:202:5)
# [err] Debugger listening on port 9229.
# [err] Warning: This is an experimental feature and could change at any time.
# [err] To start debugging, open the following URL in Chrome:
# [err]     chrome-devtools://devtools/remote/serve_file/@60cd6e859b9f557d2312f5bf532f6aec5f284980/inspector.html?experiments=true&v8only=true&ws=localhost:9229/node
# [err] 
# [test] Verifying debugger stops on start (--debug-brk option)
# [err] Debugger attached.
# [err] 
# [test] Setting a breakpoint and verifying it is hit
# [out] A message 5
# [out] 
# [test] Verify we can read current application state
# [test] Verify node waits for the frontend to disconnect
# [out] Outputed message #1
# [out] 
# [err] Waiting for the debugger to disconnect...
# [err] 
  ---

It's entirely possible that whatever fixes it for CentOS5 might fix it for Raspberry Pi 1 too.

If the issue is memory or CPU constraints, we may want to skip the test on Raspberry Pi 1.

Stress tests uncovered 2 race conditions, when IO events happened during V8 entering event loop on pause or during Node.js shutdown. Fixes: nodejs#8669 PR-URL: nodejs#8672 Reviewed-By: Ben Noordhuis <[email protected]> Reviewed-By: Aleksey Kozyatinskiy <[email protected]>

Stress tests uncovered 2 race conditions, when IO events happened during V8 entering event loop on pause or during Node.js shutdown. Fixes: #8669 PR-URL: #8672 Reviewed-By: Ben Noordhuis <[email protected]> Reviewed-By: Aleksey Kozyatinskiy <[email protected]>

mscdex added test Issues and PRs related to the tests. inspector Issues and PRs related to the V8 inspector protocol labels Sep 20, 2016

This was referenced Sep 20, 2016

inspector: introduce a smoke test for inspector #8429

Closed

inspector: address race conditions #8672

Closed

eugeneo closed this as completed in 5acbeb0 Sep 23, 2016

snyk-bot mentioned this issue Jul 17, 2020

[Snyk] Security upgrade eslint from 3.19.0 to 4.0.0 adamlaska/node#38

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Investigate flaky inspector/test-inspector #8669

Investigate flaky inspector/test-inspector #8669

mscdex commented Sep 20, 2016

Trott commented Sep 20, 2016

eugeneo commented Sep 20, 2016

eugeneo commented Sep 20, 2016

mscdex commented Sep 20, 2016

eugeneo commented Sep 20, 2016

mscdex commented Sep 20, 2016

Trott commented Sep 20, 2016

eugeneo commented Sep 20, 2016

Trott commented Sep 20, 2016

eugeneo commented Sep 21, 2016

Trott commented Sep 21, 2016

Investigate flaky inspector/test-inspector #8669

Investigate flaky inspector/test-inspector #8669

Comments

mscdex commented Sep 20, 2016

Trott commented Sep 20, 2016

eugeneo commented Sep 20, 2016

eugeneo commented Sep 20, 2016

mscdex commented Sep 20, 2016

eugeneo commented Sep 20, 2016

mscdex commented Sep 20, 2016

Trott commented Sep 20, 2016

eugeneo commented Sep 20, 2016

Trott commented Sep 20, 2016

eugeneo commented Sep 21, 2016

Trott commented Sep 21, 2016