Hang in TypingsInstaller

[mjbvz]

TypeScript Version: 2.2.2

Bug
While working in the VSCode code base, I saw this sequence of errors:

[Trace - 7:14:40 PM] Sending request: quickinfo (3058). Response expected: yes. Current queue length: 0
Arguments: {
    "file": "/Users/matb/projects/vscode/extensions/typescript/src/features/bufferSyncSupport.ts",
    "line": 350,
    "offset": 39
}
[Trace - 7:14:41 PM] TypeScript Service: trying to cancel ongoing request with sequence number 3058
[Trace - 7:14:42 PM] TypeScript Service: canceled request with sequence number 3059
[Trace - 7:14:42 PM] TypeScript Service: canceled request with sequence number 3060
[Trace - 7:14:44 PM] TypeScript Service: canceled request with sequence number 3067
[Trace - 7:15:31 PM] TypeScript Service: canceled request with sequence number 3068
[Trace - 7:15:32 PM] TypeScript Service: canceled request with sequence number 3069
[Trace - 7:15:33 PM] TypeScript Service: canceled request with sequence number 3063
[Trace - 7:15:33 PM] TypeScript Service: canceled request with sequence number 3064
[Trace - 7:15:35 PM] TypeScript Service: canceled request with sequence number 3075
[Trace - 7:15:36 PM] TypeScript Service: canceled request with sequence number 3076
[Trace - 7:15:37 PM] TypeScript Service: canceled request with sequence number 3077
[Trace - 7:15:41 PM] TypeScript Service: canceled request with sequence number 3078
[Error - 7:15:44 PM] TSServer exited with code: unknown
[Info  - 7:15:44 PM] Using tsserver from location: /Users/matb/projects/vscode/node_modules/typescript/lib/tsserver.js
[Trace - 7:15:52 PM] TypeScript Service: canceled request with sequence number 3087
[Trace - 7:15:53 PM] TypeScript Service: canceled request with sequence number 3088
[Trace - 7:16:56 PM] TypeScript Service: canceled request with sequence number 3072
[Trace - 7:16:56 PM] TypeScript Service: canceled request with sequence number 3073
[Trace - 7:17:32 PM] TypeScript Service: canceled request with sequence number 3091
[Trace - 7:17:34 PM] TypeScript Service: canceled request with sequence number 3092
[Trace - 7:17:35 PM] TypeScript Service: canceled request with sequence number 3093
[Trace - 7:18:41 PM] TypeScript Service: canceled request with sequence number 3089
[Trace - 7:18:41 PM] TypeScript Service: canceled request with sequence number 3090
[Trace - 7:19:15 PM] TypeScript Service: canceled request with sequence number 3096
[Trace - 7:19:16 PM] TypeScript Service: canceled request with sequence number 3097

Looking that the current ts processes, I don't see anything overly suspicious:

matb             41431   0.1  2.9  3751672 487264 s000  S+    5:10PM   0:14.03 /Users/matb/projects/vscode/.build/electron/Code - OSS.app/Contents/Frameworks/Code - OSS Helper.app/Contents/MacOS/Code - OSS Helper /Users/matb/projects/vscode/extensions/typescript/out/utils/electronForkStart /Users/matb/projects/vscode/extensions/node_modules/typescript/lib/tsserver.js --useSingleInferredProject --enableTelemetry --cancellationPipeName /var/folders/_0/611900jn0yb43f1rc47_2wmh0000gp/T/vscode-tscancellation-5c409339406287390651.sock* --logVerbosity verbose --logFile /var/folders/_0/611900jn0yb43f1rc47_2wmh0000gp/T/vscode-tsserver-log-QyWuNz/tsserver.log
matb             41450   0.0  0.3  3189772  45280 s000  S+    5:10PM   0:00.30 /Users/matb/projects/vscode/.build/electron/Code - OSS.app/Contents/Frameworks/Code - OSS Helper.app/Contents/MacOS/Code - OSS Helper /Users/matb/projects/vscode/extensions/node_modules/typescript/lib/typingsInstaller.js --globalTypingsCacheLocation /Users/matb/Library/Caches/typescript --enableTelemetry --logFile /var/folders/_0/611900jn0yb43f1rc47_2wmh0000gp/T/vscode-tsserver-log-QyWuNz/ti-41431.log
matb             43187   0.0  0.0  2434840    796 s004  S+    7:19PM   0:00.00 grep --color=auto -i 41431

Neither the CPU usage or the memory is out of control. It is odd to me though that the typings installer is hanging around so long. In the Typings installer log, I see this message at the end:

Adding entry into typings cache: 'xmldom' => '/Users/matb/Library/Caches/typescript/node_modules/@types/xmldom/index.d.ts'
Adding entry into typings cache: 'xtend' => '/Users/matb/Library/Caches/typescript/node_modules/@types/xtend/index.d.ts'
Adding entry into typings cache: 'xterm' => '/Users/matb/Library/Caches/typescript/node_modules/@types/xterm/index.d.ts'
Adding entry into typings cache: 'yargs' => '/Users/matb/Library/Caches/typescript/node_modules/@types/yargs/index.d.ts'
Finished processing cache location '/Users/matb/Library/Caches/typescript'
Process id: 41450
Npm config file: /Users/matb/Library/Caches/typescript/package.json
Updating types-registry npm package...

[mhegazy]

@andy-ms can you take a look.

[mjbvz]

The Updating types-registry npm package... bit at the end seems to be a common theme but I'm not sure if this is expected or not. Here's another example:

...
Adding entry into typings cache: 'yargs' => '/Users/matb/Library/Caches/typescript/node_modules/@types/yargs/index.d.ts'
Finished processing cache location '/Users/matb/Library/Caches/typescript'
Process id: 9137
Npm config file: /Users/matb/Library/Caches/typescript/package.json
Updating types-registry npm package...
Parent process has exited, shutting down...

This is logged right before npm install types-registery is invoked. Is it possible that npm is hanging here, possible due to resource contention with another process. Perhaps we could add the output from npm to the log? Or perhaps nothing is supposed to be logged after Updating types-registry npm package... in normal cases?

[mjbvz]

Never mind, I believe Updating types-registry npm package... is expected to be the last item logged if no typings installs are ever requested

[mhegazy]

Looks like we have no intimidate action on this issue. @mjbvz's change should tell us in the future if there is a problem or it was just the log that made it look like one.

Closing for now, please reopen if we have new data.