New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 685812 link

Starred by 1 user

Issue metadata

Status: Archived
Owner:
Closed: Apr 2017
Cc:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug-Regression



Sign in to add a comment

IPSec RSA VPN service down.

Project Member Reported by aashuto...@chromium.org, Jan 26 2017

Issue description

Ipsec-rsa service seems to be down and is not responding to the requests. 
 
I see the following on previously passing build, 

Server side:
Feb 22 17:51:56 ipsec-rsa-u12-04-64bt pluto[1151]: packet from 172.16.10.148:500: received Vendor ID payload [RFC 3947] method set to=109
Feb 22 17:51:56 ipsec-rsa-u12-04-64bt pluto[1151]: packet from 172.16.10.148:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 109
Feb 22 17:51:56 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: responding to Main Mode from unknown peer 172.16.10.148
Feb 22 17:51:56 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Feb 22 17:51:56 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: STATE_MAIN_R1: sent MR1, expecting MI2
Feb 22 17:51:56 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: NAT-Traversal: Result using RFC 3947 (NAT-Traversal): no NAT detected
Feb 22 17:51:56 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Feb 22 17:51:56 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: STATE_MAIN_R2: sent MR2, expecting MI3
Feb 22 17:51:57 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: Main mode peer ID is ID_DER_ASN1_DN: 'C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=client_cert, E=CrOSTest@google.com'
Feb 22 17:51:57 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: no crl from issuer "C=US, ST=CA, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=ipsec_server_ca, E=CrOSTest@google.com" found (strict=no)
Feb 22 17:51:57 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: I am sending my cert
Feb 22 17:51:57 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Feb 22 17:51:57 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[3] 172.16.10.148 #7: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=aes_128 prf=oakley_sha group=modp2048}



Client side:
2017-02-22T18:43:06.943986-08:00 INFO charon[8948]: 04[CFG]   reached self-signed root ca with a path length of 0
2017-02-22T18:43:06.944001-08:00 INFO charon[8948]: 04[IKE] authentication of 'C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=ipsec_server_cert, E=CrOSTest@google.com' with RSA successful
2017-02-22T18:43:06.944018-08:00 INFO charon[8948]: 04[IKE] IKE_SA managed[1] established between 172.16.10.148[C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=client_cert, E=CrOSTest@google.com]...172.18.10.8[C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=ipsec_server_cert, E=CrOSTest@google.com]
2017-02-22T18:43:06.944036-08:00 INFO charon[8948]: 04[IKE] IKE_SA managed[1] established between 172.16.10.148[C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=client_cert, E=CrOSTest@google.com]...172.18.10.8[C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=ipsec_server_cert, E=CrOSTest@google.com]
2017-02-22T18:43:06.944053-08:00 INFO charon[8948]: 04[IKE] scheduling reauthentication in 9752s
2017-02-22T18:43:06.944068-08:00 INFO charon[8948]: 04[IKE] maximum IKE_SA lifetime 10292s
2017-02-22T18:43:06.944082-08:00 INFO charon[8948]: 04[KNL] allocating SPI failed: Unknown error (524)
2017-02-22T18:43:06.944096-08:00 INFO charon[8948]: 04[KNL] unable to get SPI for reqid {1}
2017-02-22T18:43:06.944110-08:00 INFO charon[8948]: 04[IKE] allocating SPI from kernel failed
2017-02-22T18:43:36.582806-08:00 ERR l2tpipsec_vpn[8936]: IPsec connection timed out
2017-02-22T18:43:37.584226-08:00 INFO l2tpipsec_vpn[8936]: Shutting down...
2017-02-22T18:43:37.585643-08:00 INFO charon[8948]: 00[DMN] signal of type SIGINT received. Shutting down
2017-02-22T18:43:37.631723-08:00 ERR l2tpipsec_vpn[8936]: Unable to send signal to 8937: No such process
2017-02-22T18:43:37.631910-08:00 ERR l2tpipsec_vpn[8936]: Unable to send signal to 8948: No such process
2017-02-22T18:43:37.634253-08:00 INFO shill[1571]: [INFO:external_task.cc(107)] OnTaskDied(8936, 32)
2017-02-22T18:43:37.634332-08:00 ERR shill[1571]: [ERROR:process_manager.cc(190)] Process 8936 not being watched
2017-02-22T18:43:37.634352-08:00 INFO shill[1571]: [INFO:rpc_task.cc(43)] RPCTask 2 destroyed.
2017-02-22T18:43:37.635340-08:00 INFO shill[1571]: [INFO:service.cc(404)] Service 60: state Configuring -> Failure
2017-02-22T18:43:37.635402-08:00 INFO shill[1571]: [INFO:service.cc(990)] Noting an unexpected failure to connect.
2017-02-22T18:43:37.635422-08:00 INFO shill[1571]: [INFO:manager.cc(1487)] Service 60 updated; state: Failure failure internal-error

Note: The server has incorrect time. I will try to update the server so it shows correct time.
Summary: IPSec RSA n PSK VPN service down. (was: IPSec-Rsa VPN service down. )
Cannot connect to IPsec-PSK either. 
Cc: cernekee@chromium.org
I am seeing the "allocating SPI failed: Unknown error (524)" Error while connecting to IPsec-psk /rsa service. 
@ceerneke: Can you check the logs ?

2017-02-24T14:13:52.661672-08:00 INFO charon[5010]: 12[IKE] activating new tasks
2017-02-24T14:13:52.661758-08:00 INFO charon[5010]: 12[IKE]   activating QUICK_MODE task
2017-02-24T14:13:52.662324-08:00 INFO charon[5010]: 12[KNL] allocating SPI failed: Unknown error (524)
2017-02-24T14:13:52.662461-08:00 INFO charon[5010]: 12[KNL] unable to get SPI
2017-02-24T14:13:52.662535-08:00 INFO charon[5010]: 12[IKE] allocating SPI from kernel failed
2017-02-24T14:13:52.662973-08:00 INFO charon[5010]: 12[MGR] checkin and destroy IKE_SA managed[1]
2017-02-24T14:13:52.663111-08:00 INFO charon[5010]: 12[IKE] IKE_SA managed[1] state change: ESTABLISHED => DESTROYING
2017-02-24T14:13:52.663270-08:00 INFO charon[5010]: 12[MGR] checkin and destroy of IKE_SA successful
2017-02-24T14:13:53.349363-08:00 DEBUG shill[1649]: [VERBOSE2:rtnl_handler.cc(205)] RTNLHandler got request to dump 0x1
2017-02-24T14:13:53.349420-08:00 DEBUG shill[1649]: [VERBOSE2:rtnl_handler.cc(225)] RTNLHandler nextrequest 194 194 0x1
2017-02-24T14:13:53.350022-08:00 DEBUG shill[1649]: [VERBOSE2:rtnl_handler.cc(225)] RTNLHandler nextrequest 195 195 0
2017-02-24T14:13:53.350112-08:00 DEBUG shill[1649]: [VERBOSE2:rtnl_handler.cc(252)] Done with requests
2017-02-24T14:13:56.579982-08:00 INFO charon[5010]: 05[MGR] checkout IKEv1 SA with SPIs 232a90a5d214e3a6_i 0000000000000000_r
2017-02-24T14:13:56.580049-08:00 INFO charon[5010]: 05[MGR] IKE_SA checkout not successful
2017-02-24T14:13:56.614135-08:00 INFO charon[5010]: 11[MGR] checkout IKEv1 SA with SPIs 232a90a5d214e3a6_i c96f26d7f936a313_r
2017-02-24T14:13:56.614207-08:00 INFO charon[5010]: 11[MGR] IKE_SA checkout not successful
2017-02-24T14:13:56.651060-08:00 INFO charon[5010]: 14[MGR] checkout IKEv1 SA with SPIs 232a90a5d214e3a6_i c96f26d7f936a313_r
2017-02-24T14:13:56.651135-08:00 INFO charon[5010]: 14[MGR] IKE_SA checkout not successful
2017-02-24T14:14:12.067517-08:00 INFO shill[1649]: [INFO:wifi_service.cc(785)] Representative endpoint updated for service 79. [SSID=CrOS_WPA2_Airport_Xtreme_2.4GHz], bssid: c8:bc:c8:ff:2a:99, signal: -64, security: rsn, frequency: 2462
2017-02-24T14:14:12.067634-08:00 DEBUG shill[1649]: [VERBOSE2:chromeos_service_dbus_adaptor.cc(85)] /service/79 (79) EmitUint16sChanged: WiFi.FrequencyList
2017-02-24T14:14:12.068017-08:00 DEBUG shill[1649]: [VERBOSE2:chromeos_service_dbus_adaptor.cc(73)] /service/79 (79) EmitUint8Changed: Strength
2017-02-24T14:14:13.350454-08:00 DEBUG shill[1649]: [VERBOSE2:rtnl_handler.cc(205)] RTNLHandler got request to dump 0x1
2017-02-24T14:14:13.350499-08:00 DEBUG shill[1649]: [VERBOSE2:rtnl_handler.cc(225)] RTNLHandler nextrequest 195 195 0x1
2017-02-24T14:14:13.350873-08:00 DEBUG shill[1649]: [VERBOSE2:rtnl_handler.cc(225)] RTNLHandler nextrequest 196 196 0
2017-02-24T14:14:13.350913-08:00 DEBUG shill[1649]: [VERBOSE2:rtnl_handler.cc(252)] Done with requests
2017-02-24T14:14:22.607769-08:00 ERR l2tpipsec_vpn[4998]: IPsec connection timed out
2017-02-24T14:14:23.609204-08:00 INFO l2tpipsec_vpn[4998]: Shutting down...
2017-02-24T14:14:23.610182-08:00 INFO charon[5010]: 00[DMN] signal of type SIGINT received. Shutting down
2017-02-24T14:14:23.610625-08:00 INFO charon[5010]: 00[MGR] going to destroy IKE_SA manager and all managed IKE_SA's
2017-02-24T14:14:23.610714-08:00 INFO charon[5010]: 00[MGR] set driveout flags for all stored IKE_SA's
2017-02-24T14:14:23.610780-08:00 INFO charon[5010]: 00[MGR] wait for all threads to leave IKE_SA's
2017-02-24T14:14:23.610842-08:00 INFO charon[5010]: 00[MGR] delete all IKE_SA's
2017-02-24T14:14:23.610901-08:00 INFO charon[5010]: 00[MGR] destroy all entries
2017-02-24T14:14:23.627810-08:00 ERR l2tpipsec_vpn[4998]: Unable to send signal to 4999: No such process
2017-02-24T14:14:23.628055-08:00 ERR l2tpipsec_vpn[4998]: Unable to send signal to 5010: No such process
2017-02-24T14:14:23.631415-08:00 INFO shill[1649]: [INFO:external_task.cc(110)] OnTaskDied(4998, 32)
2017-02-24T14:14:23.631982-08:00 DEBUG shill[1649]: [VERBOSE2:l2tp_ipsec_driver.cc(194)] /service/51 Cleanup(Failure, internal-error)
net (1).log
1.8 MB View Download
> 2017-02-22T18:43:06.944082-08:00 INFO charon[8948]: 04[KNL] allocating SPI failed: Unknown error (524)

If this is XFRM_MSG_ALLOCSPI, it is a purely client-side operation so I wouldn't expect it is to be caused by anything on the server side.

Is this running on kevin or elm (possibly http://crosbug.com/p/57324 )?
Summary: IPSec RSA VPN service down. (was: IPSec RSA n PSK VPN service down. )
Yes, I was using Kevin for testing IPSEC-psk. Caroline R57-9202.37.0 was able to connect. Thanks!

I still see failures for ipsec-rsa,

2017-02-25T01:05:06.349841+00:00 INFO shill[1805]: [INFO:manager.cc(1489)] Service 1363 updated; state: Configuring failure Unknown

What can cause connection timeout issues, any idea where to look next?
2017-02-25T01:05:19.492635+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Connecting to host 172.18.10.8, port 1701
2017-02-25T01:05:24.498009+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Maximum retries exceeded for tunnel 28664.  Closing.
2017-02-25T01:05:24.498134+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Connection 0 closed to 172.18.10.8, port 1701 (Timeout)
2017-02-25T01:05:26.498020+00:00 INFO charon[2619]: 06[MGR] checkout IKEv1 SA with SPIs 9b07e0c124b0534f_i 772f3851f272c9f5_r
2017-02-25T01:05:26.498085+00:00 INFO charon[2619]: 06[MGR] IKE_SA managed[1] successfully checked out
2017-02-25T01:05:26.498302+00:00 INFO charon[2619]: 06[MGR] checkin IKE_SA managed[1]
2017-02-25T01:05:26.498345+00:00 INFO charon[2619]: 06[MGR] checkin of IKE_SA successful
2017-02-25T01:05:29.503839+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Unable to deliver closing message for tunnel 28664. Destroying anyway.

Detailed logs in attachment. 

net (3).log
85.1 KB View Download
Server side,


eb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: packet from 172.16.10.3:500: received Vendor ID payload [XAUTH]
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: packet from 172.16.10.3:500: received Vendor ID payload [Dead Peer Detection]
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: packet from 172.16.10.3:500: received Vendor ID payload [RFC 3947] method set to=109
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: packet from 172.16.10.3:500: received Vendor ID payload [draft-ietf-ipsec-nat-t-ike-02_n] meth=106, but already using method 109
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: responding to Main Mode from unknown peer 172.16.10.3
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: Oakley Transform [(null) (0), (null), OAKLEY_GROUP_MODP3072] refused due to insecure key_len and enc. alg. not listed in "ike" string
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: OAKLEY_SHA2_256 is not supported.  Attribute OAKLEY_HASH_ALGORITHM
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: transition from state STATE_MAIN_R0 to state STATE_MAIN_R1
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: STATE_MAIN_R1: sent MR1, expecting MI2
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: NAT-Traversal: Result using RFC 3947 (NAT-Traversal): peer is NATed
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: transition from state STATE_MAIN_R1 to state STATE_MAIN_R2
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: STATE_MAIN_R2: sent MR2, expecting MI3
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: Main mode peer ID is ID_DER_ASN1_DN: 'C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=client_cert, E=CrOSTest@@
google.com'
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: no crl from issuer "C=US, ST=CA, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=ipsec_server_ca, E=CrOSTest@google.com" found (strict=no)
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: I am sending my cert
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: transition from state STATE_MAIN_R2 to state STATE_MAIN_R3
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: new NAT mapping for #12, was 172.16.10.3:500, now 172.16.10.3:4500
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: STATE_MAIN_R3: sent MR3, ISAKMP SA established {auth=OAKLEY_RSA_SIG cipher=aes_128 prf=oakley_sha group=modp2048}
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: the peer proposed: 172.18.10.8/32:17/1701 -> 192.168.7.16/32:17/1701
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: NAT-Traversal: received 2 NAT-OA. using first, ignoring others
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: kernel algorithm does not like: no alg
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: unsupported ESP Transform ESP_AES_GCM_C from 172.16.10.3
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: kernel algorithm does not like: no alg
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: unsupported ESP Transform ESP_AES_GCM_C from 172.16.10.3
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: responding to Quick Mode proposal {msgid:aaf03b23}
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13:     us: 172.18.10.8<172.18.10.8>[C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=ipsec_server_cert, E=CrOSTest@google.com,+S=C]:17/1701
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13:   them: 172.16.10.3[C=US, ST=CA, L=MTV, O=ChromeOS IPSEC-RSA Testing, OU=Oysterbay IPSEC-RSA Testing, CN=client_cert, E=CrOSTest@google.com,+S=C]:17/1701
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: keeping refhim=4294901761 during rekey
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: transition from state STATE_QUICK_R0 to state STATE_QUICK_R1
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: STATE_QUICK_R1: sent QR1, inbound IPsec SA installed, expecting QI2
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: transition from state STATE_QUICK_R1 to state STATE_QUICK_R2
Feb 24 16:13:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #13: STATE_QUICK_R2: IPsec SA established transport mode {ESP=>0xc263b05e <0xa2cb5278 xfrm=AES_128-HMAC_SHA2_256 NATOA=192.168.7.16 NATD=172.16.10.3:4500 DPD=none}
Feb 24 16:14:53 ipsec-rsa-u12-04-64bt pluto[1151]: "l2tp-X.509"[5] 172.16.10.3 #12: received Delete SA payload: deleting ISAKMP State #12
Feb 24 16:14:53 ipsec-rsa-u12-04-64bt pluto[1151]: packet from 172.16.10.3:4500: received and ignored informational message
Feb 24 16:14:53 ipsec-rsa-u12-04-64bt pluto[1151]: ERROR: asynchronous network error report on eth1 (sport=4500) for message to 172.16.10.3 port 4500, complainant 172.16.10.3: Connection refused [errno 111, origin ICMP type 3 code 3 (not authenticated)]

It looks like it negotiated an SA and then xl2tpd timed out trying to start L2TP.  It did not reach the point where it would try to start PPP:

2017-02-25T01:05:06.717923+00:00 INFO charon[2619]: 13[IKE] CHILD_SA managed{1} established with SPIs c263b05e_i a2cb5278_o and TS 192.168.7.16/32[udp/l2tp] === 172.18.10.8/32[udp/l2tp]
2017-02-25T01:05:06.717964+00:00 INFO charon[2619]: 13[IKE] CHILD_SA managed{1} established with SPIs c263b05e_i a2cb5278_o and TS 192.168.7.16/32[udp/l2tp] === 172.18.10.8/32[udp/l2tp]
2017-02-25T01:05:06.723879+00:00 INFO charon[2619]: 13[IKE] reinitiating already active tasks
2017-02-25T01:05:06.723903+00:00 INFO charon[2619]: 13[IKE]   QUICK_MODE task
2017-02-25T01:05:06.724004+00:00 INFO charon[2619]: 13[ENC] generating QUICK_MODE request 591130794 [ HASH ]
2017-02-25T01:05:06.724096+00:00 INFO charon[2619]: 13[NET] sending packet: from 192.168.7.16[4500] to 172.18.10.8[4500] (60 bytes)
2017-02-25T01:05:06.724169+00:00 INFO charon[2619]: 13[IKE] activating new tasks
2017-02-25T01:05:06.724200+00:00 INFO charon[2619]: 13[IKE] nothing to initiate
2017-02-25T01:05:06.724234+00:00 INFO charon[2619]: 13[MGR] checkin IKE_SA managed[1]
2017-02-25T01:05:06.724272+00:00 INFO charon[2619]: 13[MGR] checkin of IKE_SA successful
2017-02-25T01:05:06.724340+00:00 INFO charon[2619]: 09[NET] sending packet: from 192.168.7.16[4500] to 172.18.10.8[4500]
2017-02-25T01:05:07.476774+00:00 INFO l2tpipsec_vpn[2607]: IPsec connection now up
2017-02-25T01:05:07.479320+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: setsockopt recvref[22]: Protocol not available
2017-02-25T01:05:07.479363+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: This binary does not support kernel L2TP.
2017-02-25T01:05:07.479654+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: xl2tpd version xl2tpd-1.3.0 started on localhost PID:2641
2017-02-25T01:05:07.479686+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Written by Mark Spencer, Copyright (C) 1998, Adtran, Inc.
2017-02-25T01:05:07.479721+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Forked by Scott Balmos and David Stipp, (C) 2001
2017-02-25T01:05:07.479857+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Inherited by Jeff McAdams, (C) 2002
2017-02-25T01:05:07.479889+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Forked again by Xelerance (www.xelerance.com) (C) 2006
2017-02-25T01:05:07.479913+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Listening on IP address 0.0.0.0, port 1701
2017-02-25T01:05:07.480124+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Connecting to host 172.18.10.8, port 1701
2017-02-25T01:05:10.482474+00:00 INFO charon[2619]: 04[MGR] checkout IKEv1 SA with SPIs 9b07e0c124b0534f_i 0000000000000000_r
2017-02-25T01:05:10.482533+00:00 INFO charon[2619]: 04[MGR] IKE_SA managed[1] successfully checked out
2017-02-25T01:05:10.483123+00:00 INFO charon[2619]: 04[MGR] checkin IKE_SA managed[1]
2017-02-25T01:05:10.483174+00:00 INFO charon[2619]: 04[MGR] checkin of IKE_SA successful
2017-02-25T01:05:10.489844+00:00 INFO charon[2619]: 15[MGR] checkout IKEv1 SA with SPIs 9b07e0c124b0534f_i 772f3851f272c9f5_r
2017-02-25T01:05:10.489924+00:00 INFO charon[2619]: 15[MGR] IKE_SA managed[1] successfully checked out
2017-02-25T01:05:10.489986+00:00 INFO charon[2619]: 15[MGR] checkin IKE_SA managed[1]
2017-02-25T01:05:10.490031+00:00 INFO charon[2619]: 15[MGR] checkin of IKE_SA successful
2017-02-25T01:05:10.705071+00:00 INFO charon[2619]: 16[MGR] checkout IKEv1 SA with SPIs 9b07e0c124b0534f_i 772f3851f272c9f5_r
2017-02-25T01:05:10.705119+00:00 INFO charon[2619]: 16[MGR] IKE_SA managed[1] successfully checked out
2017-02-25T01:05:10.705167+00:00 INFO charon[2619]: 16[MGR] checkin IKE_SA managed[1]
2017-02-25T01:05:10.705198+00:00 INFO charon[2619]: 16[MGR] checkin of IKE_SA successful
2017-02-25T01:05:10.712807+00:00 INFO charon[2619]: 11[MGR] checkout IKEv1 SA with SPIs 9b07e0c124b0534f_i 772f3851f272c9f5_r
2017-02-25T01:05:10.712848+00:00 INFO charon[2619]: 11[MGR] IKE_SA managed[1] successfully checked out
2017-02-25T01:05:10.712891+00:00 INFO charon[2619]: 11[MGR] checkin IKE_SA managed[1]
2017-02-25T01:05:10.712920+00:00 INFO charon[2619]: 11[MGR] checkin of IKE_SA successful
2017-02-25T01:05:12.485049+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Maximum retries exceeded for tunnel 47827.  Closing.
2017-02-25T01:05:12.485305+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Connection 0 closed to 172.18.10.8, port 1701 (Timeout)
2017-02-25T01:05:17.490049+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Unable to deliver closing message for tunnel 47827. Destroying anyway.
2017-02-25T01:05:17.490106+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Will redial in 2 seconds
2017-02-25T01:05:18.697404+00:00 DEBUG shill[1805]: [VERBOSE2:rtnl_handler.cc(205)] RTNLHandler got request to dump 0x1
2017-02-25T01:05:18.697447+00:00 DEBUG shill[1805]: [VERBOSE2:rtnl_handler.cc(225)] RTNLHandler nextrequest 5483 5483 0x1
2017-02-25T01:05:18.698034+00:00 DEBUG shill[1805]: [VERBOSE2:rtnl_handler.cc(225)] RTNLHandler nextrequest 5484 5484 0
2017-02-25T01:05:18.698064+00:00 DEBUG shill[1805]: [VERBOSE2:rtnl_handler.cc(252)] Done with requests
2017-02-25T01:05:19.492635+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Connecting to host 172.18.10.8, port 1701
2017-02-25T01:05:24.498009+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Maximum retries exceeded for tunnel 28664.  Closing.
2017-02-25T01:05:24.498134+00:00 INFO l2tpipsec_vpn[2607]: xl2tpd[2641]: Connection 0 closed to 172.18.10.8, port 1701 (Timeout)


Is xl2tpd running on the server side?  The log in c#6 only shows messages from IKE, which apparently succeeded.
xl2tpd service looks like working to me, 

root@ipsec-rsa-u12-04-64bt:/etc# ps -ef | grep -i xl2tpd
root     12890     1  0 Feb22 ?        00:00:00 /usr/sbin/xl2tpd
root     16238 12547  0 17:00 pts/1    00:00:00 grep --color=auto -i xl2tpd

root@ipsec-rsa-u12-04-64bt:/etc# netstat -anp | grep l2tp
udp        0      0 0.0.0.0:1701            0.0.0.0:*                           12890/xl2tpd    
unix  2      [ ]         DGRAM                    730218   12890/xl2tpd        


ToDO : In private conversation @cernekee  suggested,
"you could do a packet trace and see what's happening after the quick mode exchange
if the ipsec layer is working correctly you should see a bunch of ESP traffic (so you won't be able to read the port number)
probably udp encapsulated, on 4500/udp
you could also watch for anything being sent in the clear on 1701/udp. but that should not happen because that would indicate l2tp traffic bypassing the ipsec tunnel
you could strace xl2tpd to see if it's picking anything up" 

Also will check on M54-Minnie as discussed offline . We did a full release on m-55 and m-56 where it was working properly. Will check again though. 
Server is only pingable from dnsmasq machine. I am not sure, what caused this. Will try to investigate.  
From the client, I can reach the gateway machine but the gateway drops or does not forward the packet to the server (not sure).

tracepath -n ipsec-rsa
 1?: [LOCALHOST]                                         pmtu 1500
 1:  172.16.10.151                                         1.521ms 
 1:  172.16.10.151                                         1.302ms 
 2:  no reply
 3:  no reply

Gateway machine itself can ping the ipsec server. 

ping ipsec-rsa
PING ipsec-rsa (172.18.10.8) 56(84) bytes of data.
64 bytes from ipsec-rsa (172.18.10.8): icmp_req=1 ttl=64 time=0.267 ms
64 bytes from ipsec-rsa (172.18.10.8): icmp_req=2 ttl=64 time=0.245 ms
^C
--- ipsec-rsa ping statistics ---


Tracing ipsec-psk server does not seem to be an issue. Both the VPN server IP's are in the same subnet (172.18.10.8- Ipsec-rsa and 172.18.10.9 -Ipsec-psk) . 

tracepath -n ipsec-psk
 1?: [LOCALHOST]                                         pmtu 1500
 1:  172.16.10.151                                         3.218ms 
 1:  172.16.10.151                                         2.902ms 
 2:  172.18.10.9                                           2.553ms reached
     Resume: pmtu 1500 hops 2 back 63

Gateway machine ifconfig info

ifconfig | grep 'inet addr'
          inet addr:172.22.22.151  Bcast:172.22.22.191  Mask:255.255.255.192
          inet addr:172.16.10.151  Bcast:172.16.10.255  Mask:255.255.255.0
          inet addr:172.18.10.151  Bcast:172.18.10.255  Mask:255.255.255.0
          inet addr:127.0.0.1  Mask:255.0.0.0


Next step, I may try to capture packets on the gateway machine and analyse. 
Let me know, if you seen this before and what may be causing this issue. 
Status: Fixed (was: Assigned)
Thank you cernekee@ for helping, to fix this issue. Instead of adding a route as you suggested, I decided to update the default gw to point to the dnsmasq machine which has both the interfaces connected.  
It occurred to me after I left that we might have goofed something up by adding the 172.16 route, and that's why your ssh session froze.

So if changing the default route works (and brings the -rsa machine's configuration in line with -psk) that's probably a better option.
The ssh session froze, after I deleted the  172.16 route. I added a gw in /etc/network/interfaces file but it requires restarting network daemon on reboot. I am checking with dschimmels (bug below) who has earlier worked on those VM's, if there is a better way of doing it. 

https://buganizer.corp.google.com/issues/37328469

Comment 14 by dchan@google.com, May 30 2017

Labels: VerifyIn-60
Labels: VerifyIn-61

Comment 16 by dchan@chromium.org, Jan 22 2018

Status: Archived (was: Fixed)

Sign in to add a comment