Building a pull-based config change notification system with Python and Slack, part 1

Hello

Moving on one step forward from simple show commands, i’d like to be able to receive notifications if there’s been a change to a routers’s configuration. There are several ways of doing this but i’ll start simple: if i find that the config file has a new timestamp, i would like to do a backup of the new config and compare it line by line with the previous backup. I can also try to look into the log buffer of the router to see logged commands (example line: User:testuser logged command:no logging console).

Having all this info should be reason enough to send a notification, e.g. to slack. For this I can use the Notifiers library.
Finally, i can use this output as the definition of done when i start implementing changes using unicon, where config delta should be equal to the config command set of the implementation task. If it’s not equal, the implementation should be investigated.

let’s get down to work then…

Comparing file timestamps

import os

filename = 'testfile.txt'
currentstamp = os.stat(filename).st_mtime
print('This is the current timestamp of the config file ' + currentstamp)
with open('cachedstamps.txt', 'r') as reader:
  oldstamp = float(reader.read())
  print('This was the old timestamp from the archived timestamp file ' + oldstamp)
f = open('cachedstamps.txt', "w")
f.write(str(currentstamp))
if currentstamp != oldstamp:
  print('As you can see, the timestamps are different! It looks like this file has been modified')
else:
  print('this file has not been modified')

This was a nice idea until I realized that nvram: files don’t have a date attached to them.

Well, on to a new idea, copying the startup file, creating a hash out of the content and comparing the hashes.

I’ve created two scripts now: the first one copies the config and makes a hash out of it, then I modify the config on the router and run the second script, which gets the modified config, the new hash, and compares the old hash versus the new hash. If they are different, the config has been modifed.

Creating hashes from the old config

def makeoldhash():
  hasher = hashlib.md5()
  with open('oldconfig.bak', 'rb') as afile:
   buf = afile.read()
   hasher.update(buf)
  print(hasher.hexdigest())
  f = open('cashedhashes.txt', "w")
  f.write(str(hasher.hexdigest()))

def getoldconfig():
  realdevicelist = devicelist.split('%')
  print(realdevicelist)
  testbed = loader.load(testbedfile)
  x = 0
  for x in range(x,len(realdevicelist)):
    devicename = realdevicelist[x]
    c = testbed.devices[devicename]
    c.connect()
    output = c.execute(command)
    f = open("oldconfig.bak", "w")
    f.write(output)
    f.close()
    c.destroy()

if name == "main":
  command = sys.argv[1]
  testbedfile = sys.argv[2]
  devicelist = sys.argv[3]

getoldconfig()
makeoldhash()

Creating hashes from updated config

from unicon import Connection
from jinja2 import Environment, FileSystemLoader
import yaml
from pyats.topology import loader
import sys
import hashlib


def getnewconfig():
  realdevicelist = devicelist.split('%')
  print(realdevicelist)
  testbed = loader.load(testbedfile)
  x = 0
  for x in range(x,len(realdevicelist)):
    devicename = realdevicelist[x]
    c = testbed.devices[devicename]
    c.connect()
    output = c.execute(command)
    f = open("modifiedconfig.bak", "w")
    f.write(output)
    f.close()
    c.destroy()

def makenewhash():
  hasher = hashlib.md5()
  with open('modifiedconfig.bak', 'rb') as afile:  
    buf = afile.read()
    hasher.update(buf)
  f = open('newhashes.txt', "w")
  f.write(str(hasher.hexdigest()))

def comparehash():
  with open('cashedhashes.txt', 'r') as reader:
    oldhash = str(reader.read())
    print(oldhash)
  with open('newhashes.txt', 'r') as reader:
    newhash = str(reader.read())
    print(newhash)
  if oldhash == newhash:
    print('identical! config has not been changed!')
  else:
    print('someone changed the config')

if name == "main":
  command = sys.argv[1]
  testbedfile = sys.argv[2]
  devicelist = sys.argv[3]

getnewconfig()
makenewhash()
comparehash()

Now i run the first script, modify the config on R1, then run the second script. I’m still using unicon so i have my old testbed.yml file with IPs, passwords. Unicon handles the connection for me so that i don’t need to worry about waiting for prompts etc.


python3 part1.py 'show run' testbed.yml R1

(here i modified the config)

python3 part2.py 'show run' testbed.yml R1

The result is:

9af95565fda2b8e4d40b04edc26d146c
a03c81972dd99787e7f31542f3a53dbe
someone changed the config

Now i need to build the part where the script notifies Slack that the first script has been run (always early in the morning, so that i get an updated hash), and then before midnight i need another notification that part2 has been run (where i get the new hash), the second script should then compare the hashes and tell me if the config has been changed. If it has been changed, another script should run, which should compare the config files and give me the delta. Ideally, it should also get some info from the router’s log buffer about the logging time and commands.

Notifying Slack

To notify Slack, i’ve reworked the comparehash method. Your Slack webhook url needs to be used so that the app can connect to your Slack channel.

def comparehash():
  with open('cashedhashes.txt', 'r') as reader:
    oldhash = str(reader.read())
    print('the old hash from this mornings config is ' + oldhash)
  with open('newhashes.txt', 'r') as reader:
    newhash = str(reader.read())
    print('the new hash from current config is ' + newhash)
  if oldhash == newhash:
    print('the hashes are identical! This means that config on this router has not been changed!')
    p = get_notifier('slack')
    p.notify(webhook_url='yourslackwebhookurl', message='config on this router has not been changed today!')
  else:
    print('hashes are different! This may mean that someone changed the config')
    p = get_notifier('slack')
    p.notify(webhook_url='yourslackwebhookurl', message='Hello network team. This is the report for R1, 12 oct 2020. Id like to report that the config on this router has been changed today! Investigating…')

if name == "main":
  command = sys.argv[1]
  testbedfile = sys.argv[2]
  devicelist = sys.argv[3]

getnewconfig()
makenewhash()
comparehash()

running the updated script again…

R1#
the old hash from this mornings config is 9af95565fda2b8e4d40b04edc26d146c
the new hash from current config is a03c81972dd99787e7f31542f3a53dbe
hashes are different! This may mean that someone changed the config

The next step: comparing the config change with Diffios and reporting the changes to slack + getting user logins from log buffer to see who has made the changes.
Finally, I would like to reverse the logic: it is the router which should notify a service on my script server (the moment the config has been changed), which in turn should trigger slack notification (=a push-based notification system) or at least the app should monitor the slack channel constantly (a continous pull-based system) for any inputs from the slack user, while the bot should answer with router outputs, something like:
Hello Tom, run ‚show ip int brief’ on R1
App should parse this input, execute the command on R1 and the bot should return the output in the channel.

Show commands on groups of devices using Unicon and .yml hostfiles

Hello

After I created a script in Netmiko that connected to a number of devices to create an uptime report, I thought it would be nice to do a similar thing using Unicon. It was a much easier job.

here’s the python code that does the magic:

from unicon import Connection
from jinja2 import Environment, FileSystemLoader
import yaml
from pyats.topology import loader
import sys

def executeshowongroup(command,testbedfile,devicelist):
  realdevicelist = devicelist.split('%')
  print(realdevicelist)
  testbed = loader.load(testbedfile)
  x = 0
  
  for x in range(x,len(realdevicelist)):
    devicename = realdevicelist[x]
    c = testbed.devices[devicename]
    c.connect()
    c.execute(command)

if name == "main":
  command = sys.argv[1]
  testbedfile = sys.argv[2]
  devicelist = sys.argv[3]

executeshowongroup(command,testbedfile,devicelist)

and here’s the testbed.yml:

devices:
  myproxy:
   os: linux
   type: linux
   credentials:
    default:
     username: cisco
     password: cisco
    connections:
     cli:
      protocol: ssh
      ip: 1.1.1.1
      port: 722
   router1:
    os: ios
    type: router
    connections:
     defaults:
     class: unicon.Unicon
     cli:
      command: connect router1
      proxy: myproxy
   router2:
    os: ios
    type: router
    connections:
     defaults:
     class: unicon.Unicon
     cli:
      command: connect router2
      proxy: myproxy

Now I run the script with:

python3 unicongroupscript.py ‚show ip int brief’ newtestbed.yml router1%router2


It’s important to notice what is NOT in this script: gone are the time.sleep() commands, so i don’t need to worry if my proxy is particularly slow on any given day. I get the output much, much faster than in the case of netmiko. And the whole logic is done in python, unlike in Ansible where I’m artificially limited to the yaml syntax.

This is really, really cool stuff. One thing that is missing is the built-in group functionality in the testbed file, so scripts need to be run on individual hosts (or like in my case: with groups of hosts where delimiter between each host is %). I’ll try to talk to Cisco about this.

Creating a nice html-like uptime report with Pandas

This time it’s a dry-run, so instead of polling routers, i use ready strings ‚processor is …’. If you haven’t read the previous posts: in the full version of the script, i poll the router using Netmiko, issue the command ”show version”, take the bit with the uptime and process this paragraph to create a report, for example i want to know if the router has reloaded recently.

I’m using pandas with a nested dictionary to create a HTML table with values. If the script finds the word ”week”, and if the number > 4, it’s a success, otherwise it’s a partial failure (=<4) or a failure (word ”week” not found).

import re
import pandas as pd

test_results = {}
endresultstring = "processor is 3 days"
if bool(re.findall(r'(week)', endresultstring)):
   if int(str(re.findall(r'[0-9]+', endresultstring)[0])) > 4:
      test_results.update( {'R1' : {'uptime test': 'success'}})
   else:
      test_results.update( {'R1' : {'uptime test': 'partial failure'}})
else:
   test_results.update( {'R1' : {'uptime test': 'failure'}})

endresultstring = "processor is 3 weeks"
if bool(re.findall(r'(week)', endresultstring)):
   if int(str(re.findall(r'[0-9]+', endresultstring)[0])) > 4:
      test_results.update( {'R2' : {'uptime test': 'success'}})
   else:
      test_results.update( {'R2' : {'uptime test': 'partial failure'}})
else:
   test_results.update( {'R2' : {'uptime test': 'failure'}})

endresultstring = "processor is 5 weeks"
if bool(re.findall(r'(week)', endresultstring)):
   if int(str(re.findall(r'[0-9]+', endresultstring)[0])) > 4:
      test_results.update( {'R3' : {'uptime test': 'success'}})   
   else:
      test_results.update( {'R3' : {'uptime test': 'partial failure'}})
else:
   test_results.update( {'R3' : {'uptime test': 'failure'}})
df = pd.DataFrame(data=test_results)
df = df.fillna(' ').T
print(df)

Output is very nice:

Getting clear uptime data from Cisco router

Hello

Every larger IT company has some kind of infrastructure to monitor if routers are up or down. But in some companies, this data is relatively hard to get because the monitoring server can be hidden behind some ssl vpn gateways, and it takes up to 10 minutes to see if a router is/has been down, so nobody ever checks it. Due to how event engines are configured, if a router reloads, an incident will not be created and the support team will never know that a router has reloaded.

I don’t like being in the dark so I got down to work.

Of course, it is very easy to write up a script that gets output of show version from a cisco router to see the uptime. But the problem becomes more acute if you have hundreds of routers. Then you’d not be interested in plowing through hundreds of uptime lines, you’d want to get alarms only, like ”watch out, this router has been down recently because uptime is short”.
Because I will be running my script every now and again only, i’m only interested to see if the router has been down in the last 4 weeks so i cut off the details (days, minutes).

I rewrote the last script a bit to do just that: I take output of show version, find the uptime, turn uptime into a score and spit out the status: ok or not ok.

myrouters = {"R1": {"RouterOne": "172.16.0.1"}, "R2": {"RouterTwo": "172.16.0.2"}, "R3": {"RouterThree": "172.16.0.3"}, "R4": {"RouterFour": "172.16.0.4"}}

#this loop will go through the dictionary of dictionaries, connect to each router using its IP (subval), issue show version command
 
for mainkey in myrouters.keys():
    mainval = myrouters[mainkey]
    for subkey in mainval.keys():
      subval = mainval[subkey]
      print('i am now on router ' + subkey + ' , its IP address is ' + subval)
      net_connect.write_channel("connect " + subval + " \n")
      time.sleep(3)
      redispatch(net_connect, device_type="cisco_ios")
      net_connect.enable
      result = net_connect.send_command_timing("show ver")

#here i initiate an empty list, because re.findall returns a list

      endresult = []
      endresult = re.findall(r'processor .*?minutes', result)
      endresult.insert(0,subkey)
      endresultstring = endresult[1]

    #This string contains just the phrase 'processor is up 4 weeks'
    #next i query if the phrase contain the word 'week' and if it does, i take this string and make a list of digits from it, join the digits, thus making a number of weeks. There must be a better way to do this... 

      foundweeks = bool(re.findall(r'(week)', endresultstring))
      if foundweeks:
        numberweeks = re.findall(r'.*?weeks', endresultstring)
        listweeks = str(numberweeks)
        stringweeks = str(listweeks[2:23])
        processweeks = re.findall(r'\d', stringweeks)
        numberweeks = ''.join(map(str,processweeks))

    #here i calculate a score (weeks times 25)  
      
        finalscore = int(numberweeks)*25
        if finalscore>100:
            print("This router is just fine! It has been up over " + str(int(finalscore)/25) + " weeks")
        else:
            print("oh no! it's been down in the last 4 weeks! you'd better check this router")

And the output is as follows:

i am now on router R1 whose name is RouterOne and IP is 172.16.0.1
This router is just fine! It has been up over 11.0 weeks

i am now on router R2 whose name is RouterTwo and IP is 172.16.0.2
This router is just fine! It has been up over 41.0 weeks

i am now on router R3 whose name is RouterThree and IP is 172.16.0.3
This router is just fine! It has been up over 29.0 weeks

i am now on router R4 whose name is RouterFour and IP is 172.16.0.4
This router is just fine! It has been up over 28.0 weeks

Eventually I found this code to be so obnoxiously wordy that I rewrote the last part (taking the number of lines from 12 to 7) changing the logic slightly: if the word ‚week’ is found in the part of uptime output, the output will be empty; otherwise the router has been down lately and something is printed out, depending on whether the number of weeks is between 1 and 4, or below 1.

if bool(re.findall(r'(week)', endresultstring)):
   if int(str(re.findall(r'[0-9]+', endresultstring)[0])) > 4:
      pass
   else:
      print("oh no! it's been down in the last 4 weeks! you'd better check this router")
else:
   print("This router has been down in the last week!!!")

Iterating through dictionary of dictionaries to get data from multiple routers behind a custom proxy using Netmiko

I’ve been wanting to improve my netmiko script which connects to a custom (non-ssh) proxy, connects to a few routers there and outputs some info.

I’m doing a few things here: first is a dictionary of dictionaries myrouters. Then I create an embedded loop which first goes through the main key (R1, R2, R3) and then through the subkeys of the embedded dictionary (Berlinrouter etc.).

Then I use a simple regex re.findall(r’Uptime .?minutes’, result) to only get uptime and another regex to get the serial number from output of the show version command.

Finally, i want to know how long eigrp tunnels have been up (because it’s not necessarily the same as router uptime) but the string that I get from show ip eigrp neighour is a bit complex so I split it into a list and take some elements from the list. By the way the way I do this below is really not optimal so reworking could involve textfsm templates (mentioned a few posts back) . Unfortunately I can’t spontaneously come up with a nice regex to only get what i want from the output even after grepping it.

from netmiko import ConnectHandler
import time
from netmiko import redispatch
import re
jumpserver= {'device_type':'terminal_server','ip':'1.1.1.1','username':'cisco','password':'cisco','port':22,'global_delay_factor':2,'session_log': 'output.txt'}
net_connect=ConnectHandler(**jumpserver)
net_connect.find_prompt()
myrouters = {"R1": {"FrankfurtRouter": "192.168.0.1"}, "R2": {"BerlinRouter": "192.168.0.2"}, "R3": {"Hamburgrouter": "192.168.0.3"}}
for mainkey in myrouters.keys():
mainval = myrouters[mainkey]
for subkey in mainval.keys():
subval = mainval[subkey]
print('i am now on router ' + mainkey + ' whose name is ' + subkey + ' and IP is ' + subval)
net_connect.write_channel("connect " + subval + " \n")
time.sleep(3)
redispatch(net_connect, device_type="cisco_ios")
net_connect.enable
result = net_connect.send_command_timing("show ver")
endresult = re.findall(r'Uptime .?minutes', result) endresult.insert(0,subkey)
print(endresult)
time.sleep(1)
newresult = net_connect.send_command_timing("show version")
endresultser = re.findall(r'Processor .', newresult)
endresultser.insert(0,subkey)
print(endresultser)
time.sleep(1)
eigrpresult = net_connect.send_command_timing("show ip eigrp vrf 1001 nei 172.16.0.1 | i Tu1001")
eigrpresult.split()
print("For " + subkey + " eigrp datatunnel uptime is " + eigrpresult[55:62])
net_connect.write_channel("exit\n")
time.sleep(1)

and the output…

i am now in mainkey R1 whose name is FrankfurtRouter and IP is 192.168.0.1
[‚FrankfurtRouter’, ‚Uptime for this control processor is 11 weeks, 3 hours, 53 minutes’]
[‚FrankfurtRouter’, ‚Processor board ID FCZ3557C1AL’]
For FrankfurtRouter eigrp datatunnel uptime is 4w4d
i am now in mainkey R2 whose name is BerlinRouter and IP is 192.168.0.2
[‚BerlinRouter’, ‚Uptime for this control processor is 41 weeks, 2 days, 17 hours, 18 minutes’]
[‚BerlinRouter’, ‚Processor board ID FCZ8445C1AH’]
For BerlinRouter eigrp datatunnel uptime is 4w4d
i am now in mainkey R3 whose name is Hamburgrouter and IP is 192.168.0.3
[‚Hamburgrouter’, ‚Uptime for this control processor is 29 weeks, 21 hours, 38 minutes’]
[‚Hamburgrouter’, ‚Processor board ID FCZ368990W7’]
For Hamburgrouter eigrp datatunnel uptime is 2d06h

One important thing to mention here is that I use some time.sleep stuff, which I personally don’t like. It would be a better idea to use pexpect to wait for router prompts, but pexpect library won’t work on python in Windows. You’d need to run it from a Linux machine.

Vagaries of ikev2

A bit of a break from programming because i have oodles of work.

One of the main tasks where I work is creating and changing VPN tunnels with other companies so I normally feel pretty confident that I can set up a tunnel in a few minutes. However, recently I came across an interesting case where ikev1 and ikev2 behaved differently (presenting different show outputs) if the same error was present in the vpn config. Unfortunately, i started with ikev2 which showed a bizarre output so I wrongly assumed a bug and spent hours and hours trying to find the problem.
Let’s say we have multiple crypto map tunnels from the hub R1 to R2,R3, R4 with the crypto map entries in the following order:

crypto map MYMAP 12 ipsec isakmp

crypto acl R1>R2

permit ip 192.168.0.0 0.0.0.255 10.0.0.0 0.0.255.255

ip route 10.0.1.0 255.255.255.0 <R2 peer IP>

crypto map MYMAP 13 ipsec isakmp

crypto acl R1>R3

permit ip 192.168.0.0 0.0.0.255 172.16.0.0 0.0.0.255

crypto map MYMAP 14 ipsec isakmp

crypto acl R1>R4

permit ip 192.168.0.0 0.0.0.255 10.0.100.0 0.0.0.255

permit ip 192.168.0.0 0.0.0.255 192.168.1.0 0.0.0.255

ip route 10.0.100.0 255.255.255.0 <R4 peer IP>

If you have a lot of experience with vpn’s, you might have already spotted the problem. R4’s subnet is a subset of R2’s subnet so there will be a problem and it’s easy to see if you have 4 tunnels, but a bit more difficult if you have hundreds of tunnels.
Now a series of interesting things will happen: R1>R2 will be fine, same as R1>R3. In case of R1>R4, let’s additionally assume that in case of the first SA, the application on the side of R4 will try initiate a connection to the side of R1, but in case of the second SA, the application on R1 side will initiate a connection to R4. What will happen now?
In case of ikev1: second SA will form just fine, but the first SA will fail with error ‚Peer not found’ on R1, and Phase 2 mismatch on R4 because R4 will receive 10.0.0.0 proxy from R1 instead of 10.0.100.0. This is despite the fact that routing in both cases is fine (only routes to /24 networks are present through peers). This is because routing is secondary to ISAKMP and IPSEC negotiations.

In case of ikev2: both SAs will form (!) and you will see (crypto session remote <ip of r4> details) that packets from 10.0.100.0 are decrypted, but then these packets will disappear in the bitbucket.

I can’t tell you how much time I spent looking up the significance of error ”peer not found”. What it means basically is that when a peer router sends us phase 2 policies (proxies), the match is found for a different peer (higher in crypto map hierarchy).

I will try to lab this up this week.

ChatOps – Ansible gets status from router, notifies Slack channel

Hello

Just a teaser of the idea that i’m toying with while i’m still working hard on the automation post. The idea of chatops is that your automation scripts should send status notifications (or any other notifications) to a common workspace, such as Slack. I would love to see daily statuses of my routers in my slack channel:
R1: ok
R2: ok
R3: nok

The other direction is also possible (oh the chaos an attacker could wreak upon the network with this one) : it is possible to actually run scripts from Slack.

For now i’ve just registered my slack account, created an app, and ran a test curl command from my VM to the slack channel. I’ll try to built a slack notification into my ansible scripts now.

chatops

Obviously I couldn’t leave this at this unfinished stage 😀 I took my ansible playbook and modified it:

- name: add_entry_to_acl 
  hosts: testrouter
  tasks:
   - name: add_new_entry
     ios_config:
     lines:
     - "{{ acl20 }}" 
     parents: ip access-list extended permit_www
     before: ip access-list extended permit_www 
     save_when: modified
   - name: send notification to Slack
     local_action:
     module: slack
     token: <here enter your slack webhook token>
     channel: "#things"
     msg: "Name of the host is {{ ansible_net_hostname }} and the software version is {{ ansible_net_version }} while the platform is {{ ansible_net_model }}"

 

tode@ubuntu:~/ansiblefolder$ ansible-playbook aclplaybook.yml

PLAY [add_entry_to_acl] ********************************************************

TASK [Gathering Facts] *********************************************************
[WARNING]: Ignoring timeout(10) for ios_facts
[WARNING]: default value for `gather_subset` will be changed to `min` from
`!config` v2.11 onwards
ok: [testrouter]

TASK [add_new_entry] ***********************************************************
changed: [testrouter]

TASK [show clock] **************************************************************
ok: [testrouter]

TASK [send notification to Slack] **********************************************
ok: [testrouter -> localhost]

PLAY RECAP *********************************************************************
testrouter : ok=4 changed=1 unreachable=0 failed=0 skipped=0 rescued=0 ignored=0

 

and voila:

final_chat

 

Cisco IOS-XE ikev2 Denial of Service vulnerability, June 2020, fixed in 16.9.4

Hello

This may not exactly be breaking news but just to let you know that this ikev2 CVE has been out there since June. Unfortunately, there is no workaround. Even if you implement your crypto call control with max SAs, it simply means that this attack will fill up the maximum number of SA’s. I guess it’s time to upgrade your routers again…

https://tools.cisco.com/security/center/content/CiscoSecurityAdvisory/cisco-sa-ikev2-9p23Jj2a

 

IPsec preferred peer + reverse route static

Hello

A bit of a pause with automation this week. I’ve been assigned a task to set up a redundant crypto-based VPN, a task which is in fact quite easy but for some weird reason Cisco documentation doesn’t describe how to do this in the peer preferred feature.
The problem is here that you can’t set up static routes with a track object because there’s nothing to link the track object to if you don’t have logical tunnel interfaces. Of course, there’s always EEM scripts that could activate routes if it sees ”tunnel up/down” events in the syslog but… let’s be serious. Besides, I was curious to see how fast this redundancy works.
vpn_redundancy

R1 has 1.1.1.1, both R2 and R3 have 2.2.2.2 as their loopback to simulate redundant LANs behind them (e.g. distributed data center)

crypto isakmp policy 10
encr 3des
authentication pre-share
group 5
crypto isakmp key cisco address 0.0.0.0
crypto isakmp keepalive 10
crypto ipsec transform-set MYSET esp-3des esp-sha-hmac
mode tunnel
crypto map MYMAP 10 ipsec-isakmp
set peer 101.1.1.1 default !!!by default tunnel goes to R2
set peer 102.1.1.1 !!! if keepalives (DPD) to R2 fail, tunnel is initiated to R3
set transform-set MYSET
match address MYACL
reverse-route static !!!this installs routes to 2.2.2.2 dynamically based on ACL and state of DPD
crypto map MYMAP


ip access-list ext MYACL
permit ip host 1.1.1.1 2.2.2.2

int loopback0
ip addr 1.1.1.1 255.255.255.255

 

Now let’s ping 2.2.2.2 from R1’s 1.1.1.1 when R2 and R3 are up with crypto isakmp debug on.

IOU1#ping 2.2.2.2 source 1.1.1.1
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 2.2.2.2, timeout is 2 seconds:
Packet sent with a source address of 1.1.1.1

*Aug 7 03:11:44.860: ISAKMP:(0): SA request profile is (NULL)
*Aug 7 03:11:44.860: ISAKMP: Created a peer struct for 101.1.1.1, peer port 500
*Aug 7 03:11:44.860: ISAKMP: New peer created peer = 0xF2F1E4D8 peer_handle = 0x80000006
*Aug 7 03:11:44.860: ISAKMP: Locking peer struct 0xF2F1E4D8, refcount 1 for isakmp_initiator
*Aug 7 03:11:44.860: ISAKMP: local port 500, remote port 500
*Aug 7 03:11:44.860: ISAKMP: set new node 0 to QM_IDLE
*Aug 7 03:11:44.860: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = F2F30F50
*Aug 7 03:11:44.860: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
*Aug 7 03:11:44.860: ISAKMP:(0):found peer pre-shared key matching 101.1.1.1
*Aug 7 03:11:44.860: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
*Aug 7 03:11:44.860: ISAKMP:(0): constructed NAT-T vendor-07 ID
*Aug 7 03:11:44.860: ISAKMP:(0): constructed NAT-T vendor-03 ID
*Aug 7 03:11:44.860: ISAKMP:(0): constructed NAT-T vendor-02 ID
*Aug 7 03:11:44.860: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
*Aug 7 03:11:44.860: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

*Aug 7 03:11:44.860: ISAKMP:(0): beginning Main Mode exchange
*Aug 7 03:11:44.860: ISAKMP:(0): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_NO_STATE
*Aug 7 03:11:44.860: ISAKMP:(0):Sending an IKE IPv4 Packet.
*Aug 7 03:11:44.863: ISAKMP (0): received packet from 101.1.1.1 dport 500 sport 500 Global (I) MM_NO_STATE
*Aug 7 03:11:44.863: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Aug 7 03:11:44.863: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_I_MM2

*Aug 7 03:11:44.863: ISAKMP:(0): processing SA payload. message ID = 0
*Aug 7 03:11:44.863: ISAKMP:(0): processing vendor id payload
*Aug 7 03:11:44.863: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch
*Aug 7 03:11:44.863: ISAKMP (0): vendor ID is NAT-T RFC 3947
*Aug 7 03:11:44.863: ISAKMP:(0):found peer pre-shared key matching 101.1.1.1
*Aug 7 03:11:44.863: ISAKMP:(0): local preshared key found
*Aug 7 03:11:44.863: ISAKMP : Scanning profiles for xauth ...
*Aug 7 03:11:44.863: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy
*Aug 7 03:11:44.863: ISAKMP: encryption 3DES-CBC
*Aug 7 03:11:44.863: ISAKMP: hash SHA
*Aug 7 03:11:44.863: ISAKMP: default group 5
*Aug 7 03:11:44.863: ISAKMP: auth pre-share
*Aug 7 03:11:44.863: ISAKMP: life type in seconds
*Aug 7 03:11:44.863: ISAKMP: life duration (VPI) of 0x0 0x1 0x51 0x80
*Aug 7 03:11:44.863: ISAKMP:(0):atts are acceptable. Next payload is 0
*Aug 7 03:11:44.863: ISAKMP:(0):Acceptable atts:actual life: 0
*Aug 7 03:11:44.863: ISAKMP:(0):Acceptable atts:life: 0
*Aug 7 03:11:44.863: ISAKMP:(0):Fill atts in sa vpi_length:4
*Aug 7 03:11:44.863: ISAKMP:(0):Fill atts in sa life_in_seconds:86400
*Aug 7 03:11:44.863: ISAKMP:(0):Returning Actual lifetime: 86400
*Aug 7 03:11:44.863: ISAKMP:(0)::Started lifetime timer: 86400.

*Aug 7 03:11:44.863: ISAKMP:(0): processing vendor id payload
*Aug 7 03:11:44.863: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch
*Aug 7 03:11:44.863: ISAKMP (0): vendor ID is NAT-T RFC 3947
*Aug 7 03:11:44.863: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Aug 7 03:11:44.863: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM2

*Aug 7 03:11:44.863: ISAKMP:(0): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_SA_SETUP
*Aug 7 03:11:44.863: ISAKMP:(0):Sending an IKE IPv4 Packet.
*Aug 7 03:11:44.863: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Aug 7 03:11:44.863: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM3

*Aug 7 03:11:44.882: ISAKMP (0): received packet from 101.1.1.1 dport 500 sport 500 Global (I) MM_SA_SETUP
*Aug 7 03:11:44.882: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Aug 7 03:11:44.882: ISAKMP:(0):Old State = IKE_I_MM3 New State = IKE_I_MM4

*Aug 7 03:11:44.882: ISAKMP:(0): processing KE payload. message ID = 0
*Aug 7 03:11:44.896: ISAKMP:(0): processing NONCE payload. message ID = 0
*Aug 7 03:11:44.896: ISAKMP:(0):found peer pre-shared key matching 101.1.1.1
*Aug 7 03:11:44.896: ISAKMP:(1004): processing vendor id payload
*Aug 7 03:11:44.896: ISAKMP:(1004): vendor ID is Unity
*Aug 7 03:11:44.896: ISAKMP:(1004): processing vendor id payload
*Aug 7 03:11:44.896: ISAKMP:(1004): vendor ID is DPD
*Aug 7 03:11:44.896: ISAKMP:(1004): processing vendor id payload
*Aug 7 03:11:44.896: ISAKMP:(1004): speaking to another IOS box!
*Aug 7 03:11:44.896: ISAKMP:received payload type 20
*Aug 7 03:11:44.896: ISAKMP (1004): His hash no match - this node outside NAT
*Aug 7 03:11:44.896: ISAKMP:received payload type 20
*Aug 7 03:11:44.896: ISAKMP (1004): No NAT Found for self or peer
*Aug 7 03:11:44.896: ISAKMP:(1004):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Aug 7 03:11:44.896: ISAKMP:(1004):Old State = IKE_I_MM4 New State = IKE_I_MM4

*Aug 7 03:11:44.897: ISAKMP:(1004):Send initial contact
*Aug 7 03:11:44.897: ISAKMP:(1004):SA is doing pre-shared key authentication using id type ID_IPV4_ADDR
*Aug 7 03:11:44.897: ISAKMP (1004): ID payload
next-payload : 8
type : 1
address : 100.1.1.1
protocol : 17
port : 500
length : 12
*Aug 7 03:11:44.897: ISAKMP:(1004):Total payload length: 12
*Aug 7 03:11:44.897: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_KEY_EXCH
*Aug 7 03:11:44.897: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:11:44.897: ISAKMP:(1004):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Aug 7 03:11:44.897: ISAKMP:(1004):Old State = IKE_I_MM4 New State = IKE_I_MM5

*Aug 7 03:11:44.899: ISAKMP (1004): received packet from 101.1.1.1 dport 500 sport 500 Global (I) MM_KEY_EXCH
*Aug 7 03:11:44.899: ISAKMP:(1004): processing ID payload. message ID = 0
*Aug 7 03:11:44.899: ISAKMP (1004): ID payload
next-payload : 8
type : 1
address : 101.1.1.1
protocol : 17
port : 500
length : 12
*Aug 7 03:11:44.899: ISAKMP:(0):: peer matches *none* of the profiles
*Aug 7 03:11:44.899: ISAKMP:(1004): processing HASH payload. message ID = 0
*Aug 7 03:11:44.899: ISAKMP:(1004):SA authentication status:
authenticated
*Aug 7 03:11:44.899: ISAKMP:(1004):SA has been authenticated with 101.1.1.1
*Aug 7 03:11:44.899: ISAKMP: Trying to insert a peer 100.1.1.1/101.1.1.1/500/, and inserted successfully F2F1E4D8.
*Aug 7 03:11:44.899: ISAKMP:(1004):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Aug 7 03:11:44.899: ISAKMP:(1004):Old State = IKE_I_MM5 New State = IKE_I_MM6

*Aug 7 03:11:44.900: ISAKMP:(1004):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Aug 7 03:11:44.900: ISAKMP:(1004):Old State = IKE_I_MM6 New State = IKE_I_MM6

*Aug 7 03:11:44.909: ISAKMP:(1004):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Aug 7 03:11:44.909: ISAKMP:(1004):Old State = IKE_I_MM6 New State = IKE_P1_COMPLETE

*Aug 7 03:11:44.909: ISAKMP:(1004):IKE_DPD is enabled, initializing timers
*Aug 7 03:11:44.909: ISAKMP:(1004):beginning Quick Mode exchange, M-ID of 3736979590
*Aug 7 03:11:44.909: ISAKMP:(1004):QM Initiator gets spi
*Aug 7 03:11:44.909: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:11:44.909: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:11:44.909: ISAKMP:(1004):Node 3736979590, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
*Aug 7 03:11:44.909: ISAKMP:(1004):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
*Aug 7 03:11:44.909: ISAKMP:(1004):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
*Aug 7 03:11:44.909: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

*Aug 7 03:11:44.913: ISAKMP (1004): received packet from 101.1.1.1 dport 500 sport 500 Global (I) QM_IDLE
*Aug 7 03:11:44.913: ISAKMP:(1004): processing HASH payload. message ID = 3736979590
*Aug 7 03:11:44.913: ISAKMP:(1004): processing SA payload. message ID = 3736979590
*Aug 7 03:11:44.913: ISAKMP:(1004):Checking IPSec proposal 1
*Aug 7 03:11:44.913: ISAKMP: transform 1, ESP_3DES
*Aug 7 03:11:44.913: ISAKMP: attributes in transform:
*Aug 7 03:11:44.913: ISAKMP: encaps is 1 (Tunnel)
*Aug 7 03:11:44.913: ISAKMP: SA life type in seconds
*Aug 7 03:11:44.913: ISAKMP: SA life duration (basic) of 3600
*Aug 7 03:11:44.913: ISAKMP: SA life type in kilobytes
*Aug 7 03:11:44.913: ISAKMP: SA life duration (VPI) of 0x0 0x46 0x50 0x0
*Aug 7 03:11:44.913: ISAKMP: authenticator is HMAC-SHA
*Aug 7 03:11:44.913: ISAKMP:(1004):atts are acceptable.
*Aug 7 03:11:44.913: ISAKMP:(1004): processing NONCE payload. message ID = 3736979590
*Aug 7 03:11:44.913: ISAKMP:(1004): processing ID payload. message ID = 3736979590
*Aug 7 03:11:44.913: ISAKMP:(1004): processing ID payload. message ID = 3736979590
*Aug 7 03:11:44.913: ISAKMP:(1004):Node 3736979590, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
*Aug 7 03:11:44.913: ISAKMP:(1004):Old State = IKE_QM_I_QM1 New State = IKE_QM_IPSEC_INSTALL_AWAIT
*Aug 7 03:11:44.913: ISAKMP: Failed to find peer index node to update peer_info_list
*Aug 7 03:11:44.914: ISAKMP:(1004):Received IPSec Install callback... proceeding with the negotiation
*Aug 7 03:11:44.914: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:11:44.914: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:11:44.914: ISAKMP:(1004):deleting node -557987706 error FALSE reason "No Error"
*Aug 7 03:11:44.914: ISAKMP:(1004):Node 3736979590, Input = IKE_MESG_FROM_IPSEC, IPSEC_INSTALL_DONE
*Aug 7 03:11:44.914: ISAKMP:(1004):Old State = IKE_QM_IPSEC_INSTALL_AWAIT New State = IKE_QM_PHASE2_COMPLETE.!!!!
Success rate is 80 percent (4/5), round-trip min/avg/max = 8/12/18 ms
IOU1#
*Aug 7 03:11:57.029: ISAKMP (1004): received packet from 101.1.1.1 dport 500 sport 500 Global (I) QM_IDLE
*Aug 7 03:11:57.029: ISAKMP: set new node 2039185025 to QM_IDLE
*Aug 7 03:11:57.029: ISAKMP:(1004): processing HASH payload. message ID = 2039185025
*Aug 7 03:11:57.029: ISAKMP:(1004): processing NOTIFY DPD/R_U_THERE protocol 1
spi 0, message ID = 2039185025, sa = 0xF2F30F50
*Aug 7 03:11:57.029: ISAKMP:(1004):deleting node 2039185025 error FALSE reason "Informational (in) state 1"
*Aug 7 03:11:57.029: ISAKMP:(1004):Input = IKE_MESG_FROM_PEER, IKE_INFO_NOTIFY
*Aug 7 03:11:57.029: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

*Aug 7 03:11:57.029: ISAKMP:(1004):DPD/R_U_THERE received from peer 101.1.1.1, sequence 0x6EEFB371
*Aug 7 03:11:57.029: ISAKMP: set new node 1411802357 to QM_IDLE
*Aug 7 03:11:57.029: ISAKMP:(1004):Sending NOTIFY DPD/R_U_THERE_ACK protocol 1
spi 4087798040, message ID = 1411802357
*Aug 7 03:11:57.029: ISAKMP:(1004): seq. no 0x6EEFB371
*Aug 7 03:11:57.029: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:11:57.029: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:11:57.030: ISAKMP:(1004):purging node 1411802357
*Aug 7 03:11:57.030: ISAKMP:(1004):Input = IKE_MESG_FROM_PEER, IKE_MESG_KEEP_ALIVE
IOU1#
*Aug 7 03:11:57.030: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

Now on R2 let’s shut down the public facing interface eth0/0 and see what happens on R1.

IOU1#ping 2.2.2.2 source 1.1.1.1
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 2.2.2.2, timeout is 2 seconds:
Packet sent with a source address of 1.1.1.1
.....
Success rate is 0 percent (0/5)

*Aug 7 03:14:55.573: ISAKMP: DPD received KMI message.
*Aug 7 03:14:55.573: ISAKMP: set new node 1236715696 to QM_IDLE
*Aug 7 03:14:55.573: ISAKMP:(1004):Sending NOTIFY DPD/R_U_THERE protocol 1
spi 4073138204, message ID = 1236715696
*Aug 7 03:14:55.573: ISAKMP:(1004): seq. no 0x484909A3
*Aug 7 03:14:55.573: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:14:55.574: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:14:55.574: ISAKMP:(1004):purging node 1236715696
IOU1#show ip route
*Aug 7 03:14:57.586: ISAKMP:(1004):DPD incrementing error counter (1/5)
*Aug 7 03:14:57.586: ISAKMP: set new node -140430850 to QM_IDLE
*Aug 7 03:14:57.586: ISAKMP:(1004):Sending NOTIFY DPD/R_U_THERE protocol 1
spi 4087797952, message ID = 4154536446
*Aug 7 03:14:57.586: ISAKMP:(1004): seq. no 0x484909A4
*Aug 7 03:14:57.586: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:14:57.586: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:14:57.586: ISAKMP:(1004):purging node -140430850
*Aug 7 03:14:57.586: ISAKMP:(1004):Input = IKE_MESG_FROM_TIMER, IKE_TIMER_PEERS_ALIVE
IOU1#
*Aug 7 03:14:57.586: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

IOU1#
*Aug 7 03:14:59.592: ISAKMP:(1004):DPD incrementing error counter (2/5)
*Aug 7 03:14:59.592: ISAKMP: set new node 2080816415 to QM_IDLE
*Aug 7 03:14:59.592: ISAKMP:(1004):Sending NOTIFY DPD/R_U_THERE protocol 1
spi 4087797952, message ID = 2080816415
*Aug 7 03:14:59.592: ISAKMP:(1004): seq. no 0x484909A5
*Aug 7 03:14:59.592: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:14:59.592: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:14:59.592: ISAKMP:(1004):purging node 2080816415
*Aug 7 03:14:59.592: ISAKMP:(1004):Input = IKE_MESG_FROM_TIMER, IKE_TIMER_PEERS_ALIVE
IOU1#
*Aug 7 03:14:59.592: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

IOU1#
*Aug 7 03:15:02.855: ISAKMP:(1004):DPD incrementing error counter (3/5)
*Aug 7 03:15:02.855: ISAKMP: set new node 527308109 to QM_IDLE
*Aug 7 03:15:02.855: ISAKMP:(1004):Sending NOTIFY DPD/R_U_THERE protocol 1
spi 4087797952, message ID = 527308109
*Aug 7 03:15:02.855: ISAKMP:(1004): seq. no 0x484909A6
*Aug 7 03:15:02.855: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:15:02.855: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:15:02.855: ISAKMP:(1004):purging node 527308109
*Aug 7 03:15:02.855: ISAKMP:(1004):Input = IKE_MESG_FROM_TIMER, IKE_TIMER_PEERS_ALIVE
IOU1#
*Aug 7 03:15:02.855: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

IOU1#
*Aug 7 03:15:04.855: ISAKMP:(1004):DPD incrementing error counter (4/5)
*Aug 7 03:15:04.855: ISAKMP: set new node -345256241 to QM_IDLE
*Aug 7 03:15:04.855: ISAKMP:(1004):Sending NOTIFY DPD/R_U_THERE protocol 1
spi 4087797952, message ID = 3949711055
*Aug 7 03:15:04.855: ISAKMP:(1004): seq. no 0x484909A7
*Aug 7 03:15:04.855: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:15:04.855: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:15:04.855: ISAKMP:(1004):purging node -345256241
*Aug 7 03:15:04.855: ISAKMP:(1004):Input = IKE_MESG_FROM_TIMER, IKE_TIMER_PEERS_ALIVE
IOU1#
*Aug 7 03:15:04.855: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

IOU1#
*Aug 7 03:15:06.860: ISAKMP:(1004):DPD incrementing error counter (5/5)
*Aug 7 03:15:06.860: ISAKMP:(1004):peer 101.1.1.1 not responding!
*Aug 7 03:15:06.860: ISAKMP:(1004):peer does not do paranoid keepalives.

*Aug 7 03:15:06.860: ISAKMP:(1004):deleting SA reason "End of ipsec tunnel" state (I) QM_IDLE (peer 101.1.1.1)
*Aug 7 03:15:06.860: ISAKMP:(1004):Input = IKE_MESG_FROM_TIMER, IKE_TIMER_PEERS_ALIVE
*Aug 7 03:15:06.860: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

*Aug 7 03:15:06.860: ISAKMP: Failed to find peer index node to update peer_info_list
*Aug 7 03:15:06.860: ISAKMP: set new node 186812859 to QM_IDLE
*Aug 7 03:15:06.861: ISAKMP:(1004): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:15:06.861: ISAKMP:(1004):Sending an IKE IPv4 Packet.
*Aug 7 03:15:06.861: ISAKMP:(1004):purging node 186812859
*Aug 7 03:15:06.861: ISAKMP:(1004):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
*Aug 7 03:15:06.861: ISAKMP:(1004):Old State = IKE_P1_COMPLETE New State = IKE_DEST_SA

*Aug 7 03:15:06.861: ISAKMP:(1004):deleting SA reason "End of ipsec tunnel" state (I) QM_IDLE (peer 101.1.1.1)
*Aug 7 03:15:06.861: ISAKMP: Unlocking peer struct 0xF2F1E4D8 for isadb_mark_sa_deleted(), count 0
IOU1#
*Aug 7 03:15:06.861: ISAKMP:(1004):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Aug 7 03:15:06.861: ISAKMP:(1004):Old State = IKE_DEST_SA New State = IKE_DEST_SA

*Aug 7 03:15:06.988: ISAKMP: Deleting peer node by peer_reap for 101.1.1.1: F2F1E4D8
*Aug 7 03:15:06.988: ISAKMP: ignoring request to send delete notify (no ISAKMP sa) src 100.1.1.1 dst 101.1.1.1 for SPI 0xA9FAAD12
IOU1#ping 2.2.2.2 source 1.1.1.1
Type escape sequence to abort.
Sending 5, 100-byte ICMP Echos to 2.2.2.2, timeout is 2 seconds:
Packet sent with a source address of 1.1.1.1

*Aug 7 03:15:26.674: ISAKMP:(0): SA request profile is (NULL)
*Aug 7 03:15:26.674: ISAKMP: Created a peer struct for 101.1.1.1, peer port 500
*Aug 7 03:15:26.674: ISAKMP: New peer created peer = 0xF2F1E4D8 peer_handle = 0x80000007
*Aug 7 03:15:26.674: ISAKMP: Locking peer struct 0xF2F1E4D8, refcount 1 for isakmp_initiator
*Aug 7 03:15:26.674: ISAKMP: local port 500, remote port 500
*Aug 7 03:15:26.674: ISAKMP: set new node 0 to QM_IDLE
*Aug 7 03:15:26.674: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = F4AB36C8
*Aug 7 03:15:26.674: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
*Aug 7 03:15:26.674: ISAKMP:(0):found peer pre-shared key matching 101.1.1.1
*Aug 7 03:15:26.674: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
*Aug 7 03:15:26.674: ISAKMP:(0): constructed NAT-T vendor-07 ID
*Aug 7 03:15:26.674: ISAKMP:(0): constructed NAT-T vendor-03 ID
*Aug 7 03:15:26.674: ISAKMP:(0): constructed NAT-T vendor-02 ID
*Aug 7 03:15:26.674: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
*Aug 7 03:15:26.674: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

*Aug 7 03:15:26.674: ISAKMP:(0): beginning Main Mode exchange
*Aug 7 03:15:26.674: ISAKMP:(0): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_NO_STATE
*Aug 7 03:15:26.674: ISAKMP:(0):Sending an IKE IPv4 Packet......
Success rate is 0 percent (0/5)
IOU1#
*Aug 7 03:15:36.676: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
*Aug 7 03:15:36.676: ISAKMP (0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1
*Aug 7 03:15:36.676: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
*Aug 7 03:15:36.676: ISAKMP:(0): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_NO_STATE
*Aug 7 03:15:36.676: ISAKMP:(0):Sending an IKE IPv4 Packet.
IOU1#
*Aug 7 03:15:46.684: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
*Aug 7 03:15:46.684: ISAKMP (0): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
*Aug 7 03:15:46.684: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
*Aug 7 03:15:46.684: ISAKMP:(0): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_NO_STATE
*Aug 7 03:15:46.684: ISAKMP:(0):Sending an IKE IPv4 Packet.
IOU1#
*Aug 7 03:15:56.676: ISAKMP: set new node 0 to QM_IDLE
*Aug 7 03:15:56.676: ISAKMP:(0):SA is still budding. Attached new ipsec request to it. (local 100.1.1.1, remote 101.1.1.1)
*Aug 7 03:15:56.676: ISAKMP: Error while processing SA request: Failed to initialize SA
*Aug 7 03:15:56.676: ISAKMP: Error while processing KMI message 0, error 2.
*Aug 7 03:15:56.693: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
*Aug 7 03:15:56.693: ISAKMP (0): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1
*Aug 7 03:15:56.693: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
IOU1#
*Aug 7 03:15:56.693: ISAKMP:(0): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_NO_STATE
*Aug 7 03:15:56.693: ISAKMP:(0):Sending an IKE IPv4 Packet.
IOU1#
*Aug 7 03:16:06.698: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
*Aug 7 03:16:06.698: ISAKMP (0): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1
*Aug 7 03:16:06.698: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
*Aug 7 03:16:06.698: ISAKMP:(0): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_NO_STATE
*Aug 7 03:16:06.698: ISAKMP:(0):Sending an IKE IPv4 Packet.
*Aug 7 03:16:06.865: ISAKMP:(1004):purging SA., sa=F2F30F50, delme=F2F30F50
IOU1#
*Aug 7 03:16:16.699: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
*Aug 7 03:16:16.699: ISAKMP (0): incrementing error counter on sa, attempt 5 of 5: retransmit phase 1
*Aug 7 03:16:16.699: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
*Aug 7 03:16:16.699: ISAKMP:(0): sending packet to 101.1.1.1 my_port 500 peer_port 500 (I) MM_NO_STATE
*Aug 7 03:16:16.699: ISAKMP:(0):Sending an IKE IPv4 Packet.
IOU1#
*Aug 7 03:16:26.682: ISAKMP:(0):peer does not do paranoid keepalives.

*Aug 7 03:16:26.682: ISAKMP:(0):deleting SA reason "P1 delete notify (in)" state (I) MM_NO_STATE (peer 101.1.1.1)
*Aug 7 03:16:26.682: ISAKMP:(0): SA request profile is (NULL)
*Aug 7 03:16:26.682: ISAKMP: Created a peer struct for 102.1.1.1, peer port 500
*Aug 7 03:16:26.682: ISAKMP: New peer created peer = 0xF4A92B30 peer_handle = 0x80000008
*Aug 7 03:16:26.682: ISAKMP: Locking peer struct 0xF4A92B30, refcount 1 for isakmp_initiator
*Aug 7 03:16:26.682: ISAKMP: local port 500, remote port 500
*Aug 7 03:16:26.682: ISAKMP: set new node 0 to QM_IDLE
*Aug 7 03:16:26.682: ISAKMP:(0):insert sa successfully sa = F2F30F50
*Aug 7 03:16:26.682: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
*Aug 7 03:16:26.682: ISAKMP:(0):found peer pre-shared key matching 102.1.1.1
*Aug 7 03:16:26.682: ISAKMP:(0): constructed NAT-T vendor-rfc3947 ID
*Aug 7 03:16:26.682: ISAKMP:(0): constructed NAT-T vendor-07 ID
*Aug 7 03:16:26.682: ISAKMP:(0): constructed NAT-T vendor-03 ID
*Aug 7 03:16:26.682: ISAKMP:(0): constructed NAT-T vendor-02 ID
*Aug 7 03:16:26.682: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
*Aug 7 03:16:26.682: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

*Aug 7 03:16:26.682: ISAKMP:(0): beginning Main Mode exchange
*Aug 7 03:16:26.682: ISAKMP:(0): sending packet to 102.1.1.1 my_port 500 peer_port 500 (I) MM_NO_STATE
*Aug 7 03:16:26.682: ISAKMP:(0):Sending an IKE IPv4 Packet.
*Aug 7 03:16:26.682: ISAKMP:(0):deleting SA reason "P1 delete notify (in)" state (I) MM_NO_STATE (peer 101.1.1.1)
*Aug 7 03:16:26.682: ISAKMP: Unlocking peer struct 0xF2F1E4D8 for isadb_mark_sa_deleted(), count 0
*Aug 7 03:16:26.682: ISAKMP: Deleting peer node by peer_reap for 101.1.1.1: F2F1E4D8
*Aug 7 03:16:26.683: ISAKMP:(0):deleting node 189642018 error FALSE reason "IKE deleted"
*Aug 7 03:16:26.683: ISAKMP:(0):deleting node -162170267 error FALSE reason "IKE deleted"
*Aug 7 03:16:26.683: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
*Aug 7 03:16:26.683: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_DEST_SA

*Aug 7 03:16:26.684: ISAKMP (0): received packet from 102.1.1.1 dport 500 sport 500 Global (I) MM_NO_STATE
*Aug 7 03:16:26.684: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Aug 7 03:16:26.684: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_I_MM2

*Aug 7 03:16:26.684: ISAKMP:(0): processing SA payload. message ID = 0
*Aug 7 03:16:26.684: ISAKMP:(0): processing vendor id payload
*Aug 7 03:16:26.684: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch
*Aug 7 03:16:26.684: ISAKMP (0): vendor ID is NAT-T RFC 3947
*Aug 7 03:16:26.684: ISAKMP:(0):found peer pre-shared key matching 102.1.1.1
*Aug 7 03:16:26.684: ISAKMP:(0): local preshared key found
*Aug 7 03:16:26.684: ISAKMP : Scanning profiles for xauth ...
*Aug 7 03:16:26.684: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy
*Aug 7 03:16:26.684: ISAKMP: encryption 3DES-CBC
*Aug 7 03:16:26.684: ISAKMP: hash SHA
*Aug 7 03:16:26.684: ISAKMP: default group 5
*Aug 7 03:16:26.684: ISAKMP: auth pre-share
*Aug 7 03:16:26.684: ISAKMP: life type in seconds
*Aug 7 03:16:26.684: ISAKMP: life duration (VPI) of 0x0 0x1 0x51 0x80
*Aug 7 03:16:26.684: ISAKMP:(0):atts are acceptable. Next payload is 0
*Aug 7 03:16:26.684: ISAKMP:(0):Acceptable atts:actual life: 0
*Aug 7 03:16:26.684: ISAKMP:(0):Acceptable atts:life: 0
*Aug 7 03:16:26.684: ISAKMP:(0):Fill atts in sa vpi_length:4
*Aug 7 03:16:26.684: ISAKMP:(0):Fill atts in sa life_in_seconds:86400
*Aug 7 03:16:26.684: ISAKMP:(0):Returning Actual lifetime: 86400
*Aug 7 03:16:26.684: ISAKMP:(0)::Started lifetime timer: 86400.

*Aug 7 03:16:26.684: ISAKMP:(0): processing vendor id payload
*Aug 7 03:16:26.684: ISAKMP:(0): vendor ID seems Unity/DPD but major 69 mismatch
*Aug 7 03:16:26.684: ISAKMP (0): vendor ID is NAT-T RFC 3947
*Aug 7 03:16:26.684: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Aug 7 03:16:26.684: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM2

*Aug 7 03:16:26.684: ISAKMP:(0): sending packet to 102.1.1.1 my_port 500 peer_port 500 (I) MM_SA_SETUP
*Aug 7 03:16:26.684: ISAKMP:(0):Sending an IKE IPv4 Packet.
*Aug 7 03:16:26.684: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Aug 7 03:16:26.684: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM3

*Aug 7 03:16:26.698: ISAKMP (0): received packet from 102.1.1.1 dport 500 sport 500 Global (I) MM_SA_SETUP
*Aug 7 03:16:26.698: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Aug 7 03:16:26.698: ISAKMP:(0):Old State = IKE_I_MM3 New State = IKE_I_MM4

*Aug 7 03:16:26.698: ISAKMP:(0): processing KE payload. message ID = 0
*Aug 7 03:16:26.709: ISAKMP:(0): processing NONCE payload. message ID = 0
*Aug 7 03:16:26.709: ISAKMP:(0):found peer pre-shared key matching 102.1.1.1
*Aug 7 03:16:26.709: ISAKMP:(1005): processing vendor id payload
*Aug 7 03:16:26.709: ISAKMP:(1005): vendor ID is Unity
*Aug 7 03:16:26.709: ISAKMP:(1005): processing vendor id payload
*Aug 7 03:16:26.709: ISAKMP:(1005): vendor ID is DPD
*Aug 7 03:16:26.709: ISAKMP:(1005): processing vendor id payload
*Aug 7 03:16:26.709: ISAKMP:(1005): speaking to another IOS box!
*Aug 7 03:16:26.709: ISAKMP:received payload type 20
*Aug 7 03:16:26.709: ISAKMP (1005): His hash no match - this node outside NAT
*Aug 7 03:16:26.709: ISAKMP:received payload type 20
*Aug 7 03:16:26.709: ISAKMP (1005): No NAT Found for self or peer
*Aug 7 03:16:26.709: ISAKMP:(1005):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Aug 7 03:16:26.709: ISAKMP:(1005):Old State = IKE_I_MM4 New State = IKE_I_MM4

*Aug 7 03:16:26.709: ISAKMP:(1005):Send initial contact
*Aug 7 03:16:26.709: ISAKMP:(1005):SA is doing pre-shared key authentication using id type ID_IPV4_ADDR
*Aug 7 03:16:26.709: ISAKMP (1005): ID payload
next-payload : 8
type : 1
address : 100.1.1.1
protocol : 17
port : 500
length : 12
*Aug 7 03:16:26.709: ISAKMP:(1005):Total payload length: 12
*Aug 7 03:16:26.709: ISAKMP:(1005): sending packet to 102.1.1.1 my_port 500 peer_port 500 (I) MM_KEY_EXCH
*Aug 7 03:16:26.709: ISAKMP:(1005):Sending an IKE IPv4 Packet.
*Aug 7 03:16:26.710: ISAKMP:(1005):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Aug 7 03:16:26.710: ISAKMP:(1005):Old State = IKE_I_MM4 New State = IKE_I_MM5

*Aug 7 03:16:26.711: ISAKMP (1005): received packet from 102.1.1.1 dport 500 sport 500 Global (I) MM_KEY_EXCH
*Aug 7 03:16:26.711: ISAKMP:(1005): processing ID payload. message ID = 0
*Aug 7 03:16:26.711: ISAKMP (1005): ID payload
next-payload : 8
type : 1
address : 102.1.1.1
protocol : 17
port : 500
length : 12
*Aug 7 03:16:26.711: ISAKMP:(0):: peer matches *none* of the profiles
*Aug 7 03:16:26.711: ISAKMP:(1005): processing HASH payload. message ID = 0
*Aug 7 03:16:26.711: ISAKMP:(1005):SA authentication status:
authenticated
*Aug 7 03:16:26.711: ISAKMP:(1005):SA has been authenticated with 102.1.1.1
*Aug 7 03:16:26.711: ISAKMP: Trying to insert a peer 100.1.1.1/102.1.1.1/500/, and inserted successfully F4A92B30.
*Aug 7 03:16:26.711: ISAKMP:(1005):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
*Aug 7 03:16:26.711: ISAKMP:(1005):Old State = IKE_I_MM5 New State = IKE_I_MM6

*Aug 7 03:16:26.711: ISAKMP:(1005):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
*Aug 7 03:16:26.711: ISAKMP:(1005):Old State = IKE_I_MM6 New State = IKE_I_MM6

*Aug 7 03:16:26.717: ISAKMP:(1005):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
*Aug 7 03:16:26.717: ISAKMP:(1005):Old State = IKE_I_MM6 New State = IKE_P1_COMPLETE

*Aug 7 03:16:26.717: ISAKMP:(1005):IKE_DPD is enabled, initializing timers
*Aug 7 03:16:26.717: ISAKMP:(1005):beginning Quick Mode exchange, M-ID of 777919085
*Aug 7 03:16:26.717: ISAKMP:(1005):QM Initiator gets spi
*Aug 7 03:16:26.717: ISAKMP:(1005): sending packet to 102.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:16:26.717: ISAKMP:(1005):Sending an IKE IPv4 Packet.
*Aug 7 03:16:26.717: ISAKMP:(1005):Node 777919085, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
*Aug 7 03:16:26.717: ISAKMP:(1005):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
*Aug 7 03:16:26.717: ISAKMP:(1005):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
*Aug 7 03:16:26.717: ISAKMP:(1005):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

*Aug 7 03:16:26.719: ISAKMP (1005): received packet from 102.1.1.1 dport 500 sport 500 Global (I) QM_IDLE
*Aug 7 03:16:26.719: ISAKMP:(1005): processing HASH payload. message ID = 777919085
*Aug 7 03:16:26.719: ISAKMP:(1005): processing SA payload. message ID = 777919085
*Aug 7 03:16:26.719: ISAKMP:(1005):Checking IPSec proposal 1
*Aug 7 03:16:26.719: ISAKMP: transform 1, ESP_3DES
*Aug 7 03:16:26.719: ISAKMP: attributes in transform:
*Aug 7 03:16:26.719: ISAKMP: encaps is 1 (Tunnel)
*Aug 7 03:16:26.719: ISAKMP: SA life type in seconds
*Aug 7 03:16:26.719: ISAKMP: SA life duration (basic) of 3600
*Aug 7 03:16:26.719: ISAKMP: SA life type in kilobytes
*Aug 7 03:16:26.719: ISAKMP: SA life duration (VPI) of 0x0 0x46 0x50 0x0
*Aug 7 03:16:26.719: ISAKMP: authenticator is HMAC-SHA
*Aug 7 03:16:26.719: ISAKMP:(1005):atts are acceptable.
*Aug 7 03:16:26.719: ISAKMP:(1005): processing NONCE payload. message ID = 777919085
*Aug 7 03:16:26.719: ISAKMP:(1005): processing ID payload. message ID = 777919085
*Aug 7 03:16:26.719: ISAKMP:(1005): processing ID payload. message ID = 777919085
*Aug 7 03:16:26.719: ISAKMP:(1005):Node 777919085, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
*Aug 7 03:16:26.719: ISAKMP:(1005):Old State = IKE_QM_I_QM1 New State = IKE_QM_IPSEC_INSTALL_AWAIT
*Aug 7 03:16:26.720: ISAKMP: Failed to find peer index node to update peer_info_list
*Aug 7 03:16:26.720: ISAKMP:(1005):Received IPSec Install callback... proceeding with the negotiation
*Aug 7 03:16:26.720: ISAKMP:(1005): sending packet to 102.1.1.1 my_port 500 peer_port 500 (I) QM_IDLE
*Aug 7 03:16:26.720: ISAKMP:(1005):Sending an IKE IPv4 Packet.
*Aug 7 03:16:26.720: ISAKMP:(1005):deleting node 777919085 error FALSE reason "No Error"
*Aug 7 03:16:26.720: ISAKMP:(1005):Node 777919085, Input = IKE_MESG_FROM_IPSEC, IPSEC_INSTALL_DONE
IOU1#
*Aug 7 03:16:26.720: ISAKMP:(1005):Old State = IKE_QM_IPSEC_INSTALL_AWAIT New State = IKE_QM_PHASE2_COMPLETE
IOU1#


 

It’s interesting to see how much time elapsed: a lot! I shut down the interface at around 3:14:40. The DPD realized there’s a problem at 3:14:55 so it started sending keepalives every 2 seconds. It gave up at 3:15:06. This is already 26 seconds. I pinged 2.2.2.2 again at 3:15:26, R2 didn’t respond so isakmp gave up after another minute and only then did it probe R3. This gives us around 90 seconds of delay in case of a failure of the primary vpn peer.

 

Implementation and verification solutions

Hello

I’ve been looking at existing automation solutions for a while now and it seems I have the following options now:

IMPLEMENTATION:

  • netmiko + yaml
  • Unicon (pyATS transport plugin) + yaml.
  • Ansible
  • nornir
  • napalm

VERIFICATION AND DATA EXTRACTION:

  • pyATS
  • netmiko
  • napalm

The problem that I’m dealing at work is that i have a custom bastion that i need to traverse to get to my managed network devices. I will therefore try to implement a few designs (acl add, acl delete, vlan add, vpn add, route add etc.) using each of the implementation solutions, first without and then with the custom proxy. I’ll try to compare the effort to implement and verify. (And yes, I do realize that the final goal should be a continouos integration solution like Jenkins but hey, Rome wasn’t build in a day)