feat(logs): improve android logging (#5755)

Co-authored-by: Igor Randjelovic <[email protected]>

Author: ammarahm-ed

lib/common/definitions/mobile.d.ts

@@ -179,7 +179,10 @@ declare global {
 		interface ILogcatStartOptions {
 			deviceIdentifier: string;
 			pid?: string;
+			appId?: string;
 			keepSingleProcess?: boolean;
+
+			onAppRestarted?: () => void;
 		}
 
 		interface ILogcatHelper {
@@ -223,6 +226,13 @@ declare global {
 			 */
 			setApplicationPidForDevice(deviceIdentifier: string, pid: string): void;
 
+			/**
+			 * Sets the application id of the application on the specified device.
+			 * @param {string} deviceIdentifier The unique identifier of the device.
+			 * @param {string} appId The Process ID of the currently running application for which we need the logs.
+			 */
+			setApplicationIdForDevice(deviceIdentifier: string, appId: string): void;
+
 			/**
 			 * Sets the project name of the application on the specified device.
 			 * @param {string} deviceIdentifier The unique identifier of the device.
@@ -264,6 +274,10 @@ declare global {
 			 * The project name.
 			 */
 			projectName?: string;
+			/**
+			 *	The application id of the current app.
+			 */
+			applicationId?: string;
 		}
 
 		/**

lib/common/mobile/android/android-application-manager.ts

@@ -155,6 +155,11 @@ export class AndroidApplicationManager extends ApplicationManagerBase {
 				"1",
 			]);
 		}
+		await this.onAppLaunch(appData);
+	}
+
+	private async onAppLaunch(appData: Mobile.IStartApplicationData) {
+		const appIdentifier = appData.appId;
 
 		if (!this.$options.justlaunch && !appData.justLaunch) {
 			const deviceIdentifier = this.identifier;
@@ -167,13 +172,26 @@ export class AndroidApplicationManager extends ApplicationManagerBase {
 					deviceIdentifier,
 					processIdentifier
 				);
+
+				this.$deviceLogProvider.setApplicationIdForDevice(
+					deviceIdentifier,
+					appIdentifier
+				);
+
 				this.$deviceLogProvider.setProjectDirForDevice(
 					deviceIdentifier,
 					appData.projectDir
 				);
+
 				await this.$logcatHelper.start({
 					deviceIdentifier: this.identifier,
 					pid: processIdentifier,
+					appId: appIdentifier,
+					onAppRestarted: () => {
+						// If the app restarts, we update the PID and
+						// restart log helper.
+						this.onAppLaunch(appData);
+					},
 				});
 			} else {
 				await this.$logcatHelper.dump(this.identifier);
@@ -228,11 +246,12 @@ export class AndroidApplicationManager extends ApplicationManagerBase {
 	public async getDebuggableAppViews(
 		appIdentifiers: string[]
 	): Promise<IDictionary<Mobile.IDebugWebViewInfo[]>> {
-		const mappedAppIdentifierPorts = await this.$androidProcessService.getMappedAbstractToTcpPorts(
-				this.identifier,
-				appIdentifiers,
-				TARGET_FRAMEWORK_IDENTIFIERS.Cordova
-			),
+		const mappedAppIdentifierPorts =
+				await this.$androidProcessService.getMappedAbstractToTcpPorts(
+					this.identifier,
+					appIdentifiers,
+					TARGET_FRAMEWORK_IDENTIFIERS.Cordova
+				),
 			applicationViews: IDictionary<Mobile.IDebugWebViewInfo[]> = {};
 
 		await Promise.all(

lib/common/mobile/android/android-debug-bridge.ts

@@ -55,7 +55,6 @@ export class AndroidDebugBridge implements Mobile.IAndroidDebugBridge {
 			childProcessOptions,
 			{ throwError: false }
 		);
-
 		const errors = this.$androidDebugBridgeResultHandler.checkForErrors(result);
 
 		if (errors && errors.length > 0) {

lib/common/mobile/android/android-log-filter.ts

@@ -7,7 +7,8 @@ export class AndroidLogFilter implements Mobile.IPlatformLogFilter {
 
 	// sample line is "11-23 12:39:07.310  1584  1597 I art     : Background sticky concurrent mark sweep GC freed 21966(1780KB) AllocSpace objects, 4(80KB) LOS objects, 77% free, 840KB/3MB, paused 4.018ms total 158.629ms"
 	// or '12-28 10:45:08.020  3329  3329 W chromium: [WARNING:data_reduction_proxy_settings.cc(328)] SPDY proxy OFF at startup'
-	private static API_LEVEL_23_LINE_REGEX = /.+?\s+?(?:[A-Z]\s+?)([A-Za-z \.]+?)\s*?\: (.*)/;
+	private static API_LEVEL_23_LINE_REGEX =
+		/.+?\s+?(?:[A-Z]\s+?)([A-Za-z \.]+?)\s*?\: (.*)/;
 
 	constructor(private $loggingLevels: Mobile.ILoggingLevels) {}
 
@@ -23,7 +24,9 @@ export class AndroidLogFilter implements Mobile.IPlatformLogFilter {
 			);
 			if (log) {
 				if (log.tag) {
-					return `${log.tag}: ${log.message}` + EOL;
+					return (
+						`${log.tag === "JS" ? "" : `${log.tag}: `}${log.message}` + EOL
+					);
 				} else {
 					return log.message + EOL;
 				}
@@ -35,33 +38,19 @@ export class AndroidLogFilter implements Mobile.IPlatformLogFilter {
 		return data + EOL;
 	}
 
-	private getConsoleLogFromLine(lineText: string, pid: string): any {
-		// filter log line if it does not belong to the current application process id
-		if (pid && lineText.indexOf(pid) < 0) {
+	getConsoleLogFromLine(lineText: string, pid: string) {
+		if (pid && lineText.indexOf(pid) === -1) {
 			return null;
 		}
 
-		// Messages with category TNS.Native and TNS.Java will be printed by runtime to Logcat only when `__enableVerboseLogging()` is called in the application.
-		const acceptedTags = [
-			"chromium",
-			"Web Console",
-			"JS",
-			"ActivityManager",
-			"System.err",
-			"TNS.Native",
-			"TNS.Java",
-		];
-
-		let consoleLogMessage: { tag?: string; message: string };
-
+		let consoleLogMessage;
 		const match =
-			lineText.match(AndroidLogFilter.LINE_REGEX) ||
-			lineText.match(AndroidLogFilter.API_LEVEL_23_LINE_REGEX);
+			lineText.match(AndroidLogFilter.API_LEVEL_23_LINE_REGEX) ||
+			lineText.match(AndroidLogFilter.LINE_REGEX);
 
-		if (match && acceptedTags.indexOf(match[1].trim()) !== -1) {
+		if (match) {
 			consoleLogMessage = { tag: match[1].trim(), message: match[2] };
 		}
-
 		return consoleLogMessage;
 	}
 }

lib/common/mobile/android/logcat-helper.ts

@@ -8,7 +8,9 @@ import { DeviceAndroidDebugBridge } from "./device-android-debug-bridge";
 
 interface IDeviceLoggingData {
 	loggingProcess: ChildProcess;
+	appStartTrackingProcess: ChildProcess;
 	lineStream: any;
+	rawLineStream: any;
 	keepSingleProcess: boolean;
 }
 
@@ -32,16 +34,18 @@ export class LogcatHelper implements Mobile.ILogcatHelper {
 				loggingProcess: null,
 				lineStream: null,
 				keepSingleProcess: options.keepSingleProcess,
+				appStartTrackingProcess: null,
+				rawLineStream: null,
 			};
 
 			const logcatStream = await this.getLogcatStream(
 				deviceIdentifier,
 				options.pid
 			);
+
 			const lineStream = byline(logcatStream.stdout);
-			this.mapDevicesLoggingData[
-				deviceIdentifier
-			].loggingProcess = logcatStream;
+			this.mapDevicesLoggingData[deviceIdentifier].loggingProcess =
+				logcatStream;
 			this.mapDevicesLoggingData[deviceIdentifier].lineStream = lineStream;
 			logcatStream.stderr.on("data", (data: Buffer) => {
 				this.$logger.trace("ADB logcat stderr: " + data.toString());
@@ -71,6 +75,41 @@ export class LogcatHelper implements Mobile.ILogcatHelper {
 					);
 				}
 			});
+
+			const appStartTrackingStream = await this.getAppStartTrackingLogcatStream(
+				deviceIdentifier,
+				options.appId
+			);
+
+			this.mapDevicesLoggingData[deviceIdentifier].appStartTrackingProcess =
+				appStartTrackingStream;
+
+			const rawLineStream = byline(appStartTrackingStream.stdout);
+			this.mapDevicesLoggingData[deviceIdentifier].rawLineStream =
+				rawLineStream;
+
+			rawLineStream.on("data", (lineBuffer: Buffer) => {
+				if (!this.mapDevicesLoggingData[deviceIdentifier]?.loggingProcess)
+					return;
+				const lines = (lineBuffer.toString() || "").split("\n");
+				for (let line of lines) {
+					// 09-11 17:50:26.311   598  1979 I ActivityTaskManager: START u0 {flg=0x10000000 cmp=org.nativescript.myApp/com.tns.NativeScriptActivity} from uid 2000
+					//                                                       ^^^^^                          ^^^^^^^^^^^^^^^^^^^^^^                                        ^^^^
+					// 																										   action                         appId                                                         pid
+
+					if (
+						// action
+						line.includes("START") &&
+						// appId
+						line.includes(options.appId) &&
+						// pid - only if it's not the current pid...
+						!line.includes(options.pid)
+					) {
+						this.forceStop(deviceIdentifier);
+						options.onAppRestarted?.();
+					}
+				}
+			});
 		}
 	}
 
@@ -108,39 +147,92 @@ export class LogcatHelper implements Mobile.ILogcatHelper {
 	}
 
 	private forceStop(deviceIdentifier: string): void {
-		this.mapDevicesLoggingData[
-			deviceIdentifier
-		].loggingProcess.removeAllListeners();
-		this.mapDevicesLoggingData[deviceIdentifier].loggingProcess.kill("SIGINT");
-		this.mapDevicesLoggingData[
-			deviceIdentifier
-		].lineStream.removeAllListeners();
+		const loggingData = this.mapDevicesLoggingData[deviceIdentifier];
+		loggingData.loggingProcess?.removeAllListeners();
+		loggingData.loggingProcess?.kill("SIGINT");
+		loggingData.lineStream?.removeAllListeners();
+
+		loggingData.appStartTrackingProcess?.kill("SIGINT");
+		loggingData.lineStream?.removeAllListeners();
+
 		delete this.mapDevicesLoggingData[deviceIdentifier];
 	}
 
-	private async getLogcatStream(deviceIdentifier: string, pid?: string) {
+	/**
+	 * @deprecated - we likely don't need this anymore, and can simplify the code...
+	 */
+	private async isLogcatPidSupported(deviceIdentifier: string) {
 		const device = await this.$devicesService.getDevice(deviceIdentifier);
 		const minAndroidWithLogcatPidSupport = "7.0.0";
-		const isLogcatPidSupported =
+		return (
 			!!device.deviceInfo.version &&
 			semver.gte(
 				semver.coerce(device.deviceInfo.version),
 				minAndroidWithLogcatPidSupport
-			);
+			)
+		);
+	}
+
+	private async getLogcatStream(deviceIdentifier: string, pid?: string) {
+		const isLogcatPidSupported = await this.isLogcatPidSupported(
+			deviceIdentifier
+		);
 		const adb: Mobile.IDeviceAndroidDebugBridge = this.$injector.resolve(
 			DeviceAndroidDebugBridge,
 			{ identifier: deviceIdentifier }
 		);
-		const logcatCommand = ["logcat"];
+
+		// -T 1 - shows only new logs after starting adb logcat
+		const logcatCommand = ["logcat", "-T", "1"];
+
+		const acceptedTags = [
+			"chromium",
+			'"Web Console"',
+			"JS",
+			"System.err",
+			"TNS.Native",
+			"TNS.Java",
+		];
 
 		if (pid && isLogcatPidSupported) {
 			logcatCommand.push(`--pid=${pid}`);
+
+			acceptedTags.forEach((tag) => {
+				// -s <tag> - shows only logs with the specified tag
+				logcatCommand.push("-s", tag);
+			});
 		}
+
 		const logcatStream = await adb.executeCommand(logcatCommand, {
 			returnChildProcess: true,
 		});
+
 		return logcatStream;
 	}
+
+	private async getAppStartTrackingLogcatStream(
+		deviceIdentifier: string,
+		appId?: string
+	) {
+		const adb: Mobile.IDeviceAndroidDebugBridge = this.$injector.resolve(
+			DeviceAndroidDebugBridge,
+			{ identifier: deviceIdentifier }
+		);
+
+		// -b system  - shows the system buffer/logs only
+		// -T 1 			- shows only new logs after starting adb logcat
+		const logcatCommand = [`logcat`, `-b`, `system`, `-T`, `1`];
+
+		if (appId) {
+			logcatCommand.push(`--regex=START.*${appId}`);
+		}
+
+		const appStartTrackingStream = await adb.executeCommand(logcatCommand, {
+			returnChildProcess: true,
+		});
+
+		return appStartTrackingStream;
+	}
 }
 
 injector.register("logcatHelper", LogcatHelper);

lib/common/mobile/device-log-provider-base.ts

@@ -4,7 +4,8 @@ import { IDictionary } from "../declarations";
 
 export abstract class DeviceLogProviderBase
 	extends EventEmitter
-	implements Mobile.IDeviceLogProvider {
+	implements Mobile.IDeviceLogProvider
+{
 	protected devicesLogOptions: IDictionary<Mobile.IDeviceLogOptions> = {};
 
 	constructor(
@@ -50,6 +51,15 @@ export abstract class DeviceLogProviderBase
 		);
 	}
 
+	public setApplicationIdForDevice(deviceIdentifier: string, appId: string) {
+		this.setDeviceLogOptionsProperty(
+			deviceIdentifier,
+			(deviceLogOptions: Mobile.IDeviceLogOptions) =>
+				deviceLogOptions.applicationId,
+			appId
+		);
+	}
+
 	public setProjectNameForDevice(
 		deviceIdentifier: string,
 		projectName: string
@@ -89,6 +99,13 @@ export abstract class DeviceLogProviderBase
 		);
 	}
 
+	getApplicationIdForDevice(deviceIdentifier: string) {
+		return (
+			this.devicesLogOptions[deviceIdentifier] &&
+			this.devicesLogOptions[deviceIdentifier].applicationId
+		);
+	}
+
 	protected getDeviceLogOptionsForDevice(
 		deviceIdentifier: string
 	): Mobile.IDeviceLogOptions {

lib/common/mobile/device-log-provider.ts

@@ -86,9 +86,6 @@ export class DeviceLogProvider extends DeviceLogProviderBase {
 	}
 
 	private logDataCore(data: string, deviceIdentifier: string): void {
-		// strip android JS: prefix
-		data = data.replace(/^JS:\s/, "");
-
 		// todo: use config to set logger - --env.classicLogs is temporary!
 		if ("classicLogs" in (this.$options.env ?? {})) {
 			// legacy logging