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

// Tales from software development

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

Detecting when a program is executing from the Visual Studio IDE

leave a comment »

When developing small ad hoc command line utilities in the Visual Studio IDE I often add a Console.ReadKey() method call so that I can see the console output before the program terminates and returns control the IDE. This call is removed when development is complete but I’ve often thought that it would be useful to detect if the program was executing from the IDE and, if so, pause before exiting.

I finally got round to looking at how to do this yesterday. I’d assumed that simply looking at Assembly.GetEntryAssembly() would be enough to determine that the execution was initiated by the IDE but of course Visual Studio is a lot more sophisticated than this. It appears to create an application Domain and launches the program within this domain. However, as the IDE sets itself as the Domain’s DomainManager this can be used to detect whether the program is executing from the IDE:

    // If we're running from the Visual Studio IDE then pause before exiting:
    if (AppDomain.CurrentDomain.DomainManager != null && AppDomain.CurrentDomain.DomainManager.GetType().FullName == "Microsoft.VisualStudio.HostingProcess.VSHostAppDomainManager")
    {
        Console.WriteLine();
        Console.WriteLine("Press any key to exit and return to Visual Studio...");
        Console.ReadKey();
    }

This works for Visual Studio 2010 but I haven’t tested it against other versions yet.

Written by Sea Monkey

October 20, 2016 at 7:00 pm

Posted in Development

Tagged with ,

Using the word ‘function’ in a comment in a MySQL stored procedure causes the RESTORE command to fail

leave a comment »

Recently our support team had a call from a customer who suspected that their nightly MySQL backup/restore job wasn’t working.

At most of our customer sites, once the nightly backup has been run, there is a job to restore the backup to a read-only copy of the live database that is used for reports.

Examining the logs confirmed that the RESTORE command was failing with this error message:

Error Code: 1064. You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near ‘deficiency if result data is available */’ at line 35212

The syntax being rejected looked suspiciously like a user comment in a stored procedure or user defined function and I vaguely recalled that we’d encountered a similar problem a few years ago where the use of the word ‘function’ caused problems with MySQL’s BACKUP and RESTORE commands. At the time we’d circumvented the problem by changing the comment to remove the word ‘function’.

I ran the following MySQL query to identify the stored procedure that contained the comment:

SELECT * FROM `information_schema`.`routines` WHERE `routine_definition` LIKE ‘%deficiency if result data%’ AND `routine_schema`=DATABASE();

The stored procedure did indeed contain the following comment:

/* Check for functional deficiency if result data is available */

I needed to see what was in the BACKUP file created by mysqldump but opening it in Notepad.exe wasn’t an option as it was 10Gb. Instead, I used a file splitting utility that I wrote a few years ago to extract 1000 lines from the backup file starting at 900 lines before the line number in the error message. I then looked for the start of the stored procedure in the backup extract. I expected to see this:

CREATE DEFINER=`root`@`%` PROCEDURE `sp_analyze_results`()
BEGIN
/* Check for functional deficiency if result data is available */

but instead the backup file contained this:

/*!50003 CREATE*/ /*!50020 DEFINER=`root`@`%` PROCEDURE `sp_test`()
BEGIN
/* Check for*/ /*!50003 functional deficiency if result data is available */

It appears that the BACKUP command is incorrectly parsing the string ‘function’ when it appears in a user comment.

I experimented to see precisely what triggers the bug and it appears to be the exact string ‘ function’, i.e. a space character followed by the eight characters ‘function’ followed by anything else. For example, ‘ function’, ‘ functional’, ‘ functionality’ will all trigger the bug but ‘*function’ won’t.

Note that although it’s the RESTORE command that fails, it’s the invalid backup file data written by the BACKUP command that is the problem.

I thought it would be worthwhile checking to see if the problem is limited to the FUNCTION keyword or whether other keywords are also affected. I created a test stored procedure that contained each of the several hundred MySQL keywords in its own comment on its own line. The bug is only triggered by the FUNCTION keyword but in the process of conducting the test I also found that it’s only the first occurrence of the FUNCTION keyword that triggers the bug.

Now that I had a reasonably good understanding of what triggers the bug, the next step was to search the MySQL bug reports for a match.

The affected customer has MySQL 5.5.16 installed and MySQL bug report 66035 (applies to MySQL 5.5.23 / .26) and describes the issue exactly. Note the comment in the report, “This is a regression bug, as mysqldump from 5.1.64 does not have this problem.” https://bugs.mysql.com/bug.php?id=66035

Through trial and error I’ve found that the bug is fixed in mysqldump version 5.5.30.

Written by Sea Monkey

August 25, 2016 at 8:00 pm

Posted in MySQL

Tagged with

Windows Update KB3161949 causes NETBIOS problems (June/July 2016)

leave a comment »

After applying some Windows Updates that have been pending for a while I then found when accessing my work VPN that NETBIOS names for resources on the VPN were not recognised.

Windows Update KB3161949 ‘hardens’ SMB by blocking access outside of the local network as described here: https://support.microsoft.com/en-gb/kb/3161949

Fortunately, this change can be disabled by adding the following 32 bit DWORD registry value:

HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\services\NetBT\Parameters\AllowNBToInternet=1

A Windows restart is required to make the change effective.

Written by Sea Monkey

August 11, 2016 at 9:45 am

Posted in Environments

Tagged with

OS X El Capitan NETBIOS name problem in 10.11.4 is fixed in 10.11.5

leave a comment »

After applying the OS X 10.11.4 update via the App Store to my Mac Mini I found that it was no longer identifying itself on the network with its NETBIOS name.

I tried a few things to fix this but nothing resolved the problem. I came to the conclusion that the update had broken NETBIOS support and decided that the best course of action was to wait for the next version update and hope that it would be fixed.

I’ve just applied the combo update for 10.11.5 and, thankfully, as soon as the Mac Mini restarted it is now identifying itself via its NETBIOS name again.

Written by Sea Monkey

June 3, 2016 at 6:00 pm

Posted in Environments

Tagged with

MySQL covering indexes for performance

leave a comment »

Vitality’s application has a function to create clinical letters. While most customers print a physical copy of the letter and post it, increasingly we are asked to implement an interface to a document management system that sends the letter electronically to the recipient. Typically, this is the patient’s GP.

The interface executes a SELECT query on the correspondence table in the Vitality database similar to this:

SELECT
  c.FileName,
  cs.Description
  FROM 
    correspondence AS c
    INNER JOIN codesets AS cs ON cs.CodeId = c.Type
  WHERE
    c.Approved = true
    AND c.Processed = NULL
    AND cs.CodeSetNo = 20;

Note that the columns referenced on the correspondence table are FileName (of the Microsoft Word document), Type (the type of letter), Approved (indicating the letter is complete and may be sent), and Processed (indicating whether the interface has processed the letter). Codeset 20 contains a list of the letter templates and their descriptions.

This SELECT query has executed in less than a second for the past five years that the interface has been installed at one of our largest customers where approximately 60,000 letters are created each year.

However, a few weeks ago it was noticed that the interface was intermittently failing to send letters. Investigation showed that the SELECT query was sometimes taking in excess of 90 seconds to execute. The command was timing out and throwing an exception that caused the interface to suspend processing. The puzzle was, why was a query that typically executed in less than a second now taking over 90 seconds ?

I’m not sure that we’re ever going to fully understand the change in behaviour but, in part, it appears to be that the MySQL query planner changed the execution plan as the size of the correspondence table grew to over 300,000 rows. After rebuilding the indexes on the table and repairing it the execution time was consistently around 10 seconds.

We realised that whilst we had always thought that the execution time was less than a second and the interface’s processing logs usually showed this, this was likely to be because much of the time MySQL was using a cached query result.

Because the correspondence table contains a summary of the letter content, each row is quite large and a table scan is expensive. With over 300,000 rows in the table, a table scan is very expensive.

So we started to look at how the query could be optimised. Initially we thought that a suitable index would help the query engine to efficiently access the table data but after a number of failed experiments we realised that whilst this was better than a table scan the performance was still quite poor.

The last resort was to try creating a covering index. This is an index in which all the referenced columns are contained in the index so that the query engine doesn’t need to access the table data at all. Our first attempt didn’t show any improvement until we realised that whilst we had included the FileName, Approved, and Processed columns referenced in the SELECT column list and WHERE clause, we had overlooked the reference to the Type column in the INNER JOIN condition. As soon as this column was added to the index there was a massive improvement and the query now consistently executes in 0.3-06 seconds with caching disabled.

Using EXPLAIN to display the query plan shows that the correspondence table is now not being access at all. Instead the covering index is providing all the correspondence column data referenced in the query.

Written by Sea Monkey

April 13, 2016 at 8:00 pm

Posted in MySQL

Tagged with

Flipboard – what’s going on ?

leave a comment »

I’ve been using Flipboard for a couple of years to keep up with several software development blogs and noticed recently that these were showing up in Flipboard as ‘Content unavailable’. As the affected blogs are all hosted by Microsoft MSDN, I guessed that the URLs may have changed and I need to edit the Flipboard entry to point to the updated URL.

This morning I tried to do that on my iPad and discovered that there is no way to edit any property of a Flipboard entry. The Edit functionality consists of one action: X, i.e. Delete. This is poor.

As an alternative to correcting the URL, I thought I’d add a new entry for the new URLs and then delete the old entries. Erm… How do I add a URL for a blog ? It must be possible because I’ve previously done it, obviously, but it isn’t at all obvious now. After trying a number of different ways of searching and adding the blog URL I realised that Flipboard just won’t do this anymore. Or, if it can do it, the functionality is well hidden.

As I wasn’t getting very far with the iPad app I thought I’d try using the web interface on my desktop PC. Bizarrely, the web UI feels even more limited. I don’t think it is as I think it offers exactly the same functionality as the iPad app but there’s an expectation that the browser UI on a desktop PC would offer more. At least on the iPad app I get a message indicating ‘Content unavailable’ but in the desktop browser UI I just get a blank page. This is getting a bit rubbish…

I’m at a loss to understand what Flipboard is trying to achieve. They appear to have removed the ability to follow a blog web site and there is no edit functionality worth mentioning. It’s possible to delete a source but that’s it.

When Apple released its News app on iOS there were suggestions that this would compete directly against apps like Flipboard but rather than build on the existing functionality, Flipboard appears to be removing functionality and dumbing down to ensure that its app fails against News. Weird. Right now, I can’t see any reason not to delete the Flipboard app from my iPad as it’s not providing me with anything that the Apple News app doesn’t do better.

Written by Sea Monkey

April 13, 2016 at 8:30 am

Posted in Comment

Tagged with