Fix race condition when killing Chrome on Windows when disconnecting #703

mrcrane · 2018-07-17T18:49:56Z

No description provided.

digeff · 2018-07-17T20:03:37Z

src/chromeDebugAdapter.ts

+        for (let i = 0 ; i < 10; i++) {
+            // Check to see if the process is still running
+            let tasklistOutput = execSync(`tasklist /FI "PID eq ${chromePID}"`).toString();
+            if (!tasklistOutput.includes(chromePID.toString())) {


Is it possible that the chromePID is a substring of another process PID? Is it possible that the output of the command is not in the format that we expect?

When tasklist finds the process it will return output that looks like
Image Name PID Session Name Session# Mem Usage
========== === ============ ======== =========
chrome.exe 16116 Console 1 273,300 K

When tasklist doesn't find the process it outputs
INFO: No tasks are running which match the specified criteria.

In both cases the exit code is 0

Because the tasklist is run with a PID filter it will only return one or zero processes. Any process that with a PID that is a superstring will be filtered out.

I implemented with a search of PID in the output because it seemed like the most robust way to differentiate between success and failure outputs. Searching for the presence of the PID is independent of the format.

Let me know if you have any better suggestions. I can add comments as documentation for what is going on.

I changed this to use csv output which is slightly better, but still not perfect.

digeff · 2018-07-17T20:05:43Z

src/chromeDebugAdapter.ts

+
+        for (let i = 0 ; i < 10; i++) {
+            // Check to see if the process is still running
+            let tasklistOutput = execSync(`tasklist /FI "PID eq ${chromePID}"`).toString();


Can we log this execution too?

digeff · 2018-07-17T20:06:52Z

src/chromeDebugAdapter.ts

@@ -347,6 +332,37 @@ export class ChromeDebugAdapter extends CoreDebugAdapter {
        this._chromeProc = null;
    }

+    private async killChromeOnWindows(chromePID: number): Promise<void> {


Do we have enough telemetry to figure out if this method/logic is working as expected?

rakatyal · 2018-07-17T20:33:57Z

Why do we have an updated package-lock.json for this change?

rakatyal · 2018-07-17T20:36:57Z

src/chromeDebugAdapter.ts

+            // The command will fail if process was not found. This can be safely ignored.
+        }
+
+        for (let i = 0 ; i < 10; i++) {


What's the use for this for loop? How is this better than using a timeout?

This follows the pattern in findNewlyLaunchedChromeProcess() at the bottom of the file. It will try up to 10 times and wait 200ms between tries. Total time will be 2000ms in addition to command execution time. It does use a timeout to wait.

I think it's readable but I am open to changing it.

This is fine but you could also use the retryAsync helper in core's utils.ts if you want.

rakatyal · 2018-07-17T20:38:47Z

Should we store some time performance telemetry for the disconnect request? PZ gives us 5 seconds to respond to a command and we should make sure we are not near that number after this change.

mrcrane · 2018-07-17T21:52:38Z

The package-lock.json changes happen when I run npm install. I assume that is because of a previous check-in. I can leave it out but it keeps coming back so I decided to add it to the PR.

mrcrane · 2018-07-18T00:35:06Z

I addressed the logging concerns.

I still need to add telemetry, but I think it would be best to tie into the existing ClientRequest telemetry. In this case: "ClientTelemetry/disconnect". This would already cover measuring the disconnect end-to-end times, and we could see if suddenly every disconnect time started spiking.

Some issues I'm having with that:

I actually can't find any "ClientRequest/disconnect" telemetry in Kusto even though I see all the other requests. Maybe something is preventing that from being reported?
I'd like to use the TelemetryPropertyCollector to augment the telemetry, but it's not passed through properly to the disconnect handler. This would require changes in -core to fix.

Thoughts? @roblourens

digeff

Please create a user story to finish adding telemetry to killChromeOnWindows

roblourens · 2018-07-18T17:51:28Z

src/chromeDebugAdapter.ts

+            // If the process is found, tasklist will output CSV with one of the values being the PID. Exit code will be 0.
+            // If the process is not found, tasklist will give a generic "not found" message instead. Exit code will also be 0.
+            // If we see an entry in the CSV for the PID, then we can assume the process was found.
+            if (!tasklistOutput.includes(`"${chromePID}"`)) {


Redundant template string :)

Actually, it's looking for the quotes around the PID as well as the PID itself...

Oops too early for code review

roblourens · 2018-07-18T17:52:56Z

Was the bug here that Chrome takes a bit of time to shutdown, so we are force-killing it unnecessarily?

roblourens · 2018-07-18T17:53:29Z

I actually can't find any "ClientRequest/disconnect" telemetry in Kusto even though I see all the other requests

Maybe we lose telemetry from right before the process shuts down, let me check that out...

roblourens · 2018-07-18T17:57:10Z

Actually, I think that telemetry after disconnect will not be sent (looking at vscode's code at least). The event is sent to the client which then passes it on to the telemetry service, but I think the client will stop handling this telemetry after disconnect. Does VS do the same?

mrcrane · 2018-07-18T18:01:00Z

Correct, taskkill sends the request for Chrome to shut down but then in some cases the subsequent taskkill /F would happen before Chrome could shutdown gracefully.

roblourens · 2018-07-18T18:19:01Z

@rakatyal and @digeff if you sign off I'll merge this

digeff · 2018-07-18T18:36:00Z

Ship it!

rakatyal · 2018-07-18T18:37:09Z

Looks good!

roblourens · 2018-07-18T18:38:19Z

Thanks, next time you could leave an "approved" review just because I'll wait if I think you guys are still looking at it. I think anybody can create reviews on a PR.

Fix race condition when killing Chrome on Windows when disconnecting

f081f7e

vscodebot bot assigned roblourens Jul 17, 2018

digeff reviewed Jul 17, 2018

View reviewed changes

rakatyal reviewed Jul 17, 2018

View reviewed changes

PR feedback

e85978f

digeff approved these changes Jul 18, 2018

View reviewed changes

roblourens reviewed Jul 18, 2018

View reviewed changes

roblourens approved these changes Jul 18, 2018

View reviewed changes

roblourens merged commit 83decfc into microsoft:master Jul 18, 2018

roblourens added this to the July 2018 milestone Aug 3, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix race condition when killing Chrome on Windows when disconnecting #703

Fix race condition when killing Chrome on Windows when disconnecting #703

mrcrane commented Jul 17, 2018

digeff Jul 17, 2018 •

edited

Loading

mrcrane Jul 17, 2018 •

edited

Loading

mrcrane Jul 18, 2018

digeff Jul 17, 2018

digeff Jul 17, 2018 •

edited

Loading

rakatyal commented Jul 17, 2018

rakatyal Jul 17, 2018

mrcrane Jul 17, 2018

roblourens Jul 18, 2018

rakatyal commented Jul 17, 2018

mrcrane commented Jul 17, 2018

mrcrane commented Jul 18, 2018

digeff left a comment

roblourens Jul 18, 2018

mrcrane Jul 18, 2018

roblourens Jul 18, 2018

roblourens commented Jul 18, 2018

roblourens commented Jul 18, 2018

roblourens commented Jul 18, 2018 •

edited

Loading

mrcrane commented Jul 18, 2018 •

edited

Loading

roblourens commented Jul 18, 2018

digeff commented Jul 18, 2018

rakatyal commented Jul 18, 2018

roblourens commented Jul 18, 2018

Fix race condition when killing Chrome on Windows when disconnecting #703

Fix race condition when killing Chrome on Windows when disconnecting #703

Conversation

mrcrane commented Jul 17, 2018

digeff Jul 17, 2018 • edited Loading

Choose a reason for hiding this comment

mrcrane Jul 17, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

digeff Jul 17, 2018 • edited Loading

Choose a reason for hiding this comment

rakatyal commented Jul 17, 2018

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

rakatyal commented Jul 17, 2018

mrcrane commented Jul 17, 2018

mrcrane commented Jul 18, 2018

digeff left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

roblourens commented Jul 18, 2018

roblourens commented Jul 18, 2018

roblourens commented Jul 18, 2018 • edited Loading

mrcrane commented Jul 18, 2018 • edited Loading

roblourens commented Jul 18, 2018

digeff commented Jul 18, 2018

rakatyal commented Jul 18, 2018

roblourens commented Jul 18, 2018

digeff Jul 17, 2018 •

edited

Loading

mrcrane Jul 17, 2018 •

edited

Loading

digeff Jul 17, 2018 •

edited

Loading

roblourens commented Jul 18, 2018 •

edited

Loading

mrcrane commented Jul 18, 2018 •

edited

Loading