SCCM Scheduling – Failed to Execute Mandatory Program as Scheduled via SCCM

When I deploy a package via SCCM, there is two machines failing to execute a program as scheduled time.

I check two machines with IUIResourceMgr::IsMandatoryProgramPending Method, and the return value was 0 which means there is no pending even though they never kick off. (I am not sure if I should use this method in this case)

PolicyAgent.log, PolicyEvaluvator.log are same including the two machines. I didn't find any problem or difference there. This package doesn't have source file, so CAS.log and DataTransferServices.log are empty.

Package's commandline is "echo.>c:\temp\test_heartbeat.txt", and it is schedule to execute everyday at 1:15PM.

EXECMGR.log

First log (when it works) from normal machine

Raising event:

[SMS_CodePage(437), SMS_LocaleID(1033)]

instance of SoftDistProgramOfferReceivedEvent

{

AdvertisementId = "PRI218B3";

ClientID = "GUID:77a7d64a-b8cf-404c-90c8-d43d6aae8858";

DateTime = "20180815180645.947000+000";

MachineName = "######";

ProcessID = 10096;

SiteCode = "PRI";

ThreadID = 4040;
};

execmgr 8/15/2018 1:06:45 PM    4040 (0x0FC8)
Mandatory execution requested for program Test and advertisement PRI218B3   execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Creating mandatory request for advert PRI218B3, program Test, package PRI00BE0  execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

An existing MTC token was not supplied, using ExecutionRequest's Id as MTC token and this execution request is the owner of resultant MTC task. execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Request a MTC task for execution request of package PRI00BE0, program Test with request id: {8DBBEB96-5371-4897-AD24-950B563503D5}  execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Execution Request for advert PRI218B3 package PRI00BE0 program Test state change from NotExist to Ready execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

MTC task with id {8DBBEB96-5371-4897-AD24-950B563503D5}, changed state from 0 to 4  execmgr 8/15/2018 1:15:00 PM 9768 (0x2628)

Raising client SDK event for class CCM_Program, instance CCM_Program.PackageID="PRI00BE0",ProgramID="Test", actionType 1l, value , user NULL, session 4294967295l, level 0l, verbosity 30l  execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

MTC signaled SWD execution request with program id: Test, package id: PRI00BE0 for execution.   execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Sending ack to MTC for task with id: {8DBBEB96-5371-4897-AD24-950B563503D5} execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Executing program cmd.exe /c "echo.>c:\temp\test_heartbeat.txt" in Admin context    execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Execution Request for advert PRI218B3 package PRI00BE0 program Test state change from Ready to NotifyExecution execmgr  8/15/2018 1:15:00 PM    9768 (0x2628)

Raising client SDK event for class CCM_Program, instance CCM_Program.PackageID="PRI00BE0",ProgramID="Test", actionType 1l, value , user NULL, session 4294967295l, level 0l, verbosity 30l  execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Executing program as a script   execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Successfully prepared command line "C:\Windows\system32\cmd.exe" /c "echo.>c:\temp\test_heartbeat.txt"  execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Command line = "C:\Windows\system32\cmd.exe" /c "echo.>c:\temp\test_heartbeat.txt", Working Directory = C:\Windows\system32\    execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Running "C:\Windows\system32\cmd.exe" /c "echo.>c:\temp\test_heartbeat.txt" with 32bitLauncher  execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Created Process for the passed command line execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Raising event:

[SMS_CodePage(437), SMS_LocaleID(1033)]

instance of SoftDistProgramStartedEvent

{

AdvertisementId = "PRI218B3";

ClientID = "GUID:77a7d64a-b8cf-404c-90c8-d43d6aae8858";

CommandLine = "\\"C:\\\\Windows\\\\system32\\\\cmd.exe\\" /c \\"echo.>c:\\\\temp\\\\test\_heartbeat.txt\\"";

DateTime = "20180815181500.457000+000";

MachineName = "########";

PackageName = "PRI00BE0";

ProcessID = 10096;

ProgramName = "Test";

SiteCode = "PRI";

ThreadID = 9768;

UserContext = "NT AUTHORITY\\\\SYSTEM";

WorkingDirectory = "C:\\\\Windows\\\\system32\\\\";
};

execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)
Raised Program Started Event for Ad:PRI218B3, Package:PRI00BE0, Program: Test   execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Raising client SDK event for class CCM_Program, instance CCM_Program.PackageID="PRI00BE0",ProgramID="Test", actionType 1l, value NULL, user NULL, session 4294967295l, level 0l, verbosity 30l  execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

Program exit code 0 execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Looking for MIF file to get program status  execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Script for Package:PRI00BE0, Program: Test succeeded with exit code 0   execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Raising event:

[SMS_CodePage(437), SMS_LocaleID(1033)]

instance of SoftDistProgramCompletedSuccessfullyEvent

{

AdvertisementId = "PRI218B3";

ClientID = "GUID:77a7d64a-b8cf-404c-90c8-d43d6aae8858";

DateTime = "20180815181500.594000+000";

MachineName = "############";

PackageName = "PRI00BE0";

ProcessID = 10096;

ProgramName = "Test";

SiteCode = "PRI";

ThreadID = 31848;

UserContext = "NT AUTHORITY\\\\SYSTEM";
};

execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)
Raised Program Success Event for Ad:PRI218B3, Package:PRI00BE0, Program: Test   execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Execution is complete for program Test. The exit code is 0, the execution status is Success execmgr 8/15/2018 1:15:00 PM 31848 (0x7C68)

Raising client SDK event for class CCM_Program, instance CCM_Program.PackageID="PRI00BE0",ProgramID="Test", actionType 1l, value , user NULL, session 4294967295l, level 0l, verbosity 30l  execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

EvaluateRequestForExecution - Updated current running request   execmgr 8/15/2018 1:15:00 PM    9768 (0x2628)

MTC task with id {8DBBEB96-5371-4897-AD24-950B563503D5}, changed state from 4 to 5  execmgr 8/15/2018 1:15:00 PM 9768 (0x2628)

Raising client SDK event for class CCM_Program, instance CCM_Program.PackageID="PRI00BE0",ProgramID="Test", actionType 10l, value Result:TRUE ,SDKCallerId:, user NULL, session 4294967295l, level 0l, verbosity 30l    execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Requesting MTC to delete task with id: {8DBBEB96-5371-4897-AD24-950B563503D5}   execmgr 8/15/2018 1:15:00 PM 31848 (0x7C68)

MTC task with id: {8DBBEB96-5371-4897-AD24-950B563503D5} deleted successfully.  execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Raising client SDK event for class CCM_Program, instance CCM_Program.PackageID="PRI00BE0",ProgramID="Test", actionType 1l, value , user NULL, session 4294967295l, level 0l, verbosity 30l  execmgr 8/15/2018 1:15:00 PM    31848 (0x7C68)

Second log (when it doesn't work) from the two machines

Policy arrived for parent package PRI00BE0 program Test execmgr 8/15/2018 1:07:01 PM    12144 (0x2F70)

Raising client SDK event for class CCM_Program, instance CCM_Program.PackageID="PRI00BE0",ProgramID="Test", actionType 6l, value NULL, user NULL, session 4294967295l, level 0l, verbosity 30l  execmgr 8/15/2018 1:07:01 PM    12144 (0x2F70)

Raising event:

[SMS_CodePage(437), SMS_LocaleID(1033)]

instance of SoftDistProgramOfferReceivedEvent

{

AdvertisementId = "PRI218B3";

ClientID = "GUID:5350c852-6be1-4e6f-b6f2-bc688bfa00d2";

DateTime = "20180815180701.353000+000";

MachineName = "@@@@@@@@@@@@";

ProcessID = 16440;

SiteCode = "PRI";

ThreadID = 12144;
};

execmgr 8/15/2018 1:07:01 PM    12144 (0x2F70)

Please let me know if there is a part I sound vague.

Thank you for your help in advance.