Thread Info
  • State Not Answered
  • Replies 9 replies
  • Subscribers 0 subscribers
  • Views 3345 views
  • Users 0 members are here
Options
Suggested

[8.200][BUG][OPEN] Android VPN problem

x-cimo
I upgraded from 8.103 to the final 8.200, and I am trying to get the vpn working.
My android phone is  Samsung Galaxy S II running android 2.3.3

It does not connect and give no specific error on the android side,

in the logs I can see: 

2011:07:21-21:31:20 plasmashield pluto[7488]: packet from 216.218.29.142:59900: received Vendor ID payload [RFC 3947]

2011:07:21-21:31:20 plasmashield pluto[7488]: packet from 216.218.29.142:59900: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02]

2011:07:21-21:31:20 plasmashield pluto[7488]: packet from 216.218.29.142:59900: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n]

2011:07:21-21:31:20 plasmashield pluto[7488]: packet from 216.218.29.142:59900: ignoring Vendor ID payload [draft-ietf-ipsec-nat-t-ike-00]

2011:07:21-21:31:20 plasmashield pluto[7488]: packet from 216.218.29.142:59900: ignoring Vendor ID payload [FRAGMENTATION 80000000]

2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[3] 216.218.29.142:59900 #3: responding to Main Mode from unknown peer 216.218.29.142:59900

2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[3] 216.218.29.142:59900 #3: NAT-Traversal: Result using RFC 3947: peer is NATed

2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[3] 216.218.29.142:59900 #3: Peer ID is ID_IPV4_ADDR: '10.156.130.142'

2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[4] 216.218.29.142:59900 #3: deleting connection "S_for Charles"[3] instance with peer 216.218.29.142 {isakmp=#0/ipsec=#0}

2011:07:21-21:31:20 plasmashield pluto[7488]: | NAT-T: new mapping 216.218.29.142:59900/53937)

2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[4] 216.218.29.142:53937 #3: sent MR3, ISAKMP SA established

2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[4] 216.218.29.142:53937 #3: ignoring informational payload, type IPSEC_INITIAL_CONTACT

2011:07:21-21:31:21 plasmashield pluto[7488]: "S_for Charles"[1] 216.218.29.142:53937 #4: responding to Quick Mode

2011:07:21-21:31:21 plasmashield pluto[7488]: "S_for Charles"[1] 216.218.29.142:53937 #4: IPsec SA established {ESP=>0x077b67a1 
Parents
  • 0
    Kinda odd that it shows an "IPsec SA established" message at the end.  I'm not an IPSEC expert but have configured a fair number of tunnels over the years.  Almost always the reason for the connection not coming up is a mis-configuration between the client and the server.  EVERYTHING has to be exact for phase 1 and 2 and all the encryption algorithms used.  I would double check to make sure everything is the same.  Anyway just my 2 cents.  [:)]
  • 0 in reply to danodemano
    Also I am able to connect to the vpn over wireless (from inside the same network as the vpn is), but over 3G it fail (as above)
  • 0 in reply to x-cimo
    Hi,

    Issue of NAT-Traversal seems not to be fixed. 
    http://www.astaro.org/astaro-beta-versions/asg-v8-200-beta/36373-help-us-test-l2tp-psk-android.html

    Look at the following message. 
    2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[3] 216.218.29.142:59900 #3: NAT-Traversal: Result using RFC 3947: peer is NATed
    2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[3] 216.218.29.142:59900 #3: Peer ID is ID_IPV4_ADDR: '10.156.130.142'
    2011:07:21-21:31:20 plasmashield pluto[7488]: "S_for Charles"[4] 216.218.29.142:59900 #3: deleting connection "S_for Charles"[3] instance with peer 216.218.29.142 {isakmp=#0/ipsec=#0}
    2011:07:21-21:31:20 plasmashield pluto[7488]: | NAT-T: new mapping 216.218.29.142:59900/53937)


    The career that you are using does NAPT. 
    If source port of NAT-T is not changed or no NAT, you will succeed the connection. 
    Example
    NAT-T: new mapping ***.***.***.***:4500/******
    or 
    NAT-Traversal: Result using RFC 3947: no NAT detected

    I had acquired tcpdump at V7 before. This behavior seems not to have changed now. 
    http://www.astaro.org/astaro-gateway-products/vpn-site-site-remote-access/35716-android-l2tp-via-napt.html
    The response of L2TP is sent from ipsec0. However, the packet is not sent from the port of External. 
    (In External.jpg, source IP is all .25.)
  • 0 in reply to YasunoriMatsuo
    I am sorry, but is there anything I can do on the astaro box to get it working, can anyone confirm that It could be the NAT bug that is not fixed?
  • 0 in reply to x-cimo
    Does the log show more information if you enable debug at the "Remote Access >> L2TP >> Advanced" tab?
  • 0 in reply to d12fk
    I have a log with full debugging, however I am worried about posting it all here, since it seem to contain all my Private CERT etc..

    I did a log from both a working (from inside the network) over wifi, as well as a log over 3G network,

    They both look identical except that the one over 3G stop before doing any L2TP work.

    The last common line are 
    2011:07:26-21:03:41 plasmashield pluto[13302]: "S_REF_jDQIIDTrDt_0"[4] 10.100.4.205 #19: IPsec SA established {ESP=>0x0e8545f6 


    I do not know why the 3G one does not start the L2TP stuff.. and print no error. What happen at that point?

    The working one (over wifi) have the following extra stuff: 

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: Plugin aua.so loaded.

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: AUA plugin initialized.

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: Plugin ippool.so loaded.

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: Plugin pppol2tp.so loaded.

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: pppd 2.4.5 started by (unknown), uid 0

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: using channel 2

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: Using interface ppp0

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: Connect: ppp0  

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: Overriding mtu 1500 to 1380

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: PPPoL2TP options: lnsmode tid 34067 sid 33346 debugmask 0

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: Overriding mru 1500 to mtu value 1380

    2011:07:26-21:03:42 plasmashield pppd-l2tp[23945]: sent [LCP ConfReq id=0x1    ]

    2011:07:26-21:03:43 plasmashield pppd-l2tp[23945]: rcvd [LCP ConfReq id=0x1     ]

    2011:07:26-21:03:43 plasmashield pppd-l2tp[23945]: sent [LCP ConfAck id=0x1     ]

    2011:07:26-21:03:45 plasmashield pppd-l2tp[23945]: sent [LCP ConfReq id=0x1    ]

    2011:07:26-21:03:45 plasmashield pppd-l2tp[23945]: rcvd [LCP ConfAck id=0x1    ]

    2011:07:26-21:03:45 plasmashield pppd-l2tp[23945]: Overriding mtu 1400 to 1380

    2011:07:26-21:03:45 plasmashield pppd-l2tp[23945]: PPPoL2TP options: lnsmode tid 34067 sid 33346 debugmask 0

    2011:07:26-21:03:45 plasmashield pppd-l2tp[23945]: sent [CHAP Challenge id=0x44 , name = "MYINTERNETHOSTNAME.com"]

    2011:07:26-21:03:45 plasmashield pppd-l2tp[23945]: rcvd [CHAP Response id=0x44 , name = "JP"]

    2011:07:26-21:03:47 plasmashield pppd-l2tp[23945]: AUAconnect - Returned IPAddr *

    ... some more stuff
  • 0 in reply to x-cimo
    It seems the problem is in the L2TP phase then. Could you edit the file /var/mdw/scripts/openl2tpd on your ASG and change the line reading 
    $STARTPROC -q -c $CHROOT $L2TPD
     to 
    $STARTPROC -q -c $CHROOT $L2TPD -D
     (append a -D to be brief)? The log should show more information then.
  • 0 in reply to d12fk
    Here is what happen with extra debug (-D) from the point where the tunnel establish:

    I guess everything does downhill starting at: 2011:07:28-18:56:26 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: send 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 0

    It does not seem to be received as it re-send it. However I don't know why... Does this go over the tunnel or in a new outgoing connection on a different port?

    2011:07:28-18:56:25 plasmashield pluto[6993]: "S_for JP"[1] 216.218.29.182:55178 #2: IPsec SA established {ESP=>0x00829f39  WAITCTLCONN
    2011:07:28-18:56:27 plasmashield openl2tpd[14890]: XPRT: tunl 22515: send zlb ack, ns/nr=1/1
    2011:07:28-18:56:28 plasmashield openl2tpd[14890]: XPRT: tunl 22515: set retry interval to 2
    2011:07:28-18:56:29 plasmashield openl2tpd[14890]: XPRT: tunl 22515: set retry interval to 4
    2011:07:28-18:56:29 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 1
    2011:07:28-18:56:30 plasmashield openl2tpd[14890]: XPRT: tunl 22515: set retry interval to 8
    2011:07:28-18:56:30 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 2
    2011:07:28-18:56:31 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 3
    2011:07:28-18:56:33 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 4
    2011:07:28-18:56:34 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 5
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: XPRT: tunl 22515: retry failure
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: FSM: CCE(22515) event XPRT_DOWN in state WAITCTLCONN
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: AVP: tunl 22515: building STOPCCN message, 3 AVPs
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: PROTO: tunl 22515: sending STOPCCN to peer 62329
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: XPRT: tunl 22515: queuing tx packet, type 4, len 38, ns/nr 1/1
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: XPRT: tunl 22515: tx window closed
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: FUNC: tunl 22515: starting cleanup timer
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: FSM: CCE(22515) state change: WAITCTLCONN --> CLOSING
    2011:07:28-18:56:36 plasmashield openl2tpd[14890]: XPRT: tunl 22515: set retry interval to 2
    2011:07:28-18:56:36 plasmashield openl2tpd[14890]: XPRT: tunl 22515: retry failure
    2011:07:28-18:56:36 plasmashield openl2tpd[14890]: FSM: CCE(22515) event XPRT_DOWN in state CLOSING
    2011:07:28-18:57:35 plasmashield openl2tpd[14890]: FUNC: tunl 22515 deleted
    2011:07:28-18:57:35 plasmashield openl2tpd[14890]: FUNC: tunl 22515: deleting context
Reply
  • 0 in reply to d12fk
    Here is what happen with extra debug (-D) from the point where the tunnel establish:

    I guess everything does downhill starting at: 2011:07:28-18:56:26 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: send 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 0

    It does not seem to be received as it re-send it. However I don't know why... Does this go over the tunnel or in a new outgoing connection on a different port?

    2011:07:28-18:56:25 plasmashield pluto[6993]: "S_for JP"[1] 216.218.29.182:55178 #2: IPsec SA established {ESP=>0x00829f39  WAITCTLCONN
    2011:07:28-18:56:27 plasmashield openl2tpd[14890]: XPRT: tunl 22515: send zlb ack, ns/nr=1/1
    2011:07:28-18:56:28 plasmashield openl2tpd[14890]: XPRT: tunl 22515: set retry interval to 2
    2011:07:28-18:56:29 plasmashield openl2tpd[14890]: XPRT: tunl 22515: set retry interval to 4
    2011:07:28-18:56:29 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 1
    2011:07:28-18:56:30 plasmashield openl2tpd[14890]: XPRT: tunl 22515: set retry interval to 8
    2011:07:28-18:56:30 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 2
    2011:07:28-18:56:31 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 3
    2011:07:28-18:56:33 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 4
    2011:07:28-18:56:34 plasmashield openl2tpd[14890]: DATA: TX: tunl 22515/0: resend 169 bytes to peer 216.218.29.182, packet ns/nr 0/1 type 2, retry 5
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: XPRT: tunl 22515: retry failure
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: FSM: CCE(22515) event XPRT_DOWN in state WAITCTLCONN
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: AVP: tunl 22515: building STOPCCN message, 3 AVPs
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: PROTO: tunl 22515: sending STOPCCN to peer 62329
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: XPRT: tunl 22515: queuing tx packet, type 4, len 38, ns/nr 1/1
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: XPRT: tunl 22515: tx window closed
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: FUNC: tunl 22515: starting cleanup timer
    2011:07:28-18:56:35 plasmashield openl2tpd[14890]: FSM: CCE(22515) state change: WAITCTLCONN --> CLOSING
    2011:07:28-18:56:36 plasmashield openl2tpd[14890]: XPRT: tunl 22515: set retry interval to 2
    2011:07:28-18:56:36 plasmashield openl2tpd[14890]: XPRT: tunl 22515: retry failure
    2011:07:28-18:56:36 plasmashield openl2tpd[14890]: FSM: CCE(22515) event XPRT_DOWN in state CLOSING
    2011:07:28-18:57:35 plasmashield openl2tpd[14890]: FUNC: tunl 22515 deleted
    2011:07:28-18:57:35 plasmashield openl2tpd[14890]: FUNC: tunl 22515: deleting context
Children
No Data
Unfiltered HTML