Skip to content

Capture logcat messages while logcat collection was suspended #1001

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
xr-gh wants to merge 1 commit into
base: master
Choose a base branch
from
Open

Capture logcat messages while logcat collection was suspended #1001

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
15 changes: 14 additions & 1 deletion mobly/controllers/android_device_lib/services/logcat.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -63,6 +63,7 @@ def __init__(self, android_device, configs=None):
self._adb_logcat_process = None
self._adb_logcat_file_obj = None
self.adb_logcat_file_path = None
self._last_connection_time = None
# Logcat service uses a single config obj, using singular internal
# name: `_config`.
self._config = configs if configs else Config()
Expand Down Expand Up @@ -247,9 +248,14 @@ def _start(self):
# In debugging mode of IntelijIDEA, "patch_args" remove
# double quotes in args if starting and ending with it.
# Add spaces at beginning and at last to fix this issue.
cmd = ' "%s" -s %s logcat -v threadtime -T 1 %s >> "%s" ' % (
if self._last_connection_time is not None:
t_argument_value = self._last_connection_time
else:
t_argument_value = '1'
cmd = ' "%s" -s %s logcat -v threadtime -T "%s" %s >> "%s" ' % (
adb.ADB,
self._ad.serial,
t_argument_value,
self._config.logcat_params,
self.adb_logcat_file_path,
)
Expand All @@ -270,6 +276,7 @@ def _stop(self):
except Exception:
self._ad.log.exception('Failed to stop adb logcat.')
self._adb_logcat_process = None
self._last_connection_time = None

def pause(self):
"""Pauses logcat.
Expand All @@ -279,6 +286,12 @@ def pause(self):
some logs would be lost.
"""
self._stop()
try:
response = self._ad.adb.shell(['date', '-Is', r'+%Y-%m-%d\ %H:%M:%S.%N'])
if response:
self._last_connection_time = response.decode('utf-8').strip()
except adb.AdbError as e:
self._ad.log.exception('Failed to get host time.')

def resume(self):
"""Resumes a paused logcat service."""
Expand Down
185 changes: 181 additions & 4 deletions tests/mobly/controllers/android_device_lib/services/logcat_test.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,6 +67,8 @@
0,
)

_DATE_COMMAND = ['date', '-Is', r'+%Y-%m-%d\ %H:%M:%S.%N']


class LogcatTest(unittest.TestCase):
"""Tests for Logcat service and its integration with AndroidDevice."""
Expand Down Expand Up @@ -132,7 +134,7 @@ def test_start_and_stop(
'logcat,%s,fakemodel,123.txt' % ad.serial,
)
create_dir_mock.assert_called_with(os.path.dirname(expected_log_path))
adb_cmd = ' "adb" -s %s logcat -v threadtime -T 1 >> %s'
adb_cmd = ' "adb" -s %s logcat -v threadtime -T "1" >> %s'
start_proc_mock.assert_called_with(
adb_cmd % (ad.serial, '"%s" ' % expected_log_path), shell=True
)
Expand Down Expand Up @@ -206,7 +208,8 @@ def test_update_config(
self.assertTrue(logcat_service._adb_logcat_process)
create_dir_mock.assert_has_calls([mock.call('some/path')])
expected_adb_cmd = (
' "adb" -s 1 logcat -v threadtime -T 1 -a -b -c >> "some/path/log.txt" '
' "adb" -s 1 logcat -v threadtime -T "1" -a -b -c >>'
' "some/path/log.txt" '
)
start_proc_mock.assert_called_with(expected_adb_cmd, shell=True)
self.assertEqual(logcat_service.adb_logcat_file_path, 'some/path/log.txt')
Expand Down Expand Up @@ -248,6 +251,43 @@ def test_update_config_while_running(
self.assertTrue(logcat_service.is_alive)
logcat_service.stop()

def _adb_shell_logic(self, cmd, date_result=None, raise_error=False):
if cmd == _DATE_COMMAND:
if raise_error:
raise adb.AdbError(cmd, b'', b'Device is disconnected', 1)
return date_result.encode('utf-8')
return b''

def _pause_and_resume_logcat_service(
self,
logcat_service,
date,
state,
expected_log_path,
ad_serial,
stop_proc_mock,
start_proc_mock,
clear_adb_mock,
):
"""Pauses and resumes the log collection and verifies the operations."""
# Pause the logcat collection at time stamp `date`.
state['date_result'] = date
logcat_service.pause()
self.assertFalse(logcat_service.is_alive)
stop_proc_mock.assert_called_with('process')
self.assertIsNone(logcat_service._adb_logcat_process)
clear_adb_mock.reset_mock()

# Resume the logcat collection, which should look back to time
# stamp `date`.
logcat_service.resume()
self.assertTrue(logcat_service.is_alive)
clear_adb_mock.assert_not_called()
adb_cmd = ' "adb" -s %s logcat -v threadtime -T "' + date + '" >> %s'
start_proc_mock.assert_called_with(
adb_cmd % (ad_serial, '"%s" ' % expected_log_path), shell=True
)

@mock.patch(
'mobly.controllers.android_device_lib.adb.AdbProxy',
return_value=mock_android_device.MockAdbProxy('1'),
Expand All @@ -264,8 +304,105 @@ def test_update_config_while_running(
'mobly.controllers.android_device_lib.services.logcat.Logcat.clear_adb_log',
return_value=mock_android_device.MockAdbProxy('1'),
)
@mock.patch('mobly.logger.get_log_file_timestamp')
def test_pause_and_resume(
self,
get_timestamp_mock,
clear_adb_mock,
open_logcat_mock,
stop_proc_mock,
start_proc_mock,
create_dir_mock,
FastbootProxy,
MockAdbProxy,
):
# The test will pause and resume the log collection twice. The
# resume operation is supposed to request the log messages since the
# log collection got paused.

state = {'date_result': ''}
date_result_first_pause = '2026-01-14 17:01:02.342'
date_result_second_pause = '2026-01-14 17:03:04.789'

adb_instance = MockAdbProxy.return_value
adb_instance.shell = mock.MagicMock()
adb_instance.has_shell_command = mock.MagicMock(return_value=True)

adb_instance.shell.side_effect = (
lambda cmd, *args, **kwargs: self._adb_shell_logic(
cmd, state['date_result']
)
)

# Set up the logcat instance.
mock_serial = '1'
ad = android_device.AndroidDevice(serial=mock_serial)
get_timestamp_mock.return_value = '123'
configs = logcat.Config(clear_log=True)
logcat_service = logcat.Logcat(ad, configs)
logcat_service.start()
expected_log_path = os.path.join(
logging.log_path,
'AndroidDevice%s' % ad.serial,
'logcat,%s,fakemodel,123.txt' % ad.serial,
)

# We expect that the first logcat invocation happens with time "1"
# to include all previously generated log messages.
adb_cmd = ' "adb" -s %s logcat -v threadtime -T "1" >> %s'
start_proc_mock.assert_called_with(
adb_cmd % (ad.serial, '"%s" ' % expected_log_path), shell=True
)

clear_adb_mock.assert_called_once_with()
self.assertTrue(logcat_service.is_alive)

# First pause / resume iteration
self._pause_and_resume_logcat_service(
logcat_service,
date_result_first_pause,
state,
expected_log_path,
ad.serial,
stop_proc_mock,
start_proc_mock,
clear_adb_mock,
)

# Second pause / resume iteration
self._pause_and_resume_logcat_service(
logcat_service,
date_result_second_pause,
state,
expected_log_path,
ad.serial,
stop_proc_mock,
start_proc_mock,
clear_adb_mock,
)

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',
return_value=mock_android_device.MockAdbProxy('1'),
)
@mock.patch('mobly.logger.get_log_file_timestamp')
def test_pause_and_resume_while_raising_exception_when_getting_pause_time(
self,
get_timestamp_mock,
clear_adb_mock,
open_logcat_mock,
stop_proc_mock,
Expand All @@ -274,20 +411,60 @@ def test_pause_and_resume(
FastbootProxy,
MockAdbProxy,
):
# The test will pause and resume the log collection, but it will
# fail to retrieve a date while pausing the log collection. The log
# collection is expected to resume back from the earliest time stamp
# "1".

adb_instance = MockAdbProxy.return_value
adb_instance.shell = mock.MagicMock()
adb_instance.has_shell_command = mock.MagicMock(return_value=True)

adb_instance.shell.side_effect = (
lambda cmd, *args, **kwargs: self._adb_shell_logic(
cmd, raise_error=True
)
)

# Set up the logcat instance.
mock_serial = '1'
ad = android_device.AndroidDevice(serial=mock_serial)
logcat_service = logcat.Logcat(ad, logcat.Config(clear_log=True))
get_timestamp_mock.return_value = '123'
configs = logcat.Config(clear_log=True)
logcat_service = logcat.Logcat(ad, configs)
logcat_service.start()
expected_log_path = os.path.join(
logging.log_path,
'AndroidDevice%s' % ad.serial,
'logcat,%s,fakemodel,123.txt' % ad.serial,
)

# We expect that the first logcat invocation happens with time "1"
# to include all previously generated log messages.
adb_cmd = ' "adb" -s %s logcat -v threadtime -T "1" >> %s'
start_proc_mock.assert_called_with(
adb_cmd % (ad.serial, '"%s" ' % expected_log_path), shell=True
)

clear_adb_mock.assert_called_once_with()
self.assertTrue(logcat_service.is_alive)

# Pause should fail to retrieve a valid date
logcat_service.pause()
self.assertFalse(logcat_service.is_alive)
stop_proc_mock.assert_called_with('process')
self.assertIsNone(logcat_service._adb_logcat_process)
clear_adb_mock.reset_mock()

# Resume should start with the first logcat message again
logcat_service.resume()
self.assertTrue(logcat_service.is_alive)
clear_adb_mock.assert_not_called()
adb_cmd = ' "adb" -s %s logcat -v threadtime -T "1" >> %s'
start_proc_mock.assert_called_with(
adb_cmd % (ad.serial, '"%s" ' % expected_log_path), shell=True
)

logcat_service.stop()

@mock.patch(
Expand Down Expand Up @@ -422,7 +599,7 @@ def test_take_logcat_with_extra_params(
'logcat,%s,fakemodel,123.txt' % ad.serial,
)
create_dir_mock.assert_called_with(os.path.dirname(expected_log_path))
adb_cmd = ' "adb" -s %s logcat -v threadtime -T 1 -b radio >> %s'
adb_cmd = ' "adb" -s %s logcat -v threadtime -T "1" -b radio >> %s'
start_proc_mock.assert_called_with(
adb_cmd % (ad.serial, '"%s" ' % expected_log_path), shell=True
)
Expand Down
Loading