diff --git a/docs/man_pages/project/testing/run-ios.md b/docs/man_pages/project/testing/run-ios.md index 3e8d23de6f..43259fe40f 100644 --- a/docs/man_pages/project/testing/run-ios.md +++ b/docs/man_pages/project/testing/run-ios.md @@ -33,6 +33,7 @@ Start an emulator with specified device identifier and sdk | `$ ns run ios [--de * `--emulator` - If set, runs the app in all available and configured ios simulators. It will start a simulator if none are already running. * `--sdk` - Specifies the target simulator's sdk. * `--justlaunch` - If set, does not print the application output in the console. +* `--log ` - Also controls how much of the application output is printed. By default only its JavaScript output is shown. `debug` adds everything else the app logs - its native code and the system frameworks it uses, like Xcode's console - and `trace` adds debug level entries as well. * `--clean` - If set, forces the complete rebuild of the native application. * `--no-watch` - If set, changes in your code will not be reflected during the execution of this command. * `--release` - If set, produces a release build by running webpack in production mode and native build in release mode. Otherwise, produces a debug build. diff --git a/lib/common/constants.ts b/lib/common/constants.ts index 447efc7ca0..bfa8170818 100644 --- a/lib/common/constants.ts +++ b/lib/common/constants.ts @@ -62,9 +62,12 @@ export class EmulatorDiscoveryNames { } export const DEVICE_LOG_EVENT_NAME = "deviceLogData"; +export const DEVICE_LOG_ENTRY_EVENT_NAME = "deviceLogEntry"; export const IOS_LOG_PREDICATE = 'senderImagePath contains "NativeScript"'; -export const IOS_APP_CRASH_LOG_REG_EXP = /Fatal JavaScript exception \- application has been terminated/; -export const FAIL_LIVESYNC_LOG_REGEX = /Failed to refresh the application with RefreshRequest./; +export const IOS_APP_CRASH_LOG_REG_EXP = + /Fatal JavaScript exception \- application has been terminated/; +export const FAIL_LIVESYNC_LOG_REGEX = + /Failed to refresh the application with RefreshRequest./; export const TARGET_FRAMEWORK_IDENTIFIERS = { Cordova: "Cordova", diff --git a/lib/common/definitions/mobile.d.ts b/lib/common/definitions/mobile.d.ts index 4c27929b2b..32a4bb7f4c 100644 --- a/lib/common/definitions/mobile.d.ts +++ b/lib/common/definitions/mobile.d.ts @@ -154,6 +154,27 @@ declare global { /** * Describes log stream options */ + /** + * A structured unified logging (os_log) entry. + */ + interface IiOSLogEntry { + /** + * Together with the thread, tells apart messages logged at the same time. + */ + pid?: number; + thread?: number; + /** + * Path of the executable of the process that logged the entry. + */ + process: string; + /** + * Path of the binary (executable, framework or library) that logged the entry. + */ + image: string; + level: string; + message: string; + } + interface IiOSLogStreamOptions { /** * This is the --predicate option which will be passed to `log stream` command @@ -213,6 +234,21 @@ declare global { */ logData(line: string, platform: string, deviceIdentifier: string): void; + /** + * Logs a structured iOS log entry, when it belongs to the application + * whose logs are shown on the device. + */ + logEntry( + entry: IiOSLogEntry, + platform: string, + deviceIdentifier: string, + ): void; + + /** + * Returns the project name set for the device, if any. + */ + getProjectNameForDevice(deviceIdentifier: string): string; + /** * Sets the level of logging that will be used. * @param {string} level The level of logs - could be INFO or FULL. @@ -1331,6 +1367,15 @@ declare global { startDeviceLog(deviceIdentifier: string): void; + /** + * Streams structured logs of the process with the given executable name. + * Returns false when the installed ios-device-lib cannot stream them. + */ + startDeviceLogStream( + deviceIdentifier: string, + processName: string, + ): boolean; + apps( deviceIdentifiers: string[], errorHandler?: DeviceOperationErrorHandler, diff --git a/lib/common/mobile/device-log-emitter.ts b/lib/common/mobile/device-log-emitter.ts index dbb59149a5..c254034b61 100644 --- a/lib/common/mobile/device-log-emitter.ts +++ b/lib/common/mobile/device-log-emitter.ts @@ -2,13 +2,14 @@ import { DeviceLogProviderBase } from "./device-log-provider-base"; import { DEVICE_LOG_EVENT_NAME } from "../constants"; import { injector } from "../yok"; import * as _ from "lodash"; +import { getIOSLogEntryText, getIOSLogScope } from "./ios/ios-log-entry"; export class DeviceLogEmitter extends DeviceLogProviderBase { constructor( protected $logFilter: Mobile.ILogFilter, $logger: ILogger, private $loggingLevels: Mobile.ILoggingLevels, - protected $logSourceMapService: Mobile.ILogSourceMapService + protected $logSourceMapService: Mobile.ILogSourceMapService, ) { super($logFilter, $logger, $logSourceMapService); } @@ -16,20 +17,56 @@ export class DeviceLogEmitter extends DeviceLogProviderBase { public logData( line: string, platform: string, - deviceIdentifier: string + deviceIdentifier: string, ): void { this.setDefaultLogLevelForDevice(deviceIdentifier); const loggingOptions = this.getDeviceLogOptionsForDevice( - deviceIdentifier + deviceIdentifier, ) || { logLevel: this.$loggingLevels.info, projectDir: null }; let data = this.$logFilter.filterData(platform, line, loggingOptions); data = this.$logSourceMapService.replaceWithOriginalFileLocations( platform, data, - loggingOptions + loggingOptions, ); + this.emitData(data, platform, deviceIdentifier); + } + + public logEntry( + entry: Mobile.IiOSLogEntry, + platform: string, + deviceIdentifier: string, + ): void { + const loggingOptions = this.getDeviceLogOptionsForDevice(deviceIdentifier); + const text = getIOSLogEntryText(entry, { + processName: loggingOptions && loggingOptions.projectName, + ...getIOSLogScope( + this.$logger.getLevel(), + loggingOptions?.logLevel?.toUpperCase() === this.$loggingLevels.full, + ), + }); + if (text) { + this.stitchIOSLogEntry(entry, text, deviceIdentifier, (message) => + this.emitData( + this.$logSourceMapService.replaceWithOriginalFileLocations( + platform, + message + "\n", + loggingOptions, + ), + platform, + deviceIdentifier, + ), + ); + } + } + + private emitData( + data: string, + platform: string, + deviceIdentifier: string, + ): void { if (data) { this.emit("data", deviceIdentifier, data); this.emit(DEVICE_LOG_EVENT_NAME, data, deviceIdentifier, platform); @@ -42,7 +79,7 @@ export class DeviceLogEmitter extends DeviceLogProviderBase { deviceIdentifier, (deviceLogOptions: Mobile.IDeviceLogOptions) => deviceLogOptions.logLevel, - logLevel.toUpperCase() + logLevel.toUpperCase(), ); } else { this.$logFilter.loggingLevel = logLevel.toUpperCase(); @@ -50,9 +87,8 @@ export class DeviceLogEmitter extends DeviceLogProviderBase { _.keys(this.devicesLogOptions).forEach((deviceId) => { this.devicesLogOptions[deviceId] = this.devicesLogOptions[deviceId] || {}; - this.devicesLogOptions[ - deviceId - ].logLevel = this.$logFilter.loggingLevel; + this.devicesLogOptions[deviceId].logLevel = + this.$logFilter.loggingLevel; }); } } diff --git a/lib/common/mobile/device-log-provider-base.ts b/lib/common/mobile/device-log-provider-base.ts index 1329cde6da..904e8a6531 100644 --- a/lib/common/mobile/device-log-provider-base.ts +++ b/lib/common/mobile/device-log-provider-base.ts @@ -1,27 +1,29 @@ import { EventEmitter } from "events"; import { getPropertyName } from "../helpers"; import { IDictionary } from "../declarations"; +import { IOSLogChunkStitcher, isIOSRuntimeLogEntry } from "./ios/ios-log-entry"; export abstract class DeviceLogProviderBase extends EventEmitter implements Mobile.IDeviceLogProvider { protected devicesLogOptions: IDictionary = {}; + private iOSLogChunkStitcher = new IOSLogChunkStitcher(); constructor( protected $logFilter: Mobile.ILogFilter, protected $logger: ILogger, - protected $logSourceMapService: Mobile.ILogSourceMapService + protected $logSourceMapService: Mobile.ILogSourceMapService, ) { super(); } public async setSourceFileLocation( - pathToOriginalFile: string + pathToOriginalFile: string, ): Promise { try { await this.$logSourceMapService.setSourceMapConsumerForFile( - pathToOriginalFile + pathToOriginalFile, ); } catch (err) { this.$logger.trace("Error while trying to set source map file", err); @@ -31,23 +33,47 @@ export abstract class DeviceLogProviderBase public abstract logData( lineText: string, platform: string, - deviceIdentifier: string + deviceIdentifier: string, + ): void; + + public abstract logEntry( + entry: Mobile.IiOSLogEntry, + platform: string, + deviceIdentifier: string, ): void; public abstract setLogLevel( logLevel: string, - deviceIdentifier?: string + deviceIdentifier?: string, ): void; + protected stitchIOSLogEntry( + entry: Mobile.IiOSLogEntry, + text: string, + deviceIdentifier: string, + emit: (text: string) => void, + ): void { + if (!isIOSRuntimeLogEntry(entry)) { + emit(text); + return; + } + + this.iOSLogChunkStitcher.add( + `${deviceIdentifier}:${entry.pid}:${entry.thread}`, + text, + emit, + ); + } + public setApplicationPidForDevice( deviceIdentifier: string, - pid: string + pid: string, ): void { this.setDeviceLogOptionsProperty( deviceIdentifier, (deviceLogOptions: Mobile.IDeviceLogOptions) => deviceLogOptions.applicationPid, - pid + pid, ); } @@ -56,31 +82,31 @@ export abstract class DeviceLogProviderBase deviceIdentifier, (deviceLogOptions: Mobile.IDeviceLogOptions) => deviceLogOptions.applicationId, - appId + appId, ); } public setProjectNameForDevice( deviceIdentifier: string, - projectName: string + projectName: string, ): void { this.setDeviceLogOptionsProperty( deviceIdentifier, (deviceLogOptions: Mobile.IDeviceLogOptions) => deviceLogOptions.projectName, - projectName + projectName, ); } public setProjectDirForDevice( deviceIdentifier: string, - projectDir: string + projectDir: string, ): void { this.setDeviceLogOptionsProperty( deviceIdentifier, (deviceLogOptions: Mobile.IDeviceLogOptions) => deviceLogOptions.projectDir, - projectDir + projectDir, ); } @@ -99,6 +125,13 @@ export abstract class DeviceLogProviderBase ); } + public getProjectNameForDevice(deviceIdentifier: string): string { + return ( + this.devicesLogOptions[deviceIdentifier] && + this.devicesLogOptions[deviceIdentifier].projectName + ); + } + getApplicationIdForDevice(deviceIdentifier: string) { return ( this.devicesLogOptions[deviceIdentifier] && @@ -107,7 +140,7 @@ export abstract class DeviceLogProviderBase } protected getDeviceLogOptionsForDevice( - deviceIdentifier: string + deviceIdentifier: string, ): Mobile.IDeviceLogOptions { const loggingOptions = this.devicesLogOptions[deviceIdentifier]; if (!loggingOptions) { @@ -120,7 +153,7 @@ export abstract class DeviceLogProviderBase protected setDeviceLogOptionsProperty( deviceIdentifier: string, propNameFunction: Function, - propertyValue: string | boolean + propertyValue: string | boolean, ): void { const propertyName = getPropertyName(propNameFunction); diff --git a/lib/common/mobile/device-log-provider.ts b/lib/common/mobile/device-log-provider.ts index d5c548f780..0833399c25 100644 --- a/lib/common/mobile/device-log-provider.ts +++ b/lib/common/mobile/device-log-provider.ts @@ -7,6 +7,7 @@ import { IOptions } from "../../declarations"; import { color, StyleFormat } from "../../color"; import { ITimelineProfilerService } from "../../services/timeline-profiler-service"; +import { getIOSLogEntryText, getIOSLogScope } from "./ios/ios-log-entry"; export class DeviceLogProvider extends DeviceLogProviderBase { constructor( @@ -15,6 +16,7 @@ export class DeviceLogProvider extends DeviceLogProviderBase { protected $logSourceMapService: Mobile.ILogSourceMapService, protected $timelineProfilerService: ITimelineProfilerService, protected $options: IOptions, + private $loggingLevels: Mobile.ILoggingLevels, ) { super($logFilter, $logger, $logSourceMapService); } @@ -24,13 +26,41 @@ export class DeviceLogProvider extends DeviceLogProviderBase { platform: string, deviceIdentifier: string, ): void { - // console.log(lineText) const loggingOptions = this.getDeviceLogOptionsForDevice(deviceIdentifier); - let data = this.$logFilter.filterData(platform, lineText, loggingOptions); + const data = this.$logFilter.filterData(platform, lineText, loggingOptions); + this.printData(data, lineText, platform, deviceIdentifier); + } + + public logEntry( + entry: Mobile.IiOSLogEntry, + platform: string, + deviceIdentifier: string, + ): void { + const loggingOptions = this.getDeviceLogOptionsForDevice(deviceIdentifier); + const text = getIOSLogEntryText(entry, { + processName: loggingOptions.projectName, + ...getIOSLogScope( + this.$logger.getLevel(), + loggingOptions.logLevel?.toUpperCase() === this.$loggingLevels.full, + ), + }); + if (text) { + this.stitchIOSLogEntry(entry, text, deviceIdentifier, (message) => + this.printData(message + "\n", message, platform, deviceIdentifier), + ); + } + } + + private printData( + data: string, + lineText: string, + platform: string, + deviceIdentifier: string, + ): void { data = this.$logSourceMapService.replaceWithOriginalFileLocations( platform, data, - loggingOptions, + this.getDeviceLogOptionsForDevice(deviceIdentifier), ); if (data) { diff --git a/lib/common/mobile/ios/device/ios-device-operations.ts b/lib/common/mobile/ios/device/ios-device-operations.ts index bffc982e23..b0e2a8a469 100644 --- a/lib/common/mobile/ios/device/ios-device-operations.ts +++ b/lib/common/mobile/ios/device/ios-device-operations.ts @@ -1,6 +1,9 @@ import { IOSDeviceLib as IOSDeviceLibModule } from "ios-device-lib"; import { cache } from "../../../decorators"; -import { DEVICE_LOG_EVENT_NAME } from "../../../constants"; +import { + DEVICE_LOG_ENTRY_EVENT_NAME, + DEVICE_LOG_EVENT_NAME, +} from "../../../constants"; import * as _ from "lodash"; import * as assert from "assert"; import { EventEmitter } from "events"; @@ -133,6 +136,28 @@ export class IOSDeviceOperations this.deviceLib.startDeviceLog([deviceIdentifier]); } + public startDeviceLogStream( + deviceIdentifier: string, + processName: string, + ): boolean { + this.assertIsInitialized(); + if (typeof this.deviceLib.startDeviceLogStream !== "function") { + return false; + } + + this.setShouldDispose(false); + this.$logger.trace( + `Streaming structured logs of ${processName} on device with identifier: ${deviceIdentifier}.`, + ); + + this.attachDeviceLogEntryHandler(); + + this.deviceLib.startDeviceLogStream([ + { deviceId: deviceIdentifier, processName }, + ]); + return true; + } + public async apps( deviceIdentifiers: string[], errorHandler?: DeviceOperationErrorHandler, @@ -380,6 +405,16 @@ export class IOSDeviceOperations assert.ok(this.isInitialized, "iOS device operations not initialized."); } + @cache() + private attachDeviceLogEntryHandler(): void { + this.deviceLib.on( + DEVICE_LOG_ENTRY_EVENT_NAME, + (response: IOSDeviceLib.IDeviceLogEntryData) => { + this.emit(DEVICE_LOG_ENTRY_EVENT_NAME, response); + }, + ); + } + @cache() private attacheDeviceLogDataHandler(): void { this.deviceLib.on( diff --git a/lib/common/mobile/ios/device/ios-device.ts b/lib/common/mobile/ios/device/ios-device.ts index 90dd12e7bc..7aef9a2df4 100644 --- a/lib/common/mobile/ios/device/ios-device.ts +++ b/lib/common/mobile/ios/device/ios-device.ts @@ -17,6 +17,7 @@ export class IOSDevice extends IOSDeviceBase { public fileSystem: Mobile.IDeviceFileSystem; public deviceInfo: Mobile.IDeviceInfo; private _deviceLogHandler: (...args: any[]) => void; + private _deviceLogEntryHandler: (...args: any[]) => void; constructor( private deviceActionInfo: IOSDeviceLib.IDeviceActionInfo, @@ -30,16 +31,16 @@ export class IOSDevice extends IOSDeviceBase { private $devicePlatformsConstants: Mobile.IDevicePlatformsConstants, private $iOSDeviceProductNameMapper: Mobile.IiOSDeviceProductNameMapper, private $iosDeviceOperations: IIOSDeviceOperations, - private $mobileHelper: Mobile.IMobileHelper + private $mobileHelper: Mobile.IMobileHelper, ) { super(); this.applicationManager = this.$injector.resolve( applicationManagerPath.IOSApplicationManager, - { device: this, devicePointer: this.deviceActionInfo } + { device: this, devicePointer: this.deviceActionInfo }, ); this.fileSystem = this.$injector.resolve( fileSystemPath.IOSDeviceFileSystem, - { device: this, devicePointer: this.deviceActionInfo } + { device: this, devicePointer: this.deviceActionInfo }, ); const productType = deviceActionInfo.productType; const isTablet = this.$mobileHelper.isiOSTablet(productType); @@ -58,7 +59,7 @@ export class IOSDevice extends IOSDeviceBase { isTablet: isTablet, displayName: this.$iOSDeviceProductNameMapper.resolveProductName( - deviceActionInfo.deviceName + deviceActionInfo.deviceName, ) || deviceActionInfo.deviceName, model: this.$iOSDeviceProductNameMapper.resolveProductName(productType), version: deviceActionInfo.productVersion, @@ -81,28 +82,63 @@ export class IOSDevice extends IOSDeviceBase { public get isOnlyWiFiConnected(): boolean { const result = this.deviceInfo.connectionTypes.every( - (connectionType) => connectionType === constants.DeviceConnectionType.Wifi + (connectionType) => + connectionType === constants.DeviceConnectionType.Wifi, ); return result; } @cache() public async openDeviceLogStream(): Promise { - if (this.deviceInfo.status !== commonConstants.UNREACHABLE_STATUS) { - this._deviceLogHandler = this.actionOnDeviceLog.bind(this); - this.$iosDeviceOperations.on( - commonConstants.DEVICE_LOG_EVENT_NAME, - this._deviceLogHandler - ); - this.$iosDeviceOperations.startDeviceLog(this.deviceInfo.identifier); + if (this.deviceInfo.status === commonConstants.UNREACHABLE_STATUS) { + return; + } + + // Structured logs need the app's executable name to select its entries; + // without one (e.g. `ns device log`) the whole device log is shown. + const processName = this.$deviceLogProvider.getProjectNameForDevice( + this.deviceInfo.identifier, + ); + if (processName && this.startStructuredDeviceLog(processName)) { + return; + } + + this.startSyslogDeviceLog(); + } + + private startStructuredDeviceLog(processName: string): boolean { + this._deviceLogEntryHandler = this.actionOnDeviceLogEntry.bind(this); + this.$iosDeviceOperations.on( + commonConstants.DEVICE_LOG_ENTRY_EVENT_NAME, + this._deviceLogEntryHandler, + ); + if ( + this.$iosDeviceOperations.startDeviceLogStream( + this.deviceInfo.identifier, + processName, + ) + ) { + return true; } + + this.removeDeviceLogEntryHandler(); + return false; + } + + private startSyslogDeviceLog(): void { + this._deviceLogHandler = this.actionOnDeviceLog.bind(this); + this.$iosDeviceOperations.on( + commonConstants.DEVICE_LOG_EVENT_NAME, + this._deviceLogHandler, + ); + this.$iosDeviceOperations.startDeviceLog(this.deviceInfo.identifier); } protected async getDebugSocketCore(appId: string): Promise { await this.$iOSSocketRequestExecutor.executeAttachRequest( this, constants.AWAIT_NOTIFICATION_TIMEOUT_SECONDS, - appId + appId, ); const port = await super.getDebuggerPort(appId); const deviceId = this.deviceInfo.identifier; @@ -113,7 +149,7 @@ export class IOSDevice extends IOSDeviceBase { await this.$iosDeviceOperations.connectToPort([ { deviceId: deviceId, port: port }, ]) - )[deviceId] + )[deviceId], ); const _socket = new net.Socket(); _socket.connect(deviceResponse.port, deviceResponse.host); @@ -128,8 +164,42 @@ export class IOSDevice extends IOSDeviceBase { this.$deviceLogProvider.logData( response.message, this.$devicePlatformsConstants.iOS, - this.deviceInfo.identifier + this.deviceInfo.identifier, + ); + } + } + + private actionOnDeviceLogEntry( + response: IOSDeviceLib.IDeviceLogEntryData, + ): void { + if (response.deviceId !== this.deviceInfo.identifier) { + return; + } + + if (response.error) { + this.$logger.trace( + `Structured device logs are not available for ${this.deviceInfo.identifier}, falling back to the syslog relay.`, + response.error, + ); + this.removeDeviceLogEntryHandler(); + this.startSyslogDeviceLog(); + return; + } + + this.$deviceLogProvider.logEntry( + response.entry, + this.$devicePlatformsConstants.iOS, + this.deviceInfo.identifier, + ); + } + + private removeDeviceLogEntryHandler(): void { + if (this._deviceLogEntryHandler) { + this.$iosDeviceOperations.removeListener( + commonConstants.DEVICE_LOG_ENTRY_EVENT_NAME, + this._deviceLogEntryHandler, ); + this._deviceLogEntryHandler = null; } } @@ -137,9 +207,10 @@ export class IOSDevice extends IOSDeviceBase { if (this._deviceLogHandler) { this.$iosDeviceOperations.removeListener( commonConstants.DEVICE_LOG_EVENT_NAME, - this._deviceLogHandler + this._deviceLogHandler, ); } + this.removeDeviceLogEntryHandler(); } private getActiveArchitecture(productType: string): string { diff --git a/lib/common/mobile/ios/ios-log-entry.ts b/lib/common/mobile/ios/ios-log-entry.ts new file mode 100644 index 0000000000..0d1121fe52 --- /dev/null +++ b/lib/common/mobile/ios/ios-log-entry.ts @@ -0,0 +1,137 @@ +import * as path from "path"; + +export interface IIOSLogEntryFilterOptions { + /** + * Name of the application's executable. Entries are matched by name rather + * than pid, so the logs follow the app when it is relaunched. + */ + processName: string; + /** + * Include everything the app's process logs - its own native code and the + * system frameworks it uses - like Xcode's console does. + */ + includeNative?: boolean; + /** + * Include debug level entries as well. + */ + includeDebug?: boolean; +} + +/** + * Which of the app's logs to show, from the CLI's --log level: JS output by + * default, everything but debug entries (like Xcode) with "debug", and + * everything with "trace" or "all". A full device log level shows everything. + */ +export function getIOSLogScope( + cliLogLevel: string, + fullDeviceLog: boolean, +): Pick { + const level = (cliLogLevel || "").toUpperCase(); + const includeDebug = fullDeviceLog || level === "TRACE" || level === "ALL"; + return { + includeNative: includeDebug || level === "DEBUG", + includeDebug, + }; +} + +export function isIOSRuntimeLogEntry(entry: Mobile.IiOSLogEntry): boolean { + return path.basename(entry.image || "") === "NativeScript"; +} + +// Logged by the runtime itself on every launch, not by the app. +const RUNTIME_NOISE = ["NativeScript loaded bundle"]; + +/** + * Returns the text to print for a structured iOS log entry, or null when the + * entry should not be shown. + * + * JS console output and runtime errors are the entries logged by the + * NativeScript framework; everything else in the app's process is native and + * printed prefixed with the binary that logged it. + */ +export function getIOSLogEntryText( + entry: Mobile.IiOSLogEntry, + options: IIOSLogEntryFilterOptions, +): string | null { + if (!entry || path.basename(entry.process || "") !== options.processName) { + return null; + } + + const imageName = path.basename(entry.image || ""); + if (isIOSRuntimeLogEntry(entry)) { + return RUNTIME_NOISE.some((noise) => entry.message.includes(noise)) + ? null + : entry.message; + } + + if ( + !options.includeNative || + (entry.level === "debug" && !options.includeDebug) + ) { + return null; + } + + return `${imageName}: ${entry.message}`; +} + +// The runtime ends a chunk of a split message with one of these when the CLI +// asks for it, through the logChunkMarkers key of the app's package.json. +const CHUNK_JOIN_MARKER = "\u2060"; +const CHUNK_LINE_MARKER = "\u2061"; +const CONSOLE_PREFIX = /^CONSOLE [A-Z]+: /; + +// Long enough to ride out a backlog of chunks, while the rest of a message that +// never arrives, because the app crashed, still gets printed. +const CHUNK_WAIT_MS = 500; + +interface IPendingLogMessage { + text: string; + prefix: string; + separator: string; + timer: NodeJS.Timeout; +} + +/** + * Reassembles messages the runtime split to get them through os_log. + */ +export class IOSLogChunkStitcher { + private pending = new Map(); + + /** + * @param key Identifies the logging thread: chunks from different threads can interleave. + * @param emit Called with the complete message. + */ + public add(key: string, text: string, emit: (text: string) => void): void { + const marker = text[text.length - 1]; + const continues = + marker === CHUNK_JOIN_MARKER || marker === CHUNK_LINE_MARKER; + const chunk = continues ? text.slice(0, -1) : text; + + const message = this.pending.get(key) ?? { + text: "", + prefix: chunk.match(CONSOLE_PREFIX)?.[0] ?? "", + separator: "", + timer: null, + }; + clearTimeout(message.timer); + message.text += + message.separator + + (message.text && chunk.startsWith(message.prefix) + ? chunk.slice(message.prefix.length) + : chunk); + + if (!continues) { + this.pending.delete(key); + emit(message.text); + return; + } + + message.separator = marker === CHUNK_LINE_MARKER ? "\n" : ""; + message.timer = setTimeout(() => { + this.pending.delete(key); + emit(message.text); + }, CHUNK_WAIT_MS); + message.timer.unref(); + this.pending.set(key, message); + } +} diff --git a/lib/common/mobile/ios/ios-log-filter.ts b/lib/common/mobile/ios/ios-log-filter.ts deleted file mode 100644 index e5f1188659..0000000000 --- a/lib/common/mobile/ios/ios-log-filter.ts +++ /dev/null @@ -1,28 +0,0 @@ -import { injector } from "../../yok"; - -export class IOSLogFilter implements Mobile.IPlatformLogFilter { - protected infoFilterRegex = /^.*?(AppBuilder|Cordova|NativeScript).*?(:.*?|:.*?|:.*?)$/im; - - constructor(private $loggingLevels: Mobile.ILoggingLevels) {} - - public filterData( - data: string, - loggingOptions: Mobile.IDeviceLogOptions = {} - ): string { - const specifiedLogLevel = (loggingOptions.logLevel || "").toUpperCase(); - const pid = loggingOptions && loggingOptions.applicationPid; - - if (specifiedLogLevel === this.$loggingLevels.info && data) { - if (pid) { - return data.indexOf(`[${pid}]`) !== -1 ? data.trim() : null; - } - - const matchingInfoMessage = data.match(this.infoFilterRegex); - return matchingInfoMessage ? matchingInfoMessage[2] : null; - } - - return data; - } -} - -injector.register("iOSLogFilter", IOSLogFilter); diff --git a/lib/common/mobile/ios/simulator/ios-simulator-log-provider.ts b/lib/common/mobile/ios/simulator/ios-simulator-log-provider.ts index a13dd2055e..e560adf789 100644 --- a/lib/common/mobile/ios/simulator/ios-simulator-log-provider.ts +++ b/lib/common/mobile/ios/simulator/ios-simulator-log-provider.ts @@ -1,4 +1,5 @@ import { ChildProcess } from "child_process"; +import * as readline from "readline"; import { EventEmitter } from "events"; import * as _ from "lodash"; import { @@ -7,10 +8,13 @@ import { IDisposable, } from "../../../declarations"; import { injector } from "../../../yok"; +import { IChildProcess } from "../../../declarations"; +import { getIOSLogScope } from "../ios-log-entry"; export class IOSSimulatorLogProvider extends EventEmitter - implements Mobile.IiOSSimulatorLogProvider, IDisposable, IShouldDispose { + implements Mobile.IiOSSimulatorLogProvider, IDisposable, IShouldDispose +{ public shouldDispose: boolean; private simulatorsLoggingEnabled: IDictionary = {}; private simulatorsLogProcess: IDictionary = {}; @@ -19,7 +23,8 @@ export class IOSSimulatorLogProvider private $iOSSimResolver: Mobile.IiOSSimResolver, private $logger: ILogger, private $devicePlatformsConstants: Mobile.IDevicePlatformsConstants, - private $deviceLogProvider: Mobile.IDeviceLogProvider + private $deviceLogProvider: Mobile.IDeviceLogProvider, + private $childProcess: IChildProcess, ) { super(); this.shouldDispose = true; @@ -31,20 +36,26 @@ export class IOSSimulatorLogProvider public async startLogProcess( deviceId: string, - options?: Mobile.IiOSLogStreamOptions + options?: Mobile.IiOSLogStreamOptions, ): Promise { if (!this.simulatorsLoggingEnabled[deviceId]) { - const deviceLogChildProcess: ChildProcess = await this.$iOSSimResolver.iOSSim.getDeviceLogProcess( - deviceId, - options ? options.predicate : null - ); + // Structured logs need the app's executable name to select its + // entries; without one the predicate decides what is shown. + const processName = + this.$deviceLogProvider.getProjectNameForDevice(deviceId); + const deviceLogChildProcess: ChildProcess = processName + ? this.startStructuredLogProcess(deviceId, processName) + : await this.$iOSSimResolver.iOSSim.getDeviceLogProcess( + deviceId, + options ? options.predicate : null, + ); const action = (data: Buffer | string) => { const message = data.toString(); this.$deviceLogProvider.logData( message, this.$devicePlatformsConstants.iOS, - deviceId + deviceId, ); }; @@ -55,18 +66,24 @@ export class IOSSimulatorLogProvider deviceLogChildProcess.once("error", (err) => { this.$logger.trace( - `Error is thrown for device with identifier ${deviceId}. More info: ${err.message}.` + `Error is thrown for device with identifier ${deviceId}. More info: ${err.message}.`, ); this.simulatorsLoggingEnabled[deviceId] = false; }); } - if (deviceLogChildProcess.stdout) { - deviceLogChildProcess.stdout.on("data", action.bind(this)); - } + if (processName) { + readline + .createInterface({ input: deviceLogChildProcess.stdout }) + .on("line", (line) => this.logStructuredLine(deviceId, line)); + } else { + if (deviceLogChildProcess.stdout) { + deviceLogChildProcess.stdout.on("data", action.bind(this)); + } - if (deviceLogChildProcess.stderr) { - deviceLogChildProcess.stderr.on("data", action.bind(this)); + if (deviceLogChildProcess.stderr) { + deviceLogChildProcess.stderr.on("data", action.bind(this)); + } } this.simulatorsLoggingEnabled[deviceId] = true; @@ -74,6 +91,64 @@ export class IOSSimulatorLogProvider } } + private startStructuredLogProcess( + deviceId: string, + processName: string, + ): ChildProcess { + // Matched by name rather than pid, so the logs follow the app when it is + // relaunched. log stream leaves out info and debug entries by default. + const scope = getIOSLogScope(this.$logger.getLevel(), false); + const args = [ + "simctl", + "spawn", + deviceId, + "log", + "stream", + "--style", + "ndjson", + "--predicate", + `process == ${JSON.stringify(processName)}`, + ]; + if (scope.includeNative) { + args.push("--level", scope.includeDebug ? "debug" : "info"); + } + + return this.$childProcess.spawn("xcrun", args); + } + + private logStructuredLine(deviceId: string, line: string): void { + // log stream prints a non-JSON "Filtering the log data..." header first. + if (!line.startsWith("{")) { + return; + } + + let event: any; + try { + event = JSON.parse(line); + } catch (err) { + this.$logger.trace(`Unable to parse simulator log entry: ${line}`); + return; + } + + // Activities and signposts are streamed too, but are not log messages. + if (event.eventType && event.eventType !== "logEvent") { + return; + } + + this.$deviceLogProvider.logEntry( + { + pid: event.processID, + thread: event.threadID, + process: event.processImagePath, + image: event.senderImagePath, + level: (event.messageType || "").toLowerCase(), + message: event.eventMessage, + }, + this.$devicePlatformsConstants.iOS, + deviceId, + ); + } + public dispose(signal?: any) { if (this.shouldDispose) { _.each( @@ -82,7 +157,7 @@ export class IOSSimulatorLogProvider if (logProcess) { logProcess.kill(signal); } - } + }, ); } } diff --git a/lib/common/test/unit-tests/ios-log-filter.ts b/lib/common/test/unit-tests/ios-log-filter.ts deleted file mode 100644 index ed07a29e11..0000000000 --- a/lib/common/test/unit-tests/ios-log-filter.ts +++ /dev/null @@ -1,224 +0,0 @@ -import { IOSLogFilter } from "../../mobile/ios/ios-log-filter"; -import { LoggingLevels } from "../../mobile/logging-levels"; -import { Yok } from "../../yok"; -import * as assert from "assert"; -import * as _ from "lodash"; - -const iosTestData = [ - { - input: - "Dec 29 08:46:04 Dragons-iPhone iaptransportd[65] : CIapPortAppleIDBus: Auth timer timeout completed on pAIDBPort:0x135d09410, portID:01 downstream port", - output: null, - pid13309Output: null, - }, - { - input: - "Dec 29 08:46:06 Dragons-iPhone kernel[0] : AppleARMPMUCharger: AppleUSBCableDetect 1", - output: null, - pid13309Output: null, - }, - { - input: - 'Dec 29 08:47:24 Dragons-iPhone bird[131] : unable to determine evictable space: Error Domain=LibrarianErrorDomain Code=10 "The operation couldn’t be completed. (LibrarianErrorDomain error 10 - Unable to configure the collection.)" UserInfo=0x137528190 {NSDescription=Unable to configure the collection.}', - output: null, - pid13309Output: null, - }, - { - input: - "Dec 29 08:47:43 Dragons-iPhone syslog_relay[179] : syslog_relay found the ASL prompt. Starting...", - output: null, - pid13309Output: null, - }, - { - input: - "Dec 29 08:48:47 Dragons-iPhone com.apple.xpc.launchd[1] (com.apple.WebKit.Networking.08B3A589-3D68-492A-BA8D-A812EC55FDEB[13306]) : Service exited with abnormal code: 1", - output: null, - pid13309Output: null, - }, - { - input: - "Dec 29 08:48:47 Dragons-iPhone ReportCrash[13308] : Saved report to /var/mobile/Library/Logs/CrashReporter/Cordova370_2015-12-29-084847_Dragons-iPhone.ips", - output: null, - pid13309Output: null, - }, - { - input: - "Dec 29 08:48:47 Dragons-iPhone com.apple.WebKit.Networking[13306] : Faild to obtain sandbox extension for path=/private/var/mobile/Containers/Data/Application/047BB8F2-B8C8-405F-A820-8719EE207E6F/Library/Caches/com.telerik.BlankJS. Errno:1", - output: null, - pid13309Output: null, - }, - { - input: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : Apache Cordova native platform version 3.7.0 is starting.", - output: - ": Apache Cordova native platform version 3.7.0 is starting.", - pid13309Output: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : Apache Cordova native platform version 3.7.0 is starting.", - }, - { - input: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : Multi-tasking -> Device: YES, App: YES", - output: ": Multi-tasking -> Device: YES, App: YES", - pid13309Output: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : Multi-tasking -> Device: YES, App: YES", - }, - { - input: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : Unlimited access to network resources", - output: ": Unlimited access to network resources", - pid13309Output: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : Unlimited access to network resources", - }, - { - input: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : Finished load of: file:///var/mobile/Containers/Data/Application/0746156D-3C83-402E-8B4E-2B3063F42F76/Documents/index.html", - output: - ": Finished load of: file:///var/mobile/Containers/Data/Application/0746156D-3C83-402E-8B4E-2B3063F42F76/Documents/index.html", - pid13309Output: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : Finished load of: file:///var/mobile/Containers/Data/Application/0746156D-3C83-402E-8B4E-2B3063F42F76/Documents/index.html", - }, - { - input: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : ---------------------------------- LOG FROM MY APP", - output: ": ---------------------------------- LOG FROM MY APP", - pid13309Output: - "Dec 29 08:49:06 Dragons-iPhone Cordova370[13309] : ---------------------------------- LOG FROM MY APP", - }, - { - input: - "Dec 29 08:50:31 Dragons-iPhone NativeScript143[13314] : assertion failed: 12F70: libxpc.dylib + 71768 [B870B51D-AA85-3686-A7D9-ACD48C5FE153]: 0x7d", - output: - ": assertion failed: 12F70: libxpc.dylib + 71768 [B870B51D-AA85-3686-A7D9-ACD48C5FE153]: 0x7d", - pid13309Output: null, - }, - { - input: "Dec 29 08:50:31 Dragons-iPhone Unknown[13314] :", - output: null, - pid13309Output: null, - }, - { - input: - "Dec 29 08:50:31 Dragons-iPhone locationd[57] : Gesture EnabledForTopCLient: 0, EnabledInDaemonSettings: 0", - output: null, - pid13309Output: null, - }, - { - input: - "Dec 29 08:55:24 Dragons-iPhone NativeScript143[13309] : file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41", - output: - ": file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41", - pid13309Output: - "Dec 29 08:55:24 Dragons-iPhone NativeScript143[13309] : file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41", - }, - { - input: - "Dec 29 08:55:24 Dragons-iPhone NativeScript143[13309] : file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41\n", - output: - ": file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41", - pid13309Output: - "Dec 29 08:55:24 Dragons-iPhone NativeScript143[13309] : file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41", - }, - { - input: - "Dec 29 08:55:24 Dragons-iPhone NativeScript143[13309]: : file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41\n", - output: - ": file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41", - pid13309Output: - "Dec 29 08:55:24 Dragons-iPhone NativeScript143[13309]: : file:///app/main-view-model.js:11:14: CONSOLE LOG COUNTER: 41", - }, - { - input: - "Oct 4 08:53:46 bd-airtestmac com.apple.CoreSimulator.SimDevice.3616FC55-9CAB-47D4-8C58-5E5F0BE99C8E.launchd_sim[30337] (UIKitApplication:org.nativescript.ap1[0x76c5][13309]): Service exited due to signal: Terminated: 15", - output: null, - pid13309Output: - "Oct 4 08:53:46 bd-airtestmac com.apple.CoreSimulator.SimDevice.3616FC55-9CAB-47D4-8C58-5E5F0BE99C8E.launchd_sim[30337] (UIKitApplication:org.nativescript.ap1[0x76c5][13309]): Service exited due to signal: Terminated: 15", - }, - { - input: - "Oct 4 08:52:44 bd-airtestmac assertiond[13309]: assertion failed: 15G31 13A344: assertiond + 12188 [93893311-6962-33A7-A734-E36F946D8EBA]: 0x1", - output: null, - pid13309Output: - "Oct 4 08:52:44 bd-airtestmac assertiond[13309]: assertion failed: 15G31 13A344: assertiond + 12188 [93893311-6962-33A7-A734-E36F946D8EBA]: 0x1", - }, -]; - -describe("iOSLogFilter", () => { - const assertFiltering = ( - inputData: string, - expectedOutput: string, - _logLevel?: string, - _pid?: string - ) => { - const testInjector = new Yok(); - testInjector.register("loggingLevels", LoggingLevels); - const iOSLogFilter = ( - testInjector.resolve(IOSLogFilter) - ); - const filteredData = iOSLogFilter.filterData(inputData, { - logLevel: _logLevel, - applicationPid: _pid, - projectDir: null, - }); - assert.deepStrictEqual( - filteredData, - expectedOutput, - `The actual result '${filteredData}' did NOT match expected output '${expectedOutput}'.` - ); - }; - - let logLevel = "INFO"; - const pid = "13309"; - - describe("filterData", () => { - describe("when PID is not provided", () => { - it("when log level is full returns full data", () => { - logLevel = "FULL"; - _.each(iosTestData, (testData) => { - assertFiltering(testData.input, testData.input, logLevel); - }); - }); - - it("when log level is INFO filters data", () => { - logLevel = "INFO"; - _.each(iosTestData, (testData) => { - assertFiltering(testData.input, testData.output, logLevel); - }); - }); - - it("when log level is not specified returns full data", () => { - logLevel = null; - _.each(iosTestData, (testData) => { - assertFiltering(testData.input, testData.input); - }); - }); - }); - - describe("when PID is provided", () => { - it("when log level is full returns full data", () => { - logLevel = "FULL"; - _.each(iosTestData, (testData) => { - assertFiltering(testData.input, testData.input, logLevel, pid); - }); - }); - - it("when log level is INFO filters data", () => { - logLevel = "INFO"; - _.each(iosTestData, (testData) => { - assertFiltering( - testData.input, - testData.pid13309Output, - logLevel, - pid - ); - }); - }); - - it("when log level is not specified returns full data", () => { - logLevel = null; - _.each(iosTestData, (testData) => { - assertFiltering(testData.input, testData.input, logLevel, pid); - }); - }); - }); - }); -}); diff --git a/lib/common/test/unit-tests/mobile/device-log-provider.ts b/lib/common/test/unit-tests/mobile/device-log-provider.ts index 46f6929a90..b122676ceb 100644 --- a/lib/common/test/unit-tests/mobile/device-log-provider.ts +++ b/lib/common/test/unit-tests/mobile/device-log-provider.ts @@ -1671,4 +1671,27 @@ at promiseReactionJob\n`, }); }); }); + describe("structured iOS log entries", () => { + const structuredDevice = "structuredDevice"; + const appDir = "/private/var/containers/Bundle/Application/1/app.app"; + + it("prints the app's JS output and drops other entries", () => { + deviceLogProvider.setProjectNameForDevice(structuredDevice, "app"); + const log = (image: string, message: string, process = `${appDir}/app`) => + deviceLogProvider.logEntry( + { process, image, level: "notice", message }, + "iOS", + structuredDevice, + ); + + log( + `${appDir}/Frameworks/NativeScript.framework/NativeScript`, + "CONSOLE LOG: hello", + ); + log("/System/Library/Frameworks/Network.framework/Network", "nw noise"); + log("", "wlan0: noise", "/kernel"); + + assertData(logger.output, "CONSOLE LOG: hello\n"); + }); + }); }); diff --git a/lib/common/test/unit-tests/mobile/ios-log-entry.ts b/lib/common/test/unit-tests/mobile/ios-log-entry.ts new file mode 100644 index 0000000000..e8c8cc4a2e --- /dev/null +++ b/lib/common/test/unit-tests/mobile/ios-log-entry.ts @@ -0,0 +1,200 @@ +import { assert } from "chai"; +import * as sinon from "sinon"; +import { + getIOSLogEntryText, + getIOSLogScope, + IOSLogChunkStitcher, +} from "../../../mobile/ios/ios-log-entry"; + +const appDir = + "/private/var/containers/Bundle/Application/CFC7170F-ACC6-429C-942C-FF90EDC34D47/app.app"; + +const entry = (image: string, message: string, process = `${appDir}/app`) => ({ + process, + image, + level: "notice", + message, +}); + +const jsLog = entry( + `${appDir}/Frameworks/NativeScript.framework/NativeScript`, + 'CONSOLE LOG: [ "network", "internet probe -> true (status 200)" ]', +); +const appFrameworkLog = entry( + `${appDir}/Frameworks/LightLib.framework/LightLib`, + "universe 1 updated", +); +const systemFrameworkLog = entry( + "/System/Library/Frameworks/Network.framework/Network", + "nw_connection_report_state_with_handler_on_nw_queue [C2] reporting state cancelled", +); +const kernelLog = entry( + "", + "wlan0:com.apple.p2p.awdl0: isInfraRealtimePacketThresholdAllowed allowed:1", + "/kernel", +); + +describe("getIOSLogEntryText", () => { + const debugLog = { ...systemFrameworkLog, level: "debug" }; + + it("returns JS console output of the app", () => { + assert.equal( + getIOSLogEntryText(jsLog, { processName: "app" }), + jsLog.message, + ); + }); + + it("drops entries of other processes", () => { + assert.isNull(getIOSLogEntryText(kernelLog, { processName: "app" })); + assert.isNull( + getIOSLogEntryText(kernelLog, { + processName: "app", + includeNative: true, + includeDebug: true, + }), + ); + assert.isNull(getIOSLogEntryText(jsLog, { processName: "otherApp" })); + }); + + it("drops native entries unless they are requested", () => { + assert.isNull(getIOSLogEntryText(appFrameworkLog, { processName: "app" })); + assert.isNull( + getIOSLogEntryText(systemFrameworkLog, { processName: "app" }), + ); + }); + + it("includes everything the app's process logs, prefixed with the binary, when native logs are requested", () => { + const options = { processName: "app", includeNative: true }; + + assert.equal( + getIOSLogEntryText(appFrameworkLog, options), + "LightLib: universe 1 updated", + ); + assert.equal( + getIOSLogEntryText(systemFrameworkLog, options), + `Network: ${systemFrameworkLog.message}`, + ); + assert.isNull(getIOSLogEntryText(debugLog, options)); + }); + + it("includes debug entries only when requested", () => { + assert.equal( + getIOSLogEntryText(debugLog, { + processName: "app", + includeNative: true, + includeDebug: true, + }), + `Network: ${debugLog.message}`, + ); + }); + + it("drops the runtime's own startup message", () => { + assert.isNull( + getIOSLogEntryText( + { ...jsLog, message: "NativeScript loaded bundle file:///app/" }, + { processName: "app" }, + ), + ); + }); +}); + +describe("getIOSLogScope", () => { + it("maps the CLI log level to the app logs that are shown", () => { + assert.deepEqual(getIOSLogScope("INFO", false), { + includeNative: false, + includeDebug: false, + }); + assert.deepEqual(getIOSLogScope("DEBUG", false), { + includeNative: true, + includeDebug: false, + }); + assert.deepEqual(getIOSLogScope("TRACE", false), { + includeNative: true, + includeDebug: true, + }); + assert.deepEqual(getIOSLogScope("ALL", false), { + includeNative: true, + includeDebug: true, + }); + }); + + it("shows everything for a full device log", () => { + assert.deepEqual(getIOSLogScope("INFO", true), { + includeNative: true, + includeDebug: true, + }); + }); +}); + +describe("IOSLogChunkStitcher", () => { + const JOIN = "\u2060"; + const LINE = "\u2061"; + let stitcher: IOSLogChunkStitcher; + let messages: string[]; + let clock: sinon.SinonFakeTimers; + const add = (text: string, key = "thread") => + stitcher.add(key, text, (message) => messages.push(message)); + + beforeEach(() => { + clock = sinon.useFakeTimers(); + stitcher = new IOSLogChunkStitcher(); + messages = []; + }); + + afterEach(() => { + clock.restore(); + }); + + it("passes through messages that were not split", () => { + add("CONSOLE LOG: hello"); + assert.deepEqual(messages, ["CONSOLE LOG: hello"]); + }); + + it("rejoins chunks without the repeated prefix", () => { + add(`CONSOLE LOG: {"a":${JOIN}`); + add(`CONSOLE LOG: 1,"b":${JOIN}`); + assert.isEmpty(messages); + add("CONSOLE LOG: 2}"); + assert.deepEqual(messages, ['CONSOLE LOG: {"a":1,"b":2}']); + }); + + it("restores the line break a chunk was cut at", () => { + add(`CONSOLE ERROR: first${LINE}`); + add("CONSOLE ERROR: second"); + assert.deepEqual(messages, ["CONSOLE ERROR: first\nsecond"]); + }); + + it("rejoins messages that have no prefix", () => { + add(`Assertion failed: a${JOIN}`); + add("b"); + assert.deepEqual(messages, ["Assertion failed: ab"]); + }); + + it("keeps a chunk's own text when it only looks like a prefix", () => { + add(`CONSOLE LOG: a${JOIN}`); + add("CONSOLE ERROR: b"); + assert.deepEqual(messages, ["CONSOLE LOG: aCONSOLE ERROR: b"]); + }); + + it("keeps interleaved threads apart", () => { + add(`CONSOLE LOG: a1${JOIN}`, "a"); + add(`CONSOLE LOG: b1${JOIN}`, "b"); + add("CONSOLE LOG: other", "c"); + add("CONSOLE LOG: a2", "a"); + add("CONSOLE LOG: b2", "b"); + assert.deepEqual(messages, [ + "CONSOLE LOG: other", + "CONSOLE LOG: a1a2", + "CONSOLE LOG: b1b2", + ]); + }); + + it("prints what it has when the rest never arrives", () => { + add(`CONSOLE LOG: a${JOIN}`); + clock.tick(500); + assert.deepEqual(messages, ["CONSOLE LOG: a"]); + + add("CONSOLE LOG: unrelated"); + assert.deepEqual(messages, ["CONSOLE LOG: a", "CONSOLE LOG: unrelated"]); + }); +}); diff --git a/lib/common/test/unit-tests/stubs.ts b/lib/common/test/unit-tests/stubs.ts index 8bcb472531..83aeaf7f19 100644 --- a/lib/common/test/unit-tests/stubs.ts +++ b/lib/common/test/unit-tests/stubs.ts @@ -234,6 +234,18 @@ export class DeviceLogProviderStub }); } + logEntry( + entry: Mobile.IiOSLogEntry, + platform: string, + deviceIdentifier: string, + ): void { + this.logData(entry.message, platform, deviceIdentifier); + } + + getProjectNameForDevice(deviceIdentifier: string): string { + return this.currentDeviceProjectNames[deviceIdentifier]; + } + setLogLevel(level: string, deviceIdentifier?: string): void {} setApplicationPidForDevice(deviceIdentifier: string, pid: string): void { diff --git a/lib/controllers/prepare-controller.ts b/lib/controllers/prepare-controller.ts index b39a06d032..f70795f49b 100644 --- a/lib/controllers/prepare-controller.ts +++ b/lib/controllers/prepare-controller.ts @@ -341,6 +341,7 @@ export class PrepareController newNativeWatchStarted = await this.startNativeWatcher( platformData, projectData, + prepareData, ); } @@ -359,6 +360,7 @@ export class PrepareController private async startNativeWatcher( platformData: IPlatformData, projectData: IProjectData, + prepareData: IPrepareData, ): Promise { if ( this.watchersData[projectData.projectDir][ @@ -388,7 +390,11 @@ export class PrepareController this.$watchIgnoreListService.removeFileFromIgnoreList(filePath); } else { this.$logger.info(`Chokidar raised event ${event} for ${filePath}.`); - await this.writeRuntimePackageJson(projectData, platformData); + await this.writeRuntimePackageJson( + projectData, + platformData, + prepareData, + ); this.emitPrepareEvent({ files: [], staleFiles: [], @@ -518,6 +524,9 @@ export class PrepareController version: installedRuntimePackageJSON.version, }; } + if (prepareData && !prepareData.release) { + packageData.logChunkMarkers = true; + } if (packageData.ios && packageData.ios.discardUncaughtJsExceptions) { packageData.discardUncaughtJsExceptions = packageData.ios.discardUncaughtJsExceptions; diff --git a/lib/services/ios-log-filter.ts b/lib/services/ios-log-filter.ts index 04f58146dc..c994442a0c 100644 --- a/lib/services/ios-log-filter.ts +++ b/lib/services/ios-log-filter.ts @@ -2,15 +2,17 @@ import { injector } from "../common/yok"; export class IOSLogFilter implements Mobile.IPlatformLogFilter { // Used to recognize output related to the current project - // This looks for artifacts like: AppName[22432] or AppName(SomeTextHere)[23123] - private appOutputRegex: RegExp = /([^\s\(\)]+)(?:\(([^\s]+)\))?\[[0-9]+\]/; + // This looks for artifacts like: AppName[22432], AppName(SomeTextHere)[23123] + // or kernel()[0] - a header must be recognized even without an image name, + // or the line is treated as a continuation of the previous message. + private appOutputRegex: RegExp = /([^\s\(\)]+)(?:\(([^\s]*)\))?\[[0-9]+\]/; // Used to trim the passed messages to a simpler output // Example: // This: "May 24 15:54:52 Dragons-iPhone NativeScript250(NativeScript)[356] : CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3477:36: ORIGINAL STACKTRACE:" // Becomes: CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3477:36: ORIGINAL STACKTRACE: protected infoFilterRegex = new RegExp( - `^.*(?::[ \t]?|:[ \t]?|:[ \t]?|\\(NativeScript\\)[ \t]?|${this.appOutputRegex.source}:[ \t]?){1}` + `^.*(?::[ \t]?|:[ \t]?|:[ \t]?|\\(NativeScript\\)[ \t]?|${this.appOutputRegex.source}:[ \t]?){1}`, ); // Used to post filter messages that slip through but are not coming from NativeScript itself. @@ -21,6 +23,11 @@ export class IOSLogFilter implements Mobile.IPlatformLogFilter { // we then use this to filter out non-NativeScript lines protected postFilterRegex: RegExp = /^\((.+)\) \[com\.apple.+\]/; + // The markers the runtime ends a chunk of a split message with, which only the + // structured logs stitch. Syslog-style output shows them escaped. + private chunkMarkerRegex: RegExp = + /(?:\\M-b\\M\^A(?:\\240|\\M-!)|[\u2060\u2061])$/; + private filterActive: boolean = true; private partialLine: string = null; @@ -29,7 +36,7 @@ export class IOSLogFilter implements Mobile.IPlatformLogFilter { public filterData( data: string, - loggingOptions: Mobile.IDeviceLogOptions = {} + loggingOptions: Mobile.IDeviceLogOptions = {}, ): string { const specifiedLogLevel = (loggingOptions.logLevel || "").toUpperCase(); @@ -86,7 +93,8 @@ export class IOSLogFilter implements Mobile.IPlatformLogFilter { // remove lading space before CONSOLE .replace(/^\s*CONSOLE/, "CONSOLE") // trim trailing spaces only to preserve indentation - .trimEnd(); + .trimEnd() + .replace(this.chunkMarkerRegex, ""); // post filtering: () check if is not "NativeScript" const postFilterMatch = this.postFilterRegex.exec(currentLine); diff --git a/test/controllers/prepare-controller.ts b/test/controllers/prepare-controller.ts index a8a901a569..336db5e766 100644 --- a/test/controllers/prepare-controller.ts +++ b/test/controllers/prepare-controller.ts @@ -151,6 +151,42 @@ describe("prepareController", () => { }); }); + describe("writeRuntimePackageJson", () => { + const writePackageJson = async (platform: string, release: boolean) => { + const injector = createTestInjector({ hasNativeChanges: false }); + let written: any; + const prepareController: PrepareController = + injector.resolve("prepareController"); + _.assign(prepareController, { + $projectConfigService: { + detectProjectConfigs: () => ({ usingNSConfig: false }), + readConfig: () => ({}), + }, + $fs: { + readJson: () => ({}), + writeJson: (filePath: string, data: any) => { + written = data; + }, + }, + }); + await prepareController.writeRuntimePackageJson( + { projectDir, projectName: "app", packageJsonData: {} }, + { platformNameLowerCase: platform, projectRoot: projectDir }, + { ...prepareData, release }, + ); + + return written; + }; + + it("asks for log chunk markers in iOS debug builds only", async () => { + assert.isTrue((await writePackageJson("ios", false)).logChunkMarkers); + assert.isUndefined((await writePackageJson("ios", true)).logChunkMarkers); + assert.isUndefined( + (await writePackageJson("android", false)).logChunkMarkers, + ); + }); + }); + describe("stopWatchers", () => { it("detaches the bundler handler of a paused watcher", async () => { const injector = createTestInjector({ hasNativeChanges: false }); diff --git a/test/services/ios-log-filter.ts b/test/services/ios-log-filter.ts index 2330e8958e..4b71158310 100644 --- a/test/services/ios-log-filter.ts +++ b/test/services/ios-log-filter.ts @@ -182,6 +182,58 @@ describe("iOSLogFilter", () => { const infoLogLevel = "INFO"; const fullLogLevel = "FULL"; + it("removes the markers of split messages, escaped or not", () => { + testInjector = createTestInjector("app"); + logFilter = testInjector.resolve(IOSLogFilter); + const header = + "\u0000Oct 29 20:20:54 iPad app(NativeScript)[1514] : "; + const chunks = [ + `${header}CONSOLE LOG: a\\M-b\\M^A\\240\n`, + `${header}CONSOLE LOG: b\\M-b\\M^A\\M-!\n`, + `${header}CONSOLE LOG: c\u2060\n`, + `${header}CONSOLE LOG: d\n`, + ]; + + const output = chunks + .map((chunk) => + logFilter.filterData(chunk, { + logLevel: infoLogLevel, + projectName: "app", + }), + ) + .join(""); + + assert.strictEqual( + output, + "CONSOLE LOG: a\nCONSOLE LOG: b\nCONSOLE LOG: c\nCONSOLE LOG: d\n", + ); + }); + + it("drops other processes' lines that have no image name, such as the kernel's", () => { + testInjector = createTestInjector("nsconsoletablet"); + logFilter = testInjector.resolve(IOSLogFilter); + const chunks = [ + '\u0000Oct 29 20:20:54 iPad nsconsoletablet(NativeScript)[1514] : CONSOLE LOG: [ "network", "internet probe -> true (status 200)" ]\n', + "\u0000Oct 29 20:20:45 iPad kernel()[0] : wlan0:com.apple.p2p.awdl0: isInfraRealtimePacketThresholdAllowed allowed:1 option:32 threshold:50\n", + "\u0000Oct 29 20:20:45 iPad kernel()[0] : wlan0:com.apple.p2p.awdl0: currentInfraTrafficType:9274 checking if realtime upgrade required\n", + ]; + + const output = chunks + .map((chunk) => + logFilter.filterData(chunk, { + logLevel: infoLogLevel, + projectName: "nsconsoletablet", + }), + ) + .filter(Boolean) + .join(""); + + assert.strictEqual( + output, + 'CONSOLE LOG: [ "network", "internet probe -> true (status 200)" ]\n', + ); + }); + describe("filterData", () => { testData.forEach((data) => { it(`returns correct data on iOS ${data.version} when data comes in chunks`, () => { @@ -211,7 +263,7 @@ describe("iOSLogFilter", () => { assert.deepStrictEqual( output, - data.infoExpectedArr.filter((item) => item !== null).join("\n") + data.infoExpectedArr.filter((item) => item !== null).join("\n"), ); }); @@ -220,7 +272,7 @@ describe("iOSLogFilter", () => { logFilter = testInjector.resolve(IOSLogFilter); const actualData = logFilter.filterData( data.originalDataArr.join("\n"), - { logLevel: fullLogLevel, projectName: data.projectName } + { logLevel: fullLogLevel, projectName: data.projectName }, ); const actualArr = actualData.split("\n").map((line) => line.trim()); const expectedArr = data.originalDataArr @@ -252,7 +304,7 @@ describe("iOSLogFilter", () => { const actualArr = actualData.split("\n").map((line) => line.trim()); assert.deepStrictEqual( actualArr, - data.simulatorExpectedArr.filter((item) => item !== null) + data.simulatorExpectedArr.filter((item) => item !== null), ); }); @@ -261,11 +313,11 @@ describe("iOSLogFilter", () => { logFilter = testInjector.resolve(IOSLogFilter); const actualData = logFilter.filterData( data.originalDataArr.join("\n"), - { logLevel: infoLogLevel, projectName: data.projectName } + { logLevel: infoLogLevel, projectName: data.projectName }, ); const actualArr = actualData.split("\n").map((line) => line.trim()); const expectedArr = data.infoExpectedArr.filter( - (item) => item !== null + (item) => item !== null, ); assert.deepStrictEqual(actualArr, expectedArr); });