Issue: IPSEC site to site tunnel between ISA and TMG server Fails.

Scenario: Admin is trying to establish site to site IPsec tunnel between ISA server 2006 on one end and TMG 2010 on other end but tunnel does not get established. After configuring tunnel on both ends admin pings from TMG 2010 machine to domain controller on remote end and its gets request time out

Site1

Domain: mylabisa.local

TMG 2010 : External NIC IP address : 10.171.82.55

                    Internal NIC IP address : 192.168.0.124

Machine name : TMG-node1

site to site ipsec tunnel between two sites

Access rule : Allows all protocols/internal+localhost+site-to-site network(to and from)

Network rule: Route relation between site-to-site and internal network

Site 2

Domain: Domain2.local

ISA server 2006 : External NIC IP address : 10.171.82.104

                               Internal NIC IP address :   172.16.0.1

Machine name : ISAdomain2

site to site ipsec tunnel between two sites

Access rule : Allows all protocols/internal+localhost+site-to-site network(to and from)

Network rule: Route relation between site-to-site and internal network

Data collection

For the proof of concept I collected the data using TMG data packager using vpn template(refer) while doing a ping to correlate IKEext.etl logs to what could be causing the issue.

Data analysis and Solution

Formatted IKEext.etl logs collected by TMG data packager and found following

Name: ISA VPN S2S tunnel to network site-2-site
Description: (null)
Flags: 0x00000000
Provider: <unspecified>
Provider data:
Type: IKE Main Mode
Soft expiry: 28800
InitiatorImpersonationType: None
Auth methods: 1
-- 0 --
  Type: Preshared Key
    Key:
    00000000  31 32 33                                         123
    Flags: 0x00000000
Proposals: 1
-- 0 --
  Cipher algorithm:
    Type: AES-256
    Key length: 0
    Rounds: 0
  Integrity algorithm:
    Type: SHA_256
  Max lifetime (sec): 7200
  DH group: DH-2
  QM limit: 0
Flags: 0x00000000
MaxDynamicFilters: 5
RetransmitDuration: 0

[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Inserted ICookie into the high priority thread pool list
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct IKEHeader
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Initializing Kerberos SSPI
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|ACH: 0(ERROR_SUCCESS)
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|My SPN: tmg-node1$@MYLABISA.LOCAL
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct SA
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|AUTHIP keying module is not enabled for traffic
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|IKE not sending co-existence Vendor ID
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct VENDOR type MS NT5 ISAKMPOAKLEY
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct VENDOR type RFC 3947
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct VENDOR type draft-ietf-ipsec-nat-t-ike-02

[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct VENDOR type FRAGMENTATION
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct VENDOR type MS-Negotiation Discovery Capable
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct VENDOR type Vid-Initial-Contact
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Construct VENDOR type IKE CGA version 1
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Sending Packet
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|iCookie ae1067e95973fb37 rCookie 0000000000000000
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Exchange type: IKE Main Mode Length 232 NextPayload SA Flags 0x0 Messid 0x00000000
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Local Address: 10.171.82.55.500 Protocol 0
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Peer Address: 10.171.82.104.500 Protocol 0
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|IF-Luid: 1688849994481664
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Global IF index epoch (89), cache epoch (0). Querying IF index.
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|IF-Index: 13
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Created new TimerContext 0000000001FE0880, type 0
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Processing acquire with ipsec context 158, keyMod 1
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|QM localAddr: 10.171.82.55.0 Protocol 0
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|QM peerAddr : 172.16.0.0.0 Mask 255.255.0.0 Protocol 0
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|IF-Luid: 1688849994481664
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Profile ID: 1
[0]0344.0B48::05/14/2011-20:27:00.519 [ikeext] 0|10.171.82.104|Acquire flags 1
[0]0344.0B48::05/14/2011-20:27:00.520 [ikeext] 0|10.171.82.104|FwpmFilterEnum returned no matching filters
[0]0344.0B48::05/14/2011-20:27:00.520 [user] |10.171.82.104|IkeMatchFwpmFilter failed with Windows error 13825(ERROR_IPSEC_IKE_NO_POLICY)
[0]0344.0B48::05/14/2011-20:27:00.520 [user] |10.171.82.104|IkeMatchFwpmFilter failed with HRESULT 0x80073601(ERROR_IPSEC_IKE_NO_POLICY)
[0]0344.0B48::05/14/2011-20:27:00.520 [user] |10.171.82.104|IkeFindQMPolicy failed with HRESULT 0x80073601(ERROR_IPSEC_IKE_NO_POLICY)
[0]0344.0B48::05/14/2011-20:27:00.520 [ikeext] 0|10.171.82.104|Completing Acquire for ipsec context 158
[0]0344.0B48::05/14/2011-20:27:00.520 [ikeext] 0|10.171.82.104|IkeFreeAcquireContext: Freeing acquire 0000000001FE0D70
[0]0344.0B48::05/14/2011-20:27:00.520 [user] |NULL|IkeProcessAcquireDispatch failed with HRESULT 0x80073601(ERROR_IPSEC_IKE_NO_POLICY)
[0]0344.0F20::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|Original arrival IF index 13
[0]0344.0F20::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|Queuing work to high priority thread pool
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|Received packet
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|Local Address: 10.171.82.55.500 Protocol 0
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|Peer Address: 10.171.82.104.500 Protocol 0
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|IF-Luid: 1688849994481664
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|Profile ID: 1
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|iCookie ae1067e95973fb37 rCookie 5cecc0f08440ab99
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 0|10.171.82.104|Exchange type: IKE Informational Mode Length 68 NextPayload NOTIFY Flags 0x0 Messid 0x702d38a5
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|mmSa: 0x00000000017EB960
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Process Payload OAK NOTIFY/DELETE, SA 00000000017EB960
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Processing Cryptoless notify, SA 00000000017EB960
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Oak NotifyMessage 14
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Peer sent NO_PROPOSAL_CHOSEN notify
[0]0344.0C4C::05/14/2011-20:27:00.523 [user] |10.171.82.104|Peer failed with Windows error 13802(ERROR_IPSEC_IKE_ATTRIB_FAIL)
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|ProcessNotifyData: mmSa 00000000017EB960 cookie e96710ae state 1 messId 0
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Deleted ICookie from the high priority thread pool list
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|IKE diagnostic event:
Event Header:
  Timestamp: 1601-01-01T00:00:00.000Z
  Flags: 0x00000106
    Local address field set
    Remote address field set
    IP version field set
  IP version: IPv4
  IP protocol: 0
  Local address: 10.171.82.55
  Remote address: 10.171.82.104
  Local Port: 0
  Remote Port: 0
  Application ID:
  User SID: <invalid>
Failure type: IKE/Authip Main Mode Failure
Type specific info:
  Failure error code:0x000035ea
    IKE security attributes are unacceptable

  Failure point: Remote
  Flags: 0x00000000
  Keying module type: Ike
  MM State: First roundtrip packet sent
  MM SA role: Initiator
  MM auth method: Unknown
  Cert hash:
0000000000000000000000000000000000000000
  MM ID: 0x000000000000027c
  MM Filter ID: 0x0000000000014e89
  Local Principal Name: tmg-node1$@MYLABISA.LOCAL
  Remote Principal Name:
  Local Principal Group SIDs:
  Remote Principal Group SIDs:

[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Cleaning up mmSa: 00000000017EB960. Error 13802(ERROR_IPSEC_IKE_ATTRIB_FAIL)
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Destroying TimerContext 0000000001FE0880, type 0
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|TimerContext 0000000001FE0880, Old ref 2
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|TimerContext 0000000001FE0880, Old ref 1
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Freeing TimerContext 0000000001FE0880
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Inactivating MM: 00000000017EB960
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Moving mmSa 00000000017EB960 to zombie list
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Deleting MM from lists: 00000000017EB960
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|Completing Acquire for ipsec context 158
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|IkeFreeAcquireContext: Freeing acquire 0000000001FE0B80
[0]0344.0C4C::05/14/2011-20:27:00.523 [ikeext] 636|10.171.82.104|WFP free sspi 00000000017F4020
[0]0344.0F20::05/14/2011-20:27:14.832 [ikeext] 0|10.171.82.104|Original arrival IF index 13
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|Received packet
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|Local Address: 10.171.82.55.500 Protocol 0
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|Peer Address: 10.171.82.104.500 Protocol 0
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|IF-Luid: 1688849994481664
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|Profile ID: 1
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|iCookie 1062fe261a891a22 rCookie 121feda274e2ad89
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|Exchange type: IKE Informational Mode Length 56 NextPayload DELETE Flags 0x0 Messid 0xeb02c45f
[0]0344.0A20::05/14/2011-20:27:14.833 [ikeext] 0|10.171.82.104|Dropping non-initial MM packet with no state to process
[0]0344.0F20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|Original arrival IF index 13
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|Received packet
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|Local Address: 10.171.82.55.500 Protocol 0
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|Peer Address: 10.171.82.104.500 Protocol 0
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|IF-Luid: 1688849994481664
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|Profile ID: 1
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|iCookie ae1067e95973fb37 rCookie 5cecc0f08440ab99
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|Exchange type: IKE Informational Mode Length 56 NextPayload DELETE Flags 0x0 Messid 0xba1b4a76
[0]0344.0A20::05/14/2011-20:27:59.827 [ikeext] 0|10.171.82.104|Dropping non-initial MM packet with no state to process
[0]0344.0134::05/14/2011-20:28:15.455 [ikeext] 0|NULL|IkeRegConfigChangeNotifyCallback invoked
[0]0344.0134::05/14/2011-20:28:15.455 [ikeext] 0|NULL|Stopping IKE tracing

13825(ERROR_IPSEC_IKE_NO_POLICY)   error usualy means that policies are not configured properly so checked the configuration on the TMG server and found phase 1(main mode) has following settings

compared it with the phase 1(main mode) IPsec settings on the ISA server's tunnel and found following

which clearly shows the difference in settings i.e. TMG is configured with AES256 encryption and ISA is with 3DES similarly TMG is configured with SHA256 integrity and ISA is configured with SHA1.

Since we cannot configure ISA with higher values used by TMG for encryption and integrity we changed the values on TMG to match with that of ISA server. After making the changes we got our tunnel working.

Issue: Recently  I worked on a case where we were getting  following  eventid

Event Type: Error

Event Source: Microsoft ISA Server Web Proxy

Event Category: None

Event ID: 14197

Date: 04/11/2011

Time: 12:05:03 AM

User: N/A

Computer: ISA01

Description:

ISA Server was unable to write content to the cache file.

Frequently during certain periods of the day not necessarily at the peak times. Users were all internal web proxy clients. Apart from this event there was no real disruption in the ISA server operations. But admin wanted to know why it was occurring.

Troubleshooting and Solution

1. Admin had antivirus on the ISA server, Admin had not excluded the ISA folders from antivirus scanning.Made sure admin had excluded all the ISA server folders from antivirus scanning as per following article http://technet.microsoft.com/en-us/library/cc707727.aspx. Then we monitored it for a day and it came back up again during different times a day.
2. Followed the suggestions given in following blog post by Yuri Diogenes http://blogs.technet.com/b/yuridiogenes/archive/2010/01/30/isa-server-triggers-lots-of-14197-events.aspx and enabled. Auditing for object access To see which process was accessing it at the time we get the event. Then went through the logs and there were only two processes accessing it all the time wspsrv(firewall service) and mspadmin(ISA control service) accessing the cache folder which is right they are supposed to do that. It still does not explain why we were getting those events.
3. Engaged the performance team to check the health of the Hard drive as in perfmonce montor I saw Avg. Disk queue length spiking randomly but it was around 2 most of the time not above it. Performance team informed us that C drive although is very active but still not (Avg. disk queue length counter)spiking at the time when we see the events.
4. Then once again started looking at how the cache is configured and saw the cache drive size which was 1000 MB on the C drive. Asked customer about the number of users who access the internet through ISA in an average, although he was not sure but he said it should be around 5000 users.  Explained him that 1000MB is too less for 5000 users.
5. What’s the right number was question by admin and answer is provided in following blog post by me http://blogs.technet.com/b/sooraj-sec/archive/2010/04/12/formula-for-cache-drive-size.aspx as per which cache drive size for this scenario should be

0.5*5000+10MB=2510MB

      6.  We changed the value to 2510MB and monitored and Event never occurred again.