1457868 - halt unproductive windows instances where explorer is in a crash loop

Status: RESOLVED FIXED

(Infrastructure & Operations :: RelOps: General, task)

Description

[Rob Thijssen [:grenade (EET/UTC+0300)]]

jonasfj pointed out a windows 10 instance today which had been in stuck a crashed state.

the papertrail logs show 3 days of the error below repeated every second or so:

Apr 27 14:57:03 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com Application_Error: Faulting application name: explorer.exe, version: 10.0.15063.0, time stamp: 0xa25b6083  Faulting module name: twinui.dll, version: 10.0.15063.0, time stamp: 0xd3bee097  Exception code: 0xc0000409  Fault offset: 0x0000000000170abc  Faulting process id: 0x1fa0  Faulting application start time: 0x01d3de1edaefc3a0  Faulting application path: C:\Windows\explorer.exe  Faulting module path: C:\Windows\system32\twinui.dll  Report Id: 0e1abc0f-df56-4d5c-a04e-77de83fb8a68  Faulting package full name:   Faulting package-relative application ID:  

the messages immediately preceeeding the first explorer crash message were:

Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: 2018/04/27 11:57:01   Result: 1 0 The operation completed successfully. 
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Z:\task_1524830212>echo Wait for registry setting to exist before changing it...  
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Wait for registry setting to exist before changing it... 
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Z:\task_1524830212>reg query HKCU\Software\Microsoft\Windows\CurrentVersion\Explorer\StuckRects3 /ve  
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: HKEY_CURRENT_USER\Software\Microsoft\Windows\CurrentVersion\Explorer\StuckRects3 
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker:     (Default)    REG_SZ    (value not set) 
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Z:\task_1524830212>if 0 EQU 0 goto HideTaskBar  
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Z:\task_1524830212>echo Hiding taskbar...  
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Hiding taskbar... 
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Z:\task_1524830212>powershell -command "&{$p='HKCU:SOFTWARE\Microsoft\Windows\CurrentVersion\Explorer\StuckRects3';$v=(Get-ItemProperty -Path $p).Settings;$v[8]=3;&Set-ItemProperty -Path $p -Name Settings -Value $v;&Stop-Process -ProcessName explorer}"  
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com HaltOnIdle: Is-ConditionTrue :: generic-worker is running. 
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com HaltOnIdle: instance appears to be productive. 
Apr 27 14:57:02 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com HaltOnIdle: process priority for generic worker altered from Normal to AboveNormal. 
Apr 27 14:57:03 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Z:\task_1524830212>echo Setting visual effects  
Apr 27 14:57:03 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Setting visual effects 
Apr 27 14:57:03 i-01c09dbd16ceb19cb.gecko-t-win10-64.use1.mozilla.com generic-worker: Z:\task_1524830212>REG ADD "HKCU\SOFTWARE\Microsoft\Windows\CurrentVersion\Explorer\VisualEffects" /v "VisualFXSetting" /t REG_DWORD /d 1  

logs above were taken from:
https://papertrailapp.com/systems/1816519341/events?focus=926492398777982992&selected=926492398777982992

Comment 1

[Rob Thijssen [:grenade (EET/UTC+0300)]]

patched HaltOnIdle to halt instances where there have been 30 (or more) explorer crash event logs.
https://github.com/mozilla-releng/OpenCloudConfig/commit/cf97e51a5851ec32dc9801d4ea75c07ba1c7e581

Comment 2

[Pete Moore [:pmoore][:pete]]

This is causing some fallout in bug 1444168.

If there are explorer crashes, we should find the root cause, rather than terminate workers mid-task.

When workers are terminated, running tasks will get bad exit codes, and resolve as task failures, which won't get retried. This makes it difficult to diagnose what the problem was, and leaves a trail of broken tasks, and can cause tree closures too.

Let's review this particular explorer crashing issue, and see if we can find the root cause, rather than just terminating machines that we believe exhibit the issue. Terminating workers should really be a last resort, due to the trails of broken tasks they leave behind.

Comment 3

[Intermittent Failures Robot]

54 failures in 110 pushes (0.491 failures/push) were associated with this bug yesterday.    

Repository breakdown:
* mozilla-inbound: 20
* autoland: 12
* try: 11
* mozilla-central: 11

Platform breakdown:
* windows10-64: 49
* windows10-64-devedition: 3
* windows10-64-nightly: 1
* windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457868&startday=2018-05-02&endday=2018-05-02&tree=trunk

Comment 4

[Rob Thijssen [:grenade (EET/UTC+0300)]]

The instances being terminated by haltonidle are not productive. They do nothing other than send explorer crash messages indefinitely. When enough instances get into this state, the trees close because there are no productive workers. Just useless workers which burn resources and prevent other jobs from running. From an infra perspective, I'd rather not burn the whole farm just to make it easier to debug a problem.

Comment 5

[Kendall Libby [:fubar] (he/him)]

So, what's the solution to debugging explorer.exe crashes that is not 1) nuking every instance which causes jobs to not be retried, and 2) letting instances loop and do nothing until we run out of capacity? You seem to have each end of the spectrum, what's the middle ground?

Comment 6

[Pete Moore [:pmoore][:pete]]

I'm fine with terminating instances that are wasting resources, but we should do it in a way that doesn't leave tasks as failed.

The key points for me are:

1) Let's try to avoid solving problems by killing workers. This can be a stop-gap, but not a long term solution.
2) Let's try to check health of workers before it starts claiming tasks, not while tasks are running, where possible. Most tasks have a maximum run time of an hour, and will be aborted in a controlled manner if they do not complete within this time.
3) If we are sure that workers are in a bad state, and need to check this while tasks are running, let's agree an interface such that tasks can be resolved as exception/internal-error rather than failed/failed since:
 a) failed tasks don't get retried
 b) no information is currently provided in task logs for user to see that the worker was forcefully terminated, and why - the user just thinks their process crashed for no good reason
Instead with an agreed interface (which we can discuss and review together) the reason for the termination could be logged in the task log so the user that submitted the task has better context on the reason for the failure, rather than the worker just being shut down mid-task.
4) Let's try to avoid landing patches in production that haven't undergone any review, especially those that kill workers. Killing workers should be a last resort, and the conditions under which workers get terminated should be closely monitored and reviewed.

In the case of https://bugzilla.mozilla.org/show_bug.cgi?id=1444168#c39 we should review logs to be sure that explorer really was crashing and the worker really was in a bad state. From a cursory look at the logs, this didn't appear to be the case, but a deeper investigation is warranted.

Comment 7

[Rob Thijssen [:grenade (EET/UTC+0300)]]

(In reply to Pete Moore [:pmoore][:pete] from comment #6)
> I'm fine with terminating instances that are wasting resources, but we
> should do it in a way that doesn't leave tasks as failed.

when haltonidle is terminating an instance that is in an unresponsive state, how would you suggest that it "doesn't leave tasks as failed"?

> The key points for me are:
> 
> 1) Let's try to avoid solving problems by killing workers. This can be a
> stop-gap, but not a long term solution.

what should we do with an unresponsive worker if not kill it?

> 2) Let's try to check health of workers before it starts claiming tasks, not
> while tasks are running, where possible. Most tasks have a maximum run time
> of an hour, and will be aborted in a controlled manner if they do not
> complete within this time.

the condition addressed by this bug is one where the only communication from the instance for more than 24 hours was a once per second message to say that explorer had crashed and once every two minutes a notification from haltonidle that the generic worker process was running. clearly generic worker was not in a state that allowed it to gracefully fail tasks.

> 3) If we are sure that workers are in a bad state, and need to check this
> while tasks are running, let's agree an interface such that tasks can be
> resolved as exception/internal-error rather than failed/failed since:
>  a) failed tasks don't get retried
>  b) no information is currently provided in task logs for user to see that
> the worker was forcefully terminated, and why - the user just thinks their
> process crashed for no good reason
> Instead with an agreed interface (which we can discuss and review together)
> the reason for the termination could be logged in the task log so the user
> that submitted the task has better context on the reason for the failure,
> rather than the worker just being shut down mid-task.

if we assume that generic worker was not in a responsive state since the gw process was running for more than 24 hours but it was not outputting log messages, i don't really see how an interface into gw would have helped on this occasion. gw was not capable of logging. never mind responding on a status interface.

> 4) Let's try to avoid landing patches in production that haven't undergone
> any review, especially those that kill workers. Killing workers should be a
> last resort, and the conditions under which workers get terminated should be
> closely monitored and reviewed.

agreed. although i maintain that killing an unresponsive worker is an appropriate course of action. we would otherwise spend money on keeping unresponsive workers online for no good reason.
 
> In the case of https://bugzilla.mozilla.org/show_bug.cgi?id=1444168#c39 we
> should review logs to be sure that explorer really was crashing and the
> worker really was in a bad state. From a cursory look at the logs, this
> didn't appear to be the case, but a deeper investigation is warranted.

i reviewed the logs. furthermore the patch that was landed to close this bug was specifically to check the event log for log messages that contain: "Faulting application name: explorer.exe" which is part of the text from the full failure logs which read:

"Application_Error: Faulting application name: explorer.exe, version: 10.0.15063.0, time stamp: 0xa25b6083  Faulting module name: twinui.dll, version: 10.0.15063.0, time stamp: 0xd3bee097  Exception code: 0xc0000409  Fault offset: 0x0000000000170abc  Faulting process id: 0x1fa0  Faulting application start time: 0x01d3de1edaefc3a0  Faulting application path: C:\Windows\explorer.exe  Faulting module path: C:\Windows\system32\twinui.dll  Report Id: 0e1abc0f-df56-4d5c-a04e-77de83fb8a68  Faulting package full name:   Faulting package-relative application ID:"

the patch checks for 30 recurrences of this exception before terminating the worker. from my more than cursory look at the logs, i would say that it would indeed be the case that explorer had crashed.

i agree that it would be nice for generic worker or the build process to put some nicer messages into the build log when tasks are failing but i would suggest creating a new bug for that. this bug is specifically about removing unresponsive instances from the resource pool in order to keep capacity available for responsive instances. i'm confused as to why this bug was reopened at all and i have no idea how to close it now that the goal posts seem to be moving to encompass all kinds of things that aren't within the scope of occ infra and resource management.

Comment 8

[Rob Thijssen [:grenade (EET/UTC+0300)]]

also i believe the orange factor link to this bug is completely unrelated.

those orange factor builds contain the following log messages:

[taskcluster:error] Uploading error artifact public/test_info from file build/blobber_upload_dir with message "Could not read directory 'Z:\\task_1525311161\\build\\blobber_upload_dir'", reason "file-missing-on-worker" and expiry 2019-05-02T23:58:43.351Z
[taskcluster:error] TASK FAILURE during artifact upload: file-missing-on-worker: Could not read directory 'Z:\task_1525311161\build\blobber_upload_dir'
[taskcluster 2018-05-03T01:40:41.339Z] Uploading redirect artifact public/logs/live.log to URL https://queue.taskcluster.net/v1/task/M3Ldb-FxSoOrWD2gtl9Jow/runs/0/artifacts/public/logs/live_backing.log with mime type "text/plain; charset=utf-8" and expiry 2019-05-02T23:58:43.351Z
[taskcluster:error] Task not successful due to following exception(s):
[taskcluster:error] Exception 1)
[taskcluster:error] exit status 1073807364
[taskcluster:error] Exception 2)
[taskcluster:error] file-missing-on-worker: Could not read directory 'Z:\task_1525311161\build\blobber_upload_dir'
[taskcluster:error] 


if the instance where that task had run had been terminated because of explorer crashes we would not be getting messages about generic worker being unable to find an artifact. generic worker itself would not be saying anything since the instance it was on would be dead. i don't know why there's any association between whatever problems gw is having with finding artifacts and this bug at all. two different problems. so i'm closing this again. the problem this bug describes has been fixed. the problems described by the orange factor links cannot relate to that fix since a terminated worker would not be able to send messages about missing artifacts. please create another bug that is actuially related to those errors.

Comment 9

[Rob Thijssen [:grenade (EET/UTC+0300)]]

having read through the comments on bug 1444168 more carefully, i see that i am wrong. it is in fact the killing of the instance that causes the failure to find artefacts.

Comment 10

[Rob Thijssen [:grenade (EET/UTC+0300)]]

other recent commits to occ check for an idle generic worker so we'll have to rely on those to determine wether or not to terminate an instance. i have removed the check for multiple explorer crashes and these will no longer cause a termination.
https://github.com/mozilla-releng/OpenCloudConfig/commit/7b01ea86a55fe380e2c675623bf40bdd459c118f

Comment 11

[Intermittent Failures Robot]

82 failures in 551 pushes (0.149 failures/push) were associated with this bug in the last 7 days. 

This is the #14 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **   

Repository breakdown:
* mozilla-inbound: 28
* try: 23
* autoland: 20
* mozilla-central: 11

Platform breakdown:
* windows10-64: 73
* windows10-64-devedition: 5
* windows10-64-nightly: 3
* windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1457868&startday=2018-04-30&endday=2018-05-06&tree=trunk