Allow to start only one instance of log listener and crash watcher

Summary:
Changelog: Allow only a single crash watcher and a single log listener per device. Start log listener and crash watcher for every device upon connection. Remove commands to start/stop them externally.

Monitored CPU load for a physical Android device with the log listener on and off. Did not notice any real difference.

Resolved crashing adbkit-logcat by forcing the usage of 2.0.1. A proper fix would be to unify babel transforms for browser flipper and electron flipper, but we might re-think how we distribute flipper in the next half, so a simple hot fix might be a better use of time and resources.

Reviewed By: mweststrate

Differential Revision: D33132506

fbshipit-source-id: 39d422682a10a64830ac516e30f43f32f416819d
This commit is contained in:
Andrey Goncharov
2021-12-20 11:37:25 -08:00
committed by Facebook GitHub Bot
parent 731749b41f
commit debf872806
19 changed files with 838 additions and 424 deletions

View File

@@ -5,7 +5,10 @@
"rootDir": "src", "rootDir": "src",
"esModuleInterop": true, "esModuleInterop": true,
"emitDeclarationOnly": true, "emitDeclarationOnly": true,
"lib": ["DOM", "ES2019"] "lib": ["DOM", "ES2019"],
"types": [
"../types/flipperGlobals"
]
}, },
"references": [ "references": [
{ {

View File

@@ -11,7 +11,7 @@ import {CallExpression} from '@babel/types';
import {NodePath} from '@babel/traverse'; import {NodePath} from '@babel/traverse';
module.exports = () => ({ module.exports = () => ({
name: 'change-electron-to-electronRequire-in-main', name: 'change-require-to-electronRequire-in-main',
visitor: { visitor: {
CallExpression(path: NodePath<CallExpression>) { CallExpression(path: NodePath<CallExpression>) {
const node = path.node; const node = path.node;

View File

@@ -58,7 +58,7 @@ const IGNORED_MODULES = [
]; ];
module.exports = () => ({ module.exports = () => ({
name: 'infinity-import-react', name: 'change-require-to-electronRequire-in-electron-app',
visitor: { visitor: {
CallExpression(path: NodePath<CallExpression>) { CallExpression(path: NodePath<CallExpression>) {
const node = path.node; const node = path.node;

View File

@@ -198,10 +198,6 @@ export type FlipperServerCommands = {
'get-config': () => Promise<FlipperServerConfig>; 'get-config': () => Promise<FlipperServerConfig>;
'get-changelog': () => Promise<string>; 'get-changelog': () => Promise<string>;
'device-list': () => Promise<DeviceDescription[]>; 'device-list': () => Promise<DeviceDescription[]>;
'device-start-logging': (serial: string) => Promise<void>;
'device-stop-logging': (serial: string) => Promise<void>;
'device-start-crash-watcher': (serial: string) => Promise<void>;
'device-stop-crash-watcher': (serial: string) => Promise<void>;
'device-supports-screenshot': (serial: string) => Promise<boolean>; 'device-supports-screenshot': (serial: string) => Promise<boolean>;
'device-supports-screencapture': (serial: string) => Promise<boolean>; 'device-supports-screencapture': (serial: string) => Promise<boolean>;
'device-take-screenshot': (serial: string) => Promise<string>; // base64 encoded buffer 'device-take-screenshot': (serial: string) => Promise<string>; // base64 encoded buffer

View File

@@ -285,14 +285,6 @@ export class FlipperServerImpl implements FlipperServer {
'device-list': async () => { 'device-list': async () => {
return Array.from(this.devices.values()).map((d) => d.info); return Array.from(this.devices.values()).map((d) => d.info);
}, },
'device-start-logging': async (serial: string) =>
this.getDevice(serial).startLogging(),
'device-stop-logging': async (serial: string) =>
this.getDevice(serial).stopLogging(),
'device-start-crash-watcher': async (serial: string) =>
this.getDevice(serial).startCrashWatcher(),
'device-stop-crash-watcher': async (serial: string) =>
this.getDevice(serial).stopCrashWatcher(),
'device-supports-screenshot': async (serial: string) => 'device-supports-screenshot': async (serial: string) =>
this.getDevice(serial).screenshotAvailable(), this.getDevice(serial).screenshotAvailable(),
'device-supports-screencapture': async (serial: string) => 'device-supports-screencapture': async (serial: string) =>

View File

@@ -8,6 +8,7 @@
*/ */
import {DeviceDescription, DeviceLogEntry} from 'flipper-common'; import {DeviceDescription, DeviceLogEntry} from 'flipper-common';
import {DeviceListener, NoopListener} from '../utils/DeviceListener';
import {FlipperServerImpl} from '../FlipperServerImpl'; import {FlipperServerImpl} from '../FlipperServerImpl';
export abstract class ServerDevice { export abstract class ServerDevice {
@@ -17,6 +18,11 @@ export abstract class ServerDevice {
protected stopCrashWatcherCb?: () => void; protected stopCrashWatcherCb?: () => void;
readonly logListener: DeviceListener = new NoopListener(() => this.connected);
readonly crashWatcher: DeviceListener = new NoopListener(
() => this.connected,
);
constructor(flipperServer: FlipperServerImpl, info: DeviceDescription) { constructor(flipperServer: FlipperServerImpl, info: DeviceDescription) {
this.flipperServer = flipperServer; this.flipperServer = flipperServer;
this.info = info; this.info = info;
@@ -38,28 +44,8 @@ export abstract class ServerDevice {
*/ */
disconnect(): void { disconnect(): void {
this.connected = false; this.connected = false;
} this.logListener.stop();
this.crashWatcher.stop();
startLogging() {
// to be subclassed
}
stopLogging() {
// to be subclassed
}
startCrashWatcher() {
this.stopCrashWatcherCb = this.startCrashWatcherImpl?.();
}
protected startCrashWatcherImpl(): () => void {
// to be subclassed
return () => {};
}
stopCrashWatcher() {
this.stopCrashWatcherCb?.();
this.stopCrashWatcherCb = undefined;
} }
async screenshotAvailable(): Promise<boolean> { async screenshotAvailable(): Promise<boolean> {

View File

@@ -7,9 +7,9 @@
* @format * @format
*/ */
import {Entry, Priority} from 'adbkit-logcat'; import type {CrashLog, DeviceLogEntry} from 'flipper-common';
import type {CrashLog} from 'flipper-common'; import {DeviceListener} from '../../utils/DeviceListener';
import AndroidDevice from './AndroidDevice'; import {ServerDevice} from '../ServerDevice';
export function parseAndroidCrash(content: string, logDate?: Date) { export function parseAndroidCrash(content: string, logDate?: Date) {
const regForName = /.*\n/; const regForName = /.*\n/;
@@ -38,33 +38,52 @@ export function parseAndroidCrash(content: string, logDate?: Date) {
return crash; return crash;
} }
export function shouldParseAndroidLog(entry: Entry, date: Date): boolean { export function shouldParseAndroidLog(
entry: DeviceLogEntry,
date: Date,
): boolean {
return ( return (
entry.date.getTime() - date.getTime() > 0 && // The log should have arrived after the device has been registered entry.date.getTime() - date.getTime() > 0 && // The log should have arrived after the device has been registered
((entry.priority === Priority.ERROR && entry.tag === 'AndroidRuntime') || ((entry.type === 'error' && entry.tag === 'AndroidRuntime') ||
entry.priority === Priority.FATAL) entry.type === 'fatal')
); );
} }
/** export class AndroidCrashWatcher extends DeviceListener {
* Starts listening ADB logs. Emits 'device-crash' on "error" and "fatal" entries. constructor(private readonly device: ServerDevice) {
* Listens to the logs in a separate stream. super(() => device.connected);
* We can't leverage teh existing log listener mechanism (see `startLogging`) }
* it is started externally (by the client). Refactoring how we start log listeners is a bit too much. protected async startListener() {
* It is easier to start its own stream for crash watcher and manage it independently.
*/
export function startAndroidCrashWatcher(device: AndroidDevice) {
const referenceDate = new Date(); const referenceDate = new Date();
let androidLog: string = ''; let androidLog: string = '';
let androidLogUnderProcess = false; let androidLogUnderProcess = false;
let timer: null | NodeJS.Timeout = null; let timer: null | NodeJS.Timeout = null;
let gracefulShutdown = false;
const readerPromise = device.adb // Wait for the start of the log listener
.openLogcat(device.serial, {clear: true}) await new Promise<void>((resolve, reject) => {
.then((reader) => const unsubscribeFatal = this.device.logListener.once('fatal', () => {
reader reject(
.on('entry', (entry) => { this.device.logListener.error ??
if (shouldParseAndroidLog(entry, referenceDate)) { new Error('Unknown log listener error'),
);
});
this.device.logListener.once('active', () => {
unsubscribeFatal();
resolve();
});
});
const onDeviceLog = ({
entry,
serial,
}: {
entry: DeviceLogEntry;
serial: string;
}) => {
if (
serial === this.device.serial &&
shouldParseAndroidLog(entry, referenceDate)
) {
if (androidLogUnderProcess) { if (androidLogUnderProcess) {
androidLog += '\n' + entry.message; androidLog += '\n' + entry.message;
androidLog = androidLog.trim(); androidLog = androidLog.trim();
@@ -77,43 +96,29 @@ export function startAndroidCrashWatcher(device: AndroidDevice) {
} }
timer = setTimeout(() => { timer = setTimeout(() => {
if (androidLog.length > 0) { if (androidLog.length > 0) {
device.flipperServer.emit('device-crash', { this.device.flipperServer.emit('device-crash', {
crash: parseAndroidCrash(androidLog, entry.date), crash: parseAndroidCrash(androidLog, entry.date),
serial: device.info.serial, serial: this.device.serial,
}); });
} }
androidLogUnderProcess = false; androidLogUnderProcess = false;
androidLog = ''; androidLog = '';
}, 50); }, 50);
} }
}) };
.on('end', () => {
if (!gracefulShutdown) { this.device.flipperServer.on('device-log', onDeviceLog);
// logs didn't stop gracefully this.device.logListener.on('fatal', () =>
setTimeout(() => {
if (device.connected) {
console.warn( console.warn(
`Log stream broken: ${device.serial} - restarting`, 'AndroidCrashWatcher -> log listener failed. Crash listener is not functional until log listener restarts.',
),
); );
device.startCrashWatcher();
}
}, 100);
}
})
.on('error', (e) => {
console.warn('Failed to read from adb logcat: ', e);
}),
)
.catch((e) => {
console.warn('Failed to open log stream: ', e);
});
return () => { return () => {
gracefulShutdown = true; if (timer) {
readerPromise clearTimeout(timer);
.then((reader) => reader?.end()) }
.catch((e) => { this.device.flipperServer.off('device-log', onDeviceLog);
console.error('Failed to close adb logcat stream: ', e);
});
}; };
}
} }

View File

@@ -8,16 +8,17 @@
*/ */
import adb, {Client as ADBClient, PullTransfer} from 'adbkit'; import adb, {Client as ADBClient, PullTransfer} from 'adbkit';
import {Priority, Reader} from 'adbkit-logcat'; import {Reader} from 'adbkit-logcat';
import {createWriteStream} from 'fs'; import {createWriteStream} from 'fs';
import type {DeviceLogLevel, DeviceType} from 'flipper-common'; import type {DeviceType} from 'flipper-common';
import which from 'which'; import which from 'which';
import {spawn} from 'child_process'; import {spawn} from 'child_process';
import {dirname, join} from 'path'; import {dirname, join} from 'path';
import {DeviceSpec} from 'flipper-common'; import {DeviceSpec} from 'flipper-common';
import {ServerDevice} from '../ServerDevice'; import {ServerDevice} from '../ServerDevice';
import {FlipperServerImpl} from '../../FlipperServerImpl'; import {FlipperServerImpl} from '../../FlipperServerImpl';
import {startAndroidCrashWatcher} from './AndroidCrashUtils'; import {AndroidCrashWatcher} from './AndroidCrashUtils';
import {AndroidLogListener} from './AndroidLogListener';
const DEVICE_RECORDING_DIR = '/sdcard/flipper_recorder'; const DEVICE_RECORDING_DIR = '/sdcard/flipper_recorder';
@@ -26,6 +27,8 @@ export default class AndroidDevice extends ServerDevice {
pidAppMapping: {[key: number]: string} = {}; pidAppMapping: {[key: number]: string} = {};
private recordingProcess?: Promise<string>; private recordingProcess?: Promise<string>;
reader?: Reader; reader?: Reader;
readonly logListener: AndroidLogListener;
readonly crashWatcher: AndroidCrashWatcher;
constructor( constructor(
flipperServer: FlipperServerImpl, flipperServer: FlipperServerImpl,
@@ -48,74 +51,30 @@ export default class AndroidDevice extends ServerDevice {
sdkVersion, sdkVersion,
}); });
this.adb = adb; this.adb = adb;
}
// TODO: Prevent starting logging multiple times this.logListener = new AndroidLogListener(
startLogging() { () => this.connected,
this.adb (logEntry) => this.addLogEntry(logEntry),
.openLogcat(this.serial, {clear: true}) this.adb,
.then((reader) => { this.serial,
this.reader = reader; );
reader // It is OK not to await the start of the log listener. We just spawn it and handle errors internally.
.on('entry', (entry) => { this.logListener
let type: DeviceLogLevel = 'unknown'; .start()
if (entry.priority === Priority.VERBOSE) { .catch((e) =>
type = 'verbose'; console.error('AndroidDevice.logListener.start -> unexpected error', e),
} );
if (entry.priority === Priority.DEBUG) { this.crashWatcher = new AndroidCrashWatcher(this);
type = 'debug'; // It is OK not to await the start of the crash watcher. We just spawn it and handle errors internally.
} // Crash watcher depends on functioning log listener. It waits for its start internally.
if (entry.priority === Priority.INFO) { this.crashWatcher
type = 'info'; .start()
} .catch((e) =>
if (entry.priority === Priority.WARN) { console.error(
type = 'warn'; 'AndroidDevice.crashWatcher.start -> unexpected error',
} e,
if (entry.priority === Priority.ERROR) { ),
type = 'error';
}
if (entry.priority === Priority.FATAL) {
type = 'fatal';
}
this.addLogEntry({
tag: entry.tag,
pid: entry.pid,
tid: entry.tid,
message: entry.message,
date: entry.date,
type,
});
})
.on('end', () => {
if (this.reader) {
// logs didn't stop gracefully
setTimeout(() => {
if (this.connected) {
console.warn(
`Log stream broken: ${this.serial} - restarting`,
); );
this.startLogging();
}
}, 100);
}
})
.on('error', (e) => {
console.warn('Failed to read from adb logcat: ', e);
});
})
.catch((e) => {
console.warn('Failed to open log stream: ', e);
});
}
stopLogging() {
this.reader?.end();
this.reader = undefined;
}
protected startCrashWatcherImpl(): () => void {
return startAndroidCrashWatcher(this);
} }
reverse(ports: number[]): Promise<void> { reverse(ports: number[]): Promise<void> {

View File

@@ -0,0 +1,83 @@
/**
* Copyright (c) Facebook, Inc. and its affiliates.
*
* This source code is licensed under the MIT license found in the
* LICENSE file in the root directory of this source tree.
*
* @format
*/
import type {Client as ADBClient} from 'adbkit';
import {Priority} from 'adbkit-logcat';
import {DeviceLogEntry, DeviceLogLevel} from 'flipper-common';
import {DeviceListener} from '../../utils/DeviceListener';
export class AndroidLogListener extends DeviceListener {
constructor(
isDeviceConnected: () => boolean,
private onNewLogEntry: (logEntry: DeviceLogEntry) => void,
private readonly adb: ADBClient,
private readonly serial: string,
) {
super(isDeviceConnected);
}
protected async startListener() {
const reader = await this.adb.openLogcat(this.serial, {
clear: true,
});
let gracefulShutdown = false;
let lastKnownError: Error | undefined;
reader
.on('entry', (entry) => {
let type: DeviceLogLevel = 'unknown';
if (entry.priority === Priority.VERBOSE) {
type = 'verbose';
}
if (entry.priority === Priority.DEBUG) {
type = 'debug';
}
if (entry.priority === Priority.INFO) {
type = 'info';
}
if (entry.priority === Priority.WARN) {
type = 'warn';
}
if (entry.priority === Priority.ERROR) {
type = 'error';
}
if (entry.priority === Priority.FATAL) {
type = 'fatal';
}
this.onNewLogEntry({
tag: entry.tag,
pid: entry.pid,
tid: entry.tid,
message: entry.message,
date: entry.date,
type,
});
})
.on('end', () => {
if (!gracefulShutdown) {
// logs didn't stop gracefully
console.error('Unexpected shutdown of adb logcat');
this._state.set(
'fatal',
lastKnownError ?? new Error('Unexpected shutdown of adb logcat'),
);
}
})
.on('error', (e) => {
console.warn('Failed to read from adb logcat: ', e);
lastKnownError = e;
});
return () => {
gracefulShutdown = true;
reader.end();
};
}
}

View File

@@ -7,23 +7,23 @@
* @format * @format
*/ */
import {Entry, Priority} from 'adbkit-logcat'; import {DeviceLogEntry} from 'flipper-plugin';
import {parseAndroidCrash, shouldParseAndroidLog} from '../AndroidCrashUtils'; import {parseAndroidCrash, shouldParseAndroidLog} from '../AndroidCrashUtils';
function getAndroidLog( function getAndroidLog(
date: Date, date: Date,
priority: number, type: DeviceLogEntry['type'],
tag: string, tag: string,
message: string, message: string,
) { ): DeviceLogEntry {
return {date, priority, tag, message, pid: 0, tid: 0} as Entry; return {date, type, tag, message, pid: 0, tid: 0};
} }
test('test shouldParseAndroidLog function for type error and tag is AndroidRuntime', () => { test('test shouldParseAndroidLog function for type error and tag is AndroidRuntime', () => {
const referenceDate = new Date(); const referenceDate = new Date();
const log = getAndroidLog( const log = getAndroidLog(
new Date(referenceDate.getTime() + 10000), //This log arrives 10 secs after the refernce time new Date(referenceDate.getTime() + 10000), //This log arrives 10 secs after the refernce time
Priority.ERROR, 'error',
'AndroidRuntime', 'AndroidRuntime',
'Possible runtime crash', 'Possible runtime crash',
); );
@@ -34,7 +34,7 @@ test('test shouldParseAndroidLog function for type non-error', () => {
const referenceDate = new Date(); const referenceDate = new Date();
const log = getAndroidLog( const log = getAndroidLog(
new Date(referenceDate.getTime() + 10000), //This log arrives 10 secs after the refernce time new Date(referenceDate.getTime() + 10000), //This log arrives 10 secs after the refernce time
Priority.DEBUG, 'debug',
'fb4a.activitymanager', 'fb4a.activitymanager',
'Possible debug info in activitymanager', 'Possible debug info in activitymanager',
); );
@@ -45,7 +45,7 @@ test('test shouldParseAndroidLog function for the older android log', () => {
const referenceDate = new Date(); const referenceDate = new Date();
const log = getAndroidLog( const log = getAndroidLog(
new Date(referenceDate.getTime() - 10000), //This log arrives 10 secs before the refernce time new Date(referenceDate.getTime() - 10000), //This log arrives 10 secs before the refernce time
Priority.ERROR, 'error',
'fb4a.activitymanager', 'fb4a.activitymanager',
'Possible error info in activitymanager', 'Possible error info in activitymanager',
); );
@@ -56,7 +56,7 @@ test('test shouldParseAndroidLog function for the fatal log', () => {
const referenceDate = new Date(); const referenceDate = new Date();
const log = getAndroidLog( const log = getAndroidLog(
new Date(referenceDate.getTime() + 10000), //This log arrives 10 secs after the refernce time new Date(referenceDate.getTime() + 10000), //This log arrives 10 secs after the refernce time
Priority.FATAL, 'fatal',
'arbitrary tag', 'arbitrary tag',
'Possible error info in activitymanager', 'Possible error info in activitymanager',
); );
@@ -67,7 +67,7 @@ test('test shouldParseAndroidLog function for the error log which does not stais
const referenceDate = new Date(); const referenceDate = new Date();
const log = getAndroidLog( const log = getAndroidLog(
new Date(referenceDate.getTime() + 10000), //This log arrives 10 secs after the refernce time new Date(referenceDate.getTime() + 10000), //This log arrives 10 secs after the refernce time
Priority.ERROR, 'error',
'arbitrary tag', 'arbitrary tag',
'Possible error info in fb4a', 'Possible error info in fb4a',
); );

View File

@@ -7,43 +7,13 @@
* @format * @format
*/ */
import { import {DeviceType, timeout} from 'flipper-common';
DeviceLogLevel,
DeviceLogEntry,
DeviceType,
timeout,
} from 'flipper-common';
import child_process, {ChildProcess} from 'child_process'; import child_process, {ChildProcess} from 'child_process';
import JSONStream from 'JSONStream'; import {IOSBridge} from './IOSBridge';
import {Transform} from 'stream';
import {ERR_PHYSICAL_DEVICE_LOGS_WITHOUT_IDB, IOSBridge} from './IOSBridge';
import split2 from 'split2';
import {ServerDevice} from '../ServerDevice'; import {ServerDevice} from '../ServerDevice';
import {FlipperServerImpl} from '../../FlipperServerImpl'; import {FlipperServerImpl} from '../../FlipperServerImpl';
import {addFileWatcherForiOSCrashLogs} from './iOSCrashUtils'; import {iOSCrashWatcher} from './iOSCrashUtils';
import {iOSLogListener} from './iOSLogListener';
type IOSLogLevel = 'Default' | 'Info' | 'Debug' | 'Error' | 'Fault';
type RawLogEntry = {
eventMessage: string;
machTimestamp: number;
messageType: IOSLogLevel;
processID: number;
processImagePath: string;
processImageUUID: string;
processUniqueID: number;
senderImagePath: string;
senderImageUUID: string;
senderProgramCounter: number;
threadID: number;
timestamp: string;
timezoneName: string;
traceID: string;
};
// https://regex101.com/r/rrl03T/1
// Mar 25 17:06:38 iPhone symptomsd(SymptomEvaluator)[125] <Notice>: Stuff
const logRegex = /(^.{15}) ([^ ]+?) ([^\[]+?)\[(\d+?)\] <(\w+?)>: (.*)$/s;
export default class IOSDevice extends ServerDevice { export default class IOSDevice extends ServerDevice {
log?: child_process.ChildProcessWithoutNullStreams; log?: child_process.ChildProcessWithoutNullStreams;
@@ -51,6 +21,8 @@ export default class IOSDevice extends ServerDevice {
private recordingProcess?: ChildProcess; private recordingProcess?: ChildProcess;
private recordingLocation?: string; private recordingLocation?: string;
private iOSBridge: IOSBridge; private iOSBridge: IOSBridge;
readonly logListener: iOSLogListener;
readonly crashWatcher: iOSCrashWatcher;
constructor( constructor(
flipperServer: FlipperServerImpl, flipperServer: FlipperServerImpl,
@@ -68,6 +40,27 @@ export default class IOSDevice extends ServerDevice {
}); });
this.buffer = ''; this.buffer = '';
this.iOSBridge = iOSBridge; this.iOSBridge = iOSBridge;
this.logListener = new iOSLogListener(
() => this.connected,
(logEntry) => this.addLogEntry(logEntry),
this.iOSBridge,
this.serial,
this.info.deviceType,
);
// It is OK not to await the start of the log listener. We just spawn it and handle errors internally.
this.logListener
.start()
.catch((e) =>
console.error('IOSDevice.logListener.start -> unexpected error', e),
);
this.crashWatcher = new iOSCrashWatcher(this);
// It is OK not to await the start of the crash watcher. We just spawn it and handle errors internally.
this.crashWatcher
.start()
.catch((e) =>
console.error('IOSDevice.crashWatcher.start -> unexpected error', e),
);
} }
async screenshot(): Promise<Buffer> { async screenshot(): Promise<Buffer> {
@@ -84,146 +77,6 @@ export default class IOSDevice extends ServerDevice {
}); });
} }
startLogging() {
this.startLogListener(this.iOSBridge);
}
stopLogging() {
this.log?.kill();
}
startLogListener(iOSBridge: IOSBridge, retries: number = 3) {
if (retries === 0) {
console.warn('Attaching iOS log listener continuously failed.');
return;
}
if (!this.log) {
try {
this.log = iOSBridge.startLogListener(
this.serial,
this.info.deviceType,
);
} catch (e) {
if (e.message === ERR_PHYSICAL_DEVICE_LOGS_WITHOUT_IDB) {
console.warn(e);
} else {
console.error('Failed to initialise device logs:', e);
this.startLogListener(iOSBridge, retries - 1);
}
return;
}
this.log.on('error', (err: Error) => {
console.error('iOS log tailer error', err);
});
this.log.stderr.on('data', (data: Buffer) => {
console.warn('iOS log tailer stderr: ', data.toString());
});
this.log.on('exit', () => {
this.log = undefined;
});
try {
if (this.info.deviceType === 'physical') {
this.log.stdout.pipe(split2('\0')).on('data', (line: string) => {
const parsed = IOSDevice.parseLogLine(line);
if (parsed) {
this.addLogEntry(parsed);
} else {
console.warn('Failed to parse iOS log line: ', line);
}
});
} else {
this.log.stdout
.pipe(new StripLogPrefix())
.pipe(JSONStream.parse('*'))
.on('data', (data: RawLogEntry) => {
const entry = IOSDevice.parseJsonLogEntry(data);
this.addLogEntry(entry);
});
}
} catch (e) {
console.error('Could not parse iOS log stream.', e);
// restart log stream
this.log.kill();
this.log = undefined;
this.startLogListener(iOSBridge, retries - 1);
}
}
}
protected startCrashWatcherImpl(): () => void {
return addFileWatcherForiOSCrashLogs(this);
}
static getLogLevel(level: string): DeviceLogLevel {
switch (level) {
case 'Default':
return 'debug';
case 'Info':
return 'info';
case 'Debug':
return 'debug';
case 'Error':
return 'error';
case 'Notice':
return 'verbose';
case 'Fault':
return 'fatal';
default:
return 'unknown';
}
}
static parseLogLine(line: string): DeviceLogEntry | undefined {
const matches = line.match(logRegex);
if (matches) {
return {
date: new Date(Date.parse(matches[1])),
tag: matches[3],
tid: 0,
pid: parseInt(matches[4], 10),
type: IOSDevice.getLogLevel(matches[5]),
message: matches[6],
};
}
return undefined;
}
static parseJsonLogEntry(entry: RawLogEntry): DeviceLogEntry {
let type: DeviceLogLevel = IOSDevice.getLogLevel(entry.messageType);
// when Apple log levels are not used, log messages can be prefixed with
// their loglevel.
if (entry.eventMessage.startsWith('[debug]')) {
type = 'debug';
} else if (entry.eventMessage.startsWith('[info]')) {
type = 'info';
} else if (entry.eventMessage.startsWith('[warn]')) {
type = 'warn';
} else if (entry.eventMessage.startsWith('[error]')) {
type = 'error';
}
// remove type from mesage
entry.eventMessage = entry.eventMessage.replace(
/^\[(debug|info|warn|error)\]/,
'',
);
const tag = entry.processImagePath.split('/').pop() || '';
return {
date: new Date(entry.timestamp),
pid: entry.processID,
tid: entry.threadID,
tag,
message: entry.eventMessage,
type,
};
}
async screenCaptureAvailable() { async screenCaptureAvailable() {
return this.info.deviceType === 'emulator' && this.connected; return this.info.deviceType === 'emulator' && this.connected;
} }
@@ -275,27 +128,3 @@ export default class IOSDevice extends ServerDevice {
super.disconnect(); super.disconnect();
} }
} }
// Used to strip the initial output of the logging utility where it prints out settings.
// We know the log stream is json so it starts with an open brace.
class StripLogPrefix extends Transform {
passedPrefix = false;
_transform(
data: any,
_encoding: string,
callback: (err?: Error, data?: any) => void,
) {
if (this.passedPrefix) {
this.push(data);
} else {
const dataString = data.toString();
const index = dataString.indexOf('[');
if (index >= 0) {
this.push(dataString.substring(index));
this.passedPrefix = true;
}
}
callback();
}
}

View File

@@ -8,6 +8,7 @@
*/ */
import type {CrashLog} from 'flipper-common'; import type {CrashLog} from 'flipper-common';
import {DeviceListener} from '../../utils/DeviceListener';
import fs from 'fs-extra'; import fs from 'fs-extra';
import os from 'os'; import os from 'os';
import path from 'path'; import path from 'path';
@@ -63,15 +64,21 @@ export function parsePath(content: string): string | null {
return path.trim(); return path.trim();
} }
export function addFileWatcherForiOSCrashLogs(device: ServerDevice) { export class iOSCrashWatcher extends DeviceListener {
const dir = path.join(os.homedir(), 'Library', 'Logs', 'DiagnosticReports'); constructor(private readonly device: ServerDevice) {
// eslint-disable-next-line node/no-sync super(() => device.connected);
if (!fs.pathExistsSync(dir)) {
console.warn('Failed to start iOS crash watcher');
return () => {};
} }
protected async startListener() {
const dir = path.join(os.homedir(), 'Library', 'Logs', 'DiagnosticReports');
if (!(await fs.pathExists(dir))) {
throw new Error('Failed to start iOS crash watcher: path does not exist');
}
const watcher = fs.watch(dir, async (_eventType, filename) => { const watcher = fs.watch(dir, async (_eventType, filename) => {
// We just parse the crash logs with extension `.crash` // We just parse the crash logs with extension `.crash`
// TODO: Make it work on MacOS 12. ASAP!
// MacOS 12 does not create .crash reports, but uses new .ips files instead with different format.
const checkFileExtension = /.crash$/.exec(filename); const checkFileExtension = /.crash$/.exec(filename);
if (!filename || !checkFileExtension) { if (!filename || !checkFileExtension) {
return; return;
@@ -81,19 +88,24 @@ export function addFileWatcherForiOSCrashLogs(device: ServerDevice) {
if (!exists) { if (!exists) {
return; return;
} }
fs.readFile(filepath, 'utf8', function (err, data) { fs.readFile(filepath, 'utf8', (err, data) => {
if (err) { if (err) {
console.warn('Failed to read crash file', err); console.warn('Failed to read crash file', err);
return; return;
} }
if (shouldShowiOSCrashNotification(device.info.serial, data)) { if (shouldShowiOSCrashNotification(this.device.serial, data)) {
device.flipperServer.emit('device-crash', { this.device.flipperServer.emit('device-crash', {
crash: parseIosCrash(data), crash: parseIosCrash(data),
serial: device.info.serial, serial: this.device.serial,
}); });
} }
}); });
}); });
watcher.on('error', (e) => {
console.error('iOS crash watcher error', e);
});
return () => watcher.close(); return () => watcher.close();
}
} }

View File

@@ -0,0 +1,186 @@
/**
* Copyright (c) Facebook, Inc. and its affiliates.
*
* This source code is licensed under the MIT license found in the
* LICENSE file in the root directory of this source tree.
*
* @format
*/
import {ChildProcessWithoutNullStreams} from 'child_process';
import {DeviceLogEntry, DeviceLogLevel, DeviceType} from 'flipper-common';
import {Transform} from 'stream';
import {DeviceListener} from '../../utils/DeviceListener';
import {ERR_PHYSICAL_DEVICE_LOGS_WITHOUT_IDB, IOSBridge} from './IOSBridge';
import JSONStream from 'JSONStream';
import split2 from 'split2';
// Used to strip the initial output of the logging utility where it prints out settings.
// We know the log stream is json so it starts with an open brace.
class StripLogPrefix extends Transform {
passedPrefix = false;
_transform(
data: any,
_encoding: string,
callback: (err?: Error, data?: any) => void,
) {
if (this.passedPrefix) {
this.push(data);
} else {
const dataString = data.toString();
const index = dataString.indexOf('[');
if (index >= 0) {
this.push(dataString.substring(index));
this.passedPrefix = true;
}
}
callback();
}
}
type IOSLogLevel = 'Default' | 'Info' | 'Debug' | 'Error' | 'Fault';
type RawLogEntry = {
eventMessage: string;
machTimestamp: number;
messageType: IOSLogLevel;
processID: number;
processImagePath: string;
processImageUUID: string;
processUniqueID: number;
senderImagePath: string;
senderImageUUID: string;
senderProgramCounter: number;
threadID: number;
timestamp: string;
timezoneName: string;
traceID: string;
};
// https://regex101.com/r/rrl03T/1
// Mar 25 17:06:38 iPhone symptomsd(SymptomEvaluator)[125] <Notice>: Stuff
const logRegex = /(^.{15}) ([^ ]+?) ([^\[]+?)\[(\d+?)\] <(\w+?)>: (.*)$/s;
export class iOSLogListener extends DeviceListener {
constructor(
isDeviceConnected: () => boolean,
private onNewLogEntry: (logEntry: DeviceLogEntry) => void,
private readonly iOSBridge: IOSBridge,
private readonly serial: string,
private readonly deviceType: DeviceType,
) {
super(isDeviceConnected);
}
protected async startListener() {
let log: ChildProcessWithoutNullStreams;
try {
log = this.iOSBridge.startLogListener(this.serial, this.deviceType);
} catch (e) {
if (e.message === ERR_PHYSICAL_DEVICE_LOGS_WITHOUT_IDB) {
console.warn(e);
return () => {};
} else {
throw e;
}
}
log.on('error', (err: Error) => {
console.error('iOS log tailer error', err);
this._state.set('fatal', err);
});
// TODO: Do we need it?
log.stderr.on('data', (data: Buffer) => {
console.warn('iOS log tailer stderr: ', data.toString());
});
if (this.deviceType === 'physical') {
log.stdout.pipe(split2('\0')).on('data', (line: string) => {
const parsed = iOSLogListener.parseLogLine(line);
if (parsed) {
this.onNewLogEntry(parsed);
} else {
console.warn('Failed to parse iOS log line: ', line);
}
});
} else {
log.stdout
.pipe(new StripLogPrefix())
.pipe(JSONStream.parse('*'))
.on('data', (data: RawLogEntry) => {
const entry = iOSLogListener.parseJsonLogEntry(data);
this.onNewLogEntry(entry);
});
}
return () => {
log.kill();
};
}
static parseJsonLogEntry(entry: RawLogEntry): DeviceLogEntry {
let type: DeviceLogLevel = iOSLogListener.getLogLevel(entry.messageType);
// when Apple log levels are not used, log messages can be prefixed with
// their loglevel.
if (entry.eventMessage.startsWith('[debug]')) {
type = 'debug';
} else if (entry.eventMessage.startsWith('[info]')) {
type = 'info';
} else if (entry.eventMessage.startsWith('[warn]')) {
type = 'warn';
} else if (entry.eventMessage.startsWith('[error]')) {
type = 'error';
}
// remove type from mesage
entry.eventMessage = entry.eventMessage.replace(
/^\[(debug|info|warn|error)\]/,
'',
);
const tag = entry.processImagePath.split('/').pop() || '';
return {
date: new Date(entry.timestamp),
pid: entry.processID,
tid: entry.threadID,
tag,
message: entry.eventMessage,
type,
};
}
static getLogLevel(level: string): DeviceLogLevel {
switch (level) {
case 'Default':
return 'debug';
case 'Info':
return 'info';
case 'Debug':
return 'debug';
case 'Error':
return 'error';
case 'Notice':
return 'verbose';
case 'Fault':
return 'fatal';
default:
return 'unknown';
}
}
static parseLogLine(line: string): DeviceLogEntry | undefined {
const matches = line.match(logRegex);
if (matches) {
return {
date: new Date(Date.parse(matches[1])),
tag: matches[3],
tid: 0,
pid: parseInt(matches[4], 10),
type: iOSLogListener.getLogLevel(matches[5]),
message: matches[6],
};
}
return undefined;
}
}

View File

@@ -0,0 +1,277 @@
/**
* Copyright (c) Facebook, Inc. and its affiliates.
*
* This source code is licensed under the MIT license found in the
* LICENSE file in the root directory of this source tree.
*
* @format
*/
import EventEmitter from 'events';
import {sleep} from 'flipper-common';
import {assertNotNull} from '../comms/Utilities';
export const RESTART_CNT = 3;
const RESTART_SLEEP = 100;
export type DeviceLogListenerState =
| 'starting'
| 'stopping'
| 'active'
| 'inactive'
| 'fatal'
| 'zombie';
class State {
private _currentState: DeviceLogListenerState = 'inactive';
private _error?: Error;
private valueEmitter = new EventEmitter();
get error() {
return this._error;
}
get currentState() {
return this._currentState;
}
set<T extends DeviceLogListenerState>(
...[newState, error]: T extends 'fatal' | 'zombie' ? [T, Error] : [T]
) {
this._currentState = newState;
this._error = error;
this.valueEmitter.emit(newState);
}
once(
state: DeviceLogListenerState | DeviceLogListenerState[],
cb: () => void,
): () => void {
return this.subscribe(state, cb, {once: true});
}
on(
state: DeviceLogListenerState | DeviceLogListenerState[],
cb: () => void,
): () => void {
return this.subscribe(state, cb);
}
is(targetState: DeviceLogListenerState | DeviceLogListenerState[]) {
if (!Array.isArray(targetState)) {
targetState = [targetState];
}
return targetState.includes(this._currentState);
}
private subscribe(
state: DeviceLogListenerState | DeviceLogListenerState[],
cb: () => void,
{once}: {once?: boolean} = {},
): () => void {
const statesNormalized = Array.isArray(state) ? state : [state];
if (statesNormalized.includes(this._currentState)) {
cb();
return () => {};
}
let executed = false;
const wrappedCb = () => {
if (!executed) {
executed = true;
cb();
}
};
const fn = once ? 'once' : 'on';
statesNormalized.forEach((item) => {
this.valueEmitter[fn](item, wrappedCb);
});
return () => {
statesNormalized.forEach((item) => {
this.valueEmitter.off(item, wrappedCb);
});
};
}
}
export abstract class DeviceListener {
private name: string = this.constructor.name;
protected _state = new State();
private stopLogListener?: () => Promise<void> | void;
private restartCnt = RESTART_CNT;
constructor(protected readonly isDeviceConnected: () => boolean) {
// Reset number of retries every time we manage to start the listener
this._state.on('active', () => {
this.restartCnt = RESTART_CNT;
});
this._state.on('fatal', () => {
if (this.restartCnt <= 0) {
return;
}
console.info(
`${this.name} -> fatal. Listener crashed. Trying to restart.`,
);
// Auto-restarting crashed listener
this.start().catch((e) => {
console.error(`${this.name} -> unexpected start error`, e);
});
});
}
async start(): Promise<void> {
if (this._state.is('active')) {
console.debug(`${this.name}.start -> already active`);
return;
}
if (this._state.is('starting')) {
console.debug(
`${this.name}.start -> already starting. Subscribed to 'active' and 'fatal' events`,
);
return new Promise<void>((resolve, reject) => {
this._state.once(['active', 'fatal'], async () => {
try {
await this.start();
resolve();
} catch (e) {
reject(e);
}
});
});
}
if (this._state.is('stopping')) {
console.debug(
`${this.name}.start -> currently stopping. Subscribed to 'inactive' and 'zombie' events`,
);
return new Promise<void>((resolve, reject) => {
this._state.once(['inactive', 'zombie'], async () => {
try {
await this.start();
resolve();
} catch (e) {
reject(e);
}
});
});
}
// State is either 'inactive' of 'zombie'. Trying to start the listener.
console.debug(`${this.name}.start -> starting`);
this.stopLogListener = undefined;
this._state.set('starting');
while (!this.stopLogListener) {
if (!this.isDeviceConnected()) {
this._state.set('inactive');
return;
}
try {
this.stopLogListener = await this.startListener();
break;
} catch (e) {
if (this.restartCnt <= 0) {
this._state.set('fatal', e);
console.error(
`${this.name}.start -> failure after ${RESTART_CNT} retries`,
e,
);
return;
}
console.warn(
`${this.name}.start -> error. Retrying. ${this.restartCnt} retries left.`,
e,
);
this.restartCnt--;
await sleep(RESTART_SLEEP);
}
}
this._state.set('active');
console.info(`${this.name}.start -> success`);
}
protected abstract startListener(): Promise<() => Promise<void> | void>;
async stop(): Promise<void> {
if (this._state.is(['inactive', 'fatal', 'zombie'])) {
console.debug(`${this.name}.stop -> already stopped or crashed`);
return;
}
if (this._state.is('stopping')) {
console.debug(
`${this.name}.stop -> currently stopping. Subscribed to 'inactive' and 'zombie' events`,
);
return new Promise<void>((resolve, reject) => {
this._state.once(['inactive', 'zombie'], async () => {
try {
await this.stop();
resolve();
} catch (e) {
reject(e);
}
});
});
}
if (this._state.is('starting')) {
console.debug(
`${this.name}.stop -> currently starting. Subscribed to 'active' and 'fatal' events`,
);
return new Promise<void>((resolve, reject) => {
this._state.once(['active', 'fatal'], async () => {
try {
await this.stop();
resolve();
} catch (e) {
reject(e);
}
});
});
}
// State is 'active'. Trying to stop the listener.
console.debug(`${this.name}.stop -> stopping`);
this._state.set('stopping');
try {
assertNotNull(this.stopLogListener);
await this.stopLogListener();
this._state.set('inactive');
console.info(`${this.name}.stop -> success`);
} catch (e) {
this._state.set('zombie', e);
console.error(`${this.name}.stop -> failure`, e);
}
}
once(
state: DeviceLogListenerState | DeviceLogListenerState[],
cb: () => void,
) {
return this._state.once(state, cb);
}
on(state: DeviceLogListenerState | DeviceLogListenerState[], cb: () => void) {
return this._state.on(state, cb);
}
get state() {
return this._state.currentState;
}
get error() {
return this._state.error;
}
}
export class NoopListener extends DeviceListener {
async startListener() {
return () => {};
}
}

View File

@@ -0,0 +1,94 @@
/**
* Copyright (c) Facebook, Inc. and its affiliates.
*
* This source code is licensed under the MIT license found in the
* LICENSE file in the root directory of this source tree.
*
* @format
*/
import {
DeviceListener,
DeviceLogListenerState,
RESTART_CNT,
} from '../DeviceListener';
class TestDeviceListener extends DeviceListener {
public connected = true;
constructor(private listenerImpl: () => Promise<() => void>) {
super(() => this.connected);
}
protected async startListener() {
const stop = await this.listenerImpl();
return stop;
}
setState<T extends DeviceLogListenerState>(
...args: T extends 'fatal' | 'zombie' ? [T, Error] : [T]
) {
this._state.set(...args);
}
}
describe('DeviceListener', () => {
let device!: TestDeviceListener;
let listenerFn!: jest.Mock;
let stopFn!: jest.Mock;
beforeEach(() => {
stopFn = jest.fn();
listenerFn = jest.fn().mockImplementation(() => stopFn);
device = new TestDeviceListener(listenerFn);
});
test('Starts a listener if device is in "inactive" state and stops it', async () => {
expect(device.state).toBe('inactive');
const onStart = jest.fn();
device.once('starting', onStart);
expect(listenerFn).toBeCalledTimes(0);
expect(onStart).toBeCalledTimes(0);
await device.start();
expect(listenerFn).toBeCalledTimes(1);
expect(device.state).toBe('active');
expect(device.error).toBe(undefined);
expect(onStart).toBeCalledTimes(1);
const onStop = jest.fn();
device.once('stopping', onStop);
expect(stopFn).toBeCalledTimes(0);
expect(onStop).toBeCalledTimes(0);
await device.stop();
expect(stopFn).toBeCalledTimes(1);
expect(device.state).toBe('inactive');
expect(device.error).toBe(undefined);
expect(onStop).toBeCalledTimes(1);
});
test('Fails to start a listener after RESTART_CNT retries', async () => {
expect(device.state).toBe('inactive');
const onStart = jest.fn();
device.once('starting', onStart);
expect(listenerFn).toBeCalledTimes(0);
expect(onStart).toBeCalledTimes(0);
const error = new Error('42');
listenerFn.mockImplementation(() => {
throw error;
});
await device.start();
expect(listenerFn).toBeCalledTimes(RESTART_CNT + 1);
expect(device.state).toBe('fatal');
expect(device.error).toBe(error);
expect(onStart).toBeCalledTimes(1);
});
});

View File

@@ -160,13 +160,11 @@ export default class BaseDevice implements Device {
} }
async startLogging() { async startLogging() {
await this.flipperServer.exec('device-start-logging', this.serial);
this.flipperServer.on('device-log', this.deviceLogEventHandler); this.flipperServer.on('device-log', this.deviceLogEventHandler);
} }
stopLogging() { stopLogging() {
this.flipperServer.off('device-log', this.deviceLogEventHandler); this.flipperServer.off('device-log', this.deviceLogEventHandler);
return this.flipperServer.exec('device-stop-logging', this.serial);
} }
addLogListener(callback: DeviceLogListener): Symbol { addLogListener(callback: DeviceLogListener): Symbol {
@@ -206,13 +204,11 @@ export default class BaseDevice implements Device {
} }
async startCrashWatcher() { async startCrashWatcher() {
await this.flipperServer.exec('device-start-crash-watcher', this.serial);
this.flipperServer.on('device-crash', this.crashLogEventHandler); this.flipperServer.on('device-crash', this.crashLogEventHandler);
} }
stopCrashWatcher() { stopCrashWatcher() {
this.flipperServer.off('device-crash', this.crashLogEventHandler); this.flipperServer.off('device-crash', this.crashLogEventHandler);
return this.flipperServer.exec('device-stop-crash-watcher', this.serial);
} }
addCrashListener(callback: CrashLogListener): Symbol { addCrashListener(callback: CrashLogListener): Symbol {

View File

@@ -113,6 +113,7 @@
"privileged": true, "privileged": true,
"productName": "Flipper", "productName": "Flipper",
"resolutions": { "resolutions": {
"adbkit-logcat": "^2.0.1"
}, },
"scripts": { "scripts": {
"build": "cross-env NODE_ENV=production ./ts-node scripts/build-release.ts $@", "build": "cross-env NODE_ENV=production ./ts-node scripts/build-release.ts $@",

View File

@@ -2990,12 +2990,7 @@ acorn@^8.2.4:
resolved "https://registry.yarnpkg.com/acorn/-/acorn-8.3.0.tgz#1193f9b96c4e8232f00b11a9edff81b2c8b98b88" resolved "https://registry.yarnpkg.com/acorn/-/acorn-8.3.0.tgz#1193f9b96c4e8232f00b11a9edff81b2c8b98b88"
integrity sha512-tqPKHZ5CaBJw0Xmy0ZZvLs1qTV+BNFSyvn77ASXkpBNfIRk8ev26fKrD9iLGwGA9zedPao52GSHzq8lyZG0NUw== integrity sha512-tqPKHZ5CaBJw0Xmy0ZZvLs1qTV+BNFSyvn77ASXkpBNfIRk8ev26fKrD9iLGwGA9zedPao52GSHzq8lyZG0NUw==
adbkit-logcat@^1.1.0: adbkit-logcat@^1.1.0, adbkit-logcat@^2.0.1:
version "1.1.0"
resolved "https://registry.yarnpkg.com/adbkit-logcat/-/adbkit-logcat-1.1.0.tgz#01d7f9b0cef9093a30bcb3b007efff301508962f"
integrity sha1-Adf5sM75CTowvLOwB+//MBUIli8=
adbkit-logcat@^2.0.1:
version "2.0.1" version "2.0.1"
resolved "https://registry.yarnpkg.com/adbkit-logcat/-/adbkit-logcat-2.0.1.tgz#d4986b9fc7cfda42733389d46a52124abef43ca5" resolved "https://registry.yarnpkg.com/adbkit-logcat/-/adbkit-logcat-2.0.1.tgz#d4986b9fc7cfda42733389d46a52124abef43ca5"
integrity sha512-MznVzzEzcrWhIaIyblll+a0AL1TICJe/yuaia7HDYTAtiNabR/9amJkAnLt30U8/W7MVBc3mvU1jB/6MJ/TYHw== integrity sha512-MznVzzEzcrWhIaIyblll+a0AL1TICJe/yuaia7HDYTAtiNabR/9amJkAnLt30U8/W7MVBc3mvU1jB/6MJ/TYHw==