Monday, October 3, 2011

[android-developers] VPN Connectivity using android.net.vpn apis

I'm trying to build a VPN application by downloading android.net.vpn
files from Android source repository. I managed to build a jar file
and when I tried to write an app to connect to VPN, it seems to be
failing. I have tried PPTP, L2TP IPSEC PSK and L2TP IPSEC CRT
unsuccessfully.

- With L2TP IPSEC PSK, I see that the connection will get established
momentarily in the DDMS monitor, and then immediately it will be
followed by a disconnect event.
- With PPTP I cannot even get a connect event, it starts connecting
and then I immediately get a disconnect event.
- With L2TP IPSEC CRT, I tried loading a pkcs12 certificate and the
connection always fails with "unable to load own CERT" message. I have
the certificate copied onto root of SDcard and I used KeyStore APIs to
load the cert, and it was loading without any errors.

Has anyone succesfully managed to establish a VPN connection? If so,
please let me know if I need to do anything more than using the above
APIs. If I can atleast get one of the above methods working, then I
can go from there and ultimately I would need the L2TP IPSEC CRT to
work.

I came across this post that talked about a patch that helped the user
connect to a PPTP VPN profile.
http://groups.google.com/group/android-developers/browse_thread/thread/9a9d9c888521479

I'm unable to figure out what exactly the patch was..


Below is the DDMS log output when trying to establish a L2TP IPSEC PSK
vpn connection. mtpd (VPN Dameon) seems to be timing out each time..
Finally VpnService fails with connection timeout IOException..

09-29 09:24:05.810: WARN/dalvikvm(842): PGC: map but no entry for Lcom/
boingo/boingowifi/BoingoMainActivity;.displayHelpPage addr=0x0027
09-29 09:24:05.810: DEBUG/dalvikvm(842): threadid=1: still suspended
after undo (sc=1 dc=1)
09-29 09:24:05.960: DEBUG/dalvikvm(842): threadid=1: still suspended
after undo (sc=1 dc=1)
09-29 09:24:06.020: DEBUG/dalvikvm(842): GC_CONCURRENT freed 1574K,
49% free 4746K/9223K, external 4775K/5757K, paused 3ms+3ms
09-29 09:24:14.950: DEBUG/goldpricewidget(578): price cache still
valid: 2
09-29 09:24:15.060: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:24:15.970: DEBUG/dalvikvm(842): GC_CONCURRENT freed 1748K,
46% free 4999K/9223K, external 4775K/5757K, paused 4ms+3ms
09-29 09:24:24.810: DEBUG/goldpricewidget(578): price cache still
valid: 2
09-29 09:24:24.810: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:24:25.060: DEBUG/dalvikvm(842): GC_CONCURRENT freed 2440K,
52% free 4562K/9479K, external 4775K/5757K, paused 3ms+4ms
09-29 09:24:33.450: DEBUG/GTalkService(657): [GTalkConnection.1]
setInternalNetworkState: type=1, state=CONNECTED
09-29 09:24:35.020: DEBUG/goldpricewidget(578): price cache still
valid: 2
09-29 09:24:35.160: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:24:35.470: DEBUG/dalvikvm(842): GC_CONCURRENT freed 1529K,
48% free 4972K/9479K, external 4775K/5757K, paused 3ms+3ms
09-29 09:24:41.380: DEBUG/dalvikvm(235): GC_EXPLICIT freed 29K, 49%
free 2951K/5767K, external 1625K/2137K, paused 1930ms
09-29 09:24:41.940: DEBUG/dalvikvm(657): GC_CONCURRENT freed 628K, 48%
free 3525K/6727K, external 1625K/2137K, paused 2ms+3ms
09-29 09:24:45.350: DEBUG/goldpricewidget(578): price cache still
valid: 2
09-29 09:24:45.420: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:24:46.550: DEBUG/dalvikvm(842): GC_CONCURRENT freed 1506K,
43% free 5417K/9479K, external 4775K/5757K, paused 3ms+3ms
09-29 09:24:49.760: DEBUG/dalvikvm(657): GC_CONCURRENT freed 689K, 48%
free 3552K/6727K, external 1625K/2137K, paused 2ms+8ms
09-29 09:24:51.320: DEBUG/GTalkService(657): [RosterListenerImpl]
removeTalkPresence for account=1, deleted=0
09-29 09:24:51.850: DEBUG/GTalkService(657): [ContactPresence]
removeAllContactsPresence: account=1, set null presence for 0
09-29 09:24:54.070: DEBUG/GTalkService(657): [RosterMgr] roster not
modified
09-29 09:24:54.820: DEBUG/goldpricewidget(578): price cache still
valid: 2
09-29 09:24:54.820: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:24:55.130: DEBUG/dalvikvm(842): GC_CONCURRENT freed 2477K,
51% free 4924K/9863K, external 4775K/5757K, paused 3ms+3ms
09-29 09:24:55.350: DEBUG/GTalkService(657): [OtrMgr] OTR not modified
09-29 09:25:04.880: DEBUG/goldpricewidget(578): price cache still
valid: 2
09-29 09:25:04.920: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:25:14.810: DEBUG/goldpricewidget(578): price cache still
valid: 3
09-29 09:25:14.820: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:25:21.260: INFO/ActivityManager(96): Start proc
com.android.server.vpn:remote for service
com.android.server.vpn/.VpnServiceBinder: pid=876 uid=1000 gids={3002,
3001, 3003}
09-29 09:25:21.330: DEBUG/dalvikvm(67): GC_EXPLICIT freed 11K, 50%
free 2717K/5379K, external 1625K/2137K, paused 64ms
09-29 09:25:21.380: DEBUG/dalvikvm(67): GC_EXPLICIT freed <1K, 50%
free 2717K/5379K, external 1625K/2137K, paused 41ms
09-29 09:25:21.400: DEBUG/dalvikvm(67): GC_EXPLICIT freed <1K, 50%
free 2717K/5379K, external 1625K/2137K, paused 26ms
09-29 09:25:23.279: DEBUG/VpnManager(842): succeeded to connect to VPN
service
09-29 09:25:24.810: DEBUG/goldpricewidget(578): price cache still
valid: 3
09-29 09:25:24.810: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:25:26.230: INFO/SProxy_mtpd(876): Stop VPN daemon: mtpd
09-29 09:25:26.240: DEBUG/SProxy_mtpd(876): mtpd is stopped after 0
msec
09-29 09:25:26.240: DEBUG/SProxy_mtpd(876): stopping mtpd, success?
true
09-29 09:25:26.240: INFO/SProxy_racoon(876): Stop VPN daemon: racoon
09-29 09:25:26.240: DEBUG/SProxy_racoon(876): racoon is stopped after
0 msec
09-29 09:25:26.240: DEBUG/SProxy_racoon(876): stopping racoon,
success? true
09-29 09:25:26.390: DEBUG/VpnService(876): Local IP: 192.168.1.71,
if: eth0
09-29 09:25:26.400: DEBUG/VpnService(876): VPN UP: down
09-29 09:25:26.400: INFO/SProxy_racoon(876): Start VPN daemon: racoon
09-29 09:25:26.400: DEBUG/SProxy_racoon(876): racoon is running after
0 msec
09-29 09:25:26.400: DEBUG/SProxy_racoon(876): service not yet
listen()ing; try again
09-29 09:25:26.420: DEBUG/racoon(884): Waiting for control socket
09-29 09:25:26.910: DEBUG/racoon(884): Received 5 arguments
09-29 09:25:26.910: INFO/racoon(884): ipsec-tools 0.7.3 (http://ipsec-
tools.sf.net)
09-29 09:25:26.980: INFO/racoon(884): 192.168.1.71[500] used as isakmp
port (fd=10)
09-29 09:25:26.980: INFO/racoon(884): 192.168.1.71[500] used for NAT-T
09-29 09:25:26.980: INFO/racoon(884): 192.168.1.71[4500] used as
isakmp port (fd=11)
09-29 09:25:26.980: INFO/racoon(884): 192.168.1.71[4500] used for NAT-
T
09-29 09:25:26.980: INFO/SProxy_racoon(876): got data from control
socket: 5
09-29 09:25:28.980: INFO/SProxy_mtpd(876): Start VPN daemon: mtpd
09-29 09:25:28.990: DEBUG/SProxy_mtpd(876): mtpd is running after 0
msec
09-29 09:25:28.990: DEBUG/SProxy_mtpd(876): service not yet
listen()ing; try again
09-29 09:25:29.000: DEBUG/mtpd(1242): Waiting for control socket
09-29 09:25:29.489: DEBUG/mtpd(1242): Received 19 arguments
09-29 09:25:29.489: INFO/mtpd(1242): Using protocol l2tp
09-29 09:25:29.489: INFO/mtpd(1242): Connecting to 75.101.147.33 port
1701
09-29 09:25:29.489: INFO/mtpd(1242): Connection established (socket =
11)
09-29 09:25:29.489: INFO/SProxy_mtpd(876): got data from control
socket: 19
09-29 09:25:29.500: DEBUG/mtpd(1242): Sending SCCRQ (local_tunnel =
49392)
09-29 09:25:29.500: INFO/racoon(884): no in-bound policy found:
75.101.147.33/32[1701] 192.168.1.71/32[0] proto=udp dir=in
09-29 09:25:29.500: INFO/racoon(884): IPsec-SA request for
75.101.147.33 queued due to no phase1 found.
09-29 09:25:29.500: INFO/racoon(884): initiate new phase 1
negotiation: 192.168.1.71[500]<=>75.101.147.33[500]
09-29 09:25:29.500: INFO/racoon(884): begin Identity Protection mode.
09-29 09:25:29.600: INFO/racoon(884): received Vendor ID: RFC 3947
09-29 09:25:29.600: INFO/racoon(884): received Vendor ID: DPD
09-29 09:25:29.600: INFO/racoon(884): received broken Microsoft ID:
FRAGMENTATION
09-29 09:25:29.600: INFO/racoon(884): Selected NAT-T version: RFC 3947
09-29 09:25:29.670: INFO/racoon(884): Hashing 75.101.147.33[500] with
algo #2
09-29 09:25:29.670: INFO/racoon(884): Hashing 192.168.1.71[500] with
algo #2
09-29 09:25:29.670: INFO/racoon(884): Adding remote and local NAT-D
payloads.
09-29 09:25:29.760: INFO/racoon(884): Hashing 192.168.1.71[500] with
algo #2
09-29 09:25:29.760: INFO/racoon(884): NAT-D payload #0 doesn't match
09-29 09:25:29.760: INFO/racoon(884): Hashing 75.101.147.33[500] with
algo #2
09-29 09:25:29.760: INFO/racoon(884): NAT-D payload #1 doesn't match
09-29 09:25:29.760: INFO/racoon(884): NAT detected: ME PEER
09-29 09:25:29.760: INFO/racoon(884): KA list add: 192.168.1.71[4500]-
>75.101.147.33[4500]
09-29 09:25:29.810: INFO/keystore(72): uid: 1016 action: g -> 2 state:
2 -> 2 retry: 4
09-29 09:25:29.810: ERROR/racoon(884): failed to get my CERT.
09-29 09:25:29.810: ERROR/racoon(884): failed to get own CERT.
09-29 09:25:29.810: ERROR/racoon(884): failed get my ID
09-29 09:25:29.810: ERROR/racoon(884): failed to process packet.
09-29 09:25:29.810: ERROR/racoon(884): phase1 negotiation failed.
09-29 09:25:29.810: INFO/racoon(884): KA remove: 192.168.1.71[4500]-
>75.101.147.33[4500]
09-29 09:25:29.890: DEBUG/BoingoMainActivity(842): onReceive() - Got
action = vpn.connectivity
09-29 09:25:31.500: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:33.500: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:34.370: WARN/InputManagerService(96): Window already
focused, ignoring focus gain of:
com.android.internal.view.IInputMethodClient$Stub$Proxy@40619de8
09-29 09:25:35.500: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:37.499: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:39.510: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:41.510: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:43.510: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:45.510: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:47.510: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:49.510: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:51.519: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:53.520: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:54.800: DEBUG/goldpricewidget(578): price cache still
valid: 3
09-29 09:25:54.810: DEBUG/goldpricewidget(578): updating widget: 7
09-29 09:25:55.520: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:57.519: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:25:59.520: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:26:00.839: ERROR/racoon(884): phase2 negotiation failed due
to time up waiting for phase1. ESP 75.101.147.33[0]->192.168.1.71[0]
09-29 09:26:00.839: INFO/racoon(884): delete phase 2 handler.
09-29 09:26:00.839: INFO/racoon(884): Bye
09-29 09:26:01.530: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:26:03.529: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:26:05.530: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:26:07.529: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:26:09.530: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:26:11.539: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:26:11.539: ERROR/VpnService(876): onError()
09-29 09:26:11.539: ERROR/VpnService(876): java.io.IOException:
Connecting timed out
09-29 09:26:11.539: ERROR/VpnService(876): at
com.android.server.vpn.VpnService.waitUntilConnectedOrTimedout(VpnService.java:
206)
09-29 09:26:11.539: ERROR/VpnService(876): at
com.android.server.vpn.VpnService.onConnect(VpnService.java:136)
09-29 09:26:11.539: ERROR/VpnService(876): at
com.android.server.vpn.VpnServiceBinder$2.run(VpnServiceBinder.java:
117)
09-29 09:26:11.539: ERROR/VpnService(876): at
java.lang.Thread.run(Thread.java:1019)
09-29 09:26:11.539: INFO/VpnService(876): disconnecting VPN...
09-29 09:26:11.550: DEBUG/BoingoMainActivity(842): onReceive() - Got
action = vpn.connectivity
09-29 09:26:11.660: DEBUG/dalvikvm(96): GC_EXPLICIT freed 992K, 42%
free 6107K/10503K, external 5076K/6328K, paused 91ms
09-29 09:26:11.680: INFO/SProxy_mtpd(876): Stop VPN daemon: mtpd
09-29 09:26:11.680: DEBUG/mtpd(1242): Timeout -> Sending SCCRQ
09-29 09:26:11.680: INFO/mtpd(1242): Received signal 15
09-29 09:26:11.680: DEBUG/mtpd(1242): Sending STOPCCN
09-29 09:26:11.680: INFO/mtpd(1242): Mtpd is terminated (status = 6)
09-29 09:26:11.680: DEBUG/SProxy_mtpd(876): mtpd is stopped after 0
msec
09-29 09:26:11.680: DEBUG/SProxy_mtpd(876): stopping mtpd, success?
true
09-29 09:26:11.680: INFO/SProxy_racoon(876): Stop VPN daemon: racoon
09-29 09:26:11.680: DEBUG/SProxy_racoon(876): racoon is stopped after
0 msec
09-29 09:26:11.680: DEBUG/SProxy_racoon(876): stopping racoon,
success? true
09-29 09:26:11.680: DEBUG/VpnService(876): onFinalCleanUp()
09-29 09:26:11.680: INFO/VpnService(876): restore original suffices --
> null


thanks..

--
You received this message because you are subscribed to the Google
Groups "Android Developers" group.
To post to this group, send email to android-developers@googlegroups.com
To unsubscribe from this group, send email to
android-developers+unsubscribe@googlegroups.com
For more options, visit this group at
http://groups.google.com/group/android-developers?hl=en

No comments:

Post a Comment