Closed Bug 1490398 Opened 7 years ago Closed 7 years ago

Win 10 moonshot nodes not running generic-worker.exe

Categories

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

Product:
Infrastructure & Operations
Component:
RelOps: General
Type:
task
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED

People

(Reporter: markco, Assigned: markco)

References

Details

This bug is track the issue were Win 10 nodes are up, have network, but have been idle for more that 2.5 hours. I am suspecting that either we are hitting a race condition in OCC where it never places the flags generic-worker needs to start, or there is an intermittent network issue. Well need more info.
Assignee: relops → mcornmesser
Hello Mark, I took the machines that Zsolt left in bug 1452133#c97 and made this doc https://docs.google.com/spreadsheets/d/1b1TbP-76EFBo2tiSviOI0MpQb8AbQ05UkCGeB6hSgn8/edit#gid=0 There are a lot of machines that after reboot did not took tasks for more than 10h.
Mark, over the last few days I was re-imaged many MS and even they did got a fresh new install, they still not running jobs. Today I found MS-247 at the same state, I have reimaged and there are no tasks. I have found the bellow error in the logs on many MSs, including on 247. Hope it helps to fix the issue. Sep 12 05:43:55 T-W1064-MS-247.mdc1.mozilla.com Microsoft-Windows-DSC: Job {4FD5F974-B689-11E8-89A1-F40343DF520A} : This event indicates that failure happens when LCM is processing the configuration. Error Id is 0x1. Error Detail is The SendConfigurationApply function did not succeed.. Resource Id is [Registry]RegistryValueSet_reg_prevent_sec_notify and Source Info is C:\windows\TEMP\xDynamicConfig.ps1::549::9::Registry. Error Message is PowerShell DSC resource MSFT_RegistryResource failed to execute Set-TargetResource functionality with error message: (ERROR) Parameter 'ValueData' has an invalid value '0' for type 'Dword' .#015 Sep 12 05:43:55 T-W1064-MS-247.mdc1.mozilla.com Microsoft-Windows-DSC: Job {4FD5F974-B689-11E8-89A1-F40343DF520A} : MIResult: 1 Error Message: PowerShell DSC resource MSFT_RegistryResource failed to execute Set-TargetResource functionality with error message: (ERROR) Parameter 'ValueData' has an invalid value '0' for type 'Dword' Message ID: ProviderOperationExecutionFailure Error Category: 7 Error Code: 1 Error Type: MI#015 Sep 12 05:43:55 T-W1064-MS-247.mdc1.mozilla.com Microsoft-Windows-DSC: Job {4FD5F974-B689-11E8-89A1-F40343DF520A} : Job runs under the following LCM setting. ConfigurationMode: ApplyAndMonitor ConfigurationModeFrequencyMins: 15 RefreshMode: PUSH RefreshFrequencyMins: 30 RebootNodeIfNeeded: NONE DebugMode: False#015 Sep 12 05:43:55 T-W1064-MS-247.mdc1.mozilla.com Microsoft-Windows-DSC: RESULT 1 [NXLOG@14506 Keywords="4611686018427387904" EventType="ERROR" EventID="4252" ProviderGuid="{50DF9E12-A8C4-4939-B281-47E1325BA63E}" Version="0" Task="0" OpcodeValue="0" RecordNumber="37987" ActivityID="{5EE80522-4A91-0005-4F2A-E85E914AD401}" ThreadID="7648" Channel="Microsoft-Windows-DSC/Operational" Domain="NT AUTHORITY" AccountName="SYSTEM" UserID="S-1-5-18" AccountType="User" Opcode="Info" JobId="{4FD5F974-B689-11E8-89A1-F40343DF520A}" MIResult="1" ErrorMessage="The SendConfigurationApply function did not succeed." ErrorCategory="0" ErrorCode="1" ErrorType="MI" EventReceivedTime="2018-09-12 12:43:54" SourceModuleName="eventlog" SourceModuleType="im_msvistalog"] Job {4FD5F974-B689-11E8-89A1-F40343DF520A} : MIResult: 1 Error Message: The SendConfigurationApply function did not succeed. Message ID: MI RESULT 1 Error Category: 0 Error Code: 1 Error Type: MI#015 Sep 12 05:43:55 T-W1064-MS-247.mdc1.mozilla.com Microsoft-Windows-DSC: Job {4FD5F974-B689-11E8-89A1-F40343DF520A} : Details logging completed for C:\windows\System32\Configuration\ConfigurationStatus\{4FD5F974-B689-11E8-89A1-F40343DF520A}-0.details.json.#015 Sep 12 05:43:55 T-W1064-MS-247.mdc1.mozilla.com Microsoft-Windows-DSC: Job DscTimerConsistencyOperationResult : DSC Engine Error : #011 Error Message: NULL #011Error Code : 1 #015 Sep 12 05:44:50 T-W1064-MS-247.mdc1.mozilla.com Microsoft-Windows-DSC: The local configuration manager was shut down.#015
I have rebooted 247 and now I cannot see it in TC. WIll reimage it one more time. Error ResourceNotFound Worker with workerId T-W1064-MS-247, workerGroup mdc1,worker-type gecko-t-win10-64-hw and provisionerId releng-hardware not found. Are you sure it was created?
T-W1064-024 Task Started 14 hours ago (Complete) T-W1064-061 Task Started 3 hours ago (Complete) T-W1064-068 Task Started 5 hours ago (Complete) T-W1064-071 Task Started a day ago (Complete) T-W1064-117 Task Started 17 hours ago (Complete) T-W1064-128 Task Started 20 hours ago (Complete) T-W1064-129 Task Started 14 hours ago (Complete) T-W1064-131 Task Started 18 hours ago (Complete) T-W1064-133 Task Started 20 hours ago (Complete) T-W1064-134 Task Started 12 hours ago (Complete) T-W1064-135 Task Started 17 hours ago (Complete) T-W1064-157 Task Started 13 hours ago (Complete) T-W1064-158 Task Started a day ago (Complete) T-W1064-162 Task Started 14 hours ago (Complete) T-W1064-166 Task Started 21 hours ago (Complete) T-W1064-168 Task Started 6 hours ago (Complete) T-W1064-169 Task Started 19 hours ago (Complete) T-W1064-172 Task Started 10 hours ago (Complete) T-W1064-180 Task Started 5 hours ago (Complete) T-W1064-204 Task Started 20 hours ago (Complete) T-W1064-206 Task Started 10 hours ago (Complete) T-W1064-242 Task Started 5 hours ago (Complete) T-W1064-266 Task Started 8 hours ago (Complete) T-W1064-283 Task Started 7 hours ago (Complete) T-W1064-298 Task Started 4 hours ago (Complete) Should we leave them as they are or should we proceed action on them? Worth mentioning that currently there is a queue of 210 pending tasks.
Flags: needinfo?(mcornmesser)
T-W1064-MS-023 - 16 hours T-W1064-MS-044 - 10 hours T-W1064-MS-061 - 17 hours T-W1064-MS-063 - 13 hours T-W1064-MS-064 - 8 hours T-W1064-MS-068 - 20 hours T-W1064-MS-071 - 14 hours T-W1064-MS-117 - 5 hours T-W1064-MS-119 - 7 hours T-W1064-MS-125 - 13 hours T-W1064-MS-134 - 14 hours T-W1064-MS-159 - 12 hours T-W1064-MS-168 - 21 hours T-W1064-MS-176 - 7 hours T-W1064-MS-179 - 16 hours T-W1064-MS-180 - 13 hours T-W1064-MS-241 - 6 hours T-W1064-MS-242 - 4 hours T-W1064-MS-253 - 17 hours
> Should we leave them as they are or should we proceed action on them? Worth > mentioning that currently there is a queue of 210 pending tasks. Could go you take action on all but any 5 of them? I will come back to this this afternoon or tomorrow and start diving into this.
Flags: needinfo?(mcornmesser)
T-W1064-MS-134 had the same error as I posted on comment #2 plus the bellow one after reboot: Microsoft.PowerShell.DesiredStateConfiguration.Internal.ResourceProviderAdapter.ExecuteCommand(PowerShell powerShell, ResourceModuleInfo resInfo, String operationCmd, List`1 acceptedProperties, CimInstance nonResourcePropeties, CimInstance resourceConfiguration, LCMDebugMode debugMode, PSInvocationSettings pSInvocationSettings, UInt32& resultStatusHandle, Collection`1& result, ErrorRecord& errorRecord, PSModuleInfo localRunSpaceModuleInfo)" EventReceivedTime="2018-09-13 14:46:21" SourceModuleName="eventlog" SourceModuleType="im_msvistalog"] Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : Message The remote server returned an error: (429) Too Many Requests. HResult -2146233087 StackTrack at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input) at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke) at System.Management.Automation.PowerShell.Worker.CreateRunspaceIfNeededAndDoWork(Runspace rsToUse, Boolean isSync) at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings) at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings) at System.Management.Automation.PowerShell.Invoke(IEnumerable input, PSInvocationSettings settings) at Microsoft.PowerShell.DesiredStateConfiguration.Internal.ResourceProviderAdapter.ExecuteCommand(PowerShell powerShell, ResourceModuleInfo resInfo, String operationCmd, List`1 acceptedProperties, CimInstance nonResourcePropeties, CimInstance resourceConfiguration, LCMDebugMode debugMode, PSInvocationSettings pSInvocationSettings, UInt32& resultStatusHandle, Collection`1& result, ErrorRecord& errorRecord, PSModuleInfo localRunSpaceModuleInfo)#015 Sep 13 07:46:22 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : This event indicates that failure happens when LCM is processing the configuration. Error Id is 0x1. Error Detail is The SendConfigurationApply function did not succeed.. Resource Id is [Script]ChecksumFileDownload_maintenanceservice and Source Info is C:\windows\TEMP\xDynamicConfig.ps1::251::9::Script. Error Message is PowerShell DSC resource MSFT_ScriptResource failed to execute Set-TargetResource functionality with error message: The remote server returned an error: (429) Too Many Requests. .#015 Sep 13 07:46:22 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : MIResult: 1 Error Message: PowerShell DSC resource MSFT_ScriptResource failed to execute Set-TargetResource functionality with error message: The remote server returned an error: (429) Too Many Requests. Message ID: ProviderOperationExecutionFailure Error Category: 7 Error Code: 1 Error Type: MI#015 PSInvocationSettings settings)#015 Sep 13 07:47:50 t-w1064-ms-134.wintest.releng.mdc1.mozilla.com t-w1064-ms-134.wintest.releng.mdc1.mozilla.com: at Microsoft.PowerShell.DesiredStateConfiguration.Internal.ResourceProviderAdapter.ExecuteCommand(PowerShell powerShell, ResourceModuleInfo resInfo, String operationCmd, List`1 acceptedProperties, CimInstance nonResourcePropeties, CimInstance resourceConfiguration, LCMDebugMode debugMode, PSInvocationSettings pSInvocationSettings, UInt32& resultStatusHandle, Collection`1& result, ErrorRecord& errorRecord, PSModuleInfo localRunSpaceModuleInfo)" EventReceivedTime="2018-09-13 14:47:49" SourceModuleName="eventlog" SourceModuleType="im_msvistalog"] Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : Message (ERROR) Parameter 'ValueData' has an invalid value '0' for type 'Dword' HResult -2146233087 StackTrack at System.Management.Automation.Runspaces.PipelineBase.Invoke(IEnumerable input) at System.Management.Automation.PowerShell.Worker.ConstructPipelineAndDoWork(Runspace rs, Boolean performSyncInvoke) at System.Management.Automation.PowerShell.Worker.CreateRunspaceIfNeededAndDoWork(Runspace rsToUse, Boolean isSync) at System.Management.Automation.PowerShell.CoreInvokeHelper[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings) at System.Management.Automation.PowerShell.CoreInvoke[TInput,TOutput](PSDataCollection`1 input, PSDataCollection`1 output, PSInvocationSettings settings) at System.Management.Automation.PowerShell.Invoke(IEnumerable input, PSInvocationSettings settings) at Microsoft.PowerShell.DesiredStateConfiguration.Internal.ResourceProviderAdapter.ExecuteCommand(PowerShell powerShell, ResourceModuleInfo resInfo, String operationCmd, List`1 acceptedProperties, CimInstance nonResourcePropeties, CimInstance resourceConfiguration, LCMDebugMode debugMode, PSInvocationSettings pSInvocationSettings, UInt32& resultStatusHandle, Collection`1& result, ErrorRecord& errorRecord, PSModuleInfo localRunSpaceModuleInfo)#015 Sep 13 07:47:50 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : This event indicates that failure happens when LCM is processing the configuration. Error Id is 0x1. Error Detail is The SendConfigurationApply function did not succeed.. Resource Id is [Registry]RegistryValueSet_reg_prevent_sec_notify and Source Info is C:\windows\TEMP\xDynamicConfig.ps1::549::9::Registry. Error Message is PowerShell DSC resource MSFT_RegistryResource failed to execute Set-TargetResource functionality with error message: (ERROR) Parameter 'ValueData' has an invalid value '0' for type 'Dword' .#015 Sep 13 07:47:50 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : MIResult: 1 Error Message: PowerShell DSC resource MSFT_RegistryResource failed to execute Set-TargetResource functionality with error message: (ERROR) Parameter 'ValueData' has an invalid value '0' for type 'Dword' Message ID: ProviderOperationExecutionFailure Error Category: 7 Error Code: 1 Error Type: MI#015 Sep 13 07:47:50 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : Job runs under the following LCM setting. ConfigurationMode: ApplyAndMonitor ConfigurationModeFrequencyMins: 15 RefreshMode: PUSH RefreshFrequencyMins: 30 RebootNodeIfNeeded: NONE DebugMode: False#015 Sep 13 07:47:50 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: RESULT 1 [NXLOG@14506 Keywords="4611686018427387904" EventType="ERROR" EventID="4252" ProviderGuid="{50DF9E12-A8C4-4939-B281-47E1325BA63E}" Version="0" Task="0" OpcodeValue="0" RecordNumber="40100" ActivityID="{371D425F-4B70-0006-1654-1D37704BD401}" ThreadID="3400" Channel="Microsoft-Windows-DSC/Operational" Domain="NT AUTHORITY" AccountName="SYSTEM" UserID="S-1-5-18" AccountType="User" Opcode="Info" JobId="{C1965362-B763-11E8-8EB4-F40343DF4E69}" MIResult="1" ErrorMessage="The SendConfigurationApply function did not succeed." ErrorCategory="0" ErrorCode="1" ErrorType="MI" EventReceivedTime="2018-09-13 14:47:49" SourceModuleName="eventlog" SourceModuleType="im_msvistalog"] Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : MIResult: 1 Error Message: The SendConfigurationApply function did not succeed. Message ID: MI RESULT 1 Error Category: 0 Error Code: 1 Error Type: MI#015 Sep 13 07:47:50 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: Job {C1965362-B763-11E8-8EB4-F40343DF4E69} : Details logging completed for C:\windows\System32\Configuration\ConfigurationStatus\{C1965362-B763-11E8-8EB4-F40343DF4E69}-0.details.json.#015 Sep 13 07:47:50 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: Job DscTimerConsistencyOperationResult : DSC Engine Error : #011 Error Message: NULL #011Error Code : 1 #015 Sep 13 07:48:42 T-W1064-MS-134.mdc1.mozilla.com Microsoft-Windows-DSC: The local configuration manager was shut down.#015
We will need to reinstall the most recently installed machines. I don't know if it was my bad or a MDT sync issue but the install was using an incorrect script. The script was pointed to the staging repo. I am testing the deployment now using T-W1064-MS-134. The errors are being caused by an issue with the win 10 hw manifest in that repo.
What do you mean by the most recently installed? Let ciduty know how far back should we check in regards to what machines where re-imaged. We can start actioning on this as soon as you are done testing and give the green light.
Flags: needinfo?(mcornmesser)
I would go back to Monday.
Flags: needinfo?(mcornmesser)
Roger that Mark! Also here's a more up-to-date list of what hasn't taken jobs for 2.5h+ : T-W1064-MS-{035, 062, 064, 067, 070, 072, 077, 106, 117, 119, 157, 173, 176, 250, 282, 289, 298} Note, i did reboot all of them (i only saw your comment above after i rebooted them) and, 077 and 298 failed to reboot. The rest rebooted successfully and a few of them are back at work. 064, 072, 77, 117, 119, 157, 176, 298 - still haven't picked jobs yet. Will leave these to you to have a small pool to cherry pick from for troubleshooting. Also 250 recovered, did one task right after the reboot and hasn't done anything since. Might be worth looking into it as well.
After doing a couple of swipes through the W10 pool I've found this: Lazy workers of today: T-W1064-MS-{026, 031, 036, 045, 063, 071, 077, 078, 86, 89, 118, 129, 155, 165, 167, 203, 204, 212, 262, 266, 269, 292, 293} & T-W1064-MS-{024, 067, 069 , 075, 084, 131, 173, 203, 212, 285, 297, 298} These have recovered after a reboot: T-W1064-MS-{63, 86, 89, 129, 155, 165, 167, 203, 212}. The rest have been re-imaged. T-W1064-MS-{036, 045} still haven't picked up jobs after 5+ hours after the re-image finished. T-W1064-MS-{167} had its last job finished as exception T-W1064-MS-{212} Completed a few tasks after re-image until one finished as exception. After this it stopped taking jobs again. T-W1064-MS-{026} When I connected through the iLo I noticed it kept resetting every few minutes. T-W1064-MS-{221} When checking papertrail, noticed OCC wasn't running. It only came back after 2 re-images (first one failed again).
I looked at this one T-W1064-MS-212, It appears hung through ilo (screen shows the "[]\nHewlett Package\nEnterprise" screen with a frozen bottom dot animation). https://tools.taskcluster.net/provisioners/releng-hardware/worker-types/gecko-t-win10-64-hw/workers/mdc1/T-W1064-MS-212 https://papertrailapp.com/systems/1849238101/events?focus=979723850398994441&selected=979723850398994441 "last seen 7 hours ago" https://papertrailapp.com/groups/1141234?filter=T-W1064-MS-212
Changing the name of the bug because the generic-worker service is running and is starting the run-generic-worker.bat. However, the bat file is never getting to the "C:\generic-worker\generic-worker.exe run --config C:\generic-worker\gen_worker.config" command. I am going to open up blocking bugs with further information and examples.
Summary: Generic-worker service is not running on Win 10 moonshot nodes → Win 10 moonshot nodes not running generic-worker.exe
Depends on: 1493759
Lat job for the bellow server is in exception state. T-W1064-MS-456 T-W1064-MS-458 T-W1064-MS-459 T-W1064-MS-462 T-W1064-MS-475 T-W1064-MS-477
Depends on: 1494704
Depends on: 1499801
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → FIXED
Reopening this as it seems some machines encounter this once again. Context: On my ongoing shift , a lot of W10 Moonshot machines we're missing from taskcluster. Proceed to restart them but it seems that this wasn't enough. Looking into the logs , all of them have the following log line in common : Oct 27 06:22:31 T-W1064-MS-120.mdc1.mozilla.com User32: The process C:\windows\system32\shutdown.exe (T-W1064-MS-120) has initiated the restart of computer T-W1064-MS-120 on behalf of user NT AUTHORITY\SYSTEM for the following reason: No title for this reason could be found Reason Code: 0x800000ff Shutdown Type: restart Comment: Generic-worker.exe has not started within the expected time; Restarting#015 I've reimaged the following machines: 066, 081, 111, 120, 128, 170, 173, 211, 214, 252, 260, 266, 285, 289, 292, 293, 328, 337, 338, 374, 382, 385, 390, 411, 422, 429, 434, 505 Left 543, 564, 565 as an example for further investigation, if needed.
Status: RESOLVED → REOPENED
Flags: needinfo?(mcornmesser)
Resolution: FIXED → ---
I took a look at the logs for ms-565. It was looping on: Oct 28 20:23:53 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 28 20:23:58 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 28 20:24:04 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 28 20:24:09 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 28 20:24:14 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 28 20:24:19 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 28 20:24:24 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 This in conjunction with the shutdown comment of "Generic-worker.exe has not started within the expected time" is indicative of the DSC manifest not being completed. The last item rundsc.ps1 logs is creation of the MaintainSystem task: https://papertrailapp.com/groups/1141234/events?focus=993400024434114564&q=ms-565+AND+OpenCLoud&selected=993400024434114564 ct 28 20:04:04 T-W1064-MS-565.mdc2.mozilla.com OpenCloudConfig: Create-ScheduledPowershellTask :: scheduled task: MaintainSystem created.#015 Oct 28 20:04:04 T-W1064-MS-565.mdc2.mozilla.com OpenCloudConfig: Create-ScheduledPowershellTask :: end - 2018-10-29T03:04:02.7503172Z#015 Oct 28 20:34:50 T-W1064-MS-565.mdc2.mozilla.com OpenCloudConfig: Set-DefaultStrongCryptography :: begin - 2018-10-29T03:34:48.5220976Z#015 Oct 28 20:34:50 T-W1064-MS-565.mdc2.mozilla.com OpenCloudConfig: Set-DefaultStrongCryptography :: CLRVersion: 4.0.30319.42000, PSVersion: 5.1.15063.0#015 Oct 28 20:34:50 T-W1064-MS-565.mdc2.mozilla.com OpenCloudConfig: Set-DefaultStrongCryptography :: SecurityProtocol: Tls, Tls11, Tls12#015 Typical would be: ct 28 20:44:20 T-W1064-MS-018.mdc1.mozilla.com OpenCloudConfig: Create-ScheduledPowershellTask :: end - 2018-10-29T03:44:19.1559329Z#015 Oct 28 20:44:30 T-W1064-MS-018.mdc1.mozilla.com OpenCloudConfig: Run-RemoteDesiredStateConfig :: begin - 2018-10-29T03:44:29.1468405Z#015 Oct 28 20:44:30 T-W1064-MS-018.mdc1.mozilla.com OpenCloudConfig: Stop-DesiredStateConfig :: begin - 2018-10-29T03:44:29.1488464Z#015 Oct 28 20:44:30 T-W1064-MS-018.mdc1.mozilla.com OpenCloudConfig: Stop-DesiredStateConfig :: dsc process with pid 8584, stopped.#015 Oct 28 20:44:30 T-W1064-MS-018.mdc1.mozilla.com OpenCloudConfig: Stop-DesiredStateConfig :: end - 2018-10-29T03:44:29.2250575Z#015 Oct 28 20:44:30 T-W1064-MS-018.mdc1.mozilla.com OpenCloudConfig: Run-RemoteDesiredStateConfig :: downloaded C:\windows\TEMP\xDynamicConfig.ps1, from https://raw.githubusercontent.com/mozilla-releng/OpenCloudConfig/master/userdata/xDynamicConfig.ps1.#015 Oct 28 20:44:39 T-W1064-MS-018.mdc1.mozilla.com OpenCloudConfig: Run-RemoteDesiredStateConfig :: compiled mof C:\windows\TEMP\xDynamicConfig, from xDynamicConfig.#015 So I suspect that the nodes are hitting an issue somewhere within: https://github.com/mozilla-releng/OpenCloudConfig/blob/3579c876b663143321e61c050a1402874f85e265/userdata/rundsc.ps1#L1421-L1435 The other odd bit is that I can not VNC into these nodes. This might be because the desktop is never fully loading. However, that is just a guess. Rob, I am going to dive deeper into this in the morning pdt, but do you have any suggestions? Maybe suggestions on how to add logging in the above linked code?
Flags: needinfo?(mcornmesser) → needinfo?(rthijssen)
by the time i looked at this instance (https://papertrailapp.com/systems/t-w1064-ms-565.mdc2.mozilla.com/events), the log was showing successful occ & dsc run completions. there was also one successful task run too: https://tools.taskcluster.net/provisioners/releng-hardware/worker-types/gecko-t-win10-64-hw/workers/mdc2/T-W1064-MS-565 i don't know why this instance was not doing work before that task run. maybe someone got to it before i did, or it resolved itself after some reboot.
Flags: needinfo?(rthijssen)
just spotted this in the logs for 565 (https://papertrailapp.com/systems/2345167882/events?focus=993585532946776073&selected=993585532946776073): Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: 2018/10/29 15:21:12 Error: (Intermittent) HTTP response code 503#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: HTTP/1.1 503 Service Unavailable#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: Content-Length: 506#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: Cache-Control: no-cache, no-store#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: Connection: keep-alive#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: Content-Type: text/html; charset=utf-8#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: Date: Mon, 29 Oct 2018 15:21:12 GMT#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: Server: Cowboy#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: <!DOCTYPE html>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011<html>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011 <head>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011<meta name="viewport" content="width=device-width, initial-scale=1">#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011<meta charset="utf-8">#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011<title>Application Error</title>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011<style media="screen">#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011 html,body,iframe {#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011#011margin: 0;#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011#011padding: 0;#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011 }#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011 html,body {#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011#011height: 100%;#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011#011overflow: hidden;#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011 }#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011 iframe {#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011#011width: 100%;#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011#011height: 100%;#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011#011border: 0;#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011 }#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011</style>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011 </head>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011 <body>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011#011<iframe src="//www.herokucdn.com/error-pages/application-error.html"></iframe>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011 </body>#015 Oct 29 17:21:13 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: #011</html>#015 ... Oct 29 17:21:34 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: 2018/10/29 15:21:34 No task claimed. Idle for 59m25.4561302s (will exit if no task claimed in 1h0m34.5438698s).#015 Oct 29 17:21:40 T-W1064-MS-565.mdc2.mozilla.com generic-worker-service: 2018/10/29 15:21:39 Disk available: 42361749504 bytes#015 looks like an intermittent error hitting some service on heroku...
I think that is a separate issue since that is happening after generic-worker.exe is ran. The point of recovery for ms-565: Oct 29 06:08:02 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 29 06:08:07 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 29 06:08:12 T-W1064-MS-565.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 29 at 6:30 AM Oct 29 06:40:46 T-W1064-MS-565.mdc2.mozilla.com nxlog: 2018-10-29 13:40:43 INFO connecting to log-aggregator.srv.releng.mdc2.mozilla.com:514#015 Oct 29 06:40:46 T-W1064-MS-565.mdc2.mozilla.com nxlog: 2018-10-29 13:40:43 WARNING input file does not exist: C:/generic-worker/generic-worker-service.log#015 Oct 29 06:40:46 T-W1064-MS-565.mdc2.mozilla.com nxlog: 2018-10-29 13:40:43 WARNING input file does not exist: C:/generic-worker/generic-worker.log#015 Oct 29 06:40:46 T-W1064-MS-565.mdc2.mozilla.com nxlog: 2018-10-29 13:40:43 INFO nxlog-ce-2.9.1716 started#015 Oct 29 06:40:46 T-W1064-MS-565.mdc2.mozilla.com nxlog: 2018-10-29 13:40:43 WARNING input file does not exist: C:/generic-worker/generic-worker-wrapper.log#015 Oct 29 06:40:46 T-W1064-MS-565.mdc2.mozilla.com nxlog: 2018-10-29 13:40:43 ERROR failed to subscribe to msvistalog events,the channel was not found [error code It looks like the node was hitting the issue and then goes off line. On the next reboot, approximately 30 minutes later, it recovers. The same thing happened on ms-543: Oct 29 02:42:28 T-W1064-MS-543.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 29 02:42:33 T-W1064-MS-543.mdc2.mozilla.com generic-worker: Checking for manifest completetion #015 Oct 29 at 3:00 AM Oct 29 03:12:13 T-W1064-MS-543.mdc2.mozilla.com nxlog: 2018-10-29 10:12:11 ERROR failed to subscribe to msvistalog events,the channel was not found [error code: 15007]; The specified channel could not be found. Check channel configuration. #015 Oct 29 03:12:13 T-W1064-MS-543.mdc2.mozilla.com nxlog: 2018-10-29 10:12:13 WARNING input file does not exist: C:/generic-worker/generic-worker.log#015
Actually looking through the logs the nodes were reimaged a about hours ago.
I am going to to move this conversation to Bug 1499801 and close this one.
Status: REOPENED → RESOLVED
Closed: 7 years ago → 7 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.