"Process timed out" after two minutes

[mdonoughe]

I have an intermittent problem with Keybase updating itself to the same version that is already installed. In the logs, I see a pattern like this

2023/10/31 20:51:28 DEBG Checking for update (ticker)
2023/10/31 20:51:28 DEBG Set last update time
2023/10/31 20:51:28 DEBG Execute: C:\Users\user\AppData\Local\Keybase\keybase.exe [version -S]
2023/10/31 20:53:28 WARN Process timed out
2023/10/31 20:53:28 WARN Command timed out, terminating (will wait 1s before killing)
2023/10/31 20:53:28 WARN Error sending terminate: invalid argument
2023/10/31 20:53:28 WARN Terminated
2023/10/31 20:53:28 WARN Couldn't get keybase version: Timed out ([stdout]: 6.2.3-20230928105938+eba57c1814
)
2023/10/31 20:53:28 DEBG Execute: cmd [/c ver]
2023/10/31 20:55:28 WARN Process timed out
2023/10/31 20:55:28 WARN Command timed out, terminating (will wait 1s before killing)
2023/10/31 20:55:28 WARN Error sending terminate: invalid argument
2023/10/31 20:55:28 WARN Terminated
2023/10/31 20:55:28 WARN Error trying to determine OS version: Timed out ([stdout]: 
Microsoft Windows [Version 10.0.22621.2283]
)
2023/10/31 20:55:28 INFO Checking for update, current version is 
2023/10/31 20:55:28 INFO Using updater source: Keybase.io
2023/10/31 20:55:28 DEBG Using options: updater.UpdateOptions{Version:"", Platform:"windows", DestinationPath:"C:\\Users\\user\\AppData\\Local\\Keybase\\", URL:"", Channel:"", Env:"prod", Arch:"AMD64", Force:false, OSVersion:"", UpdaterVersion:"0.3.7", IgnoreSnooze:false}
2023/10/31 20:55:28 INFO Request "https://api-0.core.keybaseapi.com/_/api/1.0/pkg/update.json?arch=AMD64&auto_update=1&ignore_snooze=0&install_id=122c92806863806a45e5e8f58a28057d78ee660c5be7ca1d&os_version=&platform=windows&run_mode=prod&upd_version=0.3.7&version="
2023/10/31 20:55:28 DEBG Received update response: updater.Update{Version:"6.2.3-20230928105938+eba57c1814", Name:"v6.2.3-20230928105938+eba57c1814", Description:"• Various bug fixes and performance enhancements\n• Mark threads as unread\n", InstallID:"122c92806863806a45e5e8f58a28057d78ee660c5be7ca1d", RequestID:"96c97689b53f74c8341d881f", Type:0, PublishedAt:1695898778000, Props:[]updater.Property(nil), Asset:(*updater.Asset)(0xc0003883c0), NeedUpdate:true}
2023/10/31 20:55:28 INFO Got update with version: 6.2.3-20230928105938+eba57c1814

A few interesting things:

• It seems to happen more often when the computer has recently resumed from sleep, but no update check was in progress when the computer entered sleep.
• The log indicates two minutes and zero seconds elapse before the timeout, but the code says the timeout should be much less than that, at least when getting the Windows version.
• "Error sending terminate: invalid argument" sounds a lot like the process has already exited.
• Even though it prints "Error sending terminate", waiting on doneCh the second time immediately completes without actually doing anything to terminate the process before the second wait.
• The expected output is contained in the error message.
• After failing to determine the current version, the updater incorrectly continues as if it has successfully determined the version to be "".

It seems like there's some sort of race condition in execWithFunction but it's not apparent to me. Maybe it'd be better to replace it with new exec.CommandContext from Go 1.7 in 2016 and let exec take care of the timeout. The exec code has handling for the case where it tries to kill the process but the process finishes successfully before it is killed.