Brett Lymn wrote: > OK, does phase 2 actually complete?
I doubt that. Currently I'm not even sure whether phase 1 completes, because the phase1-up script is never called. On the other hand the phase1-down script is called, as soon as the connection is terminated. > What does a "setkey -aD" output? No SAD entries. And no SPD entries either. I guess they would be added by the phase1-up script...? > Have you tried a tcpdump to see what is going on at the network level? Yes, always. I have attached the tcpdump from my client and the vpn-status log of the Lancom-router (the VPN "server"). > You should expect encrypted packets, if you are seeing stuff in the > clear then check your routing and ensure the packets are properly > routed to the vpn tunnel end point. This is something to worry about as soon as both phases have been completed, which definitely is not the case. ;) > It has been a long while since I played with this but I seem to recall > that you do get a log of what is being proposed by both sides. The proposal is accepted (refer to the Lancom VPN log). Looking at the tcpdump I wonder why the NetBSD client says it is exchanging "isakmp: phase 2" packets, while the Lancom still calls these isakmp notifies "Phase-1 SA"? IKE info: ISAKMP_NOTIFY_DPD_R_U_THERE sent for Phase-1 SA to peer VPNCLIENT15EF90, sequence nr 0x7a8b3f4b -- Frank Wille
Mar 1 11:40:50 powerbook racoon: INFO: @(#)ipsec-tools cvs (http://ipsec-tools.sourceforge.net) Mar 1 11:40:50 powerbook racoon: INFO: @(#)This product linked OpenSSL 1.0.1p 9 Jul 2015 (http://www.openssl.org/) Mar 1 11:40:50 powerbook racoon: INFO: Reading configuration from "/etc/racoon/racoon.conf" Mar 1 11:40:50 powerbook racoon: INFO: 192.168.1.5[500] used for NAT-T Mar 1 11:40:50 powerbook racoon: INFO: 192.168.1.5[500] used as isakmp port (fd=7) Mar 1 11:40:50 powerbook racoon: INFO: 192.168.1.5[4500] used for NAT-T Mar 1 11:40:50 powerbook racoon: INFO: 192.168.1.5[4500] used as isakmp port (fd=8) Mar 1 11:40:50 powerbook racoon: INFO: 127.0.0.1[500] used for NAT-T Mar 1 11:40:50 powerbook racoon: INFO: 127.0.0.1[500] used as isakmp port (fd=9) Mar 1 11:40:50 powerbook racoon: INFO: 127.0.0.1[4500] used for NAT-T Mar 1 11:40:50 powerbook racoon: INFO: 127.0.0.1[4500] used as isakmp port (fd=10) Mar 1 11:52:06 powerbook racoon: INFO: accept a request to establish IKE-SA: 1.2.3.4 Mar 1 11:52:06 powerbook racoon: INFO: initiate new phase 1 negotiation: 192.168.1.5[500]<=>1.2.3.4[500] Mar 1 11:52:06 powerbook racoon: INFO: begin Identity Protection mode. Mar 1 11:52:06 powerbook racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02 Mar 1 11:52:06 powerbook racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-03 Mar 1 11:52:06 powerbook racoon: INFO: received Vendor ID: RFC 3947 Mar 1 11:52:06 powerbook racoon: INFO: received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt Mar 1 11:52:06 powerbook racoon: INFO: received Vendor ID: DPD Mar 1 11:52:06 powerbook racoon: [1.2.3.4] INFO: Selected NAT-T version: RFC 3947 Mar 1 11:52:06 powerbook racoon: [1.2.3.4] INFO: Hashing 1.2.3.4[500] with algo #1 Mar 1 11:52:06 powerbook racoon: [192.168.1.5] INFO: Hashing 192.168.1.5[500] with algo #1 Mar 1 11:52:06 powerbook racoon: INFO: Adding remote and local NAT-D payloads. Mar 1 11:52:06 powerbook racoon: [192.168.1.5] INFO: Hashing 192.168.1.5[500] with algo #1 Mar 1 11:52:06 powerbook racoon: INFO: NAT-D payload #0 doesn't match Mar 1 11:52:06 powerbook racoon: [1.2.3.4] INFO: Hashing 1.2.3.4[500] with algo #1 Mar 1 11:52:06 powerbook racoon: INFO: NAT-D payload #1 verified Mar 1 11:52:06 powerbook racoon: INFO: NAT detected: ME Mar 1 11:52:06 powerbook racoon: INFO: KA list add: 192.168.1.5[4500]->1.2.3.4[4500] Mar 1 11:52:07 powerbook racoon: WARNING: unable to get certificate CRL(3) at depth:0 SubjectName:/postalCode=32052/OU=IT/ST=NRW/L=HERFORD/C=DE/O=WPS/CN=ZENTRALE Mar 1 11:52:07 powerbook racoon: WARNING: unable to get certificate CRL(3) at depth:1 SubjectName:/C=DE/O=LANCOM SYSTEMS/CN=LANCOM CA Mar 1 11:52:07 powerbook racoon: [1.2.3.4] INFO: received INITIAL-CONTACT Mar 1 11:52:07 powerbook racoon: INFO: ISAKMP-SA established 192.168.1.5[4500]-1.2.3.4[4500] spi:4da2f5f910bbdf44:444ae08dd7de45a5 Mar 1 11:53:12 powerbook racoon: [1.2.3.4] INFO: DPD: remote (ISAKMP-SA spi=4da2f5f910bbdf44:444ae08dd7de45a5) seems to be dead. Mar 1 11:53:12 powerbook racoon: INFO: purging ISAKMP-SA spi=4da2f5f910bbdf44:444ae08dd7de45a5. Mar 1 11:53:12 powerbook racoon: INFO: purged ISAKMP-SA spi=4da2f5f910bbdf44:444ae08dd7de45a5. Mar 1 11:53:12 powerbook racoon: INFO: ISAKMP-SA deleted 192.168.1.5[4500]-1.2.3.4[4500] spi:4da2f5f910bbdf44:444ae08dd7de45a5 Mar 1 11:53:12 powerbook racoon: INFO: KA remove: 192.168.1.5[4500]->1.2.3.4[4500]
11:52:06.441891 IP 192.168.1.5.500 > 1.2.3.4.500: isakmp: phase 1 I ident 11:52:06.500027 IP 1.2.3.4.500 > 192.168.1.5.500: isakmp: phase 1 R ident 11:52:06.569110 IP 192.168.1.5.500 > 1.2.3.4.500: isakmp: phase 1 I ident 11:52:06.659061 IP 1.2.3.4.500 > 192.168.1.5.500: isakmp: phase 1 R ident 11:52:06.806959 IP 192.168.1.5.4500 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 1 I ident[E] 11:52:07.498526 IP 1.2.3.4.4500 > 192.168.1.5.4500: NONESP-encap: isakmp: phase 1 R ident[E] 11:52:11.124742 IP 192.168.1.5.4500 > 1.2.3.4.4500: isakmp-nat-keep-alive 11:52:23.925863 IP 1.2.3.4.4500 > 192.168.1.5.4500: NONESP-encap: isakmp: phase 2/others R inf[E] 11:52:23.957487 IP 192.168.1.5.4500 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I inf[E] 11:52:27.567012 IP 192.168.1.5.4500 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I inf[E] 11:52:27.609318 IP 1.2.3.4.4500 > 192.168.1.5.4500: NONESP-encap: isakmp: phase 2/others R inf[E] 11:52:31.144706 IP 192.168.1.5.4500 > 1.2.3.4.4500: isakmp-nat-keep-alive 11:52:47.657437 IP 192.168.1.5.4500 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I inf[E] 11:52:51.175044 IP 192.168.1.5.4500 > 1.2.3.4.4500: isakmp-nat-keep-alive 11:52:52.687182 IP 192.168.1.5.4500 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I inf[E] 11:52:57.727506 IP 192.168.1.5.4500 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I inf[E] 11:53:02.766923 IP 192.168.1.5.4500 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I inf[E] 11:53:07.807263 IP 192.168.1.5.4500 > 1.2.3.4.4500: NONESP-encap: isakmp: phase 2/others I inf[E] 11:53:11.204796 IP 192.168.1.5.4500 > 1.2.3.4.4500: isakmp-nat-keep-alive
[VPN-Status] 2016/03/01 11:52:06,101 IKE info: The remote peer def-main-peer supports NAT-T in RFC mode IKE info: The remote peer def-main-peer supports NAT-T in draft mode IKE info: The remote server 91.56.237.127:2532 (UDP) peer def-main-peer id <no_id> negotiated rfc-3706-dead-peer-detection [VPN-Status] 2016/03/01 11:52:06,102 IKE info: Phase-1 remote proposal 1 for peer def-main-peer matched with local proposal 1 [VPN-Status] 2016/03/01 11:52:06,535 IKE log: 115206.535526 Default conf_get_list: empty field, ignoring... [VPN-Status] 2016/03/01 11:52:07,095 VPN: WAN state changed to WanSetup for (0.0.0.0), called by: 009c5f50 [VPN-Status] 2016/03/01 11:52:07,095 VPN: WAN state changed to WanCalled for VPNCLIENT15EF90 (0.0.0.0), called by: 009c5cb8 [VPN-Status] 2016/03/01 11:52:07,096 vpn-maps[38], remote: VPNCLIENT15EF90, nego, connected-by-name [VPN-Status] 2016/03/01 11:52:07,096 IKE info: exchange_finalize: assuming identified for road-warrior with cert, id=VPNCLIENT15EF90, RemoteGW=91.56.237.127 [VPN-Status] 2016/03/01 11:52:07,121 IKE info: Phase-1 [responder] for peer VPNCLIENT15EF90 initiator id CN=VPNCLIENT15,O=WPS,C=DE,L=HERFORD,ST=NRW,OU=IT,postalCode=32052, responder id CN=ZENTRALE,O=WPS,C=DE,L=HERFORD,ST=NRW,OU=IT,postalCode=32052 IKE info: initiator cookie: 0x4da2f5f910bbdf44, responder cookie: 0x444ae08dd7de45a5 IKE info: NAT-T enabled in mode rfc, we are not behind a nat, the remote side is behind a nat IKE info: SA ISAKMP for peer VPNCLIENT15EF90 encryption aes-cbc authentication MD5 IKE info: life time ( 28800 sec/ 0 kb) DPD 0 sec [VPN-Status] 2016/03/01 11:52:07,123 IKE info: Phase-1 SA Timeout (Hard-Event) for peer VPNCLIENT15EF90 set to 28800 seconds (Responder) [VPN-Status] 2016/03/01 11:52:23,541 IKE info: ISAKMP_NOTIFY_DPD_R_U_THERE sent for Phase-1 SA to peer VPNCLIENT15EF90, sequence nr 0x7a8b3f4b [VPN-Status] 2016/03/01 11:52:23,614 IKE info: NOTIFY received of type ISAKMP_NOTIFY_DPD_R_U_THERE_ACK for peer VPNCLIENT15EF90 Seq-Nr 0x7a8b3f4b, expected 0x7a8b3f4b [VPN-Status] 2016/03/01 11:52:27,223 IKE info: NOTIFY received of type ISAKMP_NOTIFY_DPD_R_U_THERE for peer VPNCLIENT15EF90 Seq-Nr 0xe8, expected 0xe8 [VPN-Status] 2016/03/01 11:52:27,224 IKE info: ISAKMP_NOTIFY_DPD_R_U_THERE_ACK sent for Phase-1 SA to peer VPNCLIENT15EF90, sequence nr 0xe8 [VPN-Status] 2016/03/01 11:52:37,096 VPN: connection for VPNCLIENT15EF90 (91.56.237.127) timed out: no response [VPN-Status] 2016/03/01 11:52:37,096 VPN: Error: IFC-R-Connection-timeout-dynamic (0x1205) for VPNCLIENT15EF90 (91.56.237.127) [VPN-Status] 2016/03/01 11:52:37,096 vpn-maps[38], remote: VPNCLIENT15EF90 [VPN-Status] 2016/03/01 11:52:37,096 VPN: installing ruleset for VPNCLIENT15EF90 (91.56.237.127) [VPN-Status] 2016/03/01 11:52:37,096 VPN: WAN state changed to WanDisconnect for VPNCLIENT15EF90 (91.56.237.127), called by: 009c5cb8 [VPN-Status] 2016/03/01 11:52:37,097 IKE info: Phase-1 SA removed: peer VPNCLIENT15EF90 rule VPNCLIENT15EF90 removed [VPN-Status] 2016/03/01 11:52:37,102 VPN: WAN state changed to WanIdle for VPNCLIENT15EF90 (91.56.237.127), called by: 009c5cb8 [VPN-Status] 2016/03/01 11:52:37,103 removeAllDeletedRoutes, called by: 009bdd24 [VPN-Status] 2016/03/01 11:52:37,108 VPN: VPNCLIENT15EF90 (91.56.237.127) disconnected [VPN-Status] 2016/03/01 11:52:47,318 IKE log: 115247.318276 Default message_drop_invalid_cookies: invalid cookie(s) 4da2f5f910bbdf44 444ae08dd7de45a5 [VPN-Status] 2016/03/01 11:52:47,318 IKE log: 115247.318468 Default dropped message from 91.56.237.127 port 2500 due to notification type INVALID_COOKIE [VPN-Status] 2016/03/01 11:52:47,318 IKE info: Informational messages are unidirectional and therefore are not answered! (cookies 4D A2 F5 F9 10 BB DF 44 44 4A E0 8D D7 DE 45 A5) [VPN-Status] 2016/03/01 11:52:52,355 IKE log: 115252.355368 Default message_drop_invalid_cookies: invalid cookie(s) 4da2f5f910bbdf44 444ae08dd7de45a5 [VPN-Status] 2016/03/01 11:52:52,355 IKE log: 115252.355560 Default dropped message from 91.56.237.127 port 2500 due to notification type INVALID_COOKIE [VPN-Status] 2016/03/01 11:52:52,355 IKE info: Informational messages are unidirectional and therefore are not answered! (cookies 4D A2 F5 F9 10 BB DF 44 44 4A E0 8D D7 DE 45 A5) [VPN-Status] 2016/03/01 11:52:57,384 IKE log: 115257.384602 Default message_drop_invalid_cookies: invalid cookie(s) 4da2f5f910bbdf44 444ae08dd7de45a5 [VPN-Status] 2016/03/01 11:52:57,384 IKE log: 115257.384795 Default dropped message from 91.56.237.127 port 2500 due to notification type INVALID_COOKIE [VPN-Status] 2016/03/01 11:52:57,385 IKE info: Informational messages are unidirectional and therefore are not answered! (cookies 4D A2 F5 F9 10 BB DF 44 44 4A E0 8D D7 DE 45 A5) [VPN-Status] 2016/03/01 11:53:02,424 IKE log: 115302.424565 Default message_drop_invalid_cookies: invalid cookie(s) 4da2f5f910bbdf44 444ae08dd7de45a5 [VPN-Status] 2016/03/01 11:53:02,424 IKE log: 115302.424757 Default dropped message from 91.56.237.127 port 2500 due to notification type INVALID_COOKIE [VPN-Status] 2016/03/01 11:53:02,425 IKE info: Informational messages are unidirectional and therefore are not answered! (cookies 4D A2 F5 F9 10 BB DF 44 44 4A E0 8D D7 DE 45 A5) [VPN-Status] 2016/03/01 11:53:07,463 IKE log: 115307.463673 Default message_drop_invalid_cookies: invalid cookie(s) 4da2f5f910bbdf44 444ae08dd7de45a5 [VPN-Status] 2016/03/01 11:53:07,463 IKE log: 115307.463865 Default dropped message from 91.56.237.127 port 2500 due to notification type INVALID_COOKIE [VPN-Status] 2016/03/01 11:53:07,464 IKE info: Informational messages are unidirectional and therefore are not answered! (cookies 4D A2 F5 F9 10 BB DF 44 44 4A E0 8D D7 DE 45 A5)
