AICv10.23 unable to establish the connection

It's been days but I can't get the answer until now. I have tried to change all the setting but still can't really get the correct setting.

My current IPSec VPN setting  use default AES-128 PFS policy for connection and for the authentication I use local cert.

Below is the client log when I tried to connect to VPN server.

Mon Oct 11 01:40:27 2010:IpsDialChan::s_conreq
Mon Oct 11 01:40:27 2010:IPSec: Start building connection
Mon Oct 11 01:40:27 2010:System: pthru AddVpnPort port=500
Mon Oct 11 01:40:27 2010:Link: Adding LwsGateway
Mon Oct 11 01:40:27 2010:IPSec: UpdateSpd - 1
Mon Oct 11 01:40:27 2010:CreateSpdEntry:Adapter-0,Name-Exchange,Count-1 
Mon Oct 11 01:40:27 2010:Link: Adding LwsGateway
Mon Oct 11 01:40:27 2010:IPSec: SYSTEM->IPS - connect_phase1,spdindex=1
Mon Oct 11 01:40:27 2010:Link: ChanConReq( Exit Okey )
Mon Oct 11 01:40:27 2010:Ike: internal_reqphase1:Creating a new IKE SA outgoing
Mon Oct 11 01:40:27 2010:Ike: ConRef=7, IkeSaCreated - TotNumIkeSa's=1
Mon Oct 11 01:40:27 2010:Ike: ConRef=0, Setting Slow Line - 0
Mon Oct 11 01:40:27 2010:Ike: Outgoing connect request MAIN mode - gateway=172.16.179.4 : Exchange
Mon Oct 11 01:40:27 2010:Ike: ConRef=7, XMIT_MSG1_MAIN - Exchange
Mon Oct 11 01:40:27 2010:Ike: XMIT_MSG1_MAIN - Exchange
Mon Oct 11 01:40:27 2010:Ike: ConRef=7, recv_msg -> setting RealAdapterIndex = 200
Mon Oct 11 01:40:27 2010:Ike: ConRef=7, RECV_MSG2_MAIN - Exchange
Mon Oct 11 01:40:27 2010:Ike: RECV_MSG2_MAIN - Exchange
Mon Oct 11 01:40:27 2010:IpsDial: GetMyIpAdr aindex=200,ipadr = 0a00005b
Mon Oct 11 01:40:27 2010:Ike: ConRef=7, setting local ip address 10.00.00.91
Mon Oct 11 01:40:27 2010:Ike: ConRef=7, setting final tep 172.16.179.04
Mon Oct 11 01:40:27 2010:Ike: IKE phase I: Setting LifeTime to 28800 seconds
Mon Oct 11 01:40:27 2010:Ike: IkeSa negotiated with the following properties -
Mon Oct 11 01:40:27 2010:  Authentication=RSA_SIGNATURES,Encryption=AES,Hash=MD5,DHGroup=2,KeyLen=128
Mon Oct 11 01:40:27 2010:Ike: ConRef=7, IkeSa negotiated with the following properties -
Mon Oct 11 01:40:27 2010:  Authentication=RSA_SIGNATURES,Encryption=AES,Hash=MD5,DHGroup=2,KeyLen=128
Link: Adding LwsGateway
Mon Oct 11 01:40:27 2010:Mon Oct 11 01:40:27 2010:IPSec: Final Tunnel EndPoint is:172.016.179.004
Ike: ConRef=7, Exchange ->Support for NAT-T version - 9
Mon Oct 11 01:40:27 2010:Ike: Exchange ->Support for NAT-T version - 9
Mon Oct 11 01:40:27 2010:Ike: ConRef=7, XMIT_MSG3_MAIN - Exchange
Mon Oct 11 01:40:27 2010:Ike: XMIT_MSG3_MAIN - Exchange
Mon Oct 11 01:40:31 2010:Ike: ConRef=7, retry timeout - resend ->
Mon Oct 11 01:40:36 2010:Ike: ConRef=7, retry timeout - resend ->
Mon Oct 11 01:40:37 2010:Ike: ConRef=7, recv_msg -> setting RealAdapterIndex = 200
Mon Oct 11 01:40:42 2010:Ike: ConRef=7, retry timeout - resend ->
Mon Oct 11 01:40:49 2010:ERROR - 4022: IKE(phase1):Lost contact to Gateway (No Response) in state  - Exchange.
Mon Oct 11 01:40:49 2010:Ike: ConRef=7,  name=Exchange,msg=enter_state_closed - 
  
Mon Oct 11 01:40:49 2010:Ike: phase1:name(Exchange) - ERROR - retry timeout - max retries
Mon Oct 11 01:40:49 2010:Ike: ConRef=7, send_delete - Exchange
Mon Oct 11 01:40:49 2010:IPSec: IKE->IPS:IpsDelIkeSa - 0 
Mon Oct 11 01:40:49 2010:IPSec: IKE->IPS: phase I SA(00000007) is gone 
Mon Oct 11 01:40:49 2010:Mon Oct 11 01:40:49 2010:IpsDialCb::enter_closed_state(0)
Ike: ConRef=7, IkeSaDeleted - TotNumIkeSa's=0
Mon Oct 11 01:40:49 2010:RemoveSpdEntry:Adapter-0,Name-Exchange,Count-0 
Mon Oct 11 01:40:49 2010:IpsDial: linkdown(id = 1)
Mon Oct 11 01:40:49 2010:IPSec: Disconnected from Exchange on channel 1.
Mon Oct 11 01:40:49 2010[[:P]]PP(Lcp): linkdown(237fb84)
Mon Oct 11 01:40:49 2010:BaseCp::enter_closed_state(c021)
Mon Oct 11 01:40:49 2010[[:P]]PP(Lcp): linkdown exit(237fb84)
Mon Oct 11 01:40:49 2010:Link: Deleting LwsGateway
Mon Oct 11 01:40:49 2010:Ike: internal_delikesa[:D]elete phase1(IKE)SA (SpdIndex = 1)
Mon Oct 11 01:40:51 2010:SockifEx: UdpSocket::Re


And this is the log from server.

pluto[17914]: | *time to handle event
pluto[17914]: | event after this is EVENT_REINIT_SECRET in 295 seconds
pluto[17914]: | handling event EVENT_RETRANSMIT for ***.xx.***.xx "S_EXCHANGE KC TO OFFICE" #3
pluto[17914]: | sending 176 bytes for EVENT_RETRANSMIT through eth1 to ***.xx.***.xx:56689:
pluto[17914]: | 40 cf 60 96 29 13 ec 64 fd 39 7a ef 80 2d d9 d2
pluto[17914]: | 01 10 02 00 00 00 00 00 00 00 00 b0 0d 00 00 38
pluto[17914]: | 00 00 00 01 00 00 00 01 00 00 00 2c 01 01 00 01
pluto[17914]: | 00 00 00 24 01 01 00 00 80 01 00 07 80 02 00 01
pluto[17914]: | 80 03 00 03 80 04 00 02 80 0b 00 01 80 0c 70 80
pluto[17914]: | 80 0e 00 80 0d 00 00 14 88 2f e5 6d 6f d2 0d bc
pluto[17914]: | 22 51 61 3b 2e be 5b eb 0d 00 00 14 12 f5 f2 8c
pluto[17914]: | 45 71 68 a9 70 2d 9f e2 74 cc 01 00 0d 00 00 0c
pluto[17914]: | 09 00 26 89 df d6 b7 12 0d 00 00 14 af ca d7 13
pluto[17914]: | 68 a1 f1 c9 6b 86 96 fc 77 57 01 00 00 00 00 14
pluto[17914]: | 4a 13 1c 81 07 03 58 45 5c 57 28 f2 0e 95 45 2f
pluto[17914]: | inserting event EVENT_RETRANSMIT, timeout in 40 seconds for #3
pluto[17914]: | next event EVENT_RETRANSMIT in 40 seconds for #3
2010:10:11-16:56:41 proxy01 pluto[17914]: |
2010:10:11-16:56:41 proxy01 pluto[17914]: | *time to handle event
2010:10:11-16:56:41 proxy01 pluto[17914]: | event after this is EVENT_REINIT_SECRET in 255 seconds
2010:10:11-16:56:41 proxy01 pluto[17914]: | handling event EVENT_RETRANSMIT for ***.xx.***.xx "S_EXCHANGE KC TO OFFICE" #3
2010:10:11-16:56:41 proxy01 pluto[17914]: "S_EXCHANGE KC TO OFFICE"[2] ***.xx.***.xx:56689 #3: max number of retransmissions (2) reached STATE_MAIN_R1
2010:10:11-16:56:41 proxy01 pluto[17914]: | ICOOKIE: 40 cf 60 96 29 13 ec 64
2010:10:11-16:56:41 proxy01 pluto[17914]: | RCOOKIE: fd 39 7a ef 80 2d d9 d2
2010:10:11-16:56:41 proxy01 pluto[17914]: | peer: 7b 31 79 26
2010:10:11-16:56:41 proxy01 pluto[17914]: | state hash entry 17
2010:10:11-16:56:41 proxy01 pluto[17914]: "S_EXCHANGE KC TO OFFICE"[2] ***.xx.***.xx:56689: deleting connection "S_EXCHANGE KC TO OFFICE" instance with peer ***.xx.***.xx {isakmp=#0/ipsec=#0}
2010:10:11-16:56:41 proxy01 pluto[17914]: | next event EVENT_REINIT_SECRET in 255 seconds 


Another question from me. When I run the client, it will automatically add route to my VPN server. How can I change this routing rule?
  • Hi, and welcome to the User BB!

    I notice the private IP in the client log.  Is the Astaro behind a NATting router?  Are all of the ports in the Service Group "IPsec" port-forwarded to the Astaro?  Is NAT-T selected on the 'Advanced' tab?  In the client, have you filled in the private IP of the Astaro's "External (Address)" as a 'Manual IP Address' in 'IP Address Assignment'?

    When I run the client, it will automatically add route to my VPN server. How can I change this routing rule?

    If this still is a problem after fixing any of the above, please give an example of what you see now and what you want to change it to.

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • Thanks Bob. 

    NAT-T is selected and I just added the Manual IP address part but another error message prompted out.

    Mon Oct 11 20:04:41 2010:Ike: NOTIFY : Exchange : RECEIVED : INVALID_ID_INFORMATION : 18
    Mon Oct 11 20:04:46 2010:Ike: NOTIFY : Exchange : RECEIVED : INVALID_MESSAGE_ID : 9
    Mon Oct 11 20:04:52 2010:Ike: ConRef=156, recv_msg -> setting RealAdapterIndex = 200
    Mon Oct 11 20:04:52 2010:Ike: ConRef=156, NOTIFY : Exchange : RECEIVED : INVALID_MESSAGE_ID : 9
    Mon Oct 11 20:04:52 2010:Ike: NOTIFY : Exchange : RECEIVED : INVALID_MESSAGE_ID : 9
    Mon Oct 11 20:04:58 2010:Ike: ConRef=156, recv_msg -> setting RealAdapterIndex = 200
    Mon Oct 11 20:04:58 2010:Ike: ConRef=156, NOTIFY : Exchange : RECEIVED : INVALID_MESSAGE_ID : 9
    Mon Oct 11 20:04:58 2010:Ike: NOTIFY : Exchange : RECEIVED : INVALID_MESSAGE_ID : 9
    Mon Oct 11 20:05:00 2010:IpsDial: Request to send dpd
    Mon Oct 11 20:05:00 2010:Ike: internal_send_dpd:send_dpd -> ikeindex = 156
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156, request from driver to send dpd -> Exchange
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156, send_notify_r_u_here - 3d7448fd
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156, NOTIFY : Exchange : SENT : NOTIFY_MSG_R_U_HERE : 36136
    Mon Oct 11 20:05:00 2010:Ike: NOTIFY : Exchange : SENT : NOTIFY_MSG_R_U_HERE : 36136
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156, recv_msg -> setting RealAdapterIndex = 200
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156, NOTIFY : Exchange : RECEIVED : NOTIFY_MSG_R_U_HERE_ACK : 36137
    Mon Oct 11 20:05:00 2010:Ike: NOTIFY : Exchange : RECEIVED : NOTIFY_MSG_R_U_HERE_ACK : 36137
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156, recv_notify_r_u_here_ack - 3d7448fd
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156,  name=Exchange,msg=enter_state_closed - 
      
    Mon Oct 11 20:05:00 2010:IkeQuick: ConRef=156, 
     
    Mon Oct 11 20:05:00 2010:IkeQuick: phase2:name(Exchange) - error - cleared by phase1
    Mon Oct 11 20:05:00 2010:ERROR - 4037: IKE(phase2):Waiting for message2, cleared by phase1 - Exchange.
    Mon Oct 11 20:05:00 2010:IkeQuick: ConRef=156, 
     
    Mon Oct 11 20:05:00 2010:IpsDialCb::enter_closed_state(0)
    Mon Oct 11 20:05:00 2010:IpsDial: linkdown(id = 1)
    Mon Oct 11 20:05:00 2010:IPSec: Disconnected from Exchange on channel 1.
    Mon Oct 11 20:05:00 2010[[:P]]PP(Lcp): linkdown(26b5834)
    Mon Oct 11 20:05:00 2010:BaseCp::enter_closed_state(c021)
    Mon Oct 11 20:05:00 2010[[:P]]PP(Lcp): linkdown exit(26b5834)
    Mon Oct 11 20:05:00 2010:Link: Deleting LwsGateway
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156, send_delete - Exchange
    Mon Oct 11 20:05:00 2010:Ike: ConRef=156, IkeSaDeleted - TotNumIkeSa's=0
    Mon Oct 11 20:05:00 2010:Ike: internal_delikesa[:D]elete phase1(IKE)SA (SpdIndex = 1)
    Mon Oct 11 20:05:02 2010:SockifEx: UdpSocket::RecvThread()Leaving,Port=500
    Mon Oct 11 20:05:03 2010:SockifEx: UdpSocket::RecvThr
  • I think the problem occurs before the log excerpt above.  Also, please post the server log for your connection attempt.

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA
  • Hi Bob,

    What I'm trying right now is to connect site to site vpn from my windows server to ASG. So I use this AIC to connect. After going around the forum and information, I think this AIC doesn't support site to site vpn. This AIC is more for Remote Access VPN. Correct my if I'm wrong.
  • Yes, the AIC is meant to be used with Remote Access.  Connecting to Astaro Remote Access, you should be able to accomplish what you want, but you probably will need some manual routes and packet filters to achieve the functionality you want.

    Is this a gateway server, or is it an internal server that's a member of your domain?  If it's a gateway server, you should easily be able to use the Windows Server IPsec VPN to connect Site-to-Site with the Astaro.  If it's behind a NATting router, then the tips in this KnowledgeBase article will help you: Site To Site VPN with PSK in ASG V7 when one or both sides are behind NAT.

    Cheers - Bob
     
    Sophos UTM Community Moderator
    Sophos Certified Architect - UTM
    Sophos Certified Engineer - XG
    Gold Solution Partner since 2005
    MediaSoft, Inc. USA