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.

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

0 d12fk over 14 years ago

We're getting on the right track here. Could you check if the two processes "pluto" and "openl2tpd" are there when you have L2TP enabled. Go to "Support >> Advanced" in WebAdmin to see the process list. It should contain entries like


root      6797  0.0  0.0   2232   800 ?        Ss   Sep14   0:00 /usr/libexec/ipsec/starter

root      6799  0.0  0.3  12308  3460 ?       Ss   Sep14   0:22  \_ /usr/libexec/ipsec/pluto

root      6931  0.0  0.0   1748   320 ?         S    Sep14   0:00      \_ _pluto_adns

root     25747  0.0  0.0   2108   748 ?        S    Sep17   2:26 /usr/sbin/openl2tpd

If not, please do a `tail -f /var/log/mdw-debug.log` in a root shell when you start L2TP and attach the output here.

0 coreno over 14 years ago in reply to d12fk

I disabled and then enabled L2TP over IPSec

ASG8:/root # tail -f /var/log/mdw-debug.log
2010:09:29-12:14:01 ASG8 middleware[4397]: T core::Config::Changed:131() => configversion=112
2010:09:29-12:14:01 ASG8 middleware[4397]: T core::Config::Changed:141() => nodes=3 objects=0 triggers=0
2010:09:29-12:14:01 ASG8 middleware[4397]: T core::Config::load:265() => modules=3,2
2010:09:29-12:14:01 ASG8 middleware[4397]: D core::Config::load:273() => ssh.obj (ssh->root_keys.conf,ssh->pubkey_auth.conf,ssh->root_login.conf)
2010:09:29-12:14:01 ASG8 middleware[4397]: D utils::Exec::SystemCall:32() => /etc/init.d/sshd reload
2010:09:29-12:14:01 ASG8 middleware[4397]: :: Reload SSH..done
2010:09:29-12:14:01 ASG8 middleware[4397]: D core::Config::load:273() => ssh.adapter.obj (ssh->root_keys.conf,ssh->pubkey_auth.conf,ssh->root_login.conf)
2010:09:29-12:14:01 ASG8 middleware[4397]: D utils::Exec::ForkingSystem:99() => CHILD 2 FORK 29504 /usr/local/bin/ipt_clear_confirmed.sh
2010:09:29-12:14:01 ASG8 middleware[4397]: T main::top-level:202() => ending cycle 110, caught 0 signals
2010:09:29-12:14:01 ASG8 middleware[4397]: D utils::Exec::BuryChildren:107() => CHILD 2 EXIT 29504 /usr/local/bin/ipt_clear_confirmed.sh
2010:09:29-12:21:27 ASG8 middleware[4397]: T main::top-level:171() => starting cycle 111, caught 1 signals
2010:09:29-12:21:27 ASG8 middleware[4397]: T core::Config::Changed:131() => configversion=113
2010:09:29-12:21:27 ASG8 middleware[4397]: T core::Config::Changed:141() => nodes=0 objects=1 triggers=0
2010:09:29-12:21:27 ASG8 middleware[4397]: T core::Config::load:265() => modules=2,5
2010:09:29-12:21:27 ASG8 middleware[4397]: D core::Config::load:273() => user_authentication.obj (ipsec_connection->l2tp->status.cobj)
2010:09:29-12:21:28 ASG8 middleware[4397]: D core::Config::ConfdCall:467() => may(CB)
2010:09:29-12:21:28 ASG8 middleware[4397]: D core::Config::ConfdCall:467() => may(DM)
2010:09:29-12:21:28 ASG8 middleware[4397]: portal enabled, allow_any on
2010:09:29-12:21:28 ASG8 middleware[4397]: D core::Config::ConfdCall:467() => may(DN)
2010:09:29-12:21:28 ASG8 middleware[4397]: D core::Config::ConfdCall:467() => may(DW)
2010:09:29-12:21:28 ASG8 middleware[4397]: D core::Config::load:273() => ipsec.obj (remote_access->l2tp.conf)
2010:09:29-12:21:28 ASG8 middleware[4397]: D core::Config::load:273() => executive_report.obj (remote_access->l2tp.conf)
2010:09:29-12:21:28 ASG8 middleware[4397]: D core::Config::load:273() => afc.adapter.obj (ipsec.obj)
2010:09:29-12:21:28 ASG8 middleware[4397]: D core::Config::load:273() => ipsec.adapter.obj (ipsec.obj)
2010:09:29-12:21:28 ASG8 middleware[4397]: EBTables: /usr/sbin/ebtables -t nat -F PREROUTING
2010:09:29-12:21:28 ASG8 middleware[4397]: D utils::Exec::SystemCall:32() => /usr/sbin/ebtables -t nat -F PREROUTING
2010:09:29-12:21:28 ASG8 middleware[4397]: D utils::Exec::ForkingSystem:99() => CHILD 2 FORK 29868 /usr/local/bin/ipt_clear_confirmed.sh
2010:09:29-12:21:28 ASG8 middleware[4397]: T main::top-level:202() => ending cycle 111, caught 0 signals
2010:09:29-12:21:28 ASG8 middleware[4397]: D utils::Exec::BuryChildren:107() => CHILD 2 EXIT 29868 /usr/local/bin/ipt_clear_confirmed.sh
2010:09:29-12:21:32 ASG8 middleware[4397]: T main::top-level:171() => starting cycle 112, caught 1 signals
2010:09:29-12:21:33 ASG8 middleware[4397]: T core::Config::Changed:131() => configversion=114
2010:09:29-12:21:33 ASG8 middleware[4397]: T core::Config::Changed:141() => nodes=0 objects=1 triggers=0
2010:09:29-12:21:33 ASG8 middleware[4397]: T core::Config::load:265() => modules=2,5
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::load:273() => user_authentication.obj (ipsec_connection->l2tp->status.cobj)
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::ConfdCall:467() => may(CB)
2010:09:29-12:21:33 ASG8 middleware[4397]: portal enabled, allow_any on
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::ConfdCall:467() => may(DM)
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::ConfdCall:467() => may(DN)
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::ConfdCall:467() => may(DW)
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::load:273() => ipsec.obj (remote_access->l2tp.conf)
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::load:273() => executive_report.obj (remote_access->l2tp.conf)
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::load:273() => afc.adapter.obj (ipsec.obj)
2010:09:29-12:21:33 ASG8 middleware[4397]: D core::Config::load:273() => ipsec.adapter.obj (ipsec.obj)
2010:09:29-12:21:33 ASG8 middleware[4397]: EBTables: /usr/sbin/ebtables -t nat -F PREROUTING
2010:09:29-12:21:33 ASG8 middleware[4397]: D utils::Exec::SystemCall:32() => /usr/sbin/ebtables -t nat -F PREROUTING
2010:09:29-12:21:33 ASG8 middleware[4397]: D utils::Exec::ForkingSystem:99() => CHILD 2 FORK 29881 /usr/local/bin/ipt_clear_confirmed.sh
2010:09:29-12:21:33 ASG8 middleware[4397]: T main::top-level:202() => ending cycle 112, caught 0 signals
2010:09:29-12:21:33 ASG8 middleware[4397]: D utils::Exec::BuryChildren:107() => CHILD 2 EXIT 29881 /usr/local/bin/ipt_clear_confirmed.sh
Cancel
Vote Up 0 Vote Down

Cancel
0 d12fk over 14 years ago

Hah! It's a bug in mdw. L2TP doesn't get started when certificate based authentication is selected.
Will be fixed it in 8.004. Bug ID is #15216. Thanks for the help finding it.

Now back to your actual problem. Let's make L2TP/PSK work for you until 8.004 is publically available. Could you post the complete IPsec log output with L2TP debug enabled when you connect with your Droid and L2TP/PSK configured?
Cancel
Vote Up 0 Vote Down

Cancel