Unverified Commit df63c82c authored by Jenn Magder's avatar Jenn Magder Committed by GitHub

Convert iOS simulator log reader to simctl, use unified logging filters (#54154)

parent 4b98c056
...@@ -580,20 +580,41 @@ class IOSSimulator extends Device { ...@@ -580,20 +580,41 @@ class IOSSimulator extends Device {
} }
} }
/// Launches the device log reader process on the host. /// Launches the device log reader process on the host and parses the syslog.
Future<Process> launchDeviceLogTool(IOSSimulator device) async { @visibleForTesting
// Versions of iOS prior to iOS 11 log to the simulator syslog file. Future<Process> launchDeviceSystemLogTool(IOSSimulator device) async {
if (await device.sdkMajorVersion < 11) { return processUtils.start(<String>['tail', '-n', '0', '-F', device.logFilePath]);
return processUtils.start(<String>['tail', '-n', '0', '-F', device.logFilePath]); }
}
/// Launches the device log reader process on the host and parses unified logging.
@visibleForTesting
Future<Process> launchDeviceUnifiedLogging (IOSSimulator device, String appName) async {
// Make NSPredicate concatenation easier to read.
String orP(List<String> clauses) => '(${clauses.join(" OR ")})';
String andP(List<String> clauses) => clauses.join(' AND ');
String notP(String clause) => 'NOT($clause)';
final String predicate = andP(<String>[
'eventType = logEvent',
if (appName != null) 'processImagePath ENDSWITH "$appName"',
// Either from Flutter or Swift (maybe assertion or fatal error) or from the app itself.
orP(<String>[
'senderImagePath ENDSWITH "/Flutter"',
'senderImagePath ENDSWITH "/libswiftCore.dylib"',
'processImageUUID == senderImageUUID',
]),
// Filter out some messages that clearly aren't related to Flutter.
notP('eventMessage CONTAINS ": could not find icon for representation -> com.apple."'),
notP('eventMessage BEGINSWITH "assertion failed: "'),
notP('eventMessage CONTAINS " libxpc.dylib "'),
]);
// For iOS 11 and above, use /usr/bin/log to tail process logs.
// Run in interactive mode (via script), otherwise /usr/bin/log buffers in 4k chunks. (radar: 34420207)
return processUtils.start(<String>[ return processUtils.start(<String>[
'script', '/dev/null', '/usr/bin/log', 'stream', '--style', 'syslog', '--predicate', 'processImagePath CONTAINS "${device.id}"', _xcrunPath, 'simctl', 'spawn', device.id, 'log', 'stream', '--style', 'json', '--predicate', predicate,
]); ]);
} }
@visibleForTesting
Future<Process> launchSystemLogTool(IOSSimulator device) async { Future<Process> launchSystemLogTool(IOSSimulator device) async {
// Versions of iOS prior to 11 tail the simulator syslog file. // Versions of iOS prior to 11 tail the simulator syslog file.
if (await device.sdkMajorVersion < 11) { if (await device.sdkMajorVersion < 11) {
...@@ -630,11 +651,18 @@ class _IOSSimulatorLogReader extends DeviceLogReader { ...@@ -630,11 +651,18 @@ class _IOSSimulatorLogReader extends DeviceLogReader {
String get name => device.name; String get name => device.name;
Future<void> _start() async { Future<void> _start() async {
// Device log. // Unified logging iOS 11 and greater (introduced in iOS 10).
await device.ensureLogsExists(); if (await device.sdkMajorVersion >= 11) {
_deviceProcess = await launchDeviceLogTool(device); _deviceProcess = await launchDeviceUnifiedLogging(device, _appName);
_deviceProcess.stdout.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(_onDeviceLine); _deviceProcess.stdout.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(_onUnifiedLoggingLine);
_deviceProcess.stderr.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(_onDeviceLine); _deviceProcess.stderr.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(_onUnifiedLoggingLine);
} else {
// Fall back to syslog parsing.
await device.ensureLogsExists();
_deviceProcess = await launchDeviceSystemLogTool(device);
_deviceProcess.stdout.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(_onSysLogDeviceLine);
_deviceProcess.stderr.transform<String>(utf8.decoder).transform<String>(const LineSplitter()).listen(_onSysLogDeviceLine);
}
// Track system.log crashes. // Track system.log crashes.
// ReportCrash[37965]: Saved crash report for FlutterRunner[37941]... // ReportCrash[37965]: Saved crash report for FlutterRunner[37941]...
...@@ -729,7 +757,7 @@ class _IOSSimulatorLogReader extends DeviceLogReader { ...@@ -729,7 +757,7 @@ class _IOSSimulatorLogReader extends DeviceLogReader {
String _lastLine; String _lastLine;
void _onDeviceLine(String line) { void _onSysLogDeviceLine(String line) {
globals.printTrace('[DEVICE LOG] $line'); globals.printTrace('[DEVICE LOG] $line');
final Match multi = _lastMessageMultipleRegex.matchAsPrefix(line); final Match multi = _lastMessageMultipleRegex.matchAsPrefix(line);
...@@ -752,6 +780,19 @@ class _IOSSimulatorLogReader extends DeviceLogReader { ...@@ -752,6 +780,19 @@ class _IOSSimulatorLogReader extends DeviceLogReader {
} }
} }
// "eventMessage" : "flutter: 21",
static final RegExp _unifiedLoggingEventMessageRegex = RegExp(r'.*"eventMessage" : (".*")');
void _onUnifiedLoggingLine(String line) {
// The log command predicate handles filtering, so every log eventMessage should be decoded and added.
final Match eventMessageMatch = _unifiedLoggingEventMessageRegex.firstMatch(line);
if (eventMessageMatch != null) {
final dynamic decodedJson = jsonDecode(eventMessageMatch.group(1));
if (decodedJson is String) {
_linesController.add(decodedJson);
}
}
}
String _filterSystemLog(String string) { String _filterSystemLog(String string) {
final Match match = _mapRegex.matchAsPrefix(string); final Match match = _mapRegex.matchAsPrefix(string);
return match == null ? string : '${match.group(1)}: ${match.group(2)}'; return match == null ? string : '${match.group(1)}: ${match.group(2)}';
......
...@@ -410,7 +410,7 @@ void main() { ...@@ -410,7 +410,7 @@ void main() {
); );
}); });
group('launchDeviceLogTool', () { group('device log tool', () {
MockProcessManager mockProcessManager; MockProcessManager mockProcessManager;
MockXcode mockXcode; MockXcode mockXcode;
MockSimControl mockSimControl; MockSimControl mockSimControl;
...@@ -423,7 +423,7 @@ void main() { ...@@ -423,7 +423,7 @@ void main() {
mockXcode = MockXcode(); mockXcode = MockXcode();
}); });
testUsingContext('uses tail on iOS versions prior to iOS 11', () async { testUsingContext('syslog uses tail', () async {
final IOSSimulator device = IOSSimulator( final IOSSimulator device = IOSSimulator(
'x', 'x',
name: 'iPhone SE', name: 'iPhone SE',
...@@ -431,7 +431,7 @@ void main() { ...@@ -431,7 +431,7 @@ void main() {
simControl: mockSimControl, simControl: mockSimControl,
xcode: mockXcode, xcode: mockXcode,
); );
await launchDeviceLogTool(device); await launchDeviceSystemLogTool(device);
expect( expect(
verify(mockProcessManager.start(captureAny, environment: null, workingDirectory: null)).captured.single, verify(mockProcessManager.start(captureAny, environment: null, workingDirectory: null)).captured.single,
contains('tail'), contains('tail'),
...@@ -442,7 +442,7 @@ void main() { ...@@ -442,7 +442,7 @@ void main() {
FileSystem: () => fileSystem, FileSystem: () => fileSystem,
}); });
testUsingContext('uses /usr/bin/log on iOS 11 and above', () async { testUsingContext('unified logging with app name', () async {
final IOSSimulator device = IOSSimulator( final IOSSimulator device = IOSSimulator(
'x', 'x',
name: 'iPhone SE', name: 'iPhone SE',
...@@ -450,52 +450,35 @@ void main() { ...@@ -450,52 +450,35 @@ void main() {
simControl: mockSimControl, simControl: mockSimControl,
xcode: mockXcode, xcode: mockXcode,
); );
await launchDeviceLogTool(device); await launchDeviceUnifiedLogging(device, 'Runner');
expect(
verify(mockProcessManager.start(captureAny, environment: null, workingDirectory: null)).captured.single, const String expectedPredicate = 'eventType = logEvent AND '
contains('/usr/bin/log'), 'processImagePath ENDSWITH "Runner" AND '
); '(senderImagePath ENDSWITH "/Flutter" OR senderImagePath ENDSWITH "/libswiftCore.dylib" OR processImageUUID == senderImageUUID) AND '
}, 'NOT(eventMessage CONTAINS ": could not find icon for representation -> com.apple.") AND '
overrides: <Type, Generator>{ 'NOT(eventMessage BEGINSWITH "assertion failed: ") AND '
ProcessManager: () => mockProcessManager, 'NOT(eventMessage CONTAINS " libxpc.dylib ")';
FileSystem: () => fileSystem,
}); final List<String> command = verify(mockProcessManager.start(captureAny, environment: null, workingDirectory: null)).captured.single as List<String>;
}); expect(command, <String>[
'/usr/bin/xcrun',
group('launchSystemLogTool', () { 'simctl',
MockProcessManager mockProcessManager; 'spawn',
MockSimControl mockSimControl;
MockXcode mockXcode;
setUp(() {
mockSimControl = MockSimControl();
mockXcode = MockXcode();
mockProcessManager = MockProcessManager();
when(mockProcessManager.start(any, environment: null, workingDirectory: null))
.thenAnswer((Invocation invocation) => Future<Process>.value(MockProcess()));
});
testUsingContext('uses tail on iOS versions prior to iOS 11', () async {
final IOSSimulator device = IOSSimulator(
'x', 'x',
name: 'iPhone SE', 'log',
simulatorCategory: 'iOS 9.3', 'stream',
simControl: mockSimControl, '--style',
xcode: mockXcode, 'json',
); '--predicate',
await launchSystemLogTool(device); expectedPredicate
expect( ]);
verify(mockProcessManager.start(captureAny, environment: null, workingDirectory: null)).captured.single,
contains('tail'),
);
}, },
overrides: <Type, Generator>{ overrides: <Type, Generator>{
ProcessManager: () => mockProcessManager, ProcessManager: () => mockProcessManager,
FileSystem: () => fileSystem, FileSystem: () => fileSystem,
}); });
testUsingContext('uses /usr/bin/log on iOS 11 and above', () async { testUsingContext('unified logging without app name', () async {
final IOSSimulator device = IOSSimulator( final IOSSimulator device = IOSSimulator(
'x', 'x',
name: 'iPhone SE', name: 'iPhone SE',
...@@ -503,13 +486,32 @@ void main() { ...@@ -503,13 +486,32 @@ void main() {
simControl: mockSimControl, simControl: mockSimControl,
xcode: mockXcode, xcode: mockXcode,
); );
await launchSystemLogTool(device); await launchDeviceUnifiedLogging(device, null);
verifyNever(mockProcessManager.start(any, environment: null, workingDirectory: null));
const String expectedPredicate = 'eventType = logEvent AND '
'(senderImagePath ENDSWITH "/Flutter" OR senderImagePath ENDSWITH "/libswiftCore.dylib" OR processImageUUID == senderImageUUID) AND '
'NOT(eventMessage CONTAINS ": could not find icon for representation -> com.apple.") AND '
'NOT(eventMessage BEGINSWITH "assertion failed: ") AND '
'NOT(eventMessage CONTAINS " libxpc.dylib ")';
final List<String> command = verify(mockProcessManager.start(captureAny, environment: null, workingDirectory: null)).captured.single as List<String>;
expect(command, <String>[
'/usr/bin/xcrun',
'simctl',
'spawn',
'x',
'log',
'stream',
'--style',
'json',
'--predicate',
expectedPredicate
]);
}, },
overrides: <Type, Generator>{ overrides: <Type, Generator>{
ProcessManager: () => mockProcessManager, ProcessManager: () => mockProcessManager,
FileSystem: () => fileSystem, FileSystem: () => fileSystem,
}); });
}); });
group('log reader', () { group('log reader', () {
...@@ -525,55 +527,62 @@ void main() { ...@@ -525,55 +527,62 @@ void main() {
mockXcode = MockXcode(); mockXcode = MockXcode();
}); });
testUsingContext('simulator can output `)`', () async { group('syslog', () {
when(mockProcessManager.start(any, environment: null, workingDirectory: null)) setUp(() {
.thenAnswer((Invocation invocation) { final File syslog = fileSystem.file('system.log')..createSync();
osx.environment['IOS_SIMULATOR_LOG_FILE_PATH'] = syslog.path;
});
testUsingContext('simulator can output `)`', () async {
when(mockProcessManager.start(any, environment: null, workingDirectory: null))
.thenAnswer((Invocation invocation) {
final Process mockProcess = MockProcess(); final Process mockProcess = MockProcess();
when(mockProcess.stdout) when(mockProcess.stdout)
.thenAnswer((Invocation invocation) { .thenAnswer((Invocation invocation) {
return Stream<List<int>>.fromIterable(<List<int>>[''' return Stream<List<int>>.fromIterable(<List<int>>['''
2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) Observatory listening on http://127.0.0.1:57701/ 2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) Observatory listening on http://127.0.0.1:57701/
2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) )))))))))) 2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) ))))))))))
2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) #0 Object.noSuchMethod (dart:core-patch/dart:core/object_patch.dart:46)''' 2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) #0 Object.noSuchMethod (dart:core-patch/dart:core/object_patch.dart:46)'''
.codeUnits]); .codeUnits]);
}); });
when(mockProcess.stderr) when(mockProcess.stderr)
.thenAnswer((Invocation invocation) => const Stream<List<int>>.empty()); .thenAnswer((Invocation invocation) => const Stream<List<int>>.empty());
// Delay return of exitCode until after stdout stream data, since it terminates the logger. // Delay return of exitCode until after stdout stream data, since it terminates the logger.
when(mockProcess.exitCode) when(mockProcess.exitCode)
.thenAnswer((Invocation invocation) => Future<int>.delayed(Duration.zero, () => 0)); .thenAnswer((Invocation invocation) => Future<int>.delayed(Duration.zero, () => 0));
return Future<Process>.value(mockProcess); return Future<Process>.value(mockProcess);
}); });
final IOSSimulator device = IOSSimulator( final IOSSimulator device = IOSSimulator(
'123456', '123456',
simulatorCategory: 'iOS 11.0', simulatorCategory: 'iOS 10.3',
simControl: mockSimControl, simControl: mockSimControl,
xcode: mockXcode, xcode: mockXcode,
); );
final DeviceLogReader logReader = device.getLogReader( final DeviceLogReader logReader = device.getLogReader(
app: await BuildableIOSApp.fromProject(mockIosProject), app: await BuildableIOSApp.fromProject(mockIosProject),
); );
final List<String> lines = await logReader.logLines.toList(); final List<String> lines = await logReader.logLines.toList();
expect(lines, <String>[ expect(lines, <String>[
'Observatory listening on http://127.0.0.1:57701/', 'Observatory listening on http://127.0.0.1:57701/',
'))))))))))', '))))))))))',
'#0 Object.noSuchMethod (dart:core-patch/dart:core/object_patch.dart:46)', '#0 Object.noSuchMethod (dart:core-patch/dart:core/object_patch.dart:46)',
]); ]);
}, overrides: <Type, Generator>{ }, overrides: <Type, Generator>{
ProcessManager: () => mockProcessManager, ProcessManager: () => mockProcessManager,
FileSystem: () => fileSystem, FileSystem: () => fileSystem,
}); Platform: () => osx,
});
testUsingContext('log reader handles multiline messages', () async { testUsingContext('log reader handles multiline messages', () async {
when(mockProcessManager.start(any, environment: null, workingDirectory: null)) when(mockProcessManager.start(any, environment: null, workingDirectory: null))
.thenAnswer((Invocation invocation) { .thenAnswer((Invocation invocation) {
final Process mockProcess = MockProcess(); final Process mockProcess = MockProcess();
when(mockProcess.stdout) when(mockProcess.stdout)
.thenAnswer((Invocation invocation) { .thenAnswer((Invocation invocation) {
// Messages from 2017 should pass through, 2020 message should not // Messages from 2017 should pass through, 2020 message should not
return Stream<List<int>>.fromIterable(<List<int>>[''' return Stream<List<int>>.fromIterable(<List<int>>['''
2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) Single line message 2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) Single line message
2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) Multi line message 2017-09-13 15:26:57.228948-0700 localhost Runner[37195]: (Flutter) Multi line message
continues... continues...
...@@ -588,40 +597,94 @@ void main() { ...@@ -588,40 +597,94 @@ void main() {
and goes... and goes...
2017-09-13 15:36:57.228948-0700 localhost Runner[37195]: (Flutter) Single line message, not the part of the above 2017-09-13 15:36:57.228948-0700 localhost Runner[37195]: (Flutter) Single line message, not the part of the above
''' '''
.codeUnits]); .codeUnits]);
}); });
when(mockProcess.stderr) when(mockProcess.stderr)
.thenAnswer((Invocation invocation) => const Stream<List<int>>.empty()); .thenAnswer((Invocation invocation) => const Stream<List<int>>.empty());
// Delay return of exitCode until after stdout stream data, since it terminates the logger. // Delay return of exitCode until after stdout stream data, since it terminates the logger.
when(mockProcess.exitCode) when(mockProcess.exitCode)
.thenAnswer((Invocation invocation) => Future<int>.delayed(Duration.zero, () => 0)); .thenAnswer((Invocation invocation) => Future<int>.delayed(Duration.zero, () => 0));
return Future<Process>.value(mockProcess); return Future<Process>.value(mockProcess);
}); });
final IOSSimulator device = IOSSimulator( final IOSSimulator device = IOSSimulator(
'123456', '123456',
simulatorCategory: 'iOS 11.0', simulatorCategory: 'iOS 10.3',
simControl: mockSimControl, simControl: mockSimControl,
xcode: mockXcode, xcode: mockXcode,
); );
final DeviceLogReader logReader = device.getLogReader( final DeviceLogReader logReader = device.getLogReader(
app: await BuildableIOSApp.fromProject(mockIosProject), app: await BuildableIOSApp.fromProject(mockIosProject),
); );
final List<String> lines = await logReader.logLines.toList();
expect(lines, <String>[
'Single line message',
'Multi line message',
' continues...',
' continues...',
'Multi line message again',
' and it goes...',
' and goes...',
'Single line message, not the part of the above'
]);
}, overrides: <Type, Generator>{
ProcessManager: () => mockProcessManager,
FileSystem: () => fileSystem,
Platform: () => osx,
});
});
final List<String> lines = await logReader.logLines.toList(); group('unified logging', () {
expect(lines, <String>[ testUsingContext('log reader handles escaped multiline messages', () async {
'Single line message', when(mockProcessManager.start(any, environment: null, workingDirectory: null))
'Multi line message', .thenAnswer((Invocation invocation) {
' continues...', final Process mockProcess = MockProcess();
' continues...', when(mockProcess.stdout)
'Multi line message again', .thenAnswer((Invocation invocation) {
' and it goes...', return Stream<List<int>>.fromIterable(<List<int>>['''
' and goes...', },{
'Single line message, not the part of the above' "traceID" : 37579774151491588,
]); "eventMessage" : "Single line message",
}, overrides: <Type, Generator>{ "eventType" : "logEvent"
ProcessManager: () => mockProcessManager, },{
FileSystem: () => fileSystem, "traceID" : 37579774151491588,
"eventMessage" : "Multi line message\\n continues...\\n continues..."
},{
"traceID" : 37579774151491588,
"eventMessage" : "Single line message, not the part of the above",
"eventType" : "logEvent"
},{
'''
.codeUnits]);
});
when(mockProcess.stderr)
.thenAnswer((Invocation invocation) => const Stream<List<int>>.empty());
// Delay return of exitCode until after stdout stream data, since it terminates the logger.
when(mockProcess.exitCode)
.thenAnswer((Invocation invocation) => Future<int>.delayed(Duration.zero, () => 0));
return Future<Process>.value(mockProcess);
});
final IOSSimulator device = IOSSimulator(
'123456',
simulatorCategory: 'iOS 11.0',
simControl: mockSimControl,
xcode: mockXcode,
);
final DeviceLogReader logReader = device.getLogReader(
app: await BuildableIOSApp.fromProject(mockIosProject),
);
final List<String> lines = await logReader.logLines.toList();
expect(lines, <String>[
'Single line message', 'Multi line message\n continues...\n continues...',
'Single line message, not the part of the above'
]);
}, overrides: <Type, Generator>{
ProcessManager: () => mockProcessManager,
FileSystem: () => fileSystem,
});
}); });
}); });
......
Markdown is supported
0% or
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment