Keep boot-time logs when the logcat service restarts after a reboot (#1074) `AndroidDevice.handle_reboot()` stops all services before the reboot and starts them again once `sys.boot_completed` is set. `Logcat.start()` did not distinguish that restart from the first start of a run: it cleared the device buffer (`Config.clear_log` defaults to True) and started `adb logcat -T 1`, which only follows from the most recent line. Everything logged between kernel boot and boot completion was therefore dropped from `adb_logcat_file_path`, and `get_lines()` / `wait_for()` / `listen()` could not see boot-time events such as the MediaProvider `MEDIA_MOUNTED` scan, even though they were still available via a raw `adb logcat -d`. `start()` now reads `/proc/sys/kernel/random/boot_id` and, when it differs from the id seen by the previous start, treats the call as a restart after a reboot: the buffer (which only holds this boot's logs) is not cleared and the new `adb logcat` process dumps the whole buffer before following. A stop/start on the same boot, or when the boot id cannot be read, keeps the existing clear-and-follow behavior. `pause()`/`resume()` are unchanged.
diff --git a/mobly/controllers/android_device_lib/services/logcat.py b/mobly/controllers/android_device_lib/services/logcat.py index ea88065..50e9931 100644 --- a/mobly/controllers/android_device_lib/services/logcat.py +++ b/mobly/controllers/android_device_lib/services/logcat.py
@@ -34,6 +34,10 @@ ' && logpersist.start' ) +# Unique per kernel boot; used to detect that the device rebooted between a +# `stop()` and the next `start()` of this service. +_BOOT_ID_CMD = 'cat /proc/sys/kernel/random/boot_id' + class Error(errors.ServiceError): """Root error type for logcat service.""" @@ -80,6 +84,9 @@ self.adb_logcat_file_path = None self._processor = None self._last_connection_time = None + # Kernel boot id observed by the most recent `start()`; None until the + # service has started once (or if the id could not be read). + self._boot_id = None # Logcat service uses a single config obj, using singular internal # name: `_config`. self._config = configs if configs else Config() @@ -130,6 +137,16 @@ self._ad.log.debug('Failed to get device timestamp.') return None + def _get_boot_id(self) -> Optional[str]: + """Returns the device's current kernel boot id, or None if unavailable.""" + try: + response = self._ad.adb.shell(_BOOT_ID_CMD) + if response: + return response.decode('utf-8').strip() or None + except (adb.AdbError, UnicodeDecodeError): + self._ad.log.debug('Failed to get device boot id.') + return None + def now(self) -> logcat_processor.LogcatPosition: """Captures the current logcat position and device timestamp. @@ -441,6 +458,14 @@ """Starts a standing adb logcat collection. The collection runs in a separate subprocess and saves logs in a file. + + When the service is restarted after the device rebooted (e.g. by + `AndroidDevice.handle_reboot`), the device's log buffer only holds lines + produced since boot and nothing from it has been collected yet. In that + case the buffer is not cleared, regardless of `Config.clear_log`, and the + new `adb logcat` process dumps the whole buffer before following, so that + logs emitted during boot (before `sys.boot_completed`) end up in + `adb_logcat_file_path` and are visible to `get_lines`, `wait_for`, etc. """ if self._ad.is_bootloader: self._ad.log.warning( @@ -448,13 +473,30 @@ ) return self._assert_not_running() - if self._config.clear_log: + boot_id = self._get_boot_id() + rebooted = ( + self._boot_id is not None + and boot_id is not None + and boot_id != self._boot_id + ) + self._boot_id = boot_id + if rebooted: + self._ad.log.debug( + '[LogcatService] Device rebooted since the last start; keeping the' + ' boot-time logs instead of clearing the buffer.' + ) + elif self._config.clear_log: self.clear_adb_log() - self._start() + self._start(dump_buffer=rebooted) self._open_logcat_file() - def _start(self): - """Starts the actual subprocess logic of starting logcat.""" + def _start(self, dump_buffer=False): + """Starts the actual subprocess logic of starting logcat. + + Args: + dump_buffer: bool, if True the whole device log buffer is dumped before + following new output, instead of only the most recent line. + """ self._enable_logpersist() if self._config.output_file_path: self._close_logcat_file() @@ -474,14 +516,19 @@ # double quotes in args if starting and ending with it. # Add spaces at beginning and at last to fix this issue. if self._last_connection_time is not None: - t_argument_value = self._last_connection_time + # Resuming: pick up everything logged since the service was paused. + t_argument = '-T "%s"' % self._last_connection_time self._last_connection_time = None + elif dump_buffer: + # Restarting after a reboot: the buffer only holds this boot's logs. + t_argument = '' else: - t_argument_value = '1' - cmd = ' "%s" -s %s logcat -v threadtime -T "%s" %s >> "%s" ' % ( + # Fresh start: follow from the most recent line only. + t_argument = '-T "1"' + cmd = ' "%s" -s %s logcat -v threadtime %s %s >> "%s" ' % ( adb.ADB, self._ad.serial, - t_argument_value, + t_argument, self._config.logcat_params, self.adb_logcat_file_path, )
diff --git a/tests/mobly/controllers/android_device_lib/services/logcat_test.py b/tests/mobly/controllers/android_device_lib/services/logcat_test.py index 0a8c03c..46def19 100755 --- a/tests/mobly/controllers/android_device_lib/services/logcat_test.py +++ b/tests/mobly/controllers/android_device_lib/services/logcat_test.py
@@ -471,6 +471,188 @@ logcat_service.stop() + def _make_restart_logcat_service(self, MockAdbProxy, boot_ids): + """Creates a started Logcat service whose device reports `boot_ids`. + + Args: + MockAdbProxy: the patched AdbProxy class. + boot_ids: list of values returned by successive boot id reads; a value of + None makes the read fail with AdbError. + + Returns: + A tuple of (logcat_service, expected_log_path, expected_adb_cmd_fmt). + """ + boot_id_iter = iter(boot_ids) + + def _shell(cmd, *args, **kwargs): + if cmd == logcat._BOOT_ID_CMD: + boot_id = next(boot_id_iter) + if boot_id is None: + raise adb.AdbError(cmd, b'', b'Device is disconnected', 1) + return boot_id.encode('utf-8') + return b'' + + adb_instance = MockAdbProxy.return_value + adb_instance.shell = mock.MagicMock(side_effect=_shell) + ad = android_device.AndroidDevice(serial='1') + logcat_service = logcat.Logcat(ad, logcat.Config(clear_log=True)) + logcat_service.start() + expected_log_path = os.path.join( + logging.log_path, + 'AndroidDevice%s' % ad.serial, + 'logcat,%s,fakemodel,123.txt' % ad.serial, + ) + adb_cmd_fmt = ' "adb" -s %s logcat -v threadtime %s >> "%s" ' + return logcat_service, expected_log_path, adb_cmd_fmt + + @mock.patch( + 'mobly.controllers.android_device_lib.adb.AdbProxy', + return_value=mock_android_device.MockAdbProxy('1'), + ) + @mock.patch( + 'mobly.controllers.android_device_lib.fastboot.FastbootProxy', + return_value=mock_android_device.MockFastbootProxy('1'), + ) + @mock.patch('mobly.utils.create_dir') + @mock.patch('mobly.utils.start_standing_subprocess', return_value='process') + @mock.patch('mobly.utils.stop_standing_subprocess') + @mock.patch.object(logcat.Logcat, '_open_logcat_file') + @mock.patch( + 'mobly.controllers.android_device_lib.services.logcat.Logcat.clear_adb_log' + ) + @mock.patch('mobly.logger.get_log_file_timestamp', return_value='123') + def test_restart_after_reboot_keeps_boot_logs( + self, + get_timestamp_mock, + clear_adb_mock, + open_logcat_mock, + stop_proc_mock, + start_proc_mock, + create_dir_mock, + FastbootProxy, + MockAdbProxy, + ): + """A restart after a reboot must not clear or skip the boot-time logs. + + This is the `AndroidDevice.handle_reboot` flow: `stop()` before the + reboot and `start()` once the device has booted. The boot id changes, so + the service dumps the whole (fresh) device buffer instead of clearing it + and following from the most recent line only. + """ + logcat_service, log_path, adb_cmd_fmt = self._make_restart_logcat_service( + MockAdbProxy, boot_ids=['boot-1', 'boot-2'] + ) + # Fresh start: buffer cleared, follow from the most recent line. + clear_adb_mock.assert_called_once_with() + start_proc_mock.assert_called_with( + adb_cmd_fmt % ('1', '-T "1"', log_path), shell=True + ) + clear_adb_mock.reset_mock() + + logcat_service.stop() + logcat_service.start() + + # Restart after reboot: buffer kept and dumped in full. + clear_adb_mock.assert_not_called() + start_proc_mock.assert_called_with( + adb_cmd_fmt % ('1', '', log_path), shell=True + ) + self.assertEqual(logcat_service.adb_logcat_file_path, log_path) + logcat_service.stop() + + @mock.patch( + 'mobly.controllers.android_device_lib.adb.AdbProxy', + return_value=mock_android_device.MockAdbProxy('1'), + ) + @mock.patch( + 'mobly.controllers.android_device_lib.fastboot.FastbootProxy', + return_value=mock_android_device.MockFastbootProxy('1'), + ) + @mock.patch('mobly.utils.create_dir') + @mock.patch('mobly.utils.start_standing_subprocess', return_value='process') + @mock.patch('mobly.utils.stop_standing_subprocess') + @mock.patch.object(logcat.Logcat, '_open_logcat_file') + @mock.patch( + 'mobly.controllers.android_device_lib.services.logcat.Logcat.clear_adb_log' + ) + @mock.patch('mobly.logger.get_log_file_timestamp', return_value='123') + def test_restart_without_reboot_clears_log( + self, + get_timestamp_mock, + clear_adb_mock, + open_logcat_mock, + stop_proc_mock, + start_proc_mock, + create_dir_mock, + FastbootProxy, + MockAdbProxy, + ): + """A stop/start on the same boot behaves like a fresh start.""" + logcat_service, log_path, adb_cmd_fmt = self._make_restart_logcat_service( + MockAdbProxy, boot_ids=['boot-1', 'boot-1'] + ) + clear_adb_mock.reset_mock() + + logcat_service.stop() + logcat_service.start() + + clear_adb_mock.assert_called_once_with() + start_proc_mock.assert_called_with( + adb_cmd_fmt % ('1', '-T "1"', log_path), shell=True + ) + logcat_service.stop() + + @mock.patch( + 'mobly.controllers.android_device_lib.adb.AdbProxy', + return_value=mock_android_device.MockAdbProxy('1'), + ) + @mock.patch( + 'mobly.controllers.android_device_lib.fastboot.FastbootProxy', + return_value=mock_android_device.MockFastbootProxy('1'), + ) + @mock.patch('mobly.utils.create_dir') + @mock.patch('mobly.utils.start_standing_subprocess', return_value='process') + @mock.patch('mobly.utils.stop_standing_subprocess') + @mock.patch.object(logcat.Logcat, '_open_logcat_file') + @mock.patch( + 'mobly.controllers.android_device_lib.services.logcat.Logcat.clear_adb_log' + ) + @mock.patch('mobly.logger.get_log_file_timestamp', return_value='123') + def test_restart_with_unreadable_boot_id_clears_log( + self, + get_timestamp_mock, + clear_adb_mock, + open_logcat_mock, + stop_proc_mock, + start_proc_mock, + create_dir_mock, + FastbootProxy, + MockAdbProxy, + ): + """If the boot id cannot be read, fall back to the fresh-start behavior.""" + logcat_service, log_path, adb_cmd_fmt = self._make_restart_logcat_service( + MockAdbProxy, boot_ids=['boot-1', None, 'boot-3'] + ) + clear_adb_mock.reset_mock() + + # Boot id read fails on this start: cannot tell, so clear as configured. + logcat_service.stop() + logcat_service.start() + clear_adb_mock.assert_called_once_with() + start_proc_mock.assert_called_with( + adb_cmd_fmt % ('1', '-T "1"', log_path), shell=True + ) + clear_adb_mock.reset_mock() + + # No previous boot id to compare against on the next start either. + logcat_service.stop() + logcat_service.start() + clear_adb_mock.assert_called_once_with() + start_proc_mock.assert_called_with( + adb_cmd_fmt % ('1', '-T "1"', log_path), shell=True + ) + logcat_service.stop() + @mock.patch( 'mobly.controllers.android_device_lib.adb.AdbProxy', return_value=mock_android_device.MockAdbProxy('1'),