firmware_TouchMTB: print metrics with missing values
[chromiumos/third_party/autotest.git] / client / cros / cros_ui_test.py
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
5 import glob, logging, os, re, shutil, subprocess, sys, time
6
7 import auth_server, common, constants, cros_logging, cros_ui, cryptohome
8 import dns_server, login, ownership, pyauto_test
9 from autotest_lib.client.bin import utils
10 from autotest_lib.client.common_lib import error
11
12 class UITest(pyauto_test.PyAutoTest):
13     """Base class for tests that drive some portion of the user interface.
14
15     By default subclasses will use the default remote credentials before
16     the run_once method is invoked, and will log out at the completion
17     of the test case even if an exception is thrown.
18
19     Subclasses can opt out of the automatic login by setting the member
20     variable 'auto_login' to False.
21
22     Subclasses can log in with arbitrary credentials by passing
23     the 'creds' parameter in their control file.  See the documentation of
24     UITest.initialize for more details.
25
26     If your subclass overrides the initialize() or cleanup() methods, it
27     should make sure to invoke this class' version of those methods as well.
28     The standard super(...) function cannot be used for this, since the base
29     test class is not a 'new style' Python class.
30     """
31     version = 1
32
33     skip_oobe = True
34     auto_login = True
35     fake_owner = True
36     username = None
37     password = None
38
39     # Processes that we know crash and are willing to ignore.
40     crash_blacklist = []
41
42     # ftrace-related files.
43     _ftrace_process_fork_event_enable_file = \
44         '/sys/kernel/debug/tracing/events/sched/sched_process_fork/enable'
45     _ftrace_process_fork_event_filter_file = \
46         '/sys/kernel/debug/tracing/events/sched/sched_process_fork/filter'
47     _ftrace_signal_generate_event_enable_file = \
48         '/sys/kernel/debug/tracing/events/signal/signal_generate/enable'
49     _ftrace_signal_generate_event_filter_file = \
50         '/sys/kernel/debug/tracing/events/signal/signal_generate/filter'
51     _ftrace_trace_file = '/sys/kernel/debug/tracing/trace'
52
53     _last_chrome_log = ''
54
55
56     def start_authserver(self, authenticator=None):
57         """Spin up a local mock of the Google Accounts server, then spin up
58         a local fake DNS server and tell the networking stack to use it.  This
59         will trick Chrome into talking to our mock when we login.
60         Subclasses can override this method to change this behavior.
61         """
62         self._authServer = auth_server.GoogleAuthServer(
63             authenticator=authenticator)
64         self._authServer.run()
65         self._dnsServer = dns_server.LocalDns()
66         self._dnsServer.run()
67
68
69     def stop_authserver(self):
70         """Tears down fake dns and fake Google Accounts server.  If your
71         subclass does not create these objects, you will want to override this
72         method as well.
73         """
74         if hasattr(self, '_authServer'):
75             self._authServer.stop()
76             del self._authServer
77         if hasattr(self, '_dnsServer'):
78             try:
79                 self._dnsServer.stop()
80             except utils.TimeoutError as err:
81                 raise error.TestWarn(err)
82             del self._dnsServer
83
84
85     def start_chrome_event_tracing(self):
86         """Start tracing events of a chrome process being created or receiving a
87         signal.
88         """
89         try:
90             # Clear the trace buffer.
91             utils.open_write_close(self._ftrace_trace_file, '')
92
93             # Trace only chrome process creation events, which we may later use
94             # to determine if a chrome process is killed by its parent.
95             utils.open_write_close(
96                 self._ftrace_process_fork_event_filter_file,
97                 'child_comm==chrome')
98             # Trace only chrome processes receiving any signal except for
99             # the uninteresting SIGPROF (sig 27 on x86 and arm).
100             utils.open_write_close(
101                 self._ftrace_signal_generate_event_filter_file,
102                 'comm==chrome && sig!=27')
103
104             # Enable the process_fork event tracing.
105             utils.open_write_close(
106                 self._ftrace_process_fork_event_enable_file, '1')
107             # Enable the signal_generate event tracing.
108             utils.open_write_close(
109                 self._ftrace_signal_generate_event_enable_file, '1')
110         except IOError as err:
111             logging.warning('Failed to start chrome signal tracing: %s', err)
112
113
114     def stop_chrome_event_tracing(self):
115         """Stop tracing events of a chrome process being created or receiving a
116         signal.
117         """
118         try:
119             # Disable the process_fork event tracing.
120             utils.open_write_close(
121                 self._ftrace_process_fork_event_enable_file, '0')
122             # Disable the signal_generate event tracing.
123             utils.open_write_close(
124                 self._ftrace_signal_generate_event_enable_file, '0')
125
126             # Clear the process_fork event filter.
127             utils.open_write_close(
128                 self._ftrace_process_fork_event_filter_file, '0')
129             # Clear the signal_generate event filter.
130             utils.open_write_close(
131                 self._ftrace_signal_generate_event_filter_file, '0')
132
133             # Dump the trace buffer to a log file.
134             trace_file = os.path.join(self.resultsdir, 'chrome_event_trace')
135             trace_data = utils.read_file(self._ftrace_trace_file)
136             utils.open_write_close(trace_file, trace_data)
137         except IOError as err:
138             logging.warning('Failed to stop chrome signal tracing: %s', err)
139
140
141     def start_tcpdump(self, iface):
142         """Start tcpdump process, if not running already."""
143         if not hasattr(self, '_tcpdump'):
144             self._tcpdump = subprocess.Popen(
145                 ['tcpdump', '-i', iface, '-vv'], stdout=subprocess.PIPE,
146                 stderr=subprocess.STDOUT)
147
148
149     def stop_tcpdump(self, fname_prefix):
150         """Stop tcpdump process and save output to a new file."""
151         if hasattr(self, '_tcpdump'):
152             self._tcpdump.terminate()
153             # Save output to a new file
154             next_index = len(glob.glob(
155                 os.path.join(self.resultsdir, '%s-*' % fname_prefix)))
156             tcpdump_file = os.path.join(
157                 self.resultsdir, '%s-%d' % (fname_prefix, next_index))
158             logging.info('Saving tcpdump output to %s' % tcpdump_file)
159             utils.open_write_close(tcpdump_file, self._tcpdump.communicate()[0])
160             del self._tcpdump
161
162
163     def __log_all_processes(self, fname_prefix):
164         """Log all processes to a file.
165
166         Args:
167             fname_prefix: Prefix of the log file.
168         """
169         try:
170             next_index = len(glob.glob(
171                 os.path.join(self.resultsdir, '%s-*' % fname_prefix)))
172             log_file = os.path.join(
173                 self.resultsdir, '%s-%d' % (fname_prefix, next_index))
174             utils.open_write_close(log_file, utils.system_output('ps -eF'))
175         except (error.CmdError, IOError, OSError) as err:
176             logging.warning('Failed to log all processes: %s', err)
177
178
179     def __perform_ui_diagnostics(self):
180         """Save diagnostic logs about UI.
181
182         This includes the output of:
183           $ initctl status ui
184           $ ps auxwww
185         """
186         output_file = os.path.join(self.resultsdir, 'ui_diagnostics.txt')
187         with open(output_file, 'w') as output_fd:
188             print >> output_fd, time.asctime(), '\n'
189             cmd = 'initctl status ui'
190             print >> output_fd, '$ %s' % cmd
191             print >> output_fd, utils.system_output(cmd), '\n'
192             cmd = 'ps auxwww'
193             print >> output_fd, '$ %s' % cmd
194             print >> output_fd, utils.system_output(cmd), '\n'
195         logging.info('Saved UI diagnostics to %s' % output_file)
196
197
198     def __generate_coredumps(self, names):
199         """Generate core dump files in results dir for given processes.
200
201         Note that the coredumps are forced via SIGBUS and the processes will be
202         terminated. Ideally we should use gdb gcore to create dumps
203         non-intrusively. However, the current dumps generated by gcore could not
204         be properly read back by gdb, i.e. no reasonable symbolized stack could
205         be generated.
206
207         Args:
208             names: A list of process names that need to be dumped.
209         """
210
211         # Get all pids of named processes.
212         pids = []
213         for name in names:
214             # Get pids of given name, slice [1:] to skip ps's first line 'PID'
215             pids = pids + [ pid.strip() for pid in utils.system_output(
216                 'ps -C %s -o pid' % name).splitlines()[1:]]
217         logging.info('Will force core dumps for the following pid: %s' %
218             ' '.join(pids))
219
220         # Stop all processes so that forcing dump would change their state.
221         for pid in pids:
222             utils.system('kill -STOP %s' % pid)
223
224         # Force core dump.
225         for pid in pids:
226             utils.system('kill -BUS %s' % pid)
227
228         # Resume to let the core dump finish.
229         for pid in reversed(pids):
230             utils.system('kill -CONT %s' % pid)
231
232
233     def initialize(self, creds=None, is_creating_owner=False,
234                    extra_chrome_flags=[], subtract_extra_chrome_flags=[],
235                    *args, **kwargs):
236         """Overridden from test.initialize() to log out and (maybe) log in.
237
238         If self.auto_login is True, this will automatically log in using the
239         credentials specified by 'creds' at startup, otherwise login will not
240         happen.
241
242         Regardless of the state of self.auto_login, the self.username and
243         self.password properties will be set to the credentials specified
244         by 'creds'.
245
246         Authentication is not performed against live servers.  Instead, we spin
247         up a local DNS server that will lie and say that all sites resolve to
248         127.0.0.1.  The DNS server tells flimflam via DBus that it should be
249         used to resolve addresses.  We then spin up a local httpd that will
250         respond to queries at the Google Accounts endpoints.  We clear the DNS
251         setting and tear down these servers in cleanup().
252
253         Args:
254             creds: String specifying the credentials for this test case.  Can
255                 be a named set of credentials as defined by
256                 constants.CREDENTIALS, or a 'username:password' pair.
257                 Defaults to None -- browse without signing-in.
258             is_creating_owner: If the test case is creating a new device owner.
259             extra_chrome_flags: Extra chrome flags to pass to chrome, if any.
260             subtract_extra_chrome_flags: Remove default flags passed to chrome
261                 by pyauto, if any.
262         """
263         # Mark /var/log/messages now; we'll run through all subsequent
264         # log messages at the end of the test and log info about processes that
265         # crashed.
266         self._log_reader = cros_logging.LogReader()
267         self._log_reader.set_start_by_current()
268
269         # Do not use gaia even for incognito browsing.
270         self.start_authserver()
271
272         # Run tcpdump on 'lo' interface to investigate network
273         # issues in the lab during login.
274         self.start_tcpdump(iface='lo')
275
276         # Log all processes so that we can correlate PIDs to processes in
277         # the chrome signal trace.
278         self.__log_all_processes('processes--before-tracing')
279
280         # Start event tracing related to chrome processes.
281         self.start_chrome_event_tracing()
282
283         # We yearn for Chrome coredumps...
284         open(constants.CHROME_CORE_MAGIC_FILE, 'w').close()
285
286         # The UI must be taken down to ensure that no stale state persists.
287         cros_ui.stop()
288         (self.username, self.password) = self.__resolve_creds(creds)
289         # Ensure there's no stale cryptohome from previous tests.
290         try:
291             cryptohome.remove_all_vaults()
292         except cryptohome.ChromiumOSError as err:
293             logging.error(err)
294
295         # Fake ownership unless the test is explicitly testing owner creation.
296         if not is_creating_owner:
297             logging.info('Faking ownership...')
298             ownership.fake_ownership()
299             self.fake_owner = True
300         else:
301             logging.info('Erasing stale owner state.')
302             ownership.clear_ownership_files()
303             self.fake_owner = False
304
305         try:
306             cros_ui.start()
307         except:
308             self.__perform_ui_diagnostics()
309             if not login.wait_for_browser_exit('Chrome crashed during login'):
310               self.__generate_coredumps([constants.BROWSER])
311             raise
312
313         # Save name of the last chrome log before our test started.
314         log_files = glob.glob(constants.CHROME_LOG_DIR + '/chrome_*')
315         self._last_chrome_log = max(log_files) if log_files else ''
316
317         pyauto_test.PyAutoTest.initialize(
318             self, auto_login=False,
319             extra_chrome_flags=extra_chrome_flags,
320             subtract_extra_chrome_flags=subtract_extra_chrome_flags,
321             *args, **kwargs)
322         if self.skip_oobe or self.auto_login:
323             self.pyauto.SkipToLogin()
324         if self.auto_login:
325             self.login(self.username, self.password)
326             if is_creating_owner:
327                 login.wait_for_ownership()
328
329
330     def __resolve_creds(self, creds):
331         """Map credential identifier to username, password and type.
332         Args:
333           creds: credential identifier to resolve.
334
335         Returns:
336           A (username, password) tuple.
337         """
338         if not creds:
339             return [None, None]  # Browse without signing-in.
340         if creds[0] == '$':
341             if creds not in constants.CREDENTIALS:
342                 raise error.TestFail('Unknown credentials: %s' % creds)
343
344             (name, passwd) = constants.CREDENTIALS[creds]
345             return [cryptohome.canonicalize(name), passwd]
346
347         (name, passwd) = creds.split(':')
348         return [cryptohome.canonicalize(name), passwd]
349
350
351     def take_screenshot(self, fname_prefix, format='png'):
352       """Take screenshot and save to a new file in the results dir.
353
354       Args:
355         fname_prefix: prefix for the output fname
356         format:       string indicating file format ('png', 'jpg', etc)
357
358       Returns:
359         the path of the saved screenshot file
360       """
361       next_index = len(glob.glob(
362           os.path.join(self.resultsdir, '%s-*.%s' % (fname_prefix, format))))
363       screenshot_file = os.path.join(
364           self.resultsdir, '%s-%d.%s' % (fname_prefix, next_index, format))
365       logging.info('Saving screenshot to %s.' % screenshot_file)
366
367       old_exc_type = sys.exc_info()[0]
368       try:
369           utils.system('DISPLAY=:0.0 XAUTHORITY=/home/chronos/.Xauthority '
370                        '/usr/local/bin/import -window root -depth 8 %s' %
371                        screenshot_file)
372       except Exception as err:
373           # Do not raise an exception if the screenshot fails while processing
374           # another exception.
375           if old_exc_type is None:
376               raise
377           logging.error(err)
378
379       return screenshot_file
380
381
382     def login(self, username=None, password=None):
383         """Log in with a set of credentials.
384
385         This method is called from UITest.initialize(), so you won't need it
386         unless your testcase has cause to log in multiple times.  This
387         DOES NOT affect self.username or self.password.
388
389         If username and self.username are not defined, logs in as guest.
390
391         Forces a log out if already logged in.
392         Blocks until login is complete.
393
394         Args:
395             username: username to log in as, defaults to self.username.
396             password: password to log in with, defaults to self.password.
397
398         Raises:
399             error.TestError, if login has an error
400         """
401         if self.logged_in():
402             self.logout()
403
404         uname = username or self.username
405         passwd = password or self.password
406
407         try:
408             screenshot_name = 'login-success-screenshot'
409             if uname:  # Regular login
410                 login_error = self.pyauto.Login(username=uname,
411                                                 password=passwd)
412                 if login_error:
413                     screenshot_name = 'login-error-screenshot'
414                     raise error.TestFail(
415                         'Error during login (%s, %s): %s.  See the file named '
416                         '%s.png in the results folder.' % (uname, passwd,
417                         login_error, screenshot_name))
418             else:  # Login as guest
419                 self.pyauto.LoginAsGuest()
420                 logging.info('Logged in as guest.')
421             if not self.logged_in():
422                 screenshot_name = 'login-bizarre-fail-screenshot'
423                 raise error.TestFail('Login was successful, but logged_in() '
424                                      'returned False. This should not happen. '
425                                      'Please check the file named %s.png '
426                                      'located in the results folder.' %
427                                      screenshot_name)
428         except Exception as err:
429             if isinstance(err, error.AutotestError):
430                 raise  # Do not modify our own errors.
431
432             screenshot_name = 'login-fail-screenshot'
433             raise error.TestFail('Exception raised during login: %s. See the '
434                                  'file named %s.png in the results folder.' %
435                                  (err, screenshot_name))
436         finally:
437             self.take_screenshot(fname_prefix=screenshot_name)
438             self.stop_tcpdump(fname_prefix='tcpdump-lo--till-login')
439
440         logging.info('Logged in as %s.  You can verify with the '
441                      'file named %s.png located in the results '
442                      'folder.' % (uname, screenshot_name))
443
444     def logged_in(self):
445         return self.pyauto.GetLoginInfo()['is_logged_in']
446
447
448     def logout(self):
449         """Log out.
450
451         This method is called from UITest.cleanup(), so you won't need it
452         unless your testcase needs to test functionality while logged out.
453         """
454         if not self.logged_in():
455             return
456         self._save_logs_from_cryptohome()
457
458         try:
459             cros_ui.restart(self.pyauto.Logout)
460         except:
461             self.__perform_ui_diagnostics()
462             if not login.wait_for_browser_exit('Chrome crashed during logout'):
463               self.__generate_coredumps([constants.BROWSER])
464             raise
465
466
467     def _save_logs_from_cryptohome(self):
468         """Recover dirs from cryptohome in case another test run wipes."""
469         try:
470             for dir in constants.CRYPTOHOME_DIRS_TO_RECOVER:
471                 dir_path = os.path.join(constants.CRYPTOHOME_MOUNT_PT, dir)
472                 if os.path.isdir(dir_path):
473                     target = os.path.join(self.resultsdir,
474                                           '%s-%f' % (dir, time.time()))
475                     logging.debug('Saving %s to %s.', dir_path, target)
476                     shutil.copytree(src=dir_path, dst=target, symlinks=True)
477         except (IOError, OSError, shutil.Error) as err:
478             logging.error(err)
479
480
481     def validate_basic_policy(self, basic_policy):
482         # Pull in protobuf definitions.
483         sys.path.append(self.srcdir)
484         from device_management_backend_pb2 import PolicyFetchResponse
485         from device_management_backend_pb2 import PolicyData
486         from chrome_device_policy_pb2 import ChromeDeviceSettingsProto
487         from chrome_device_policy_pb2 import UserWhitelistProto
488
489         response_proto = PolicyFetchResponse()
490         response_proto.ParseFromString(basic_policy)
491         ownership.assert_has_policy_data(response_proto)
492
493         poldata = PolicyData()
494         poldata.ParseFromString(response_proto.policy_data)
495         ownership.assert_has_device_settings(poldata)
496         ownership.assert_username(poldata, self.username)
497
498         polval = ChromeDeviceSettingsProto()
499         polval.ParseFromString(poldata.policy_value)
500         ownership.assert_new_users(polval, True)
501         ownership.assert_users_on_whitelist(polval, (self.username,))
502
503
504     def __log_crashed_processes(self, processes):
505         """Runs through the log watched by |watcher| to see if a crash was
506         reported for any process names not listed in |processes|. SIGABRT
507         crashes in chrome or supplied-chrome during ui restart are ignored.
508         """
509         ui_restart_begin_regex = re.compile(cros_ui.UI_RESTART_ATTEMPT_MSG)
510         crash_regex = re.compile(
511             'Received crash notification for ([-\w]+).+ (sig \d+)')
512         ui_restart_end_regex = re.compile(cros_ui.UI_RESTART_COMPLETE_MSG)
513
514         in_restart = False
515         for line in self._log_reader.get_logs().splitlines():
516             if ui_restart_begin_regex.search(line):
517                 in_restart = True
518             elif ui_restart_end_regex.search(line):
519                 in_restart = False
520             else:
521                 match = crash_regex.search(line)
522                 if (match and not match.group(1) in processes and
523                     not (in_restart and
524                          (match.group(1) == constants.BROWSER or
525                           match.group(1) == 'supplied_chrome') and
526                          match.group(2) == 'sig 6')):
527                     self.job.record('INFO', self.tagged_testname,
528                                     line[match.start():])
529
530
531     def execute(self, iterations=None, test_length=None,
532                 profile_only=None, _get_time=time.time,
533                 postprocess_profiled_run=None, constraints=(), *args, **kwargs):
534         """Wrapper around execute to take a screenshot for any exception."""
535         try:
536             super(UITest, self).execute(iterations=iterations,
537                                         test_length=test_length,
538                                         profile_only=profile_only,
539                                         _get_time=_get_time,
540                                         postprocess_profiled_run=
541                                           postprocess_profiled_run,
542                                         constraints=constraints,
543                                         *args, **kwargs)
544         except:
545             self.take_screenshot(fname_prefix='test-fail-screenshot')
546             raise
547
548
549     def cleanup(self):
550         """Overridden from pyauto_test.cleanup() to log out and restart
551            session_manager when the test is complete.
552         """
553         try:
554             # Save all chrome logs created during the test.
555             try:
556                 for fullpath in glob.glob(
557                     constants.CHROME_LOG_DIR + '/chrome_*'):
558                     if os.path.isfile(fullpath) and \
559                         not os.path.islink(fullpath) and \
560                         fullpath > self._last_chrome_log:  # ignore old logs
561                         shutil.copy2(fullpath, self.resultsdir)
562
563             except (IOError, OSError) as err:
564                 logging.error(err)
565
566             self._save_logs_from_cryptohome()
567             pyauto_test.PyAutoTest.cleanup(self)
568
569             if os.path.isfile(constants.CRYPTOHOMED_LOG):
570                 try:
571                     base = os.path.basename(constants.CRYPTOHOMED_LOG)
572                     shutil.copy(constants.CRYPTOHOMED_LOG,
573                                 os.path.join(self.resultsdir, base))
574                 except (IOError, OSError) as err:
575                     logging.error(err)
576
577             if self.fake_owner:
578                 logging.info('Erasing fake owner state.')
579                 ownership.clear_ownership_files()
580
581             self.__log_crashed_processes(self.crash_blacklist)
582
583             if os.path.isfile(constants.CHROME_CORE_MAGIC_FILE):
584                 os.unlink(constants.CHROME_CORE_MAGIC_FILE)
585         finally:
586             self.stop_chrome_event_tracing()
587             self.__log_all_processes('processes--after-tracing')
588             self.stop_tcpdump(fname_prefix='tcpdump-lo--till-end')
589             self.stop_authserver()
590
591
592     def get_auth_endpoint_misses(self):
593         if hasattr(self, '_authServer'):
594             return self._authServer.get_endpoint_misses()
595         else:
596             return {}