Skip to content

feat(logs): improve android logging #5755

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.

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

Merged
merged 2 commits into from
Sep 11, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
14 changes: 14 additions & 0 deletions lib/common/definitions/mobile.d.ts
Original file line number Diff line number Diff line change
Expand Up @@ -179,7 +179,10 @@ declare global {
interface ILogcatStartOptions {
deviceIdentifier: string;
pid?: string;
appId?: string;
keepSingleProcess?: boolean;

onAppRestarted?: () => void;
}

interface ILogcatHelper {
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -264,6 +274,10 @@ declare global {
* The project name.
*/
projectName?: string;
/**
* The application id of the current app.
*/
applicationId?: string;
}

/**
Expand Down
29 changes: 24 additions & 5 deletions lib/common/mobile/android/android-application-manager.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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);
Expand Down Expand Up @@ -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(
Expand Down
1 change: 0 additions & 1 deletion lib/common/mobile/android/android-debug-bridge.ts
Original file line number Diff line number Diff line change
Expand Up @@ -55,7 +55,6 @@ export class AndroidDebugBridge implements Mobile.IAndroidDebugBridge {
childProcessOptions,
{ throwError: false }
);

const errors = this.$androidDebugBridgeResultHandler.checkForErrors(result);

if (errors && errors.length > 0) {
Expand Down
33 changes: 11 additions & 22 deletions lib/common/mobile/android/android-log-filter.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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) {}

Expand All @@ -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;
}
Expand All @@ -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);
Comment on lines +48 to +49
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note: I flipped this condition to speed up matching by optimizing for API23 first and then falling back to legacy regex.


if (match && acceptedTags.indexOf(match[1].trim()) !== -1) {
if (match) {
consoleLogMessage = { tag: match[1].trim(), message: match[2] };
}

return consoleLogMessage;
}
}
Expand Down
120 changes: 106 additions & 14 deletions lib/common/mobile/android/logcat-helper.ts
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,9 @@ import { DeviceAndroidDebugBridge } from "./device-android-debug-bridge";

interface IDeviceLoggingData {
loggingProcess: ChildProcess;
appStartTrackingProcess: ChildProcess;
lineStream: any;
rawLineStream: any;
keepSingleProcess: boolean;
}

Expand All @@ -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());
Expand Down Expand Up @@ -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?.();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note: not break;-ing here, since it's possible (though unlikely) that two subsequent START lines come in the same lineBuffer. Though this doesn't really matter - this stream is not noisy at all because we're pre-filtering with the adb logcat regex.

}
}
});
}
}

Expand Down Expand Up @@ -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);
});
Comment on lines +188 to +203
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@ammarahm-ed this is a great idea to move here - technically if isLogcatPidSupported is false - we'd log out all tags even if not accepted - since the filtering has been removed from android-log-filter, however I don't think this would ever be a problem.

I've extracted the isLogcatPidSupported to a function since it's used by both methods here - and I marked is @deprecated because I don't think we need to worry about that soon anymore (if I understood correctly, that's for API24 or below - android 7.0)...

}

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`];
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Note: Added the -b system flag. Probably not a huge difference, but only showing the system buffer should theoretically be faster than showing the default (system, crash, main).


if (appId) {
logcatCommand.push(`--regex=START.*${appId}`);
}

const appStartTrackingStream = await adb.executeCommand(logcatCommand, {
returnChildProcess: true,
});

return appStartTrackingStream;
}
}

injector.register("logcatHelper", LogcatHelper);
19 changes: 18 additions & 1 deletion lib/common/mobile/device-log-provider-base.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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(
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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 {
Expand Down
3 changes: 0 additions & 3 deletions lib/common/mobile/device-log-provider.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
Loading