3 Replies Latest reply on Sep 18, 2017 12:35 AM by NDietz

    Windows 7 Provisioning task stuck on running for hours without continuing other provisioning tasks

    HermiM Apprentice

      Hi,

      Recently, For some reasons, I start facing issues with many provisioning tasks. Most of tasks keep displaying running but they stuck in an action without continuing the rest (not the same action for all taks).

       

      I tried to investigate the issue and that is what I found:

      in ldprovision (C:\windows\temp) :

      2017-09-07 08:43:37(2544-2548) ldProvision.exe:download prerequisite files OK

      2017-09-07 08:43:37(2544-2548) ldProvision.exe:Running in Daemon mode.

      2017-09-07 08:43:37(2544-2548) ldProvision.exe:Provision Mode = PROVISION_MODE_CORE_SID

      2017-09-07 08:43:53(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:53:53(2544-2548) ldProvision.exe:Web service call attempt:0. ExitCode:259

      2017-09-07 08:54:05(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:54:17(2544-2548) ldProvision.exe:Web service call attempt:1. ExitCode:1

      2017-09-07 08:54:27(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:54:48(2544-2548) ldProvision.exe:Web service call attempt:2. ExitCode:2

      2017-09-07 08:54:59(2544-2548) ldProvision.exe:Failed to call web service. exitCode=2

      2017-09-07 08:54:59(2544-2548) ldProvision.exe:Caught exception in main: code=80001500H, file=ProvisioningWebSvc.cpp, line=1080

      2017-09-07 08:54:59(2544-2548) ldProvision.exe:Call web service GetStatusString()

      2017-09-07 08:54:59(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:55:02(2544-2548) ldProvision.exe:Web service call attempt:0. ExitCode:1

      2017-09-07 08:55:09(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:55:10(2544-2548) ldProvision.exe:Web service call attempt:1. ExitCode:1

      2017-09-07 08:55:23(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:55:23(2544-2548) ldProvision.exe:Web service call attempt:2. ExitCode:1

      2017-09-07 08:55:29(2544-2548) ldProvision.exe:Failed to call web service. exitCode=1

      2017-09-07 08:55:29(2544-2548) ldProvision.exe:Call web service SetActionStatus()

      2017-09-07 08:55:29(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:55:32(2544-2548) ldProvision.exe:Web service call attempt:0. ExitCode:1

      2017-09-07 08:55:37(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:55:37(2544-2548) ldProvision.exe:Web service call attempt:1. ExitCode:1

      2017-09-07 08:55:48(2544-2548) ldProvision.exe:Calling Program:C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe  -b ncs -H"C:\ldprovisioning\header.txt" -o"C:\ldprovisioning\body.txt" -f"C:\ldprovisioning\result.xml" https://coreserver/LANDesk/ManagementSuite/Core/ProvisioningWebService/WebService.asmx

      2017-09-07 08:56:10(2544-2548) ldProvision.exe:Web service call attempt:2. ExitCode:2

      2017-09-07 08:56:19(2544-2548) ldProvision.exe:Failed to call web service. exitCode=2

      2017-09-07 08:56:19(2544-2548) ldProvision.exe:Provision GUI still found alive, waiting.

      2017-09-07 08:56:20(2544-2548) ldProvision.exe:Entering downloadbyproxy.

      2017-09-07 08:56:20(2544-2548) ldProvision.exe:Create process (C:\Program Files (x86)\LANDesk\Shared Files\httpclient.exe) with args (  -f "ldsleep.exe" http://coreserver/landesk/files/ldsleep.exe)

      2017-09-07 08:56:21(2544-2548) ldProvision.exe:Waiting for process result: 0.

      2017-09-07 08:56:21(2544-2548) ldProvision.exe:Process exit code:0

       

      So it seems that the client wasn't able to reach the provisioning web service.

       

      I go deeper and I checked log file under core server provisioning.log \\coreserver\ldlog\provisioning\ and I found some thing weired.

       

      VERBOSE ProvisioningWebService  9/7/2017 10:40:44 AM  : SetActionStatus (historyTaskIdn 5566, historyEntryIdn 549280, next 549281): state SUCCESS (last prov action done by the client which is installing a software)

      VERBOSE ProvisioningWebService  9/7/2017 10:40:45 AM  : SetActionStatus (historyTaskIdn 5566, historyEntryIdn 549281, next 549282): state REBOOTING (action 549281 which is a reboot)

       

      Now the client is booting up and contacting the core server to pull boot options (from winpe or from local hard drive) and to check if there is an ongoing provisioning task to which it is assigned. as you can see it tried many times (I didn't put all attempts)

       

      VERBOSE ProvisioningWebService  9/7/2017 10:41:34 AM  : >>  GetProvisioningBootOption, clientMacAddress=XXXXXXXXXXXX

      DEBUGGING ProvisioningWebService  9/7/2017 10:41:35 AM  : Succeed to GetBootOption.PreBoot=WindowsPE,SectionOrder=4,clientMacAddress=XXXXXXXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:41:35 AM  : << GetProvisioningBootOption, BootOption=64 for macaddress XXXXXXXXXXXX.

      VERBOSE ProvisioningWebService  9/7/2017 10:41:36 AM  : >>  GetProvisioningBootOption, clientMacAddress=XXXXXXXXXXXX

      DEBUGGING ProvisioningWebService  9/7/2017 10:41:36 AM  : Succeed to GetBootOption.PreBoot=WindowsPE,SectionOrder=4,clientMacAddress=XXXXXXXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:41:36 AM  : << GetProvisioningBootOption, BootOption=64 for macaddress XXXXXXXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:41:40 AM  : >>  GetProvisioningBootOption, clientMacAddress=XXXXXXXXXXXX

      DEBUGGING ProvisioningWebService  9/7/2017 10:41:40 AM  : Succeed to GetBootOption.PreBoot=WindowsPE,SectionOrder=4,clientMacAddress=XXXXXXXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:41:40 AM  : << GetProvisioningBootOption, BootOption=64 for macaddressXXXXXXXXXXXX.

       

       

      Once boot process is done the client will contact the core server to get the task xml describing provisinong tasks that were done and those that still waiting to be proceed.

       

      VERBOSE ProvisioningWebService  9/7/2017 10:44:02 AM  : Identifiers to use - Mac Address: True, Serial Number: True, AMT GUID: True

      VERBOSE ProvisioningWebService  9/7/2017 10:44:02 AM  :  Identifiers:

      VERBOSE ProvisioningWebService  9/7/2017 10:44:02 AM  :   MACAddress: XXXXXXXXXXXX -----> Bluetooth [email protected]

      VERBOSE ProvisioningWebService  9/7/2017 10:44:02 AM  :   MACAddress: A44CC8245A73 --> Ethernet [email protected]

      VERBOSE ProvisioningWebService  9/7/2017 10:44:02 AM  :   SerialNumber: XXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:44:03 AM  : Returning task XML

       

      Now the client computer should continue from the last provisioning task before reboot but that wasn't the case. I found out that the device computer start again to contact the core server to pull boot options

       

      VERBOSE ProvisioningWebService  9/7/2017 10:44:39 AM  : >>  GetProvisioningBootOption, clientMacAddress=XXXXXXXXXXXX

      DEBUGGING ProvisioningWebService  9/7/2017 10:44:39 AM  : Succeed to GetBootOption.PreBoot=WindowsPE,SectionOrder=4,clientMacAddress=XXXXXXXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:44:39 AM  : << GetProvisioningBootOption, BootOption=64 for macaddress XXXXXXXXXXXX

       

      After many attempts it receive again the same answer about task xml  !!!!

       

      DEBUGGING ProvisioningWebService  9/7/2017 10:54:14 AM  : GetTaskXmlInternal

      VERBOSE ProvisioningWebService  9/7/2017 10:54:14 AM  : Identifiers to use - Mac Address: True, Serial Number: True, AMT GUID: True

      VERBOSE ProvisioningWebService  9/7/2017 10:54:14 AM  :  Identifiers:

      VERBOSE ProvisioningWebService  9/7/2017 10:54:14 AM  :   MACAddress: XXXXXXXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:54:14 AM  :   MACAddress: XXXXXXXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:54:14 AM  :   SerialNumber: XXXXXXX

      VERBOSE ProvisioningWebService  9/7/2017 10:54:15 AM  : Returning task XML

       

      After 1 minutes I found these lines in the log file. I think that this is the reason why the task will remain active but without doing any thing.

       

      VERBOSE ProvisioningWebService  9/7/2017 10:55:32 AM  : SetActionStatus (historyTaskIdn -1, historyEntryIdn -1, next -1): state FAILED

      VERBOSE PHistoryEntry  9/7/2017 10:55:32 AM  : Unable to write to database. Problem with history task record Idn, Declared history task Idn='-1'. History entry's task Idn='0. Next history entry's task Idn='0

      ERROR ProvisioningWebService  9/7/2017 10:55:32 AM  : Unable to set the action status (historyTaskIdn -1, historyEntryIdn -1, next -1): Invalid history task.

      VERBOSE ProvisioningWebService  9/7/2017 10:55:37 AM  : SetActionStatus (historyTaskIdn -1, historyEntryIdn -1, next -1): state FAILED

      VERBOSE PHistoryEntry  9/7/2017 10:55:37 AM  : Unable to write to database. Problem with history task record Idn, Declared history task Idn='-1'. History entry's task Idn='0. Next history entry's task Idn='0

      ERROR ProvisioningWebService  9/7/2017 10:55:37 AM  : Unable to set the action status (historyTaskIdn -1, historyEntryIdn -1, next -1): Invalid history task.

       

      Do you guys have any idea about this issue and how we can fix it?

       

      we are using LDMS2016SU04

       

       

      Thanks in advance

        • 1. Re: Windows 7 Provisioning task stuck on running for hours without continuing other provisioning tasks
          phoffmann SupportEmployee

          Would probably help stating what version & service pack / service update level you're at as a starter for 10 .

           

          Also - if you're failing to talk with the PXE www-service, do you see anything interesting in the IIS Logs (i.e. - do you see *ANY* kind of pokes, or does traffic just magically stop?).

           

          Often run into those sorts of "mysterious" issues when there's DNS shenanigans going on, for instance (not SURE if that's in your case, but it may certainly not help)..

           

          <The client trying to re-connect to the WWW-service 50 times is "normal" - it seemed a sufficiently paranoid number to cope with bad networks & shenanigans >

           

          Another thing is to check IIS itself (resourcing, and fun stuff like that, if it stops being responsive). One way to give it a try to see if the IIS side of things can be helped along is runnign an "iisreset" (must be run as admin).#

           

          If that "magically cures" your issues, you may need to revise some of your IIS config (for instance). IIS is a complex beast .

           

          Worth a try as a simple "yes/no" at any rate.

          • 2. Re: Windows 7 Provisioning task stuck on running for hours without continuing other provisioning tasks
            HermiM Apprentice

            Hi phoffmann

             

            Thank you for your quick answer.

            I didn't understand all of your reply but I am going to try to answer some question:

            do you see anything interesting in the IIS logs ?

            --> I compare the IIS log related to a successful installed computer to the log related to a computer with that issue and I found that once the computer do a reboot it generated this HTTP request. This was done in the case of a computer successfully installed and after previous reboot in the case of computer with the issue that we are discussing (previous reboot = reboot before the error appears)

             

            [521105]2017-09-12 07:50:11 <core server ip> POST /incomingdata/postcgi.exe - 80 - <client IP>- - 202 0 0 203

            [521110]2017-09-12 07:50:11 <core server ip> POST /incomingdata/postcgi.exe - 80 - <client IP> - - 202 0 0 203

            [521119]2017-09-12 07:50:11 <core server ip> POST /incomingdata/postcgi.exe - 80 - <client IP> - - 202 0 0 187

             

            So as I explained the problem occurs in General after a reboot. So at this step no similar trafic will be generated and instead there is this weird HTTP Get (I can't understand what is its role)

            [532519]2017-09-12 07:57:36 <core server IP> GET /landesk/files/ldsleep.exe - 80 - <client IP> - - 200 0 0 703

             

            From the client side log file (ldprovision.log) I have the same log file mentioned in my first post with the same exception:

            2017-09-07 08:54:59(2544-2548) ldProvision.exe:Caught exception in main: code=80001500H, file=ProvisioningWebSvc.cpp, line=1080

             

             

            If you don't mind I have some question about your last answer:

            - what you mean by "DNS shenanigans"? and how it can cause this behavior?

            - what do you mean by this sentence "<The client trying to re-connect to the WWW-service 50 times is "normal" - it seemed a sufficiently paranoid number to cope with bad networks & shenanigans >"

             

            For IIS reset I made couple reboot to the LANDesk core server but the same issue still shows up.

             

             

            Thank you again for your help

            • 3. Re: Windows 7 Provisioning task stuck on running for hours without continuing other provisioning tasks
              NDietz Rookie

              Hi Hermi,

               

              >>VERBOSE PHistoryEntry  9/7/2017 10:55:37 AM  : Unable to write to database. Problem with history task record Idn, Declared history task Idn='-1'. History entry's task Idn='0. Next history entry's task Idn='0

              >>ERROR ProvisioningWebService  9/7/2017 10:55:37 AM  : Unable to set the action status (historyTaskIdn -1, historyEntryIdn -1, next -1): Invalid history task.

               

              This is a known issue in 2017.1 and was fixed with SU1.


              415349 Provisioning DB tables can get locked up in certain conditions

              See this post: PHistoryEntry - Unable to write to database

              According to your post, you still have 2016 running, maybe the issue sneaked into 2016 also. But it is pretty clear, if the provisioning tables get locked it will stuck.