Did some more testing.
Another post talked about adding a vbscript delay to the execution of their task sequences. This got me thinking about timing issues. I think I'm onto something.. I added an 'Run Command Line' task consisting of
'cmd /c ping -n 301 127.0.0.1' so we'd get a 5 minute delay before running the failing Install Application task. This proved useful for troubleshooting. Since you can open multiple log files with CMTrace with a merged view, I did just that.
In LocationServices.log we can see that the system is unable to determine which MP to use...
<![LOG[No pending site assignments]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="lsad.cpp:3499">
<![LOG[LSRefreshSecuritySettings]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="lssecurity.cpp:4736">
<![LOG[Local Machine is joined to an AD domain]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="lsad.cpp:714">
<![LOG[No INF MP available]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:2325">
<![LOG[LSGetLookupMP: Unable to find any lookup MP(s)]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lsad.cpp:2485">
<![LOG[Failed to refresh security settings over MP with error 0x80004005.]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lsad.cpp:5052">
<![LOG[No security settings update detected.]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lssecurity.cpp:5070">
<![LOG[No INF MP available]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:2325">
<![LOG[LSGetLookupMP: Unable to find any lookup MP(s)]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lsad.cpp:2485">
<![LOG[Failed to refresh Site Signing Certificate over MP with error 0x80004005.]LOG]!><time="10:15:27.770+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lsad.cpp:4935">
<![LOG[Refreshing Site Signing Certificate over HTTP]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lssecurity.cpp:1286">
<![LOG[Failed to refresh Site Signing Certificate over HTTP with error 0x8000000a.]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lssecurity.cpp:1368">
<![LOG[No INF MP available]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:2325">
<![LOG[LSGetLookupMP: Unable to find any lookup MP(s)]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lsad.cpp:2485">
<![LOG[Unable to retrieve compatible MP(s) from AD]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:2687">
<![LOG[Failed to retrieve Default Management Points from lookup MP(s)]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lsad.cpp:2746">
<![LOG[Using default DNS suffix domain.tld]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:3244">
<![LOG[Attempting to retrieve default management points from DNS]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:3253">
<![LOG[Found DNS record of cmpri-00-0.domain.tld port 80]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:3299">
<![LOG[Default Management Points from DNS:]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsutils.h:205">
<![LOG[Name: 'cmpri-00-0.domain.tld' HTTPS: 'N' ForestTrust: 'N']LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsutils.h:211">
<![LOG[Persisting the default management points in WMI]LOG]!><time="10:15:27.786+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:3974">
<![LOG[Current AD forest name is domain.tld, domain name is domain.tld]LOG]!><time="10:15:27.802+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:842">
<![LOG[LSGetManagementPointsForSiteFromManagementPoint: Client is on Internet, skipping Intranet MP list request.]LOG]!><time="10:15:27.817+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lssecurity.cpp:5824">
<![LOG[LSUpdateInternetManagementPoints]LOG]!><time="10:15:27.817+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:2853">
<![LOG[Current AD site of machine is SWP-Site-00]LOG]!><time="10:15:27.817+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:770">
<![LOG[DhcpGetOriginalSubnetMask entry point is supported.]LOG]!><time="10:15:27.817+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:117">
<![LOG[Begin checking Alternate Network Configuration]LOG]!><time="10:15:27.817+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:1095">
<![LOG[Finished checking Alternate Network Configuration]LOG]!><time="10:15:27.817+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:1172">
<![LOG[Adapter {69C7E4D7-9182-4CB0-A6DD-CE8BC4F7078C} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.833+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Adapter {2637B3BB-C058-4661-A749-AF659077517E} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.833+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Adapter {E52E2179-C2AF-4E03-9F5B-B662115D6865} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.833+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Obtained 2 IPv4 addresses.]LOG]!><time="10:15:27.833+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:469">
<![LOG[Sending message to endpoint 'raw:httpsync:cmpri-00-0.domain.tld:MP_LocationManager']LOG]!><time="10:15:27.833+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="lssecurity.cpp:5528">
<![LOG[Failed to send management point list Location Request Message to cmpri-00-0.domain.tld]LOG]!><time="10:15:27.880+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lssecurity.cpp:5558">
<![LOG[LSUpdateInternetManagementPoints: Failed to retrieve internet MPs from MP cmpri-00-0.domain.tld with error 0x80004005, retaining previous list.]LOG]!><time="10:15:27.880+420" date="03-31-2014" component="LocationServices" context="" type="2" thread="2884" file="lsad.cpp:2884">
<![LOG[Persisted Default Management Point Locations locally]LOG]!><time="10:15:27.880+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="2884" file="lsad.cpp:4068">
<![LOG[DHCP entry points already initialized.]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:75">
<![LOG[Begin checking Alternate Network Configuration]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:1095">
<![LOG[Policy indicates that encryption is disabled. Encryption info will not be refreshed.]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2552" file="lssecurity.cpp:4473">
<![LOG[Successfully executed task to refresh encryption certificate info.]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2552" file="lsutils.cpp:2474">
<![LOG[Finished checking Alternate Network Configuration]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:1172">
<![LOG[Adapter {69C7E4D7-9182-4CB0-A6DD-CE8BC4F7078C} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Adapter {2637B3BB-C058-4661-A749-AF659077517E} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Adapter {E52E2179-C2AF-4E03-9F5B-B662115D6865} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Obtained 2 IPv4 addresses.]LOG]!><time="10:15:27.911+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:469">
<![LOG[DHCP entry points already initialized.]LOG]!><time="10:15:27.926+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:75">
<![LOG[Begin checking Alternate Network Configuration]LOG]!><time="10:15:27.926+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:1095">
<![LOG[Finished checking Alternate Network Configuration]LOG]!><time="10:15:27.926+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:1172">
<![LOG[Adapter {69C7E4D7-9182-4CB0-A6DD-CE8BC4F7078C} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.926+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Adapter {2637B3BB-C058-4661-A749-AF659077517E} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.926+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Adapter {E52E2179-C2AF-4E03-9F5B-B662115D6865} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:15:27.926+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:436">
<![LOG[Obtained 2 IPv4 addresses.]LOG]!><time="10:15:27.926+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="ccmiputil.cpp:469">
<![LOG[The client version is compatible with the MP for Application Catalog.]LOG]!><time="10:15:27.926+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="lssecurity.cpp:5417">
<![LOG[Registered for changes to reg key Software\Microsoft\SMS\Mobile Client.]LOG]!><time="10:15:27.942+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="2884" file="lsmaintenancetask.cpp:398">
The task sequence continues on and begins to run ping at 10:15:34 ... We can see this in
smsts.log
<![LOG[Start executing an instruction. Instruction name: WAIT FOR 5 MINUTES. Instruction pointer: 159]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="1" thread="2276" file="engine.cxx:116">
<![LOG[Set a global environment variable _SMSTSCurrentActionName=WAIT FOR 5 MINUTES]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="executionenv.cxx:668">
<![LOG[Set a global environment variable _SMSTSNextInstructionPointer=159]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="executionenv.cxx:668">
<![LOG[Set a local default variable SMSTSDisableWow64Redirection]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="executionenv.cxx:700">
<![LOG[Set a local default variable _SMSTSRunCommandLineAsUser]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="executionenv.cxx:700">
<![LOG[Set a global environment variable _SMSTSLogPath=C:\Windows\CCM\Logs\SMSTSLog]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="executionenv.cxx:668">
<![LOG[Expand a string: smsswd.exe /run: cmd /c ping -n 301 127.0.0.1]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="executionenv.cxx:782">
<![LOG[Expand a string: ]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="executionenv.cxx:782">
<![LOG[Command line for extension .exe is "%1" %*]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="commandline.cpp:228">
<![LOG[Set command line: smsswd.exe /run: cmd /c ping -n 301 127.0.0.1]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="commandline.cpp:731">
<![LOG[Start executing the command line: smsswd.exe /run: cmd /c ping -n 301 127.0.0.1]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="1" thread="2276" file="instruction.cxx:722">
<![LOG[!--------------------------------------------------------------------------------------------!]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="1" thread="2276" file="instruction.cxx:751">
<![LOG[Expand a string: WinPEandFullOS]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="0" thread="2276" file="executionenv.cxx:782">
<![LOG[Executing command line: smsswd.exe /run: cmd /c ping -n 301 127.0.0.1]LOG]!><time="10:15:34.182+420" date="03-31-2014" component="TSManager" context="" type="1" thread="2276" file="commandline.cpp:827">
<![LOG[[ smsswd.exe ]]LOG]!><time="10:15:34.213+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="main.cpp:289">
<![LOG[PackageID = '']LOG]!><time="10:15:34.213+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="main.cpp:318">
<![LOG[BaseVar = '', ContinueOnError='']LOG]!><time="10:15:34.213+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="main.cpp:319">
<![LOG[ProgramName = 'cmd /c ping -n 301 127.0.0.1']LOG]!><time="10:15:34.213+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="main.cpp:320">
<![LOG[SwdAction = '0001']LOG]!><time="10:15:34.213+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="main.cpp:321">
<![LOG[Set command line: Run command line]LOG]!><time="10:15:34.213+420" date="03-31-2014" component="InstallSoftware" context="" type="0" thread="3268" file="commandline.cpp:731">
<![LOG[Working dir 'not set']LOG]!><time="10:15:34.213+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:546">
<![LOG[Executing command line: Run command line]LOG]!><time="10:15:34.213+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="commandline.cpp:827">
<![LOG[]LOG]!><time="10:15:34.494+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Pinging 127.0.0.1 with 32 bytes of data:]LOG]!><time="10:15:34.494+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:34.494+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:35.290+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:36.350+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:37.410+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:38.470+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:39.529+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:40.589+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:41.384+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:15:42.444+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
This gives us a good reference for if anything happens while the ping is ticking away with one entry every second. Something happens ~107 seconds later at
10:17:21 in LocationServices.log
<![LOG[Current AD site of machine is SWP-Site-00]LOG]!><time="10:17:21.541+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsad.cpp:770">
<![LOG[Force AD refresh at network change event handler.]LOG]!><time="10:17:21.572+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="lsnetworkchangetask.cpp:71">
<![LOG[System is not in quarantine state.]LOG]!><time="10:17:21.572+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="lsnapinteraction.cpp:40">
<![LOG[LSGetLookupMPFromRegistry: Successfully retrieved MP [CMPRI-00-0.SD67.EDU] from Registry]LOG]!><time="10:17:21.588+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="lsad.cpp:2532">
<![LOG[Retrieved MP [CMPRI-00-0.SD67.EDU] from Registry]LOG]!><time="10:17:21.603+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsad.cpp:2344">
<![LOG[Attempting to retrieve lookup MP(s) from AD]LOG]!><time="10:17:21.603+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsad.cpp:2351">
<![LOG[Performing AD query: '(&(ObjectCategory=mSSMSManagementPoint)(mSSMSDefaultMP=TRUE)(mSSMSSiteCode=PEN))']LOG]!><time="10:17:21.728+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="lsad.cpp:656">
<![LOG[OperationalXml '<ClientOperationalSettings><Version>5.00.7958.1000</Version><SecurityConfiguration><SecurityModeMask>0</SecurityModeMask><SecurityModeMaskEx>224</SecurityModeMaskEx><HTTPPort>80</HTTPPort><HTTPSPort>443</HTTPSPort><CertificateStoreName></CertificateStoreName><CertificateIssuers></CertificateIssuers><CertificateSelectionCriteria></CertificateSelectionCriteria><CertificateSelectFirstFlag>1</CertificateSelectFirstFlag><SiteSigningCert>308202F0308201D8A00302010202104808A4CFB36476924F1CECEE04A03D06300D06092A864886F70D01010B05003016311430120603550403130B53697465205365727665723020170D3132303731363136333633385A180F32313132303632333136333633385A3016311430120603550403130B536974652053657276657230820122300D06092A864886F70D01010105000382010F003082010A0282010100A3326560ECEC00FAAF8481A47D52768A3D3EEB0CA38AC039877860672BE159F88D1447F6C14BAEBBD9F4F924EDB626899497216963B9F5CB580A247544CD714AF837EC40DECA71925568F2DBD3C4A247F3929BEBC4D82894BE0DF8664C691027B335CB6924B604587508FA1354B5A8F352F3CAA72EC3078058B592DA5F12B8EDC858E5AE213CDED0A82C6D226600CB341530470E0AF10BA2C608C4054E40F5A65C2EB02AC71D3D4B094AB3CC2EC886426841C18B1A596EEC640D519A7BAF6220F598E694010CE44349F2128D0EFC52957B213186CAA4C58257E3FF1A6A6A2CA469C8E08E800EEB8C4F6059BCEAAA6217AA0894B5FD6CBA261B6E64D4E62F57510203010001A3383036301E0603551D11041730158213434D5052492D30302D302E736436372E65647530140603551D25040D300B06092B060104018237650B300D06092A864886F70D01010B05000382010100654EA9E0EA7B4DF6F7A7C66046F3FC75CF68B18502C8FD2473834FDB36BC4A776394143DC786E01EB99EE363FF61FA6A7990405DB14BBCD051FC0E6803010BD5CE2B2219952348DAB313B2A6D467AB80717F82D01752A5902971AB15DF6A44F41F3549C1E7A9047529EA05DB614A7C1ED7C94094065DDC3C651F1379B46C272992703AA787350747232633147E20BA61A185A034B793BCDB58FC5CC80D6F6AC4B73A87F4F18DC3D0335A31AB5129471FC54C8A7E919163A72EFAB1F6E6CF5A976259687B18027D97FC8D78B9A514F9392D94569B2CC3349BD546B8886B3A03C50F72E14D02D46BD51C7DD9315F7FACB06B21FE8D20A9DF788875CD959E9D649A</SiteSigningCert></SecurityConfiguration><RootSiteCode>SWP</RootSiteCode><CCM> <CommandLine>SMSSITECODE=AUTO FSP=CMPRI-00-0</CommandLine> </CCM><FSP> <FSPServer>CMPRI-00-0.domain.tld</FSPServer> </FSP><Capabilities SchemaVersion ="1.0"><Property Name="SSLState" Value="0" /></Capabilities><Domain Value="domain.tld" /><Forest Value="domain.tld" /></ClientOperationalSettings>']LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="lsadcache.cpp:236">
<![LOG[The MP name retrieved is 'CMPRI-00-0.domain.tld' with version '7958' and capabilities '<Capabilities SchemaVersion="1.0"><Property Name="SSLState" Value="0"/></Capabilities>']LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsadcache.cpp:334">
<![LOG[MP 'CMPRI-00-0.domain.tld' is compatible]LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsadcache.cpp:339">
<![LOG[Retrieved 1 MP records from AD for site 'PEN']LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="lsadcache.cpp:287">
<![LOG[Lookup Management Points from AD:]LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsutils.h:205">
<![LOG[Name: 'CMPRI-00-0.domain.tld' HTTPS: 'N' ForestTrust: 'N']LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsutils.h:211">
<![LOG[Retrieved lookup MP(s) from AD]LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsad.cpp:2377">
<![LOG[Default Management Points from AD:]LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsutils.h:205">
<![LOG[Name: 'CMPRI-00-0.domain.tld' HTTPS: 'N' ForestTrust: 'N']LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsutils.h:211">
<![LOG[Persisting the default management points in WMI]LOG]!><time="10:17:21.915+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsad.cpp:3974">
<![LOG[Current AD site of machine is SWP-Site-00]LOG]!><time="10:17:21.946+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsad.cpp:770">
<![LOG[DHCP entry points already initialized.]LOG]!><time="10:17:21.946+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="ccmiputil.cpp:75">
<![LOG[Begin checking Alternate Network Configuration]LOG]!><time="10:17:21.946+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="ccmiputil.cpp:1095">
<![LOG[Finished checking Alternate Network Configuration]LOG]!><time="10:17:21.946+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="ccmiputil.cpp:1172">
<![LOG[Adapter {69C7E4D7-9182-4CB0-A6DD-CE8BC4F7078C} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:17:21.946+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="ccmiputil.cpp:436">
<![LOG[Adapter {2637B3BB-C058-4661-A749-AF659077517E} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:17:21.946+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="ccmiputil.cpp:436">
<![LOG[Adapter {E52E2179-C2AF-4E03-9F5B-B662115D6865} is DHCP enabled. Checking quarantine status.]LOG]!><time="10:17:21.946+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="ccmiputil.cpp:436">
<![LOG[Sending message to endpoint 'raw:httpsync:CMPRI-00-0.domain.tld:MP_LocationManager']LOG]!><time="10:17:21.946+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="lssecurity.cpp:5528">
<![LOG[Default CSP is Microsoft Enhanced RSA and AES Cryptographic Provider]LOG]!><time="10:17:22.009+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="ccmutillib.cpp:1363">
<![LOG[Default CSP Type is 24]LOG]!><time="10:17:22.009+420" date="03-31-2014" component="LocationServices" context="" type="0" thread="3564" file="ccmutillib.cpp:1364">
<![LOG[LSUpdateInternetManagementPoints]LOG]!><time="10:17:22.009+420" date="03-31-2014" component="LocationServices" context="" type="1" thread="3564" file="lsad.cpp:2853">
So, I'll start looking for log entries between 10:15:34 and
10:17:21
CcmNotificationAgent.log has the following..
<![LOG[===========================================================]LOG]!><time="10:15:32.825+420" date="03-31-2014" component="BgbAgent" context="" type="1" thread="2964" file="agentendpoint.cpp:237">
<![LOG[Bgb client agent is starting...]LOG]!><time="10:15:32.825+420" date="03-31-2014" component="BgbAgent" context="" type="1" thread="2964" file="agentendpoint.cpp:238">
<![LOG[Bgb client agent is disabled]LOG]!><time="10:15:32.825+420" date="03-31-2014" component="BgbAgent" context="" type="2" thread="2964" file="agentendpoint.cpp:242">
<![LOG[TCP Listener is disabled.]LOG]!><time="10:15:32.825+420" date="03-31-2014" component="BgbAgent" context="" type="2" thread="2964" file="agentendpoint.cpp:247">
<![LOG[BgbController main thread is started with settings: {bgb enable = 0}, {tcp enabled = 0}, {tcp port = 0} and {http enabled = 0}.]LOG]!><time="10:15:32.840+420" date="03-31-2014" component="BgbAgent" context="" type="1" thread="2964" file="bgbcontroller.cpp:126">
<![LOG[Wait 3600 seconds for event notification.]LOG]!><time="10:15:32.840+420" date="03-31-2014" component="BgbAgent" context="" type="1" thread="3132" file="bgbcontroller.cpp:441">
<![LOG[Event :NetworkAvailability.]LOG]!><time="10:15:36.600+420" date="03-31-2014" component="BgbAgent" context="" type="0" thread="2824" file="systemtasks.cpp:117">
<![LOG[Event Data :Connected.]LOG]!><time="10:15:36.600+420" date="03-31-2014" component="BgbAgent" context="" type="0" thread="2824" file="systemtasks.cpp:126">
<![LOG[Netowrk state get updated to Connected.]LOG]!><time="10:15:36.600+420" date="03-31-2014" component="BgbAgent" context="" type="1" thread="2824" file="systemtasks.cpp:173">
CcmExec.log has the following... You can see the [NWSTATE] DISCONNECTED state at
10:15:21 but the state changes to [NWSTATE] CONNECTED AND DOMAIN AUTHENTICATED at
10:15:36 and Detected #IPs has changed [0] [1] at 10:17:21. That correlates with the entries above in
LocationServices.log
<![LOG[Starting CCMEXEC service...]LOG]!><time="10:15:19.877+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2621">
<![LOG[Running on machine DTS-LAB-WS03 as user SYSTEM.]LOG]!><time="10:15:19.877+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2632">
<![LOG[Initializing COM.]LOG]!><time="10:15:19.877+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2652">
<![LOG[Registering for logging change notifications.]LOG]!><time="10:15:19.877+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2665">
<![LOG[Setting default logging component for process.]LOG]!><time="10:15:19.877+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2682">
<![LOG[Setting service status to RUNNING.]LOG]!><time="10:15:19.877+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2702">
<![LOG[Checking configuration.]LOG]!><time="10:15:19.892+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2733">
<![LOG[Successfully Created Thread for CheckConfiguration. Waiting for Configuration to Complete]LOG]!><time="10:15:19.892+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2742">
<![LOG[Starting phase 0 initialization.]LOG]!><time="10:15:21.156+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="entrypoint.cpp:2768">
...
<![LOG[Initialzing network state manager.]LOG]!><time="10:15:21.172+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="init.cpp:856">
<![LOG[[NWCOST] UNRESTRICTED]LOG]!><time="10:15:21.203+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="networkstatemanager.cpp:593">
<![LOG[>>> Condition type 'NetworkCost' value is changed from unknown to 0x1]LOG]!><time="10:15:21.203+420" date="03-31-2014" component="CcmExec" context="" type="0" thread="1908" file="ccmservice_iccmsystemresources.cpp:366">
<![LOG[[NWSTATE] DISCONNECTED]LOG]!><time="10:15:21.203+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="networkstatemanager.cpp:333">
<![LOG[>>> Condition type 'Network' value is changed from unknown to 0x1]LOG]!><time="10:15:21.203+420" date="03-31-2014" component="CcmExec" context="" type="0" thread="1908" file="ccmservice_iccmsystemresources.cpp:366">
<![LOG[Initialzing task scheduler.]LOG]!><time="10:15:21.203+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="init.cpp:859">
<![LOG[Refresh CCM Identity using any registered identity stores]LOG]!><time="10:15:21.203+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="1908" file="init.cpp:862">
...
<![LOG[Winmgmt service current status is 0x4. Process Id 952.]LOG]!><time="10:15:32.965+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="2884" file="wmiprocessmonitor.cpp:177">
<![LOG[Completed phase 1 initialization. Service is now fully operational.]LOG]!><time="10:15:32.965+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="2580" file="entrypoint.cpp:2534">
<![LOG[*** System is now free to go to sleep]LOG]!><time="10:15:32.965+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="2556" file="powerstatemanager.cpp:1068">
<![LOG[[NWSTATE] CONNECTED AND DOMAIN AUTHENTICATED]LOG]!><time="10:15:36.600+420" date="03-31-2014" component="CcmExec" context="" type="1" thread="2556" file="networkstatemanager.cpp:333">
<![LOG[>>> Condition type 'Network' value is changed from 0x1 to 0x302]LOG]!><time="10:15:36.600+420" date="03-31-2014" component="CcmExec" context="" type="0" thread="2556" file="ccmservice_iccmsystemresources.cpp:360">
And as expected after the MP is found there is a flurry of log entries. The ping finishes and is followed by the successful installation of the next Install Application task.
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:20:34.359+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:20:35.154+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:20:36.214+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:20:37.274+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Process completed with exit code 0]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="commandline.cpp:1123">
<![LOG[Reply from 127.0.0.1: bytes=32 time<1ms TTL=128]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Ping statistics for 127.0.0.1:]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[ Packets: Sent = 301, Received = 301, Lost = 0 (0% loss),]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Approximate round trip times in milli-seconds:]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[ Minimum = 0ms, Maximum = 0ms, Average = 0ms]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:34">
<![LOG[Command line returned 0]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="InstallSoftware" context="" type="1" thread="3268" file="runcommandline.cpp:569">
<![LOG[Process completed with exit code 0]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="TSManager" context="" type="1" thread="2276" file="commandline.cpp:1123">
<![LOG[!--------------------------------------------------------------------------------------------!]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="TSManager" context="" type="1" thread="2276" file="instruction.cxx:804">
<![LOG[Successfully completed the action (WAIT FOR 5 MINUTES) with the exit win32 code 0]LOG]!><time="10:20:38.148+420" date="03-31-2014" component="TSManager" context="" type="1" thread="2276" file="instruction.cxx:830">
Ping is done at 10:20:38. Install the Broadcom Bluetooth software at
10:21:08.
<![LOG[+++ Starting Install enforcement for App DT "Broadcom Bluetooth 4.0 Software and Driver (sp61616)" ApplicationDeliveryType - ScopeId_97D1FF5E-8D10-41FE-A013-61A6846E89E0/DeploymentType_8a6a93eb-fedf-4a78-bd42-5a9349d6106d, Revision - 6, ContentPath - C:\Windows\ccmcache\14, Execution Context - System]LOG]!><time="10:21:06.560+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appprovider.cpp:1702">
<![LOG[ A user is not logged on to the system.]LOG]!><time="10:21:08.104+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appprovider.cpp:2083">
<![LOG[ Performing detection of app deployment type Broadcom Bluetooth 4.0 Software and Driver (sp61616)(ScopeId_97D1FF5E-8D10-41FE-A013-61A6846E89E0/DeploymentType_8a6a93eb-fedf-4a78-bd42-5a9349d6106d, revision 6) for system.]LOG]!><time="10:21:08.104+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appprovider.cpp:2148">
<![LOG[+++ Application not discovered. [AppDT Id: ScopeId_97D1FF5E-8D10-41FE-A013-61A6846E89E0/DeploymentType_8a6a93eb-fedf-4a78-bd42-5a9349d6106d, Revision: 6]]LOG]!><time="10:21:08.104+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="localapphandler.cpp:291">
<![LOG[ App enforcement environment:
Context: Machine
Command line: setup.exe /qn /ri /f2c:\windows\temp\Broadcom-Bluetooth-4.0-v6.5revL-install.log
Allow user interaction: No
UI mode: 0
User token: null
Session Id: 4294967295
Content path: C:\Windows\ccmcache\14
Working directory: ]LOG]!><time="10:21:08.104+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appcontext.cpp:85">
<![LOG[ Prepared working directory: C:\Windows\ccmcache\14]LOG]!><time="10:21:08.120+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appcontext.cpp:189">
<![LOG[ Prepared command line: "C:\Windows\ccmcache\14\Setup.exe" /qn /ri /f2c:\windows\temp\Broadcom-Bluetooth-4.0-v6.5revL-install.log]LOG]!><time="10:21:08.120+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appcontext.cpp:338">
<![LOG[ Executing Command line: "C:\Windows\ccmcache\14\Setup.exe" /qn /ri /f2c:\windows\temp\Broadcom-Bluetooth-4.0-v6.5revL-install.log with system context]LOG]!><time="10:21:08.120+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appexcnlib.cpp:201">
<![LOG[ Working directory C:\Windows\ccmcache\14]LOG]!><time="10:21:08.120+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appexcnlib.cpp:215">
<![LOG[ Post install behavior is ForceReboot]LOG]!><time="10:21:08.198+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appcommon.cpp:1094">
<![LOG[ Waiting for process 3364 to finish. Timeout = 15 minutes.]LOG]!><time="10:21:08.198+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appexcnlib.cpp:1958">
<![LOG[ Process 3364 terminated with exitcode: 0]LOG]!><time="10:21:40.119+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appexcnlib.cpp:1967">
<![LOG[ Looking for exit code 0 in exit codes table...]LOG]!><time="10:21:40.119+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appexcnlib.cpp:505">
<![LOG[ ConfigMgr will request a hard reboot after successful enforcement]LOG]!><time="10:21:40.119+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appexcnlib.cpp:575">
<![LOG[++++++ App enforcement completed (33 seconds) for App DT "Broadcom Bluetooth 4.0 Software and Driver (sp61616)" [ScopeId_97D1FF5E-8D10-41FE-A013-61A6846E89E0/DeploymentType_8a6a93eb-fedf-4a78-bd42-5a9349d6106d], Revision: 6, User SID: ] ++++++]LOG]!><time="10:21:40.135+420" date="03-31-2014" component="AppEnforce" context="" type="1" thread="2960" file="appprovider.cpp:2448">
However, this isn't the last Install Application task in the sequence. After the Broadcom stuff is installed, the system reboots as intended and the NEXT Install Application task fails with the same log entries in LocationServices.log saying Unable to find
any lookup MP(s).
I'm confident the network is up because I can see the BDD.log entries being written for the DynamicLogging to the file share which happens to be on the Primary server. So I know the network link is up and that the workstation is passing traffic. It just
appears that SCCM thinks the network is down.