fix: device logs are parsed slowly

Currently it takes around half a second to parse each console message from the application. For callstacks, which contain a lot of lines, which we try to map to original file, it takes several seconds.
Also, at the moment, when the application reports that some log is from bundle.js/vendor.js, we parse the local files, which may not be the same files uploaded on the device. This may happen in cases where we have applied a hot module, the local bundle.js is changed and its source map is changed, but we have not uploaded it on the device yet.

The reason for the slowness is that we read the whole original file every time when we see lines from the logs that points to it. We also create a new SourceMapConsumer for it. This means, that if the stacktrace contains 10 lines pointing to vendor.js, we'll read it 10 times.

To handle both issues, set the sourceMapConsumer (and read the original file location) at the point when we upload files on the device. This way we'll always have in memory the same file as the one currently running on device and the source map will be correct. Also, this way the files will be parsed only once.

Author: rosen-vladimirov

lib/common/definitions/mobile.d.ts

@@ -164,6 +164,14 @@ declare module Mobile {
 	 * Describes methods for providing device logs to a specific consumer.
 	 */
 	interface IDeviceLogProvider extends NodeJS.EventEmitter {
+		/**
+		 * Sets the path to source file from which the logs are produced,
+		 * i.e. the original file location of the file running on device.
+		 * @param {string} pathToSourceFile Path to the source file.
+		 * @returns {Promise<void>}
+		 */
+		setSourceFileLocation(pathToSourceFile: string): Promise<void>;
+
 		/**
 		 * Logs data in the specific way for the consumer.
 		 * @param {string} line String from the device logs.
@@ -258,6 +266,12 @@ declare module Mobile {
 	 * Replaces file paths in device log with their original location
 	 */
 	interface ILogSourceMapService {
+		/**
+		 * Sets the sourceMapConsumer instance for specified file.
+		 * @param {string} filePath Full path to a local file containing both content and inline source map.
+		 * @return {Promise<void>}
+		 */
+		setSourceMapConsumerForFile(filePath: string): Promise<void>;
 		replaceWithOriginalFileLocations(platform: string, messageData: string, loggingOptions: Mobile.IDeviceLogOptions): string
 	}
 
@@ -307,6 +321,12 @@ declare module Mobile {
 		tryStartApplication(appData: IApplicationData): Promise<void>;
 		getDebuggableApps(): Promise<Mobile.IDeviceApplicationInformation[]>;
 		getDebuggableAppViews(appIdentifiers: string[]): Promise<IDictionary<Mobile.IDebugWebViewInfo[]>>;
+		/**
+		 * Sets the files transferred on device.
+		 * @param {string[]} files Local paths to files transferred on device.
+		 * @returns {Promise<void>}
+		 */
+		setTransferredAppFiles(files: string[]): Promise<void>;
 	}
 
 	/**

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

@@ -14,11 +14,11 @@ export class AndroidApplicationManager extends ApplicationManagerBase {
 		private $logcatHelper: Mobile.ILogcatHelper,
 		private $androidProcessService: Mobile.IAndroidProcessService,
 		private $httpClient: Server.IHttpClient,
-		private $deviceLogProvider: Mobile.IDeviceLogProvider,
+		protected $deviceLogProvider: Mobile.IDeviceLogProvider,
 		private $errors: IErrors,
 		$logger: ILogger,
 		$hooksService: IHooksService) {
-		super($logger, $hooksService);
+		super($logger, $hooksService, $deviceLogProvider);
 	}
 
 	public async getInstalledApplications(): Promise<string[]> {

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

@@ -7,10 +7,17 @@ export abstract class ApplicationManagerBase extends EventEmitter implements Mob
 	private lastAvailableDebuggableAppViews: IDictionary<Mobile.IDebugWebViewInfo[]> = {};
 
 	constructor(protected $logger: ILogger,
-		protected $hooksService: IHooksService) {
+		protected $hooksService: IHooksService,
+		protected $deviceLogProvider: Mobile.IDeviceLogProvider) {
 		super();
 	}
 
+	public async setTransferredAppFiles(files: string[]): Promise<void> {
+		for (const file of files) {
+			await this.$deviceLogProvider.setSourceFileLocation(file);
+		}
+	}
+
 	public async reinstallApplication(appIdentifier: string, packageFilePath: string): Promise<void> {
 		const isApplicationInstalled = await this.isApplicationInstalled(appIdentifier);
 

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

@@ -5,8 +5,8 @@ export class DeviceLogEmitter extends DeviceLogProviderBase {
 	constructor(protected $logFilter: Mobile.ILogFilter,
 		$logger: ILogger,
 		private $loggingLevels: Mobile.ILoggingLevels,
-		private $logSourceMapService: Mobile.ILogSourceMapService) {
-		super($logFilter, $logger);
+		protected $logSourceMapService: Mobile.ILogSourceMapService) {
+		super($logFilter, $logger, $logSourceMapService);
 	}
 
 	public logData(line: string, platform: string, deviceIdentifier: string): void {

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

@@ -5,10 +5,19 @@ export abstract class DeviceLogProviderBase extends EventEmitter implements Mobi
 	protected devicesLogOptions: IDictionary<Mobile.IDeviceLogOptions> = {};
 
 	constructor(protected $logFilter: Mobile.ILogFilter,
-		protected $logger: ILogger) {
+		protected $logger: ILogger,
+		protected $logSourceMapService: Mobile.ILogSourceMapService) {
 		super();
 	}
 
+	public async setSourceFileLocation(pathToOriginalFile: string): Promise<void> {
+		try {
+			await this.$logSourceMapService.setSourceMapConsumerForFile(pathToOriginalFile);
+		} catch (err) {
+			this.$logger.trace("Error while trying to set source map file", err);
+		}
+	}
+
 	public abstract logData(lineText: string, platform: string, deviceIdentifier: string): void;
 
 	public abstract setLogLevel(logLevel: string, deviceIdentifier?: string): void;

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

@@ -5,8 +5,8 @@ import { LoggerConfigData } from "../../constants";
 export class DeviceLogProvider extends DeviceLogProviderBase {
 	constructor(protected $logFilter: Mobile.ILogFilter,
 		protected $logger: ILogger,
-		private $logSourceMapService: Mobile.ILogSourceMapService) {
-		super($logFilter, $logger);
+		protected $logSourceMapService: Mobile.ILogSourceMapService) {
+		super($logFilter, $logger, $logSourceMapService);
 	}
 
 	public logData(lineText: string, platform: string, deviceIdentifier: string): void {

lib/common/mobile/ios/device/ios-application-manager.ts

@@ -13,8 +13,8 @@ export class IOSApplicationManager extends ApplicationManagerBase {
 		private $iOSNotificationService: IiOSNotificationService,
 		private $iosDeviceOperations: IIOSDeviceOperations,
 		private $options: IOptions,
-		private $deviceLogProvider: Mobile.IDeviceLogProvider) {
-		super($logger, $hooksService);
+		protected $deviceLogProvider: Mobile.IDeviceLogProvider) {
+		super($logger, $hooksService, $deviceLogProvider);
 	}
 
 	public async getInstalledApplications(): Promise<string[]> {

lib/common/mobile/ios/simulator/ios-simulator-application-manager.ts

@@ -15,10 +15,10 @@ export class IOSSimulatorApplicationManager extends ApplicationManagerBase {
 		private device: Mobile.IiOSDevice,
 		private $options: IOptions,
 		private $fs: IFileSystem,
-		private $deviceLogProvider: Mobile.IDeviceLogProvider,
+		protected $deviceLogProvider: Mobile.IDeviceLogProvider,
 		$logger: ILogger,
 		$hooksService: IHooksService) {
-		super($logger, $hooksService);
+		super($logger, $hooksService, $deviceLogProvider);
 	}
 
 	public async getInstalledApplications(): Promise<string[]> {

lib/common/test/unit-tests/mobile/application-manager-base.ts

@@ -1,15 +1,15 @@
 import { Yok } from "../../../yok";
 import { assert } from "chai";
-import { CommonLoggerStub, HooksServiceStub } from "../stubs";
+import { CommonLoggerStub, HooksServiceStub, DeviceLogProviderStub } from "../stubs";
 import { ApplicationManagerBase } from "../../../mobile/application-manager-base";
 
 let currentlyAvailableAppsForDebugging: Mobile.IDeviceApplicationInformation[];
 let currentlyInstalledApps: string[];
 let currentlyAvailableAppWebViewsForDebugging: IDictionary<Mobile.IDebugWebViewInfo[]>;
 
 class ApplicationManager extends ApplicationManagerBase {
-	constructor($logger: ILogger, $hooksService: IHooksService) {
-		super($logger, $hooksService);
+	constructor($logger: ILogger, $hooksService: IHooksService, $deviceLogProvider: Mobile.IDeviceLogProvider) {
+		super($logger, $hooksService, $deviceLogProvider);
 	}
 
 	public async installApplication(packageFilePath: string): Promise<void> {
@@ -46,6 +46,7 @@ function createTestInjector(): IInjector {
 	testInjector.register("logger", CommonLoggerStub);
 	testInjector.register("hooksService", HooksServiceStub);
 	testInjector.register("applicationManager", ApplicationManager);
+	testInjector.register("deviceLogProvider", DeviceLogProviderStub);
 	return testInjector;
 }
 

lib/common/test/unit-tests/stubs.ts

@@ -164,6 +164,9 @@ export class DeviceLogProviderStub extends EventEmitter implements Mobile.IDevic
 	public currentDeviceProjectNames: IStringDictionary = {};
 	public currentDeviceProjectDirs: IStringDictionary = {};
 
+	async setSourceFileLocation(pathToSourceFile: string): Promise<void> {
+	}
+
 	logData(line: string, platform: string, deviceIdentifier: string): void {
 		this.logger.info(line, platform, deviceIdentifier, { [LoggerConfigData.skipNewLine]: true });
 	}

lib/services/livesync/platform-livesync-service-base.ts

@@ -128,12 +128,14 @@ export abstract class PlatformLiveSyncServiceBase {
 		};
 	}
 
-	protected async transferFiles(deviceAppData: Mobile.IDeviceAppData, localToDevicePaths: Mobile.ILocalToDevicePathData[], projectFilesPath: string, projectData: IProjectData, liveSyncDeviceData: ILiveSyncDeviceDescriptor, options: ITransferFilesOptions): Promise<Mobile.ILocalToDevicePathData[]> {
+	private async transferFiles(deviceAppData: Mobile.IDeviceAppData, localToDevicePaths: Mobile.ILocalToDevicePathData[], projectFilesPath: string, projectData: IProjectData, liveSyncDeviceData: ILiveSyncDeviceDescriptor, options: ITransferFilesOptions): Promise<Mobile.ILocalToDevicePathData[]> {
 		let transferredFiles: Mobile.ILocalToDevicePathData[] = [];
 		const deviceLiveSyncService = this.getDeviceLiveSyncService(deviceAppData.device, projectData);
 
 		transferredFiles = await deviceLiveSyncService.transferFiles(deviceAppData, localToDevicePaths, projectFilesPath, projectData, liveSyncDeviceData, options);
 
+		await deviceAppData.device.applicationManager.setTransferredAppFiles(localToDevicePaths.map(l => l.getLocalPath()));
+
 		this.logFilesSyncInformation(transferredFiles, "Successfully transferred %s on device %s.", this.$logger.info, deviceAppData.device.deviceInfo.identifier);
 
 		return transferredFiles;

lib/services/log-source-map-service.ts

@@ -22,12 +22,34 @@ interface IFileLocation {
 export class LogSourceMapService implements Mobile.ILogSourceMapService {
 	private static FILE_PREFIX = "file:///";
 	private getProjectData: Function;
+	private cache: IDictionary<sourcemap.SourceMapConsumer> = {};
+
 	constructor(
 		private $fs: IFileSystem,
 		private $projectDataService: IProjectDataService,
 		private $injector: IInjector,
-		private $devicePlatformsConstants: Mobile.IDevicePlatformsConstants) {
-			this.getProjectData = _.memoize(this.$projectDataService.getProjectData.bind(this.$projectDataService));
+		private $devicePlatformsConstants: Mobile.IDevicePlatformsConstants,
+		private $logger: ILogger) {
+		this.getProjectData = _.memoize(this.$projectDataService.getProjectData.bind(this.$projectDataService));
+	}
+
+	public async setSourceMapConsumerForFile(filePath: string): Promise<void> {
+		try {
+			if (!this.$fs.getFsStats(filePath).isDirectory()) {
+				const source = this.$fs.readText(filePath);
+				const sourceMapRaw = sourceMapConverter.fromSource(source);
+				let smc: sourcemap.SourceMapConsumer = null;
+				if (sourceMapRaw && sourceMapRaw.sourcemap) {
+					const sourceMap = sourceMapRaw.sourcemap;
+					smc = new sourcemap.SourceMapConsumer(sourceMap);
+				}
+
+				this.cache[filePath] = smc;
+			}
+		} catch (err) {
+			this.$logger.trace(`Unable to set sourceMapConsumer for file ${filePath}. Error is: ${err}`);
+		}
+
 	}
 
 	public replaceWithOriginalFileLocations(platform: string, messageData: string, loggingOptions: Mobile.IDeviceLogOptions): string {
@@ -46,7 +68,7 @@ export class LogSourceMapService implements Mobile.ILogSourceMapService {
 			const originalLocation = this.getOriginalFileLocation(platform, parsedLine, projectData);
 
 			if (originalLocation && originalLocation.sourceFile) {
-				const {sourceFile, line, column} = originalLocation;
+				const { sourceFile, line, column } = originalLocation;
 				outputData = `${outputData}${parsedLine.messagePrefix}${LogSourceMapService.FILE_PREFIX}${sourceFile}:${line}:${column}${parsedLine.messageSuffix}\n`;
 			} else if (rawLine !== "") {
 				outputData = `${outputData}${rawLine}\n`;
@@ -57,25 +79,21 @@ export class LogSourceMapService implements Mobile.ILogSourceMapService {
 	}
 
 	private getOriginalFileLocation(platform: string, parsedLine: IParsedMessage, projectData: IProjectData): IFileLocation {
-		const fileLoaction = path.join(this.getFilesLocation(platform, projectData), APP_FOLDER_NAME);
+		const fileLocation = path.join(this.getFilesLocation(platform, projectData), APP_FOLDER_NAME);
 
 		if (parsedLine && parsedLine.filePath) {
-			const sourceMapFile = path.join(fileLoaction, parsedLine.filePath);
-			if (this.$fs.exists(sourceMapFile)) {
-				const source = this.$fs.readText(sourceMapFile);
-				const sourceMapRaw = sourceMapConverter.fromSource(source);
-				if (sourceMapRaw && sourceMapRaw.sourcemap) {
-					const sourceMap = sourceMapRaw.sourcemap;
-					const smc = new sourcemap.SourceMapConsumer(sourceMap);
-					const originalPosition = smc.originalPositionFor({ line: parsedLine.line, column: parsedLine.column });
-					let sourceFile = originalPosition.source && originalPosition.source.replace("webpack:///", "");
-					if (sourceFile) {
-						if (!_.startsWith(sourceFile, NODE_MODULES_FOLDER_NAME)) {
-							sourceFile = path.join(projectData.getAppDirectoryRelativePath(), sourceFile);
-						}
-						sourceFile = stringReplaceAll(sourceFile, "/", path.sep);
-						return { sourceFile, line: originalPosition.line, column: originalPosition.column};
+			const sourceMapFile = path.join(fileLocation, parsedLine.filePath);
+			const smc = this.cache[sourceMapFile];
+			if (smc) {
+				const originalPosition = smc.originalPositionFor({ line: parsedLine.line, column: parsedLine.column });
+				let sourceFile = originalPosition.source && originalPosition.source.replace("webpack:///", "");
+				if (sourceFile) {
+					if (!_.startsWith(sourceFile, NODE_MODULES_FOLDER_NAME)) {
+						sourceFile = path.join(projectData.getAppDirectoryRelativePath(), sourceFile);
 					}
+
+					sourceFile = stringReplaceAll(sourceFile, "/", path.sep);
+					return { sourceFile, line: originalPosition.line, column: originalPosition.column };
 				}
 			}
 		}
@@ -111,7 +129,7 @@ export class LogSourceMapService implements Mobile.ILogSourceMapService {
 				// "/data/data/org.nativescript.sourceMap/files/app/"
 				const devicePath = `${deviceProjectPath}/${APP_FOLDER_NAME}/`;
 				// "bundle.js"
-				filePath =  path.relative(devicePath, `${"/"}${parts[0]}`);
+				filePath = path.relative(devicePath, `${"/"}${parts[0]}`);
 				line = parseInt(parts[1]);
 				column = parseInt(parts[2]);
 				messagePrefix = rawMessage.substring(0, fileIndex);
@@ -123,7 +141,7 @@ export class LogSourceMapService implements Mobile.ILogSourceMapService {
 			}
 		}
 
-		return { filePath, line, column, messagePrefix, messageSuffix};
+		return { filePath, line, column, messagePrefix, messageSuffix };
 	}
 
 	private parseIosLog(rawMessage: string): IParsedMessage {
@@ -138,10 +156,10 @@ export class LogSourceMapService implements Mobile.ILogSourceMapService {
 			parts = fileSubstring.split(":");
 
 			if (parts && parts.length >= 3) {
-				filePath =  parts[0];
+				filePath = parts[0];
 				// "app/vendor.js"
 				if (_.startsWith(filePath, APP_FOLDER_NAME)) {
-					filePath = path.relative(APP_FOLDER_NAME , parts[0]);
+					filePath = path.relative(APP_FOLDER_NAME, parts[0]);
 				}
 				line = parseInt(parts[1]);
 				column = parseInt(parts[2]);

test/services/log-source-map-service.ts

@@ -5,6 +5,7 @@ import { LogSourceMapService } from "../../lib/services/log-source-map-service";
 import { DevicePlatformsConstants } from "../../lib/common/mobile/device-platforms-constants";
 import { FileSystem } from "../../lib/common/file-system";
 import { stringReplaceAll } from "../../lib/common/helpers";
+import { LoggerStub } from "../stubs";
 
 function createTestInjector(): IInjector {
 	const testInjector = new Yok();
@@ -30,6 +31,7 @@ function createTestInjector(): IInjector {
 	});
 	testInjector.register("fs", FileSystem);
 	testInjector.register("devicePlatformsConstants", DevicePlatformsConstants);
+	testInjector.register("logger", LoggerStub);
 	testInjector.register("logSourceMapService", LogSourceMapService);
 
 	return testInjector;
@@ -83,9 +85,15 @@ const testCases: IDictionary<Array<{caseName: string, message: string, expected:
 describe("log-source-map-service", () => {
 	describe("replaceWithOriginalFileLocations", () => {
 		let logSourceMapService: Mobile.ILogSourceMapService;
-		before(() => {
+		before(async () => {
 			const testInjector = createTestInjector();
 			logSourceMapService = testInjector.resolve("logSourceMapService");
+			const originalFilesLocation = path.join(__dirname, ".." , "files", "sourceMapBundle");
+			const fs = testInjector.resolve<IFileSystem>("fs");
+			const files = fs.enumerateFilesInDirectorySync(originalFilesLocation);
+			for (const file of files) {
+				await logSourceMapService.setSourceMapConsumerForFile(file);
+			}
 		});
 
 		_.forEach(testCases, ( cases, platform ) => {