[Openswan Users]
Brian Candler
B.Candler at pobox.com
Fri Apr 7 12:08:34 CEST 2006
OK, I think I have some good information on this which I hope can help nail
this problem down.
Firstly, regarding versions:
- if I rollback userland to 2.4.4, but leave the kernel module as 2.4.5rc7,
then it still fails (i.e. Cisco gives decryption errors)
- if I then rollback the kernel module to 2.4.4, it works
- if I roll forward userland to 2.4.5, it works
- if I roll forward kernel module to 2.4.5, it fails again
Therefore, it looks like there's definitely something wrong in the kernel
module for 2.4.5 for transport mode + NAT-T.
Secondly, I can replicate a similar [hopefully the same] problem using
openswan to openswan. Here's my test setup, both running 2.4.5:
openswan B
| 172.17.0.193
|
| 172.17.0.145
firewall ^
(FreeBSD) | NAT
| 10.71.32.14
|
| 10.71.32.1
openswan A
Here's the config on openswan A:
[/etc/ipsec.conf]
version 2.0
config setup
nat_traversal=yes
plutodebug="natt control"
conn TEST
authby=secret
ike=3des-sha
esp=3des-sha1
pfs=no
left=%defaultroute
leftprotoport=17/1701
right=172.17.0.193
rightprotoport=17/1701
type=transport
auto=add
#Disable Opportunistic Encryption
include /etc/ipsec.d/examples/no_oe.conf
[/etc/ipsec.secrets]
10.71.32.1 172.17.0.193 : PSK "abc123"
And here's the config on openswan B:
[/etc/ipsec.conf]
version 2.0
config setup
nat_traversal=yes
plutodebug="natt control"
conn TEST
authby=secret
ike=3des-sha
esp=3des-sha1
pfs=no
left=%any
leftprotoport=17/1701
right=172.17.0.193
rightprotoport=17/1701
type=transport
auto=add
#Disable Opportunistic Encryption
include /etc/ipsec.d/examples/no_oe.conf
[/etc/ipsec.secrets]
172.17.0.193 %any : PSK "abc123"
Now when I bring up the session from A:
root at OpenWrt:~# ipsec auto --verbose --up TEST
002 "TEST" #1: initiating Main Mode
104 "TEST" #1: STATE_MAIN_I1: initiate
003 "TEST" #1: received Vendor ID payload [Openswan (this version) 2.4.5 X.509-1.5.4 PLUTO_SENDS_VENDORID PLUTO_USES_KEYRR]
003 "TEST" #1: received Vendor ID payload [Dead Peer Detection]
003 "TEST" #1: received Vendor ID payload [RFC 3947] method set to=110
002 "TEST" #1: enabling possible NAT-traversal with method 3
002 "TEST" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
106 "TEST" #1: STATE_MAIN_I2: sent MI2, expecting MR2
002 "TEST" #1: I did not send a certificate because I do not have one.
003 "TEST" #1: NAT-Traversal: Result using 3: i am NATed
002 "TEST" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
108 "TEST" #1: STATE_MAIN_I3: sent MI3, expecting MR3
002 "TEST" #1: Main mode peer ID is ID_IPV4_ADDR: '172.17.0.193'
002 "TEST" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
004 "TEST" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1536}
002 "TEST" #2: initiating Quick Mode PSK+ENCRYPT+UP {using isakmp#1}
117 "TEST" #2: STATE_QUICK_I1: initiate
010 "TEST" #2: STATE_QUICK_I1: retransmission; will wait 20s for response
010 "TEST" #2: STATE_QUICK_I1: retransmission; will wait 40s for response
^C
So, phase 1 works but phase 2 doesn't. tcpdump shows an encrypted "phase
2/others R inf[E]" sent in response.
Logs on openswan B show:
Jan 1 00:23:32 (none) kern.warn pluto[2220]: "TEST"[2] 172.17.0.145 #1: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1536}
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | modecfg pull: noquirk policy:push not-client
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | phase 1 is done, looking for phase 1 to unpend
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | next event EVENT_NAT_T_KEEPALIVE in 19 seconds
Jan 1 00:23:32 (none) kern.debug pluto[2220]: |
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | *received 156 bytes from 172.17.0.145:52382 on br0 (port=4500)
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | processing packet with exchange type=ISAKMP_XCHG_QUICK (32)
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | ICOOKIE: bc e9 0a e0 a9 53 2e 0c
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | RCOOKIE: b9 03 68 14 ec be c6 bc
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | peer: ac 11 00 91
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | state hash entry 31
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | peer and cookies match on #1, provided msgid bb2e2a87 vs 00000000
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | state object not found
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | ICOOKIE: bc e9 0a e0 a9 53 2e 0c
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | RCOOKIE: b9 03 68 14 ec be c6 bc
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | peer: ac 11 00 91
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | state hash entry 31
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | state object #1 found, in STATE_MAIN_R3
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | processing connection TEST[2] 172.17.0.145
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | peer client is 10.71.32.1
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | peer client protocol/port is 17/1701
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | our client is 172.17.0.193
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | our client protocol/port is 17/1701
Jan 1 00:23:32 (none) kern.warn pluto[2220]: "TEST"[2] 172.17.0.145 #1: cannot respond to IPsec SA request because no connection is known for 172.17.0.193:17/1701...172.17.0.145[10.71.32.1]:17/1701===10.71.32.1/32
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | complete state transition with (null)
Jan 1 00:23:32 (none) kern.warn pluto[2220]: "TEST"[2] 172.17.0.145 #1: sending encrypted notification INVALID_ID_INFORMATION to 172.17.0.145:52382
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | sending 68 bytes for notification packet through br0:4500 to 172.17.0.145:52382:
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | state transition function for STATE_QUICK_R0 failed: INVALID_ID_INFORMATION
Jan 1 00:23:32 (none) kern.debug pluto[2220]: | next event EVENT_NAT_T_KEEPALIVE in 19 seconds
So it looks like there's some problem to do with mismatch between the
original address (10.71.32.1) versus the NATted address (172.17.0.145)
Attached below are some more logs from openswan A and openswan B, showing
the phase 1 NAT-T negotation. AFAICS this looks OK, although the problem
with natt_type_bitnames I mentioned before seems to be visible here too, in
the messages
"enabling possible NAT-traversal with method 3"
"Result using 3"
where instead of "3" this should say "RFC 3947 (NAT-Traversal)"
If you have some specific suggestions where I should look next, that would
be appreciated. Otherwise I can only poke around randomly in code that's
unfamiliar, for a protocol whose depths I have yet to fully plumb.
Could you reproduce the problem as described above, either in hardware or
within a software test harness?
Thanks,
Brian.
At openswan A:
...
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | best_match 0>6 best=0x1001ecd0 (line=2)
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 1: compared PSK 82.109.191.23 to 10.71.32.1 / 172.17.0.193 -> 0
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 2: compared PSK 10.71.32.1 to 10.71.32.1 / 172.17.0.193 -> 4
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | concluding with best_match=6 best=0x1001ecd0 (lineno=2)
Apr 7 10:47:59 (none) kern.warn pluto[3016]: "TEST" #1: enabling possible NAT-traversal with method 3
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | asking helper 0 to do build_kenonce op on seq: 1
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | complete state transition with STF_SUSPEND
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | next event EVENT_SHUNT_SCAN in 111 seconds
Apr 7 10:47:59 (none) kern.debug pluto[3024]: ! helper -1 doing build_kenonce op id: 1
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | processing connection TEST
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: hasher=0x10004530(20)
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: icookie=
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: rcookie=
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: ip= ac 11 00 c1
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: port=500
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: hash= eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 24 76 b8 de
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: hasher=0x10004530(20)
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: icookie=
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: rcookie=
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: ip= 0a 47 20 01
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: port=500
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | _natd_hash: hash= 5b 4a 1e de f3 29 39 6b 27 ce ea af ae 9d fb da
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | 5c a7 4f d3
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | ICOOKIE: 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | RCOOKIE: 00 00 00 00 00 00 00 00
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | peer: ac 11 00 c1
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | state hash entry 14
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | ICOOKIE: 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | RCOOKIE: 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | peer: ac 11 00 c1
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | state hash entry 10
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | complete state transition with STF_OK
Apr 7 10:47:59 (none) kern.warn pluto[3016]: "TEST" #1: transition from state STATE_MAIN_I1 to state STATE_MAIN_I2
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | sending reply packet to 172.17.0.193:500 (from port=500)
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | sending 292 bytes for STATE_MAIN_I1 through br0:500 to 172.17.0.193:500:
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
Apr 7 10:47:59 (none) kern.warn pluto[3016]: "TEST" #1: STATE_MAIN_I2: sent MI2, expecting MR2
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | modecfg pull: noquirk policy:push not-client
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | phase 1 is done, looking for phase 1 to unpend
Apr 7 10:47:59 (none) kern.debug pluto[3016]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Apr 7 10:48:00 (none) kern.debug pluto[3016]: |
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | *received 292 bytes from 172.17.0.193:500 on br0 (port=500)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | ICOOKIE: 57 bd 04 61 e2 cf 56 16
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | RCOOKIE: 8c 63 1a cf 03 65 a4 8a
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | peer: ac 11 00 c1
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | state hash entry 10
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | state object #1 found, in STATE_MAIN_I2
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | processing connection TEST
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | thinking about whether to send my certificate:
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | I have RSA key: OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | sendcert: CERT_ALWAYSSEND and I did not get a certificate request
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | so do not send cert.
Apr 7 10:48:00 (none) kern.warn pluto[3016]: "TEST" #1: I did not send a certificate because I do not have one.
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | I am not sending a certificate request
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | started looking for secret for 10.71.32.1->172.17.0.193 of kind PPK_PSK
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | actually looking for secret for 10.71.32.1->172.17.0.193 of kind PPK_PSK
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 1: compared PSK 172.17.0.193 to 10.71.32.1 / 172.17.0.193 -> 2
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 2: compared PSK 10.71.32.1 to 10.71.32.1 / 172.17.0.193 -> 6
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | best_match 0>6 best=0x1001ecd0 (line=2)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 1: compared PSK 82.109.191.23 to 10.71.32.1 / 172.17.0.193 -> 0
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 2: compared PSK 10.71.32.1 to 10.71.32.1 / 172.17.0.193 -> 4
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | concluding with best_match=6 best=0x1001ecd0 (lineno=2)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: hasher=0x10004530(20)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: icookie=
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 57 bd 04 61 e2 cf 56 16
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: rcookie=
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 8c 63 1a cf 03 65 a4 8a
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: ip= 0a 47 20 01
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: port=500
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: hash= 5b 4a 1e de f3 29 39 6b 27 ce ea af ae 9d fb da
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 5c a7 4f d3
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: hasher=0x10004530(20)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: icookie=
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 57 bd 04 61 e2 cf 56 16
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: rcookie=
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 8c 63 1a cf 03 65 a4 8a
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: ip= ac 11 00 c1
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: port=500
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | _natd_hash: hash= eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 24 76 b8 de
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | NAT_TRAVERSAL hash=0 (me:0) (him:0)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | expected NAT-D(me): 5b 4a 1e de f3 29 39 6b 27 ce ea af ae 9d fb da
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 5c a7 4f d3
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | expected NAT-D(him):
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 24 76 b8 de
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | received NAT-D: 78 ee 26 7a 32 3c 19 ba 67 ea 50 e2 49 ff cb 98
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 9a 0e 38 42
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | NAT_TRAVERSAL hash=1 (me:0) (him:0)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | expected NAT-D(me): 5b 4a 1e de f3 29 39 6b 27 ce ea af ae 9d fb da
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 5c a7 4f d3
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | expected NAT-D(him):
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 24 76 b8 de
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | received NAT-D: eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | 24 76 b8 de
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | NAT_TRAVERSAL hash=2 (me:0) (him:1)
Apr 7 10:48:00 (none) kern.warn pluto[3016]: "TEST" #1: NAT-Traversal: Result using 3: i am NATed
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | inserting event EVENT_NAT_T_KEEPALIVE, timeout in 20 seconds
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | complete state transition with STF_OK
Apr 7 10:48:00 (none) kern.warn pluto[3016]: "TEST" #1: transition from state STATE_MAIN_I2 to state STATE_MAIN_I3
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | sending reply packet to 172.17.0.193:500 (from port=500)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | NAT-T: floating to port 4500
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | NAT-T connection has wrong interface definition 10.71.32.1:4500 vs 10.71.32.1:500
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | NAT-T: using interface br0:4500
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | sending 68 bytes for STATE_MAIN_I2 through br0:4500 to 172.17.0.193:4500:
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
Apr 7 10:48:00 (none) kern.warn pluto[3016]: "TEST" #1: STATE_MAIN_I3: sent MI3, expecting MR3
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | modecfg pull: noquirk policy:push not-client
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | phase 1 is done, looking for phase 1 to unpend
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Apr 7 10:48:00 (none) kern.debug pluto[3016]: |
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | *received 68 bytes from 172.17.0.193:4500 on br0 (port=4500)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | ICOOKIE: 57 bd 04 61 e2 cf 56 16
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | RCOOKIE: 8c 63 1a cf 03 65 a4 8a
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | peer: ac 11 00 c1
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | state hash entry 10
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | state object #1 found, in STATE_MAIN_I3
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | processing connection TEST
Apr 7 10:48:00 (none) kern.warn pluto[3016]: "TEST" #1: Main mode peer ID is ID_IPV4_ADDR: '172.17.0.193'
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | complete state transition with STF_OK
Apr 7 10:48:00 (none) kern.warn pluto[3016]: "TEST" #1: transition from state STATE_MAIN_I3 to state STATE_MAIN_I4
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | inserting event EVENT_SA_REPLACE, timeout in 2912 seconds for #1
Apr 7 10:48:00 (none) kern.warn pluto[3016]: "TEST" #1: STATE_MAIN_I4: ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1536}
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | modecfg pull: noquirk policy:push not-client
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | phase 1 is done, looking for phase 1 to unpend
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | unqueuing pending Quick Mode with 172.17.0.193 "TEST"
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | duplicating state object #1
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | creating state object #2 at 0x1001fc20
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | processing connection TEST
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | ICOOKIE: 57 bd 04 61 e2 cf 56 16
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | RCOOKIE: 8c 63 1a cf 03 65 a4 8a
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | peer: ac 11 00 c1
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | state hash entry 10
Apr 7 10:48:00 (none) kern.debug pluto[3016]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #2
Apr 7 10:48:00 (none) kern.warn pluto[3016]: "TEST" #2: initiating Quick Mode PSK+ENCRYPT+UP {using isakmp#1}
At openswan B:
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | *received 292 bytes from 172.17.0.145:51274 on br0 (port=500)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | ICOOKIE: 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | RCOOKIE: 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | peer: ac 11 00 91
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | state hash entry 26
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | state object #1 found, in STATE_MAIN_R1
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | processing connection TEST[1] 172.17.0.145
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: hasher=0x10004530(20)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: icookie=
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: rcookie=
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: ip= ac 11 00 c1
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: port=500
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: hash= eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 24 76 b8 de
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: hasher=0x10004530(20)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: icookie=
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: rcookie=
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: ip= ac 11 00 91
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: port=51274
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: hash= 78 ee 26 7a 32 3c 19 ba 67 ea 50 e2 49 ff cb 98
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 9a 0e 38 42
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | NAT_TRAVERSAL hash=0 (me:0) (him:0)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | expected NAT-D(me): eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 24 76 b8 de
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | expected NAT-D(him):
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 78 ee 26 7a 32 3c 19 ba 67 ea 50 e2 49 ff cb 98
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 9a 0e 38 42
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | received NAT-D: eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 24 76 b8 de
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | NAT_TRAVERSAL hash=1 (me:1) (him:0)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | expected NAT-D(me): eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 24 76 b8 de
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | expected NAT-D(him):
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 78 ee 26 7a 32 3c 19 ba 67 ea 50 e2 49 ff cb 98
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 9a 0e 38 42
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | received NAT-D: 5b 4a 1e de f3 29 39 6b 27 ce ea af ae 9d fb da
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 5c a7 4f d3
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | NAT_TRAVERSAL hash=2 (me:1) (him:0)
Apr 7 10:47:59 (none) kern.warn pluto[2690]: "TEST"[1] 172.17.0.145 #1: NAT-Traversal: Result using 3: peer is NATed
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | inserting event EVENT_NAT_T_KEEPALIVE, timeout in 20 seconds
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 0: w->pcw_dead: 0 w->pcw_work: 0 cnt: 1
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | asking helper 0 to do build_kenonce op on seq: 1
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | inserting event EVENT_CRYPTO_FAILED, timeout in 300 seconds for #1
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | complete state transition with STF_SUSPEND
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | next event EVENT_NAT_T_KEEPALIVE in 20 seconds
Apr 7 10:47:59 (none) kern.debug pluto[2699]: ! helper -1 doing build_kenonce op id: 1
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | processing connection TEST[1] 172.17.0.145
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: hasher=0x10004530(20)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: icookie=
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: rcookie=
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: ip= ac 11 00 91
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: port=51274
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: hash= 78 ee 26 7a 32 3c 19 ba 67 ea 50 e2 49 ff cb 98
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 9a 0e 38 42
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: hasher=0x10004530(20)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: icookie=
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: rcookie=
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: ip= ac 11 00 c1
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: port=500
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | _natd_hash: hash= eb 9e 95 51 b4 1c a0 42 df dc 6d 2f 19 1e 1a 3b
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 24 76 b8 de
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | started looking for secret for 172.17.0.193->172.17.0.145 of kind PPK_PSK
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | instantiating him to 0.0.0.0
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | actually looking for secret for 172.17.0.193->0.0.0.0 of kind PPK_PSK
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 1: compared PSK 0.0.0.0 to 172.17.0.193 / 172.17.0.145 -> 2
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | 2: compared PSK 172.17.0.193 to 172.17.0.193 / 172.17.0.145 -> 6
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | best_match 0>6 best=0x1001ec38 (line=1)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | concluding with best_match=6 best=0x1001ec38 (lineno=1)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | complete state transition with STF_OK
Apr 7 10:47:59 (none) kern.warn pluto[2690]: "TEST"[1] 172.17.0.145 #1: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | sending reply packet to 172.17.0.145:51274 (from port=500)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | sending 292 bytes for STATE_MAIN_R1 through br0:500 to 172.17.0.145:51274:
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
Apr 7 10:47:59 (none) kern.warn pluto[2690]: "TEST"[1] 172.17.0.145 #1: STATE_MAIN_R2: sent MR2, expecting MI3
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | modecfg pull: noquirk policy:push not-client
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | phase 1 is done, looking for phase 1 to unpend
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | next event EVENT_RETRANSMIT in 10 seconds for #1
Apr 7 10:47:59 (none) kern.debug pluto[2690]: |
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | *received 68 bytes from 172.17.0.145:52510 on br0 (port=4500)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | processing packet with exchange type=ISAKMP_XCHG_IDPROT (2)
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | ICOOKIE: 57 bd 04 61 e2 cf 56 16
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | RCOOKIE: 8c 63 1a cf 03 65 a4 8a
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | peer: ac 11 00 91
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | state hash entry 26
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | peer and cookies match on #1, provided msgid 00000000 vs 00000000
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | state object #1 found, in STATE_MAIN_R2
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | processing connection TEST[1] 172.17.0.145
Apr 7 10:47:59 (none) kern.warn pluto[2690]: "TEST"[1] 172.17.0.145 #1: Main mode peer ID is ID_IPV4_ADDR: '10.71.32.1'
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | started looking for secret for 172.17.0.193->172.17.0.145 of kind PPK_PSK
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | instantiating him to 0.0.0.0
Apr 7 10:47:59 (none) kern.debug pluto[2690]: | actually looking for secret for 172.17.0.193->0.0.0.0 of kind PPK_PSK
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | 1: compared PSK 0.0.0.0 to 172.17.0.193 / 172.17.0.145 -> 2
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | 2: compared PSK 172.17.0.193 to 172.17.0.193 / 172.17.0.145 -> 6
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | best_match 0>6 best=0x1001ec38 (line=1)
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | concluding with best_match=6 best=0x1001ec38 (lineno=1)
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | started looking for secret for 172.17.0.193->(none) of kind PPK_PSK
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | replace him to 0.0.0.0
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | actually looking for secret for 172.17.0.193->0.0.0.0 of kind PPK_PSK
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | 1: compared PSK 0.0.0.0 to 172.17.0.193 / (none) -> 2
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | 2: compared PSK 172.17.0.193 to 172.17.0.193 / (none) -> 6
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | best_match 0>6 best=0x1001ec38 (line=1)
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | concluding with best_match=6 best=0x1001ec38 (lineno=1)
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | offered CA: '%none'
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | switched from "TEST" to "TEST"
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | alg_info_addref() alg_info->ref_cnt=5
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | alg_info_addref() alg_info->ref_cnt=5
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | alg_info_addref() alg_info->ref_cnt=6
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | alg_info_addref() alg_info->ref_cnt=6
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | instantiated "TEST" for 172.17.0.145
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | processing connection TEST[2] 172.17.0.145
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | processing connection TEST[1] 172.17.0.145
Apr 7 10:48:00 (none) kern.warn pluto[2690]: "TEST"[2] 172.17.0.145 #1: deleting connection "TEST" instance with peer 172.17.0.145 {isakmp=#0/ipsec=#0}
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | alg_info_delref(0x1001d4c0) alg_info->ref_cnt=6
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | alg_info_delref(0x1001cd00) alg_info->ref_cnt=6
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | thinking about whether to send my certificate:
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | I have RSA key: OAKLEY_PRESHARED_KEY cert.type: CERT_NONE
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | sendcert: CERT_ALWAYSSEND and I did not get a certificate request
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | so do not send cert.
Apr 7 10:48:00 (none) kern.warn pluto[2690]: "TEST"[2] 172.17.0.145 #1: I did not send a certificate because I do not have one.
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | complete state transition with STF_OK
Apr 7 10:48:00 (none) kern.warn pluto[2690]: "TEST"[2] 172.17.0.145 #1: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | sending reply packet to 172.17.0.145:51274 (from port=500)
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | NAT-T: new mapping 172.17.0.145:51274/52510)
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | processing connection TEST[2] 172.17.0.145
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | NAT-T: updating local port to 4500
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | NAT-T connection has wrong interface definition 172.17.0.193:4500 vs 172.17.0.193:500
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | NAT-T: using interface br0:4500
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | sending 68 bytes for STATE_MAIN_R2 through br0:4500 to 172.17.0.145:52510:
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | inserting event EVENT_SA_REPLACE, timeout in 3330 seconds for #1
Apr 7 10:48:00 (none) kern.warn pluto[2690]: "TEST"[2] 172.17.0.145 #1: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_PRESHARED_KEY cipher=oakley_3des_cbc_192 prf=oakley_sha group=modp1536}
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | modecfg pull: noquirk policy:push not-client
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | phase 1 is done, looking for phase 1 to unpend
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | next event EVENT_NAT_T_KEEPALIVE in 19 seconds
Apr 7 10:48:00 (none) kern.debug pluto[2690]: |
Apr 7 10:48:00 (none) kern.debug pluto[2690]: | *received 156 bytes from 172.17.0.145:52510 on br0 (port=4500)
More information about the Users
mailing list