This discussion has been locked.

You can no longer post new replies to this discussion. If you have a question you can start a new discussion

L2TP Certificate & Android: No public key known

I'm really pulling at strings here to get Android working with this.

PPTP doesn't work, L2TP/IPSec doesn't work with PSK (Android wants to use CHAP, which Astaro doesn't support).

So I'm trying L2TP/IPSec with certificates, hoping maybe this will work better.

I'm all doing it in a virtual sort of enviroment, so there are no routers, firewalls, or NAT in the way.

2010:09:26-13:02:58 ASG8 pluto[10531]: | *received 352 bytes from 192.168.1.139:500 on eth1
2010:09:26-13:02:58 ASG8 pluto[10531]: packet from 192.168.1.139:500: received Vendor ID payload [RFC 3947]
2010:09:26-13:02:58 ASG8 pluto[10531]: packet from 192.168.1.139:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02]
2010:09:26-13:02:58 ASG8 pluto[10531]: packet from 192.168.1.139:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]
2010:09:26-13:02:58 ASG8 pluto[10531]: packet from 192.168.1.139:500: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]
2010:09:26-13:02:58 ASG8 pluto[10531]: packet from 192.168.1.139:500: ignoring Vendor ID payload [FRAGMENTATION 80000000]
2010:09:26-13:02:58 ASG8 pluto[10531]: | preparse_isakmp_policy: peer requests PUBKEY authentication
2010:09:26-13:02:58 ASG8 pluto[10531]: | instantiated "D_Android" for 192.168.1.139
2010:09:26-13:02:58 ASG8 pluto[10531]: | creating state object #1 at 0x8e80c10
2010:09:26-13:02:58 ASG8 pluto[10531]: | ICOOKIE: 88 ed 8c 32 47 fc 41 cd
2010:09:26-13:02:58 ASG8 pluto[10531]: | RCOOKIE: a1 19 ff 94 1c 10 f6 c6
2010:09:26-13:02:58 ASG8 pluto[10531]: | peer: c0 a8 01 8b
2010:09:26-13:02:58 ASG8 pluto[10531]: | state hash entry 21
2010:09:26-13:02:58 ASG8 pluto[10531]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #1
2010:09:26-13:02:58 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: responding to Main Mode from unknown peer 192.168.1.139
2010:09:26-13:02:58 ASG8 pluto[10531]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
2010:09:26-13:02:58 ASG8 pluto[10531]: | next event EVENT_RETRANSMIT in 10 seconds for #1
2010:09:26-13:02:58 ASG8 pluto[10531]: |
2010:09:26-13:02:58 ASG8 pluto[10531]: | *received 228 bytes from 192.168.1.139:500 on eth1
2010:09:26-13:02:58 ASG8 pluto[10531]: | ICOOKIE: 88 ed 8c 32 47 fc 41 cd
2010:09:26-13:02:58 ASG8 pluto[10531]: | RCOOKIE: a1 19 ff 94 1c 10 f6 c6
2010:09:26-13:02:58 ASG8 pluto[10531]: | peer: c0 a8 01 8b
2010:09:26-13:02:58 ASG8 pluto[10531]: | state hash entry 21
2010:09:26-13:02:58 ASG8 pluto[10531]: | state object #1 found, in STATE_MAIN_R1
2010:09:26-13:02:58 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: NAT-Traversal: Result using RFC 3947: no NAT detected
2010:09:26-13:02:58 ASG8 pluto[10531]: | inserting event EVENT_NAT_T_KEEPALIVE, timeout in 60 seconds
2010:09:26-13:02:58 ASG8 pluto[10531]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #1
2010:09:26-13:02:58 ASG8 pluto[10531]: | next event EVENT_RETRANSMIT in 10 seconds for #1
2010:09:26-13:02:58 ASG8 pluto[10531]: |
2010:09:26-13:02:58 ASG8 pluto[10531]: | *received 988 bytes from 192.168.1.139:500 on eth1
2010:09:26-13:02:58 ASG8 pluto[10531]: | ICOOKIE: 88 ed 8c 32 47 fc 41 cd
2010:09:26-13:02:58 ASG8 pluto[10531]: | RCOOKIE: a1 19 ff 94 1c 10 f6 c6
2010:09:26-13:02:58 ASG8 pluto[10531]: | peer: c0 a8 01 8b
2010:09:26-13:02:58 ASG8 pluto[10531]: | state hash entry 21
2010:09:26-13:02:58 ASG8 pluto[10531]: | state object #1 found, in STATE_MAIN_R2
2010:09:26-13:02:58 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: Peer ID is ID_IPV4_ADDR: '192.168.1.139'
2010:09:26-13:02:58 ASG8 pluto[10531]: | subject: 'C=us, L=*****, O=*****, CN=*****'
2010:09:26-13:02:58 ASG8 pluto[10531]: | issuer: 'C=us, L=*****, O=*****, CN=***** VPN CA, E=*****@gmail.com'
2010:09:26-13:02:58 ASG8 pluto[10531]: | authkey: da:2b:a6[:D]4:af:44:2a:5b:9f:c8:4f:2a:8a:6b:fc:a3:a5:c2:90:eb
2010:09:26-13:02:58 ASG8 pluto[10531]: | certificate is valid
2010:09:26-13:02:58 ASG8 pluto[10531]: | issuer cacert found
2010:09:26-13:02:58 ASG8 pluto[10531]: | certificate signature is valid
2010:09:26-13:02:58 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: crl not found
2010:09:26-13:02:58 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: certificate status unknown
2010:09:26-13:02:58 ASG8 pluto[10531]: | subject: 'C=us, L=*****, O=*****, CN=***** VPN CA, E=*****@gmail.com'
2010:09:26-13:02:58 ASG8 pluto[10531]: | issuer: 'C=us, L=*****, O=*****, CN=***** VPN CA, E=*****@gmail.com'
2010:09:26-13:02:58 ASG8 pluto[10531]: | certificate is valid
2010:09:26-13:02:58 ASG8 pluto[10531]: | issuer cacert found
2010:09:26-13:02:58 ASG8 pluto[10531]: | certificate signature is valid
2010:09:26-13:02:58 ASG8 pluto[10531]: | reached self-signed root ca with a path length of 0
2010:09:26-13:02:58 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: no public key known for '192.168.1.139'
2010:09:26-13:02:58 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: sending encrypted notification INVALID_KEY_INFORMATION to 192.168.1.139:500
2010:09:26-13:02:58 ASG8 pluto[10531]: | state transition function for STATE_MAIN_R2 failed: INVALID_KEY_INFORMATION
2010:09:26-13:02:58 ASG8 pluto[10531]: | next event EVENT_RETRANSMIT in 10 seconds for #1

It does that a couple of times and then fails with this

2010:09:26-13:03:28 ASG8 pluto[10531]: | *time to handle event
2010:09:26-13:03:28 ASG8 pluto[10531]: | event after this is EVENT_NAT_T_KEEPALIVE in 30 seconds
2010:09:26-13:03:28 ASG8 pluto[10531]: | handling event EVENT_RETRANSMIT for 192.168.1.139 "D_Android" #1
2010:09:26-13:03:28 ASG8 pluto[10531]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #1
2010:09:26-13:03:28 ASG8 pluto[10531]: | next event EVENT_NAT_T_KEEPALIVE in 30 seconds
2010:09:26-13:03:28 ASG8 pluto[10531]: | rejected packet:
2010:09:26-13:03:28 ASG8 pluto[10531]: | 88 ed 8c 32 47 fc 41 cd a1 19 ff 94 1c 10 f6 c6
2010:09:26-13:03:28 ASG8 pluto[10531]: | 04 10 02 00 00 00 00 00 00 00 00 e4 0a 00 00 84
2010:09:26-13:03:28 ASG8 pluto[10531]: | 78 db 1c 97 a1 b4 58 2a 8d 9b 93 5e 22 41 2d 5c
2010:09:26-13:03:28 ASG8 pluto[10531]: | 8c 3d b0 ed 61 49 7f 6f ef 0b 4d 88 cc ed d2 ac
2010:09:26-13:03:28 ASG8 pluto[10531]: | 6f 8f 54 c7 b1 d7 3c 69 51 42 c7 86 3b 30 c5 5e
2010:09:26-13:03:28 ASG8 pluto[10531]: | 0b 1f eb e2 e8 db 26 a8 1f ee 5f da ec 3e bf ee
2010:09:26-13:03:28 ASG8 pluto[10531]: | 1d 91 22 d1 cf 20 e6 fb 21 dd 59 19 6b f0 89 ef
2010:09:26-13:03:28 ASG8 pluto[10531]: | b7 e5 4d 76 56 15 ac 5b 57 66 0d be 85 a9 f5 f7
2010:09:26-13:03:28 ASG8 pluto[10531]: | eb d6 87 57 08 eb a6 ed 63 86 b2 fd 36 12 fc 8c
2010:09:26-13:03:28 ASG8 pluto[10531]: | 79 22 43 32 8d e4 6c 37 e4 98 f1 82 25 53 e0 1a
2010:09:26-13:03:28 ASG8 pluto[10531]: | 14 00 00 14 9a e3 c8 30 b9 e5 ed 34 73 88 0a f8
2010:09:26-13:03:28 ASG8 pluto[10531]: | 1a 71 ca 54 14 00 00 18 dd ea 91 06 d4 4b 0c 70
2010:09:26-13:03:28 ASG8 pluto[10531]: | ea 6f 79 1d f1 35 66 5b 33 57 e1 d5 00 00 00 18
2010:09:26-13:03:28 ASG8 pluto[10531]: | c0 71 8e a8 ea 7f a9 48 2b d5 e4 07 a0 5b 3d 21
2010:09:26-13:03:28 ASG8 pluto[10531]: | de fa 90 5e
2010:09:26-13:03:28 ASG8 pluto[10531]: | control:
2010:09:26-13:03:28 ASG8 pluto[10531]: | 2c 00 00 00 00 00 00 00 0b 00 00 00 6f 00 00 00
2010:09:26-13:03:28 ASG8 pluto[10531]: | 02 03 03 00 00 00 00 00 00 00 00 00 02 00 00 00
2010:09:26-13:03:28 ASG8 pluto[10531]: | c0 a8 01 8b 00 00 00 00 00 00 00 00
2010:09:26-13:03:28 ASG8 pluto[10531]: | name:
2010:09:26-13:03:28 ASG8 pluto[10531]: | 02 00 01 f4 c0 a8 01 8b 00 00 00 00 00 00 00 00
2010:09:26-13:03:28 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: ERROR: asynchronous network error report on eth1 for message to 192.168.1.139 port 500, complainant 192.168.1.139: Connection refused [errno 111, origin ICMP type 3 code 3 (not authenticated)]
2010:09:26-13:03:28 ASG8 pluto[10531]: | next event EVENT_NAT_T_KEEPALIVE in 30 seconds
2010:09:26-13:03:58 ASG8 pluto[10531]: |
2010:09:26-13:03:58 ASG8 pluto[10531]: | *time to handle event
2010:09:26-13:03:58 ASG8 pluto[10531]: | event after this is EVENT_RETRANSMIT in 10 seconds
2010:09:26-13:03:58 ASG8 pluto[10531]: | next event EVENT_RETRANSMIT in 10 seconds for #1
2010:09:26-13:04:08 ASG8 pluto[10531]: |
2010:09:26-13:04:08 ASG8 pluto[10531]: | *time to handle event
2010:09:26-13:04:08 ASG8 pluto[10531]: | event after this is EVENT_REINIT_SECRET in 3515 seconds
2010:09:26-13:04:08 ASG8 pluto[10531]: | handling event EVENT_RETRANSMIT for 192.168.1.139 "D_Android" #1
2010:09:26-13:04:08 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139 #1: max number of retransmissions (2) reached STATE_MAIN_R2
2010:09:26-13:04:08 ASG8 pluto[10531]: | ICOOKIE: 88 ed 8c 32 47 fc 41 cd
2010:09:26-13:04:08 ASG8 pluto[10531]: | RCOOKIE: a1 19 ff 94 1c 10 f6 c6
2010:09:26-13:04:08 ASG8 pluto[10531]: | peer: c0 a8 01 8b
2010:09:26-13:04:08 ASG8 pluto[10531]: | state hash entry 21
2010:09:26-13:04:08 ASG8 pluto[10531]: "D_Android"[1] 192.168.1.139: deleting connection "D_Android" instance with peer 192.168.1.139 {isakmp=#0/ipsec=#0}

I have a remote access rule called Android, interface external (which is the 192.168.1.x network), TripleDES Policy, Local network is the virtual internal network (eth0), I have the user i'm trying to log on as set in the allowed users, and automatic packet filter rules checked.

This thread was automatically locked due to age.

Parents

0 BAlfson over 14 years ago

-----Original Message-----
From: Support AMER
Sent: Wednesday, December 09, 2009 5:42 PM
To: Bob Alfson
Subject: Re: [Ticket#2009120810000035] Case #00111535

Hi Bob,

Because the DHCP server is leasing IPs on the same network as the internal network, it is causing hosts on the internal network to ARP for the MAC address of the l2tp client. ARP traffic will not route through the l2tp tunnel.

My IP was 10.x.x.71. The server was sending the ARP request but it was never sent down the tunnel:

17:06:16.278231 arp who-has 10.x.x.71 tell 10.x.x.7
17:06:17.068875 IP (tos 0x0, ttl 64, id 51623, offset 0, flags [none], proto ICMP
(1), length 84) 10.x.x.71 > 10.x.x.7: ICMP echo request, id 59139, seq 27, length 64
17:06:17.069010 IP (tos 0x0, ttl 63, id 51623, offset 0, flags [none], proto ICMP
(1), length 84) 10.x.x.71 > 10.x.x.7: ICMP echo request, id 59139, seq 27, length 64
17:06:18.068557 IP (tos 0x0, ttl 64, id 2041, offset 0, flags [none], proto ICMP
(1), length 84) 10.x.x.71 > 10.x.x.7: ICMP echo request, id 59139, seq 28, length 64
17:06:18.068691 IP (tos 0x0, ttl 63, id 2041, offset 0, flags [none], proto ICMP
(1), length 84) 10.x.x.71 > 10.x.x.7: ICMP echo request, id 59139, seq 28, length 64
17:06:18.069902 arp who-has 10.x.x.71 tell 10.x.x.7
17:06:19.068516 IP (tos 0x0, ttl 64, id 33194, offset 0, flags [none], proto ICMP
(1), length 84) 10.x.x.71 > 10.x.x.7: ICMP echo request, id 59139, seq 29, length 64
17:06:19.068646 IP (tos 0x0, ttl 63, id 33194, offset 0, flags [none], proto ICMP
(1), length 84) 10.x.x.71 > 10.x.x.7: ICMP echo request, id 59139, seq 29, length 64
17:06:19.277886 IP (tos 0x18, ttl 255, id 52912, offset 0, flags [none], proto UDP
(17), length 89) 10.x.x.71.63216 > 10.x.x.7.53: 56269+[|domain]
17:06:19.278019 IP (tos 0x18, ttl 254, id 52912, offset 0, flags [none], proto UDP
(17), length 89) 10.x.x.71.63216 > 10.x.x.7.53: 56269+[|domain]
17:06:19.278227 arp who-has 10.x.x.71 tell 10.x.x.7

I would recommend setting the DHCP server to lease an address from a separate network pool for the L2TP client for proper routing.

Best regards,

Astaro Technical Support Team

Jason Simon

Personally, I think the Astaro should be smart enough to handle such ARP requests, but...

Cheers - Bob
Cancel
Vote Up 0 Vote Down

Cancel
0 d12fk over 14 years ago in reply to BAlfson

Personally, I think the Astaro should be smart enough to handle such ARP requests, but...

Well, doing proxy ARP the right way automatically isn't that easy if not impossible without configuration by the user. Made a mental note about the issue and will let it sit for a while. =)
Cancel
Vote Up 0 Vote Down

Cancel
0 coreno over 14 years ago in reply to d12fk

Doesn't look much different with Parsing Debug enabled, and looks "normal" still, up until "no connection known". Trimmed some fat from the top and bottom of the log for post-length's sake.

2010:09:27-19:45:57 ASG8 pluto[8474]: | *received 284 bytes from 192.168.1.139:500 on eth1
2010:09:27-19:45:57 ASG8 pluto[8474]: | **parse ISAKMP Message:
2010:09:27-19:45:57 ASG8 pluto[8474]: | initiator cookie:
2010:09:27-19:45:57 ASG8 pluto[8474]: | 67 b0 75 32 ba fc 0f 1e
2010:09:27-19:45:57 ASG8 pluto[8474]: | responder cookie:
2010:09:27-19:45:57 ASG8 pluto[8474]: | 8f d9 52 6e 11 a7 54 63
2010:09:27-19:45:57 ASG8 pluto[8474]: | next payload type: ISAKMP_NEXT_HASH
2010:09:27-19:45:57 ASG8 pluto[8474]: | ISAKMP version: ISAKMP Version 1.0
2010:09:27-19:45:57 ASG8 pluto[8474]: | exchange type: ISAKMP_XCHG_QUICK
2010:09:27-19:45:57 ASG8 pluto[8474]: | flags: ISAKMP_FLAG_ENCRYPTION
2010:09:27-19:45:57 ASG8 pluto[8474]: | message ID: b0 c1 50 90
2010:09:27-19:45:57 ASG8 pluto[8474]: | length: 284
2010:09:27-19:45:57 ASG8 pluto[8474]: | ICOOKIE: 67 b0 75 32 ba fc 0f 1e
2010:09:27-19:45:57 ASG8 pluto[8474]: | RCOOKIE: 8f d9 52 6e 11 a7 54 63
2010:09:27-19:45:57 ASG8 pluto[8474]: | peer: c0 a8 01 8b
2010:09:27-19:45:57 ASG8 pluto[8474]: | state hash entry 18
2010:09:27-19:45:57 ASG8 pluto[8474]: | state object not found
2010:09:27-19:45:57 ASG8 pluto[8474]: | ICOOKIE: 67 b0 75 32 ba fc 0f 1e
2010:09:27-19:45:57 ASG8 pluto[8474]: | RCOOKIE: 8f d9 52 6e 11 a7 54 63
2010:09:27-19:45:57 ASG8 pluto[8474]: | peer: c0 a8 01 8b
2010:09:27-19:45:57 ASG8 pluto[8474]: | state hash entry 18
2010:09:27-19:45:57 ASG8 pluto[8474]: | state object #1 found, in STATE_MAIN_R3
2010:09:27-19:45:57 ASG8 pluto[8474]: | ***parse ISAKMP Hash Payload:
2010:09:27-19:45:57 ASG8 pluto[8474]: | next payload type: ISAKMP_NEXT_SA
2010:09:27-19:45:57 ASG8 pluto[8474]: | length: 24
2010:09:27-19:45:57 ASG8 pluto[8474]: | ***parse ISAKMP Security Association Payload:
2010:09:27-19:45:57 ASG8 pluto[8474]: | next payload type: ISAKMP_NEXT_NONCE
2010:09:27-19:45:57 ASG8 pluto[8474]: | length: 176
2010:09:27-19:45:57 ASG8 pluto[8474]: | DOI: ISAKMP_DOI_IPSEC
2010:09:27-19:45:57 ASG8 pluto[8474]: | ***parse ISAKMP Nonce Payload:
2010:09:27-19:45:57 ASG8 pluto[8474]: | next payload type: ISAKMP_NEXT_ID
2010:09:27-19:45:57 ASG8 pluto[8474]: | length: 20
2010:09:27-19:45:57 ASG8 pluto[8474]: | ***parse ISAKMP Identification Payload (IPsec DOI):
2010:09:27-19:45:57 ASG8 pluto[8474]: | next payload type: ISAKMP_NEXT_ID
2010:09:27-19:45:57 ASG8 pluto[8474]: | length: 12
2010:09:27-19:45:57 ASG8 pluto[8474]: | ID type: ID_IPV4_ADDR
2010:09:27-19:45:57 ASG8 pluto[8474]: | Protocol ID: 17
2010:09:27-19:45:57 ASG8 pluto[8474]: | port: 0
2010:09:27-19:45:57 ASG8 pluto[8474]: | ***parse ISAKMP Identification Payload (IPsec DOI):
2010:09:27-19:45:57 ASG8 pluto[8474]: | next payload type: ISAKMP_NEXT_NONE
2010:09:27-19:45:57 ASG8 pluto[8474]: | length: 12
2010:09:27-19:45:57 ASG8 pluto[8474]: | ID type: ID_IPV4_ADDR
2010:09:27-19:45:57 ASG8 pluto[8474]: | Protocol ID: 17
2010:09:27-19:45:57 ASG8 pluto[8474]: | port: 1701
2010:09:27-19:45:57 ASG8 pluto[8474]: | removing 12 bytes of padding
2010:09:27-19:45:57 ASG8 pluto[8474]: | peer client is 192.168.1.139
2010:09:27-19:45:57 ASG8 pluto[8474]: | peer client protocol/port is 17/0
2010:09:27-19:45:57 ASG8 pluto[8474]: | our client is 192.168.1.154
2010:09:27-19:45:57 ASG8 pluto[8474]: | our client protocol/port is 17/1701
2010:09:27-19:45:57 ASG8 pluto[8474]: | no valid attribute cert found
2010:09:27-19:45:57 ASG8 pluto[8474]: "D_Android"[1] 192.168.1.139 #1: cannot respond to IPsec SA request because no connection is known for 192.168.1.154[ASG8]:17/1701...192.168.1.139[192.168.1.139]:17/0===%VPN Pool (IPSec)
2010:09:27-19:45:57 ASG8 pluto[8474]: "D_Android"[1] 192.168.1.139 #1: sending encrypted notification INVALID_ID_INFORMATION to 192.168.1.139:500
2010:09:27-19:45:57 ASG8 pluto[8474]: | state transition function for STATE_QUICK_R0 failed: INVALID_ID_INFORMATION
2010:09:27-19:45:57 ASG8 pluto[8474]: | next event EVENT_NAT_T_KEEPALIVE in 59 seconds
2010:09:27-19:46:07 ASG8 pluto[8474]: |
2010:09:27-19:46:07 ASG8 pluto[8474]: | *received 284 bytes from 192.168.1.139:500 on eth1
2010:09:27-19:46:07 ASG8 pluto[8474]: | **parse ISAKMP Message:
2010:09:27-19:46:07 ASG8 pluto[8474]: | initiator cookie:
2010:09:27-19:46:07 ASG8 pluto[8474]: | 67 b0 75 32 ba fc 0f 1e
2010:09:27-19:46:07 ASG8 pluto[8474]: | responder cookie:
2010:09:27-19:46:07 ASG8 pluto[8474]: | 8f d9 52 6e 11 a7 54 63
2010:09:27-19:46:07 ASG8 pluto[8474]: | next payload type: ISAKMP_NEXT_HASH
2010:09:27-19:46:07 ASG8 pluto[8474]: | ISAKMP version: ISAKMP Version 1.0
2010:09:27-19:46:07 ASG8 pluto[8474]: | exchange type: ISAKMP_XCHG_QUICK
2010:09:27-19:46:07 ASG8 pluto[8474]: | flags: ISAKMP_FLAG_ENCRYPTION
2010:09:27-19:46:07 ASG8 pluto[8474]: | message ID: b0 c1 50 90
2010:09:27-19:46:07 ASG8 pluto[8474]: | length: 284
2010:09:27-19:46:07 ASG8 pluto[8474]: | ICOOKIE: 67 b0 75 32 ba fc 0f 1e
2010:09:27-19:46:07 ASG8 pluto[8474]: | RCOOKIE: 8f d9 52 6e 11 a7 54 63
2010:09:27-19:46:07 ASG8 pluto[8474]: | peer: c0 a8 01 8b
2010:09:27-19:46:07 ASG8 pluto[8474]: | state hash entry 18
2010:09:27-19:46:07 ASG8 pluto[8474]: | state object not found
2010:09:27-19:46:07 ASG8 pluto[8474]: | ICOOKIE: 67 b0 75 32 ba fc 0f 1e
2010:09:27-19:46:07 ASG8 pluto[8474]: | RCOOKIE: 8f d9 52 6e 11 a7 54 63
2010:09:27-19:46:07 ASG8 pluto[8474]: | peer: c0 a8 01 8b
2010:09:27-19:46:07 ASG8 pluto[8474]: | state hash entry 18
2010:09:27-19:46:07 ASG8 pluto[8474]: | state object #1 found, in STATE_MAIN_R3
2010:09:27-19:46:07 ASG8 pluto[8474]: "D_Android"[1] 192.168.1.139 #1: Quick Mode I1 message is unacceptable because it uses a previously used Message ID 0x9050c1b0 (perhaps this is a duplicated packet)
2010:09:27-19:46:07 ASG8 pluto[8474]: "D_Android"[1] 192.168.1.139 #1: sending encrypted notification INVALID_MESSAGE_ID to 192.168.1.139:500
2010:09:27-19:46:07 ASG8 pluto[8474]: | next event EVENT_NAT_T_KEEPALIVE in 49 seconds
Cancel
Vote Up 0 Vote Down

Cancel
0 coreno over 14 years ago in reply to coreno

I got the logs from android as well...

Also, my "internal" network is 192.168.137.x, and I've left the IP Pool for the VPN at default for now.

09-27 21:59:03.361: INFO/SProxy_racoon(17164): Start VPN daemon: racoon
09-27 21:59:03.371: DEBUG/racoon(17475): Waiting for control socket
09-27 21:59:03.371: DEBUG/SProxy_racoon(17164): racoon is running after 0 msec
09-27 21:59:03.412: DEBUG/racoon(17475): Received 5 arguments
09-27 21:59:03.412: INFO/racoon(17475): ipsec-tools 0.7.3 (IPsec Tools Homepage)
09-27 21:59:03.452: INFO/AudioHardwareQSD(70): AUDIO_START: start kernel pcm_out driver.
09-27 21:59:03.452: WARN/AudioFlinger(70): write blocked for 219 msecs, 390 delayed writes, thread 0x155c0
09-27 21:59:03.471: INFO/racoon(17475): 192.168.1.139[500] used as isakmp port (fd=12)
09-27 21:59:03.471: INFO/racoon(17475): 192.168.1.139[500] used for NAT-T
09-27 21:59:03.471: INFO/racoon(17475): 192.168.1.139[4500] used as isakmp port (fd=13)
09-27 21:59:03.471: INFO/racoon(17475): 192.168.1.139[4500] used for NAT-T
09-27 21:59:03.471: INFO/SProxy_racoon(17164): got data from control socket: 5
09-27 21:59:05.472: INFO/SProxy_mtpd(17164): Start VPN daemon: mtpd
09-27 21:59:05.472: DEBUG/SProxy_mtpd(17164): mtpd is running after 0 msec
09-27 21:59:05.481: DEBUG/mtpd(17743): Waiting for control socket
09-27 21:59:05.481: DEBUG/SProxy_mtpd(17164): service not yet listen()ing; try again
09-27 21:59:06.031: DEBUG/mtpd(17743): Received 19 arguments
09-27 21:59:06.031: INFO/mtpd(17743): Using protocol l2tp
09-27 21:59:06.031: INFO/mtpd(17743): Connecting to 192.168.1.154 port 1701
09-27 21:59:06.031: INFO/racoon(17475): no in-bound policy found: 192.168.1.154/32[1701] 192.168.1.139/32[0] proto=udp dir=in
09-27 21:59:06.031: INFO/racoon(17475): IPsec-SA request for 192.168.1.154 queued due to no phase1 found.
09-27 21:59:06.031: INFO/racoon(17475): initiate new phase 1 negotiation: 192.168.1.139[500]192.168.1.154[500]
09-27 21:59:06.031: INFO/racoon(17475): begin Identity Protection mode.
09-27 21:59:06.031: INFO/mtpd(17743): Connection established (socket = 13)
09-27 21:59:06.042: DEBUG/mtpd(17743): Sending SCCRQ (local_tunnel = 30911)
09-27 21:59:06.042: INFO/SProxy_mtpd(17164): got data from control socket: 19
09-27 21:59:06.251: INFO/racoon(17475): received Vendor ID: CISCO-UNITY
09-27 21:59:06.251: INFO/racoon(17475): received Vendor ID: draft-ietf-ipsra-isakmp-xauth-06.txt
09-27 21:59:06.251: INFO/racoon(17475): received Vendor ID: DPD
09-27 21:59:06.251: INFO/racoon(17475): received Vendor ID: RFC 3947
09-27 21:59:06.251: INFO/racoon(17475): Selected NAT-T version: RFC 3947
09-27 21:59:06.301: INFO/racoon(17475): Hashing 192.168.1.154[500] with algo #2
09-27 21:59:06.301: INFO/racoon(17475): Hashing 192.168.1.139[500] with algo #2
09-27 21:59:06.301: INFO/racoon(17475): Adding remote and local NAT-D payloads.
09-27 21:59:06.322: INFO/racoon(17475): Hashing 192.168.1.139[500] with algo #2
09-27 21:59:06.322: INFO/racoon(17475): NAT-D payload #0 verified
09-27 21:59:06.322: INFO/racoon(17475): Hashing 192.168.1.154[500] with algo #2
09-27 21:59:06.322: INFO/racoon(17475): NAT-D payload #1 verified
09-27 21:59:06.322: INFO/racoon(17475): NAT not detected
09-27 21:59:06.362: INFO/keystore(73): uid: 1016 action: g -> 1 state: 1 -> 1 retry: 4
09-27 21:59:06.362: INFO/keystore(73): uid: 1016 action: g -> 1 state: 1 -> 1 retry: 4
09-27 21:59:06.441: INFO/keystore(73): uid: 1016 action: g -> 1 state: 1 -> 1 retry: 4
09-27 21:59:06.441: WARN/racoon(17475): unable to get certificate CRL(3) at depth:0 SubjectName:/C=us/L=*****/O=*****/CN=ASG8/emailAddress=*****
09-27 21:59:06.441: WARN/racoon(17475): unable to get certificate CRL(3) at depth:1 SubjectName:/C=us/L=*****/O=*****/CN=***** VPN CA/emailAddress=*****
09-27 21:59:06.441: INFO/racoon(17475): ISAKMP-SA established 192.168.1.139[500]-192.168.1.154[500] spi:8e8f44d403939c73:892011df73a64f21
09-27 21:59:06.522: INFO/AudioHardwareQSD(70): AudioHardware pcm playback is going to standby.
09-27 21:59:06.522: DEBUG/StreamProcess(70): OutputStreamProcess::ResetAOLC()
09-27 21:59:07.449: INFO/racoon(17475): initiate new phase 2 negotiation: 192.168.1.139[500]192.168.1.154[500]
09-27 21:59:07.451: ERROR/racoon(17475): fatal INVALID-ID-INFORMATION notify messsage, phase1 should be deleted.
09-27 21:59:08.043: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:10.044: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:12.048: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:13.341: DEBUG/dalvikvm(17013): GC_EXPLICIT freed 240 objects / 15880 bytes in 88ms
09-27 21:59:14.051: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:16.054: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:17.464: ERROR/racoon(17475): fatal INVALID-MESSAGE-ID notify messsage, phase1 should be deleted.
09-27 21:59:18.057: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:20.060: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:22.063: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:23.351: DEBUG/dalvikvm(14618): GC_EXPLICIT freed 2046 objects / 132032 bytes in 84ms
09-27 21:59:24.066: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:26.068: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:27.481: ERROR/racoon(17475): fatal INVALID-MESSAGE-ID notify messsage, phase1 should be deleted.
09-27 21:59:28.070: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:30.072: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:32.074: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:33.331: DEBUG/dalvikvm(272): GC_EXPLICIT freed 1857 objects / 145136 bytes in 66ms
09-27 21:59:34.076: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:36.078: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:37.441: INFO/racoon(17475): IPsec-SA expired: ESP/Transport 192.168.1.154[0]->192.168.1.139[0] spi=100907697(0x603bab1)
09-27 21:59:37.441: WARN/racoon(17475): the expire message is received but the handler has not been established.
09-27 21:59:37.441: ERROR/racoon(17475): 192.168.1.154 give up to get IPsec-SA due to time up to wait.
09-27 21:59:37.441: INFO/racoon(17475): Bye
09-27 21:59:38.080: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:40.082: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:42.085: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:44.087: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:46.081: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:48.085: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:48.092: ERROR/VpnService(17164): onError()
09-27 21:59:48.092: ERROR/VpnService(17164): java.io.IOException: Connecting timed out
09-27 21:59:48.092: ERROR/VpnService(17164):     at com.android.server.vpn.VpnService.waitUntilConnectedOrTimedout(VpnService.java:210)
09-27 21:59:48.092: ERROR/VpnService(17164):     at com.android.server.vpn.VpnService.onConnect(VpnService.java:139)
09-27 21:59:48.092: ERROR/VpnService(17164):     at com.android.server.vpn.VpnServiceBinder$2.run(VpnServiceBinder.java:114)
09-27 21:59:48.092: ERROR/VpnService(17164):     at java.lang.Thread.run(Thread.java:1102)
09-27 21:59:48.092: INFO/VpnService(17164): disconnecting VPN...
09-27 21:59:48.101: DEBUG/VpnSettings(9926): received connectivity: Crt: connected? DISCONNECTING   err=0
09-27 21:59:48.171: INFO/SProxy_mtpd(17164): Stop VPN daemon: mtpd
09-27 21:59:48.191: DEBUG/mtpd(17743): Timeout -> Sending SCCRQ
09-27 21:59:48.191: INFO/mtpd(17743): Received signal 15
09-27 21:59:48.191: DEBUG/mtpd(17743): Sending STOPCCN
09-27 21:59:48.191: INFO/mtpd(17743): Mtpd is terminated (status = 6)
09-27 21:59:48.191: DEBUG/SProxy_mtpd(17164): mtpd is stopped after 0 msec
09-27 21:59:48.201: INFO/LSState(97): EventReceiver:android.intent.action.NOTIFICATION_ADD
09-27 21:59:48.201: DEBUG/SProxy_mtpd(17164): stopping mtpd, success? true
09-27 21:59:48.221: INFO/SProxy_racoon(17164): Stop VPN daemon: racoon
09-27 21:59:48.231: DEBUG/SProxy_racoon(17164): racoon is stopped after 0 msec
09-27 21:59:48.251: DEBUG/SProxy_racoon(17164): stopping racoon, success? true
09-27 21:59:48.271: INFO/ipd(74): IP CMD: /system/bin/ip ru del from all to all table vpn prio 2500
09-27 21:59:48.271: DEBUG/VpnService(17164): onFinalCleanUp()
09-27 21:59:48.271: INFO/VpnService(17164): restore original suffices --> null
09-27 21:59:48.291: DEBUG/VpnSettings(9926): received connectivity: Crt: connected? IDLE   err=101

Unfortunately, I don't know enough about IPSec and Certificate exchange to know what is the normal processes of connection negotiation.

According to Android though, looks like things are falling apart during Phase 2.
Cancel
Vote Up 0 Vote Down

Cancel
0 d12fk over 14 years ago in reply to coreno

Doesn't look much different with Parsing Debug enabled, and looks "normal" still, up until "no connection known". Trimmed some fat from the top and bottom of the log for post-length's sake.

The fat parts might be the interesting ones. In this case I'd need to see the first message in Quick Mode from the phone, as that one contains the proposals for phase 2. Could you post it, please?
Cancel
Vote Up 0 Vote Down

Cancel
0 coreno over 14 years ago in reply to d12fk

Don't I feel silly now [:P]

Here ya go, unaltered log: 2010:09:28-09:35:40 ASG8 pluto - Coreno - Tr47GMH0 - Pastebin.com
Cancel
Vote Up 0 Vote Down

Cancel
0 d12fk over 14 years ago in reply to coreno

Could it be possible that you have an enabled IPsec remote access connection called "Android" on the ASG? If so, please disable it and retry connecting via L2TP. I suspect they are equal enough for pluto to confuse the one with the other. That would explain the expected address from "VPN Pool (IPSec)" as well.

Edit: oh, and stop feeling silly, now! =)
Cancel
Vote Up 0 Vote Down

Cancel
0 coreno over 14 years ago in reply to d12fk

I did have an IPSec rule called Android. I deleted it and created a new one called Test, adn the results were the same. Here's the log output though in case I overlooked something.

P.S. thanks for the help so far. Hopefully we can get this working [:)]
Cancel
Vote Up 0 Vote Down

Cancel
0 d12fk over 14 years ago in reply to coreno

You don't need an extra IPsec connection if you want to use L2TP for remote access. If you don't need it for other clients you can delete it completely.
Cancel
Vote Up 0 Vote Down

Cancel
0 coreno over 14 years ago in reply to d12fk

Really?

When I delete everything from the IPSec connections, I don't see anything show up in the IPSec VPN log when I try to connect.

Is there something else I should make sure is enabled instead?

In L2TP over IPSec settings, interface I have set to External (WAN) which is a 192.168.1.x network, auth mode X509 Cert, and I have the Local X509 Cert selected, assign by IP Address Pool (VPN Pool IPSec), and just the one user i'm trying to log in as in the users and groups access control, authenticating locally.

Android wants a User certificate, which I've installed and selected the certificate of the user I'm trying to log on as, and a CA certificate, which I've installed the VPN Signing CA from the Certificate Management section.
Cancel
Vote Up 0 Vote Down

Cancel

Reply

0 coreno over 14 years ago in reply to d12fk

Really?

When I delete everything from the IPSec connections, I don't see anything show up in the IPSec VPN log when I try to connect.

Is there something else I should make sure is enabled instead?

In L2TP over IPSec settings, interface I have set to External (WAN) which is a 192.168.1.x network, auth mode X509 Cert, and I have the Local X509 Cert selected, assign by IP Address Pool (VPN Pool IPSec), and just the one user i'm trying to log in as in the users and groups access control, authenticating locally.

Android wants a User certificate, which I've installed and selected the certificate of the user I'm trying to log on as, and a CA certificate, which I've installed the VPN Signing CA from the Certificate Management section.
Cancel
Vote Up 0 Vote Down

Cancel

Children

No Data