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

Issue 804524 link

Starred by 2 users
Status: Verified
Owner:
█ cernekee@chromium.org
Last visit > 30 days ago
Closed: Feb 2018
Cc:
aashuto...@chromium.org
dsunk...@chromium.org
bhthompson@google.com
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

network_VPNConnect tests failing on M64, M65, M66 with "Error pinging server IP"

Project Member Reported by harpreet@chromium.org, Jan 22 2018 
Most VPN connect autotests are failing on 64,65,66 milestones.

https://stainless.corp.google.com/search?view=matrix&row=test&col=build&first_date=2017-12-01&last_date=2018-01-22&suite=%5Ebvt%5C-perbuild%24&test=network_*&exclude_cts=true&exclude_not_run=false&exclude_non_release=true&exclude_au=true&exclude_acts=true&exclude_retried=true&exclude_non_production=true





Sample test / device logs: https://storage.cloud.google.com/chromeos-autotest-results/171586138-chromeos-test/chromeos6-row3-rack7-host21/network_VPNConnect.l2tpipsec_xauth.tgz


------------------NET LOG--------------------
018-01-22T04:09:53.299378-08:00 INFO shill[28362]: [INFO:device.cc(206)] Device destructed: ppp0 index 10
2018-01-22T04:09:53.299560-08:00 INFO shill[28362]: [INFO:service.cc(296)] Service 68 destroyed.
2018-01-22T04:09:53.300024-08:00 INFO shill[28362]: [INFO:manager.cc(601)] Skipping unload of service 3: re-configured from another profile.
2018-01-22T04:09:53.300279-08:00 INFO shill[28362]: [INFO:manager.cc(601)] Skipping unload of service 2: re-configured from another profile.
2018-01-22T04:09:53.300308-08:00 INFO shill[28362]: [INFO:manager.cc(594)] Skipping unload of service 0: wasn't using this profile.
2018-01-22T04:09:53.300463-08:00 INFO shill[28362]: [INFO:manager.cc(619)] PopProfileInternal finished; 1 profile(s) still present.
2018-01-22T04:09:53.300888-08:00 INFO shill[28362]: [INFO:rpc_task.cc(42)] RPCTask 0 destroyed.
2018-01-22T04:09:53.300894-08:00 INFO l2tpipsec_vpn[16377]: Caught signal 15
2018-01-22T04:09:53.300945-08:00 INFO l2tpipsec_vpn[16377]: Shutting down...
2018-01-22T04:09:53.300975-08:00 INFO l2tpipsec_vpn[16377]: Shutting down L2TP
2018-01-22T04:09:53.301586-08:00 NOTICE pppd[16430]: Modem hangup
2018-01-22T04:09:53.301830-08:00 INFO charon[16384]: 00[DMN] signal of type SIGINT received. Shutting down
2018-01-22T04:09:53.301886-08:00 INFO charon[16384]: 13[KNL] 192.168.1.128 disappeared from ppp0
2018-01-22T04:09:53.303205-08:00 INFO pppd[16430]: [INFO:ppp.cc(102)] OnAuthenticateDone
2018-01-22T04:09:53.304927-08:00 INFO pppd[16430]: [INFO:ppp.cc(168)] Task proxy created: :1.413 - /task/0
2018-01-22T04:09:53.304961-08:00 INFO pppd[16430]: [INFO:task_proxy.cc(36)] Notify(authenticated, argcount: 0)
2018-01-22T04:09:53.306634-08:00 INFO shill[28362]: [INFO:service.cc(312)] Suppressed autoconnect to service 2 (no carrier)
2018-01-22T04:09:53.309770-08:00 WARNING pppd[16430]: [WARNING:object_proxy.cc(580)] Failed to call method: org.chromium.flimflam.Task.notify: object_path= /task/0: org.freedesktop.DBus.Error.UnknownObject: Method "notify" with signature "sa{ss}" on interface "org.chromium.flimflam.Task" doesn't exist#012
2018-01-22T04:09:53.309833-08:00 ERR pppd[16430]: [ERROR:dbus_method_invoker.h(111)] CallMethodAndBlockWithTimeout(...): Domain=dbus, Code=org.freedesktop.DBus.Error.UnknownObject, Message=Method "notify" with signature "sa{ss}" on interface "org.chromium.flimflam.Task" doesn't exist#012
2018-01-22T04:09:53.309872-08:00 ERR pppd[16430]: [ERROR:task_proxy.cc(40)] DBus error: org.freedesktop.DBus.Error.UnknownObject: Method "notify" with signature "sa{ss}" on interface "org.chromium.flimflam.Task" doesn't exist#012
2018-01-22T04:09:53.309976-08:00 INFO pppd[16430]: [INFO:ppp.cc(177)] Task proxy destroyed.
2018-01-22T04:09:53.310012-08:00 INFO pppd[16430]: Connect time 0.3 minutes.
2018-01-22T04:09:53.310044-08:00 INFO pppd[16430]: Sent 5850 bytes, received 518 bytes.
2018-01-22T04:09:53.311289-08:00 INFO pppd[16430]: [INFO:ppp.cc(144)] OnDisconnect
.
.
.
.
.
2018-01-22T04:09:55.139419-08:00 INFO l2tpipsec_vpn[16578]: Starting starter
2018-01-22T04:09:55.139937-08:00 INFO l2tpipsec_vpn[16578]: Starter started as pid 16579
2018-01-22T04:09:55.142933-08:00 INFO l2tpipsec_vpn[16578]: ipsec[16579]: Starting strongSwan 5.5.3 IPsec [starter]...
2018-01-22T04:09:55.170602-08:00 INFO charon[16585]: 00[DMN] Starting IKE charon daemon (strongSwan 5.5.3, Linux 3.14.0, armv7l)
2018-01-22T04:09:55.189007-08:00 INFO l2tpipsec_vpn[16578]: ipsec[16579]: [0122/040955:ERROR:chaps.cc(160)] C_Initialize - CKR_CANT_LOCK
2018-01-22T04:09:55.192244-08:00 INFO charon[16585]: 00[CFG] loaded PKCS#11 v2.20 library 'crypto_module' (/usr/lib/libchaps.so)
2018-01-22T04:09:55.192342-08:00 INFO charon[16585]: 00[CFG]   Chromium OS: Chaps Client Library v0.1
2018-01-22T04:09:55.192401-08:00 INFO charon[16585]: 00[CFG]   uses OS locking functions
2018-01-22T04:09:55.194430-08:00 INFO charon[16585]: 00[CFG]   found token in slot 'crypto_module':0 (TPM Slot)
2018-01-22T04:09:55.195138-08:00 INFO charon[16585]: 00[CFG]     System TPM Token (Chromium OS:  )
2018-01-22T04:09:55.216422-08:00 INFO charon[16585]: 00[CFG]   found token in slot 'crypto_module':1 (TPM Slot)
2018-01-22T04:09:55.217481-08:00 INFO charon[16585]: 00[CFG]     Default Token (Chromium OS:  )
2018-01-22T04:09:55.255794-08:00 INFO charon[16585]: 00[CFG] loading ca certificates from '/etc/ipsec.d/cacerts'
2018-01-22T04:09:55.256054-08:00 INFO charon[16585]: 00[LIB] stat() on '/etc/ipsec.d/cacerts/cacert.der' failed: No such file or directory
2018-01-22T04:09:55.256161-08:00 INFO charon[16585]: 00[CFG] loading aa certificates from '/etc/ipsec.d/aacerts'
2018-01-22T04:09:55.256262-08:00 INFO charon[16585]: 00[CFG] loading ocsp signer certificates from '/etc/ipsec.d/ocspcerts'
2018-01-22T04:09:55.256354-08:00 INFO charon[16585]: 00[CFG] loading attribute certificates from '/etc/ipsec.d/acerts'
2018-01-22T04:09:55.256448-08:00 INFO charon[16585]: 00[CFG] loading crls from '/etc/ipsec.d/crls'
2018-01-22T04:09:55.256548-08:00 INFO charon[16585]: 00[CFG] loading secrets from '/etc/ipsec.secrets'
2018-01-22T04:09:55.256704-08:00 INFO charon[16585]: 00[CFG]   loaded IKE secret for 10.9.8.2 10.9.8.1
2018-01-22T04:09:55.256800-08:00 INFO charon[16585]: 00[CFG]   loaded EAP secret for wrong_user
2018-01-22T04:09:55.257383-08:00 INFO charon[16585]: 00[CFG] no threshold configured for systime-fix, disabled
2018-01-22T04:09:55.257544-08:00 INFO charon[16585]: 00[LIB] loaded plugins: charon pkcs11 aes des rc2 sha2 sha1 md5 random nonce x509 revocation constraints pubkey pkcs1 pkcs7 pkcs8 pkcs12 pgp dnskey sshkey pem openssl fips-prf gmp curve25519 xcbc cmac hmac attr kernel-netlink resolve socket-default socket-dynamic stroke vici updown xauth-generic xauth-pam lookip led
2018-01-22T04:09:55.258093-08:00 INFO charon[16585]: 00[LIB] dropped capabilities, running as uid 212, gid 212
2018-01-22T04:09:55.258471-08:00 INFO charon[16585]: 00[JOB] spawning 16 worker threads
2018-01-22T04:09:55.266370-08:00 INFO l2tpipsec_vpn[16578]: ipsec[16579]: charon (16585) started after 100 ms
2018-01-22T04:09:55.266755-08:00 INFO charon[16585]: 06[CFG] received stroke: add connection 'managed'
2018-01-22T04:09:55.267326-08:00 INFO charon[16585]: 06[CFG] added configuration 'managed'
2018-01-22T04:09:55.267720-08:00 INFO charon[16585]: 08[CFG] received stroke: initiate 'managed'
2018-01-22T04:09:55.268225-08:00 INFO charon[16585]: 08[IKE] initiating Main Mode IKE_SA managed[1] to 10.9.8.1
2018-01-22T04:09:55.268249-08:00 INFO charon[16585]: 08[IKE] initiating Main Mode IKE_SA managed[1] to 10.9.8.1
2018-01-22T04:09:55.268480-08:00 INFO charon[16585]: 08[ENC] generating ID_PROT request 0 [ SA V V V V V ]
2018-01-22T04:09:55.268737-08:00 INFO charon[16585]: 08[NET] sending packet: from 10.9.8.2[500] to 10.9.8.1[500] (340 bytes)
2018-01-22T04:09:55.284045-08:00 INFO charon[16585]: 10[NET] received packet: from 10.9.8.1[500] to 10.9.8.2[500] (160 bytes)
2018-01-22T04:09:55.284186-08:00 INFO charon[16585]: 10[ENC] parsed ID_PROT response 0 [ SA V V V V ]
2018-01-22T04:09:55.284232-08:00 INFO charon[16585]: 10[IKE] received XAuth vendor ID
2018-01-22T04:09:55.284263-08:00 INFO charon[16585]: 10[IKE] received DPD vendor ID
2018-01-22T04:09:55.284289-08:00 INFO charon[16585]: 10[IKE] received FRAGMENTATION vendor ID
2018-01-22T04:09:55.284317-08:00 INFO charon[16585]: 10[IKE] received NAT-T (RFC 3947) vendor ID
2018-01-22T04:09:55.333506-08:00 INFO charon[16585]: 10[ENC] generating ID_PROT request 0 [ KE No NAT-D NAT-D ]
2018-01-22T04:09:55.333633-08:00 INFO charon[16585]: 10[NET] sending packet: from 10.9.8.2[500] to 10.9.8.1[500] (372 bytes)
2018-01-22T04:09:55.420513-08:00 INFO charon[16585]: 12[NET] received packet: from 10.9.8.1[500] to 10.9.8.2[500] (372 bytes)
2018-01-22T04:09:55.420588-08:00 INFO charon[16585]: 12[ENC] parsed ID_PROT response 0 [ KE No NAT-D NAT-D ]
2018-01-22T04:09:55.453879-08:00 INFO charon[16585]: 12[ENC] generating ID_PROT request 0 [ ID HASH ]
2018-01-22T04:09:55.453978-08:00 INFO charon[16585]: 12[NET] sending packet: from 10.9.8.2[500] to 10.9.8.1[500] (76 bytes)
2018-01-22T04:09:55.457753-08:00 INFO charon[16585]: 05[NET] received packet: from 10.9.8.1[500] to 10.9.8.2[500] (76 bytes)
2018-01-22T04:09:55.457825-08:00 INFO charon[16585]: 05[ENC] parsed ID_PROT response 0 [ ID HASH ]
2018-01-22T04:09:55.457965-08:00 INFO charon[16585]: 13[NET] received packet: from 10.9.8.1[500] to 10.9.8.2[500] (76 bytes)
2018-01-22T04:09:55.458042-08:00 INFO charon[16585]: 13[ENC] parsed TRANSACTION request 1402797103 [ HASH CPRQ(X_USER X_PWD) ]
2018-01-22T04:09:55.458138-08:00 INFO charon[16585]: 13[ENC] generating TRANSACTION response 1402797103 [ HASH CPRP(X_USER X_PWD) ]
2018-01-22T04:09:55.458220-08:00 INFO charon[16585]: 13[NET] sending packet: from 10.9.8.2[500] to 10.9.8.1[500] (108 bytes)
2018-01-22T04:09:55.461132-08:00 INFO charon[16585]: 14[NET] received packet: from 10.9.8.1[500] to 10.9.8.2[500] (76 bytes)
2018-01-22T04:09:55.461235-08:00 INFO charon[16585]: 14[ENC] parsed TRANSACTION request 1765592680 [ HASH CPS(X_STATUS) ]
2018-01-22T04:09:55.461314-08:00 INFO charon[16585]: 14[IKE] XAuth authentication of 'wrong_user' (myself) failed
2018-01-22T04:09:55.461405-08:00 INFO charon[16585]: 14[ENC] generating TRANSACTION response 1765592680 [ HASH CPA(X_STATUS) ]
2018-01-22T04:09:55.461585-08:00 INFO charon[16585]: 14[NET] sending packet: from 10.9.8.2[500] to 10.9.8.1[500] (76 bytes)
2018-01-22T04:09:56.630885-08:00 ERR shill[28362]: [ERROR:error.cc(138)] [dns_client.cc(113)]: No valid DNS server addresses
2018-01-22T04:09:56.630926-08:00 ERR shill[28362]: [ERROR:http_request.cc(125)] Failed to start DNS client: No valid DNS server addresses
2018-01-22T04:09:56.631113-08:00 INFO shill[28362]: [INFO:portal_detector.cc(125)] Portal detection completed attempt 2 with phase==DNS, status==Failure, failures in content==0
2018-01-22T04:09:57.793586-08:00 INFO dhcpcd[16514]: pseudoethernet0: sending DISCOVER (xid 0x2f919ffd), next in 7.5 seconds
2018-01-22T04:09:59.638548-08:00 ERR shill[28362]: [ERROR:error.cc(138)] [dns_client.cc(113)]: No valid DNS server addresses
2018-01-22T04:09:59.638589-08:00 ERR shill[28362]: [ERROR:http_request.cc(125)] Failed to start DNS client: No valid DNS server addresses
2018-01-22T04:09:59.638800-08:00 INFO shill[28362]: [INFO:portal_detector.cc(125)] Portal detection completed attempt 3 with phase==DNS, status==Failure, failures in content==0
2018-01-22T04:09:59.639225-08:00 INFO shill[28362]: [INFO:service.cc(398)] Service 71: state Connected -> Portal
2018-01-22T04:09:59.639270-08:00 INFO shill[28362]: [INFO:manager.cc(1485)] Service 71 updated; state: Portal failure Unknown
2018-01-22T04:09:59.651181-08:00 INFO shill[28362]: [INFO:service.cc(312)] Suppressed autoconnect to service 2 (no carrier)
2018-01-22T04:09:59.651800-08:00 INFO shill[28362]: [INFO:connection_diagnostics.cc(277)] Connection diagnostics events:
2018-01-22T04:09:59.651842-08:00 INFO shill[28362]: [INFO:connection_diagnostics.cc(279)]   #0: Event: Portal detection          Phase: End (DNS)        Result: Failure   
2018-01-22T04:09:59.651866-08:00 INFO shill[28362]: [INFO:connection_diagnostics.cc(282)] Connection diagnostics completed. Connection issue: DNS servers responding to DNS queries, but sending invalid responses. DNS servers might be misconfigured.
2018-01-22T04:10:05.291433-08:00 INFO dhcpcd[16514]: pseudoethernet0: sending DISCOVER (xid 0x2f919ffd), next in 15.1 seconds
2018-01-22T04:10:20.363624-08:00 INFO dhcpcd[16514]: pseudoethernet0: sending DISCOVER (xid 0x2f919ffd), next in 31.5 seconds
2018-01-22T04:10:23.494689-08:00 INFO charon[16585]: 12[KNL] interface pseudoethernet0 deactivated
2018-01-22T04:10:23.494755-08:00 ERR dhcpcd[16514]: pseudoethernet0: dhcp if_readrawpacket: Network is down
2018-01-22T04:10:23.496141-08:00 INFO charon[16585]: 09[KNL] fe80::a824:feff:fe40:a6bf disappeared from pseudoethernet0
2018-01-22T04:10:23.496405-08:00 INFO charon[16585]: 10[KNL] 10.9.8.2 disappeared from pseudoethernet0
2018-01-22T04:10:23.496616-08:00 INFO charon[16585]: 12[KNL] interface pseudoethernet0 deleted
2018-01-22T04:10:23.533646-08:00 INFO dhcpcd[16514]: pseudoethernet0: removing interface
2018-01-22T04:10:23.533696-08:00 INFO dhcpcd[16514]: status changed to Release
2018-01-22T04:10:23.534085-08:00 INFO dhcpcd[16514]: dhcpcd exited
2018-01-22T04:10:23.535198-08:00 ERR shill[28362]: [ERROR:object_proxy.cc(582)] Failed to call method: org.chromium.dhcpcd.Release: object_path= /org/chromium/dhcpcd: org.freedesktop.DBus.Error.NoReply: Message recipient disconnected from message bus without replying
2018-01-22T04:10:23.535241-08:00 ERR shill[28362]: [ERROR:dbus_method_invoker.h(111)] CallMethodAndBlockWithTimeout(...): Domain=dbus, Code=org.freedesktop.DBus.Error.NoReply, Message=Message recipient disconnected from message bus without replying
2018-01-22T04:10:23.535278-08:00 INFO shill[28362]: [INFO:chromeos_dhcpcd_proxy.cc(63)] Release: dhcpcd daemon appears to have exited.
2018-01-22T04:10:23.535307-08:00 INFO shill[28362]: [INFO:dhcp_config.cc(210)] Stopping 16514 (ReleaseIP)


-----------------TEST LOG--------------------
Jan 22 12:09:56 14[JOB
==> /tmp/chroot.v3Y6wJP7h/var/log/startup.log <==
+ echo 16525
+ sleep 5
+ wait
+ echo 16527
/etc/chroot_startup.sh: line 7: 16527 Terminated              sleep 5
+ ip addr add 10.9.8.1/24 dev serverethernet0
+ ip link set serverethernet0 up
+ /usr/sbin/ipsec start
Starting strongSwan 5.5.3 IPsec [starter]...
+ /usr/sbin/xl2tpd -c /etc/xl2tpd/xl2tpd.conf -C /tmp/l2tpd.control
01/22 04:10:22.524 DEBUG|             utils:0212| Running 'minijail0 -e -C /tmp/chroot.v3Y6wJP7h -b /bin,/bin -b /dev,/dev -b /dev/pts,/dev/pts,1 -b /lib,/lib -b /proc,/proc -b /sbin,/sbin -b /sys,/sys -b /usr,/usr -b /usr/local,/usr/local /usr/sbin/ipsec stop'
01/22 04:10:22.602 DEBUG|             utils:0280| [stderr] Stopping strongSwan IPsec...
01/22 04:10:22.794 DEBUG|             utils:0212| Running 'kill 16546'
01/22 04:10:32.813 DEBUG|             utils:0212| Running 'rm -rf --one-file-system /tmp/chroot.v3Y6wJP7h'
01/22 04:10:32.830 DEBUG|             utils:0212| Running 'iptables -D INPUT -i serverethernet0 -j ACCEPT'
01/22 04:10:32.845 DEBUG|             utils:0212| Running 'iptables -D INPUT -i pseudoethernet0 -j ACCEPT'
01/22 04:10:32.861 DEBUG|             utils:0212| Running 'ip addr show serverethernet0 2> /dev/null'
01/22 04:10:32.882 DEBUG|             utils:0212| Running 'ip addr show pseudoethernet0 2> /dev/null'
01/22 04:10:32.901 WARNI|virtual_ethernet_p:0129| VirtualEthernetPair.teardown() called, but no interface was found.
01/22 04:10:32.918 DEBUG|              test:0410| Test failed due to Error pinging server IP. Exception log follows the after_iteration_hooks.
01/22 04:10:32.919 DEBUG|              test:0415| Starting after_iteration_hooks for network_VPNConnect.l2tpipsec_xauth
01/22 04:10:32.922 DEBUG|      base_sysinfo:0124| Loggable saves logs to /usr/local/autotest/results/default/network_VPNConnect.l2tpipsec_xauth/sysinfo/iteration.1/interrupts.after
01/22 04:10:32.924 DEBUG|             utils:0212| Running 'mkdir -p /usr/local/autotest/results/default/network_VPNConnect.l2tpipsec_xauth/sysinfo/iteration.1/var/spool'
01/22 04:10:32.940 DEBUG|             utils:0212| Running 'rsync --no-perms --chmod=ugo+r -a --safe-links --exclude=/crash/**autoserv* --exclude=/crash/*.core /var/spool/crash /usr/local/autotest/results/default/network_VPNConnect.l2tpipsec_xauth/sysinfo/iteration.1/var/spool'
01/22 04:10:32.958 DEBUG|             utils:0212| Running 'rm -rf /var/spool/crash/*'
01/22 04:10:32.974 DEBUG|      base_sysinfo:0124| Loggable saves logs to /usr/local/autotest/results/default/network_VPNConnect.l2tpipsec_xauth/sysinfo/iteration.1/meminfo.after
01/22 04:10:32.976 DEBUG|      base_sysinfo:0124| Loggable saves logs to /usr/local/autotest/results/default/network_VPNConnect.l2tpipsec_xauth/sysinfo/iteration.1/slabinfo.after
01/22 04:10:32.977 DEBUG|      base_sysinfo:0124| Loggable saves logs to /usr/local/autotest/results/default/network_VPNConnect.l2tpipsec_xauth/sysinfo/iteration.1/schedstat.after
01/22 04:10:32.978 DEBUG|             utils:0212| Running 'logger "autotest finished iteration /usr/local/autotest/results/default/network_VPNConnect.l2tpipsec_xauth/sysinfo/iteration.1"'
01/22 04:10:32.990 DEBUG|              test:0420| after_iteration_hooks completed
01/22 04:10:32.991 WARNI|              test:0637| The test failed with the following exception
Traceback (most recent call last):
  File "/usr/local/autotest/common_lib/test.py", line 631, in _exec
    _call_test_function(self.execute, *p_args, **p_dargs)
  File "/usr/local/autotest/common_lib/test.py", line 831, in _call_test_function
    return func(*args, **dargs)
  File "/usr/local/autotest/common_lib/test.py", line 495, in execute
    dargs)
  File "/usr/local/autotest/common_lib/test.py", line 362, in _call_run_once_with_retry
    postprocess_profiled_run, args, dargs)
  File "/usr/local/autotest/common_lib/test.py", line 400, in _call_run_once
    self.run_once(*args, **dargs)
  File "/usr/local/autotest/tests/network_VPNConnect/network_VPNConnect.py", line 216, in run_once
    self.run_vpn_test(vpn_type)
  File "/usr/local/autotest/tests/network_VPNConnect/network_VPNConnect.py", line 255, in run_vpn_test
    raise error.TestFail('Error pinging server IP')
TestFail: Error pinging server IP

Comment 1 by cernekee@chromium.org, Jan 22 2018 

Aww crud, I guess ping probably has to run as chronos rather than root...

Surprised this test isn't part of the CQ.  We could have caught this a long time ago.

Comment 2 by harpreet@chromium.org, Feb 13 2018

Labels: wifi-test-failures
Project Member

Comment 3 by bugdroid1@chromium.org, Feb 21 2018 

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/0f709a6baf883726cd64e80687766eefedac8d18

commit 0f709a6baf883726cd64e80687766eefedac8d18
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Wed Feb 21 04:31:48 2018

network_VPNConnect: Run `ping` as the correct UID

Now that VPN uses per-device routing tables, UID 1000 (chronos/Chrome)
can send traffic over the VPN but UID 0 (root) cannot.  Change the
autotest so that `ping` runs as chronos.

This fixes:

    network_VPNConnect.l2tpipsec_cert
    network_VPNConnect.l2tpipsec_xauth
    network_VPNConnect.openvpn_user_pass
    network_VPNConnect.openvpn

network_VPNConnect.l2tpipsec_psk appears to be broken for other reasons
(charon logs a 'wrong_user' error during connection setup so it is
unrelated to the ping UID).

Note that this changes ping() to invoke `su -c ...` rather than plumbing
the user logic through run() and BgJob.  We may want to reconsider this
approach if other tests need similar functionality, but for now, this
was the most straightforward approach.

BUG= chromium:804524 
TEST=test_that

Change-Id: I0bd229837d02673768dab853e212cd621b67032b
Reviewed-on: https://chromium-review.googlesource.com/924632
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Kirtika Ruchandani <kirtika@chromium.org>

[modify] https://crrev.com/0f709a6baf883726cd64e80687766eefedac8d18/client/common_lib/utils.py
[modify] https://crrev.com/0f709a6baf883726cd64e80687766eefedac8d18/client/site_tests/network_VPNConnect/network_VPNConnect.py
Project Member

Comment 4 by bugdroid1@chromium.org, Feb 22 2018 

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/2008ad60659ed9114f519a094a5068e54a1ed916

commit 2008ad60659ed9114f519a094a5068e54a1ed916
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Thu Feb 22 03:51:59 2018

network_VPNConnect: ping check fails when _expect_success is False

If self._expect_success is False, it means that the VPN client is
intentionally using incorrect credentials, therefore the VPN connection
should not be established.  Skip the ping check if the VPN isn't up.

BUG= chromium:804524 
TEST=`test_that -b eve IP network_VPNConnect.l2tpipsec_psk \
                          network_VPNConnect.l2tpipsec_cert \
                          network_VPNConnect.l2tpipsec_xauth \
                          network_VPNConnect.openvpn_user_pass \
                          network_VPNConnect.openvpn`

Change-Id: I526f83600613ebc9c90b51af311e32df85d0b993
Reviewed-on: https://chromium-review.googlesource.com/924763
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>

[modify] https://crrev.com/2008ad60659ed9114f519a094a5068e54a1ed916/client/site_tests/network_VPNConnect/network_VPNConnect.py

Comment 5 by cernekee@chromium.org, Feb 22 2018

Status: Fixed (was: Available)
These should all be passing now.

Comment 7 by harpreet@chromium.org, Mar 6 2018

Labels: Merge-Request-65
Lets merge this back to M65.

I also opened crbug.com/819045 to add this test(s) to bvt-cq.
Project Member

Comment 8 by sheriffbot@chromium.org, Mar 6 2018

Labels: -Merge-Request-65 Merge-Review-65 Hotlist-Merge-Review
This bug requires manual review: Request affecting a post-stable build
Please contact the milestone owner if you have questions.
Owners: cmasso@(Android), cmasso@(iOS), bhthompson@(ChromeOS), govind@(Desktop)

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot

Comment 9 by bhthompson@google.com, Mar 6 2018

Labels: -Hotlist-Merge-Review -Merge-Review-65 Merge-Approved-65
Project Member

Comment 10 by sheriffbot@chromium.org, Mar 12 2018

Cc: bhthompson@google.com
This issue has been approved for a merge. Please merge the fix to any appropriate branches as soon as possible!

If all merges have been completed, please remove any remaining Merge-Approved labels from this issue.

Thanks for your time! To disable nags, add the Disable-Nags label.

For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
Project Member

Comment 11 by bugdroid1@chromium.org, Mar 12 2018

Labels: merge-merged-release-R65-10323.B
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/7cc3a0181f0c2e6ba401f1ad997ed994295d67ec

commit 7cc3a0181f0c2e6ba401f1ad997ed994295d67ec
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Mon Mar 12 16:33:40 2018

network_VPNConnect: Run `ping` as the correct UID

Now that VPN uses per-device routing tables, UID 1000 (chronos/Chrome)
can send traffic over the VPN but UID 0 (root) cannot.  Change the
autotest so that `ping` runs as chronos.

This fixes:

    network_VPNConnect.l2tpipsec_cert
    network_VPNConnect.l2tpipsec_xauth
    network_VPNConnect.openvpn_user_pass
    network_VPNConnect.openvpn

network_VPNConnect.l2tpipsec_psk appears to be broken for other reasons
(charon logs a 'wrong_user' error during connection setup so it is
unrelated to the ping UID).

Note that this changes ping() to invoke `su -c ...` rather than plumbing
the user logic through run() and BgJob.  We may want to reconsider this
approach if other tests need similar functionality, but for now, this
was the most straightforward approach.

BUG= chromium:804524 
TEST=test_that

Change-Id: I0bd229837d02673768dab853e212cd621b67032b
Reviewed-on: https://chromium-review.googlesource.com/924632
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Kirtika Ruchandani <kirtika@chromium.org>
(cherry picked from commit 0f709a6baf883726cd64e80687766eefedac8d18)
Reviewed-on: https://chromium-review.googlesource.com/959181
Reviewed-by: Kevin Cernekee <cernekee@chromium.org>
Commit-Queue: Kevin Cernekee <cernekee@chromium.org>

[modify] https://crrev.com/7cc3a0181f0c2e6ba401f1ad997ed994295d67ec/client/common_lib/utils.py
[modify] https://crrev.com/7cc3a0181f0c2e6ba401f1ad997ed994295d67ec/client/site_tests/network_VPNConnect/network_VPNConnect.py
Project Member

Comment 12 by bugdroid1@chromium.org, Mar 12 2018 

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/aa3378251fede517ed2b92f51ae51dfec3402b33

commit aa3378251fede517ed2b92f51ae51dfec3402b33
Author: Kevin Cernekee <cernekee@chromium.org>
Date: Mon Mar 12 16:34:04 2018

network_VPNConnect: ping check fails when _expect_success is False

If self._expect_success is False, it means that the VPN client is
intentionally using incorrect credentials, therefore the VPN connection
should not be established.  Skip the ping check if the VPN isn't up.

BUG= chromium:804524 
TEST=`test_that -b eve IP network_VPNConnect.l2tpipsec_psk \
                          network_VPNConnect.l2tpipsec_cert \
                          network_VPNConnect.l2tpipsec_xauth \
                          network_VPNConnect.openvpn_user_pass \
                          network_VPNConnect.openvpn`

Change-Id: I526f83600613ebc9c90b51af311e32df85d0b993
Reviewed-on: https://chromium-review.googlesource.com/924763
Commit-Ready: Kevin Cernekee <cernekee@chromium.org>
Tested-by: Kevin Cernekee <cernekee@chromium.org>
Reviewed-by: Harpreet Grewal <harpreet@chromium.org>
(cherry picked from commit 2008ad60659ed9114f519a094a5068e54a1ed916)
Reviewed-on: https://chromium-review.googlesource.com/959182
Reviewed-by: Kevin Cernekee <cernekee@chromium.org>
Commit-Queue: Kevin Cernekee <cernekee@chromium.org>

[modify] https://crrev.com/aa3378251fede517ed2b92f51ae51dfec3402b33/client/site_tests/network_VPNConnect/network_VPNConnect.py

Comment 13 by cernekee@chromium.org, Mar 12 2018

Labels: -Merge-Approved-65
►

Sign in to add a comment