Here’s a brief one that tripped me up a couple of weeks ago, I was deploying FortiGate LDAPS authentication for some FortiClient SSLVPN connections into a FortiGate firewall like so;
Despite my best efforts I was getting authentication failures? If I tested the username and password in the GUI web management portal, that worked fine?
Testing FortiGate LDAPS
First step is to test authentication at command line, like so;
[box]
Forti-FW # diag test auth ldap My-DC test.user Password123
authenticate 'test.user' against 'My-DC' failed!
[/box]
Note: My-DC is the domain controller, test, user is the username, and Password123 is the password for my AD user. (The fact I need to explain that is depressing, but c’est la vie).
So despite what the GUI is telling me, authentication is actually failing, remember I’m using LDAPS, so the FortiGate needs to have the CA certificate, (that issued the Kerberos certificates on my domain controller(s)), in its trusted CA list! And TCP port 636 needs to be open between the firewall and the domain controllers.
Debugging FortiGate LDAPS
So now we need to debug what’s going on;
[box]
Forti-FW # diagnose debug enable
Forti-FW # diagnose debug application fnbamd 255
Debug messages will be on for 30 minutes.
[/box]
Then simply attempt to authenticate via FortiClient, or recall the ‘diag test’ command from above.
[box]
Forti-FW # diag test auth ldap My-DC test.user Password123
[1932] handle_req-Rcvd auth req 1296531457 for test.user in My-DC opt=0000001b prot=0
[424] __compose_group_list_from_req-Group 'My-DC', type 1
[617] fnbamd_pop3_start-test.user
[970] __fnbamd_cfg_get_ldap_list_by_server-
[976] __fnbamd_cfg_get_ldap_list_by_server-Loaded LDAP server 'My-DC'
[1131] fnbamd_cfg_get_ldap_list-Total ldap servers to try: 1
[1713] fnbamd_ldap_init-search filter is: sAMAccountName=test.user
[1722] fnbamd_ldap_init-search base is: dc=testbench,dc=co,dc=uk
[1146] __fnbamd_ldap_dns_cb-Resolved My-DC:192.168.1.122 to 192.168.1.122, cur stack size:1
[919] __fnbamd_ldap_get_next_addr-
[1152] __fnbamd_ldap_dns_cb-Connection starts My-DC:192.168.1.122, addr 192.168.1.122 over SSL
[874] __fnbamd_ldap_start_conn-Still connecting 192.168.1.122.
[591] create_auth_session-Total 1 server(s) to try
[1097] __ldap_connect-tcps_connect(192.168.1.122) failed: ssl_connect() failed: 337047686 (error:1416F086:SSL routines:tls_process_server_certificate:certificate verify failed).
[930] __ldap_error-My-DC:192.168.1.122, addr 192.168.1.122
[725] __ldap_stop-Conn with 192.168.1.122 destroyed.
[919] __fnbamd_ldap_get_next_addr-
[902] __ldap_try_next_server-No more server to try for 'My-DC'.
[785] __ldap_done-svr 'My-DC'
[755] __ldap_destroy-
[2870] fnbamd_ldap_result-Error (3) for req 1296531457
[217] fnbamd_comm_send_result-Sending result 3 (nid 0) for req 1296531457, len=2044
authenticate 'test.user' against 'My-DC' failed!
Forti-FW # [747] destroy_auth_session-delete session 1296531457
[755] __ldap_destroy-
[1764] fnbamd_ldap_auth_ctx_free-Freeing 'My-DC' ctx
[2099] fnbamd_ldap_free-Freeing 'My-DC'
[/box]
OK so it’s SSL related? For SSL to work you need the following;
To trust the CA that issued the certificate
To be able to resolve (via DNS) the common name (or Subject Alternative Name) on the certificate
If you’ve specified the LDAP server by IP address the IP address of the server needs to be on the certificate as a Subject Alternative Name (SAN).
Your firewall and the AD/LDAP server need to have compatible SSL ciphers.
So I had number 1 covered, and the chance of it being number 4 are rare, (server and firewall are fully updated).
So my problem was initially number 2 I’d specified the LDAPS server via its internal IP. I needed to use its FQDN, then of course the firewall needed to be able to resolve that IP with a DNS lookup (try execute ping server-name.doman-name if you’re unsure!)
[box]
Forti-FW # execute ping win-server.testbench.co.ukUnable to resolve hostname. <---OOPS THAT'S NOT GOOD!
Forti-FW # execute ping 192.168.1.122 <---CONNECTIVITY IS OK!
PING 192.168.1.122 (192.168.1.122): 56 data bytes
64 bytes from 192.168.1.122: icmp_seq=0 ttl=128 time=5.4 ms
64 bytes from 192.168.1.122: icmp_seq=1 ttl=128 time=2.0 ms
64 bytes from 192.168.1.122: icmp_seq=2 ttl=128 time=1.9 ms
^C
--- 192.168.1.122 ping statistics ---
3 packets transmitted, 3 packets received, 0% packet loss
round-trip min/avg/max = 1.9/3.1/5.4 ms
[/box]
Once DNS was setup correctly;
[box]
Forti-FW # execute ping win-server.testbench.co.uk
PING win-server.testbench.co.uk (192.168.1.122): 56 data bytes
64 bytes from 192.168.1.122: icmp_seq=0 ttl=128 time=1.9 ms
64 bytes from 192.168.1.122: icmp_seq=1 ttl=128 time=2.3 ms
64 bytes from 192.168.1.122: icmp_seq=2 ttl=128 time=2.1 ms
^C
--- win-server.testbench.co.uk ping statistics ---
3 packets transmitted, 3 packets received, 0% packet loss <---BOOM THAT'S BETTER
round-trip min/avg/max = 1.9/2.1/2.3 ms
[/box]
Then retest.
[box]
Forti-FW # diag test auth ldap My-DC test.user Password123
authenticate 'test.user' against 'My-DC' succeeded!
Group membership(s) - CN=GS-VPN-Users,OU=Securty-Groups,DC=testbench,DC=co,DC=uk
CN=Domain Users,CN=Users,DC=testbench,DC=co,DC=uk
[/box]
Related Articles, References, Credits, or External Links
While migrating a VPN tunnel from an ASA 5520 firewall to a new 5516-X I got this problem. The other end was a Cisco router (2900). As soon as I swapped it over, it was stuck at MM_WAIT_MSG3, and phase 1 would not establish;
[box]
NUFC-ASA5516x(config-tunnel-ipsec)# show crypto isa
IKEv1 SAs:
Active SA: 6
Rekey SA: 0 (A tunnel will report 1 Active and 1 Rekey SA during rekey)
Total IKE SA: 6
1 IKE Peer: 1.1.1.1
Type : user Role : responder
Rekey : no State : MM_WAIT_MSG3
[/box]
Debugs didn’t help much either;
[box]
Mar 25 2019 18:50:49: %ASA-7-713236: IP = 1.1.1.1, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 164
Mar 25 2019 18:50:49: %ASA-7-715047: IP = 1.1.1.1, processing SA payload
Mar 25 2019 18:50:49: %ASA-7-713906: IP = 1.1.1.1, Oakley proposal is acceptable
Mar 25 2019 18:50:49: %ASA-7-715047: IP = 1.1.1.1, processing VID payload
Mar 25 2019 18:50:49: %ASA-7-715049: IP = 1.1.1.1, Received NAT-Traversal RFC VID
Mar 25 2019 18:50:49: %ASA-7-715047: IP = 1.1.1.1, processing VID payload
Mar 25 2019 18:50:49: %ASA-7-715047: IP = 1.1.1.1, processing VID payload
Mar 25 2019 18:50:49: %ASA-7-715049: IP = 1.1.1.1, Received NAT-Traversal ver 03 VID
Mar 25 2019 18:50:49: %ASA-7-715047: IP = 1.1.1.1, processing VID payload
Mar 25 2019 18:50:49: %ASA-7-715049: IP = 1.1.1.1, Received NAT-Traversal ver 02 VID
Mar 25 2019 18:50:49: %ASA-7-715047: IP = 1.1.1.1, processing IKE SA payload
Mar 25 2019 18:50:49: %ASA-7-715028: IP = 1.1.1.1, IKE SA Proposal # 1, Transform # 1 acceptable Matches global IKE entry # 8
Mar 25 2019 18:50:49: %ASA-7-715046: IP = 1.1.1.1, constructing ISAKMP SA payload
Mar 25 2019 18:50:49: %ASA-7-715046: IP = 1.1.1.1, constructing NAT-Traversal VID ver RFC payload
Mar 25 2019 18:50:49: %ASA-7-715046: IP = 1.1.1.1, constructing Fragmentation VID + extended capabilities payload
Mar 25 2019 18:50:49: %ASA-7-713236: IP = 1.1.1.1, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 128
Mar 25 2019 18:50:57: %ASA-7-713236: IP = 1.1.1.1, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 128
Mar 25 2019 18:50:59: %ASA-7-713906: IKE Receiver: Packet received on 2.2.2.2:500 from 1.1.1.1:500
Mar 25 2019 18:50:59: %ASA-5-713202: IP = 1.1.1.1, Duplicate first packet detected. Ignoring packet.
Mar 25 2019 18:51:05: %ASA-7-713236: IP = 1.1.1.1, IKE_DECODE RESENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 128
Mar 25 2019 18:51:21: %ASA-7-715065: IP = 1.1.1.1, IKE MM Responder FSM error history (struct &0x00007f4d2d293690) , : MM_DONE, EV_ERROR-->MM_WAIT_MSG3, EV_TIMEOUT-->MM_WAIT_MSG3, NullEvent-->MM_SND_MSG2, EV_SND_MSG-->MM_SND_MSG2, EV_START_TMR-->MM_SND_MSG2, EV_RESEND_MSG-->MM_WAIT_MSG3, EV_TIMEOUT-->MM_WAIT_MSG3, NullEvent
Mar 25 2019 18:51:21: %ASA-7-713906: IP = 1.1.1.1, IKE SA MM:5f3d6a94 terminating: flags 0x01000002, refcnt 0, tuncnt 0
Mar 25 2019 18:51:21: %ASA-7-713906: IP = 1.1.1.1, sending delete/delete with reason message
Mar 25 2019 18:51:21: %ASA-6-713905: IP = 1.1.1.1, Warning: Ignoring IKE SA (src) without VM bit set
[/box]
Solution
Well, as you can tell from my Troubleshooting Phase 1 Cisco Site to Site (L2L) VPN Tunnels article MM_WAIT_MSG3 usually happens if something is blocking ISAKMP (UDP 500) in-between the peers. Or there’s a ‘bug’ that needs some newer or older code. The problem was not spotted by me, I was chatting to an ex colleague about it and he knew what it was straight away (annoyingly). The Router had an ACL on its outside interface that was NOT allowing the peer in to establish a VPN.
On the router take a look a the outside interface, and look for an access-list;
[box]
Remote-Router#show run interface GigabitEthernet 0/0
Building configuration...
Current configuration : 214 bytes
!
interface GigabitEthernet0/0
bandwidth 200000
ip address 1.1.1.1 255.255.255.248
ip access-group outside-in in
ip nat outside
ip virtual-reassembly in
duplex auto
speed auto
crypto map CMAP-1
end
Remote-Router#
[/box]
So it’s called outside-in what’s it doing?
[box]
Remote-Router#show access-list outside-in
Extended IP access list outside-in
10 permit udp any eq domain any
20 permit icmp any any echo-reply (956 matches)
30 permit ip 123.123.123.64 0.0.0.15 any (127341882 matches)
40 permit ip 123.123.123.128 0.0.0.127 any (572 matches)
50 permit ip 222.222.222.96 0.0.0.15 any (4 matches)
60 permit ip host 123.123.123.68 any
70 permit udp host 222.222.222.76 eq ntp any
80 permit udp host 222.222.222.204 eq ntp any
90 permit udp host 222.222.222.232 eq ntp any
100 permit icmp any any (1320 matches)
110 permit ip 223.223.233.0 0.0.0.255 any
[/box]
Add in our peer IP address;
[box]
Remote-Router#configure terminal
Enter configuration commands, one per line. End with CNTL/Z.
Remote-Router(config)#ipaccess-list extended outside-in
Remote-Router(config-ext-nacl)# permit esp host 2.2.2.2 any
Remote-Router(config-ext-nacl)# permit udp host 2.2.2.2 any eq isakmp
Remote-Router(config-ext-nacl)# permit udp host 2.2.2.2 any eq non500-isakmp
Remote-Router(config-ext-nacl)#exit
Remote-Router(config)#
[/box]
Let’s just make sure it’s there;
[box]
Remote-Router#show access-list outside-in
Extended IP access list outside-in
10 permit udp any eq domain any
20 permit icmp any any echo-reply (956 matches)
30 permit ip 123.123.123.64 0.0.0.15 any (127341882 matches)
40 permit ip 123.123.123.128 0.0.0.127 any (572 matches)
50 permit ip 222.222.222.96 0.0.0.15 any (4 matches)
60 permit ip host 123.123.123.68 any
70 permit udp host 222.222.222.76 eq ntp any
80 permit udp host 222.222.222.204 eq ntp any
90 permit udp host 222.222.222.232 eq ntp any
100 permit icmp any any (1320 matches)
110 permit ip 223.223.233.0 0.0.0.255 any
120 permit esp host 2.2.2.2 any
130 permit udp host 2.2.2.2 any eq isakmp
140 permit udp host 2.2.2.2 any eq non500-isakmp
[/box]
Don’t forget to save the changes with a ‘write mem’ command!
Related Articles, References, Credits, or External Links
Once again, thanks to SteveH for spotting, (in less than sixty seconds) what was wrong.
I see this get asked in forums A LOT, typically the poster has another problem they are trying to fix, someone has asked them to debug the problem and they cant see any debug output.
Solution
Firstly you need to understand what logging is, and how debugging fits within it. (Bear with me, this is good knowledge to have).
The firewall saves logs in syslog format, and there are 8 Levels of logs, the one with the MOST information is called ‘debugging’ (or severity 7 in Syslog world)
0=Emergencies
1=Alert
2=Critical
3=Errors
4=Warnings
5=Notifications
6=Informational
7=Debugging
So if you are debugging, then all you are doing is looking at syslog output thats severity 7. The ASA can send these logs to an internal memory buffer, and external Syslog server, or to the screen, either the console (via rollover cable) or the monitor (SSH/Telnet session, or what router types, call the virtual terminal lines).
Fine but I cant see anything doofus, that’s why I’m here!
OK, now you understand how it all works, you should understand when you see the commands, why it wasn’t working!
Issue a ‘show log’ command;
What does this tell us? Well mose importantly it tells us logging in ON.
[box]Syslog logging: enabled[/box]
If it were disabled then you turn it on with;
[box]logging on[/box]
The next piece of pertinent information is.
[box]Timestamp Logging: Disabled[/box]
While not critical, logs are much easier to interpret when they are stamped with the correct time! I’m in the UK so this is the command I would use (Note: I’m enabling NTP Time sync, this can take a while to synchronise);
[box]
clock timezone GMT 0
clock summer-time BST recurring last Sun Mar 1:00 last Sun Oct 2:00
!
ntp server 130.88.203.12 source outside
!
logging timestamp
[/box]
Sending Debug Output to the Screen
As mentioned above, you can send output to the console or the monitor;
Send Debug to SSH/Telnet Session
[box]logging monitor debugging
terminal monitor[/box]
Note: To disable, the command is ‘terminal no monitor‘ NOT ‘no terminal monitor’ (Thanks Cisco!)
Sending Debug Output to the Console (Serial Connection)
Send Debug to SSH/Telnet Session
[box]logging console debugging[/box]
Note: To stop it, set it back to ‘warnings’ (the default).
[box]logging console warnings[/box]
Sending Debug Output to the Internal Log (Buffer)
This is easier, as you can filter the results for particular IP addresses/ports/usernames etc, which is handy if there are pages and pages to look though, and they are not scrolling past you yes, faster than you can read them!
Saw this in a forum today, and knew what it was straight away! While attempting to get a VPN tunnel up from a Cisco ASA (5508-x) to a Sonicwall firewall this was there debug output;
[box]
Apr 06 00:45:21 [IKEv1]IP = x.x.x.x, IKE Initiator: New Phase 1, Intf Lan, IKE Peer x.x.x.x local Proxy Address 192.168.90.150, remote Proxy Address 10.252.1.1, Crypto map (Internet_map)
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, constructing ISAKMP SA payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, constructing Fragmentation VID + extended capabilities payload
Apr 06 00:45:21 [IKEv1]IP = x.x.x.x, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + NONE (0) total length : 340
Apr 06 00:45:21 [IKEv1]IP = x.x.x.x, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + NONE (0) total length : 96
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, processing SA payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, Oakley proposal is acceptable
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, processing VID payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, constructing ke payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, constructing nonce payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, constructing Cisco Unity VID payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, constructing xauth V6 VID payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, Send IOS VID
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, Constructing ASA spoofing IOS Vendor ID payload (version: 1.0.0, capabilities: 20000001)
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, constructing VID payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, Send Altiga/Cisco VPN3000/Cisco ASA GW VID
Apr 06 00:45:21 [IKEv1]IP = x.x.x.x, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + KE (4) + NONCE (10) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 320
Apr 06 00:45:21 [IKEv1]IP = x.x.x.x, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + KE (4) + NONCE (10) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 272
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, processing ke payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, processing ISA_KE payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, processing nonce payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, processing VID payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, processing VID payload
Apr 06 00:45:21 [IKEv1 DEBUG]IP = x.x.x.x, Received xauth V6 VID
Apr 06 00:45:21 [IKEv1]IP = x.x.x.x, Connection landed on tunnel_group x.x.x.x
Apr 06 00:45:21 [IKEv1 DEBUG]Group = x.x.x.x, IP = x.x.x.x, Generating keys for Initiator...
Apr 06 00:45:21 [IKEv1 DEBUG]Group = x.x.x.x, IP = x.x.x.x, constructing ID payload
Apr 06 00:45:21 [IKEv1 DEBUG]Group = x.x.x.x, IP = x.x.x.x, constructing hash payload
Apr 06 00:45:21 [IKEv1 DEBUG]Group = x.x.x.x, IP = x.x.x.x, Computing hash for ISAKMP
Apr 06 00:45:21 [IKEv1 DEBUG]Group = x.x.x.x, IP = x.x.x.x, constructing dpd vid payload
Apr 06 00:45:21 [IKEv1]IP = x.x.x.x, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + ID (5) + HASH (8) + VENDOR (13) + NONE (0) total length : 110
Apr 06 00:45:29 [IKEv1]IP = x.x.x.x, IKE_DECODE RECEIVED Message (msgid=c0ea3190) with payloads : HDR + NOTIFY (11) + NONE (0) total length : 220
Apr 06 00:45:29 [IKEv1]IP = x.x.x.x, IKE_DECODE RECEIVED Message (msgid=c0ea3190) with payloads : HDR + NOTIFY (11) + NONE (0) total length : 220
Apr 06 00:45:29 [IKEv1]Group = x.x.x.x, IP = x.x.x.x, Received an un-encrypted INVALID_COOKIE notify message, dropping
[/box]
Solution
So we can see phase 1 (ISAKMP v1) isn’t establishing, I’ve seen this happen before, you need to get the ASA to specify its IP address as its identification.
Site to Site VPN’s either work faultlessly straight away, or involve head scratching and a call to Cisco TAC, or someone like me to come and take a look. If I’m honest, the simplest and best answer to the problem is “Remove the Tunnel from both ends and put it back again”. Just about every VPN tunnel I’ve put in that did not work, was a result of my fat fingers putting in the wrong subnet, IP address or shared secret.
However you can’t always remove the tunnel and start again, especially if you only have control of your end of the tunnel. In that case you need to do some troubleshooting and debugging.
Solution
To Troubleshoot and debug a VPN tunnel you need to have an appreciation of how VPN Tunnels work READ THIS.
Now you have read that you are an expert on IKE VPN Tunnels 🙂
Step 1
To bring up a VPN tunnel you need to generate some “Interesting Traffic” Start by attempting to send some traffic over the VPN tunnel.
User Access Verification
Password:
Type help or '?' for a list of available commands.
PetesASA> enable
Password: ********
PetesASA# show crypto isakmp
[/box]
You may see a lot more information if you have Existing VPN tunnels, but what you are looking for is this,
[box]
IKEv1 SAs:
Active SA: 2
Rekey SA: 0 (A tunnel will report 1 Active and 1 Rekey SA during rekey)
Total IKE SA: 2
1 IKE Peer: 123.123.123.123
Type : L2L Role : initiator
Rekey : no State : MM_ACTIVE <<YOUR SIDE BROUGHT THE VPN UP
There are no IKEv2 SAs
[/box]
If you see MM_ACTIVE (This means phase 1 has completed in Main Mode, and is active) So phase 1 has completed successfully, you need to jump forward and troubleshoot Phase 2.
Note: If you see AG_{something} this means you are trying to bring the tunnel up in aggressive mode!
If there is nothing listed at all – then your side is not even trying to bring up the tunnel. Try and generate a lot of VPN traffic – Like a persistent ping {ping 192.168.1.1 -t} and issue the show crypto isakmp command a few times to be sure. if you never see anything then its not getting as far as phase 1!
If your still reading this, then your problem is with Phase 1, and you have an ISAKMPSA state error.
ISAKMP SA MESSAGE STATES (On the Initiator)
MM_WAIT_MSG2
Message 1 has been sent to the responder but there has been no reply.
Causes:
1. There is no network connectivity to the firewallsecurity device at the other end, can you ping it?
2. The IP address of the far firewall is incorrect in the tunnel-group, issue a “show run tunnel-group” command, check you have a tunnel group with the correct IP address.
3. The IP address in the “Crypto Map” is incorrect, issue a “show run crypto map” command and check the line that ends “crypto map {name} {number} set peer xxx.xxx.xxx.xxx” to make sure.
4. You do not have a matching phase 1 policy with the other end, issue a “show run crypto isakmp” command make sure the other end has a matching policy, if you cant check the other end then generate some VPN traffic, issue the following command and check for the following,
[box]
EXAMPLE PHASE 1 POLICIES DONT MATCH
Password: Type help or ‘?’ for a list of available commands. PetesASA> en Password: ******** PetesASA#debug crypto isakmp 200
<<<<<<<LOTS Of DEBUG TEXT REMOVED>>>>>>>
Apr 01 14:48:48 [IKEv1]: IP = 123.123.123.123, IKE_DECODE RECEIVED Message (msgid=ce4a3ffe) with payloads : HDR + NOTIFY (11) + NONE (0) total length : 56 Apr 01 14:48:48 [IKEv1]: IP = 123.123.123.123, Received an un-encrypted NO_PROPOSAL_CHOSEN notify message, dropping Apr 01 14:48:48 [IKEv1]: IP = 123.123.123.123, Information Exchange processing failed
<<<<<<<LOTS Of DEBUG TEXT REMOVED>>>>>>>
[/box]
MM_WAIT_MSG4
The Phase 1 Policies have been agreed with both peers, the initiator is waiting for the responder to send it its keying information. I’ve seen two things cause this.
1. Different Vendors equipment talking the the ASA, or simply the version of OS on the ASA have been different.
2. There is a comms error, check there’s no router with firewall capabilities in the link.
MM_WAIT_MSG6
If there’s a firewall ‘in-between’ make sure UDP port 4500 is open for both peers.
Check your Pre-Shared Keys match on the ASA issue a “more system:running-config” then keep pressing the space bar till you see the tunnel- group and shared key
Again if you can’t check the other end then issue the following debug and the following will tell you if there is a key mismatch.
This error can also be seen if one end has PFS set and the other end does not. In this case the error will appear and dissapear and the connection is repeatedly “torn down”
e.g
crypto map outside_map 20 set pfs [box]
EXAMPLE PHASE 1 PRE SHARED KEYS DONT MATCH
Password: Type help or ‘?’ for a list of available commands. PetesASA> en Password: ******** PetesASA#debug crypto isakmp 200
<<<<<<<LOTS Of DEBUG TEXT REMOVED>>>>>>>
Apr 01 15:11:47 [IKEv1]: IP = 123.123.123.123, IKE_DECODE RECEIVED Message (msgid=5456d64e) with payloads : HDR + NOTIFY (11) + NONE (0) total length : 56 Apr 01 15:11:47 [IKEv1]: Group = 123.123.123.123, IP = 123.123.123.123, Received an un-encrypted PAYLOAD_MALFORMED notify message, dropping Apr 01 15:11:47 [IKEv1]: Group = 123.123.123.123, IP = 123.123.123.123, Error, peer has indicated that something is wrong with our message. This could indicate a pre-shared key mismatch. Apr 01 15:11:47 [IKEv1]: Group = 123.123.123.123, IP = 123.123.123.123, Information Exchange processing failed
<<<<<<<LOTS Of DEBUG TEXT REMOVED>>>>>>>
[/box]
ISAKMP SA MESSAGE STATES (On the Responder)
MM_WAIT_MSG3
The Phase 1 Policies have been agreed with both peers, the responder is waiting for the initiator to send it its keying information. I’ve seen two things cause this.
1. Different Vendors equipment talking the the ASA, or simply the version of OS on the ASA have been different.
2. There is a comms error, check there’s no router with firewall capabilities in the link.
3. I’ve seen this on a VPN from a VMware Edge Gateway, that had PFS (perfect forward secrecy) enabled, and the ASA did not.
If there’s a firewall ‘in-between’ make sure UDP port 4500 is open for both peers.
Here’s an Example of Phase one completing message by message successfully.
MESSAGE 1 (Leaving the Initiator)
[box]
Apr 01 11:38:51 [IKEv1]: IP = 123.123.123.123, IKE Initiator: New Phase 1, Intf inside, IKE Peer 123.123.123.123 local Proxy Address 192.168.1.0, remote Proxy Address 172.16.1.0, Crypto map (outside_map) Apr 01 11:38:51 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing ISAKMP SA payload Apr 01 11:38:51 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing NAT-Traversal VID ver 02 payload Apr 01 11:38:51 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing NAT-Traversal VID ver 03 payload Apr 01 11:38:51 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing NAT-Traversal VID ver RFC payload Apr 01 11:38:51 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing Fragmentation VID + extended capabilities payload Apr 01 11:38:51 [IKEv1]: IP = 123.123.123.123, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 168
[/box]
MESSAGE 2 (Arriving at the Responder)
[box]
Apr 01 11:38:52 [IKEv1]: IP = 123.123.123.123, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + SA (1) + VENDOR (13) + NONE (0) total length : 117
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, processing SA payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, Oakley proposal is acceptable
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, processing VID payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing ke payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing nonce payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing Cisco Unity VID payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing xauth V6 VID payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, Send IOS VID
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, Constructing ASA spoofing IOS Vendor ID payload (version: 1.0.0, capabilities: 20000001)
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, constructing VID payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, Send Altiga/Cisco VPN3000/Cisco ASA GW VID
[/box]
MESSAGE 3 (Leaving the Initiator)
[box]
Apr 01 11:38:52 [IKEv1]: IP = 123.123.123.123, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + KE (4) + NONCE (10) + VENDOR (13) + VENDOR (13) + VENDOR (13) + VENDOR (13) + NONE (0) total length : 256
[/box]
MESSAGE 4 (Arriving at the Initiator)
[box]
Apr 01 11:38:52 [IKEv1]: IP = 123.123.123.123, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + KE (4) + NONCE (10) + NONE (0) total length : 228
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, processing ke payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, processing ISA_KE payload
Apr 01 11:38:52 [IKEv1 DEBUG]: IP = 123.123.123.123, processing nonce payload
[/box]
MESSAGE 5 (Leaving the Initiator)
[box]
Apr 01 11:38:52 [IKEv1]: IP = 123.123.123.123, Connection landed on tunnel_group 123.123.123.123
Apr 01 11:38:52 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, Generating keys for Initiator...
Apr 01 11:38:52 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, constructing ID payload
Apr 01 11:38:52 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, constructing hash payload
Apr 01 11:38:52 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, Computing hash for ISAKMP
Apr 01 11:38:52 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, constructing dpd vid payload
Apr 01 11:38:52 [IKEv1]: IP = 123.123.123.123, IKE_DECODE SENDING Message (msgid=0) with payloads : HDR + ID (5) + HASH (8) + VENDOR (13) + NONE (0) total length : 84
[/box]
MESSAGE 6 (Arriving at the Initiator)
[box]
Apr 01 11:38:53 [IKEv1]: IP = 123.123.123.123, IKE_DECODE RECEIVED Message (msgid=0) with payloads : HDR + ID (5) + HASH (8) + NONE (0) total length : 64
Apr 01 11:38:53 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, processing ID payload
Apr 01 11:38:53 [IKEv1 DECODE]: Group = 123.123.123.123, IP = 123.123.123.123, ID_IPV4_ADDR ID received 123.123.123.123
Apr 01 11:38:53 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, processing hash payload
Apr 01 11:38:53 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, Computing hash for ISAKMP
Apr 01 11:38:53 [IKEv1]: IP = 123.123.123.123, Connection landed on tunnel_group 123.123.123.123
Apr 01 11:38:53 [IKEv1 DEBUG]: Group = 123.123.123.123, IP = 123.123.123.123, Oakley begin quick mode
Apr 01 11:38:53 [IKEv1 DECODE]: Group = 123.123.123.123, IP = 123.123.123.123, IKE Initiator starting QM: msg id = 26f952ae
Apr 01 11:38:53 [IKEv1]: Group = 123.123.123.123, IP = 123.123.123.123, PHASE 1 COMPLETED
[/box]
Note: You can debug Phase 1 traffic on a particular tunnel, with the following command.
debug crypto condition peer 123.123.123.123
or, simply;
debug crypto isakmp
Phase 1 Debug Errors
[box]
Petes-ASA((config)# debug crypto isakmp
Feb 29 11:49:08 [IKEv1]Group = 123.123.123.123, IP = 123.123.123.123, QM FSM error (P2 struct &0x00007fda92308b10, mess id 0xc02b7a5d)!
Feb 29 11:49:08 [IKEv1]Group = 123.123.123.123, IP = 123.123.123.123, Removing peer from correlator table failed, no match!
Feb 29 11:49:08 [IKEv1]Group = 123.123.123.123, IP = 123.123.123.123, Session is being torn down. Reason: crypto map policy not found
[/box]
This was due to more than one misconfiguration, firstly the source and destination network objects in the interesting traffic ACL were the wrong way round! (Don’t forget to check your static NAT statement as well). And the TRANSFORM SET didn’t match, (sometimes you can see phase one established but then it disappears).
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
[box]
Petes-ASA((config)# debug crypto ikev1
Apr 19 16:36:10 [IKEv1]IP = 123.123.123.123, No Group found by matching OU(s) from ID payload: Unknown
Apr 19 16:36:10 [IKEv1]IP = 123.123.123.123, Trying to find group via IKE ID...
Apr 19 16:36:10 [IKEv1]IP = 123.123.123.123, Trying to find group via IP ADDR...
Apr 19 16:36:10 [IKEv1]IP = 123.123.123.123, Connection landed on tunnel_group 123.123.123.123
Apr 19 16:36:10 [IKEv1 DEBUG]Group = 123.123.123.123, IP = 123.123.123.123, peer ID type 2 received (FQDN)Apr 19 16:36:10 [IKEv1]Group = 123.123.123.123, IP = 123.123.123.123, Unable to compare IKE ID against peer cert Subject Alt Name
Apr 19 16:36:10 [IKEv1 DEBUG]Group = 123.123.123.123, IP = 123.123.123.123, IKE MM Responder FSM error history (struct &0x00007ffd9e230670) <state>, <event>: MM_DONE, EV_ERROR-->MM_BLD_MSG6, EV_COMPARE_IDS-->MM_BLD_MSG6, EV_CERT_OK-->MM_BLD_MSG6, NullEvent-->MM_BLD_MSG6, EV_ACTIVATE_NEW_SA-->MM_BLD_MSG6, NullEvent-->MM_BLD_MSG6, EV_VALIDATE_CERT-->MM_BLD_MSG6, EV_UPDATE_CERT
Apr 19 16:36:10 [IKEv1 DEBUG]Group = 123.123.123.123, IP = 123.123.123.123, IKE SA MM:3a1ed893 terminating: flags 0x01018002, refcnt 0, tuncnt 0
Apr 19 16:36:10 [IKEv1 DEBUG]Group = 123.123.123.123, IP = 123.123.123.123, sending delete/delete with reason message
[/box]
The ASA did not like the certificate presented by the remote peer, (Even though is was a good cert issued by NDES). To get past this you need to make a change to the tunnel group.
Petes-ASA((config)# debug crypto ikev1
%ASA-3-717009: Certificate validation failed. Peer certificate key usage is invalid, serial number: 6B00002B3F8571E2605FA02883000100002C3E, subject name: hostname=Petes-Router-Petes-HQ.petenetlive.com.
%ASA-3-717027: Certificate chain failed validation. Certificate chain is either invalid or not authorized.
[/box]
The ASA did not like the certificate presented by the remote peer, (Even though is was a good cert issued by NDES). To get past this you need to make a change to the trustpoint on the ASA.
[box]
Petes-ASA(config)# crypto ca trustpoint PNL-Trustpoint
Petes-ASA(config-ca-trustpoint)# ignore-ipsec-keyusage
[/box]
-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
[box]
Petes-ASA# debug crypto ikev1
Petes-ASA# Feb 17 12:25:17 [IKEv1]Group = 123.123.123.123, IP = 123.123.123.123, Received encrypted Oakley Main Mode packet with invalid payloads, MessID = 0
Feb 17 12:25:17 [IKEv1]Group = 212.20.251.44, IP = 123.123.123.123, ERROR, had problems decrypting packet, probably due to mismatched pre-shared key. Aborting
Feb 17 12:25:23 [IKEv1]IP = 123.123.123.123, Header invalid, missing SA payload! (next payload = 4)
\
[/box]
Amazingly this had nothing to do with a mismatched pre shared key, the other end was set to use PFS (Perfect Forward Secrecy,) and my end (the ASA) was not.
If you have got this far the next step is to troubleshoot Phase 2
Related Articles, References, Credits, or External Links
This article is NOT intended to be a ‘fix all” for phase 2 problems, it’s designed to point you in the right direction to locate the source of the problem.
1. Before you start: We are looking at phase 2 problems, MAKE SURE phase 1 has established!
[box]
Petes-ASA>
Petes-ASA> en
Password: ********
Petes-ASA# show crypto isakmp
IKEv1 SAs:
Active SA: 1 Rekey SA: 0 (A tunnel will report 1 Active and 1 Rekey SA during rekey)
Total IKE SA: 1
1 IKE Peer: 234.234.234.234
Type : L2L Role : responder
Rekey : no State : MM_ACTIVE <<<< Phase 1 has established!
[/box]
2. At the first site, issue a ‘show crypto ipsec sa’ command. Note: if you have a lot of tunnels and the output is confusing use a ‘show crypto ipsec sa peer 234.234.234.234’ command instead.
Note: Yes I can zero in on the problem here, but your output may be different (And if you already know why are you reading this!).
3. Check the IP addresses and networks listed highlighted in yellow are correct, then repeat for the ones highlighted in pink (I don’t care if you don’t think it’s pink! I’m a man, I see in 16 colours like a Sinclair ZX Spectrum!). Check the access-list (above shown in blue text) that access-list should be referenced in the crypto map like so;
[box]
Petes-ASA# show run crypto
{Lots of output removed for the sake of space}
crypto map outside_map 1 match address outside_38_cryptomap <<<<Good!!
crypto map outside_map 1 set pfs
crypto map outside_map 1 set peer 234.234.234.234
crypto map outside_map 1 set ikev1 transform-set ESP-3DES-SHA <<<< Only seen after v8.4!{Lots of output removed for the sake of space}
[/box]
4. Now we need to make sure that the traffic is NOT subject to NAT, issue a “show run nat” command;
[box]
Output with an Operating System Newer than 8.3
Petes-ASA# show run nat
{Lots of output removed for the sake of space}
nat (inside,outside) source static NETWORK_OBJ_192.168.1.0_24 NETWORK_OBJ_192.168.1.0_24 destination static NETWORK_192.168.2.0_24 NETWORK_OBJ_192.168.2.0_2
{Lots of output removed for the sake of space}
Petes-ASA# show run object network <<<<Lets check those objects exist
object network obj_any
subnet 0.0.0.0 0.0.0.0
object network NETWORK_OBJ_192.168.1.0_24
subnet 192.168.1.0 255.255.255.0
object network NETWORK_OBJ_192.168.2.0_24
subnet 192.168.2.0 255.255.255.0
Output with an Operating System Older than 8.3
Petes-ASA# show run nat
nat (inside) 0 access-list inside_nat0_outbound
nat (inside) 1 192.168.1.0 255.255.255.0
Petes-ASA# show run access-list inside_nat0_outbound <<<<Lets make sure that ACL is correct
access-list inside_nat0_outbound extended permit ip 192.168.1.0 255.255.255.0 192.168.2.0 255.255.255.0
6. You will notice I’ve shown the SPI numbers in green, these should match (but be the opposite way round) at both ends. (Geek Note: These denote the TWO tunnels IPSEC brings up inside the original ISAKMP tunnel that it then passes information up one and down the other – like a two lane road).
7. If you compare both outputs look at the pkts encaps (in red) and the pkts decaps (in purple). In this case we can see that the tunnel is working as it should from the 234.234.234.234 site but no traffic is getting encrypted from the 123.123.123.123 site. THAT’S WHERE THE PROBLEM IS.
8. Now you know where the problem is you can issue a “debug crypto ipsec” command there. Then try to bring up the tunnel and analyse the output. Note: If debug shows nothing make sure there is NOT another crypto map pointing to the same subnet, with a different peer.
9. So on our ‘problem’ end we see something like;
So on that firewall, locate the ACL that is being used for the crypto map, and make sure its ‘hit count’ is going up as you try and send traffic over the VPN tunnel. If not then the ACL is wrong, there’s a routing problem or a subnet mask is wrong on the firewalls internal interface.
[box]
Petes-ASA# show run crypto
crypto ipsec ikev1 transform-set ESP-3DES-SHA esp-3des esp-sha-hmac
crypto map outside_map 1 match address outside_1_cryptomap << Here!
crypto map outside_map 1 set pfs
crypto map outside_map 1 set peer 234.234.234.234
crypto map outside_map 1 set ikev1 transform-set ESP-3DES-SHA
crypto map outside_map interface outside
crypto ikev1 enable outside
crypto ikev1 policy 10
authentication pre-share
encryption 3des
hash sha
group 2
lifetime 86400
Petes-ASA# show access-list outside_1_cryptomap
access-list outside_1_cryptomap; 1 element; name hash: 0xcf826bcb
access-list outside_1_cryptomap line 1 extended permit ip 192.168.1.0 255.255.255.0 192.168.2.0 255.255.255.0 (hitcnt=93) 0xf965c6f9
[/box]
10. As a last resort recycle/restart the VPN Tunnel.
11. You’ve done your best and still it wont establish! Then I would upgrade the ASA(s) to the latest OS (70% of the calls I log to Cisco TAC for VPN issues are fixed by simply upgrading them, 29% are caused by a configuration error, and 1% need a version of the operating system that has not been released yet). If you’re under warranty or Cisco SmartNet, you can then log a call to Cisco TAC. If not then I would suggest heading over to EE and asking for help. (You might even get hold of me).
Related Articles, References, Credits, or External Links
Until very recently I’d never had to configure PPPoE. Most of my clients in that sort of connection speed range have ADSL with a router provided by their ISP. A Router that connects via PPPoA usually.
Here in the UK the main ISP’s (BT and Virgin) are busy rolling out FTTC connections that terminate with a ‘modem’ that presents an RJ45 socket.
So without the need for a router, you can get the ASA to perform the authentication (supply the username and password via PPPoE) and either use a static IP address, or obtain its IP via DHCP.
Solution
1. Before you attempt to configure the connection, you will need the following from your ISP;
Username
Password
IP Details (If you have bought static IP’s you will need the range of IP addresses and the IP address to use as the firewalls default route (default gateway). Some ISP’s will expect you to configure DHCP and will make sure you always get the same IP.
Authentication method: CHAP, MSCHAP, or PAP (If your ISP acts confused when you ask, it’s probably CHAP).
2. Connect to the ASA > Go to enable mode > Go to configuration mode > Create a ‘vpdn’ group, (here I’ve called it PNL-DIALER-GROUP) > Set the authentication method, (here I’m using CHAP).
[box]
User Access Verification
Password:
Type help or '?' for a list of available commands.
PetesASA> enable
Password: ********PetesASA# configure terminal
PetesASA(config)# vpdn group PNL-DIALER-GROUP request dialout pppoe
PetesASA(config)# vpdn group PNL-DIALER-GROUP ppp authentication chap
[/box]
3. Supply your username and password. (The store-local command puts the details in a protected area of flash memory).