2 Replies Latest reply on Apr 5, 2011 8:32 AM by AspenSkier

    provisioning fails immediately - would like to know why

    Specialist

      I've just recovered my core from a bout of bad patches and for the first time in many months I have been able to use provisioning end to end without an error; specifically I have used PXE to boot a group of machines into WinPE where I select WinPE Provisioning and then run them through a lengthy Windows 7 deployment process.

       

      So this was all great, but now that I have the machines up and running I can't run other provisioning tasks against them; the provisioning steps fail immediately.  I'd like to know why.

       

       

       

      Here is what I am trying to do:

       

      I have a group of Win7 Pro 64-bit machines, all are alike, and I have just used provisioning to get the Win7 image down to them.  They have all been configured appropriately and I can use the Win7 OS; they appear to work just fine.

       

      ...now I am trying to run another provisioning task against them which applies a bios configuration and a bios password.  I am selecting these machines to run the provisioning task from the Win7 OS.  When I do this and tell the task to START NOW, I observe the machines moving into the ACTIVE part of the schedule task, but then almost immediately they get dumped in FAILED.  Sometimes when I try to do this against a single machine I notice that the scheduled task shows 1 active and 1 failed particiapant; this is when there is only 1 machine in the task...evidence that the task is failing immediately before it ever starts???  In any event the clients never show any hint of participating in a provisioning task.

       

      When I look at the details for any given FAILED machine I see a result of NOT SPECIFIED and a return code of 0, or ZERO.  If I select PROVISIONING HISTORY for the failed client I end up staring at a blank provisioning template...no details because there are no actions listed for it.  If I get out of the scheduled tasks area and select PROVISIONING HISTORY from the actual client where it is found in NETWORK VIEW, I then see that my attempts to provision the bios on that computer are NOT listed in the provisioning history...it will instead show the most recent task which I actually was able to witness.

       

      From the console I can remote control any of these failed machines and I can run inventory update requests against them.  All other evidence shows that these agents are playing according to the rules...its only when I attempt to run a provisioning task against them that they refuse to play.

       

      any thoughts on where I should begin to troubleshoot this problem?

        • 1. Re: provisioning fails immediately - would like to know why
          Apprentice

          Maybe the provisioning scheduler failed to generate the locked template.

          This usually happen when it can't find scripts, packages or package files.

           

          Please have a look at prov_schedule.exe.log.

           

          HTH,

           

          Jary Busato

          • 2. Re: provisioning fails immediately - would like to know why
            Specialist

            thanks Jary,

             

             

            selected results from the PROV_SCHEDULE.EXE.LOG file:

             

            Here are some results that I picked out from two weeks ago that show the variety of messages that can be found.  I am unable to correlate these entries to anything in the console because I don't know where to find the task ID and because the affected clients don't report these provisioning tasks in their provisioning history...

             

             

            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Reading task information from the database
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, got task status WORKING
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Database read for task data appears to have succeeded
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Reading task configuration info from the database
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, got task status WORKING
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Database read for task config data appears to have succeeded
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Reading task information from the database
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, got task status WORKING
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Database read for task data appears to have succeeded
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Reading task information from the database
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, got task status WORKING
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Database read for task data appears to have succeeded
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : template:1067,Freezing template succeeded.
            03/25/2011 09:11:46 INFO  4428:1     RollingLog : LDTaskIdn: 1015, Updating task configuration with the template idn: 1077
            03/25/2011 09:11:48 INFO  4428:1     RollingLog : Prod(templateIdn:1077), deviceIdn:1235, IP:172.16.4.90, This is a Windows box
            03/25/2011 09:11:50 INFO  4428:1     RollingLog : Prod(templateIdn:1077), deviceIdn:1235, IP:172.16.4.90, adding AHS2730-MATH08 (172.16.4.90) to queue
            03/25/2011 09:11:51 INFO  4428:1     RollingLog : Prod(templateIdn:1077), deviceIdn:1241, IP:172.16.4.73, This is a Windows box
            03/25/2011 09:11:52 INFO  4428:1     RollingLog : Prod(templateIdn:1077), deviceIdn:1241, IP:172.16.4.73, adding AHS2730-MATH09 (172.16.4.73) to queue
            03/25/2011 09:11:52 INFO  4428:1     RollingLog : Prod(templateIdn:1077), deviceIdn:1253, IP:172.16.4.78, This is a Windows box
            03/25/2011 09:11:54 INFO  4428:1     RollingLog : Prod(templateIdn:1077), deviceIdn:1253, IP:172.16.4.78, adding AHS2730-MATH10 (172.16.4.78) to queue
            03/25/2011 09:11:54 INFO  4428:1     RollingLog : Prod(templateIdn:1077), prodding 3 devices
            03/25/2011 09:11:54 INFO  4428:1     RollingLog : Prod(templateIdn:1077), device:AHS2730-MATH10, IP:172.16.4.78, target device has been successfully prodded
            03/25/2011 09:11:54 INFO  4428:1     RollingLog : Prod(templateIdn:1077), device:AHS2730-MATH09, IP:172.16.4.73, target device has been successfully prodded
            03/25/2011 09:11:55 INFO  4428:1     RollingLog : Prod(templateIdn:1077), device:AHS2730-MATH08, IP:172.16.4.90, target device has been successfully prodded
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Reading task information from the database
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, got task status WORKING
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Database read for task data appears to have succeeded
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Reading task configuration info from the database
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, got task status WORKING
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Database read for task config data appears to have succeeded
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Reading task information from the database
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, got task status WORKING
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Database read for task data appears to have succeeded
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Reading task information from the database
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, got task status WORKING
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Database read for task data appears to have succeeded
            03/25/2011 09:19:35 INFO  2864:1     RollingLog : LDTaskIdn: 994, Updating task configuration with the template idn: 1055
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Reading task information from the database
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, got task status WORKING
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Database read for task data appears to have succeeded
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Reading task configuration info from the database
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, got task status WORKING
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Database read for task config data appears to have succeeded
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Reading task information from the database
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, got task status WORKING
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Database read for task data appears to have succeeded
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Reading task information from the database
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, got task status WORKING
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Database read for task data appears to have succeeded
            03/25/2011 09:19:56 INFO  5712:1     RollingLog : LDTaskIdn: 994, Updating task configuration with the template idn: 1055
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Reading task information from the database
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, got task status WORKING
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Database read for task data appears to have succeeded
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Reading task configuration info from the database
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, got task status WORKING
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Database read for task config data appears to have succeeded
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Reading task information from the database
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, got task status WORKING
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Database read for task data appears to have succeeded
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Reading task information from the database
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, got task status WORKING
            03/25/2011 09:33:48 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Database read for task data appears to have succeeded
            03/25/2011 09:33:49 INFO  1244:1     RollingLog : template:1078,Template is not flattened, will attempt to flatten.
            03/25/2011 09:33:55 INFO  1244:1     RollingLog : template:1078,Flattening template succeeded, new template idn = 1079
            03/25/2011 09:33:56 INFO  1244:1     RollingLog : template:1078, template:1079,Freezing template succeeded.
            03/25/2011 09:33:56 INFO  1244:1     RollingLog : LDTaskIdn: 1018, Updating task configuration with the template idn: 1079
            03/25/2011 09:33:59 INFO  1244:1     RollingLog : Prod(templateIdn:1079), deviceIdn:960, IP:172.16.201.27, This is a Windows box
            03/25/2011 09:34:41 INFO  1244:1     RollingLog : Prod(templateIdn:1079), deviceIdn:960, IP:172.16.201.27, RemoteExec failed creating directory:  rv 2147485451 from [cmd][/C mkdir c:\ldprovisioning]
            03/25/2011 09:34:41 INFO  1244:1     RollingLog : Prod(templateIdn:1079), prodding 0 devices
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Reading task information from the database
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, got task status WORKING
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Database read for task data appears to have succeeded
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Reading task configuration info from the database
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, got task status WORKING
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Database read for task config data appears to have succeeded
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Reading task information from the database
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, got task status WORKING
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Database read for task data appears to have succeeded
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Reading task information from the database
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, got task status WORKING
            03/25/2011 09:35:13 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Database read for task data appears to have succeeded
            03/25/2011 09:35:14 INFO  6232:1     RollingLog : template:1067,Freezing template succeeded.
            03/25/2011 09:35:14 INFO  6232:1     RollingLog : LDTaskIdn: 1019, Updating task configuration with the template idn: 1080

             

             

             

            Here are three entries from today; three separate tasks created from the same template:

             

            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Reading task information from the database
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, got task status WORKING
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Database read for task data appears to have succeeded
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Reading task configuration info from the database
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, got task status WORKING
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Database read for task config data appears to have succeeded
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Reading task information from the database
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, got task status WORKING
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Database read for task data appears to have succeeded
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Reading task information from the database
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, got task status WORKING
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Database read for task data appears to have succeeded
            04/05/2011 08:31:57 INFO  756:1     RollingLog : LDTaskIdn: 1045, Updating task configuration with the template idn: 1109
            04/05/2011 08:33:05 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Reading task information from the database
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, got task status WORKING
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Database read for task data appears to have succeeded
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Reading task configuration info from the database
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, got task status WORKING
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Database read for task config data appears to have succeeded
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Reading task information from the database
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, got task status WORKING
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Database read for task data appears to have succeeded
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Reading task information from the database
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, got task status WORKING
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Database read for task data appears to have succeeded
            04/05/2011 08:33:06 INFO  3864:1     RollingLog : LDTaskIdn: 1034, Updating task configuration with the template idn: 1098
            04/05/2011 08:35:06 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Reading task information from the database
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, got task status WORKING
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Database read for task data appears to have succeeded
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Reading task configuration info from the database
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, got task status WORKING
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Database read for task config data appears to have succeeded
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Reading task information from the database
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, got task status WORKING
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Database read for task data appears to have succeeded
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Reading task information from the database
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, got task status WORKING
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Database read for task data appears to have succeeded
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : template:1067,Freezing template succeeded.
            04/05/2011 08:35:07 INFO  4328:1     RollingLog : LDTaskIdn: 1069, Updating task configuration with the template idn: 1111

             

             

            I think your idea about LDMS not locking the templates was a good idea; but I don't see evidence for this in the latter entries from today.  I was able to find several entries saying the FREEZING was successful.  The only failure here is the attempt to make a directory on C:

             

            03/25/2011 09:34:41 INFO  1244:1     RollingLog : Prod(templateIdn:1079), deviceIdn:960, IP:172.16.201.27, RemoteExec failed creating directory:  rv 2147485451 from [cmd][/C mkdir c:\ldprovisioning]

             

            I'm not sure which task this was but I can't recreate this entry today so I'm thinking it was something else.

             

            I've even tried to run a shutdown task that has previously worked...it just performs a remote file execute of PSSHUTDOWN.EXE which is already on the machine...I get a very similar entry for it:

             

             

            04/05/2011 08:46:52 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Reading task information from the database
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, got task status WORKING
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Database read for task data appears to have succeeded
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Reading task configuration info from the database
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, got task status WORKING
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Database read for task config data appears to have succeeded
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Reading task information from the database
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, got task status WORKING
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Database read for task data appears to have succeeded
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Reading task information from the database
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, got task status WORKING
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Database read for task data appears to have succeeded
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : template:570,Freezing template succeeded.
            04/05/2011 08:46:53 INFO  2772:1     RollingLog : LDTaskIdn: 1070, Updating task configuration with the template idn: 1112

             

             

            I'm not sure where to go with this because the log seems to report that all is well...