VPN: L2TP: always timeout when Sending SCCRQ

[Jiejing.Zhang]

Hi All,

Hi Chia-CHi Yeh, I cc you since I found your kernel commit which is enable VPN stuff.

I'm doing enable VPN function in an android froyo/gingerbread porting.
After apply android pppol2tp, pppopptp related patch in android/common.git, I can success enable PPTP protocol, but I meet problem with L2TP profile.

My error is:
mtpd is keeping print error like this, then the connection will timeout

D/mtpd    ( 3020): Timeout -> Sending SCCRQ
D/mtpd    ( 3020): Timeout -> Sending SCCRQ

but SCCRQ in PPTP profile in return quite fast,
(I tested in Samsung 's Galax tab with same account and website, it works with L2TP profile)

So, I'm suspecting maybe I missed some patch in kernel or some patch needed, can anyone give some suggestion ?

Below is full vpn enable log:

D/VpnManager( 2336): succeeded to connect to VPN service
I/SProxy_mtpd( 2603): Stop VPN daemon: mtpd
D/SProxy_mtpd( 2603): mtpd is stopped after 0 msec
D/SProxy_mtpd( 2603): stopping mtpd, success? true
I/SProxy_racoon( 2603): Stop VPN daemon: racoon
D/SProxy_racoon( 2603): racoon is stopped after 0 msec
D/SProxy_racoon( 2603): stopping racoon, success? true
D/VpnService( 2603):   Local IP: 172.21.229.212, if: ppp0
D/VpnService( 2603):        VPN UP: down
I/SProxy_mtpd( 2603): Start VPN daemon: mtpd
D/mtpd    ( 3022): Waiting for control socket
D/com.android.settings.vpn.AuthenticationActor( 2336): ~~~~~~ connect() succeede
d!
D/VpnSettings( 2336): received connectivity: S2lt: connected? CONNECTING   err=0
D/SProxy_mtpd( 2603): mtpd is running after 200 msec
D/mtpd    ( 3022): Received 19 arguments
I/mtpd    ( 3022): Using protocol l2tp
I/mtpd    ( 3022): Connecting to 178.18.17.149 port 1701
I/mtpd    ( 3022): Connection established (socket = 11)
D/mtpd    ( 3022): Sending SCCRQ (local_tunnel = 10642)
I/SProxy_mtpd( 2603): got data from control socket: 19
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/dalvikvm( 2603): GC_EXPLICIT freed 1251 objects / 62352 bytes in 29ms
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
E/VpnService( 2603): onError()
E/VpnService( 2603): java.io.IOException: Connecting timed out
E/VpnService( 2603):    at com.android.server.vpn.VpnService.waitUntilConnectedO
rTimedout(VpnService.java:206)
E/VpnService( 2603):    at com.android.server.vpn.VpnService.onConnect(VpnServic
e.java:136)
E/VpnService( 2603):    at com.android.server.vpn.VpnServiceBinder$2.run(VpnServ
iceBinder.java:114)
E/VpnService( 2603):    at java.lang.Thread.run(Thread.java:1096)
I/VpnService( 2603): disconnecting VPN...
I/SProxy_mtpd( 2603): Stop VPN daemon: mtpd
D/mtpd    ( 3022): Timeout -> Sending SCCRQ
I/mtpd    ( 3022): Received signal 15
D/mtpd    ( 3022): Sending STOPCCN
I/mtpd    ( 3022): Mtpd is terminated (status = 6)
D/VpnSettings( 2336): received connectivity: S2lt: connected? DISCONNECTING   er
r=0
D/SProxy_mtpd( 2603): mtpd is stopped after 200 msec
D/SProxy_mtpd( 2603): stopping mtpd, success? true
I/SProxy_racoon( 2603): Stop VPN daemon: racoon
D/SProxy_racoon( 2603): racoon is stopped after 0 msec
D/SProxy_racoon( 2603): stopping racoon, success? true
D/VpnService( 2603): onFinalCleanUp()
I/VpnService( 2603): restore original suffices --> null
D/VpnSettings( 2336): received connectivity: S2lt: connected? IDLE   err=101

Thank you in advance!!!

BR,
Jiejing

Best regards,
Zhang Jiejing

[Jiejing.Zhang]

Hi All,

After apply this patch https://lkml.org/lkml/2011/1/2/82

pure l2tp VPN is working.

But I found L2TP+IPSec PSK, and L2TP+IPSec CRT profile is not working.

I can't capture any package in tcpdump, I suspect some crypto related config.
could you give me some suggestions ?

Thanks.


log is :

n
D/VpnManager( 2579): succeeded to connect to VPN service
I/SProxy_mtpd( 2570): Stop VPN daemon: mtpd
D/SProxy_mtpd( 2570): mtpd is stopped after 0 msec
D/SProxy_mtpd( 2570): stopping mtpd, success? true
I/SProxy_racoon( 2570): Stop VPN daemon: racoon
D/SProxy_racoon( 2570): racoon is stopped after 0 msec
D/SProxy_racoon( 2570): stopping racoon, success? true
D/com.android.settings.vpn.AuthenticationActor( 2579): ~~~~~~ connect() succeede
d!
D/VpnSettings( 2579): received connectivity: Psk: connected? CONNECTING   err=0
D/VpnService( 2570):   Local IP: 172.20.132.170, if: ppp0
D/VpnService( 2570):        VPN UP: down
I/SProxy_racoon( 2570): Start VPN daemon: racoon
D/racoon  ( 2619): Waiting for control socket
D/SProxy_racoon( 2570): racoon is running after 200 msec
D/racoon  ( 2619): Received 3 arguments
I/racoon  ( 2619): ipsec-tools 0.7.3 (http://ipsec-tools.sf.net)
I/racoon  ( 2619): 172.20.132.170[500] used as isakmp port (fd=10)
I/racoon  ( 2619): 172.20.132.170[500] used for NAT-T
I/racoon  ( 2619): 172.20.132.170[4500] used as isakmp port (fd=11)
I/racoon  ( 2619): 172.20.132.170[4500] used for NAT-T
I/SProxy_racoon( 2570): got data from control socket: 3
I/SProxy_mtpd( 2570): Start VPN daemon: mtpd
D/mtpd    ( 2884): Waiting for control socket
D/SProxy_mtpd( 2570): mtpd is running after 200 msec
D/mtpd    ( 2884): Received 19 arguments
I/mtpd    ( 2884): Using protocol l2tp
I/mtpd    ( 2884): Connecting to 178.18.17.149 port 1701
I/mtpd    ( 2884): Connection established (socket = 11)
D/mtpd    ( 2884): Sending SCCRQ (local_tunnel = 35596)
D/mtpd    ( 2884): sending package: 0xc6d0 with leng:69
I/racoon  ( 2619): no in-bound policy found: 178.18.17.149/32[1701] 172.20.132.1
70/32[0] proto=udp dir=in
I/racoon  ( 2619): IPsec-SA request for 178.18.17.149 queued due to no phase1 fo
und.
I/racoon  ( 2619): initiate new phase 1 negotiation: 172.20.132.170[500]<=>178.1
8.17.149[500]
I/racoon  ( 2619): begin Identity Protection mode.
I/SProxy_mtpd( 2570): got data from control socket: 19
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
E/racoon  ( 2619): phase2 negotiation failed due to time up waiting for phase1.
ESP 178.18.17.149[0]->172.20.132.170[0]
I/racoon  ( 2619): delete phase 2 handler.
I/racoon  ( 2619): Bye
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
E/VpnService( 2570): onError()
E/VpnService( 2570): java.io.IOException: Connecting timed out
E/VpnService( 2570):    at com.android.server.vpn.VpnService.waitUntilConnectedO
rTimedout(VpnService.java:206)
E/VpnService( 2570):    at com.android.server.vpn.VpnService.onConnect(VpnServic
e.java:136)
E/VpnService( 2570):    at com.android.server.vpn.VpnServiceBinder$2.run(VpnServ
iceBinder.java:114)
E/VpnService( 2570):    at java.lang.Thread.run(Thread.java:1096)
I/VpnService( 2570): disconnecting VPN...
D/VpnSettings( 2579): received connectivity: Psk: connected? DISCONNECTING   err
=0
I/SProxy_mtpd( 2570): Stop VPN daemon: mtpd
D/mtpd    ( 2884): Timeout -> Sending SCCRQ
I/mtpd    ( 2884): Received signal 15
D/mtpd    ( 2884): Sending STOPCCN
D/mtpd    ( 2884): sending package: 0xc6d0 with leng:36
I/mtpd    ( 2884): Mtpd is terminated (status = 6)
D/SProxy_mtpd( 2570): mtpd is stopped after 0 msec
D/SProxy_mtpd( 2570): stopping mtpd, success? true
I/SProxy_racoon( 2570): Stop VPN daemon: racoon
D/SProxy_racoon( 2570): racoon is stopped after 0 msec
D/SProxy_racoon( 2570): stopping racoon, success? true
D/VpnService( 2570): onFinalCleanUp()
I/VpnService( 2570): restore original suffices --> null
D/VpnSettings( 2579): received connectivity: Psk: connected? IDLE   err=101
D/VpnSettings( 2579): create reconnect dialog for event 101

Best regards,
Zhang Jiejing

2011/4/30 Jiejing.Zhang <kzj...@gmail.com>