Interface Fa0/0 on Cisco 1841 fails after 4 to 5 hours, no pings

wilsonbolanos · ‎06-22-2013

Cisco GRE Tunnel with IPSec. Connection is lost every 4 to 5 hours and has happened for the last 7 days (where I loose ping and telnet capabilities to router for about 15 minutes) Cisco router 1841, Version 12.4(11)T4. I was lucky that I was telneted to router (router is 400 miles away). I was running a deb ip packet detail when the event happened. I lost connection to the router, but I was able to catch the out put from the log after the outage was over and I was able to telnet back in:

654389: Jun 21 12:50:43.048: IP: s=74.84.10.66 (local), d=72.164.247.66 (FastEthernet0/0), len 135, sending, proto=47

654390: Jun 21 12:50:43.048: IP: s=74.84.10.66 (local), d=72.164.247.66 (FastEthernet0/0), len 135, output crypto map check failed., proto=47

654391: Jun 21 12:50:43.184: IP: tableid=0, s=72.164.245.14 (local), d=192.168.24.146 (FastEthernet0/1), routed via FIB

654392: Jun 21 12:50:43.184: IP: s=72.164.245.14 (local), d=192.168.24.146 (FastEthernet0/1), len 40, sending

654393: Jun 21 12:50:43.184: TCP src=443, dst=60989, seq=0, ack=0, win=32 RST

654394: Jun 21 12:50:43.184: IP: tableid=0, s=192.168.24.146 (local), d=72.164.245.14 (FastEthernet0/0), routed via FIB

654395: Jun 21 12:50:43.184: IP: s=192.168.24.146 (local), d=72.164.245.14 (FastEthernet0/0), len 40, sending

654396: Jun 21 12:50:43.184: TCP src=60989, dst=443, seq=839014993, ack=0, win=0 RST

654397: Jun 21 12:50:43.388: IP: tableid=0, s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654398: Jun 21 12:50:43.388: IP: s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654399: Jun 21 12:50:43.392: UDP src=137, dst=137

654400: Jun 21 12:50:44.100: IP: tableid=0, s=192.168.24.19 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), routed via FIB

654401: Jun 21 12:50:44.100: IP: s=74.84.10.66 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), g=74.84.10.65, len 80, forward

654402: Jun 21 12:50:44.100: UDP src=49945, dst=53

654403: Jun 21 12:50:44.144: IP: tableid=0, s=74.84.10.66 (local), d=72.164.247.66 (FastEthernet0/0), routed via FIB

654404: Jun 21 12:50:44.144: IP: s=74.84.10.66 (local), d=72.164.247.66 (FastEthernet0/0), len 280, sending

654405: Jun 21 12:50:44.144: UDP src=500, dst=500

654406: Jun 21 12:50:44.156: IP: tableid=0, s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654407: Jun 21 12:50:44.156: IP: s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654408: Jun 21 12:50:44.156: UDP src=137, dst=137

654409: Jun 21 12:50:44.320: IP: tableid=0, s=192.168.24.150 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654410: Jun 21 12:50:44.320: IP: s=192.168.24.150 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654411: Jun 21 12:50:44.320: UDP src=137, dst=137

654412: Jun 21 12:50:44.668: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654413: Jun 21 12:50:44.668: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654414: Jun 21 12:50:44.668: UDP src=137, dst=137

654415: Jun 21 12:50:45.084: IP: tableid=0, s=192.168.24.150 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654416: Jun 21 12:50:45.084: IP: s=192.168.24.150 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654417: Jun 21 12:50:45.084: UDP src=137, dst=137

654418: Jun 21 12:50:45.144: IP: tableid=0, s=192.168.24.18 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), routed via FIB

654419: Jun 21 12:50:45.144: IP: s=74.84.10.66 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), g=74.84.10.65, len 80, forward

654420: Jun 21 12:50:45.144: UDP src=59181, dst=53

654421: Jun 21 12:50:45.416: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654422: Jun 21 12:50:45.416: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654423: Jun 21 12:50:45.416: UDP src=137, dst=137

654424: Jun 21 12:50:45.700: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654425: Jun 21 12:50:45.700: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654426: Jun 21 12:50:45.700: UDP src=137, dst=137

654427: Jun 21 12:50:45.848: IP: tableid=0, s=192.168.24.150 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654428: Jun 21 12:50:45.848: IP: s=192.168.24.150 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654429: Jun 21 12:50:45.848: UDP src=137, dst=137

654430: Jun 21 12:50:45.964: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654431: Jun 21 12:50:45.964: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654432: Jun 21 12:50:45.968: UDP src=137, dst=137

654433: Jun 21 12:50:45.968: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654434: Jun 21 12:50:45.968: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654435: Jun 21 12:50:45.968: UDP src=137, dst=137

654436: Jun 21 12:50:46.144: IP: tableid=0, s=192.168.24.18 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), routed via FIB

654437: Jun 21 12:50:46.144: IP: s=74.84.10.66 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), g=74.84.10.65, len 80, forward

654438: Jun 21 12:50:46.144: UDP src=64473, dst=53

654439: Jun 21 12:50:46.168: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654440: Jun 21 12:50:46.168: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654441: Jun 21 12:50:46.168: UDP src=137, dst=137

654442: Jun 21 12:50:46.448: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654443: Jun 21 12:50:46.452: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654444: Jun 21 12:50:46.452: UDP src=137, dst=137

654445: Jun 21 12:50:46.732: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654446: Jun 21 12:50:46.732: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654447: Jun 21 12:50:46.732: UDP src=137, dst=137

654448: Jun 21 12:50:46.732: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654449: Jun 21 12:50:46.732: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654450: Jun 21 12:50:46.732: UDP src=137, dst=137

654451: Jun 21 12:50:46.968: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654452: Jun 21 12:50:46.968: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654453: Jun 21 12:50:46.968: UDP src=137, dst=137

654454: Jun 21 12:50:47.200: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654455: Jun 21 12:50:47.200: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654456: Jun 21 12:50:47.200: UDP src=137, dst=137

654457: Jun 21 12:50:47.280: IP: tableid=0, s=208.85.40.44 (local), d=192.168.24.168 (FastEthernet0/1), routed via FIB

654458: Jun 21 12:50:47.280: IP: s=208.85.40.44 (local), d=192.168.24.168 (FastEthernet0/1), len 40, sending

654459: Jun 21 12:50:47.280: TCP src=80, dst=52519, seq=0, ack=0, win=2048 RST

654460: Jun 21 12:50:47.280: IP: tableid=0, s=192.168.24.168 (local), d=208.85.40.44 (FastEthernet0/0), routed via FIB

654461: Jun 21 12:50:47.280: IP: s=192.168.24.168 (local), d=208.85.40.44 (FastEthernet0/0), len 40, sending

654462: Jun 21 12:50:47.280: TCP src=52519, dst=80, seq=1558673772, ack=0, win=0 RST

654463: Jun 21 12:50:47.280: IP: tableid=0, s=208.85.40.44 (local), d=192.168.24.168 (FastEthernet0/1), routed via FIB

654464: Jun 21 12:50:47.280: IP: s=208.85.40.44 (local), d=192.168.24.168 (FastEthernet0/1), len 40, sending

654465: Jun 21 12:50:47.280: TCP src=80, dst=52520, seq=0, ack=0, win=2048 RST

654466: Jun 21 12:50:47.280: IP: tableid=0, s=192.168.24.168 (local), d=208.85.40.44 (FastEthernet0/0), routed via FIB

654467: Jun 21 12:50:47.280: IP: s=192.168.24.168 (local), d=208.85.40.44 (FastEthernet0/0), len 40, sending

654468: Jun 21 12:50:47.280: TCP src=52520, dst=80, seq=1119269488, ack=0, win=0 RST

654469: Jun 21 12:50:47.316: IP: tableid=0, s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654470: Jun 21 12:50:47.316: IP: s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654471: Jun 21 12:50:47.316: UDP src=137, dst=137

654472: Jun 21 12:50:47.496: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654473: Jun 21 12:50:47.496: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654474: Jun 21 12:50:47.496: UDP src=137, dst=137

654475: Jun 21 12:50:47.496: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654476: Jun 21 12:50:47.496: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654477: Jun 21 12:50:47.496: UDP src=137, dst=137

654478: Jun 21 12:50:47.716: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654479: Jun 21 12:50:47.716: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654480: Jun 21 12:50:47.716: UDP src=137, dst=137

654481: Jun 21 12:50:48.080: IP: tableid=0, s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654482: Jun 21 12:50:48.080: IP: s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654483: Jun 21 12:50:48.080: UDP src=137, dst=137

654484: Jun 21 12:50:48.100: IP: tableid=0, s=192.168.24.19 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), routed via FIB

654485: Jun 21 12:50:48.100: IP: s=74.84.10.66 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), g=74.84.10.65, len 80, forward

654486: Jun 21 12:50:48.100: UDP src=56776, dst=53

654487: Jun 21 12:50:48.144: IP: tableid=0, s=192.168.24.18 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), routed via FIB

654488: Jun 21 12:50:48.144: IP: s=74.84.10.66 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), g=74.84.10.65, len 83, forward

654489: Jun 21 12:50:48.144: UDP src=55218, dst=53

654490: Jun 21 12:50:48.304: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654491: Jun 21 12:50:48.308: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654492: Jun 21 12:50:48.308: UDP src=137, dst=137

654493: Jun 21 12:50:48.468: IP: tableid=0, s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654494: Jun 21 12:50:48.468: IP: s=192.168.24.168 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654495: Jun 21 12:50:48.468: UDP src=137, dst=137

654496: Jun 21 12:50:48.844: IP: tableid=0, s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654497: Jun 21 12:50:48.844: IP: s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654498: Jun 21 12:50:48.844: UDP src=137, dst=137

654499: Jun 21 12:50:49.071: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654500: Jun 21 12:50:49.071: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654501: Jun 21 12:50:49.071: UDP src=137, dst=137

654502: Jun 21 12:50:49.163: IP: tableid=0, s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654503: Jun 21 12:50:49.163: IP: s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654504: Jun 21 12:50:49.163: UDP src=137, dst=137

654505: Jun 21 12:50:49.671: IP: tableid=0, s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654506: Jun 21 12:50:49.671: IP: s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654507: Jun 21 12:50:49.671: UDP src=137, dst=137

654508: Jun 21 12:50:49.835: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654509: Jun 21 12:50:49.835: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654510: Jun 21 12:50:49.835: UDP src=137, dst=137

654511: Jun 21 12:50:49.927: IP: tableid=0, s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654512: Jun 21 12:50:49.927: IP: s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654513: Jun 21 12:50:49.927: UDP src=137, dst=137

654514: Jun 21 12:50:50.435: IP: tableid=0, s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654515: Jun 21 12:50:50.435: IP: s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654516: Jun 21 12:50:50.435: UDP src=137, dst=137

654517: Jun 21 12:50:50.643: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654518: Jun 21 12:50:50.647: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654519: Jun 21 12:50:50.647: UDP src=137, dst=137

654520: Jun 21 12:50:50.691: IP: tableid=0, s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654521: Jun 21 12:50:50.691: IP: s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654522: Jun 21 12:50:50.691: UDP src=137, dst=137

654523: Jun 21 12:50:51.099: IP: tableid=0, s=192.168.24.19 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), routed via FIB

654524: Jun 21 12:50:51.099: IP: s=74.84.10.66 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), g=74.84.10.65, len 80, forward

654525: Jun 21 12:50:51.099: UDP src=57905, dst=53

654526: Jun 21 12:50:51.143: IP: tableid=0, s=192.168.24.18 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), routed via FIB

654527: Jun 21 12:50:51.143: IP: s=74.84.10.66 (FastEthernet0/1), d=74.84.8.21 (FastEthernet0/0), g=74.84.10.65, len 80, forward

654528: Jun 21 12:50:51.143: UDP src=59781, dst=53

654529: Jun 21 12:50:51.199: IP: tableid=0, s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654530: Jun 21 12:50:51.199: IP: s=192.168.24.128 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654531: Jun 21 12:50:51.199: UDP src=137, dst=137

654532: Jun 21 12:50:51.411: IP: tableid=0, s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654533: Jun 21 12:50:51.411: IP: s=192.168.24.138 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

654534: Jun 21 12:50:51.411: UDP src=137, dst=137

654535: Jun 21 12:50:51.471: IP: tableid=0, s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), routed via RIB

654536: Jun 21 12:50:51.471: IP: s=192.168.24.146 (FastEthernet0/1), d=192.168.24.255 (FastEthernet0/1), len 78, rcvd 3

Richard Burts · ‎06-23-2013

You tell us that the outage typically lasts about 15 minutes. The debug output that you provide covers about 8 seconds. It gives a hint about what the problem might be but not nearly enough for us to be sure about the problem.

What I do see in the logs is this:

- the router was attempting to send a GRE packet and detected some issue with the crypto map.

- the router then attempts to begin an ISAKMP negotiation.

One possibility that this may suggest is that there was an issue with a security association, perhaps it timed out, or perhaps some other issue. I have seen issues in several versions of 12.4T where there were problems with crdypto rekey. Perhaps you are running into something like that.

I would suggest that you start by running debug crypto isakmp and see if there is ISAKMP activity associated with the issue. Perhaps you may also need debug crypto ipsec to see if there is IPSec activity associated with the problem.

HTH

Rick

HTH

Rick

wilsonbolanos · ‎06-23-2013

Outage again for about 6 minutes. deb crypto isakmp and deb crypto ipsec. I just hope the error messages were not the cause of the ISP being down. starts at about 14:00:00 to 14:06:00:

Hub ip has been changed to 172.16.0.1 - Cisco 3845 Se1/0

Spoke ip has been changed to 10.10.0.1 this is on the router Cisco 1841 Fa0/0

007050: Jun 23 13:58:11.257: IPSEC(lifetime_expiry): SA lifetime threshold reached, expiring in 32 seconds
007051: Jun 23 13:58:11.257: ISAKMP: set new node 0 to QM_IDLE
007052: Jun 23 13:58:11.257: SA has outstanding requests (local 100.88.56.140 port 500, remote 100.88.56.112 port 500)
007053: Jun 23 13:58:11.257: ISAKMP:(2009): sitting IDLE. Starting QM immediately (QM_IDLE      )
007054: Jun 23 13:58:11.257: ISAKMP:(2009):beginning Quick Mode exchange, M-ID of 167915285
007055: Jun 23 13:58:11.257: ISAKMP:(2009):QM Initiator gets spi
007056: Jun 23 13:58:11.261: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007057: Jun 23 13:58:11.261: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007058: Jun 23 13:58:11.261: ISAKMP:(2009):Node 167915285, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
007059: Jun 23 13:58:11.261: ISAKMP:(2009):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
007060: Jun 23 13:58:11.365: ISAKMP (0:2009): received packet from 172.16.0.1 dport 500 sport 500 Global (I) QM_IDLE
007061: Jun 23 13:58:11.369: ISAKMP:(2009): processing HASH payload. message ID = 167915285
007062: Jun 23 13:58:11.369: ISAKMP:(2009): processing SA payload. message ID = 167915285
007063: Jun 23 13:58:11.369: ISAKMP:(2009):Checking IPSec proposal 1
007064: Jun 23 13:58:11.369: ISAKMP: transform 1, ESP_3DES
007065: Jun 23 13:58:11.369: ISAKMP:   attributes in transform:
007066: Jun 23 13:58:11.369: ISAKMP:      encaps is 2 (Transport)
007067: Jun 23 13:58:11.369: ISAKMP:      SA life type in seconds
007068: Jun 23 13:58:11.369: ISAKMP:      SA life duration (basic) of 120
007069: Jun 23 13:58:11.369: ISAKMP:      SA life type in kilobytes
007070: Jun 23 13:58:11.369: ISAKMP:      SA life duration (VPI) of 0x0 0x46 0x50 0x0
007071: Jun 23 13:58:11.369: ISAKMP:      authenticator is HMAC-MD5
007072: Jun 23 13:58:11.369: ISAKMP:(2009):atts are acceptable.
007073: Jun 23 13:58:11.369: IPSEC(validate_proposal_request): proposal part #1
007074: Jun 23 13:58:11.369: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= esp-3des esp-md5-hmac (Transport),
    lifedur= 0s and 0kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007075: Jun 23 13:58:11.373: Crypto mapdb : proxy_match
src addr     : 10.10.0.1
dst addr     : 172.16.0.1
protocol     : 47
src port     : 0
dst port     : 0
007076: Jun 23 13:58:11.373: ISAKMP:(2009): processing NONCE payload. message ID = 167915285
007077: Jun 23 13:58:11.373: ISAKMP:(2009): processing ID payload. message ID = 167915285
007078: Jun 23 13:58:11.373: ISAKMP:(2009): processing ID payload. message ID = 167915285
007079: Jun 23 13:58:11.381: ISAKMP:(2009): Creating IPSec SAs
007080: Jun 23 13:58:11.381:         inbound SA from 172.16.0.1 to 10.10.0.1 (f/i) 0/ 0
        (proxy 172.16.0.1 to 10.10.0.1)
007081: Jun 23 13:58:11.381:         has spi 0x23CD47B9 and conn_id 0
007082: Jun 23 13:58:11.381:         lifetime of 120 seconds
007083: Jun 23 13:58:11.381:         lifetime of 4608000 kilobytes
007084: Jun 23 13:58:11.381:         outbound SA from 10.10.0.1 to 172.16.0.1 (f/i) 0/0
        (proxy 10.10.0.1 to 172.16.0.1)
007085: Jun 23 13:58:11.381:         has spi 0xEEDBE0CE and conn_id 0
007086: Jun 23 13:58:11.381:         lifetime of 120 seconds
007087: Jun 23 13:58:11.381:         lifetime of 4608000 kilobytes
007088: Jun 23 13:58:11.381: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007089: Jun 23 13:58:11.381: Crypto mapdb : proxy_match
src addr     : 10.10.0.1
dst addr     : 172.16.0.1
protocol     : 47
src port     : 0
dst port     : 0
007090: Jun 23 13:58:11.381: IPSEC(crypto_ipsec_sa_find_ident_head): reconnecting with the same proxies and peer 172.16.0.1
007091: Jun 23 13:58:11.381: IPSEC(create_sa): sa created,
(sa) sa_dest= 10.10.0.1, sa_proto= 50,
    sa_spi= 0x23CD47B9(600655801),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1775
007092: Jun 23 13:58:11.385: IPSEC(create_sa): sa created,
(sa) sa_dest= 172.16.0.1, sa_proto= 50,
    sa_spi= 0xEEDBE0CE(4007387342),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1776
007093: Jun 23 13:58:11.385: IPSEC(update_current_outbound_sa): updated peer 172.16.0.1 current outbound sa to SPI EEDBE0CE
007094: Jun 23 13:58:11.385: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007095: Jun 23 13:58:11.385: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007096: Jun 23 13:58:11.385: ISAKMP:(2009):deleting node 167915285 error FALSE reason "No Error"
007097: Jun 23 13:58:11.385: ISAKMP:(2009):Node 167915285, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
007098: Jun 23 13:58:11.385: ISAKMP:(2009):Old State = IKE_QM_I_QM1 New State = IKE_QM_PHASE2_COMPLETE
007099: Jun 23 13:58:41.482: ISAKMP (0:2009): received packet from 172.16.0.1 dport 500 sport 500 Global (I) QM_IDLE
007100: Jun 23 13:58:41.482: ISAKMP: set new node -1038539984 to QM_IDLE
007101: Jun 23 13:58:41.482: ISAKMP:(2009): processing HASH payload. message ID = -1038539984
007102: Jun 23 13:58:41.486: ISAKMP:(2009): processing DELETE payload. message ID = -1038539984
007103: Jun 23 13:58:41.486: ISAKMP:(2009):peer does not do paranoid keepalives.

007104: Jun 23 13:58:41.486: ISAKMP:(2009):deleting node -1038539984 error FALSE reason "Informational (in) state 1"
007105: Jun 23 13:58:41.486: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007106: Jun 23 13:58:41.486: IPSEC(key_engine_delete_sas): rec'd delete notify from ISAKMP
007107: Jun 23 13:58:41.486: IPSEC(key_engine_delete_sas): delete SA with spi 0xAFDE8967 proto 50 for 172.16.0.1
007108: Jun 23 13:58:41.486: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 10.10.0.1, sa_proto= 50,
    sa_spi= 0xAA33E349(2855527241),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1773,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007109: Jun 23 13:58:41.486: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 172.16.0.1, sa_proto= 50,
    sa_spi= 0xAFDE8967(2950596967),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1774,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007110: Jun 23 13:59:01.381: ISAKMP:(2009):purging node 167915285
007111: Jun 23 13:59:31.483: ISAKMP:(2009):purging node -1038539984
007112: Jun 23 13:59:37.507: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007113: Jun 23 13:59:37.507: IPSEC(lifetime_expiry): SA lifetime threshold reached, expiring in 33 seconds
007114: Jun 23 13:59:37.507: ISAKMP: set new node 0 to QM_IDLE
007115: Jun 23 13:59:37.507: SA has outstanding requests (local 100.88.56.140 port 500, remote 100.88.56.112 port 500)
007116: Jun 23 13:59:37.507: ISAKMP:(2009): sitting IDLE. Starting QM immediately (QM_IDLE      )
007117: Jun 23 13:59:37.507: ISAKMP:(2009):beginning Quick Mode exchange, M-ID of 145469079
007118: Jun 23 13:59:37.507: ISAKMP:(2009):QM Initiator gets spi
007119: Jun 23 13:59:37.511: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007120: Jun 23 13:59:37.511: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007121: Jun 23 13:59:37.511: ISAKMP:(2009):Node 145469079, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
007122: Jun 23 13:59:37.511: ISAKMP:(2009):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
007123: Jun 23 13:59:47.511: ISAKMP:(2009): retransmitting phase 2 QM_IDLE       145469079 ...
007124: Jun 23 13:59:47.511: ISAKMP (0:2009): incrementing error counter on node, attempt 1 of 5: retransmit phase 2
007125: Jun 23 13:59:47.511: ISAKMP (0:2009): incrementing error counter on sa, attempt 1 of 5: retransmit phase 2
007126: Jun 23 13:59:47.511: ISAKMP:(2009): retransmitting phase 2 145469079 QM_IDLE
007127: Jun 23 13:59:47.511: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007128: Jun 23 13:59:47.511: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007129: Jun 23 13:59:57.510: ISAKMP:(2009): retransmitting phase 2 QM_IDLE       145469079 ...
007130: Jun 23 13:59:57.510: ISAKMP (0:2009): incrementing error counter on node, attempt 2 of 5: retransmit phase 2
007131: Jun 23 13:59:57.510: ISAKMP (0:2009): incrementing error counter on sa, attempt 2 of 5: retransmit phase 2
007132: Jun 23 13:59:57.510: ISAKMP:(2009): retransmitting phase 2 145469079 QM_IDLE
007133: Jun 23 13:59:57.510: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007134: Jun 23 13:59:57.510: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007135: Jun 23 14:00:07.506: IPSEC(key_engine): request timer fired: count = 1,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007136: Jun 23 14:00:07.506: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007137: Jun 23 14:00:07.506: ISAKMP: set new node 0 to QM_IDLE
007138: Jun 23 14:00:07.506: SA has outstanding requests (local 100.88.56.140 port 500, remote 100.88.56.112 port 500)
007139: Jun 23 14:00:07.506: ISAKMP:(2009): sitting IDLE. Starting QM immediately (QM_IDLE      )
007140: Jun 23 14:00:07.506: ISAKMP:(2009):beginning Quick Mode exchange, M-ID of -747304630
007141: Jun 23 14:00:07.506: ISAKMP:(2009):QM Initiator gets spi
007142: Jun 23 14:00:07.510: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007143: Jun 23 14:00:07.510: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007144: Jun 23 14:00:07.510: ISAKMP:(2009):Node -747304630, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
007145: Jun 23 14:00:07.510: ISAKMP:(2009):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
007146: Jun 23 14:00:07.510: ISAKMP:(2009): retransmitting phase 2 QM_IDLE       145469079 ...
007147: Jun 23 14:00:07.510: ISAKMP (0:2009): incrementing error counter on node, attempt 3 of 5: retransmit phase 2
007148: Jun 23 14:00:07.510: ISAKMP (0:2009): incrementing error counter on sa, attempt 3 of 5: retransmit phase 2
007149: Jun 23 14:00:07.510: ISAKMP:(2009): retransmitting phase 2 145469079 QM_IDLE
007150: Jun 23 14:00:07.510: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007151: Jun 23 14:00:07.510: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007152: Jun 23 14:00:11.373: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 10.10.0.1, sa_proto= 50,
    sa_spi= 0x23CD47B9(600655801),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1775,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007153: Jun 23 14:00:11.373: IPSEC(update_current_outbound_sa): updated peer 172.16.0.1 current outbound sa to SPI 0
007154: Jun 23 14:00:11.373: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 172.16.0.1, sa_proto= 50,
    sa_spi= 0xEEDBE0CE(4007387342),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1776,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007155: Jun 23 14:00:11.373: ISAKMP: set new node -896289620 to QM_IDLE
007156: Jun 23 14:00:11.377: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007157: Jun 23 14:00:11.377: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007158: Jun 23 14:00:11.377: ISAKMP:(2009):purging node -896289620
007159: Jun 23 14:00:11.377: ISAKMP:(2009):Input = IKE_MESG_FROM_IPSEC, IKE_PHASE2_DEL
007160: Jun 23 14:00:11.377: ISAKMP:(2009):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

007161: Jun 23 14:00:17.509: ISAKMP:(2009): retransmitting phase 2 QM_IDLE       -747304630 ...
007162: Jun 23 14:00:17.509: ISAKMP (0:2009): incrementing error counter on node, attempt 1 of 5: retransmit phase 2
007163: Jun 23 14:00:17.509: ISAKMP (0:2009): incrementing error counter on sa, attempt 4 of 5: retransmit phase 2
007164: Jun 23 14:00:17.509: ISAKMP:(2009): retransmitting phase 2 -747304630 QM_IDLE
007165: Jun 23 14:00:17.509: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007166: Jun 23 14:00:17.509: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007167: Jun 23 14:00:17.509: ISAKMP:(2009): retransmitting phase 2 QM_IDLE       145469079 ...
007168: Jun 23 14:00:17.509: ISAKMP (0:2009): incrementing error counter on node, attempt 4 of 5: retransmit phase 2
007169: Jun 23 14:00:17.509: ISAKMP (0:2009): incrementing error counter on sa, attempt 5 of 5: retransmit phase 2
007170: Jun 23 14:00:17.509: ISAKMP:(2009): retransmitting phase 2 145469079 QM_IDLE
007171: Jun 23 14:00:17.509: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007172: Jun 23 14:00:17.509: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007173: Jun 23 14:00:27.509: ISAKMP:(2009): retransmitting phase 2 QM_IDLE       -747304630 ...
007174: Jun 23 14:00:27.509: ISAKMP:(2009):peer does not do paranoid keepalives.

007175: Jun 23 14:00:27.509: ISAKMP:(2009):deleting SA reason "Death by retransmission P2" state (I) QM_IDLE (peer 172.16.0.1)
007176: Jun 23 14:00:27.509: ISAKMP:(2009): retransmitting phase 2 QM_IDLE 145469079 ...
007177: Jun 23 14:00:27.509: ISAKMP:(2009):peer does not do paranoid keepalives.

007178: Jun 23 14:00:27.509: ISAKMP: set new node -1374653830 to QM_IDLE
007179: Jun 23 14:00:27.509: ISAKMP:(2009): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007180: Jun 23 14:00:27.509: ISAKMP:(2009):Sending an IKE IPv4 Packet.
007181: Jun 23 14:00:27.513: ISAKMP:(2009):purging node -1374653830
007182: Jun 23 14:00:27.513: ISAKMP:(2009):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
007183: Jun 23 14:00:27.513: ISAKMP:(2009):Old State = IKE_P1_COMPLETE New State = IKE_DEST_SA

007184: Jun 23 14:00:27.513: ISAKMP:(2009):deleting SA reason "Death by retransmission P2" state (I) QM_IDLE (peer 172.16.0.1)
007185: Jun 23 14:00:27.513: ISAKMP:(0):Can't decrement IKE Call Admission Control stat outgoing_active since it's already 0.
007186: Jun 23 14:00:27.513: ISAKMP: Unlocking peer struct 0x64714A0C for isadb_mark_sa_deleted(), count 0
007187: Jun 23 14:00:27.513: ISAKMP: Deleting peer node by peer_reap for 172.16.0.1: 64714A0C
007188: Jun 23 14:00:27.513: ISAKMP:(2009):deleting node 145469079 error FALSE reason "IKE deleted"
007189: Jun 23 14:00:27.513: ISAKMP:(2009):deleting node -747304630 error FALSE reason "IKE deleted"
007190: Jun 23 14:00:27.517: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007191: Jun 23 14:00:27.517: ISAKMP:(2009):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
007192: Jun 23 14:00:27.517: ISAKMP:(2009):Old State = IKE_DEST_SA New State = IKE_DEST_SA

007193: Jun 23 14:00:37.504: IPSEC(key_engine): request timer fired: count = 2,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007194: Jun 23 14:00:37.580: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007195: Jun 23 14:00:37.580: ISAKMP:(0): SA request profile is (NULL)
007196: Jun 23 14:00:37.580: ISAKMP: Created a peer struct for 172.16.0.1, peer port 500
007197: Jun 23 14:00:37.580: ISAKMP: New peer created peer = 0x64714A0C peer_handle = 0x80000032
007198: Jun 23 14:00:37.584: ISAKMP: Locking peer struct 0x64714A0C, refcount 1 for isakmp_initiator
007199: Jun 23 14:00:37.584: ISAKMP: local port 500, remote port 500
007200: Jun 23 14:00:37.584: ISAKMP: set new node 0 to QM_IDLE
007201: Jun 23 14:00:37.584: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 6541FD58
007202: Jun 23 14:00:37.584: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
007203: Jun 23 14:00:37.584: ISAKMP:(0):found peer pre-shared key matching 172.16.0.1
007204: Jun 23 14:00:37.584: ISAKMP:(0): constructed NAT-T vendor-07 ID
007205: Jun 23 14:00:37.584: ISAKMP:(0): constructed NAT-T vendor-03 ID
007206: Jun 23 14:00:37.584: ISAKMP:(0): constructed NAT-T vendor-02 ID
007207: Jun 23 14:00:37.584: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
007208: Jun 23 14:00:37.584: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

007209: Jun 23 14:00:37.584: ISAKMP:(0): beginning Main Mode exchange
007210: Jun 23 14:00:37.584: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007211: Jun 23 14:00:37.584: ISAKMP:(0):Sending an IKE IPv4 Packet.
007212: Jun 23 14:00:47.584: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007213: Jun 23 14:00:47.584: ISAKMP (0:0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1
007214: Jun 23 14:00:47.584: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007215: Jun 23 14:00:47.584: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007216: Jun 23 14:00:47.584: ISAKMP:(0):Sending an IKE IPv4 Packet.
007217: Jun 23 14:00:57.583: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007218: Jun 23 14:00:57.583: ISAKMP (0:0): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
007219: Jun 23 14:00:57.583: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007220: Jun 23 14:00:57.583: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007221: Jun 23 14:00:57.583: ISAKMP:(0):Sending an IKE IPv4 Packet.
007222: Jun 23 14:01:07.579: IPSEC(key_engine): request timer fired: count = 1,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007223: Jun 23 14:01:07.579: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007224: Jun 23 14:01:07.579: ISAKMP: set new node 0 to QM_IDLE
007225: Jun 23 14:01:07.579: ISAKMP:(0):SA is still budding. Attached new ipsec request to it. (local 10.10.0.1, remote 172.16.0.1)
007226: Jun 23 14:01:07.579: ISAKMP: Error while processing SA request: Failed to initialize SA
007227: Jun 23 14:01:07.583: ISAKMP: Error while processing KMI message 0, error 2.
007228: Jun 23 14:01:07.583: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007229: Jun 23 14:01:07.583: ISAKMP (0:0): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1
007230: Jun 23 14:01:07.583: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007231: Jun 23 14:01:07.583: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007232: Jun 23 14:01:07.583: ISAKMP:(0):Sending an IKE IPv4 Packet.
007233: Jun 23 14:01:17.511: ISAKMP:(2009):purging node 145469079
007234: Jun 23 14:01:17.511: ISAKMP:(2009):purging node -747304630
007235: Jun 23 14:01:17.583: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007236: Jun 23 14:01:17.583: ISAKMP (0:0): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1
007237: Jun 23 14:01:17.583: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007238: Jun 23 14:01:17.583: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007239: Jun 23 14:01:17.583: ISAKMP:(0):Sending an IKE IPv4 Packet.
007240: Jun 23 14:01:27.510: ISAKMP:(2009):purging SA., sa=64583728, delme=64583728
007241: Jun 23 14:01:27.582: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007242: Jun 23 14:01:27.582: ISAKMP (0:0): incrementing error counter on sa, attempt 5 of 5: retransmit phase 1
007243: Jun 23 14:01:27.582: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007244: Jun 23 14:01:27.582: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007245: Jun 23 14:01:27.582: ISAKMP:(0):Sending an IKE IPv4 Packet.
007246: Jun 23 14:01:37.578: IPSEC(key_engine): request timer fired: count = 2,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007247: Jun 23 14:01:37.582: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007248: Jun 23 14:01:37.582: ISAKMP:(0):peer does not do paranoid keepalives.

007249: Jun 23 14:01:37.582: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 172.16.0.1)
007250: Jun 23 14:01:37.582: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 172.16.0.1)
007251: Jun 23 14:01:37.582: ISAKMP: Unlocking peer struct 0x64714A0C for isadb_mark_sa_deleted(), count 0
007252: Jun 23 14:01:37.582: ISAKMP: Deleting peer node by peer_reap for 172.16.0.1: 64714A0C
007253: Jun 23 14:01:37.582: ISAKMP:(0):deleting node -1325544619 error FALSE reason "IKE deleted"
007254: Jun 23 14:01:37.582: ISAKMP:(0):deleting node -1577708965 error FALSE reason "IKE deleted"
007255: Jun 23 14:01:37.582: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
007256: Jun 23 14:01:37.586: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_DEST_SA

007257: Jun 23 14:01:37.586: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007258: Jun 23 14:01:37.586: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007259: Jun 23 14:01:37.586: ISAKMP:(0): SA request profile is (NULL)
007260: Jun 23 14:01:37.586: ISAKMP: Created a peer struct for 172.16.0.1, peer port 500
007261: Jun 23 14:01:37.586: ISAKMP: New peer created peer = 0x64714A0C peer_handle = 0x80000033
007262: Jun 23 14:01:37.586: ISAKMP: Locking peer struct 0x64714A0C, refcount 1 for isakmp_initiator
007263: Jun 23 14:01:37.586: ISAKMP: local port 500, remote port 500
007264: Jun 23 14:01:37.590: ISAKMP: set new node 0 to QM_IDLE
007265: Jun 23 14:01:37.590: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 6582C51C
007266: Jun 23 14:01:37.590: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
007267: Jun 23 14:01:37.590: ISAKMP:(0):found peer pre-shared key matching 172.16.0.1
007268: Jun 23 14:01:37.590: ISAKMP:(0): constructed NAT-T vendor-07 ID
007269: Jun 23 14:01:37.590: ISAKMP:(0): constructed NAT-T vendor-03 ID
007270: Jun 23 14:01:37.590: ISAKMP:(0): constructed NAT-T vendor-02 ID
007271: Jun 23 14:01:37.590: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
007272: Jun 23 14:01:37.590: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

007273: Jun 23 14:01:37.590: ISAKMP:(0): beginning Main Mode exchange
007274: Jun 23 14:01:37.590: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007275: Jun 23 14:01:37.590: ISAKMP:(0):Sending an IKE IPv4 Packet.
007276: Jun 23 14:01:47.589: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007277: Jun 23 14:01:47.589: ISAKMP (0:0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1
007278: Jun 23 14:01:47.589: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007279: Jun 23 14:01:47.589: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007280: Jun 23 14:01:47.589: ISAKMP:(0):Sending an IKE IPv4 Packet.
007281: Jun 23 14:01:57.589: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007282: Jun 23 14:01:57.589: ISAKMP (0:0): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
007283: Jun 23 14:01:57.589: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007284: Jun 23 14:01:57.589: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007285: Jun 23 14:01:57.589: ISAKMP:(0):Sending an IKE IPv4 Packet.
007286: Jun 23 14:02:07.585: IPSEC(key_engine): request timer fired: count = 1,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007287: Jun 23 14:02:07.585: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007288: Jun 23 14:02:07.585: ISAKMP: set new node 0 to QM_IDLE
007289: Jun 23 14:02:07.589: ISAKMP:(0):SA is still budding. Attached new ipsec request to it. (local 10.10.0.1, remote 172.16.0.1)
007290: Jun 23 14:02:07.589: ISAKMP: Error while processing SA request: Failed to initialize SA
007291: Jun 23 14:02:07.589: ISAKMP: Error while processing KMI message 0, error 2.
007292: Jun 23 14:02:07.589: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007293: Jun 23 14:02:07.589: ISAKMP (0:0): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1
007294: Jun 23 14:02:07.589: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007295: Jun 23 14:02:07.589: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007296: Jun 23 14:02:07.589: ISAKMP:(0):Sending an IKE IPv4 Packet.
007297: Jun 23 14:02:17.588: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007298: Jun 23 14:02:17.588: ISAKMP (0:0): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1
007299: Jun 23 14:02:17.588: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007300: Jun 23 14:02:17.588: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007301: Jun 23 14:02:17.588: ISAKMP:(0):Sending an IKE IPv4 Packet.
007302: Jun 23 14:02:27.580: ISAKMP:(0):purging node -1325544619
007303: Jun 23 14:02:27.580: ISAKMP:(0):purging node -1577708965
007304: Jun 23 14:02:27.588: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007305: Jun 23 14:02:27.588: ISAKMP (0:0): incrementing error counter on sa, attempt 5 of 5: retransmit phase 1
007306: Jun 23 14:02:27.588: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007307: Jun 23 14:02:27.588: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007308: Jun 23 14:02:27.588: ISAKMP:(0):Sending an IKE IPv4 Packet.
007309: Jun 23 14:02:37.580: ISAKMP:(0):purging SA., sa=6541FD58, delme=6541FD58
007310: Jun 23 14:02:37.584: IPSEC(key_engine): request timer fired: count = 2,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007311: Jun 23 14:02:37.588: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007312: Jun 23 14:02:37.588: ISAKMP:(0):peer does not do paranoid keepalives.

007313: Jun 23 14:02:37.588: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 172.16.0.1)
007314: Jun 23 14:02:37.588: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 172.16.0.1)
007315: Jun 23 14:02:37.588: ISAKMP: Unlocking peer struct 0x64714A0C for isadb_mark_sa_deleted(), count 0
007316: Jun 23 14:02:37.588: ISAKMP: Deleting peer node by peer_reap for 172.16.0.1: 64714A0C
007317: Jun 23 14:02:37.588: ISAKMP:(0):deleting node -1840443706 error FALSE reason "IKE deleted"
007318: Jun 23 14:02:37.588: ISAKMP:(0):deleting node -1326619720 error FALSE reason "IKE deleted"
007319: Jun 23 14:02:37.588: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
007320: Jun 23 14:02:37.588: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_DEST_SA

007321: Jun 23 14:02:37.588: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007322: Jun 23 14:02:38.048: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007323: Jun 23 14:02:38.048: ISAKMP:(0): SA request profile is (NULL)
007324: Jun 23 14:02:38.048: ISAKMP: Created a peer struct for 172.16.0.1, peer port 500
007325: Jun 23 14:02:38.048: ISAKMP: New peer created peer = 0x64714A0C peer_handle = 0x80000034
007326: Jun 23 14:02:38.048: ISAKMP: Locking peer struct 0x64714A0C, refcount 1 for isakmp_initiator
007327: Jun 23 14:02:38.048: ISAKMP: local port 500, remote port 500
007328: Jun 23 14:02:38.048: ISAKMP: set new node 0 to QM_IDLE
007329: Jun 23 14:02:38.048: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 6541FD58
007330: Jun 23 14:02:38.048: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
007331: Jun 23 14:02:38.048: ISAKMP:(0):found peer pre-shared key matching 172.16.0.1
007332: Jun 23 14:02:38.052: ISAKMP:(0): constructed NAT-T vendor-07 ID
007333: Jun 23 14:02:38.052: ISAKMP:(0): constructed NAT-T vendor-03 ID
007334: Jun 23 14:02:38.052: ISAKMP:(0): constructed NAT-T vendor-02 ID
007335: Jun 23 14:02:38.052: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
007336: Jun 23 14:02:38.052: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

007337: Jun 23 14:02:38.052: ISAKMP:(0): beginning Main Mode exchange
007338: Jun 23 14:02:38.052: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007339: Jun 23 14:02:38.052: ISAKMP:(0):Sending an IKE IPv4 Packet.
007340: Jun 23 14:02:48.051: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007341: Jun 23 14:02:48.051: ISAKMP (0:0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1
007342: Jun 23 14:02:48.051: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007343: Jun 23 14:02:48.051: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007344: Jun 23 14:02:48.051: ISAKMP:(0):Sending an IKE IPv4 Packet.
007345: Jun 23 14:02:58.051: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007346: Jun 23 14:02:58.051: ISAKMP (0:0): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
007347: Jun 23 14:02:58.051: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007348: Jun 23 14:02:58.051: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007349: Jun 23 14:02:58.051: ISAKMP:(0):Sending an IKE IPv4 Packet.
007350: Jun 23 14:03:08.046: IPSEC(key_engine): request timer fired: count = 1,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007351: Jun 23 14:03:08.046: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007352: Jun 23 14:03:08.046: ISAKMP: set new node 0 to QM_IDLE
007353: Jun 23 14:03:08.046: ISAKMP:(0):SA is still budding. Attached new ipsec request to it. (local 10.10.0.1, remote 172.16.0.1)
007354: Jun 23 14:03:08.046: ISAKMP: Error while processing SA request: Failed to initialize SA
007355: Jun 23 14:03:08.046: ISAKMP: Error while processing KMI message 0, error 2.
007356: Jun 23 14:03:08.050: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007357: Jun 23 14:03:08.050: ISAKMP (0:0): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1
007358: Jun 23 14:03:08.050: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007359: Jun 23 14:03:08.050: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007360: Jun 23 14:03:08.050: ISAKMP:(0):Sending an IKE IPv4 Packet.
007361: Jun 23 14:03:18.050: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007362: Jun 23 14:03:18.050: ISAKMP (0:0): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1
007363: Jun 23 14:03:18.050: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007364: Jun 23 14:03:18.050: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007365: Jun 23 14:03:18.050: ISAKMP:(0):Sending an IKE IPv4 Packet.
007366: Jun 23 14:03:27.586: ISAKMP:(0):purging node -1840443706
007367: Jun 23 14:03:27.586: ISAKMP:(0):purging node -1326619720
007368: Jun 23 14:03:28.050: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007369: Jun 23 14:03:28.050: ISAKMP (0:0): incrementing error counter on sa, attempt 5 of 5: retransmit phase 1
007370: Jun 23 14:03:28.050: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007371: Jun 23 14:03:28.050: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007372: Jun 23 14:03:28.050: ISAKMP:(0):Sending an IKE IPv4 Packet.
007373: Jun 23 14:03:37.585: ISAKMP:(0):purging SA., sa=6582C51C, delme=6582C51C
007374: Jun 23 14:03:38.045: IPSEC(key_engine): request timer fired: count = 2,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007375: Jun 23 14:03:38.049: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007376: Jun 23 14:03:38.049: ISAKMP:(0):peer does not do paranoid keepalives.

007377: Jun 23 14:03:38.049: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 172.16.0.1)
007378: Jun 23 14:03:38.049: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 172.16.0.1)
007379: Jun 23 14:03:38.049: ISAKMP: Unlocking peer struct 0x64714A0C for isadb_mark_sa_deleted(), count 0
007380: Jun 23 14:03:38.049: ISAKMP: Deleting peer node by peer_reap for 172.16.0.1: 64714A0C
007381: Jun 23 14:03:38.049: ISAKMP:(0):deleting node -724917655 error FALSE reason "IKE deleted"
007382: Jun 23 14:03:38.049: ISAKMP:(0):deleting node 1443344140 error FALSE reason "IKE deleted"
007383: Jun 23 14:03:38.049: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
007384: Jun 23 14:03:38.049: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_DEST_SA

007385: Jun 23 14:03:38.049: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007386: Jun 23 14:03:38.589: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007387: Jun 23 14:03:38.593: ISAKMP:(0): SA request profile is (NULL)
007388: Jun 23 14:03:38.593: ISAKMP: Created a peer struct for 172.16.0.1, peer port 500
007389: Jun 23 14:03:38.593: ISAKMP: New peer created peer = 0x64714A0C peer_handle = 0x80000035
007390: Jun 23 14:03:38.593: ISAKMP: Locking peer struct 0x64714A0C, refcount 1 for isakmp_initiator
007391: Jun 23 14:03:38.593: ISAKMP: local port 500, remote port 500
007392: Jun 23 14:03:38.593: ISAKMP: set new node 0 to QM_IDLE
007393: Jun 23 14:03:38.593: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 654204AC
007394: Jun 23 14:03:38.593: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
007395: Jun 23 14:03:38.593: ISAKMP:(0):found peer pre-shared key matching 172.16.0.1
007396: Jun 23 14:03:38.597: ISAKMP:(0): constructed NAT-T vendor-07 ID
007397: Jun 23 14:03:38.597: ISAKMP:(0): constructed NAT-T vendor-03 ID
007398: Jun 23 14:03:38.597: ISAKMP:(0): constructed NAT-T vendor-02 ID
007399: Jun 23 14:03:38.597: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
007400: Jun 23 14:03:38.597: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

007401: Jun 23 14:03:38.597: ISAKMP:(0): beginning Main Mode exchange
007402: Jun 23 14:03:38.597: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007403: Jun 23 14:03:38.597: ISAKMP:(0):Sending an IKE IPv4 Packet.
007404: Jun 23 14:03:48.597: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007405: Jun 23 14:03:48.597: ISAKMP (0:0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1
007406: Jun 23 14:03:48.597: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007407: Jun 23 14:03:48.597: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007408: Jun 23 14:03:48.597: ISAKMP:(0):Sending an IKE IPv4 Packet.
007409: Jun 23 14:03:58.597: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007410: Jun 23 14:03:58.597: ISAKMP (0:0): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
007411: Jun 23 14:03:58.597: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007412: Jun 23 14:03:58.597: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007413: Jun 23 14:03:58.597: ISAKMP:(0):Sending an IKE IPv4 Packet.
007414: Jun 23 14:04:08.588: IPSEC(key_engine): request timer fired: count = 1,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007415: Jun 23 14:04:08.588: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007416: Jun 23 14:04:08.588: ISAKMP: set new node 0 to QM_IDLE
007417: Jun 23 14:04:08.588: ISAKMP:(0):SA is still budding. Attached new ipsec request to it. (local 10.10.0.1, remote 172.16.0.1)
007418: Jun 23 14:04:08.588: ISAKMP: Error while processing SA request: Failed to initialize SA
007419: Jun 23 14:04:08.588: ISAKMP: Error while processing KMI message 0, error 2.
007420: Jun 23 14:04:08.596: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007421: Jun 23 14:04:08.596: ISAKMP (0:0): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1
007422: Jun 23 14:04:08.596: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007423: Jun 23 14:04:08.596: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007424: Jun 23 14:04:08.596: ISAKMP:(0):Sending an IKE IPv4 Packet.
007425: Jun 23 14:04:18.596: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007426: Jun 23 14:04:18.596: ISAKMP (0:0): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1
007427: Jun 23 14:04:18.596: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007428: Jun 23 14:04:18.596: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007429: Jun 23 14:04:18.596: ISAKMP:(0):Sending an IKE IPv4 Packet.
007430: Jun 23 14:04:28.048: ISAKMP:(0):purging node -724917655
007431: Jun 23 14:04:28.048: ISAKMP:(0):purging node 1443344140
007432: Jun 23 14:04:28.596: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007433: Jun 23 14:04:28.596: ISAKMP (0:0): incrementing error counter on sa, attempt 5 of 5: retransmit phase 1
007434: Jun 23 14:04:28.596: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007435: Jun 23 14:04:28.596: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007436: Jun 23 14:04:28.596: ISAKMP:(0):Sending an IKE IPv4 Packet.
007437: Jun 23 14:04:38.047: ISAKMP:(0):purging SA., sa=6541FD58, delme=6541FD58
007438: Jun 23 14:04:38.587: IPSEC(key_engine): request timer fired: count = 2,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007439: Jun 23 14:04:38.595: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007440: Jun 23 14:04:38.595: ISAKMP:(0):peer does not do paranoid keepalives.

007441: Jun 23 14:04:38.595: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 172.16.0.1)
007442: Jun 23 14:04:38.595: ISAKMP:(0):deleting SA reason "Death by retransmission P1" state (I) MM_NO_STATE (peer 172.16.0.1)
007443: Jun 23 14:04:38.595: ISAKMP: Unlocking peer struct 0x64714A0C for isadb_mark_sa_deleted(), count 0
007444: Jun 23 14:04:38.595: ISAKMP: Deleting peer node by peer_reap for 172.16.0.1: 64714A0C
007445: Jun 23 14:04:38.595: ISAKMP:(0):deleting node 330065933 error FALSE reason "IKE deleted"
007446: Jun 23 14:04:38.595: ISAKMP:(0):deleting node 1621986003 error FALSE reason "IKE deleted"
007447: Jun 23 14:04:38.595: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PHASE1_DEL
007448: Jun 23 14:04:38.595: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_DEST_SA

007449: Jun 23 14:04:38.595: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007450: Jun 23 14:04:38.623: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007451: Jun 23 14:04:38.627: ISAKMP:(0): SA request profile is (NULL)
007452: Jun 23 14:04:38.627: ISAKMP: Created a peer struct for 172.16.0.1, peer port 500
007453: Jun 23 14:04:38.627: ISAKMP: New peer created peer = 0x64714A0C peer_handle = 0x80000036
007454: Jun 23 14:04:38.627: ISAKMP: Locking peer struct 0x64714A0C, refcount 1 for isakmp_initiator
007455: Jun 23 14:04:38.627: ISAKMP: local port 500, remote port 500
007456: Jun 23 14:04:38.627: ISAKMP: set new node 0 to QM_IDLE
007457: Jun 23 14:04:38.627: ISAKMP: Find a dup sa in the avl tree during calling isadb_insert sa = 6582C51C
007458: Jun 23 14:04:38.627: ISAKMP:(0):Can not start Aggressive mode, trying Main mode.
007459: Jun 23 14:04:38.627: ISAKMP:(0):found peer pre-shared key matching 172.16.0.1
007460: Jun 23 14:04:38.627: ISAKMP:(0): constructed NAT-T vendor-07 ID
007461: Jun 23 14:04:38.627: ISAKMP:(0): constructed NAT-T vendor-03 ID
007462: Jun 23 14:04:38.627: ISAKMP:(0): constructed NAT-T vendor-02 ID
007463: Jun 23 14:04:38.627: ISAKMP:(0):Input = IKE_MESG_FROM_IPSEC, IKE_SA_REQ_MM
007464: Jun 23 14:04:38.627: ISAKMP:(0):Old State = IKE_READY New State = IKE_I_MM1

007465: Jun 23 14:04:38.627: ISAKMP:(0): beginning Main Mode exchange
007466: Jun 23 14:04:38.627: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007467: Jun 23 14:04:38.627: ISAKMP:(0):Sending an IKE IPv4 Packet.
007468: Jun 23 14:04:48.631: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007469: Jun 23 14:04:48.631: ISAKMP (0:0): incrementing error counter on sa, attempt 1 of 5: retransmit phase 1
007470: Jun 23 14:04:48.631: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007471: Jun 23 14:04:48.631: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007472: Jun 23 14:04:48.631: ISAKMP:(0):Sending an IKE IPv4 Packet.
007473: Jun 23 14:04:58.630: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007474: Jun 23 14:04:58.630: ISAKMP (0:0): incrementing error counter on sa, attempt 2 of 5: retransmit phase 1
007475: Jun 23 14:04:58.630: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007476: Jun 23 14:04:58.630: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007477: Jun 23 14:04:58.630: ISAKMP:(0):Sending an IKE IPv4 Packet.
007478: Jun 23 14:05:08.622: IPSEC(key_engine): request timer fired: count = 1,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007479: Jun 23 14:05:08.622: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007480: Jun 23 14:05:08.622: ISAKMP: set new node 0 to QM_IDLE
007481: Jun 23 14:05:08.622: ISAKMP:(0):SA is still budding. Attached new ipsec request to it. (local 10.10.0.1, remote 172.16.0.1)
007482: Jun 23 14:05:08.622: ISAKMP: Error while processing SA request: Failed to initialize SA
007483: Jun 23 14:05:08.622: ISAKMP: Error while processing KMI message 0, error 2.
007484: Jun 23 14:05:08.630: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007485: Jun 23 14:05:08.630: ISAKMP (0:0): incrementing error counter on sa, attempt 3 of 5: retransmit phase 1
007486: Jun 23 14:05:08.630: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007487: Jun 23 14:05:08.630: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007488: Jun 23 14:05:08.630: ISAKMP:(0):Sending an IKE IPv4 Packet.
007489: Jun 23 14:05:18.630: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007490: Jun 23 14:05:18.630: ISAKMP (0:0): incrementing error counter on sa, attempt 4 of 5: retransmit phase 1
007491: Jun 23 14:05:18.630: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007492: Jun 23 14:05:18.630: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007493: Jun 23 14:05:18.630: ISAKMP:(0):Sending an IKE IPv4 Packet.
007494: Jun 23 14:05:28.593: ISAKMP:(0):purging node 330065933
007495: Jun 23 14:05:28.593: ISAKMP:(0):purging node 1621986003
007496: Jun 23 14:05:28.629: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE...
007497: Jun 23 14:05:28.629: ISAKMP (0:0): incrementing error counter on sa, attempt 5 of 5: retransmit phase 1
007498: Jun 23 14:05:28.629: ISAKMP:(0): retransmitting phase 1 MM_NO_STATE
007499: Jun 23 14:05:28.629: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_NO_STATE
007500: Jun 23 14:05:28.629: ISAKMP:(0):Sending an IKE IPv4 Packet.
007501: Jun 23 14:05:29.229: ISAKMP (0:0): received packet from 172.16.0.1 dport 500 sport 500 Global (I) MM_NO_STATE
007502: Jun 23 14:05:29.229: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
007503: Jun 23 14:05:29.233: ISAKMP:(0):Old State = IKE_I_MM1 New State = IKE_I_MM2

007504: Jun 23 14:05:29.233: ISAKMP:(0): processing SA payload. message ID = 0
007505: Jun 23 14:05:29.233: ISAKMP:(0): processing vendor id payload
007506: Jun 23 14:05:29.233: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch
007507: Jun 23 14:05:29.233: ISAKMP (0:0): vendor ID is NAT-T v7
007508: Jun 23 14:05:29.233: ISAKMP:(0):found peer pre-shared key matching 172.16.0.1
007509: Jun 23 14:05:29.233: ISAKMP:(0): local preshared key found
007510: Jun 23 14:05:29.233: ISAKMP : Scanning profiles for xauth ... VPNclient
007511: Jun 23 14:05:29.233: ISAKMP:(0): Authentication by xauth preshared
007512: Jun 23 14:05:29.233: ISAKMP:(0):Checking ISAKMP transform 1 against priority 10 policy
007513: Jun 23 14:05:29.233: ISAKMP:      encryption DES-CBC
007514: Jun 23 14:05:29.233: ISAKMP:      hash MD5
007515: Jun 23 14:05:29.233: ISAKMP:      default group 1
007516: Jun 23 14:05:29.233: ISAKMP:      auth pre-share
007517: Jun 23 14:05:29.233: ISAKMP:      life type in seconds
007518: Jun 23 14:05:29.233: ISAKMP:      life duration (VPI) of 0x0 0x1 0x51 0x80
007519: Jun 23 14:05:29.233: ISAKMP:(0):atts are acceptable. Next payload is 0
007520: Jun 23 14:05:29.233: ISAKMP:(0): processing vendor id payload
007521: Jun 23 14:05:29.233: ISAKMP:(0): vendor ID seems Unity/DPD but major 245 mismatch
007522: Jun 23 14:05:29.233: ISAKMP (0:0): vendor ID is NAT-T v7
007523: Jun 23 14:05:29.233: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
007524: Jun 23 14:05:29.233: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM2

007525: Jun 23 14:05:29.237: ISAKMP:(0): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_SA_SETUP
007526: Jun 23 14:05:29.237: ISAKMP:(0):Sending an IKE IPv4 Packet.
007527: Jun 23 14:05:29.237: ISAKMP:(0):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
007528: Jun 23 14:05:29.237: ISAKMP:(0):Old State = IKE_I_MM2 New State = IKE_I_MM3

007529: Jun 23 14:05:29.337: ISAKMP (0:0): received packet from 172.16.0.1 dport 500 sport 500 Global (I) MM_SA_SETUP
007530: Jun 23 14:05:29.337: ISAKMP:(0):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
007531: Jun 23 14:05:29.337: ISAKMP:(0):Old State = IKE_I_MM3 New State = IKE_I_MM4

007532: Jun 23 14:05:29.337: ISAKMP:(0): processing KE payload. message ID = 0
007533: Jun 23 14:05:29.341: ISAKMP:(0): processing NONCE payload. message ID = 0
007534: Jun 23 14:05:29.341: ISAKMP:(0):found peer pre-shared key matching 172.16.0.1
007535: Jun 23 14:05:29.345: ISAKMP:(2010): processing vendor id payload
007536: Jun 23 14:05:29.345: ISAKMP:(2010): vendor ID is Unity
007537: Jun 23 14:05:29.345: ISAKMP:(2010): processing vendor id payload
007538: Jun 23 14:05:29.345: ISAKMP:(2010): vendor ID is DPD
007539: Jun 23 14:05:29.345: ISAKMP:(2010): processing vendor id payload
007540: Jun 23 14:05:29.345: ISAKMP:(2010): speaking to another IOS box!
007541: Jun 23 14:05:29.345: ISAKMP:(2010):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
007542: Jun 23 14:05:29.345: ISAKMP:(2010):Old State = IKE_I_MM4 New State = IKE_I_MM4

007543: Jun 23 14:05:29.345: ISAKMP:(2010):Send initial contact
007544: Jun 23 14:05:29.345: ISAKMP:(2010):SA is doing pre-shared key authentication using id type ID_IPV4_ADDR
007545: Jun 23 14:05:29.345: ISAKMP (0:2010): ID payload
next-payload : 8
type         : 1
address      : 10.10.0.1
protocol     : 17
port         : 500
length       : 12
007546: Jun 23 14:05:29.345: ISAKMP:(2010):Total payload length: 12
007547: Jun 23 14:05:29.349: ISAKMP:(2010): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) MM_KEY_EXCH
007548: Jun 23 14:05:29.349: ISAKMP:(2010):Sending an IKE IPv4 Packet.
007549: Jun 23 14:05:29.349: ISAKMP:(2010):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
007550: Jun 23 14:05:29.349: ISAKMP:(2010):Old State = IKE_I_MM4 New State = IKE_I_MM5

007551: Jun 23 14:05:29.441: ISAKMP (0:2010): received packet from 172.16.0.1 dport 500 sport 500 Global (I) MM_KEY_EXCH
007552: Jun 23 14:05:29.441: ISAKMP:(2010): processing ID payload. message ID = 0
007553: Jun 23 14:05:29.441: ISAKMP (0:2010): ID payload
next-payload : 8
type         : 1
address      : 172.16.0.1
protocol     : 17
port         : 500
length       : 12
007554: Jun 23 14:05:29.441: ISAKMP:(0):: peer matches *none* of the profiles
007555: Jun 23 14:05:29.441: ISAKMP:(2010): processing HASH payload. message ID = 0
007556: Jun 23 14:05:29.445: ISAKMP:(2010):SA authentication status:
authenticated
007557: Jun 23 14:05:29.445: ISAKMP:(2010):SA has been authenticated with 172.16.0.1
007558: Jun 23 14:05:29.445: ISAKMP: Trying to insert a peer 10.10.0.1/172.16.0.1/500/, and inserted successfully 64714A0C.
007559: Jun 23 14:05:29.445: ISAKMP:(2010):Input = IKE_MESG_FROM_PEER, IKE_MM_EXCH
007560: Jun 23 14:05:29.445: ISAKMP:(2010):Old State = IKE_I_MM5 New State = IKE_I_MM6

007561: Jun 23 14:05:29.445: ISAKMP:(2010):Input = IKE_MESG_INTERNAL, IKE_PROCESS_MAIN_MODE
007562: Jun 23 14:05:29.445: ISAKMP:(2010):Old State = IKE_I_MM6 New State = IKE_I_MM6

007563: Jun 23 14:05:29.445: ISAKMP:(2010):Input = IKE_MESG_INTERNAL, IKE_PROCESS_COMPLETE
007564: Jun 23 14:05:29.445: ISAKMP:(2010):Old State = IKE_I_MM6 New State = IKE_P1_COMPLETE

007565: Jun 23 14:05:29.449: ISAKMP:(2010):beginning Quick Mode exchange, M-ID of 1663596817
007566: Jun 23 14:05:29.449: ISAKMP:(2010):QM Initiator gets spi
007567: Jun 23 14:05:29.449: ISAKMP:(2010): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007568: Jun 23 14:05:29.449: ISAKMP:(2010):Sending an IKE IPv4 Packet.
007569: Jun 23 14:05:29.453: ISAKMP:(2010):Node 1663596817, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
007570: Jun 23 14:05:29.453: ISAKMP:(2010):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
007571: Jun 23 14:05:29.453: ISAKMP:(2010):beginning Quick Mode exchange, M-ID of 2097686851
007572: Jun 23 14:05:29.453: ISAKMP:(2010):QM Initiator gets spi
007573: Jun 23 14:05:29.453: ISAKMP:(2010): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007574: Jun 23 14:05:29.453: ISAKMP:(2010):Sending an IKE IPv4 Packet.
007575: Jun 23 14:05:29.457: ISAKMP:(2010):Node 2097686851, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
007576: Jun 23 14:05:29.457: ISAKMP:(2010):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
007577: Jun 23 14:05:29.457: ISAKMP:(2010):Input = IKE_MESG_INTERNAL, IKE_PHASE1_COMPLETE
007578: Jun 23 14:05:29.457: ISAKMP:(2010):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

007579: Jun 23 14:05:29.553: ISAKMP (0:2010): received packet from 172.16.0.1 dport 500 sport 500 Global (I) QM_IDLE
007580: Jun 23 14:05:29.553: ISAKMP:(2010): processing HASH payload. message ID = 1663596817
007581: Jun 23 14:05:29.553: ISAKMP:(2010): processing SA payload. message ID = 1663596817
007582: Jun 23 14:05:29.553: ISAKMP:(2010):Checking IPSec proposal 1
007583: Jun 23 14:05:29.553: ISAKMP: transform 1, ESP_3DES
007584: Jun 23 14:05:29.557: ISAKMP:   attributes in transform:
007585: Jun 23 14:05:29.557: ISAKMP:      encaps is 2 (Transport)
007586: Jun 23 14:05:29.557: ISAKMP:      SA life type in seconds
007587: Jun 23 14:05:29.557: ISAKMP:      SA life duration (basic) of 120
007588: Jun 23 14:05:29.557: ISAKMP:      SA life type in kilobytes
007589: Jun 23 14:05:29.557: ISAKMP:      SA life duration (VPI) of 0x0 0x46 0x50 0x0
007590: Jun 23 14:05:29.557: ISAKMP:      authenticator is HMAC-MD5
007591: Jun 23 14:05:29.557: ISAKMP:(2010):atts are acceptable.
007592: Jun 23 14:05:29.557: IPSEC(validate_proposal_request): proposal part #1
007593: Jun 23 14:05:29.557: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= esp-3des esp-md5-hmac (Transport),
    lifedur= 0s and 0kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007594: Jun 23 14:05:29.557: Crypto mapdb : proxy_match
src addr     : 10.10.0.1
dst addr     : 172.16.0.1
protocol     : 47
src port     : 0
dst port     : 0
007595: Jun 23 14:05:29.557: ISAKMP:(2010): processing NONCE payload. message ID = 1663596817
007596: Jun 23 14:05:29.557: ISAKMP:(2010): processing ID payload. message ID = 1663596817
007597: Jun 23 14:05:29.557: ISAKMP:(2010): processing ID payload. message ID = 1663596817
007598: Jun 23 14:05:29.565: ISAKMP:(2010): Creating IPSec SAs
007599: Jun 23 14:05:29.565:         inbound SA from 172.16.0.1 to 10.10.0.1 (f/i) 0/ 0
        (proxy 172.16.0.1 to 10.10.0.1)
007600: Jun 23 14:05:29.565:         has spi 0x28403477 and conn_id 0
007601: Jun 23 14:05:29.565:         lifetime of 120 seconds
007602: Jun 23 14:05:29.565:         lifetime of 4608000 kilobytes
007603: Jun 23 14:05:29.565:         outbound SA from 10.10.0.1 to 172.16.0.1 (f/i) 0/0
        (proxy 10.10.0.1 to 172.16.0.1)
007604: Jun 23 14:05:29.565:         has spi 0x1117B473 and conn_id 0
007605: Jun 23 14:05:29.569:         lifetime of 120 seconds
007606: Jun 23 14:05:29.569:         lifetime of 4608000 kilobytes
007607: Jun 23 14:05:29.569: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007608: Jun 23 14:05:29.569: Crypto mapdb : proxy_match
src addr     : 10.10.0.1
dst addr     : 172.16.0.1
protocol     : 47
src port     : 0
dst port     : 0
007609: Jun 23 14:05:29.569: IPSEC(crypto_ipsec_sa_find_ident_head): reconnecting with the same proxies and peer 172.16.0.1
007610: Jun 23 14:05:29.569: IPSEC(policy_db_add_ident): src 10.10.0.1, dest 172.16.0.1, dest_port 0

007611: Jun 23 14:05:29.569: IPSEC(create_sa): sa created,
(sa) sa_dest= 10.10.0.1, sa_proto= 50,
    sa_spi= 0x28403477(675296375),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1777
007612: Jun 23 14:05:29.569: IPSEC(create_sa): sa created,
(sa) sa_dest= 172.16.0.1, sa_proto= 50,
    sa_spi= 0x1117B473(286766195),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1778
007613: Jun 23 14:05:29.569: IPSEC(update_current_outbound_sa): updated peer 172.16.0.1 current outbound sa to SPI 1117B473
007614: Jun 23 14:05:29.569: ISAKMP:(2010): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007615: Jun 23 14:05:29.573: ISAKMP:(2010):Sending an IKE IPv4 Packet.
007616: Jun 23 14:05:29.573: ISAKMP:(2010):deleting node 1663596817 error FALSE reason "No Error"
007617: Jun 23 14:05:29.573: ISAKMP:(2010):Node 1663596817, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
007618: Jun 23 14:05:29.573: ISAKMP:(2010):Old State = IKE_QM_I_QM1 New State = IKE_QM_PHASE2_COMPLETE
007619: Jun 23 14:05:29.573: ISAKMP (0:2010): received packet from 172.16.0.1 dport 500 sport 500 Global (I) QM_IDLE
007620: Jun 23 14:05:29.577: ISAKMP:(2010): processing HASH payload. message ID = 2097686851
007621: Jun 23 14:05:29.577: ISAKMP:(2010): processing SA payload. message ID = 2097686851
007622: Jun 23 14:05:29.577: ISAKMP:(2010):Checking IPSec proposal 1
007623: Jun 23 14:05:29.577: ISAKMP: transform 1, ESP_3DES
007624: Jun 23 14:05:29.577: ISAKMP:   attributes in transform:
007625: Jun 23 14:05:29.577: ISAKMP:      encaps is 2 (Transport)
007626: Jun 23 14:05:29.577: ISAKMP:      SA life type in seconds
007627: Jun 23 14:05:29.577: ISAKMP:      SA life duration (basic) of 120
007628: Jun 23 14:05:29.577: ISAKMP:      SA life type in kilobytes
007629: Jun 23 14:05:29.577: ISAKMP:      SA life duration (VPI) of 0x0 0x46 0x50 0x0
007630: Jun 23 14:05:29.577: ISAKMP:      authenticator is HMAC-MD5
007631: Jun 23 14:05:29.577: ISAKMP:(2010):atts are acceptable.
007632: Jun 23 14:05:29.577: IPSEC(validate_proposal_request): proposal part #1
007633: Jun 23 14:05:29.577: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= esp-3des esp-md5-hmac (Transport),
    lifedur= 0s and 0kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007634: Jun 23 14:05:29.577: Crypto mapdb : proxy_match
src addr     : 10.10.0.1
dst addr     : 172.16.0.1
protocol     : 47
src port     : 0
dst port     : 0
007635: Jun 23 14:05:29.577: ISAKMP:(2010): processing NONCE payload. message ID = 2097686851
007636: Jun 23 14:05:29.577: ISAKMP:(2010): processing ID payload. message ID = 2097686851
007637: Jun 23 14:05:29.577: ISAKMP:(2010): processing ID payload. message ID = 2097686851
007638: Jun 23 14:05:29.589: ISAKMP:(2010): Creating IPSec SAs
007639: Jun 23 14:05:29.589:         inbound SA from 172.16.0.1 to 10.10.0.1 (f/i) 0/ 0
        (proxy 172.16.0.1 to 10.10.0.1)
007640: Jun 23 14:05:29.589:         has spi 0x70B65FA8 and conn_id 0
007641: Jun 23 14:05:29.589:         lifetime of 120 seconds
007642: Jun 23 14:05:29.589:         lifetime of 4608000 kilobytes
007643: Jun 23 14:05:29.589:         outbound SA from 10.10.0.1 to 172.16.0.1 (f/i) 0/0
        (proxy 10.10.0.1 to 172.16.0.1)
007644: Jun 23 14:05:29.589:         has spi 0x8CC6A487 and conn_id 0
007645: Jun 23 14:05:29.589:         lifetime of 120 seconds
007646: Jun 23 14:05:29.589:         lifetime of 4608000 kilobytes
007647: Jun 23 14:05:29.589: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007648: Jun 23 14:05:29.589: Crypto mapdb : proxy_match
src addr     : 10.10.0.1
dst addr     : 172.16.0.1
protocol     : 47
src port     : 0
dst port     : 0
007649: Jun 23 14:05:29.589: IPSEC(crypto_ipsec_sa_find_ident_head): reconnecting with the same proxies and peer 172.16.0.1
007650: Jun 23 14:05:29.589: IPSEC(create_sa): sa created,
(sa) sa_dest= 10.10.0.1, sa_proto= 50,
    sa_spi= 0x70B65FA8(1891000232),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1779
007651: Jun 23 14:05:29.593: IPSEC(create_sa): sa created,
(sa) sa_dest= 172.16.0.1, sa_proto= 50,
    sa_spi= 0x8CC6A487(2361828487),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1780
007652: Jun 23 14:05:29.593: IPSEC(update_current_outbound_sa): updated peer 172.16.0.1 current outbound sa to SPI 8CC6A487
007653: Jun 23 14:05:29.593: IPSEC(check_delete_duplicate_sa_bundle): found duplicated fresh SA bundle, aging it out. min_spi=1117B473
007654: Jun 23 14:05:29.593: IPSEC(early_age_out_sibling): sibling outbound SPI 1117B473 expiring in 30 seconds
007655: Jun 23 14:05:29.593: ISAKMP:(2010): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007656: Jun 23 14:05:29.593: ISAKMP:(2010):Sending an IKE IPv4 Packet.
007657: Jun 23 14:05:29.593: ISAKMP:(2010):deleting node 2097686851 error FALSE reason "No Error"
007658: Jun 23 14:05:29.593: ISAKMP:(2010):Node 2097686851, Input = IKE_MESG_FROM_PEER, IKE_QM_EXCH
007659: Jun 23 14:05:29.593: ISAKMP:(2010):Old State = IKE_QM_I_QM1 New State = IKE_QM_PHASE2_COMPLETE
007660: Jun 23 14:05:38.593: ISAKMP:(0):purging SA., sa=654204AC, delme=654204AC
007661: Jun 23 14:05:59.589: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 10.10.0.1, sa_proto= 50,
    sa_spi= 0x28403477(675296375),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1777,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007662: Jun 23 14:05:59.589: IPSEC(delete_sa): deleting SA,
(sa) sa_dest= 172.16.0.1, sa_proto= 50,
    sa_spi= 0x1117B473(286766195),
    sa_trans= esp-3des esp-md5-hmac , sa_conn_id= 1778,
(identity) local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1)
007663: Jun 23 14:05:59.589: ISAKMP: set new node -1720612644 to QM_IDLE
007664: Jun 23 14:05:59.593: ISAKMP:(2010): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007665: Jun 23 14:05:59.593: ISAKMP:(2010):Sending an IKE IPv4 Packet.
007666: Jun 23 14:05:59.593: ISAKMP:(2010):purging node -1720612644
007667: Jun 23 14:05:59.593: ISAKMP:(2010):Input = IKE_MESG_FROM_IPSEC, IKE_PHASE2_DEL
007668: Jun 23 14:05:59.593: ISAKMP:(2010):Old State = IKE_P1_COMPLETE New State = IKE_P1_COMPLETE

007669: Jun 23 14:06:19.561: ISAKMP:(2010):purging node 1663596817
007670: Jun 23 14:06:19.581: ISAKMP:(2010):purging node 2097686851
007671: Jun 23 14:06:58.486: IPSEC(sa_request): ,
(key eng. msg.) OUTBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= NONE (Transport),
    lifedur= 120s and 4608000kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007672: Jun 23 14:06:58.486: IPSEC(lifetime_expiry): SA lifetime threshold reached, expiring in 31 seconds
007673: Jun 23 14:06:58.486: ISAKMP: set new node 0 to QM_IDLE
007674: Jun 23 14:06:58.486: SA has outstanding requests (local 101.130.198.128 port 500, remote 101.130.198.100 port 500)
007675: Jun 23 14:06:58.486: ISAKMP:(2010): sitting IDLE. Starting QM immediately (QM_IDLE      )
007676: Jun 23 14:06:58.486: ISAKMP:(2010):beginning Quick Mode exchange, M-ID of 495597016
007677: Jun 23 14:06:58.486: ISAKMP:(2010):QM Initiator gets spi
007678: Jun 23 14:06:58.490: ISAKMP:(2010): sending packet to 172.16.0.1 my_port 500 peer_port 500 (I) QM_IDLE
007679: Jun 23 14:06:58.490: ISAKMP:(2010):Sending an IKE IPv4 Packet.
007680: Jun 23 14:06:58.490: ISAKMP:(2010):Node 495597016, Input = IKE_MESG_INTERNAL, IKE_INIT_QM
007681: Jun 23 14:06:58.490: ISAKMP:(2010):Old State = IKE_QM_READY New State = IKE_QM_I_QM1
007682: Jun 23 14:06:58.586: ISAKMP (0:2010): received packet from 172.16.0.1 dport 500 sport 500 Global (I) QM_IDLE
007683: Jun 23 14:06:58.586: ISAKMP:(2010): processing HASH payload. message ID = 495597016
007684: Jun 23 14:06:58.590: ISAKMP:(2010): processing SA payload. message ID = 495597016
007685: Jun 23 14:06:58.590: ISAKMP:(2010):Checking IPSec proposal 1
007686: Jun 23 14:06:58.590: ISAKMP: transform 1, ESP_3DES
007687: Jun 23 14:06:58.590: ISAKMP:   attributes in transform:
007688: Jun 23 14:06:58.590: ISAKMP:      encaps is 2 (Transport)
007689: Jun 23 14:06:58.590: ISAKMP:      SA life type in seconds
007690: Jun 23 14:06:58.590: ISAKMP:      SA life duration (basic) of 120
007691: Jun 23 14:06:58.590: ISAKMP:      SA life type in kilobytes
007692: Jun 23 14:06:58.590: ISAKMP:      SA life duration (VPI) of 0x0 0x46 0x50 0x0
007693: Jun 23 14:06:58.590: ISAKMP:      authenticator is HMAC-MD5
007694: Jun 23 14:06:58.590: ISAKMP:(2010):atts are acceptable.
007695: Jun 23 14:06:58.590: IPSEC(validate_proposal_request): proposal part #1
007696: Jun 23 14:06:58.590: IPSEC(validate_proposal_request): proposal part #1,
(key eng. msg.) INBOUND local= 10.10.0.1, remote= 172.16.0.1,
    local_proxy= 10.10.0.1/255.255.255.255/47/0 (type=1),
    remote_proxy= 172.16.0.1/255.255.255.255/47/0 (type=1),
    protocol= ESP, transform= esp-3des esp-md5-hmac (Transport),
    lifedur= 0s and 0kb,
    spi= 0x0(0), conn_id= 0, keysize= 0, flags= 0x0
007697: Jun 23 14:06:58.590: Crypto mapdb : proxy_match
src addr     : 10.10.0.1
dst addr     : 172.16.0.1
protocol     : 47
src port     : 0
dst port     : 0
007698: Jun 23 14:06:58.590: ISAKMP:(2010): processing NONCE payload. message ID = 495597016
007699: Jun 23 14:06:58.590: ISAKMP:(2010): processing ID payload. message ID = 495597016
007700: Jun 23 14:06:58.590: ISAKMP:(2010): processing ID payload. message ID = 495597016
007701: Jun 23 14:06:58.598: ISAKMP:(2010): Creating IPSec SAs
007702: Jun 23 14:06:58.598:         inbound SA from 172.16.0.1 to 10.10.0.1 (f/i) 0/ 0
        (proxy 172.16.0.1 to 10.10.0.1)
007703: Jun 23 14:06:58.598:         has spi 0xBFB6AF8 and conn_id 0
007704: Jun 23 14:06:58.598:         lifetime of 120 seconds
007705: Jun 23 14:06:58.598:         lifetime of 4608000 kilobytes
007706: Jun 23 14:06:58.598:         outbound SA from 10.10.0.1 to 172.16.0.1 (f/i) 0/0
        (proxy 10.10.0.1 to 172.16.0.1)
007707: Jun 23 14:06:58.598:         has spi 0xDFEB5FEA and conn_id 0
007708: Jun 23 14:06:58.602:         lifetime of 120 seconds
007709: Jun 23 14:06:58.602:         lifetime of 4608000 kilobytes
007710: Jun 23 14:06:58.602: IPSEC(key_engine): got a queue event with 1 KMI message(s)
007711: Jun 23 14:06:58.602: Crypto mapdb : proxy_match

Richard Burts · ‎06-23-2013

Thanks for the additional information and the debug outputs. I have looked through the outputs and here is what I notice:

- it does seem to be a problem with crypto rekey. The old Security Association is about to expire and the routers attempt to negotiate a new key.

- the lifetime is set to 120 seconds. That is a pretty aggressive setting and I wonder if there is a reason for it? I can not say that this setting is aggravating the problem. But I do wonder what would happen if you were to set a lifetime that was longer.

- there was an SA expiration at 13:58:11.257 and this one had no difficulty.

- there was another expiration at 13:59:37.507 and this one had problems. There were multiple attempts to send and multiple retransmissions, but no indication of responses.

- at 14:00:11.373 the existing SA was deleted and there was no SA to take its place. At this point the GRE/IPSec tunnel is completely non functional.

- the attempts to send and to retransmit continue till 14:05:29.229 but there is no sign of a response.

- then at 14:05:29.229: these is a transmission from the peer and negotiation begins which results in creating a new set of SA and connectivity is restored.

It is quite odd that about 6 minutes went by when there were no responses to the attempt to negotiate a new SA. It suggests that either there was a problem with the ISP or that there might be a problem with the other end. Can you verify whether there is or there is not IP connectivity to the peer IP address?

I believe that these debugs were from the remote router. Would it be possible to run these debugs on the hub router and see what they report during one of these outages?

It might be time to start thinking whether a TAC case is a possibility since this is starting to get into the nitty gritty of what happens during crypto rekey and they are better equipped to analyze that than most of us are.

HTH

Rick

HTH

Rick

wilsonbolanos · ‎06-24-2013

The hub router was up and operational since I was VPNed to it from home. The other spoke sites that connect to the hub were also up with no problems. Wug would have notified me of outages at other sites, but the only site that goes down is this one. I am suspecting the ISP as well.

wilsonbolanos · ‎06-26-2013

Thanks Rick for your help. The ISP had assigned our static IP to someone else as well. Is 120 seconds the default? What is best practice? I think we have it set to default of lifetime of 120 seconds. How would we change it to a higher number of seconds?

wilsonbolanos · ‎06-26-2013

Do you have to change it on the hub and the spoke or will it be ok to just change it on the spoke?

Richard Burts · ‎06-30-2013

120 seconds is not the default for the VPN tunnels that I have set up on ISR routers. I frequently set the lifetime to one hour and that is less than the default. You should change it on both the spoke and the hub.

HTH

Rick

HTH

Rick

Interface Fa0/0 on Cisco 1841 fails after 4 to 5 hours, no pings allowed to that external interface fa0/0, deb ip packet detail output crypto map check failed., proto=47