Hi folks,
I was wondering whether anyone would be able to shed any insight into why my IPSec tunnel isn't working. I'm using Arokh's WNDR3700 alternate build which is supposedly configured for IPSec already. Unfortunately, I'm getting the error below when I try to connect using my Mac. I can't figure out why - I've checked racoon.conf and it's calling setkey from what I can see. However, I get an error about duplicate tunnels being requested, and the link is finally disconnected.
Update: Evidently, I can't test things very well! :-/ It worked fine once I tried to connect from outside the network.
Mon Dec 9 19:46:19 2013 daemon.debug xl2tpd[5494]: death_handler: Fatal signal 15 received
Mon Dec 9 19:46:19 2013 daemon.debug xl2tpd[6567]: setsockopt recvref[30]: Protocol not available
Mon Dec 9 19:46:19 2013 daemon.info xl2tpd[6567]: Not looking for kernel support.
Mon Dec 9 19:46:19 2013 daemon.info xl2tpd[6568]: xl2tpd version xl2tpd-1.3.1 started on OpenWrt PID:6568
Mon Dec 9 19:46:19 2013 daemon.info xl2tpd[6568]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
Mon Dec 9 19:46:19 2013 daemon.info xl2tpd[6568]: Forked by Scott Balmos and David Stipp, (C) 2001
Mon Dec 9 19:46:19 2013 daemon.info xl2tpd[6568]: Inherited by Jeff McAdams, (C) 2002
Mon Dec 9 19:46:19 2013 daemon.info xl2tpd[6568]: Forked again by Xelerance (www.xelerance.com) (C) 2006
Mon Dec 9 19:46:19 2013 daemon.info xl2tpd[6568]: Listening on IP address 0.0.0.0, port 1701
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: respond new phase 1 negotiation: xx.xx.xx.xx.xx[500]<=>192.168.1.182[500]
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: begin Identity Protection mode.
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: RFC 3947
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-08
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-07
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-06
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-05
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-04
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-03
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: received Vendor ID: draft-ietf-ipsec-nat-t-ike-02
Mon Dec 9 19:46:25 2013 daemon.info racoon: [xx.xx.xx.xx.xx] INFO: Hashing xx.xx.xx.xx.xx[500] with algo #2
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: NAT-D payload #0 verified
Mon Dec 9 19:46:25 2013 daemon.info racoon: [192.168.1.182] INFO: Hashing 192.168.1.182[500] with algo #2
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: NAT-D payload #1 verified
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: NAT not detected
Mon Dec 9 19:46:25 2013 daemon.info racoon: [192.168.1.182] INFO: Hashing 192.168.1.182[500] with algo #2
Mon Dec 9 19:46:25 2013 daemon.info racoon: [xx.xx.xx.xx.xx] INFO: Hashing xx.xx.xx.xx.xx[500] with algo #2
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: Adding remote and local NAT-D payloads.
Mon Dec 9 19:46:25 2013 daemon.info racoon: [192.168.1.182] ERROR: couldn't find the pskey for 192.168.1.182.
Mon Dec 9 19:46:25 2013 daemon.info racoon: [192.168.1.182] NOTIFY: Using default PSK.
Mon Dec 9 19:46:25 2013 daemon.info racoon: [192.168.1.182] INFO: received INITIAL-CONTACT
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: purging spi=213299205.
Mon Dec 9 19:46:25 2013 daemon.info racoon: INFO: ISAKMP-SA established xx.xx.xx.xx.xx[500]-192.168.1.182[500] spi:bef67780ab57fc68:d6cf27ee2a013141
Mon Dec 9 19:46:27 2013 daemon.info racoon: INFO: respond new phase 2 negotiation: xx.xx.xx.xx.xx[500]<=>192.168.1.182[500]
Mon Dec 9 19:46:27 2013 daemon.info racoon: INFO: Update the generated policy : 192.168.1.182/32[57808] xx.xx.xx.xx.xx/32[1701] proto=udp dir=in
Mon Dec 9 19:46:27 2013 daemon.info racoon: INFO: IPsec-SA established: ESP/Transport xx.xx.xx.xx.xx[500]->192.168.1.182[500] spi=261335155(0xf93a873)
Mon Dec 9 19:46:27 2013 daemon.info racoon: INFO: IPsec-SA established: ESP/Transport xx.xx.xx.xx.xx[500]->192.168.1.182[500] spi=197284226(0xbc25182)
Mon Dec 9 19:46:27 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec 9 19:46:27 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec 9 19:46:27 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 5, call is 0.
Mon Dec 9 19:46:27 2013 daemon.none xl2tpd[6568]: control_finish: sending SCCRP
Mon Dec 9 19:46:29 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec 9 19:46:29 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec 9 19:46:29 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 5, call is 0.
Mon Dec 9 19:46:29 2013 daemon.none xl2tpd[6568]: control_finish: Peer requested tunnel 5 twice, ignoring second one.
Mon Dec 9 19:46:29 2013 daemon.none xl2tpd[6568]: build_fdset: closing down tunnel 62959
Mon Dec 9 19:46:30 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:31 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:32 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:33 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec 9 19:46:33 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec 9 19:46:33 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 5, call is 0.
Mon Dec 9 19:46:33 2013 daemon.none xl2tpd[6568]: control_finish: Peer requested tunnel 5 twice, ignoring second one.
Mon Dec 9 19:46:33 2013 daemon.none xl2tpd[6568]: build_fdset: closing down tunnel 1234
Mon Dec 9 19:46:33 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:34 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:34 2013 daemon.error xl2tpd[6568]: Maximum retries exceeded for tunnel 57327. Closing.
Mon Dec 9 19:46:34 2013 daemon.info xl2tpd[6568]: Connection 5 closed to 192.168.1.182, port 57808 (Timeout)
Mon Dec 9 19:46:35 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:36 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:37 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:37 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec 9 19:46:37 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec 9 19:46:37 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 5, call is 0.
Mon Dec 9 19:46:37 2013 daemon.none xl2tpd[6568]: control_finish: Peer requested tunnel 5 twice, ignoring second one.
Mon Dec 9 19:46:37 2013 daemon.none xl2tpd[6568]: build_fdset: closing down tunnel 18582
Mon Dec 9 19:46:38 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:39 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:39 2013 daemon.none xl2tpd[6568]: Unable to deliver closing message for tunnel 57327. Destroying anyway.
Mon Dec 9 19:46:41 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec 9 19:46:41 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec 9 19:46:41 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 5, call is 0.
Mon Dec 9 19:46:41 2013 daemon.none xl2tpd[6568]: control_finish: sending SCCRP
Mon Dec 9 19:46:44 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:45 2013 daemon.none xl2tpd[6568]: network_thread: recv packet from 192.168.1.182, size = 76, tunnel = 0, call = 0 ref=0 refhim=0
Mon Dec 9 19:46:45 2013 daemon.none xl2tpd[6568]: get_call: allocating new tunnel for host 192.168.1.182, port 57808.
Mon Dec 9 19:46:45 2013 daemon.none xl2tpd[6568]: control_finish: message type is Start-Control-Connection-Request(1). Tunnel is 5, call is 0.
Mon Dec 9 19:46:45 2013 daemon.none xl2tpd[6568]: control_finish: Peer requested tunnel 5 twice, ignoring second one.
Mon Dec 9 19:46:45 2013 daemon.none xl2tpd[6568]: build_fdset: closing down tunnel 59973
Mon Dec 9 19:46:45 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:46 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:47 2013 daemon.info racoon: INFO: deleting a generated policy.
Mon Dec 9 19:46:47 2013 daemon.info racoon: INFO: purged IPsec-SA proto_id=ESP spi=197284226.
Mon Dec 9 19:46:47 2013 daemon.info racoon: INFO: ISAKMP-SA expired xx.xx.xx.xx.xx[500]-192.168.1.182[500] spi:bef67780ab57fc68:d6cf27ee2a013141
Mon Dec 9 19:46:47 2013 daemon.info racoon: INFO: ISAKMP-SA deleted xx.xx.xx.xx.xx[500]-192.168.1.182[500] spi:bef67780ab57fc68:d6cf27ee2a013141
Mon Dec 9 19:46:47 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:48 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:48 2013 daemon.error xl2tpd[6568]: Maximum retries exceeded for tunnel 65259. Closing.
Mon Dec 9 19:46:48 2013 daemon.info xl2tpd[6568]: Connection 5 closed to 192.168.1.182, port 57808 (Timeout)
Mon Dec 9 19:46:49 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:50 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:51 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:52 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:53 2013 daemon.none xl2tpd[6568]: network_thread: select timeout
Mon Dec 9 19:46:53 2013 daemon.none xl2tpd[6568]: Unable to deliver closing message for tunnel 65259. Destroying anyway.
Any help would be greatly appreciated!
Cheers,
(Last edited by kop48 on 23 Feb 2014, 19:11)