S h o r t S t o r i e s

// Tales from software development

Archive for November 2016

Monitoring Windows Updates

leave a comment »

As noted in the previous post, Windows Update can sometimes take a long time to process updates and runs at 100% CPU seemingly doing nothing.

A few days after the the maintenance of the virtual machine described in the previous post I had to update another Windows Server 2003 VM and although this was also eventually successful, it took even longer.

It installed 62 Windows updates but each update took 15-20 minutes to install. I suspect that this was because the disk was fragmented. To minimise this problem it’s worth running a defrag first. You might also consider temporarily turning off undo disks to apply the updates.

Monitoring the Windows Updates log is a useful way of reassuring yourself that something is happening even if there are sometimes periods of hours when nothing is logged.  The log file is C:\Windows\WindowsUpdate.log.

I’ve also noticed that C:\Windows\SoftwareDistribution\ReportingEvents.log is updated with a summary of the updates applied.

A useful way of monitoring what’s going on is to open these two files remotely on your desktop PC using a text editor such as Notepad++. You’ll need access to the server’s C$ network share, e.g. \\WS2003-VM1\C$\Windows\WindowsUpdate.log. Use Notepad++’s File | Reload from disk menu command to refresh the contents. I’ve mapped this command to CTRL-R for convenience.

I was concerned at the number of updates that completed with an error code but then noticed that error code 0x80070bc2 appears to indicate that a reboot is required and so is normal:

2016-09-30 09:45:14:709 2624 a9c Handler  : Install completed: result type = 0x1, installer error = False, error = 0x80070bc2, disabled until reboot = No, reboot required = Yes

Written by Sea Monkey

November 17, 2016 at 8:00 pm

Posted in Environments

Tagged with

Windows Update 7.6.7600.256 on Windows Server 2003 at 100% CPU: wait, wait, wait…

leave a comment »

It seems that many people are having problems with Windows Update 7.6.7600.256 on versions of Windows prior to Windows 8 / Server 2010.

In the past I’ve experienced the problem where Windows Update takes a very long time (i.e. hours rather than minutes) at a very high CPU utilisation without seeming to do anything but, if left long enough, it always eventually started downloading updates. This problem is always more of a issue with virtual machines that are frequently not switched on for months on end and quickly get out of date with regard to Windows Update.

A couple of years ago I switched my virtual hosting platform from Microsoft Virtual Server running under Windows Server to Parallels running under OS X on an Apple MacBook Pro. I’ve barely used the Microsoft Virtual Server VMs since but the other day decided that I’d better start them up and do some maintenance so that I can use them again if, and when, necessary.

I had a bit of a shock when I realised that I hadn’t started up the Windows Server 2003 since August 2008! I had a feeling that applying Windows Updates was going to be a bit problematic…

I started the VM up and left it for a few hours. When I checked it, it was running at 100% CPU and seemingly no disk I/O. Having seen this before with Windows Update I wasn’t overly worried but it wasn’t a good sign.

After two and half hours of processing I checked the log file, C:\Windows\WindowsUpdate.log

I could see that there was short burst of activity at the start of processing and then nothing for an hour. Then there was some activity over the next hour, or so, and finally these lines appeared:

2016-11-09 17:07:45:986 812 70c PT +++++++++++ PT: Synchronizing extended update info +++++++++++
2016-11-09 17:07:45:986 812 70c PT + ServiceId = {9482F4B4-E343-43B6-B170-9A65BC822C77}, Server URL = https://www.update.microsoft.com/v6/ClientWebService/client.asmx
2016-11-09 17:08:02:961 812 70c DtaStor WARNING: Attempted to add URL http://www.download.windowsupdate.com/msdownload/update/software/svpk/2008/05/1281479_4d9eac07944723bf757ef2bacba66bfeee5cd5ea.cab for file TZ6sB5RHI791fvK6y6Zr/u5c1eo= when file has not been previously added to the datastore
2016-11-09 17:08:02:961 812 70c DtaStor WARNING: Attempted to add URL http://www.download.windowsupdate.com/msdownload/update/v3-19990518/cabpool/861922_9233cb306099739fc3f4f9c81ce9c7cf663e9869.cab for file kjPLMGCZc5/D9PnIHOnHz2Y+mGk= when file has not been previously added to the datastore
... (26 similar messages) ...
2016-11-09 17:08:06:266 812 70c DtaStor WARNING: Attempted to add URL http://download.windowsupdate.com/d/msdownload/update/others/2015/07/18273876_72ecb3735936f961bab664695296ab36605c7078.cab for file cuyzc1k2+WG6tmRpUparNmBccHg= when file has not been previously added to the datastore

I left the VM running for another twenty minutes but then shut it down and discarded the undo disks when I left the office for the day.

The following day I tried some of the suggestions I found on various internet sites to help ‘force’ updates including a manual install of the Windows Update 7.6.7600.256 client but the result was always the same. When the processing reached the stage shown in the log extract above, nothing further happened – Windows Update continued to run at 100% CPU and no I/O.

I had almost decided that this old VM was a lost cause but decided to let Windows Update run for at least a couple of days to see if it eventually ‘came good’. I started the VM up again mid-afternoon on the following day and the log showed exactly the same messages during the course of the afternoon. Shortly after 5pm I saw the messages shown in the log extract above. This time I suspended the VM by choosing the Save stated and keep undo disks option. Early the following morning I started the VM up again using the Restore from saved state option and left it running through the morning.

Shortly before lunchtime it dawned on me that there was a lot of disk access noise coming from the VM host server machine. I quickly logged on to the VM and checked the Windows Update log file. Finally, after over seven hours of executing, there was evidence that Windows Update was working, albeit very slowly:

2016-11-11 12:53:46:363 812 70c Agent Update {F536CF5E-F74E-4F29-A562-FD78ED07A723}.102 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {0437FD3B-8E82-4989-BC54-B1C2BD098C33}.102 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {F08E4144-5CAB-42CA-A9DA-87D7BF08A27C}.102 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {02754C95-2A6A-40AF-8EF5-98A6199F8F42}.101 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {0A63AB0A-FA37-47FD-BF3C-C34457D954CB}.102 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {B65EE9A7-2C2A-4509-AFCA-A26867D85276}.103 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent * Added update {6485E5A2-7B05-4C94-B3C9-FDD7C0797089}.101 to search result
2016-11-11 12:53:46:363 812 70c Agent Update {E9D59D08-D622-41F8-BA5D-D39077FA6278}.101 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {B014A927-5C2B-4CF8-A28F-76482E6B9DF8}.101 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {5FD8B062-40C1-4C70-AEF9-C770C9B5B98C}.101 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {F3741FBB-1957-4945-8BDD-6C903AAD9482}.103 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {1F392D05-76AC-4D60-9B9D-D6F95EEA3BC9}.102 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {BB1E694D-58E9-451F-8956-5BED33B3EB0C}.102 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {8111E3DA-1329-45B9-8361-FD20CF8F1274}.101 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {A5D343F1-DCAC-4509-AD69-D9741F8B9438}.102 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {46C1E11A-0629-4D64-9D02-5394E0D7671F}.101 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent Update {607B8E7B-BDE9-4A09-AC67-1E169DCAF227}.101 is pruned out due to potential supersedence
2016-11-11 12:53:46:363 812 70c Agent * Added update {A63AC02D-F827-4274-9C30-8393381F2D5E}.102 to search result
2016-11-11 12:53:46:363 812 70c Agent * Added update {2A382F96-3F11-465D-9123-2C9E8569F4F0}.102 to search result
2016-11-11 12:53:46:363 812 70c Agent * Added update {4AC48E96-CAC1-43A0-A87D-C9FCEAE6F0B7}.101 to search result
2016-11-11 12:53:46:363 812 70c Agent * Added update {050039BE-09C7-442F-B27D-ECC41E6F7D6E}.101 to search result
2016-11-11 12:53:46:363 812 70c Agent * Added update {9BC08715-A16A-4150-9CCF-D303A0461678}.104 to search result

and, finally, an hour later the process completed:

2016-11-11 13:43:31:134 812 e2c AU #########
2016-11-11 13:43:31:134 812 e2c AU ## END ## AU: Download updates
2016-11-11 13:43:31:134 812 e2c AU #############
2016-11-11 13:43:31:235 812 e2c AU AU setting pending client directive to 'Install Approval'
2016-11-11 13:43:31:235 812 e2c AU Changing existing AU client directive from 'Download Progress' to 'Install Approval', session id = 0x0
2016-11-11 13:43:31:615 1948 7a0 CltUI AU client got new directive = 'Install Approval', serviceId = {9482F4B4-E343-43B6-B170-9A65BC822C77}, return = 0x00000000
2016-11-11 13:43:31:615 1948 7a0 CltUI AU client creating default WU/WSUS UI plugin
2016-11-11 13:43:36:242 812 70c Report REPORT EVENT: {E940FE82-7988-493A-A4D6-33511686966A} 2016-11-14 13:43:31:235-0000 1 189 102 {00000000-0000-0000-0000-000000000000} 0 0 AutomaticUpdates Success Content Install Installation Ready: The following updates are downloaded and ready for installation. To install the updates, an administrator should log on to this computer and Windows will prompt with further instructions: - Security Update for Windows Server 2003 (KB974318) - Security Update for Windows Server 2003 (KB2443105) - Security Update for Windows Server 2003 (KB2603381) - Security Update for Windows Server 2003 (KB3033889) - Security Update for Windows Server 2003 (KB978338) - Security Update for Windows Server 2003 (KB2780091) - Security Update for Windows Server 2003 (KB979687) - Security Update for Windows Server 2003 (KB2478960) - Security Update for Microsoft .NET Framework 1.1 SP1 on Windows Server 2003 and Windows Server 2003 R2 x86 (KB3023211) - Security Update for Windows Server 2003 (KB2922229) - Security Update for Windows Server 2003 (KB923561) - Security Update for Windows Server 2003 (KB2423089) - Security Update for Windows Server 2003 (KB3004361) - Security Update for Windows Media Format Runtime 9.5 for Windows Server 2003 (KB954155) - Update for Windows Server 2003 (KB971029) - Security Update for Windows Server 2003 (KB2864063) - Security Update for Windows Server 2003 (KB
2016-11-11 13:43:36:242 812 70c Report REPORT EVENT: {962EF573-CF6B-41C5-AF08-F6DAAA282497} 2016-11-14 13:43:31:235-0000 1 162 101 {92BC721E-0E2F-404B-8F69-757201C8B86F} 103 0 AutomaticUpdates Success Content Download Download succeeded.

Windows Update processing took seven hours in total with around four and a half hours where nothing seemed to be going on but the process was running at 100% CPU.

So, if you’re having similar problems, I can’t offer any suggestions on how to fix Windows Update but I would suggest that you give the process plenty of time to complete – that might be all it needs.

 

Written by Sea Monkey

November 14, 2016 at 7:00 pm

Posted in Environments

Tagged with