locked
NAP client not capable at boot, becomes capable after more than 1 minute RRS feed

  • Question

  • Win2008R2, NAP-protected DHCP setup, NAP settings to Win7 clients pushed via GPO.

    The clients boots into "non NAP-capable" mode, and switches to "NAP Capable" by itself while at logon screen for more than 1 minute.

    This is an excerpt from the NPS log where the first RADIUS query is the first DHCPRequest the client generates after the reboot, the second block is the first request having SOH attached from the client, note the timecodes. See following post.

    This delay allows an user to interactively log in (with cached credentials) despite not having IP configured, or prevents an user to log in if not done already due to the DC not being reachable.

    Please advice.

    Luigi



    Wednesday, May 2, 2012 3:56 PM

All replies

  • Adding the log entries again:

    <Event>
    <Timestamp data_type="4">05/02/2012 17:36:05.446</Timestamp>
    <Computer-Name data_type="1">DHCPNPS02</Computer-Name>
    <Event-Source data_type="1">RAS</Event-Source>
    <Service-Type data_type="0">12</Service-Type>
    <MS-Identity-Type data_type="0">1</MS-Identity-Type>
    <NAS-Port-Type data_type="0">15</NAS-Port-Type>
    <MS-Network-Access-Server-Type data_type="0">3</MS-Network-Access-Server-Type>
    <Called-Station-Id data_type="1">192.168.0.0</Called-Station-Id>
    <MS-Service-Class data_type="2">
    </MS-Service-Class>
    <Calling-Station-Id data_type="1">00155DDCF016</Calling-Station-Id>
    <MS-Machine-Name data_type="1">MININT-DEVTEST</MS-Machine-Name>
    <NAS-Identifier data_type="1">DHCPNPS02</NAS-Identifier>
    <Acct-Session-Id data_type="1">931711348</Acct-Session-Id>
    <NAS-IP-Address data_type="3">192.168.0.237</NAS-IP-Address>
    <Framed-IP-Address data_type="3">192.168.0.12</Framed-IP-Address>
    <Proxy-Policy-Name data_type="1">NAP Enforced DHCP</Proxy-Policy-Name>
    <Provider-Type data_type="0">1</Provider-Type>
    <Class data_type="1">311 1 fe80::188a:dfc9:d167:b33a 05/02/2012 12:28:09 137</Class>
    <Authentication-Type data_type="0">7</Authentication-Type>
    <NP-Policy-Name data_type="1">DHCP Non NAP-Capable</NP-Policy-Name>
    <Quarantine-Update-Non-Compliant data_type="0">1</Quarantine-Update-Non-Compliant>
    <Packet-Type data_type="0">1</Packet-Type>
    <Reason-Code data_type="0">0</Reason-Code>
    </Event>
    <Event>
    <Timestamp data_type="4">05/02/2012 17:36:05.446</Timestamp>
    <Computer-Name data_type="1">DHCPNPS02</Computer-Name>
    <Event-Source data_type="1">RAS</Event-Source>
    <Class data_type="1">311 1 fe80::188a:dfc9:d167:b33a 05/02/2012 12:28:09 137</Class>
    <Quarantine-Update-Non-Compliant data_type="0">1</Quarantine-Update-Non-Compliant>
    <NP-Policy-Name data_type="1">DHCP Non NAP-Capable</NP-Policy-Name>
    <Acct-Session-Id data_type="1">931711348</Acct-Session-Id>
    <Authentication-Type data_type="0">7</Authentication-Type>
    <Proxy-Policy-Name data_type="1">NAP Enforced DHCP</Proxy-Policy-Name>
    <Provider-Type data_type="0">1</Provider-Type>
    <Packet-Type data_type="0">3</Packet-Type>
    <Reason-Code data_type="0">65</Reason-Code>
    </Event>
    (...)
    <Event>
    <Timestamp data_type="4">05/02/2012 17:37:18.080</Timestamp>
    <Computer-Name data_type="1">DHCPNPS02</Computer-Name>
    <Event-Source data_type="1">RAS</Event-Source>
    <Service-Type data_type="0">12</Service-Type>
    <MS-Identity-Type data_type="0">1</MS-Identity-Type>
    <NAS-Port-Type data_type="0">15</NAS-Port-Type>
    <MS-Network-Access-Server-Type data_type="0">3</MS-Network-Access-Server-Type>
    <Called-Station-Id data_type="1">192.168.0.0</Called-Station-Id>
    <MS-Service-Class data_type="2">
    </MS-Service-Class>
    <Calling-Station-Id data_type="1">00155DDCF016</Calling-Station-Id>
    <MS-Machine-Name data_type="1">MININT-DEVTEST</MS-Machine-Name>
    <NAS-Identifier data_type="1">DHCPNPS02</NAS-Identifier>
    <Acct-Session-Id data_type="1">1135103416</Acct-Session-Id>
    <NAS-IP-Address data_type="3">192.168.0.237</NAS-IP-Address>
    <Framed-IP-Address data_type="3">192.168.0.12</Framed-IP-Address>
    <Proxy-Policy-Name data_type="1">NAP Enforced DHCP</Proxy-Policy-Name>
    <Provider-Type data_type="0">1</Provider-Type>
    <Class data_type="1">311 1 fe80::188a:dfc9:d167:b33a 05/02/2012 12:28:09 145</Class>
    <Quarantine-Session-Id data_type="1">{1AE773BB-84E3-49DB-A7FF-3551E07008A2} - 2012-05-02 15:37:06.791Z</Quarantine-Session-Id>
    <Machine-Inventory data_type="1">6.1.7600 0.0 x86 Workstation</Machine-Inventory>
    <Fully-Qualified-Machine-Name data_type="1">DEVDOM\MININT-DEVTEST$</Fully-Qualified-Machine-Name>
    <Authentication-Type data_type="0">7</Authentication-Type>
    <NP-Policy-Name data_type="1">DHCP NAP Compliant</NP-Policy-Name>
    <Quarantine-Update-Non-Compliant data_type="0">1</Quarantine-Update-Non-Compliant>
    <Packet-Type data_type="0">1</Packet-Type>
    <Reason-Code data_type="0">0</Reason-Code>
    </Event>
    <Event>
    <Timestamp data_type="4">05/02/2012 17:37:18.080</Timestamp>
    <Computer-Name data_type="1">DHCPNPS02</Computer-Name>
    <Event-Source data_type="1">RAS</Event-Source>
    <Class data_type="1">311 1 fe80::188a:dfc9:d167:b33a 05/02/2012 12:28:09 145</Class>
    <MS-Extended-Quarantine-State data_type="0">0</MS-Extended-Quarantine-State>
    <MS-Quarantine-State data_type="0">0</MS-Quarantine-State>
    <Service-Type data_type="0">2</Service-Type>
    <Framed-Protocol data_type="0">1</Framed-Protocol>
    <Quarantine-Update-Non-Compliant data_type="0">1</Quarantine-Update-Non-Compliant>
    <Acct-Session-Id data_type="1">1135103416</Acct-Session-Id>
    <Proxy-Policy-Name data_type="1">NAP Enforced DHCP</Proxy-Policy-Name>
    <Provider-Type data_type="0">1</Provider-Type>
    <Quarantine-Session-Id data_type="1">{1AE773BB-84E3-49DB-A7FF-3551E07008A2} - 2012-05-02 15:37:06.791Z</Quarantine-Session-Id>
    <Machine-Inventory data_type="1">6.1.7600 0.0 x86 Workstation</Machine-Inventory>
    <Fully-Qualified-Machine-Name data_type="1">DEVDOM\MININT-DEVTEST$</Fully-Qualified-Machine-Name>
    <Authentication-Type data_type="0">7</Authentication-Type>
    <System-Health-Result data_type="1">Windows Security Health Validator:Compliant:No Data:None[]:(0x0 - ):(0x0 - ):(0x0 - ):(0x0 - ):(0x0 - ):(0x0 - ):(0x0 - ):(0x0 - )</System-Health-Result>
    <System-Health-ResultEx data_type="1">
    <SHV-Name data_type="1">Windows Security Health Validator</SHV-Name>
    <Config-ID data_type="0">0</Config-ID>
    <Config-Friendly-Name data_type="1">
    </Config-Friendly-Name>
    <Health-Result data_type="1">Compliant</Health-Result>
    <Extended-Isolation-State data_type="1">No Data</Extended-Isolation-State>
    <Failure-Category data_type="1">None</Failure-Category>
    <Failure-Category-String data_type="1">
    </Failure-Category-String>
    <Compliance-Results data_type="1">
    </Compliance-Results>
    </System-Health-ResultEx>
    <NP-Policy-Name data_type="1">DHCP NAP Compliant</NP-Policy-Name>
    <Packet-Type data_type="0">2</Packet-Type>
    <Reason-Code data_type="0">0</Reason-Code>
    </Event>

    Thursday, May 3, 2012 7:37 AM
  • Adding selected output lines of netsh commands (while client reports itself as non nap-capable):

    netsh nap client show grouppolicy

    Enforcement clients: 
    ---------------------------------------------------- 
    Name            = DHCP Quarantine Enforcement Client 
    ID              = 79617 
    Admin           = Enabled
    

    netsh nap client show state

    Enforcement client state: 
    ---------------------------------------------------- 
    Id                     = 79617 
    Name                   = DHCP Quarantine Enforcement Client 
    Description            = Provides DHCP based enforcement for NAP 
    Version                = 1.0 
    Vendor name            = Microsoft Corporation 
    Registration date      =  
    Initialized            = Yes 
    

    Thursday, May 3, 2012 10:29 AM
  • as a follow-up, I am including the relevant event viewer entries on the Win7 client.

    This is the entry generated when client has been leased an IP, ie it reports itself as being NAP compliant:

    <Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'>
    <System>
    <Provider Name='Microsoft-Windows-SystemHealthAgent' Guid='{B1BEBB9A-24AA-4B83-9E4A-38C2A9A44377}'/>
    <EventID>1025</EventID>
    <Version>0</Version>
    <Level>4</Level>
    <Task>0</Task>
    <Opcode>0</Opcode>
    <Keywords>0x4000000000000000</Keywords>
    <TimeCreated SystemTime='2012-05-03T13:51:39.664221800Z'/>
    <EventRecordID>266</EventRecordID>
    <Correlation/>
    <Execution ProcessID='1112' ThreadID='1524'/>
    <Channel>Microsoft-Windows-NetworkAccessProtection/Operational</Channel>
    <Computer>minint-devtest.devdom.org<</Computer>
    <Security UserID='S-1-5-20'/>
    </System>
    <EventData>
    <Data Name='SuccessString'>{ABC28A6C-7E9F-46F4-9354-37C373472506} - 2012-05-03 13:51:39.648Z</Data>
    </EventData>
    <RenderingInfo Culture='en-US'>
    <Message>The Windows Security Health Agent specified a new security health state for the computer.
    The correlation id for this transaction is {ABC28A6C-7E9F-46F4-9354-37C373472506} - 2012-05-03 13:51:39.648Z</Message>
    <Level>Information</Level>
    <Task>
    </Task>
    <Opcode>Info</Opcode>
    <Channel>
    </Channel>
    <Provider>Microsoft-Windows-SystemHealthAgent</Provider>
    <Keywords>
    </Keywords>
    </RenderingInfo>
    </Event>
    
    

    the previous event is the last in the boot sequence, again note timecodes:

    <Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'>
    <System>
    <Provider Name='Microsoft-Windows-NetworkAccessProtection' Guid='{4EF850D8-BF30-4E64-A917-EE21B9BE1F0A}'/>
    <EventID>9</EventID>
    <Version>0</Version>
    <Level>4</Level>
    <Task>0</Task>
    <Opcode>0</Opcode>
    <Keywords>0x8000000000000000</Keywords>
    <TimeCreated SystemTime='2012-05-03T13:49:38.627875000Z'/>
    <EventRecordID>265</EventRecordID>
    <Correlation/>
    <Execution ProcessID='1112' ThreadID='1576'/>
    <Channel>Microsoft-Windows-NetworkAccessProtection/Operational</Channel>
    <Computer>minint-devtest.devdom.org</Computer>
    <Security UserID='S-1-5-20'/>
    </System>
    <UserData>
    <NapEvent xmlns:auto-ns2='http://schemas.microsoft.com/win/2004/08/events' xmlns='myNs'>
    <ComponentId>79617</ComponentId>
    </NapEvent>
    </UserData>
    <RenderingInfo Culture='en-US'>
    <Message>The enforcement client 79617 successfully initialized.</Message>
    <Level>Information</Level>
    <Task>
    </Task>
    <Opcode>Info</Opcode>
    <Channel>Microsoft-Windows-NetworkAccessProtection/Operational</Channel>
    <Provider>Microsoft-Windows-Network Access Protection</Provider>
    <Keywords>
    </Keywords>
    </RenderingInfo>
    </Event>
    

    Again, almost 2 minutes before the correct status is declared.

    Thursday, May 3, 2012 2:09 PM
  • I'd appreciate any comments on the specific issue.
    Saturday, May 5, 2012 8:19 AM
  • wouldn't it be possible to use the last SOH so that at reboot the SOH is not evaluated and the first DHCPRequest comes out with the last known SOH?
    Tuesday, May 8, 2012 8:36 AM
  • Hi Luigi,

    Thanks for contacting Microsoft.

    By checking your logs, I noticed that the time point on the client side does not matc the point on the server side. And the format of them seems a bit confused, could you please provide me any link for download them for checking the information in detail?

    Besides, my understanding is that you have the main concern about the delay of "non-capable" status to the "capable" status. Do you think it is too late? Based on this problem, I think there are two points I could make for the possible cause:

    1. The client does not receive the health information so that it doesn't send the package out to the DHCP server.

    2. NAP agent service does not enabled on the client.

    Please let me know if you have any other information to be clarified.

    I appreciate your time.

    Best Regards,

    Annie Gu

    Tuesday, May 8, 2012 9:54 AM
  • Hi Annie,

    tks for your support, I have uploaded both NPS server log entries and event viewer NAP entries from client in my skydrive.

    As you may see from the logs, it takes two minutes for the DHCP client to obtain an IP, and this is way too late given that the interactive user could log on (with cached credentials) without any connectivity, thus skipping the whole domain logon process.

    By using Network Monitor, I can confirm that initially at boot the DHCPRequest packets from the client do not contain the SOH, and after one-two minutes eventually the SOH is later attached correctly. I can provide you the captured session as well.

    Tks

    Luigi

    Tuesday, May 8, 2012 10:33 AM
  • Hi Luigi,

    Thanks for your reply.

    I have just downloaded the file from yours. I will check it and reply to you later.

    It may take some time before I can reply to you, thanks for your patience!

    Best Regards,

    Annie Gu

    Thursday, May 10, 2012 9:30 AM
  • tks a lot.

    Luigi

    Thursday, May 10, 2012 9:42 AM
  • Hi,

    See http://social.technet.microsoft.com/Forums/en-US/winserverNAP/thread/bc4656e8-018d-42bc-b038-e28b9f5bd146

    You can try setting a dependency for the napagent service on the DHCP client service.

    -Greg

    Saturday, May 12, 2012 6:23 PM
  • Hi Greg,

    I tried adding the dependency but no changes. See screenshot of netmon output at client boot, where you can see that a lot of DHCPRequest packets come out without SOH attached. Only after more than two minutes, way after the interactive user is prompted with the logon screen, the SOH is attached and IP is leased.


    For debugging purposes I created a startup script logging the client NPS state, and the output shows everything is in good order. 

    Luigi

    Monday, May 14, 2012 8:21 AM
  • Hi,

    Sorry for the delay.

    From the logs you uploaded, we find the reason code 65 involved in the logs. For this kind of code, it indicates that the Network Access Permission setting in the dial-in properties of the user account in Active Directory is set to Deny access to the user. To change the Network Access Permission setting to either Allow access or Control access through NPS Network Policy, obtain the properties of the user account in Active Directory Users and Computers, click the Dial-in tab, and change Network Access Permission.

    So, could you please check the Dial-in tab to ensure the user was not chosen as the "Deny".

    Thanks.

    Best Regards,

    Annie

    Tuesday, May 22, 2012 8:49 AM
  • Hi,

    tks for the reply.

    NPS policies already are set to ignore user account dial-in properties, although the policy here is not related to user, but to computer accounts.

    The policy is correct, given that when the computer is on since some time the SOH is included in the DHCPRequest right away and the policy is evaluated properly.

    Very recently the issue has been acknowledged by MS support, a fix will be provided in due time.

    Tuesday, May 22, 2012 10:33 AM