none
SMSTSPostAction Not Working as Expected

    Question

  • Hey Everyone

    Ever since we moved to 1610 from 1602 (we skipped 1606) it seems that I'm not seeing the expected result from SMSTSPostAction which is set with a value of "cmd /c shutdown /r /t 0 /f" It runs but it seems to run before the task sequence has actually completed.

    How I've come to that conclusion: We've got MDT integrated in our SCCM solution and are using UDI wizards for our staff and student computer task sequences. Prior to upgrading to 1610 the task sequence would complete, skip past the "Report Summary" screen generated by MDT, reboot, and the systems would come up (getting group policy on the way), and get their PKI key. On the systems that we're forced to run Deep Freeze on they'd come up frozen (I've got a step at the end of the TS to freeze the computer on the next boot).

    Since going to 1610 we're seeing the reboot and then it comes up with the Report Summary screen. On frozen computers every time the systems boots it comes up with the summary screen. On systems that don't have Deep Freeze they won't get their PKI cert until they are manually rebooted one more time.

    Basically, I'm wondering if anyone else has been seeing this type of behavior and, if so, what they're doing to get around it/fix it.

    Tuesday, March 07, 2017 5:58 PM

Answers

  • I suggest that you add a delay to your reboot.

    cmd.exe /c timeout /t 15 & shutdown /r /t 0 /f

    My guess is that the reboot event fires off while the TS engine is still in the process of completing. It then thinks that the TS is still active and that this is one those reboots that are caused by some valid step. So, it saved the stated and resumed again after the reboot.

    • Marked as answer by Mike Horton Friday, March 10, 2017 11:04 PM
    Wednesday, March 08, 2017 10:43 PM

All replies

  • What does the SMSTS log file say about what the post action is? There should be a log line that looks like:

    "End program: cmd ..."

    Wednesday, March 08, 2017 12:02 AM
  • Thanks Kerwin

    I checked the log again to verify when I got into work this morning... It does have a line "End program: cmd /c shutdown /r /t 0 /f". It does a few other things after like looking if the ccmexec service is up and operational, sets the command line with the shutdown line, executes it according the the log, says it completed with an exit code of 0, does a time sync with the domain, resumes SCCM Client, uninstalls setup hook, removes three files from C:\Windows\system32, then has a line that just says "End program:", then successfully finalizes the logs to the log directory. This all happens in the span of close to a minute. I've put a couple of pauses in the task sequence and I'm about to image one of my test systems again so that I can look at the log in real time to see if it's actually finalized before the reboot happens.

    Wednesday, March 08, 2017 3:35 PM
  • I'm using only shutdown /r /f /t 0 as my post action and seen some variable results, sometimes it runs correctly sometimes it doesn't and I'm getting this annoying first-login prompt after the OSD: https://support.microsoft.com/fi-fi/help/2976660/first-logon-fails-with-the-universal-unique-identifier-uuid-type-is-not-supported

    Haven't checked the logs on the client. Running Windows 10 1607 + SCCM CB 1610.


    Wednesday, March 08, 2017 4:03 PM
  • Thanks Kerwin

    I checked the log again to verify when I got into work this morning... It does have a line "End program: cmd /c shutdown /r /t 0 /f". It does a few other things after like looking if the ccmexec service is up and operational, sets the command line with the shutdown line, executes it according the the log, says it completed with an exit code of 0, does a time sync with the domain, resumes SCCM Client, uninstalls setup hook, removes three files from C:\Windows\system32, then has a line that just says "End program:", then successfully finalizes the logs to the log directory. This all happens in the span of close to a minute. I've put a couple of pauses in the task sequence and I'm about to image one of my test systems again so that I can look at the log in real time to see if it's actually finalized before the reboot happens.

    As a test I changed the SMSTSPostAction to just notepad.exe to see what happens. This time in my smsts.log I've got two lines that say "End Program: notepad.exe" vs only the one line with the shutdown cmd in the previous log. I'm going to change the line from cmd /c shutdown to just shutdown.exe /r /t 0 /f and see if that makes a difference.
    Wednesday, March 08, 2017 5:47 PM
  • Running it with shutdown.exe /r /t 0 /f resulted in the same thing as originally in my smsts.log. So the reboot is happening but not writing it to the log and not after the TS officially finishes. It did the reboot then when it came back up I had the OSD Summary screen. The only steps after my TS Pause step are "Run OSD Results" and "Report Done" neither of which causes a reboot based on when I was using notepad.exe as the SMSTSPostAction.
    Wednesday, March 08, 2017 8:48 PM
  • I suggest that you add a delay to your reboot.

    cmd.exe /c timeout /t 15 & shutdown /r /t 0 /f

    My guess is that the reboot event fires off while the TS engine is still in the process of completing. It then thinks that the TS is still active and that this is one those reboots that are caused by some valid step. So, it saved the stated and resumed again after the reboot.

    • Marked as answer by Mike Horton Friday, March 10, 2017 11:04 PM
    Wednesday, March 08, 2017 10:43 PM
  • I'll give that a shot but it just seems so hit and miss. Out of the four times I've imaged one of my test machines today between testing different variations of commands for the SMSTSPostAction, twice the second to last line in the smsts.log has read "End program: <whatever the command is>" and the other two times it's just read "End program:" The last two times the PostAction command has just simply been "shutdown.exe /r /t 0 /f". The first time it worked as expected and the last time it didn't and the smsts.log reflects that.
    Wednesday, March 08, 2017 11:54 PM
  • The "End program:" will show multiple times. The important part is that when it shows up the first time in the log, it should be the command you entered. After that, it will always show as empty. So, please don't get too caught up on that.

    The first question is, does the TS always get the command that you give it? If so, then at least we can rule out any policy error.

    Second, will the delay work? Try a longer value (say 60 seconds). When you do this, while your delay is active, look at the task sequence log and see if the TS indeed completed or if it detected an unexpected reboot.

    Better yet, instead of us exchanging questions back and forth, you can just share the complete SMSTS log file.

    Thursday, March 09, 2017 12:52 AM
  • It always shows up the first time in the log and, from what I've seen today, if it doesn't show up the second time then the system will reboot and finish on the OSD Summary screen. I left two running when I left work tonight and just remoted into my console. Looking at the status messages in the console one completed properly, gotten its PKI cert via GPO, and is happy (which is what I'd expect to see). The other one's last status message was that that it had completed the task sequence and nothing after that. I can't seem to ping it which on our network means it's still on the guest network (we're running 802.1x) and hasn't flipped over to the student network (part of GPO).

    This was with a timeout of 15 seconds. I can try boosting it tomorrow to longer to see if I can get the logs after they've copied out of _SMSTaskSequence to CCM\Logs and before it reboots.

    Below is the ending portion of the smsts.log from the working machine:

    <![LOG[Request was successful.]LOG]!><time="18:17:45.093+420" date="03-08-2017" component="TSManager" context="" type="0" thread="2780" file="libsmsmessaging.cpp:9163">
    <![LOG[End program: cmd.exe /c timeout /t 15 & shutdown /r /t 0 /f]LOG]!><time="18:17:45.093+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="tsmanager.cpp:1069">
    <![LOG[Finalize logging request ignored from process 2776]LOG]!><time="18:17:45.093+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="tslogging.cpp:2106">
    <![LOG[Waiting for CcmExec service to be fully operational]LOG]!><time="18:17:45.093+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="utils.cpp:5241">
    <![LOG[CcmExec service is up and fully operational]LOG]!><time="18:17:45.093+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="utils.cpp:5246">
    <![LOG[Access handle will be read from _SMSTSActiveRequestHandle]LOG]!><time="18:17:45.093+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="tsmanagerutils.cpp:100">
    <![LOG[Access handle: {80EE84DA-DF22-4744-BBAB-FE7B7D49F10D}]LOG]!><time="18:17:45.093+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="tsmanagerutils.cpp:111">
    <![LOG[Attempting to release request using {80EE84DA-DF22-4744-BBAB-FE7B7D49F10D}]LOG]!><time="18:17:45.093+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="tsmanagerutils.cpp:119">
    <![LOG[CoCreateInstance succeeded]LOG]!><time="18:17:45.124+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="tsmanagerutils.cpp:133">
    <![LOG[pISoftwareExecutionRequestMgr->ReleaseRequest(ActiveRequestGUID), HRESULT=80004005 (e:\nts_sccm_release\sms\client\tasksequence\tsmanager\tsmanagerutils.cpp,136)]LOG]!><time="18:17:45.155+420" date="03-08-2017" component="TSManager" context="" type="0" thread="2780" file="tsmanagerutils.cpp:136">
    <![LOG[ReleaseRequest failed with error code 0x80004005]LOG]!><time="18:17:45.155+420" date="03-08-2017" component="TSManager" context="" type="3" thread="2780" file="tsmanagerutils.cpp:136">
    <![LOG[Task Sequence Manager could not release active TS request. code 80004005]LOG]!><time="18:17:45.155+420" date="03-08-2017" component="TSManager" context="" type="2" thread="2780" file="tsmanagerutils.cpp:166">
    <![LOG[Command line for extension .exe is "%1" %*]LOG]!><time="18:17:45.155+420" date="03-08-2017" component="TSManager" context="" type="0" thread="2780" file="commandline.cpp:229">
    <![LOG[Set command line: "cmd.exe" /c timeout /t 15 & shutdown /r /t 0 /f]LOG]!><time="18:17:45.155+420" date="03-08-2017" component="TSManager" context="" type="0" thread="2780" file="commandline.cpp:732">
    <![LOG[Executing command line: "cmd.exe" /c timeout /t 15 & shutdown /r /t 0 /f]LOG]!><time="18:17:45.155+420" date="03-08-2017" component="TSManager" context="" type="1" thread="2780" file="commandline.cpp:828">
    <![LOG[Process completed with exit code 0]LOG]!><time="18:17:45.218+420" date="03-08-2017" component="TSMBootstrap" context="" type="1" thread="2508" file="commandline.cpp:1124">
    <![LOG[Exiting with return code 0x00000000]LOG]!><time="18:17:45.218+420" date="03-08-2017" component="TSMBootstrap" context="" type="1" thread="2508" file="tsmbootstrap.cpp:1270">
    <![LOG[Process completed with exit code 0]LOG]!><time="18:17:45.233+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="commandline.cpp:1124">
    <![LOG[Task sequence completed 0x00000000]LOG]!><time="18:17:45.233+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="basesetuphook.cpp:1590">
    <![LOG[Resume SCCM Client.]LOG]!><time="18:17:45.233+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="basesetuphook.cpp:1264">
    <![LOG[Uninstalling Setup Hook]LOG]!><time="18:17:47.372+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="basesetuphook.cpp:1625">
    <![LOG[Removing setup hook from registry.]LOG]!><time="18:17:47.372+420" date="03-08-2017" component="OSDSetupHook" context="" type="0" thread="1064" file="vistasetuphook.cpp:143">
    <![LOG[Successfully removed C:\WINDOWS\system32\OSDGINA.DLL]LOG]!><time="18:17:47.372+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="basesetuphook.cpp:1321">
    <![LOG[Successfully removed C:\WINDOWS\system32\OSDSETUPHOOK.EXE]LOG]!><time="18:17:47.372+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="basesetuphook.cpp:1321">
    <![LOG[Successfully removed C:\WINDOWS\system32\_SMSOSDSetup]LOG]!><time="18:17:47.372+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="basesetuphook.cpp:1358">
    <![LOG[End program: cmd.exe /c timeout /t 15 & shutdown /r /t 0 /f]LOG]!><time="18:17:47.372+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="basesetuphook.cpp:1639">
    <![LOG[Successfully finalized logs to SMS client log directory from T:\CCM\Logs]LOG]!><time="18:17:47.434+420" date="03-08-2017" component="OSDSetupHook" context="" type="1" thread="1064" file="tslogging.cpp:1911">


    • Edited by Mike Horton Thursday, March 09, 2017 6:46 AM
    Thursday, March 09, 2017 6:45 AM
  • Can yo please share the SMSTS log file for the failure case?

    Friday, March 10, 2017 12:09 AM
  • I don't have a recent one, just one for a couple of days ago. I boosted the timeout to 120 seconds so that I could try to see if the TS completed before rebooting. Only problem there was that I was cmtrace, etc were being forced closed on me. I'm assuming it's because the TS was done. That said, if I just left everything running without breaking into the task sequence it seemed to work as I'd expect (system rebooted and got its PKI key from GPO). I need to do some further testing.
    Friday, March 10, 2017 4:31 PM
  • I've imaged two systems today three times each and it looks like the timeout fixed the problem. Both machines have gotten the PKI cert. I do have one of them that I've been imaging with Windows 10 that's failing to download policy after it gets its key but that's a separate issue and may just be that system. I've currently got the timeout set a 60 seconds. Thanks for your help Kerwin.
    Friday, March 10, 2017 11:04 PM
  • Hi Mike, we experienced the same problem. Actually the command runs twice. The first time is before task sequence is about to complete, and the second time is when the task sequence ends.

    We have a script that uninstalls SCCM client at the end of task sequence, so this breaks our uninstallation...

    Friday, April 21, 2017 2:26 PM