1# Copyright (c) 2012 The Chromium OS Authors. All rights reserved.
2# Use of this source code is governed by a BSD-style license that can be
3# found in the LICENSE file.
4
5import collections, logging, numpy, os, tempfile, time
6from autotest_lib.client.bin import utils, test
7from autotest_lib.client.common_lib import error
8from autotest_lib.client.common_lib import file_utils
9from autotest_lib.client.common_lib.cros import chrome
10from autotest_lib.client.common_lib.cros.network import xmlrpc_datatypes
11from autotest_lib.client.common_lib.cros.network import xmlrpc_security_types
12from autotest_lib.client.cros import backchannel, httpd
13from autotest_lib.client.cros import memory_bandwidth_logger
14from autotest_lib.client.cros import power_rapl, power_status, power_utils
15from autotest_lib.client.cros import service_stopper
16from autotest_lib.client.cros.audio import audio_helper
17from autotest_lib.client.cros.networking import wifi_proxy
18from telemetry.core import exceptions
19
20params_dict = {
21    'test_time_ms': '_mseconds',
22    'should_scroll': '_should_scroll',
23    'should_scroll_up': '_should_scroll_up',
24    'scroll_loop': '_scroll_loop',
25    'scroll_interval_ms': '_scroll_interval_ms',
26    'scroll_by_pixels': '_scroll_by_pixels',
27    'tasks': '_tasks',
28}
29
30class power_LoadTest(test.test):
31    """test class"""
32    version = 2
33    _username = 'powerloadtest@gmail.com'
34    _pltp_url = 'https://sites.google.com/a/chromium.org/dev/chromium-os' \
35                '/testing/power-testing/pltp/pltp'
36
37
38    def initialize(self, percent_initial_charge_min=None,
39                 check_network=True, loop_time=3600, loop_count=1,
40                 should_scroll='true', should_scroll_up='true',
41                 scroll_loop='false', scroll_interval_ms='10000',
42                 scroll_by_pixels='600', test_low_batt_p=3,
43                 verbose=True, force_wifi=False, wifi_ap='', wifi_sec='none',
44                 wifi_pw='', wifi_timeout=60, tasks='',
45                 volume_level=10, mic_gain=10, low_batt_margin_p=2,
46                 ac_ok=False, log_mem_bandwidth=False, gaia_login=True):
47        """
48        percent_initial_charge_min: min battery charge at start of test
49        check_network: check that Ethernet interface is not running
50        loop_time: length of time to run the test for in each loop
51        loop_count: number of times to loop the test for
52        should_scroll: should the extension scroll pages
53        should_scroll_up: should scroll in up direction
54        scroll_loop: continue scrolling indefinitely
55        scroll_interval_ms: how often to scoll
56        scroll_by_pixels: number of pixels to scroll each time
57        test_low_batt_p: percent battery at which test should stop
58        verbose: add more logging information
59        force_wifi: should we force to test to run on wifi
60        wifi_ap: the name (ssid) of the wifi access point
61        wifi_sec: the type of security for the wifi ap
62        wifi_pw: password for the wifi ap
63        wifi_timeout: The timeout for wifi configuration
64        volume_level: percent audio volume level
65        mic_gain: percent audio microphone gain level
66        low_batt_margin_p: percent low battery margin to be added to
67            sys_low_batt_p to guarantee test completes prior to powerd shutdown
68        ac_ok: boolean to allow running on AC
69        log_mem_bandwidth: boolean to log memory bandwidth during the test
70        gaia_login: boolean of whether real GAIA login should be attempted.
71        """
72        self._backlight = None
73        self._services = None
74        self._browser = None
75        self._loop_time = loop_time
76        self._loop_count = loop_count
77        self._mseconds = self._loop_time * 1000
78        self._verbose = verbose
79
80        self._sys_low_batt_p = 0.
81        self._sys_low_batt_s = 0.
82        self._test_low_batt_p = test_low_batt_p
83        self._should_scroll = should_scroll
84        self._should_scroll_up = should_scroll_up
85        self._scroll_loop = scroll_loop
86        self._scroll_interval_ms = scroll_interval_ms
87        self._scroll_by_pixels = scroll_by_pixels
88        self._tmp_keyvals = {}
89        self._power_status = None
90        self._force_wifi = force_wifi
91        self._testServer = None
92        self._tasks = tasks.replace(' ','')
93        self._backchannel = None
94        self._shill_proxy = None
95        self._volume_level = volume_level
96        self._mic_gain = mic_gain
97        self._ac_ok = ac_ok
98        self._log_mem_bandwidth = log_mem_bandwidth
99        self._wait_time = 60
100        self._stats = collections.defaultdict(list)
101        self._gaia_login = gaia_login
102
103        if not power_utils.has_battery():
104            rsp = "Device designed without battery. Skipping test."
105            raise error.TestNAError(rsp)
106        self._power_status = power_status.get_status()
107        self._tmp_keyvals['b_on_ac'] = self._power_status.on_ac()
108
109        with tempfile.NamedTemporaryFile() as pltp:
110            file_utils.download_file(self._pltp_url, pltp.name)
111            self._password = pltp.read().rstrip()
112
113        if not ac_ok:
114            self._power_status.assert_battery_state(percent_initial_charge_min)
115        # If force wifi enabled, convert eth0 to backchannel and connect to the
116        # specified WiFi AP.
117        if self._force_wifi:
118            sec_config = None
119            # TODO(dbasehore): Fix this when we get a better way of figuring out
120            # the wifi security configuration.
121            if wifi_sec == 'rsn' or wifi_sec == 'wpa':
122                sec_config = xmlrpc_security_types.WPAConfig(
123                        psk=wifi_pw,
124                        wpa_mode=xmlrpc_security_types.WPAConfig.MODE_PURE_WPA2,
125                        wpa2_ciphers=
126                                [xmlrpc_security_types.WPAConfig.CIPHER_CCMP])
127            wifi_config = xmlrpc_datatypes.AssociationParameters(
128                    ssid=wifi_ap, security_config=sec_config,
129                    configuration_timeout=wifi_timeout)
130            # If backchannel is already running, don't run it again.
131            self._backchannel = backchannel.Backchannel()
132            if not self._backchannel.setup():
133                raise error.TestError('Could not setup Backchannel network.')
134
135            self._shill_proxy = wifi_proxy.WifiProxy()
136            self._shill_proxy.remove_all_wifi_entries()
137            for i in xrange(1,4):
138                raw_output = self._shill_proxy.connect_to_wifi_network(
139                        wifi_config.ssid,
140                        wifi_config.security,
141                        wifi_config.security_parameters,
142                        wifi_config.save_credentials,
143                        station_type=wifi_config.station_type,
144                        hidden_network=wifi_config.is_hidden,
145                        discovery_timeout_seconds=
146                                wifi_config.discovery_timeout,
147                        association_timeout_seconds=
148                                wifi_config.association_timeout,
149                        configuration_timeout_seconds=
150                                wifi_config.configuration_timeout * i)
151                result = xmlrpc_datatypes.AssociationResult. \
152                        from_dbus_proxy_output(raw_output)
153                if result.success:
154                    break
155                logging.warn('wifi connect: disc:%d assoc:%d config:%d fail:%s',
156                             result.discovery_time, result.association_time,
157                             result.configuration_time, result.failure_reason)
158            else:
159                raise error.TestError('Could not connect to WiFi network.')
160
161        else:
162            # Find all wired ethernet interfaces.
163            # TODO: combine this with code in network_DisableInterface, in a
164            # common library somewhere.
165            ifaces = [ nic.strip() for nic in os.listdir('/sys/class/net/')
166                if ((not os.path.exists('/sys/class/net/' + nic + '/phy80211'))
167                    and nic.find('eth') != -1) ]
168            logging.debug(str(ifaces))
169            for iface in ifaces:
170                if check_network and self._is_network_iface_running(iface):
171                    raise error.TestError('Ethernet interface is active. ' +
172                                          'Please remove Ethernet cable')
173
174        # record the max backlight level
175        self._backlight = power_utils.Backlight()
176        self._tmp_keyvals['level_backlight_max'] = \
177            self._backlight.get_max_level()
178
179        self._services = service_stopper.ServiceStopper(
180            service_stopper.ServiceStopper.POWER_DRAW_SERVICES)
181        self._services.stop_services()
182
183        # fix up file perms for the power test extension so that chrome
184        # can access it
185        os.system('chmod -R 755 %s' % self.bindir)
186
187        # setup a HTTP Server to listen for status updates from the power
188        # test extension
189        self._testServer = httpd.HTTPListener(8001, docroot=self.bindir)
190        self._testServer.run()
191
192        # initialize various interesting power related stats
193        self._statomatic = power_status.StatoMatic()
194
195        self._power_status.refresh()
196        help_output = utils.system_output('check_powerd_config --help')
197        if 'low_battery_shutdown' in help_output:
198          logging.info('Have low_battery_shutdown option')
199          self._sys_low_batt_p = float(utils.system_output(
200                  'check_powerd_config --low_battery_shutdown_percent'))
201          self._sys_low_batt_s = int(utils.system_output(
202                  'check_powerd_config --low_battery_shutdown_time'))
203        else:
204          # TODO(dchan) Once M57 in stable, remove this option and function.
205          logging.info('No low_battery_shutdown option')
206          (self._sys_low_batt_p, self._sys_low_batt_s) = \
207              self._get_sys_low_batt_values_from_log()
208
209        if self._sys_low_batt_p and self._sys_low_batt_s:
210            raise error.TestError(
211                    "Low battery percent and seconds are non-zero.")
212
213        min_low_batt_p = min(self._sys_low_batt_p + low_batt_margin_p, 100)
214        if self._sys_low_batt_p and (min_low_batt_p > self._test_low_batt_p):
215            logging.warning("test low battery threshold is below system " +
216                         "low battery requirement.  Setting to %f",
217                         min_low_batt_p)
218            self._test_low_batt_p = min_low_batt_p
219
220        self._ah_charge_start = self._power_status.battery[0].charge_now
221        self._wh_energy_start = self._power_status.battery[0].energy
222
223
224    def run_once(self):
225        t0 = time.time()
226
227        # record the PSR related info.
228        psr = power_utils.DisplayPanelSelfRefresh(init_time=t0)
229
230        try:
231            self._keyboard_backlight = power_utils.KbdBacklight()
232            self._set_keyboard_backlight_level()
233        except power_utils.KbdBacklightException as e:
234            logging.info("Assuming no keyboard backlight due to :: %s", str(e))
235            self._keyboard_backlight = None
236
237        measurements = \
238            [power_status.SystemPower(self._power_status.battery_path)]
239        if power_utils.has_rapl_support():
240            measurements += power_rapl.create_rapl()
241        self._plog = power_status.PowerLogger(measurements, seconds_period=20)
242        self._tlog = power_status.TempLogger([], seconds_period=20)
243        self._plog.start()
244        self._tlog.start()
245        if self._log_mem_bandwidth:
246            self._mlog = memory_bandwidth_logger.MemoryBandwidthLogger(
247                raw=False, seconds_period=2)
248            self._mlog.start()
249
250        ext_path = os.path.join(os.path.dirname(__file__), 'extension')
251        self._tmp_keyvals['username'] = self._username
252        try:
253            self._browser = chrome.Chrome(extension_paths=[ext_path],
254                                          gaia_login=self._gaia_login,
255                                          username=self._username,
256                                          password=self._password)
257        except exceptions.LoginException:
258            # already failed guest login
259            if not self._gaia_login:
260                raise
261            self._gaia_login = False
262            logging.warn("Unable to use GAIA acct %s.  Using GUEST instead.\n",
263                         self._username)
264            self._browser = chrome.Chrome(extension_paths=[ext_path],
265                                          gaia_login=self._gaia_login)
266        if not self._gaia_login:
267            self._tmp_keyvals['username'] = 'GUEST'
268
269        extension = self._browser.get_extension(ext_path)
270        for k in params_dict:
271            if getattr(self, params_dict[k]) is not '':
272                extension.ExecuteJavaScript('var %s = %s;' %
273                                            (k, getattr(self, params_dict[k])))
274
275        # This opens a trap start page to capture tabs opened for first login.
276        # It will be closed when startTest is run.
277        extension.ExecuteJavaScript('chrome.windows.create(null, null);')
278
279        for i in range(self._loop_count):
280            start_time = time.time()
281            extension.ExecuteJavaScript('startTest();')
282            # the power test extension will report its status here
283            latch = self._testServer.add_wait_url('/status')
284
285            # this starts a thread in the server that listens to log
286            # information from the script
287            script_logging = self._testServer.add_wait_url(url='/log')
288
289            # dump any log entry that comes from the script into
290            # the debug log
291            self._testServer.add_url_handler(url='/log',\
292                handler_func=(lambda handler, forms, loop_counter=i:\
293                    _extension_log_handler(handler, forms, loop_counter)))
294
295            pagelt_tracking = self._testServer.add_wait_url(url='/pagelt')
296
297            self._testServer.add_url_handler(url='/pagelt',\
298                handler_func=(lambda handler, forms, tracker=self, loop_counter=i:\
299                    _extension_page_load_info_handler(handler, forms, loop_counter, self)))
300
301            # reset backlight level since powerd might've modified it
302            # based on ambient light
303            self._set_backlight_level()
304            self._set_lightbar_level()
305            if self._keyboard_backlight:
306                self._set_keyboard_backlight_level()
307            audio_helper.set_volume_levels(self._volume_level,
308                                           self._mic_gain)
309
310            low_battery = self._do_wait(self._verbose, self._loop_time,
311                                        latch)
312
313            script_logging.set();
314            pagelt_tracking.set();
315            self._plog.checkpoint('loop%d' % (i), start_time)
316            self._tlog.checkpoint('loop%d' % (i), start_time)
317            if self._verbose:
318                logging.debug('loop %d completed', i)
319
320            if low_battery:
321                logging.info('Exiting due to low battery')
322                break
323
324        # done with logging from the script, so we can collect that thread
325        t1 = time.time()
326        psr.refresh()
327        self._tmp_keyvals['minutes_battery_life_tested'] = (t1 - t0) / 60
328        self._tmp_keyvals.update(psr.get_keyvals())
329
330
331    def postprocess_iteration(self):
332        def _log_stats(prefix, stats):
333            if not len(stats):
334                return
335            np = numpy.array(stats)
336            logging.debug("%s samples: %d", prefix, len(np))
337            logging.debug("%s mean:    %.2f", prefix, np.mean())
338            logging.debug("%s stdev:   %.2f", prefix, np.std())
339            logging.debug("%s max:     %.2f", prefix, np.max())
340            logging.debug("%s min:     %.2f", prefix, np.min())
341
342
343        def _log_per_loop_stats():
344            samples_per_loop = self._loop_time / self._wait_time + 1
345            for kname in self._stats:
346                start_idx = 0
347                loop = 1
348                for end_idx in xrange(samples_per_loop, len(self._stats[kname]),
349                                      samples_per_loop):
350                    _log_stats("%s loop %d" % (kname, loop),
351                               self._stats[kname][start_idx:end_idx])
352                    loop += 1
353                    start_idx = end_idx
354
355
356        def _log_all_stats():
357            for kname in self._stats:
358                _log_stats(kname, self._stats[kname])
359
360
361        keyvals = self._plog.calc()
362        keyvals.update(self._tlog.calc())
363        keyvals.update(self._statomatic.publish())
364
365        if self._log_mem_bandwidth:
366            self._mlog.stop()
367            self._mlog.join()
368
369        _log_all_stats()
370        _log_per_loop_stats()
371
372        # record battery stats
373        keyvals['a_current_now'] = self._power_status.battery[0].current_now
374        keyvals['ah_charge_full'] = self._power_status.battery[0].charge_full
375        keyvals['ah_charge_full_design'] = \
376                             self._power_status.battery[0].charge_full_design
377        keyvals['ah_charge_start'] = self._ah_charge_start
378        keyvals['ah_charge_now'] = self._power_status.battery[0].charge_now
379        keyvals['ah_charge_used'] = keyvals['ah_charge_start'] - \
380                                    keyvals['ah_charge_now']
381        keyvals['wh_energy_start'] = self._wh_energy_start
382        keyvals['wh_energy_now'] = self._power_status.battery[0].energy
383        keyvals['wh_energy_used'] = keyvals['wh_energy_start'] - \
384                                    keyvals['wh_energy_now']
385        keyvals['v_voltage_min_design'] = \
386                             self._power_status.battery[0].voltage_min_design
387        keyvals['wh_energy_full_design'] = \
388                             self._power_status.battery[0].energy_full_design
389        keyvals['v_voltage_now'] = self._power_status.battery[0].voltage_now
390
391        keyvals.update(self._tmp_keyvals)
392
393        keyvals['percent_sys_low_battery'] = self._sys_low_batt_p
394        keyvals['seconds_sys_low_battery'] = self._sys_low_batt_s
395        voltage_np = numpy.array(self._stats['v_voltage_now'])
396        voltage_mean = voltage_np.mean()
397        keyvals['v_voltage_mean'] = voltage_mean
398
399        keyvals['wh_energy_powerlogger'] = \
400                             self._energy_use_from_powerlogger(keyvals)
401
402        if keyvals['ah_charge_used'] > 0 and not self._power_status.on_ac():
403            # For full runs, we should use charge to scale for battery life,
404            # since the voltage swing is accounted for.
405            # For short runs, energy will be a better estimate.
406            if self._loop_count > 1:
407                estimated_reps = (keyvals['ah_charge_full_design'] /
408                                  keyvals['ah_charge_used'])
409            else:
410                estimated_reps = (keyvals['wh_energy_full_design'] /
411                                  keyvals['wh_energy_powerlogger'])
412
413            bat_life_scale =  estimated_reps * \
414                              ((100 - keyvals['percent_sys_low_battery']) / 100)
415
416            keyvals['minutes_battery_life'] = bat_life_scale * \
417                keyvals['minutes_battery_life_tested']
418            # In the case where sys_low_batt_s is non-zero subtract those
419            # minutes from the final extrapolation.
420            if self._sys_low_batt_s:
421                keyvals['minutes_battery_life'] -= self._sys_low_batt_s / 60
422
423            keyvals['a_current_rate'] = keyvals['ah_charge_used'] * 60 / \
424                                        keyvals['minutes_battery_life_tested']
425            keyvals['w_energy_rate'] = keyvals['wh_energy_used'] * 60 / \
426                                       keyvals['minutes_battery_life_tested']
427            if self._gaia_login:
428                self.output_perf_value(description='minutes_battery_life',
429                                       value=keyvals['minutes_battery_life'],
430                                       units='minutes',
431                                       higher_is_better=True)
432
433        if not self._gaia_login:
434            keyvals = dict(map(lambda (key, value):
435                               ('INVALID_' + str(key), value), keyvals.items()))
436        else:
437            for key, value in keyvals.iteritems():
438                if key.startswith('percent_cpuidle') and \
439                   key.endswith('C0_time'):
440                    self.output_perf_value(description=key,
441                                           value=value,
442                                           units='percent',
443                                           higher_is_better=False)
444
445        self.write_perf_keyval(keyvals)
446        self._plog.save_results(self.resultsdir)
447        self._tlog.save_results(self.resultsdir)
448
449
450    def cleanup(self):
451        if self._backlight:
452            self._backlight.restore()
453        if self._services:
454            self._services.restore_services()
455
456        # cleanup backchannel interface
457        # Prevent wifi congestion in test lab by forcing machines to forget the
458        # wifi AP we connected to at the start of the test.
459        if self._shill_proxy:
460            self._shill_proxy.remove_all_wifi_entries()
461        if self._backchannel:
462            self._backchannel.teardown()
463        if self._browser:
464            self._browser.close()
465        if self._testServer:
466            self._testServer.stop()
467
468
469    def _do_wait(self, verbose, seconds, latch):
470        latched = False
471        low_battery = False
472        total_time = seconds + self._wait_time
473        elapsed_time = 0
474
475        while elapsed_time < total_time:
476            time.sleep(self._wait_time)
477            elapsed_time += self._wait_time
478
479            self._power_status.refresh()
480
481            if not self._ac_ok and self._power_status.on_ac():
482                raise error.TestError('Running on AC power now.')
483
484            charge_now = self._power_status.battery[0].charge_now
485            energy_rate = self._power_status.battery[0].energy_rate
486            voltage_now = self._power_status.battery[0].voltage_now
487            self._stats['w_energy_rate'].append(energy_rate)
488            self._stats['v_voltage_now'].append(voltage_now)
489            if verbose:
490                logging.debug('ah_charge_now %f', charge_now)
491                logging.debug('w_energy_rate %f', energy_rate)
492                logging.debug('v_voltage_now %f', voltage_now)
493
494            low_battery = (self._power_status.percent_current_charge() <
495                           self._test_low_batt_p)
496
497            latched = latch.is_set()
498
499            if latched or low_battery:
500                break
501
502        if latched:
503            # record chrome power extension stats
504            form_data = self._testServer.get_form_entries()
505            logging.debug(form_data)
506            for e in form_data:
507                key = 'ext_' + e
508                if key in self._tmp_keyvals:
509                    self._tmp_keyvals[key] += "_%s" % form_data[e]
510                else:
511                    self._tmp_keyvals[key] = form_data[e]
512        else:
513            logging.debug("Didn't get status back from power extension")
514
515        return low_battery
516
517
518    def _set_backlight_level(self):
519        self._backlight.set_default()
520        # record brightness level
521        self._tmp_keyvals['level_backlight_current'] = \
522            self._backlight.get_level()
523
524
525    def _set_lightbar_level(self, level='off'):
526        """Set lightbar level.
527
528        Args:
529          level: string value to set lightbar to.  See ectool for more details.
530        """
531        rv = utils.system('which ectool', ignore_status=True)
532        if rv:
533            return
534        rv = utils.system('ectool lightbar %s' % level, ignore_status=True)
535        if rv:
536            logging.info('Assuming no lightbar due to non-zero exit status')
537        else:
538            logging.info('Setting lightbar to %s', level)
539            self._tmp_keyvals['level_lightbar_current'] = level
540
541
542    def _get_sys_low_batt_values_from_log(self):
543        """Determine the low battery values for device and return.
544
545        2012/11/01: power manager (powerd.cc) parses parameters in filesystem
546          and outputs a log message like:
547
548           [1101/173837:INFO:powerd.cc(258)] Using low battery time threshold
549                     of 0 secs and using low battery percent threshold of 3.5
550
551           It currently checks to make sure that only one of these values is
552           defined.
553
554        Returns:
555          Tuple of (percent, seconds)
556            percent: float of low battery percentage
557            seconds: float of low battery seconds
558
559        """
560        split_re = 'threshold of'
561
562        powerd_log = '/var/log/power_manager/powerd.LATEST'
563        cmd = 'grep "low battery time" %s' % powerd_log
564        line = utils.system_output(cmd)
565        secs = float(line.split(split_re)[1].split()[0])
566        percent = float(line.split(split_re)[2].split()[0])
567        return (percent, secs)
568
569
570    def _has_light_sensor(self):
571        """
572        Determine if there is a light sensor on the board.
573
574        @returns True if this host has a light sensor or
575                 False if it does not.
576        """
577        # If the command exits with a failure status,
578        # we do not have a light sensor
579        cmd = 'check_powerd_config --ambient_light_sensor'
580        result = utils.run(cmd, ignore_status=True)
581        if result.exit_status:
582            logging.debug('Ambient light sensor not present')
583            return False
584        logging.debug('Ambient light sensor present')
585        return True
586
587
588    def _is_network_iface_running(self, name):
589        """
590        Checks to see if the interface is running.
591
592        Args:
593          name: name of the interface to check.
594
595        Returns:
596          True if the interface is running.
597
598        """
599        try:
600            # TODO: Switch to 'ip' (crbug.com/410601).
601            out = utils.system_output('ifconfig %s' % name)
602        except error.CmdError, e:
603            logging.info(e)
604            return False
605
606        return out.find('RUNNING') >= 0
607
608
609    def _energy_use_from_powerlogger(self, keyval):
610        """
611        Calculates the energy use, in Wh, used over the course of the run as
612        reported by the PowerLogger.
613
614        Args:
615          keyval: the dictionary of keyvals containing PowerLogger output
616
617        Returns:
618          energy_wh: total energy used over the course of this run
619
620        """
621        energy_wh = 0
622        loop = 0
623        while True:
624            duration_key = 'loop%d_system_duration' % loop
625            avg_power_key = 'loop%d_system_pwr' % loop
626            if duration_key not in keyval or avg_power_key not in keyval:
627                break
628            energy_wh += keyval[duration_key] * keyval[avg_power_key] / 3600
629            loop += 1
630        return energy_wh
631
632
633    def _has_hover_detection(self):
634        """
635        Checks if hover is detected by the device.
636
637        Returns:
638            Returns True if the hover detection support is enabled.
639            Else returns false.
640        """
641
642        cmd = 'check_powerd_config --hover_detection'
643        result = utils.run(cmd, ignore_status=True)
644        if result.exit_status:
645            logging.debug('Hover not present')
646            return False
647        logging.debug('Hover present')
648        return True
649
650
651    def _set_keyboard_backlight_level(self):
652        """
653        Sets keyboard backlight based on light sensor and hover.
654        These values are based on UMA as mentioned in
655        https://bugs.chromium.org/p/chromium/issues/detail?id=603233#c10
656
657        ALS  | hover | keyboard backlight level
658        ---------------------------------------
659        No   | No    | default
660        ---------------------------------------
661        Yes  | No    | 40% of default
662        --------------------------------------
663        No   | Yes   | System with this configuration does not exist
664        --------------------------------------
665        Yes  | Yes   | 30% of default
666        --------------------------------------
667
668        Here default is no Ambient Light Sensor, no hover,
669        default always-on brightness level.
670        """
671
672        default_level = self._keyboard_backlight.get_default_level()
673        level_to_set = default_level
674        has_light_sensor = self._has_light_sensor()
675        has_hover = self._has_hover_detection()
676        # TODO(ravisadineni):if (crbug: 603233) becomes default
677        # change this to reflect it.
678        if has_light_sensor and has_hover:
679            level_to_set = (30 * default_level) / 100
680        elif has_light_sensor:
681            level_to_set = (40 * default_level) / 100
682        elif has_hover:
683            logging.warn('Device has hover but no light sensor')
684
685        logging.info('Setting keyboard backlight to %d', level_to_set)
686        self._keyboard_backlight.set_level(level_to_set)
687        self._tmp_keyvals['percent_kbd_backlight'] = \
688            self._keyboard_backlight.get_percent()
689
690def _extension_log_handler(handler, form, loop_number):
691    """
692    We use the httpd library to allow us to log whatever we
693    want from the extension JS script into the log files.
694
695    This method is provided to the server as a handler for
696    all requests that come for the log url in the testServer
697
698    unused parameter, because httpd passes the server itself
699    into the handler.
700    """
701    if form:
702        for field in form.keys():
703            logging.debug("[extension] @ loop_%d %s", loop_number,
704            form[field].value)
705            # we don't want to add url information to our keyvals.
706            # httpd adds them automatically so we remove them again
707            del handler.server._form_entries[field]
708
709def _extension_page_load_info_handler(handler, form, loop_number, tracker):
710    stats_ids = ['mean', 'min', 'max', 'std']
711    time_measurements = []
712    sorted_pagelt = []
713    #show up to this number of slow page-loads
714    num_slow_page_loads = 5;
715
716    if not form:
717        logging.debug("no page load information returned")
718        return;
719
720    for field in form.keys():
721        url = field[str.find(field, "http"):]
722        load_time = int(form[field].value)
723
724        time_measurements.append(load_time)
725        sorted_pagelt.append((url, load_time))
726
727        logging.debug("[extension] @ loop_%d url: %s load time: %d ms",
728            loop_number, url, load_time)
729        # we don't want to add url information to our keyvals.
730        # httpd adds them automatically so we remove them again
731        del handler.server._form_entries[field]
732
733    time_measurements = numpy.array(time_measurements)
734    stats_vals = [time_measurements.mean(), time_measurements.min(),
735    time_measurements.max(),time_measurements.std()]
736
737    key_base = 'ext_ms_page_load_time_'
738    for i in range(len(stats_ids)):
739        key = key_base + stats_ids[i]
740        if key in tracker._tmp_keyvals:
741            tracker._tmp_keyvals[key] += "_%.2f" % stats_vals[i]
742        else:
743            tracker._tmp_keyvals[key] = "%.2f" % stats_vals[i]
744
745
746    sorted_pagelt.sort(key=lambda item: item[1], reverse=True)
747
748    message = "The %d slowest page-load-times are:\n" % (num_slow_page_loads)
749    for url, msecs in sorted_pagelt[:num_slow_page_loads]:
750        message += "\t%s w/ %d ms" % (url, msecs)
751
752    logging.debug("%s\n", message)
753