Home | History | Annotate | Download | only in network_3GRecoverFromGobiDesync 
      1 # Copyright (c) 2011 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 dbus
      6 import glib
      7 import gobject
      8 import logging
      9 import os
     10 import pty
     11 import re
     12 import subprocess
     13 import traceback
     14 
     15 from autotest_lib.client.bin import test
     16 from autotest_lib.client.bin import utils
     17 from autotest_lib.client.common_lib import error
     18 from autotest_lib.client.cros.cellular import mm
     19 from autotest_lib.client.cros.cellular import modem_utils
     20 
     21 TEST_TIMEOUT = 120
     22 
     23 # Preconditions for starting
     24 START_DEVICE_PRESENT = 'start_device_present'
     25 START_UDEVADM_RUNNING = 'start_udevadm_running'
     26 
     27 # ModemManager service enters, leaves bus
     28 MM_APPEARED = 'modem_manager_appeared'
     29 MM_DISAPPEARED = 'modem_manager_disappeared'
     30 
     31 # userlevel UDEV sees the modem come and go
     32 MODEM_APPEARED = 'modem_appeared'
     33 MODEM_DISAPPEARED = 'modem_disappeared'
     34 
     35 class TestEventLoop(object):
     36   """Common tools for running glib event loops."""
     37   def __init__(self):
     38     # The glib mainloop sinks exceptions thrown by event handlers, so we
     39     # provide a wrapper that saves the exceptions so the event loop can
     40     # re-raise them.
     41 
     42     # TODO(rochberg): The rethrown exceptions come with the stack of the
     43     # rethrow point, not the original exceptions.  Fix.
     44     self.to_raise = None
     45 
     46     # Autotest won't continue until our children are dead.  Keep track
     47     # of them
     48     self.to_kill = []
     49 
     50   def ExceptionWrapper(self, f):
     51     """Returns a wrapper that calls f and saves exceptions for re-raising."""
     52     def to_return(*args, **kwargs):
     53       try:
     54         return f(*args, **kwargs)
     55       except Exception, e:
     56         logging.info('Caught: ' + traceback.format_exc())
     57         self.to_raise = e
     58         return True
     59     return to_return
     60 
     61   def Popen(self, *args, **kwargs):
     62     """Builds a supbrocess.Popen, saves a copy for later kill()ing."""
     63     to_return = subprocess.Popen(*args, **kwargs)
     64     self.to_kill.append(to_return)
     65     return to_return
     66 
     67   def KillSubprocesses(self):
     68     for victim in self.to_kill:
     69       victim.kill()
     70 
     71 class GobiDesyncEventLoop(TestEventLoop):
     72   def __init__(self, test_env):
     73     super(GobiDesyncEventLoop, self).__init__()
     74     self.test_env = test_env
     75     self.dbus_signal_receivers = []
     76 
     77     # Start conditions; once these have been met, call StartTest.
     78     # This makes sure that cromo and udevadm are ready to use
     79     self.remaining_start_conditions = set([START_DEVICE_PRESENT,
     80                                            START_UDEVADM_RUNNING])
     81 
     82     # We want to see all of these events before we're done
     83     self.remaining_events = set([MM_APPEARED, MM_DISAPPEARED,
     84                                  MODEM_APPEARED, MODEM_DISAPPEARED, ])
     85 
     86 
     87     # udevadm monitor output for user-level notifications of device
     88     # add and remove
     89     # UDEV  [1296763045.687859] add      /devices/virtual/QCQMI/qcqmi0 (QCQMI)
     90     self.udev_qcqmi = re.compile(
     91         r'UDEV.*\s(?P<action>\w+).*/QCQMI/qcqmi')
     92 
     93   def NameOwnerChanged(self, name, old, new):
     94     if name != 'org.chromium.ModemManager':
     95       return
     96     if not new:
     97       self.remaining_events.remove(MM_DISAPPEARED)
     98     elif not old:
     99       if MM_DISAPPEARED in self.remaining_events:
    100         raise Exception('Saw cromo appear before it disappeared')
    101       self.remaining_events.remove(MM_APPEARED)
    102     return True
    103 
    104   def ModemAdded(self, path):
    105     """Clock the StartIfReady() state machine when we see a modem added."""
    106     logging.info('Modem %s added' % path)
    107     self.StartIfReady()         # Checks to see if the modem is present
    108 
    109   def TimedOut(self):
    110     raise Exception('Timed out: still waiting for: '
    111                     + str(self.remaining_events))
    112 
    113   def UdevOutputReceived(self, source, condition):
    114     if condition & glib.IO_IN:
    115       output = os.read(source.fileno(), 65536)
    116 
    117       # We don't want to start the test until udevadm is running
    118       if 'KERNEL - the kernel uevent' in output:
    119         self.StartIfReady(START_UDEVADM_RUNNING)
    120 
    121       for line in output.split('\r\n'):
    122         logging.info(line)
    123         match = self.udev_qcqmi.search(line)
    124         if not match:
    125           continue
    126         action = match.group('action')
    127         logging.info('Action:[%s]' % action)
    128         if action == 'add':
    129           if MM_DISAPPEARED in self.remaining_events:
    130             raise Exception('Saw modem appear before it disappeared')
    131           self.remaining_events.remove(MODEM_APPEARED)
    132 
    133         elif action == 'remove':
    134           self.remaining_events.remove(MODEM_DISAPPEARED)
    135     return True
    136 
    137 
    138   def StartIfReady(self, condition_to_remove=None):
    139     """Call StartTest when remaining_start_conditions have been met."""
    140     if condition_to_remove:
    141       self.remaining_start_conditions.discard(condition_to_remove)
    142 
    143     try:
    144       if (START_DEVICE_PRESENT in self.remaining_start_conditions and
    145           mm.PickOneModem('Gobi')):
    146         self.remaining_start_conditions.discard(START_DEVICE_PRESENT)
    147     except dbus.exceptions.DBusException, e:
    148       if e.get_dbus_name() != 'org.freedesktop.DBus.Error.NoReply':
    149         raise
    150 
    151     if self.remaining_start_conditions:
    152       logging.info('Not starting until: %s' % self.remaining_start_conditions)
    153     else:
    154       logging.info('Preconditions satisfied')
    155       self.StartTest()
    156       self.remaining_start_conditions = ['dummy entry so we do not start twice']
    157 
    158   def RegisterDbusSignal(self, *args, **kwargs):
    159     """Register signal receiver with dbus and our cleanup list."""
    160     self.dbus_signal_receivers.append(
    161         self.test_env.bus.add_signal_receiver(*args, **kwargs))
    162 
    163   def CleanupDbusSignalReceivers(self):
    164     for signal_match in self.dbus_signal_receivers:
    165       signal_match.remove()
    166 
    167   def RegisterForDbusSignals(self):
    168     # Watch cromo leave the bus when it terminates and return when it
    169     # is restarted
    170     self.RegisterDbusSignal(self.ExceptionWrapper(self.NameOwnerChanged),
    171                             bus_name='org.freedesktop.DBus',
    172                             signal_name='NameOwnerChanged')
    173 
    174     # Wait for cromo to report that the modem is present.
    175     self.RegisterDbusSignal(self.ExceptionWrapper(self.ModemAdded),
    176                             bus_name='org.freedesktop.DBus',
    177                             signal_name='DeviceAdded',
    178                             dbus_interface='org.freedesktop.ModemManager')
    179 
    180   def RegisterForUdevMonitor(self):
    181     # have udevadm output to a pty so it will line buffer
    182     (master, slave) = pty.openpty()
    183     monitor = self.Popen(['udevadm', 'monitor'],
    184                          stdout=os.fdopen(slave),
    185                          bufsize=1)
    186 
    187     glib.io_add_watch(os.fdopen(master),
    188                       glib.IO_IN | glib.IO_HUP,
    189                       self.ExceptionWrapper(self.UdevOutputReceived))
    190 
    191   def Wait(self, timeout_seconds):
    192     self.RegisterForDbusSignals()
    193     self.RegisterForUdevMonitor()
    194     gobject.timeout_add(timeout_seconds * 1000,
    195                         self.ExceptionWrapper(self.TimedOut))
    196 
    197     # Check to see if the modem is present and remove that from the
    198     # start preconditions if need be
    199     self.StartIfReady()
    200 
    201     context = gobject.MainLoop().get_context()
    202     while self.remaining_events and not self.to_raise:
    203       logging.info('Waiting for: ' + str(self.remaining_events))
    204       context.iteration()
    205 
    206     modem_utils.ClearGobiModemFaultInjection()
    207     self.KillSubprocesses()
    208     self.CleanupDbusSignalReceivers()
    209     if self.to_raise:
    210       raise self.to_raise
    211     logging.info('Done waiting for events')
    212 
    213 
    214 class RegularOperationTest(GobiDesyncEventLoop):
    215   """This covers the case where the modem makes an API call that
    216      returns a "we've lost sync" error that should cause a reboot."""
    217 
    218   def __init__(self, test_env):
    219     super(RegularOperationTest, self).__init__(test_env)
    220 
    221   def StartTest(self):
    222     self.test_env.modem.GobiModem().InjectFault('SdkError', 12)
    223     self.test_env.modem.SimpleModem().GetStatus()
    224 
    225 
    226 class DataConnectTest(GobiDesyncEventLoop):
    227   """Test the special-case code path where we receive an error from
    228      StartDataSession.  If we're not also disabling at the same time,
    229      this should behave the same as other desync errors."""
    230 
    231   def __init__(self, test_env):
    232     super(DataConnectTest, self).__init__(test_env)
    233 
    234   def ignore(self, *args, **kwargs):
    235     logging.info('ignoring')
    236     pass
    237 
    238   def StartTest(self):
    239     gobi = self.test_env.modem.GobiModem()
    240     gobi.InjectFault('AsyncConnectSleepMs', 1000)
    241     gobi.InjectFault('ConnectFailsWithErrorSendingQmiRequest', 1)
    242     self.test_env.modem.SimpleModem().Connect(
    243             {}, reply_handler=self.ignore, error_handler=self.ignore)
    244 
    245 class ApiConnectTest(GobiDesyncEventLoop):
    246   """Test the special-case code on errors connecting to the API. """
    247   def __init__(self, test_env):
    248     super(ApiConnectTest, self).__init__(test_env)
    249 
    250   def StartTest(self):
    251     self.test_env.modem.Enable(False)
    252 
    253     saw_exception = False
    254     # Failures on API connect are a different code path
    255     self.test_env.modem.GobiModem().InjectFault('SdkError', 1)
    256     try:
    257       self.test_env.modem.Enable(True)
    258     except dbus.exceptions.DBusException:
    259       saw_exception = True
    260     if not saw_exception:
    261       raise error.TestFail('Enable returned when it should have crashed')
    262 
    263 class EnableDisableTest():
    264   """Test that the Enable and Disable technology functions work."""
    265 
    266   def __init__(self, test_env):
    267     self.test_env = test_env
    268 
    269   def CompareModemPowerState(self, modem, expected_state):
    270     """Compare the power state of a modem to an expected state."""
    271     props = modem.GetModemProperties()
    272     state = props['Enabled']
    273     logging.info('Modem Enabled = %s' % state)
    274     return state == expected_state
    275 
    276   def CompareDevicePowerState(self, device, expected_state):
    277     """Compare the shill device power state to an expected state."""
    278     device_properties = device.GetProperties(utf8_strings=True);
    279     state = device_properties['Powered']
    280     logging.info('Device Enabled = %s' % state)
    281     return state == expected_state
    282 
    283   def Test(self):
    284     """Test that the Enable and Disable technology functions work.
    285 
    286        The expectation is that by using enable technology shill
    287        will change the power state of the device by requesting that
    288        the modem manager modem be either Enabled or Disabled.  The
    289        state tracked by shill should not change until *after* the
    290        modem state has changed.  Thus after Enabling or Disabling the
    291        technology, we wait until the shill device state changes,
    292        and then assert that the modem state has also changed, without
    293        having to wait again.
    294 
    295        Raises:
    296          error.TestFail - if the shill device or the modem manager
    297            modem is not in the expected state
    298     """
    299     device = self.test_env.shill.find_cellular_device_object()
    300 
    301     for i in range(2):
    302       # Enable technology, ensure that device and modem are enabled.
    303       self.test_env.shill.manager.EnableTechnology('cellular')
    304       utils.poll_for_condition(
    305           lambda: self.CompareDevicePowerState(device, True),
    306           error.TestFail('Device Failed to enter state Powered=True'))
    307       if not self.CompareModemPowerState(self.test_env.modem, True):
    308         raise error.TestFail('Modem Failed to enter state Enabled')
    309 
    310       # Disable technology, ensure that device and modem are disabled.
    311       self.test_env.shill.manager.DisableTechnology('cellular')
    312       utils.poll_for_condition(
    313           lambda: self.CompareDevicePowerState(device, False),
    314           error.TestFail('Device Failed to enter state Powered=False'))
    315       if not self.CompareModemPowerState(self.test_env.modem, False):
    316         raise error.TestFail('Modem Failed to enter state Disabled')
    317 
    318 
    319 class network_3GRecoverFromGobiDesync(test.test):
    320   version = 1
    321 
    322   def run_test(self, test_env, test):
    323     with test_env:
    324       try:
    325         test()
    326       finally:
    327         modem_utils.ClearGobiModemFaultInjection()
    328 
    329   def run_once(self, test_env, cycles=1, min=1, max=20):
    330     logging.info('Testing failure during DataConnect')
    331     self.run_test(test_env,
    332                   lambda: DataConnectTest(test_env).Wait(TEST_TIMEOUT))
    333 
    334     logging.info('Testing failure while in regular operation')
    335     self.run_test(test_env,
    336                   lambda: RegularOperationTest(test_env).Wait(TEST_TIMEOUT))
    337 
    338     logging.info('Testing failure during device initialization')
    339     self.run_test(test_env,
    340                   lambda: ApiConnectTest(test_env).Wait(TEST_TIMEOUT))
    341 
    342     logging.info('Testing that Enable and Disable technology still work')
    343     self.run_test(test_env,
    344                   lambda: EnableDisableTest(test_env).Test())
    345