[windows][ci][electron] Occasional electron-mocha test failure on the Windows CI

[kittaakos]

I have seen this couple of times before. Restarting the build with the same commit hash fixes the issue. Perhaps, this is a timing issue.

$ yarn rebuild:electron && run test "@theia/example-electron"
2004$ theia rebuild:electron
2005Processing node-pty
2006Processing vscode-nsfw
2007Processing find-git-repositories
2008Parallel lerna execution is disabled on Windows. Falling back to sequential execution with the '--concurrency==1' flag.
2009Running lerna as: C:\Program Files\nodejs\node.exe C:\projects\theia\dev-packages\ext-scripts\theia-run run test --scope @theia/example-electron --concurrency==1
2010lerna info version 2.11.0
2011lerna info scope @theia/example-electron
2012@theia/example-electron: $ electron-mocha --timeout 60000 --require ts-node/register "./test/**/*.espec.ts"
2013@theia/example-electron: 
2014@theia/example-electron:   basic-example-spec
2015@theia/example-electron:     01 #start example app
2016@theia/example-electron: Starting server worker...
2017@theia/example-electron:       √ should start the electron example app (842ms)
2018@theia/example-electron: Server worker has been started. [ID: 1 | PID: 3596]
2019@theia/example-electron:   1 passing (1s)
2020@theia/example-electron: C:\projects\theia\node_modules\electron-mocha\index.js:18
2021@theia/example-electron: const tmpdir = fs.mkdtempSync(join(app.getPath('temp'), 'electron-mocha-'))\n                                      ^
2022@theia/example-electron: TypeError: Cannot read property 'getPath' of undefined\n    at Object.<anonymous> (C:\projects\theia\node_modules\electron-mocha\index.js:18:39)\n    at Object.<anonymous> (C:\projects\theia\node_modules\electron-mocha\index.js:109:3)\n    at Module._compile (module.js:569:30)\n    at Object.Module._extensions..js (module.js:580:10)\n    at Module.load (module.js:503:32)\n    at tryModuleLoad (module.js:466:12)\n    at Function.Module._load (module.js:458:3)\n    at Function.Module.runMain (module.js:605:10)\n    at startup (bootstrap_node.js:167:16)\n    at bootstrap_node.js:589:3
2023@theia/example-electron: Server worker has been disconnected. [ID: 1 | PID: 3596]
2024@theia/example-electron: Server worker failed to start.
2025@theia/example-electron: Server worker has been stopped. [ID: 1 | PID: 3596]
2026@theia/example-electron: root INFO Theia app listening on http://localhost:1143.
2027@theia/example-electron: root INFO Started watching: c:\projects\theia\examples\electron\package.json
2028@theia/example-electron: info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
2029@theia/example-electron: error Command failed with exit code 1.
2030lerna ERR! execute callback with error
2031lerna ERR! Error: Command failed: yarn run test
2032lerna ERR! C:\projects\theia\node_modules\electron-mocha\index.js:18
2033lerna ERR! const tmpdir = fs.mkdtempSync(join(app.getPath('temp'), 'electron-mocha-'))
2034lerna ERR!                                       ^
2035lerna ERR! 
2036lerna ERR! TypeError: Cannot read property 'getPath' of undefined
2037lerna ERR!     at Object.<anonymous> (C:\projects\theia\node_modules\electron-mocha\index.js:18:39)
2038lerna ERR!     at Object.<anonymous> (C:\projects\theia\node_modules\electron-mocha\index.js:109:3)
2039lerna ERR!     at Module._compile (module.js:569:30)
2040lerna ERR!     at Object.Module._extensions..js (module.js:580:10)
2041lerna ERR!     at Module.load (module.js:503:32)
2042lerna ERR!     at tryModuleLoad (module.js:466:12)
2043lerna ERR!     at Function.Module._load (module.js:458:3)
2044lerna ERR!     at Function.Module.runMain (module.js:605:10)
2045lerna ERR!     at startup (bootstrap_node.js:167:16)
2046lerna ERR!     at bootstrap_node.js:589:3
2047lerna ERR! error Command failed with exit code 1.
2048lerna ERR! 
2049lerna ERR! $ electron-mocha --timeout 60000 --require ts-node/register "./test/**/*.espec.ts"
2050lerna ERR! 
2051lerna ERR! 
2052lerna ERR! 
2053lerna ERR!   basic-example-spec
2054lerna ERR!     01 #start example app
2055lerna ERR! Starting server worker...
2056lerna ERR!       √ should start the electron example app (842ms)
2057lerna ERR! Server worker has been started. [ID: 1 | PID: 3596]
2058lerna ERR! 
2059lerna ERR! 
2060lerna ERR!   1 passing (1s)
2061lerna ERR! 
2062lerna ERR! Server worker has been disconnected. [ID: 1 | PID: 3596]
2063lerna ERR! Server worker failed to start.
2064lerna ERR! Server worker has been stopped. [ID: 1 | PID: 3596]
2065lerna ERR! root INFO Theia app listening on http://localhost:1143.
2066lerna ERR! root INFO Started watching: c:\projects\theia\examples\electron\package.json
2067lerna ERR! info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.
2068lerna ERR! 
2069lerna ERR!     at Promise.all.then.arr (C:\projects\theia\node_modules\lerna\node_modules\execa\index.js:236:11)
2070lerna ERR!     at <anonymous>
2071{ Error: Command failed: yarn run test
2072C:\projects\theia\node_modules\electron-mocha\index.js:18
2073const tmpdir = fs.mkdtempSync(join(app.getPath('temp'), 'electron-mocha-'))
2074                                      ^
2075
2076TypeError: Cannot read property 'getPath' of undefined
2077    at Object.<anonymous> (C:\projects\theia\node_modules\electron-mocha\index.js:18:39)
2078    at Object.<anonymous> (C:\projects\theia\node_modules\electron-mocha\index.js:109:3)
2079    at Module._compile (module.js:569:30)
2080    at Object.Module._extensions..js (module.js:580:10)
2081    at Module.load (module.js:503:32)
2082    at tryModuleLoad (module.js:466:12)
2083    at Function.Module._load (module.js:458:3)
2084    at Function.Module.runMain (module.js:605:10)
2085    at startup (bootstrap_node.js:167:16)
2086    at bootstrap_node.js:589:3
2087error Command failed with exit code 1.
2088
2089$ electron-mocha --timeout 60000 --require ts-node/register "./test/**/*.espec.ts"
2090
2091
2092

[jonahgraham]

I see (what I assume is) the same problem simply running Theia on Windows:

PS D:\debug\git\theia\examples\browser> yarn run start
yarn run v1.9.4
$ theia start
Starting server worker...
Server worker has been started. [ID: 1 | PID: 25168]
Server worker failed to start.
Server worker is ready to accept messages. [ID: 1 | PID: 25168]
Server worker has been disconnected. [ID: 1 | PID: 25168]
root INFO [nsfw-watcher: 15952] Started watching: d:\debug\git\theia\examples\browser\package.json

It seems to happen randomly about 10-20% of the time.

The rest of the time everything starts fine:

PS D:\debug\git\theia\examples\browser> yarn run start
yarn run v1.9.4
$ theia start
Starting server worker...
Server worker has been started. [ID: 1 | PID: 26076]
Server worker is ready to accept messages. [ID: 1 | PID: 26076]
root INFO Theia app listening on http://localhost:3000.
Received message which is neither a response nor a notification message:
"3000"
root INFO [nsfw-watcher: 24992] Started watching: d:\debug\git\theia\examples\browser\package.json

On initial investigation, the cause of the error is obfuscated by a Promise.race in fork. Perhaps the first step is to log which one of the failure conditions actually caused the failed to start?

[jonahgraham]

BTW Issue #2710 seems related too, I haven't updated to the code containing the fix yet, but the startup time is very quick so I don't think I am seeing the timeout.

[paul-marechal]

Ok so I tried to give a look at this issue, and turns out that it has to do with the way the backend is started in the test using electron-mocha.

Because we use the cluster module and we are expecting to reparse the exact same file (that is master on the first parse) in order to run the workers, it tries to restart the test script using the same command that we used to run the file.

Issues:

1. The command we used is to run tests, not to run this particular file. So replaying the command will have unexpected effects.
2. File is a .ts file that is ran with ts-node, which is implicitly used with --require ts-node/register in the test command. So even if we try to re-parse the file, it has to be done with ts-node. I tried without success...

Now, why does everything fail with the following message?

2020@theia/example-electron: C:\projects\theia\node_modules\electron-mocha\index.js:18
2021@theia/example-electron: const tmpdir = fs.mkdtempSync(join(app.getPath('temp'), 'electron-mocha-'))
2022@theia/example-electron: TypeError: Cannot read property 'getPath' of undefined

It is because when the worker is started by re-running the test command, the chai import at the beginning is triggered. But because we aren't in the electron main-process anymore, doing require('electron') will not return the Electron API, it will instead return a path or something else. See jprichardson/electron-mocha#104 (comment).

You can note that the error comes from theia\node_modules\electron-mocha\index.js:18, because by re-running the tests, we aren't in Electron main-process, but electron-chai still assumes to be in an Electron environment.

---

Long story short, it is a pain. I will keep trying things and push it to a branch (cannot guaranty a PR...), but how about temporally removing this flaky test and make AppVeyor less likely to fail for no reason? @kittaakos

[paul-marechal]

The issue also happens on Ubuntu by the way, but for some reason it doesn't fail the tests on this platform.