Re: Simple IPSEC client with certificate - phase 1 time out

To: Brett Lymn <blymn%internode.on.net@localhost>
Subject: Re: Simple IPSEC client with certificate - phase 1 time out
From: Frank Wille <frank%phoenix.owl.de@localhost>
Date: Tue, 01 Mar 2016 13:11:08 +0100

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)

Follow-Ups:
- Re: Simple IPSEC client with certificate - phase 1 time out
  - From: Brett Lymn
- Re: Simple IPSEC client with certificate - phase 1 time out
  - From: Greg Troxel

References:
- Simple IPSEC client with certificate - phase 1 time out
  - From: Frank Wille
- Re: Simple IPSEC client with certificate - phase 1 time out
  - From: Frank Wille
- Re: Simple IPSEC client with certificate - phase 1 time out
  - From: Andy Ruhl
- Re: Simple IPSEC client with certificate - phase 1 time out
  - From: Frank Wille
- Re: Simple IPSEC client with certificate - phase 1 time out
  - From: Brett Lymn
- Re: Simple IPSEC client with certificate - phase 1 time out
  - From: Frank Wille
- Re: Simple IPSEC client with certificate - phase 1 time out
  - From: Brett Lymn

Prev by Date: Re: RAIDframe corruption
Next by Date: Re: RAIDframe corruption
Previous by Thread: Re: Simple IPSEC client with certificate - phase 1 time out
Next by Thread: Re: Simple IPSEC client with certificate - phase 1 time out
Indexes:

Home | Main Index | Thread Index | Old Index