[Openswan Users]

Mon Mar 13 10:23:36 CET 2006

On Fri, Mar 10, 2006 at 07:04:55PM +0100, Paul Wouters wrote:
> Thanks for all the information.
> 
> I've assigned the bug to me to create a testcase that fails, and then
> appl the patch to see it is the proper patch. It should make it into 2.4.5

Thank you.

Having left this connection running over the weekend, I found it wasn't
working when I came back today. I can see another problem in logs, this time
it looks like when the SA negotiation starts from the PIX side:

Jan  3 14:01:59 (none) kern.debug pluto[2085]: | processing connection pix
Jan  3 14:01:59 (none) kern.warn pluto[2085]: "pix" #174: responding to Aggressive Mode, state #174, connection "pix" from p.p.p.p
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | processing connection pix
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: hasher=0x10004510(16)
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: icookie=
Jan  3 14:01:59 (none) kern.debug pluto[2085]: |   26 db 01 53  00 cb 26 56
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: rcookie=
Jan  3 14:01:59 (none) kern.debug pluto[2085]: |   ec 9d aa 05  8d 94 66 35
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: ip=  pp pp pp pp
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: port=4500
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: hash=  dd cb fb 68  9f 22 49 92  c5 c4 20 c6  8b 2e 3f b9
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: hasher=0x10004510(16)
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: icookie=
Jan  3 14:01:59 (none) kern.debug pluto[2085]: |   26 db 01 53  00 cb 26 56
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: rcookie=
Jan  3 14:01:59 (none) kern.debug pluto[2085]: |   ec 9d aa 05  8d 94 66 35
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: ip=  ac 97 71 34
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: port=4500
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | _natd_hash: hash=  d3 25 25 e7  82 96 14 35  a6 7d 69 3c  f5 44 40 34
Jan  3 14:01:59 (none) kern.warn pluto[2085]: "pix" #174: transition from state STATE_AGGR_R0 to state STATE_AGGR_R1
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | NAT-T: updating local port to 4500
Jan  3 14:01:59 (none) kern.debug pluto[2085]: | NAT-T connection has wrong interface definition <invalid>:4500 vs 172.151.113.52:4500
Jan  3 14:01:59 (none) kern.warn pluto[2085]: "pix" #174: STATE_AGGR_R1: sent AR1, expecting AI2
Jan  3 14:02:00 (none) kern.debug pluto[2085]: | processing connection pix
Jan  3 14:02:00 (none) kern.debug pluto[2085]: | processing connection pix
Jan  3 14:02:00 (none) kern.warn pluto[2085]: "pix" #174: Informational Exchange message must be encrypted
Jan  3 14:02:07 (none) kern.warn pluto[2085]: packet from p.p.p.p:4500: received Vendor ID payload [Cisco-Unity]
Jan  3 14:02:07 (none) kern.warn pluto[2085]: packet from p.p.p.p:4500: received Vendor ID payload [XAUTH]
Jan  3 14:02:07 (none) kern.warn pluto[2085]: packet from p.p.p.p:4500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] method set to=106
Jan  3 14:02:07 (none) kern.warn pluto[2085]: packet from p.p.p.p:4500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-03] method set to=108
Jan  3 14:02:07 (none) kern.warn pluto[2085]: packet from p.p.p.p:4500: ignoring unknown Vendor ID payload [4048b7d56ebce88525e7de7f00d6c2d3c0000000]
Jan  3 14:02:07 (none) kern.warn pluto[2085]: "pix" #175: protocol/port in Phase 1 ID Payload must be 0/0 or 17/500 but are 17/0
Jan  3 14:02:07 (none) kern.warn pluto[2085]: "pix" #175: Aggressive mode peer ID is ID_IPV4_ADDR: 'p.p.p.p'
Jan  3 14:02:07 (none) kern.debug pluto[2085]: | processing connection pix
Jan  3 14:02:07 (none) kern.warn pluto[2085]: "pix" #175: responding to Aggressive Mode, state #175, connection "pix" from p.p.p.p
Jan  3 14:02:07 (none) kern.debug pluto[2085]: | processing connection pix
Jan  3 14:02:07 (none) kern.debug pluto[2085]: | _natd_hash: hasher=0x10004510(16)
Jan  3 14:02:07 (none) kern.debug pluto[2085]: | _natd_hash: icookie=
Jan  3 14:02:07 (none) kern.debug pluto[2085]: |   26 db 01 53  00 cb 26 56
Jan  3 14:02:07 (none) kern.debug pluto[2085]: | _natd_hash: rcookie=
Jan  3 14:02:07 (none) kern.debug pluto[2085]: |   1e ed 73 bb  49 58 0d ed
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: ip=  pp pp pp pp
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: port=4500
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: hash=  4d 70 f3 f0  b6 f6 8a 1c  7c 05 11 13  b9 04 e4 d0
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: hasher=0x10004510(16)
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: icookie=
Jan  3 14:02:08 (none) kern.debug pluto[2085]: |   26 db 01 53  00 cb 26 56
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: rcookie=
Jan  3 14:02:08 (none) kern.debug pluto[2085]: |   1e ed 73 bb  49 58 0d ed
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: ip=  ac 97 71 34
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: port=4500
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | _natd_hash: hash=  ea b7 76 ef  26 fa 2e 25  18 d0 ea 91  20 c2 7c 69
Jan  3 14:02:08 (none) kern.warn pluto[2085]: "pix" #175: transition from state STATE_AGGR_R0 to state STATE_AGGR_R1
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | NAT-T: updating local port to 4500
Jan  3 14:02:08 (none) kern.debug pluto[2085]: | NAT-T connection has wrong interface definition <invalid>:4500 vs 172.151.113.52:4500
Jan  3 14:02:08 (none) kern.warn pluto[2085]: "pix" #175: STATE_AGGR_R1: sent AR1, expecting AI2

Unfortunately no record seems to be kept of the informational message which
was rejected because it was unencrypted.

If I tear down and rebuild the connection down with

   ipsec auto --down pix
   ipsec auto --up pix

then it works again. However this isn't going to give a stable solution I
can rely on :-(

I don't know exactly why the PIX decided to initiate aggressive mode - it
could just be because the SA timed out. There should have been no live
traffic going through this tunnel. The openswan box is running under OpenWRT
and syslogging to a small ramdisk file, so I don't have a lot of history
there.

However I do have logs from the PIX side:

Mar 13 06:34:42 pixfw2 %PIX-7-710005: UDP request discarded from x.x.x.x/39088 to outside:p.p.p.p/4500
Mar 13 06:34:44 pixfw2 %PIX-3-713902: IP = x.x.x.x, Invalid packet detected!
Mar 13 06:34:45 pixfw2 %PIX-3-713902: IP = x.x.x.x, Invalid packet detected!
Mar 13 06:34:46 pixfw2 %PIX-3-713902: IP = x.x.x.x, Invalid packet detected!
Mar 13 06:34:54 pixfw2 %PIX-7-715036: Group = gprstesting1, IP = x.x.x.x, Sending keep-alive of type DPD R-U-THERE (seq number 0x3585673e)
Mar 13 06:34:54 pixfw2 %PIX-7-713906: Group = gprstesting1, IP = x.x.x.x, constructing blank hash
Mar 13 06:34:54 pixfw2 %PIX-7-713906: Group = gprstesting1, IP = x.x.x.x, constructing qm hash
Mar 13 06:34:54 pixfw2 %PIX-7-713906: IP = x.x.x.x, IKE DECODE SENDING Message (msgid=1878b863) with payloads : HDR + HASH (8) + NOTIFY (11) + NONE (0) total length : 80
Mar 13 06:34:54 pixfw2 %PIX-7-720041: (VPN-Primary) Sending Phase 1 SA Expired message (type L2L, remote addr x.x.x.x, my cookie CEBBE712, his cookie 09D90D04) to standby unit
Mar 13 06:34:54 pixfw2 %PIX-7-713906: Group = gprstesting1, IP = x.x.x.x, IKE SA AM:cebbe712 terminating:  flags 0x01000001, refcnt 0, tuncnt 0
Mar 13 06:34:54 pixfw2 %PIX-7-713906: sending delete/delete with reason message
Mar 13 06:34:54 pixfw2 %PIX-7-713906: Group = gprstesting1, IP = x.x.x.x, constructing blank hash
Mar 13 06:34:54 pixfw2 %PIX-7-713906: constructing IKE delete payload
Mar 13 06:34:54 pixfw2 %PIX-7-713906: Group = gprstesting1, IP = x.x.x.x, constructing qm hash
Mar 13 06:34:54 pixfw2 %PIX-7-713906: IP = x.x.x.x, IKE DECODE SENDING Message (msgid=854d88ee) with payloads : HDR + HASH (8) + DELETE (12) + NONE (0) total length : 76
Mar 13 06:34:54 pixfw2 %PIX-3-713902: Group = gprstesting1, IP = x.x.x.x, Removing peer from peer table failed, no match!
Mar 13 06:34:54 pixfw2 %PIX-4-713903: Group = gprstesting1, IP = x.x.x.x, Error: Unable to remove PeerTblEntry
Mar 13 06:34:54 pixfw2 %PIX-4-113019: Group = gprstesting1, Username = gprstesting1, IP = x.x.x.x, Session disconnected. Session Type: IPSecLAN2LAN, Duration: 0h:45m:38s, Bytes xmt: 0, Bytes rcv: 0, Reason: Unknown
Mar 13 06:34:55 pixfw2 %PIX-3-713902: IP = x.x.x.x, Invalid packet detected!
Mar 13 06:34:56 pixfw2 %PIX-5-713904: IP = x.x.x.x, Received encrypted packet with no matching SA, dropping
Mar 13 06:34:57 pixfw2 %PIX-5-713904: IP = x.x.x.x, Received encrypted packet with no matching SA, dropping
Mar 13 06:35:05 pixfw2 %PIX-3-713902: IP = x.x.x.x, Invalid packet detected!
Mar 13 06:35:06 pixfw2 %PIX-3-713902: IP = x.x.x.x, Invalid packet detected!
Mar 13 06:36:58 pixfw2 %PIX-6-302016: Teardown UDP connection 11949846 for outside:x.x.x.x/39088 to NP Identity Ifc:p.p.p.p/4500 duration 0:49:16 bytes 14180
Mar 13 06:36:58 pixfw2 %PIX-6-609002: Teardown local-host outside:x.x.x.x duration 0:49:16

I also notice that the GPRS dynamic IP address (x.x.x.x) has changed from
what it was on Friday afternoon. This implies that somewhere along the line
the GPRS session or the firewall at the GPRS provider kicked the session off
and on again. The first time I see this new IP address in the logs is about
5am this morning:

Mar 13 05:12:42 pixfw2 %PIX-6-609001: Built local-host outside:x.x.x.x
Mar 13 05:12:42 pixfw2 %PIX-6-302015: Built inbound UDP connection 11948335 for outside:x.x.x.x/39088 (x.x.x.x/39088) to NP Identity Ifc:p.p.p.p/4500 (p.p.p.p/4500)
Mar 13 05:12:42 pixfw2 %PIX-7-710005: UDP request discarded from x.x.x.x/39088 to outside:p.p.p.p/4500

So I also wonder whether openswan is able to detect this case automatically
- for example, can dead peer detection determine that the session has failed
due to a change of NAT outside IP address, and if so, with "auto=start"
will it attempt to reconnect or will the tunnel just be cleared?

Regards,

Brian.