From 8783785a678effd1cf3b89ef95f59a4d6bfc7f83 Mon Sep 17 00:00:00 2001 From: Igor Randjelovic Date: Fri, 30 Oct 2026 17:23:48 +0100 Subject: [PATCH] feat(ios): structured app logs that follow relaunches Devices stream com.apple.os_trace_relay and simulators use log stream, both selected by executable name, so logs survive closing and reopening the app. --log picks the scope: JS output by default, the app's native logs without debug entries with debug, everything with trace or all. Without a new enough ios-device-lib, devices fall back to the syslog relay. Debug builds ask the runtime for chunk markers through logChunkMarkers in the app's package.json, and the CLI stitches split messages back together per process and thread. --- docs/man_pages/project/testing/run-ios.md | 1 + lib/common/constants.ts | 7 +- lib/common/definitions/mobile.d.ts | 45 ++++ lib/common/mobile/device-log-emitter.ts | 52 +++- lib/common/mobile/device-log-provider-base.ts | 61 +++-- lib/common/mobile/device-log-provider.ts | 36 ++- .../ios/device/ios-device-operations.ts | 37 ++- lib/common/mobile/ios/device/ios-device.ts | 103 ++++++-- lib/common/mobile/ios/ios-log-entry.ts | 137 +++++++++++ lib/common/mobile/ios/ios-log-filter.ts | 28 --- .../simulator/ios-simulator-log-provider.ts | 105 ++++++-- lib/common/test/unit-tests/ios-log-filter.ts | 224 ------------------ .../unit-tests/mobile/device-log-provider.ts | 23 ++ .../test/unit-tests/mobile/ios-log-entry.ts | 200 ++++++++++++++++ lib/common/test/unit-tests/stubs.ts | 12 + lib/controllers/prepare-controller.ts | 11 +- lib/services/ios-log-filter.ts | 18 +- test/controllers/prepare-controller.ts | 36 +++ test/services/ios-log-filter.ts | 62 ++++- 19 files changed, 876 insertions(+), 322 deletions(-) create mode 100644 lib/common/mobile/ios/ios-log-entry.ts delete mode 100644 lib/common/mobile/ios/ios-log-filter.ts delete mode 100644 lib/common/test/unit-tests/ios-log-filter.ts create mode 100644 lib/common/test/unit-tests/mobile/ios-log-entry.ts 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); });