Thread Info
  • State Not Answered
  • Locked Locked
  • Replies 35 replies
  • Subscribers 1 subscriber
  • Views 41684 views
  • Users 0 members are here
Options
Suggested
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

coreno
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.
  • 0
    Generate a new certificate on the ASG with a VPN ID type of "IP address" and the value "192.168.1.139" and assign that certificate to the user you are testing with. User certificates use the E-Mail address as VPN ID by default. You could of course change the VPN ID on the Android device as well, if that's an option.
  • 0 in reply to d12fk
    I did that, and made sure my Android phone had the proper certificates installed, and at least getting different error logs.

    Looks like this time the issue is on the ASG side... "no connection known for....." which I'm not sure I know why that is.

    Posted on 2nd post because I was just over the character limit.
  • 0
    2010:09:26-23:19:24 ASG8 pluto[10531]: | *received 352 bytes from 192.168.1.139:500 on eth1
    2010:09:26-23:19:24 ASG8 pluto[10531]: | preparse_isakmp_policy: peer requests PUBKEY authentication
    2010:09:26-23:19:24 ASG8 pluto[10531]: | creating state object #9 at 0x8e83ef0
    2010:09:26-23:19:24 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:24 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:24 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:24 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:24 ASG8 pluto[10531]: | inserting event EVENT_SO_DISCARD, timeout in 0 seconds for #9
    2010:09:26-23:19:24 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: responding to Main Mode from unknown peer 192.168.1.139
    2010:09:26-23:19:24 ASG8 pluto[10531]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #9
    2010:09:26-23:19:24 ASG8 pluto[10531]: | next event EVENT_RETRANSMIT in 10 seconds for #9
    2010:09:26-23:19:24 ASG8 pluto[10531]: |
    2010:09:26-23:19:24 ASG8 pluto[10531]: | *received 228 bytes from 192.168.1.139:500 on eth1
    2010:09:26-23:19:24 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:24 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:24 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:24 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:24 ASG8 pluto[10531]: | state object #9 found, in STATE_MAIN_R1
    2010:09:26-23:19:24 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: NAT-Traversal: Result using RFC 3947: no NAT detected
    2010:09:26-23:19:24 ASG8 pluto[10531]: | inserting event EVENT_NAT_T_KEEPALIVE, timeout in 60 seconds
    2010:09:26-23:19:24 ASG8 pluto[10531]: | inserting event EVENT_RETRANSMIT, timeout in 10 seconds for #9
    2010:09:26-23:19:24 ASG8 pluto[10531]: | next event EVENT_RETRANSMIT in 10 seconds for #9
    2010:09:26-23:19:24 ASG8 pluto[10531]: |
    2010:09:26-23:19:24 ASG8 pluto[10531]: | *received 1244 bytes from 192.168.1.139:500 on eth1
    2010:09:26-23:19:24 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:24 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:24 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:24 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:24 ASG8 pluto[10531]: | state object #9 found, in STATE_MAIN_R2
    2010:09:26-23:19:24 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: Peer ID is ID_IPV4_ADDR: '192.168.1.139'
    2010:09:26-23:19:24 ASG8 pluto[10531]: | subject: 'C=us, L=*****, O=*****'
    2010:09:26-23:19:24 ASG8 pluto[10531]: | issuer: 'C=us, L=*****, O=*****, CN=***** VPN CA, E=*****@gmail.com'
    2010:09:26-23:19:24 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-23:19:24 ASG8 pluto[10531]: | certificate is valid
    2010:09:26-23:19:24 ASG8 pluto[10531]: | issuer cacert found
    2010:09:26-23:19:24 ASG8 pluto[10531]: | certificate signature is valid
    2010:09:26-23:19:24 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: crl not found
    2010:09:26-23:19:24 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: certificate status unknown
    2010:09:26-23:19:24 ASG8 pluto[10531]: | subject: 'C=us, L=*****, O=*****, CN=***** VPN CA, E=*****@gmail.com'
    2010:09:26-23:19:24 ASG8 pluto[10531]: | issuer: 'C=us, L=*****, O=*****, CN=***** VPN CA, E=*****@gmail.com'
    2010:09:26-23:19:24 ASG8 pluto[10531]: | certificate is valid
    2010:09:26-23:19:24 ASG8 pluto[10531]: | issuer cacert found
    2010:09:26-23:19:24 ASG8 pluto[10531]: | certificate signature is valid
    2010:09:26-23:19:24 ASG8 pluto[10531]: | reached self-signed root ca with a path length of 0
    2010:09:26-23:19:24 ASG8 pluto[10531]: | RSA signature check passed with keyid 52:ac:32:a0:8a:59:7c:7c:1e:b2:e7:bd:f9:32:a5:25:7e:60:9d:4c
    2010:09:26-23:19:24 ASG8 pluto[10531]: | peer CA: "C=us, L=*****, O=*****, CN=***** VPN CA, E=*****@gmail.com"
    2010:09:26-23:19:24 ASG8 pluto[10531]: | requested CA: %any
    2010:09:26-23:19:24 ASG8 pluto[10531]: | current connection is a full match -- no need to look further
    2010:09:26-23:19:24 ASG8 pluto[10531]: | offered CA: "C=us, L=*****, O=*****, CN=***** VPN CA, E=*****@gmail.com"
    2010:09:26-23:19:24 ASG8 pluto[10531]: | our certificate policy is ALWAYS_SEND
    2010:09:26-23:19:24 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: we have a cert and are sending it
    2010:09:26-23:19:24 ASG8 pluto[10531]: | inserting event EVENT_SA_REPLACE, timeout in 7530 seconds for #9
    2010:09:26-23:19:24 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: sent MR3, ISAKMP SA established
    2010:09:26-23:19:24 ASG8 pluto[10531]: | next event EVENT_NAT_T_KEEPALIVE in 60 seconds
    2010:09:26-23:19:24 ASG8 pluto[10531]: |
    2010:09:26-23:19:24 ASG8 pluto[10531]: | *received 92 bytes from 192.168.1.139:500 on eth1
    2010:09:26-23:19:24 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:24 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:24 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:24 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:24 ASG8 pluto[10531]: | state object #9 found, in STATE_MAIN_R3
    2010:09:26-23:19:24 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: ignoring informational payload, type IPSEC_INITIAL_CONTACT
    2010:09:26-23:19:24 ASG8 pluto[10531]: | next event EVENT_NAT_T_KEEPALIVE in 60 seconds
    2010:09:26-23:19:25 ASG8 pluto[10531]: |
    2010:09:26-23:19:25 ASG8 pluto[10531]: | *received 284 bytes from 192.168.1.139:500 on eth1
    2010:09:26-23:19:25 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:25 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:25 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:25 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:25 ASG8 pluto[10531]: | state object not found
    2010:09:26-23:19:25 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:25 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:25 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:25 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:25 ASG8 pluto[10531]: | state object #9 found, in STATE_MAIN_R3
    2010:09:26-23:19:25 ASG8 pluto[10531]: | peer client is 192.168.1.139
    2010:09:26-23:19:25 ASG8 pluto[10531]: | peer client protocol/port is 17/0
    2010:09:26-23:19:25 ASG8 pluto[10531]: | our client is 192.168.1.154
    2010:09:26-23:19:25 ASG8 pluto[10531]: | our client protocol/port is 17/1701
    2010:09:26-23:19:25 ASG8 pluto[10531]: | no valid attribute cert found
    2010:09:26-23:19:25 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: 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:26-23:19:25 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: sending encrypted notification INVALID_ID_INFORMATION to 192.168.1.139:500
    2010:09:26-23:19:25 ASG8 pluto[10531]: | state transition function for STATE_QUICK_R0 failed: INVALID_ID_INFORMATION
    2010:09:26-23:19:25 ASG8 pluto[10531]: | next event EVENT_NAT_T_KEEPALIVE in 59 seconds
    2010:09:26-23:19:35 ASG8 pluto[10531]: |
    2010:09:26-23:19:35 ASG8 pluto[10531]: | *received 284 bytes from 192.168.1.139:500 on eth1
    2010:09:26-23:19:35 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:35 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:35 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:35 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:35 ASG8 pluto[10531]: | state object not found
    2010:09:26-23:19:35 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:35 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:35 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:35 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:35 ASG8 pluto[10531]: | state object #9 found, in STATE_MAIN_R3
    2010:09:26-23:19:35 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: Quick Mode I1 message is unacceptable because it uses a previously used Message ID 0xf0cf53da (perhaps this is a duplicated packet)
    2010:09:26-23:19:35 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: sending encrypted notification INVALID_MESSAGE_ID to 192.168.1.139:500
    2010:09:26-23:19:35 ASG8 pluto[10531]: | next event EVENT_NAT_T_KEEPALIVE in 49 seconds
    2010:09:26-23:19:45 ASG8 pluto[10531]: |
    2010:09:26-23:19:45 ASG8 pluto[10531]: | *received 284 bytes from 192.168.1.139:500 on eth1
    2010:09:26-23:19:45 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:45 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:45 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:45 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:45 ASG8 pluto[10531]: | state object not found
    2010:09:26-23:19:45 ASG8 pluto[10531]: | ICOOKIE: d8 3d 75 0c 6d 6c 6d 37
    2010:09:26-23:19:45 ASG8 pluto[10531]: | RCOOKIE: 79 a2 88 43 b9 dd b2 42
    2010:09:26-23:19:45 ASG8 pluto[10531]: | peer: c0 a8 01 8b
    2010:09:26-23:19:45 ASG8 pluto[10531]: | state hash entry 29
    2010:09:26-23:19:45 ASG8 pluto[10531]: | state object #9 found, in STATE_MAIN_R3
    2010:09:26-23:19:45 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: Quick Mode I1 message is unacceptable because it uses a previously used Message ID 0xf0cf53da (perhaps this is a duplicated packet)
    2010:09:26-23:19:45 ASG8 pluto[10531]: "D_Android"[3] 192.168.1.139 #9: sending encrypted notification INVALID_MESSAGE_ID to 192.168.1.139:500
    2010:09:26-23:19:45 ASG8 pluto[10531]: | next event EVENT_NAT_T_KEEPALIVE in 39 seconds
  • 0 in reply to coreno
    This error messages looks like the Android is proposing a local subnet that is equal to the IPsec Pool on the ASG:


    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)


    L2TP normally uses Transport Mode, so it is really weird that there is a client network involved in proposals. Maybe Android is broken?!
  • 0
    I could verify this if you'd post a log snippet with the "Parsing" debug level enabled
  • 0
    Coreno, in the L2TP configuration, have you selected to 'Assign addresses by' "IP address pool" with 'Pool network' "VPN Pool (L2TP)"?

    In the later versions of V7, assigning IP addresses with the same DHCP service as the LAN causes problems.  Perhaps d12fk can tell us if there's still an issue with that in V8.

    Cheers - Bob
  • 0 in reply to BAlfson

    In the later versions of V7, assigning IP addresses with the same DHCP service as the LAN causes problems.  Perhaps d12fk can tell us if there's still an issue with that in V8.


    Frankly, I've never heard about this kind of problem. Please elaborate or point me to the right thread.
  • 0
    -----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
  • 0 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. =)
  • 0 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