locked
Slow startup with 7.4.7600.226 (The Automatic Updates service hung on starting.) RRS feed

  • Question

  • We are experiencing a delay at startup time on all our WSUS clients with version 7.4.7600.226, with an entry in the eventlog eventid 7022 - "The Automatic Updates service hung on starting."
    After a few seconds the system log shows that this service is succesfully started.

    After testing some time I tried a manual downgrade to 7.2.6001.788 and this resulted in a normal startup time, without the delay. So I think this is a client-only issue.

    After a short time while the client is updated again by the WSUS server to 7.4.7600.226 and all the delays at boot time are back again.

    With the error at startup time and the delay the updates and the reporting to the WSUS server still work with client 7.4.7600.226.

    What should I do?

    OS: XP Pro, SP3
    WSUS 3.0 SP2
    Sunday, October 4, 2009 4:20 PM

Answers

  • It looks like we found the Policy/Agent conflict for our environemt.  We have the "Download missing COM components" policy enabled in our GPO (Computer Configuration -> Administrative Templates -> System), Disabling or setting to Not Configured, appears to be resolving the slowness/service hanging.

    We are still doing some testing, but so far, we are reliably able to fix/break it by changing that policy.

    • Proposed as answer by RogueSpear Tuesday, October 13, 2009 6:01 PM
    • Marked as answer by Sven J Tuesday, October 13, 2009 7:46 PM
    • Unmarked as answer by Sven J Tuesday, October 13, 2009 7:47 PM
    • Unproposed as answer by Sven J Tuesday, October 13, 2009 7:47 PM
    • Marked as answer by Sven J Tuesday, October 13, 2009 7:47 PM
    Tuesday, October 13, 2009 3:08 PM
  • Some additional information on this:

    We have researched the issue internally and the problem is caused by a CoCreateInstance call being blocked by trying to download application code from AD when a call to InstallApplication is made. A sample thread stack:

    kd> knL50
     # ChildEBP RetAddr 
    00 f7c59c68 804dc0f7 nt!KiSwapContext+0x2e
    01 f7c59c74 804dc143 nt!KiSwapThread+0x46
    02 f7c59c9c 8056dd00 nt!KeWaitForSingleObject+0x1c2
    03 f7c59d50 804de7ec nt!NtRequestWaitReplyPort+0x63d
    04 f7c59d50 7c90e514 nt!KiFastCallEntry+0xf8
    05 022eebac 7c90daea ntdll!KiFastSystemCallRet
    06 022eebb0 77e7cac1 ntdll!NtRequestWaitReplyPort+0xc
    07 022eebfc 77e7a33e RPCRT4!LRPC_CCALL::SendReceive+0x228
    08 022eec08 77e7a36f RPCRT4!I_RpcSendReceive+0x24
    09 022eec1c 77ef4675 RPCRT4!NdrSendReceive+0x2b
    0a 022eeff8 77df3efc RPCRT4!NdrClientCall2+0x222
    0b 022ef00c 77df3eb2 ADVAPI32!RStartServiceW+0x1b
    0c 022ef04c 77e1dfda ADVAPI32!StartServiceW+0x1e
    0d 022ef094 77e1d7d7 ADVAPI32!Bind+0x95
    0e 022ef168 77566eb6 ADVAPI32!InstallApplication+0x20                 <==
    0f 022ef1ac 7752029d ole32!DownloadClass+0x4b
    10 022ef964 77500575 ole32!ICoCreateInstanceEx+0x440
    11 022ef98c 77500544 ole32!CComActivator::DoCreateInstance+0x28
    12 022ef9b0 775005b2 ole32!CoCreateInstanceEx+0x1e
    13 022ef9e0 5016f098 ole32!CoCreateInstance+0x37                  <==
    14 022efa10 5016f6b3 wuaueng!CoCreateDatastore+0x36
    15 022efb10 5016fb2a wuaueng!CSusDatastoreWrap::CreateCOMObject+0xe4
    16 022efb30 5017057e wuaueng!CSusDatastoreWrap::CreateStoreObject+0x68
    17 022efb50 501708c4 wuaueng!CSusDatastoreWrap::DoMethodEntry+0xb6
    18 022efb94 501104d0 wuaueng!CSusDatastoreWrap::GetSession+0x94
    19 022efbb8 500e61cf wuaueng!CAgentFeaturedUpdatesManager::Init+0xf2
    1a 022efbe4 500ce94c wuaueng!CAgentUpdateManager::Init+0xd6
    1b 022efc00 500ca8df wuaueng!CSusAgent::Init+0x51
    1c 022efe5c 500ca97c wuaueng!CSusClientGlobal::Init+0x207
    1d 022efe70 500ca050 wuaueng!CSusClientGlobal::StartSusClient+0x11
    1e 022eff18 500013f0 wuaueng!ServiceMain+0x195
    1f 022eff6c 010011cc wuauserv!ServiceMain+0xaf
    20 022effa0 77df354b svchost!ServiceStarter+0x9e
    21 022effb4 7c80b729 ADVAPI32!ScSvcctrlThreadA+0x12
    22 022effec 00000000 kernel32!BaseThreadStart+0x37

    If the application in question was not configured to be installed through GPO, the block is expected. Please refer to:
    http://msdn.microsoft.com/en-us/library/aa374307(VS.85).aspx

    For now, disabling the policy as mentioned at the top of this thread is the only workaround. If I get more information on this I will post an update here.


    Kind regards,

    \Rob

    Wednesday, December 9, 2009 9:41 AM

All replies

  • We have the exact same issue. I have a case logged with MS, however I suspect a new versio nof the Windows Update Agent will be released and it will solve the issue.

    Monday, October 5, 2009 9:37 AM
  • We have the exact same issue. I have a case logged with MS, however I suspect a new versio nof the Windows Update Agent will be released and it will solve the issue.


    Thank You, for informing us. Now I know, that I'm not the only one who's having problem like that. Could You please be so kind and let us know if You
    find any solution for this problem.

    rgds
    Sven
    Monday, October 5, 2009 9:48 AM
  • Hi Sven,

    Please run "services.msc", check printer spooler service, if it was disabled, please  changed from Disabled to Manual.

    Then check whether Automatic Update service will be normal.
    Monday, October 5, 2009 10:26 AM
  • Hi Sven,

    Please run "services.msc", check printer spooler service, if it was disabled, please  changed from Disabled to Manual.

    Then check whether Automatic Update service will be normal.

    Printer Spooler is started, and startup is Automatic...
    Monday, October 5, 2009 10:50 AM
  • We are seeing the exact same behaviour.  We had ~5000 workstations recieve this update on 9/30 and all are experiencing the same slow down/hung service issue.  This has actually caused a problem with a Fetal Monitoring application we use...
    Wednesday, October 7, 2009 6:29 PM
  • We are seeing the exact same behaviour.  We had ~5000 workstations recieve this update on 9/30 and all are experiencing the same slow down/hung service issue.  This has actually caused a problem with a Fetal Monitoring application we use...

    Any ideas.. progress.. I'm out of ideas.. I've heard rumors, that somewhere, where are also installed WSUS 3.0 SP2 and new clients (on XP) there are no problems at all. Maybe there are some environmental settings what was causing this weird behavior (I can not figure out).

    Thursday, October 8, 2009 9:15 AM
  • No news I'm afraid. Microsoft still collecting logs and asking me to do things which I've already done.

    Will keep you posted
    Thursday, October 8, 2009 9:54 AM
  • We are seeing the exact same behaviour.  We had ~5000 workstations recieve this update on 9/30 and all are experiencing the same slow down/hung service issue.  This has actually caused a problem with a Fetal Monitoring application we use...

    Any ideas.. progress.. I'm out of ideas.. I've heard rumors, that somewhere, where are also installed WSUS 3.0 SP2 and new clients (on XP) there are no problems at all. Maybe there are some environmental settings what was causing this weird behavior (I can not figure out).


    FWIW, I was not able to reproduce this behavior with my WSUS3SP2 server and an XP SP3 client.
    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Thursday, October 8, 2009 5:14 PM
  • We are running WSUS 3 SP2 with both XP SP2/3 clients and both have the issue.  Although we also have another group of workstations that do not appear to be experiencing this problem.
    Thursday, October 8, 2009 7:28 PM
  • We are running WSUS 3 SP2 with both XP SP2/3 clients and both have the issue.  Although we also have another group of workstations that do not appear to be experiencing this problem.
    This is significant diagnostic information, and your next step should be to enumerate all of the common features of the group that is having issues, all of the common features of the group that is not having issues, and then analyze the differential between those two common feature sets. The likely result is that you'll identify the actual cause of the performance issue on the affected machines.

    At any rate, your own statement here confirms that this problem is not with the WUAgent, but rather environmental.

    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Thursday, October 8, 2009 7:56 PM
  • Weird is that, that I have taken one of the affected workstation out from domain, reverted into WORKGROUP so that no GPO's is messing with it, and the issue presist. If I have a time, I should try clean install in a next few days, maybe it gives me something to think about.

    BTW. All pervious "Automatic Update Client" updatest went fine - the enviroment isn't changed that much. Maybe some "minor" changes in some GPO's. "Minor changes" - I mean, no extra registry settings, no modification in services and security area and so on..

    rgds
    Sven
    Thursday, October 8, 2009 8:20 PM
  • At any rate, your own statement here confirms that this problem is not with the WUAgent, but rather environmental.

    Well, it confirms that the combination of the environment and the WUAgent caused the problem, the environment alone was not an issue prior to the new agent...  The new agent and the problem occuring have a direct corrolation, plus our environment is not the only one affected. 

    The problem with isolating the differences between our two groups is that the differences between the two are enormous.  The affected workstations are highly locked down via group policy with a *large* number of medical applications installed.  Whereas the unaffected workstations are unrestricted with basic Office-type applications installed.

    That said, we are attempting to determine the difference in our environment, the reason I posted here was to make sure MS was aware that the latest update is causing a problem.  If specific environmental configurations can cause issues with a required update, that seems like it would be an important thing to know about.
    Thursday, October 8, 2009 9:01 PM
  • For anyone else troubleshooting this.  Look into your Computer based policies.  Moving a working machine under our restricted policy has caused the slowness/hung service to appear.  Hopefully someone else has fewer policies than we do, cuz it's likely going to take me a while to find the one(s) causing the problem...
    Thursday, October 8, 2009 9:55 PM
  • can you please share what OSes are running on your workstations that do NOT have a problem with new version of Windows Update client 7.4.7600.226?
    Are they also XP SP2/3?
    • Proposed as answer by ulianad Friday, October 9, 2009 1:53 AM
    • Unproposed as answer by Lawrence Garvin Friday, October 9, 2009 6:34 PM
    Friday, October 9, 2009 1:23 AM
  • Can the people with the issue please attach the verbose client logs (%windir%\windowsupdate.log) of the failing machines and send them my way? I would like to take a look.
    In order to create a verbose log, Please modify the following reg. keys on the problem system:

    [HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\WindowsUpdate\Trace]
    "Level"=dword:00000004
    "Flags"=dword:000000016

    Reboot the machine for these reg. keys to take effect.
    If the machine repros the issue, copy and attach the %windir%\windowsupdate.log file and send it my way.

    Turning on extended logging will cause Windows Update to perform more slowly, so you will probably want to reverse these changes when you are finished with your test. To do that, just remove the following reg key [HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\WindowsUpdate\Trace] and reboot.

    Thanks

    Friday, October 9, 2009 1:51 AM
  • Can the people with the issue please attach the verbose client logs (%windir%\windowsupdate.log) of the failing machines and send them my way? I would like to take a look.
    In order to create a verbose log, Please modify the following reg. keys on the problem system:

    [HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\WindowsUpdate\Trace]
    "Level"=dword:00000004
    "Flags"=dword:000000016

    Reboot the machine for these reg. keys to take effect.
    If the machine repros the issue, copy and attach the %windir%\windowsupdate.log file and send it my way.

    Turning on extended logging will cause Windows Update to perform more slowly, so you will probably want to reverse these changes when you are finished with your test. To do that, just remove the following reg key [HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\WindowsUpdate\Trace] and reboot.

    Thanks


    Send where?
    Friday, October 9, 2009 12:06 PM
  • Can the people with the issue please attach the verbose client logs (%windir%\windowsupdate.log) of the failing machines and send them my way? I would like to take a look.
    In order to create a verbose log, Please modify the following reg. keys on the problem system:

    [HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\WindowsUpdate\Trace]
    "Level"=dword:00000004
    "Flags"=dword:000000016

    Reboot the machine for these reg. keys to take effect.
    If the machine repros the issue, copy and attach the %windir%\windowsupdate.log file and send it my way.

    Turning on extended logging will cause Windows Update to perform more slowly, so you will probably want to reverse these changes when you are finished with your test. To do that, just remove the following reg key [HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows\CurrentVersion\WindowsUpdate\Trace] and reboot.

    Thanks


    Send where?

    you are right, technet doesn't have a way to attach file. Fortunately, there is the other site that does have a way to attach files, and there is a similar discussion there: 

    http://www.wsus.info/index.php?showtopic=14114&st=0&gopid=46229&#entry46229

      Please send your verbose logs to this wsus discussion. thanks!

    Friday, October 9, 2009 6:28 PM
  • Send where?

    @Janx444:
    I'm trying to find my login credentials for wsus.info, so for the moment (and on the off chance I get digressed don't get logged onto wsus.info until later), I'd like to call attention to these two lines from your LOGFILE:


    2009-09-30 09:33:07:803 1088  74 Agent   * WSUS server: [url="http://srv-dsb-021:8530"]http://srv-dsb-021:8530[/url]
    2009-09-30 09:33:07:803 1088  74 Agent   * WSUS status server: [url="http://srv-dsb-021:8530"]http://srv-dsb-021:8530[/url]

    Is this an accurate indication of the actual value you have configured in your policy, or is this something that's been messed up by some translator somewhere trying wrap tags around an actual hyperlink?


    As for the "send where"... you can post the relevant portions of the logfiles as TEXT into the body of a message in this forum; which is the preferred methdology in these forums.


    As for the time delay in your service startup... let's note here that the delay is not occuring as result of a DETECTION, but rather as a result of the agent attempting to read the configuration from the registry!

    2009-09-30 09:30:25:109 1088  74 Service ** START **  Service: Service startup
    2009-09-30 09:30:25:109 1088  74 Service *********
    2009-09-30 09:30:25:156 1088  74 Agent   * WU client version 7.4.7600.226
    2009-09-30 09:30:25:156 1088  74 Agent   * Base directory: C:\WINDOWS\SoftwareDistribution
    2009-09-30 09:30:25:171 1088  74 Agent   * Access type: No proxy
    2009-09-30 09:30:25:171 1088  74 Agent   * Network state: Connected

    Here's the time delay, *before* the client has collected all of the configuration data from the registry and logged it -- almost three full minutes.

    2009-09-30 09:33:07:803 1088  74 Agent ***********  Agent: Initializing Windows Update Agent  ***********
    2009
    -09-30 09:33:07:803 1088  74 Agent ***********  Agent: Initializing global settings cache  ***********
    2009-09-30 09:33:07:803 1088  74 Agent   * WSUS server: [url="http://srv-dsb-021:8530"]http://srv-dsb-021:8530[/url]
    2009-09-30 09:33:07:803 1088  74 Agent   * WSUS status server: [url="http://srv-dsb-021:8530"]http://srv-dsb-021:8530[/url]
    2009-09-30 09:33:07:803 1088  74 Agent   * Target group: DSB Workstations SP3 Pilot
    2009-09-30 09:33:07:803 1088  74 Agent   * Windows Update access disabled: No

    And, I'll reiterate, this appears to be an environmental problem, not a defect in the WUAgent, as I cannot reproduce this behavior on my own XP SP3 system, which btw, just to emphasize a relative point, is running on a P3/850 with 512mb RAM, so is probably running on a pretty slow machine to start with -- less than 60 seconds from first entry to the initialization of the settings cache, but note the majority of that time does exist in the same location -- it's just not as pronounced as your 2.5 minute delay.

    2009-10-08 01:33:57:426 1396 380 Service *************
    2009-10-08 01:33:57:466 1396 380 Service ** START **  Service: Service startup
    2009-10-08 01:33:57:466 1396 380 Service *********
    2009-10-08 01:33:59:158 1396 380 Agent   * WU client version 7.4.7600.226
    2009-10-08 01:33:59:158 1396 380 Agent   * Base directory: C:\WINDOWS\SoftwareDistribution
    2009-10-08 01:33:59:218 1396 380 Agent   * Access type: No proxy
    2009-10-08 01:33:59:258 1396 380 Agent   * Network state: Connected
    2009-10-08 01:34:53:664 1396 380 Agent ***********  Agent: Initializing Windows Update Agent  ***********
    2009-10-08 01:34:53:664 1396 380 Agent ***********  Agent: Initializing global settings cache  ***********
    2009-10-08 01:34:53:664 1396 380 Agent   * WSUS server: http://sbs2003r2:8530
    2009-10-08 01:34:53:675 1396 380 Agent   * WSUS status server: http://sbs2003r2:8530
    2009-10-08 01:34:53:675 1396 380 Agent   * Target group: (Unassigned Computers)
    2009-10-08 01:34:53:675 1396 380 Agent   * Windows Update access disabled: No



    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Friday, October 9, 2009 6:53 PM
  • Can the people with the issue please attach the verbose client logs


    @Janx44

    Okay, so I was able to retrieve  your extended log from the wsus.info thread.


    Here's the key entries:

    2009-10-01 20:19:11:485 1140 254 Agent   * Network state: Connected
    2009-10-01 20:19:11:688  632 27c Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0100)  ===========
    2009-10-01 20:19:11:688  632 27c Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-01 20:19:11:688  632 27c Misc   = Module: C:\WINDOWS\system32\wuaueng.dll
    2009-10-01 20:19:11:688  632 27c Service Registering proxy/stubs.
    2009-10-01 20:19:11:688  632 27c DtaStor Trying to make out of proc datastore active
    2009-10-01 20:21:02:912  632 27c Agent Service registration data backed up to registry
    2009-10-01 20:21:02:943  632 27c DtaStor SUS client data store initialized
    2009-10-01 20:21:02:943  632 27c DtaStor Out of proc datastore is now active


    Now we can see that the specific issue is one of two things:

    [1] Either a function of waiting to make the datastore active, or
    [2] A function of trying to backup the service registration data to the registry.


    With regard to the datastore ... does this machine have AntiVirus software running on it? If so, what product/version.

    Second, is that AV software configured to EXCLUDE the %windir%\SoftwareDistribution folder, or any subfolders from its scanning?

    Specifically, these two subfolders should be excluded from AV scanning:
        %windir%\SoftwareDistribution\Datastore -- which is where the Jet database that the WUAgent uses to cache information is located

        and

        %windir%\SoftwareDistribution\Download -- which is where the signed binary files are written to/read from

    While you're there, you might also want to exclude the %windir%\Installer folder, which is chock full of MSI files that are scanned at each detection as well.

    Third, do you have any utilities running on these systems that intercept any registry activity that could be interfering with the WUAgent's ability to "backup the service registration data to the registry"? While I don't know the specific internals of this process, though, my suspicion is that the "backup the service registration data to the registry" is the LAST step in this process and the logging of the datastore initialization complete 31 millseconds later is normal. I don't really think this is a registry write issue, but is more likely related to the datastore initialization.

    Note: This could also be caused by a heavily fragmented datastore, or a corrupted datastore (though these would more likely be occuring on individual PCs rather than an entire class of PCs). Nonetheless, you could test this theory by doing the following:

    1. Stop the Automatic Updates service (NET STOP WUAUSERV)
    2. Clear the BITS download queue (BITSADMIN /RESET /ALLUSERS)
    3. Rename the %windir%\SoftwareDistribution folder to SoftwareDistribution.OLD
    4. Start the Automatic Updates service (NET START WUAUSERV)

    Do *NOT* based any evaluation on the first startup of the service as it will require time to rebuild the datastore, etc.

    5. Execute a detection (WUAUCLT /RESETAUTHORIZATION /DETECTNOW)
    6. Wait 15 minutes or force flush the reporting cache after 5 minutes (WUAUCLT /REPORTNOW).
    7. Note the system time.
    8. Restart the Automatic Updates service (NET STOP/START WUAUSERV)
    9. Observe the service startup behavior and logging entries to determine if a clean datastore has helped the situation.



    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Friday, October 9, 2009 7:28 PM
  • To: Lawrence Garvin

    Hi,

    I'm janx in wsus.info forum dealing with this issue.

    First of all, those pervious cutouts from log files isn't mine so I can not comment.
    But I'v endabled extended logging and I'm trying to post it here - at least, part of it.

    You should keep in mind that:

    1. I have tried w & w/o Antivirus (Trend Micro 8.0 w latest patches)
    2. I have deleted "SoftwareDistribution" folder contents several times.
    3. Executed detections... /reset.. /detectnow..
    4. I don't have any 3rd party programs dealing with registry.
    5. Rewerted back to pervious AU Client (works fine until selfupdate to newer version and restarting after that)
    6. If I simply restart AU service - no problem at all. (problem rises only on bootup)
    7. I do have some GPO's configured, but here I can not point out anything special...
    8. Maybe You should compare the latest logs posted into wsus.info (Mine "janx" and "marcrp")
    9. Maybe I forgot something.... :)


    Below You see some bold lines witch may (or may not) indicate something.
    Event log - System log - "The Automatic Update Service hung on starting" is reported 14:50:xx
    About few seconds later, my Event log shows that AU service is started succesfully.

    -----------------
    2009-10-09 14:46:53:984 1480 7e4 AU AU found 0 updates for install at shutdown
    2009-10-09 14:46:53:984  568 12c Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:46:53:984  568 12c Misc   = Process: C:\WINDOWS\Explorer.EXE
    2009-10-09 14:46:53:984  568 12c Misc   = Module: C:\WINDOWS\system32\wuaueng.dll
    2009-10-09 14:46:53:984  568 12c Shutdwn 0 updates are ready to be installed at shutdown.
    2009-10-09 14:46:53:984  568 12c Shutdwn Install at shutdown: no updates to install
    2009-10-09 14:47:02:515 1480 7e4 AU AU found 0 updates for install at shutdown
    2009-10-09 14:47:02:515  568 12c Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:47:02:515  568 12c Misc   = Process: C:\WINDOWS\Explorer.EXE
    2009-10-09 14:47:02:515  568 12c Misc   = Module: C:\WINDOWS\system32\wuaueng.dll
    2009-10-09 14:47:02:515  568 12c Shutdwn 0 updates are ready to be installed at shutdown.
    2009-10-09 14:47:02:515  568 12c Shutdwn Install at shutdown: no updates to install
    2009-10-09 14:47:18:468 1480 2cc AU ###########  AU: Uninitializing Automatic Updates  ###########
    2009-10-09 14:47:18:765 1584 504 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:47:18:765 1584 504 Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-09 14:47:18:765 1584 504 AUClnt wuauclt.exe launched with command line "C:\WINDOWS\system32\wuauclt.exe" /RunStoreAsComServer Local\[5c8]SUSDS2b83eeb71c4a774ab622cb70fee0eafd
    2009-10-09 14:47:18:906 1584 504 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:47:18:906 1584 504 Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-09 14:47:18:906 1584 504 Misc   = Module: C:\WINDOWS\system32\wuaueng.dll
    2009-10-09 14:47:18:906 1584 504 Service Registering proxy/stubs.
    2009-10-09 14:47:18:906 1584 504 DtaStor Trying to make out of proc datastore active
    2009-10-09 14:47:19:343 1584 504 DtaStor Created new ESE session
    2009-10-09 14:47:19:343 1584 504 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:47:19:343 1584 504 DtaStor CSusDatastore AddRef: refcount is 1
    2009-10-09 14:47:19:343 1584 504 DtaStor Attempting to open table tbStoreVersion
    2009-10-09 14:47:19:343 1584 504 DtaStor Opened table: tableid: 41156608
    2009-10-09 14:47:19:343 1584 504 DtaStor Transaction begun. sesid 026D0320. Nesting: 0
    2009-10-09 14:47:19:343 1584 504 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:47:19:343 1584 504 DtaStor Transaction commited. sesid: 026D0320. Nesting: 0
    2009-10-09 14:47:19:343 1584 504 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:47:19:343 1584 504 DtaStor Store version is 0.185
    2009-10-09 14:47:19:374 1584 504 DtaStor Attempting to open table tbServiceData
    2009-10-09 14:47:19:374 1584 504 DtaStor Opened table: tableid: 41156608
    2009-10-09 14:47:19:374 1584 504 DtaStor Transaction begun. sesid 026D0320. Nesting: 0
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:47:19:374 1584 504 DtaStor Transaction commited. sesid: 026D0320. Nesting: 0
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 0
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore Release: refcount is 0
    2009-10-09 14:47:19:374 1584 504 DtaStor SUS client data store initialized
    2009-10-09 14:47:19:374 1584 504 DtaStor Out of proc datastore is now active
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastoreWrap QI: IClassFactory
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: IUnknown requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore AddRef: refcount is 1
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore AddRef: refcount is 2
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: IUnknown requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore AddRef: refcount is 3
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore AddRef: refcount is 4
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore Release: refcount is 3
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: ISusDatastore requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore AddRef: refcount is 4
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: ISusDatastore requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore AddRef: refcount is 5
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore Release: refcount is 4
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore Release: refcount is 3
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor Retrieved existing ESE session
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusDatastore AddRef: refcount is 4
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: ISusEseSession
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: IUnknown
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 3
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: ISusEseSession
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 3
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: ISusEseSession
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 4
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 3
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:47:19:374 1584 504 DtaStor Section 6 locked by session 000C0738 (thread: 1284)
    2009-10-09 14:47:19:374 1584 504 DtaStor Attempting to open table tbAUState
    2009-10-09 14:47:19:374 1584 504 DtaStor Opened table: tableid: 41156608
    2009-10-09 14:47:19:374 1584 504 DtaStor Transaction begun. sesid 026D0320. Nesting: 0
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 4
    2009-10-09 14:47:19:374 1584 504 DtaStor Transaction commited. sesid: 026D0320. Nesting: 0
    2009-10-09 14:47:19:374 1584 504 DtaStor CSusEseSession reference count at 3
    2009-10-09 14:47:19:374 1584 504 DtaStor Section 6 unlocked by session 000C0738 (thread: 1284)
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusEseSession reference count at 0
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusDatastore Release: refcount is 3
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusDatastore Release: refcount is 2
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusDatastore Release: refcount is 1
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusDatastore Release: refcount is 0
    2009-10-09 14:47:19:390 1584 504 DtaStor Out of proc datastore is shutting down
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusDatastoreWrap QI: unsupported interface requested
    2009-10-09 14:47:19:390 1584 504 DtaStor CSusDatastoreWrap QI: IUnknown
    2009-10-09 14:47:19:406 1480 2cc Service *********
    2009-10-09 14:47:19:406 1480 2cc Service **  END  **  Service: Service exit [Exit code = 0x240001]
    2009-10-09 14:47:19:406 1480 2cc Service *************
    2009-10-09 14:47:19:421 1584 504 DtaStor SUS client data store uninitialized
    2009-10-09 14:47:20:421 1584 504 DtaStor Out of proc datastore is now inactive
    2009-10-09 14:47:20:421 1584 504 AUClnt wuauclt.exe is exiting with code 0x00000000
    2009-10-09 14:48:29:453 1468 2e0 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:48:29:484 1468 2e0 Misc   = Process: C:\WINDOWS\System32\svchost.exe
    2009-10-09 14:48:29:484 1468 2e0 Misc   = Module: C:\WINDOWS\system32\wuaueng.dll
    2009-10-09 14:48:29:453 1468 2e0 Service *************
    2009-10-09 14:48:29:484 1468 2e0 Service ** START **  Service: Service startup
    2009-10-09 14:48:29:500 1468 2e0 Service *********
    2009-10-09 14:48:29:500 1468 2e0 Service updated service status to 2
    2009-10-09 14:48:29:500 1468 2e0 Setup Processing any required registration
    2009-10-09 14:48:29:500 1468 2e0 Service Registering proxy/stubs.
    2009-10-09 14:48:29:500 1468 2e0 Agent   * WU client version 7.4.7600.226
    2009-10-09 14:48:29:500 1468 2e0 Agent   * Base directory: C:\WINDOWS\SoftwareDistribution
    2009-10-09 14:48:29:500 1468 2e0 Misc CSusProxyManager successfully initialized.
    2009-10-09 14:48:29:500 1468 2e0 Misc Default Winhttp settings are Proxy : <(null)> ProxyByPass : <(null)>
    2009-10-09 14:48:29:500 1468 2e0 Agent   * Access type: No proxy
    2009-10-09 14:48:29:500 1468 2e0 Service WARNING: WSASocket() for Ipv6 failed with error: 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service failed to initialize Ip V6 network monitor with error 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 0
    2009-10-09 14:48:29:500 1468 2e0 Service WARNING: WSASocket() for Ipv6 failed with error: 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service failed to get network state for Ipv6 with error 8007273f, because CIpAddressMonitor is not initialized
    2009-10-09 14:48:29:515 1468 2e0 Service Network interfaces : 1
    2009-10-09 14:48:29:515 1468 2e0 Agent   * Network state: Connected
    2009-10-09 14:48:29:515 1468 2e0 EEHndlr EE does not support subexpression parsing.
    2009-10-09 14:48:29:515 1468 2e0 EEHndlr EE Handler QI: ISusExprEvaluate3
    2009-10-09 14:48:29:515 1468 2e0 EEHndlr CEEMsiHandler::AddRef: refcount is 2
    2009-10-09 14:48:29:515 1468 2e0 EEHndlr EE Handler QI: unsupported interface
    2009-10-09 14:48:29:515 1468 2e0 EEHndlr EE does not support subexpression parsing.
    2009-10-09 14:48:29:515 1468 2e0 EEHndlr EE does not support subexpression parsing.
    2009-10-09 14:48:29:515 1468 2e0 DnldMgr Initializing BITS callback handler.
    2009-10-09 14:48:29:515 1468 2e0 DnldMgr AddRef: ref count -> 1
    2009-10-09 14:48:29:515 1468 2e0 DnldMgr DH Listener AddRef: ref count -> 1
    2009-10-09 14:50:23:145 1468 2e0 DtaStor FATAL: DS: 0x80040154: Failed to CoCreate datastore
    2009-10-09 14:50:24:438  716 4b4 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:50:24:438  716 4b4 Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-09 14:50:24:438  716 4b4 AUClnt wuauclt.exe launched with command line "C:\WINDOWS\system32\wuauclt.exe" /RunStoreAsComServer Local\[5bc]SUSDSc4e347b2b098014eaf90107969454f65
    2009-10-09 14:50:24:643  716 4b4 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:50:24:643  716 4b4 Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-09 14:50:24:643  716 4b4 Misc   = Module: C:\WINDOWS\system32\wuaueng.dll
    2009-10-09 14:50:24:643  716 4b4 Service Registering proxy/stubs.
    2009-10-09 14:50:24:658  716 4b4 DtaStor Trying to make out of proc datastore active
    2009-10-09 14:50:26:645  716 4b4 DtaStor Created new ESE session
    2009-10-09 14:50:26:645  716 4b4 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:50:26:645  716 4b4 DtaStor CSusDatastore AddRef: refcount is 1
    2009-10-09 14:50:27:275  716 4b4 DtaStor Attempting to open table tbStoreVersion
    2009-10-09 14:50:27:275  716 4b4 DtaStor Opened table: tableid: 41156608
    2009-10-09 14:50:27:275  716 4b4 DtaStor Transaction begun. sesid 026D0320. Nesting: 0
    2009-10-09 14:50:27:275  716 4b4 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:50:27:323  716 4b4 DtaStor Transaction commited. sesid: 026D0320. Nesting: 0
    2009-10-09 14:50:27:323  716 4b4 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:50:27:323  716 4b4 DtaStor Store version is 0.185
    2009-10-09 14:50:27:859  716 4b4 DtaStor Attempting to open table tbServiceData
    2009-10-09 14:50:27:859  716 4b4 DtaStor Opened table: tableid: 41156608
    2009-10-09 14:50:27:859  716 4b4 DtaStor Transaction begun. sesid 026D0320. Nesting: 0
    2009-10-09 14:50:27:859  716 4b4 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:50:27:937  716 4b4 DtaStor Transaction commited. sesid: 026D0320. Nesting: 0
    2009-10-09 14:50:27:937  716 4b4 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:50:27:937  716 4b4 DtaStor CSusEseSession reference count at 0
    2009-10-09 14:50:27:937  716 4b4 DtaStor CSusDatastore Release: refcount is 0
    2009-10-09 14:50:27:937  716 4b4 DtaStor SUS client data store initialized
    2009-10-09 14:50:27:937  716 4b4 DtaStor Out of proc datastore is now active
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastoreWrap QI: IClassFactory
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: IUnknown requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore AddRef: refcount is 1
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore AddRef: refcount is 2
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: IUnknown requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore AddRef: refcount is 3
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore AddRef: refcount is 4
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore Release: refcount is 3
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: ISusDatastore requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore AddRef: refcount is 4
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore QI: ISusDatastore requested
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore AddRef: refcount is 5
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore Release: refcount is 4
    2009-10-09 14:50:27:953  716 4b4 DtaStor CSusDatastore Release: refcount is 3
    2009-10-09 14:50:27:953 1468 2e0 DtaStor Attempt 0 to CoCreate the datastore succeeded
    2009-10-09 14:50:27:953 1468 2e0 DtaStor Session caching is enabled
    2009-10-09 14:50:28:000 1468 2e0 DtaStor Store locked. Internal lock count is 1
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusDatastore QI: Unknown interface requested
    2009-10-09 14:50:28:000  716 4b4 DtaStor Retrieved existing ESE session
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusDatastore AddRef: refcount is 4
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: ISusEseSession
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 1
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: IUnknown
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 3
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 2
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: ISusEseSession
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 3
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: ISusEseSession
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 4
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 3
    2009-10-09 14:50:28:000 1468 2e0 DtaStor CSusEseSessionWrap ref count at 1
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession QI: Unknown interface requested
    2009-10-09 14:50:28:000  716 4b4 DtaStor Section 0 locked by session 000C0708 (thread: 1204)
    2009-10-09 14:50:28:000  716 4b4 DtaStor Attempting to open table tbFeaturedUpdateNotificationsData
    2009-10-09 14:50:28:000  716 4b4 DtaStor Opened table: tableid: 41156608
    2009-10-09 14:50:28:000  716 4b4 DtaStor Attempting to open table tbFeaturedUpdateNotificationsLocData
    2009-10-09 14:50:28:000  716 4b4 DtaStor Opened table: tableid: 41156880
    2009-10-09 14:50:28:000  716 4b4 DtaStor Transaction begun. sesid 026D0320. Nesting: 0
    2009-10-09 14:50:28:000  716 4b4 DtaStor CSusEseSession reference count at 4
    2009-10-09 14:50:28:016  716 4b4 DtaStor Transaction commited. sesid: 026D0320. Nesting: 0
    2009-10-09 14:50:28:016  716 4b4 DtaStor CSusEseSession reference count at 3
    2009-10-09 14:50:28:016  716 4b4 DtaStor Section 0 unlocked by session 000C0708 (thread: 1204)
    2009-10-09 14:50:28:032 1468 2e0 DtaStor CSusEseSessionWrap ref count at 0
    2009-10-09 14:50:28:032 1468 2e0 DtaStor Wrapper store lock count at 0
    2009-10-09 14:50:28:032 1468 2e0 DtaStor Created timer queue timer with delay 300 sec
    2009-10-09 14:50:28:127 1468 2e0 Handler CUHHandlerBase::AddRef: refcount is 2
    2009-10-09 14:50:28:127 1468 2e0 Handler CUHHandlerBase::Release: refcount is 1
    2009-10-09 14:50:28:127 1468 2e0 Handler CUHHandlerBase::AddRef: refcount is 2
    2009-10-09 14:50:28:142 1468 2e0 Handler CUHHandlerBase::Release: refcount is 1
    2009-10-09 14:50:28:142 1468 2e0 Agent ref count on CCR after AddRef is 2
    2009-10-09 14:50:28:158 1468 2e0 Service destination 0 subscribes for subscription 1 with internalrouting 0
    2009-10-09 14:50:28:158 1468 2e0 Service destination 0 subscribes for subscription 0 with internalrouting 0
    2009-10-09 14:50:28:158 1468 2e0 Service destination 0 subscribes for subscription 14 with internalrouting 0
    2009-10-09 14:50:28:158 1468 2e0 Service new event 12 of type 1 added to event system
    2009-10-09 14:50:28:190 1468 2e0 Agent ref count on CCR after AddRef is 3
    2009-10-09 14:50:28:190 1468 2e0 Agent ref count on CCR after AddRef is 4
    2009-10-09 14:50:28:190 1468 2e0 Agent ref count on CCR after Release is 3
    2009-10-09 14:50:28:190 1468 2e0 Agent ref count on CCR after AddRef is 4
    2009-10-09 14:50:28:190 1468 2e0 Agent ref count on CCR after Release is 3
    2009-10-09 14:50:28:190 1468 2e0 Agent ref count on CCR after AddRef is 4
    2009-10-09 14:50:28:221 1468 2e0 AU AddRef: refcount is 2
    2009-10-09 14:50:28:221 1468 2e0 Service destination 1 subscribes for subscription 18 with internalrouting 5
    2009-10-09 14:50:28:221 1468 2e0 Setup Using INF-based selfupdate
    2009-10-09 14:50:28:316 1468 2e0 Service updated service status to 4
    2009-10-09 14:50:28:316 1468 2e0 Service Service status is now SERVICE_RUNNING
    2009-10-09 14:50:28:316 1468 2e0 Service Event system starts running
    2009-10-09 14:50:28:316 1468 2e0 Service WARNING: WSASocket() for Ipv6 failed with error: 8007273f
    2009-10-09 14:50:28:316 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 8007273f
    2009-10-09 14:50:28:316 1468 2e0 Service failed to start listening in CIpAddressMonitor with error 8007273f, because it is not initialized
    2009-10-09 14:50:28:316 1468 2e0 Service failed to start listening Ip V6 network monitor with error 8007273f
    2009-10-09 14:50:28:316 1468 2e0 Service Updated network state. Prev Num of Interfaces : 1, now : 1.
    2009-10-09 14:50:28:316 1468 2e0 Service Wait object starts waiting with timeout 44842 msecs
    2009-10-09 14:50:28:316 1468 2e0 Service Wait object starts waiting with timeout 44842 msecs
    2009-10-09 14:50:28:316 1468 2e0 Service Signal subscription event 7
    2009-10-09 14:50:28:316 1468 2e0 Service Wait object starts waiting with timeout 44842 msecs
    2009-10-09 14:50:28:316 1468 2e0 Service WARNING: WSASocket() for Ipv6 failed with error: 8007273f
    2009-10-09 14:50:28:316 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 8007273f
    2009-10-09 14:50:28:316 1468 2e0 Service failed to get network state for Ipv6 with error 8007273f, because CIpAddressMonitor is not initialized
    2009-10-09 14:50:28:316 1468 2e0 Service Network interfaces : 1
    2009-10-09 14:50:28:316 1468 2e0 Service networkState = 2. DidNetworkStatusChanged = 0, DidNetworkConnectivityOptionsChanged = 0
    2009-10-09 14:50:28:316 1468 2e0 Service Wait object starts waiting with timeout 44842 msecs
    2009-10-09 14:50:31:973 1468 5c0 Service Service received connect notification
    2009-10-09 14:50:31:973 1468 5c0 Service Signal subscription event 5
    ---------------------------
    Friday, October 9, 2009 8:25 PM
  • > 2009-10-09 14:47:18:765 1584 504 AUClnt wuauclt.exe launched with command line
    > "C:\WINDOWS\system32\wuauclt.exe" /RunStoreAsComServer Local\[5c8]SUSDS2b83eeb71c4a774ab622cb70fee0eafd

    Uh... WHAT is this? ? ?

    =============

    Okay.. I thought about this a bit. I think I just freaked by what may be an improperly worded debug-level log entry.

    This is actually the command that's used to load up the WUAgent's DataStore as a COM Server (just like the command parameter suggests). It's not normally logged in the standard logs, and I freaked from the "launched with command line" phrase; which is probably not an accurate indication, unless that's a manifestation of this all happening as a result of a NET START or SC START command.


    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Friday, October 9, 2009 10:34 PM
  • First thing I notice is something I don't regularly see ..

    2009-10-09 14:48:29:453 1468 2e0 Service *************
    2009-10-09 14:48:29:484 1468 2e0 Service ** START **  Service: Service startup
    2009-10-09 14:48:29:500 1468 2e0 Service *********
    2009-10-09 14:48:29:500 1468 2e0 Service updated service status to 2
    2009-10-09 14:48:29:500 1468 2e0 Setup Processing any required registration
    2009-10-09 14:48:29:500 1468 2e0 Service Registering proxy/stubs.
    2009-10-09 14:48:29:500 1468 2e0 Agent   * WU client version 7.4.7600.226
    2009-10-09 14:48:29:500 1468 2e0 Agent   * Base directory: C:\WINDOWS\SoftwareDistribution
    2009-10-09 14:48:29:500 1468 2e0 Misc CSusProxyManager successfully initialized.
    2009-10-09 14:48:29:500 1468 2e0 Misc Default Winhttp settings are Proxy : <(null)> ProxyByPass : <(null)>
    2009-10-09 14:48:29:500 1468 2e0 Agent   * Access type: No proxy
    2009-10-09 14:48:29:500 1468 2e0 Service WARNING: WSASocket() for Ipv6 failed with error: 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service failed to initialize Ip V6 network monitor with error 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 0
    2009-10-09 14:48:29:500 1468 2e0 Service WARNING: WSASocket() for Ipv6 failed with error: 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service failed to get network state for Ipv6 with error 8007273f, because CIpAddressMonitor is not initialized

    Can you consider DISABLING IP v6 on this client system and re-testing your service startup / system poweron scenario? (after reinstalling the v7.4 WUAgent using the /wuforce parameter).

    This could also be a manifestation of an improperly registered DLL (perhaps even the same thing causing the 0x80040154 error loading the datastore)



    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Friday, October 9, 2009 10:36 PM
  • 2009-10-09 14:48:29:515 1468 2e0 DnldMgr Initializing BITS callback handler.
    2009-10-09 14:48:29:515 1468 2e0 DnldMgr AddRef: ref count -> 1
    2009-10-09 14:48:29:515 1468 2e0 DnldMgr DH Listener AddRef: ref count -> 1
    2009-10-09 14:50:23:145 1468 2e0 DtaStor FATAL: DS: 0x80040154: Failed to CoCreate datastore
    2009-10-09 14:50:24:438  716 4b4 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:50:24:438  716 4b4 Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-09 14:50:24:438  716 4b4 AUClnt wuauclt.exe launched with command line "C:\WINDOWS\system32\wuauclt.exe" /RunStoreAsComServer Local\[5bc]SUSDSc4e347b2b098014eaf90107969454f65
    2009-10-09 14:50:24:643  716 4b4 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:50:24:643  716 4b4 Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-09 14:50:24:643  716 4b4 Misc   = Module: C:\WINDOWS\system32\wuaueng.dll

    Well, this is definitely where the time delay is occuring.

    Some preliminary research suggests that the 0x80040154 error code may be an indication of an improperly registered DLL.

    I would suggest reinstalling the v7.4 WUAgent using the WindowsUpdateAgent-x86.exe installer and the /wuforce command line parameter.


    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Friday, October 9, 2009 10:39 PM
  • to Janx444:

    thanks for the log snippets. Please ignore the IPV6 errors, it just means that IPV6 is not supported on this machine.
    Can you please share the whole log in wsus discussion?

    thanks!
    Saturday, October 10, 2009 2:30 AM
  • To: Lawrence Garvin

    Hi,

    I'm janx in wsus.info forum dealing with this issue.

    First of all, those pervious cutouts from log files isn't mine so I can not comment.
    Getting back to this statement...

    You are the original poster in this thread, Yes?

    An exceptionally similar message to yours is posted in the WSUS.Info forums under the screenname "Reink" that started that thread.

    This thread was started 10/4/09 4:20pm; the WSUS.Info thread was started 9/22 9:39am (though I only now noticed the 12 day separation). I also now see that your first apperance in the WSUS.Info forum thread was dated 10/4 8:43am -- about 30 hours before this thread ever existed.

    The logs I copied and pasted are from a post in that WSUS.Info forum thread, dated 9/30 2:58am, from the poster named "Reink", which I thought was you, because the issues were so similarly worded. I must say, I'm quite intrigued that your message here, dated 10/4 is so similar to the message posted by "Reink" on 9/22!

    So, I'd say we still need *YOUR* logfiles, in this thread, in order to address *YOUR* question which started this thread. :-)





    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Saturday, October 10, 2009 3:32 AM
  • First thing I notice is something I don't regularly see ..

    2009-10-09 14:48:29:453 1468 2e0 Service *************
    2009-10-09 14:48:29:484 1468 2e0 Service ** START **  Service: Service startup
    2009-10-09 14:48:29:500 1468 2e0 Service *********
    2009-10-09 14:48:29:500 1468 2e0 Service updated service status to 2
    2009-10-09 14:48:29:500 1468 2e0 Setup Processing any required registration
    2009-10-09 14:48:29:500 1468 2e0 Service Registering proxy/stubs.
    2009-10-09 14:48:29:500 1468 2e0 Agent   * WU client version 7.4.7600.226
    2009-10-09 14:48:29:500 1468 2e0 Agent   * Base directory: C:\WINDOWS\SoftwareDistribution
    2009-10-09 14:48:29:500 1468 2e0 Misc CSusProxyManager successfully initialized.
    2009-10-09 14:48:29:500 1468 2e0 Misc Default Winhttp settings are Proxy : <(null)> ProxyByPass : <(null)>
    2009-10-09 14:48:29:500 1468 2e0 Agent   * Access type: No proxy
    2009-10-09 14:48:29:500 1468 2e0 Service WARNING: WSASocket() for Ipv6 failed with error: 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service failed to initialize Ip V6 network monitor with error 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 0
    2009-10-09 14:48:29:500 1468 2e0 Service WARNING: WSASocket() for Ipv6 failed with error: 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service CIpAddressMonitor::CreateListenSocket returning with hr = 8007273f
    2009-10-09 14:48:29:500 1468 2e0 Service failed to get network state for Ipv6 with error 8007273f, because CIpAddressMonitor is not initialized

    Can you consider DISABLING IP v6 on this client system and re-testing your service startup / system poweron scenario? (after reinstalling the v7.4 WUAgent using the /wuforce parameter).

    This could also be a manifestation of an improperly registered DLL (perhaps even the same thing causing the 0x80040154 error loading the datastore)



    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com

    I don't have IPv6 at all.

    rgds
    Sven
    Saturday, October 10, 2009 7:57 AM
  • 2009-10-09 14:48:29:515 1468 2e0 DnldMgr Initializing BITS callback handler.
    2009-10-09 14:48:29:515 1468 2e0 DnldMgr AddRef: ref count -> 1
    2009-10-09 14:48:29:515 1468 2e0 DnldMgr DH Listener AddRef: ref count -> 1
    2009-10-09 14:50:23:145 1468 2e0 DtaStor FATAL: DS: 0x80040154: Failed to CoCreate datastore
    2009-10-09 14:50:24:438  716 4b4 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:50:24:438  716 4b4 Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-09 14:50:24:438  716 4b4 AUClnt wuauclt.exe launched with command line "C:\WINDOWS\system32\wuauclt.exe" /RunStoreAsComServer Local\[5bc]SUSDSc4e347b2b098014eaf90107969454f65
    2009-10-09 14:50:24:643  716 4b4 Misc ===========  Logging initialized (build: 7.4.7600.226, tz: +0300)  ===========
    2009-10-09 14:50:24:643  716 4b4 Misc   = Process: C:\WINDOWS\system32\wuauclt.exe
    2009-10-09 14:50:24:643  716 4b4 Misc   = Module: C:\WINDOWS\system32\wuaueng.dll

    Well, this is definitely where the time delay is occuring.

    Some preliminary research suggests that the 0x80040154 error code may be an indication of an improperly registered DLL.

    I would suggest reinstalling the v7.4 WUAgent using the WindowsUpdateAgent-x86.exe installer and the /wuforce command line parameter.


    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com

    Hi,

    It could be or not.. Look at the "marcrp" log file into wsus.info forum and compare it to mine.
    You can see quite similar behaviour, with little exception. Look at same point (same lines) of the log file.

    rgds
    Sven
    Saturday, October 10, 2009 8:00 AM
  • to Janx444:

    thanks for the log snippets. Please ignore the IPV6 errors, it just means that IPV6 is not supported on this machine.
    Can you please share the whole log in wsus discussion?

    thanks!

    Hi,

    Today unfortunatley I don't have access to originatig computer.
    ASAP.

    rgds
    Sven
    Saturday, October 10, 2009 8:02 AM
  • To: Lawrence Garvin

    Hi,

    I'm janx in wsus.info forum dealing with this issue.

    First of all, those pervious cutouts from log files isn't mine so I can not comment.
    Getting back to this statement...

    You are the original poster in this thread, Yes?

    An exceptionally similar message to yours is posted in the WSUS.Info forums under the screenname "Reink" that started that thread.

    This thread was started 10/4/09 4:20pm; the WSUS.Info thread was started 9/22 9:39am (though I only now noticed the 12 day separation). I also now see that your first apperance in the WSUS.Info forum thread was dated 10/4 8:43am -- about 30 hours before this thread ever existed.

    The logs I copied and pasted are from a post in that WSUS.Info forum thread, dated 9/30 2:58am, from the poster named "Reink", which I thought was you, because the issues were so similarly worded. I must say, I'm quite intrigued that your message here, dated 10/4 is so similar to the message posted by "Reink" on 9/22!

    So, I'd say we still need *YOUR* logfiles, in this thread, in order to address *YOUR* question which started this thread. :-)





    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com

    Hi,

    I'm the original poster here under the name Janx444 and I started this thread after reading similar thread in wsus.info.
    (I need as much information as possible to solve my problem, sorry folks if this is confusing)
    In wsus.info forum, I'm using name janx and I'm not the starter of thread - I found it, when I search solution for my problem trough Google. So... I'm not "reink" :)
    So far thanks to You all for effort.

    rgds
    Sven
    Saturday, October 10, 2009 8:11 AM
  • Anything? I'm out of ideas..

    rgds
    Sven
    Tuesday, October 13, 2009 8:00 AM
  • It looks like we found the Policy/Agent conflict for our environemt.  We have the "Download missing COM components" policy enabled in our GPO (Computer Configuration -> Administrative Templates -> System), Disabling or setting to Not Configured, appears to be resolving the slowness/service hanging.

    We are still doing some testing, but so far, we are reliably able to fix/break it by changing that policy.

    • Proposed as answer by RogueSpear Tuesday, October 13, 2009 6:01 PM
    • Marked as answer by Sven J Tuesday, October 13, 2009 7:46 PM
    • Unmarked as answer by Sven J Tuesday, October 13, 2009 7:47 PM
    • Unproposed as answer by Sven J Tuesday, October 13, 2009 7:47 PM
    • Marked as answer by Sven J Tuesday, October 13, 2009 7:47 PM
    Tuesday, October 13, 2009 3:08 PM
  • Interesting! The delay could be a result of the system trying to verify the several COM modules that are used in the WUAgent. I'll see if I can reproduce that behavior on my system(s).
    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Tuesday, October 13, 2009 3:45 PM
  • It looks like we found the Policy/Agent conflict for our environemt.  We have the "Download missing COM components" policy enabled in our GPO (Computer Configuration -> Administrative Templates -> System), Disabling or setting to Not Configured, appears to be resolving the slowness/service hanging.

    We are still doing some testing, but so far, we are reliably able to fix/break it by changing that policy.


    I'm a little late to the party, but I discovered this thread today via Google.  I've been experiencing the exact same issue as described by others here.  I tried the above quoted change in group policy and suddenly everybody is rebooting in record time.  I haven't done thorough testing to see if there are any possible side effects from this seemingly innocuous GPO change, but I was desperate for a solution.

    I will post an update if I come across any issues.  Many thanks to mimicvii for the solution.  This has been dogging me for a couple of months now.

    Dave
    Tuesday, October 13, 2009 6:05 PM
  • Yeah, we've gone ahead and implimented this change for our workstations.  I figured since disabled/not configured is the default behaviour for Windows, it shouldn't hurt to set it back that way.

    Tuesday, October 13, 2009 6:12 PM
  • It looks like we found the Policy/Agent conflict for our environemt.  We have the "Download missing COM components" policy enabled in our GPO (Computer Configuration -> Administrative Templates -> System), Disabling or setting to Not Configured, appears to be resolving the slowness/service hanging.

    We are still doing some testing, but so far, we are reliably able to fix/break it by changing that policy.


    Thank You, thank You, thank You...
    First tests are succesful :)

    rgds
    Sven
    Tuesday, October 13, 2009 7:46 PM
  • No luck for me I'm afraid. The setting was already set to 'Not Configured'
    Wednesday, October 14, 2009 7:43 AM
  • No luck for me I'm afraid. The setting was already set to 'Not Configured'

    Did You check RSoP for specific client?
    I had to correct at least 2 policies. Default domain and OU.
    For some reasons, i had this settings enabled on both policies.
    Of course.. I don't know yet, is there any side effects that my clients could see...

    rgds
    Sven
    Wednesday, October 14, 2009 10:22 AM
  • No luck for me I'm afraid. The setting was already set to 'Not Configured'

    Did You check RSoP for specific client?
    I had to correct at least 2 policies. Default domain and OU.
    For some reasons, i had this settings enabled on both policies.
    Of course.. I don't know yet, is there any side effects that my clients could see...

    rgds
    Sven

    I did and I can't see anything. If I remove a computer from the domain and delete the local group policy and let it recreate the default group policy I still get the hang with the Automatic Updates service.

    So for me, unfortunately I don't think it is group policy related.
    Wednesday, October 14, 2009 10:50 AM
  • No luck for me I'm afraid. The setting was already set to 'Not Configured'

    Did You check RSoP for specific client?
    I had to correct at least 2 policies. Default domain and OU.
    For some reasons, i had this settings enabled on both policies.
    Of course.. I don't know yet, is there any side effects that my clients could see...

    rgds
    Sven

    I did and I can't see anything. If I remove a computer from the domain and delete the local group policy and let it recreate the default group policy I still get the hang with the Automatic Updates service.

    So for me, unfortunately I don't think it is group policy related.
    There's an important behavior of Group Policy and Administrative Templates that configure Registry-Based settings that must be considered here.

    The fact that a policy is currently "Not Configured" is not an authoritative indication that the setting is not in effect, and simply removing a machine from a policy or reconfiguring the policy will also have no effect if the setting still remains at "Not Configured".

    To be authoritative that the setting is not in force, you need to set the policy setting to DISABLED.

    Remember, an Administrative Setting creates a registry value. In this case it creates a registry value and marks it as enabled (dword:0x1, most likely). When that policy is reset to "Not Configured", the registry value is NOT reset -- it remains on the local system. Only if that policy setting is explicitly DISABLED will the registry value be reset to dword:0x0.

    The registry value is located in HKLM\Software\Policies\Microsoft\Windows\App Management

    Lawrence Garvin, M.S., MCITP:EA, MCDBA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Wednesday, October 14, 2009 1:58 PM
  • I checked the registry but the value isn't present. Infact the key App Management isn't even present. I set the Computer Policy and even the User policy to DISABLED on the download missing com components but it has made no difference.
    Wednesday, October 14, 2009 2:38 PM
  • I've seen that same behaviour with some settings where you have to explicitly define the setting in order to change it back to default.  However, for this particular setting, changing from Enabled to Not Configured actually did work for us.  I could see a potential issue where if perhaps a policy higher up the hierarchy (OU -> Domain -> Site -> Local) had this setting enabled, changing an OU level policy to Not Configured would have no effect.  So yeah, changing to Disabled would be the only way to know for sure, but even then, if something higher up is set to block override, that still may not work.
    Wednesday, October 14, 2009 2:48 PM
  • hello,

    i have this same problem in 400 xp clients. The only solution, for the slow log on, was to  put not configured in "Download missing COM components".

    As the solution for this problem found yet?

    Best regards


    IT
    Thursday, December 3, 2009 1:59 PM
  • hello,

    i have this same problem in 400 xp clients. The only solution, for the slow log on, was to  put not configured in "Download missing COM components".

    As the solution for this problem found yet?

    JC.. that *is* the solution. :-)

    The WUAgent has several COM DLL components. Enabling the check will cause a significant performance hit when using the WUAgent. Disabling the check resolves the issue.



    Lawrence Garvin, M.S., MCITP:EA, MCDBA, MCSA
    Principal/CTO, Onsite Technology Solutions, Houston, Texas
    Microsoft MVP - Software Distribution (2005-2009)
    My MVP Profile: http://mvp.support.microsoft.com/profile/Lawrence.Garvin
    My Blog: http://onsitechsolutions.spaces.live.com
    Thursday, December 3, 2009 3:26 PM
  • Some additional information on this:

    We have researched the issue internally and the problem is caused by a CoCreateInstance call being blocked by trying to download application code from AD when a call to InstallApplication is made. A sample thread stack:

    kd> knL50
     # ChildEBP RetAddr 
    00 f7c59c68 804dc0f7 nt!KiSwapContext+0x2e
    01 f7c59c74 804dc143 nt!KiSwapThread+0x46
    02 f7c59c9c 8056dd00 nt!KeWaitForSingleObject+0x1c2
    03 f7c59d50 804de7ec nt!NtRequestWaitReplyPort+0x63d
    04 f7c59d50 7c90e514 nt!KiFastCallEntry+0xf8
    05 022eebac 7c90daea ntdll!KiFastSystemCallRet
    06 022eebb0 77e7cac1 ntdll!NtRequestWaitReplyPort+0xc
    07 022eebfc 77e7a33e RPCRT4!LRPC_CCALL::SendReceive+0x228
    08 022eec08 77e7a36f RPCRT4!I_RpcSendReceive+0x24
    09 022eec1c 77ef4675 RPCRT4!NdrSendReceive+0x2b
    0a 022eeff8 77df3efc RPCRT4!NdrClientCall2+0x222
    0b 022ef00c 77df3eb2 ADVAPI32!RStartServiceW+0x1b
    0c 022ef04c 77e1dfda ADVAPI32!StartServiceW+0x1e
    0d 022ef094 77e1d7d7 ADVAPI32!Bind+0x95
    0e 022ef168 77566eb6 ADVAPI32!InstallApplication+0x20                 <==
    0f 022ef1ac 7752029d ole32!DownloadClass+0x4b
    10 022ef964 77500575 ole32!ICoCreateInstanceEx+0x440
    11 022ef98c 77500544 ole32!CComActivator::DoCreateInstance+0x28
    12 022ef9b0 775005b2 ole32!CoCreateInstanceEx+0x1e
    13 022ef9e0 5016f098 ole32!CoCreateInstance+0x37                  <==
    14 022efa10 5016f6b3 wuaueng!CoCreateDatastore+0x36
    15 022efb10 5016fb2a wuaueng!CSusDatastoreWrap::CreateCOMObject+0xe4
    16 022efb30 5017057e wuaueng!CSusDatastoreWrap::CreateStoreObject+0x68
    17 022efb50 501708c4 wuaueng!CSusDatastoreWrap::DoMethodEntry+0xb6
    18 022efb94 501104d0 wuaueng!CSusDatastoreWrap::GetSession+0x94
    19 022efbb8 500e61cf wuaueng!CAgentFeaturedUpdatesManager::Init+0xf2
    1a 022efbe4 500ce94c wuaueng!CAgentUpdateManager::Init+0xd6
    1b 022efc00 500ca8df wuaueng!CSusAgent::Init+0x51
    1c 022efe5c 500ca97c wuaueng!CSusClientGlobal::Init+0x207
    1d 022efe70 500ca050 wuaueng!CSusClientGlobal::StartSusClient+0x11
    1e 022eff18 500013f0 wuaueng!ServiceMain+0x195
    1f 022eff6c 010011cc wuauserv!ServiceMain+0xaf
    20 022effa0 77df354b svchost!ServiceStarter+0x9e
    21 022effb4 7c80b729 ADVAPI32!ScSvcctrlThreadA+0x12
    22 022effec 00000000 kernel32!BaseThreadStart+0x37

    If the application in question was not configured to be installed through GPO, the block is expected. Please refer to:
    http://msdn.microsoft.com/en-us/library/aa374307(VS.85).aspx

    For now, disabling the policy as mentioned at the top of this thread is the only workaround. If I get more information on this I will post an update here.


    Kind regards,

    \Rob

    Wednesday, December 9, 2009 9:41 AM
  • It is fine that problem could be solved by changing GPO. I have to say that Flags value mentioned above "Flags"=dword:000000016 is not correct, because is is longer than DWORD. And the key is not created. What is the meaning of these flags?  Anyway, dword:00000016 generates extended WIndowsUpdate.log
    Wednesday, December 23, 2009 12:50 PM
  • I've tried the things here and I'm having an issue.

    Basically, i've set the GPO setting for "Download missing COM components" to disabled and verified the machine has applied the said policy, but the registry entry (Remember, an Administrative Setting creates a registry value. In this case it creates a registry value and marks it as enabled (dword:0x1, most likely). When that policy is reset to "Not Configured", the registry value is NOT reset -- it remains on the local system. Only if that policy setting is explicitly DISABLED will the registry value be reset to dword:0x0.

    The registry value is located in HKLM\Software\Policies\Microsoft\Windows\App Management) doesn't exists and i'm still getting %100 CPU usage on SVCHOST (wuauclt). Thanks in advance for taking the time.

     

    Our work around for the moment has been to disable our WSUS policy, which is not good long term.

     

    Oh, I now have two customers for sure seeing this (125 nodes / 20 nodes). I imagine there are more, but it seems to behave differently on dual core machines (only maxing one core) and they are still able to work.

    Thursday, March 25, 2010 5:18 PM
  • It looks like we found the Policy/Agent conflict for our environemt.  We have the "Download missing COM components" policy enabled in our GPO (Computer Configuration -> Administrative Templates -> System), Disabling or setting to Not Configured, appears to be resolving the slowness/service hanging.

    We are still doing some testing, but so far, we are reliably able to fix/break it by changing that policy.


    Has anyone found any problems to have arisen as a result of setting that to "disabled"?
    Tuesday, March 30, 2010 3:12 PM
  • Per our discussion on another thread:

    I've checked the COM GP setting as indicated in the other thread and it's not the issue.  I've also checked the antivirus exclusions and we're explicitly excluding the .edb file in question.  I've tried pretty much every single thing I've found in every one of these threads and still no luck.

    Small mix of SP2/SP3 XP clients with 7.4 agents on WSUS3SP2 servers running 100% CPU on svchost.

    Tuesday, April 13, 2010 4:36 PM
  • Hi Todd

    I'm in the same boat as you on this one, did you have any success in resolving the issue?

    Regards

    Philip

    Thursday, August 19, 2010 4:18 PM