Skip to content

Commit 443afaf

Browse files
author
Deyan Ginev
committed
update(cli): Improve filtering of iOS logs
1 parent e482d14 commit 443afaf

File tree

2 files changed

+140
-78
lines changed

2 files changed

+140
-78
lines changed

‎lib/services/ios-log-filter.ts

+65-44
Original file line numberDiff line numberDiff line change
@@ -1,65 +1,86 @@
11
const sourcemap = require("source-map");
22
import * as path from "path";
33
import { cache } from "../common/decorators";
4-
import * as iOSLogFilterBase from "../common/mobile/ios/ios-log-filter";
54

6-
export class IOSLogFilter extends iOSLogFilterBase.IOSLogFilter implements Mobile.IPlatformLogFilter {
7-
protected infoFilterRegex = /^.*?((?:<Notice>:)?.*?(((?:CONSOLE|JS) (?:LOG|ERROR)).*?))$/im;
5+
export class IOSLogFilter implements Mobile.IPlatformLogFilter {
6+
// Used to recognize output related to the current project
7+
// This looks for artifacts like: AppName[22432] or AppName(SomeTextHere)[23123]
8+
private appOutputRegex: RegExp = /([^\s\(\)]+)(?:\([^\s]+\))?\[[0-9]+\]/;
9+
10+
// Used to trim the passed messages to a simpler output
11+
// Example:
12+
// This: "May 24 15:54:52 Dragons-iPhone NativeScript250(NativeScript)[356] <Notice>: CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3477:36: ORIGINAL STACKTRACE:"
13+
// Becomes: CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3477:36: ORIGINAL STACKTRACE:
14+
protected infoFilterRegex = new RegExp(`^.*(?:<Notice>:|<Error>:|<Warning>:|\\(NativeScript\\)|${this.appOutputRegex.source}:){1}`);
15+
16+
private filterActive: boolean = true;
17+
private projectName: string;
818

919
private partialLine: string = null;
1020

11-
constructor($loggingLevels: Mobile.ILoggingLevels,
21+
constructor(
22+
private $loggingLevels: Mobile.ILoggingLevels,
1223
private $fs: IFileSystem,
1324
private $projectData: IProjectData) {
14-
super($loggingLevels);
25+
this.projectName = this.$projectData.projectName;
1526
}
1627

1728
public filterData(data: string, logLevel: string, pid?: string): string {
18-
data = super.filterData(data, logLevel, pid);
19-
if (pid && data && data.indexOf(`[${pid}]`) === -1) {
20-
return null;
29+
const specifiedLogLevel = (logLevel || '').toUpperCase();
30+
31+
if (specifiedLogLevel !== this.$loggingLevels.info || !data) {
32+
return data;
2133
}
2234

23-
if (data) {
24-
const skipLastLine = data[data.length - 1] !== "\n";
25-
const lines = data.split("\n");
26-
let result = "";
27-
for (let i = 0; i < lines.length; i++) {
28-
let line = lines[i];
29-
if (i === 0 && this.partialLine) {
30-
line = this.partialLine + line;
31-
this.partialLine = null;
32-
}
33-
if (line.length < 1 ||
34-
line.indexOf("SecTaskCopyDebugDescription") !== -1 ||
35-
line.indexOf("NativeScript loaded bundle") !== -1 ||
36-
(line.indexOf("assertion failed:") !== -1 && data.indexOf("libxpc.dylib") !== -1)) {
37-
continue;
38-
}
39-
// CONSOLE LOG messages comme in the following form:
40-
// <date> <domain> <app>[pid] CONSOLE LOG file:///location:row:column: <actual message goes here>
41-
// This code removes unnecessary information from log messages. The output looks like:
42-
// CONSOLE LOG file:///location:row:column: <actual message goes here>
43-
if (pid) {
44-
if (line.indexOf(`[${pid}]: `) !== -1) {
45-
const pidRegex = new RegExp(`^.*\\[${pid}\\]:\\s(?:\\(NativeScript\\)\\s)?`);
46-
line = line.replace(pidRegex, "").trim();
47-
this.getOriginalFileLocation(line);
48-
result += this.getOriginalFileLocation(line) + "\n";
49-
}
35+
const chunkLines = data.split('\n');
36+
const skipLastLine = chunkLines.length > 0 ? data[data.length - 1] !== "\n" : false;
37+
let output = "";
38+
for (let i = 0; i < chunkLines.length; i++) {
39+
let currentLine = chunkLines[i];
5040

51-
continue;
52-
}
53-
if (skipLastLine && i === lines.length - 1 && lines.length > 1) {
54-
this.partialLine = line;
55-
} else {
56-
result += this.getOriginalFileLocation(line) + "\n";
57-
}
41+
if (this.partialLine) {
42+
currentLine = this.partialLine + currentLine;
43+
this.partialLine = undefined;
44+
}
45+
46+
if (i === chunkLines.length - 1 && skipLastLine) {
47+
this.partialLine = currentLine;
48+
break;
49+
}
50+
51+
// Legacy filter moved to preFilter
52+
if (this.preFilter(data, currentLine)) {
53+
continue;
54+
}
55+
56+
const matchResult = this.appOutputRegex.exec(currentLine);
57+
58+
if (matchResult && matchResult.length > 1) {
59+
// Check if the name of the app equals the name of the CLI project and turn on the filter if not.
60+
this.filterActive = matchResult[1] !== this.projectName;
61+
}
62+
63+
if (this.filterActive) {
64+
continue;
5865
}
59-
return result;
66+
67+
const filteredLineInfo = currentLine.match(this.infoFilterRegex);
68+
if (filteredLineInfo && filteredLineInfo.length > 0) {
69+
currentLine = currentLine.replace(filteredLineInfo[0], "");
70+
}
71+
72+
currentLine = currentLine.trim();
73+
output += this.getOriginalFileLocation(currentLine) + '\n';
6074
}
6175

62-
return data;
76+
return output.length === 0 ? null : output;
77+
}
78+
79+
private preFilter(data:string, currentLine: string): boolean {
80+
return currentLine.length < 1 ||
81+
currentLine.indexOf("SecTaskCopyDebugDescription") !== -1 ||
82+
currentLine.indexOf("NativeScript loaded bundle") !== -1 ||
83+
(currentLine.indexOf("assertion failed:") !== -1 && data.indexOf("libxpc.dylib") !== -1);
6384
}
6485

6586
private getOriginalFileLocation(data: string): string {

‎test/services/ios-log-filter.ts

+75-34
Original file line numberDiff line numberDiff line change
@@ -3,15 +3,16 @@ import { Yok } from "../../lib/common/yok";
33
import { LoggingLevels } from "../../lib/common/mobile/logging-levels";
44
import * as assert from "assert";
55

6-
function createTestInjector(): IInjector {
6+
function createTestInjector(projectName: string): IInjector {
77
const testInjector = new Yok();
88
testInjector.register("loggingLevels", LoggingLevels);
99
testInjector.register("fs", {
1010
exists: () => false
1111
});
1212
testInjector.register("projectData", {
1313
initializeProjectData: () => { /* empty */ },
14-
projectDir: "test"
14+
projectDir: "test",
15+
projectName: projectName
1516
});
1617

1718
return testInjector;
@@ -24,6 +25,7 @@ describe("iOSLogFilter", () => {
2425
const testData = [
2526
{
2627
version: 9,
28+
projectName: "NativeScript250",
2729
originalDataArr: [
2830
"May 24 15:54:38 Dragons-iPhone backboardd(BaseBoard)[62] <Error>: Unable to bootstrap_look_up port with name .gsEvents: unknown error code (1102)",
2931
"May 24 15:54:51 Dragons-iPhone locationd[67] <Notice>: Client com.apple.springboard disconnected",
@@ -45,9 +47,10 @@ describe("iOSLogFilter", () => {
4547
null,
4648
null,
4749
"CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3472:32: EXCEPTION: Uncaught (in promise): Error: CUSTOM EXCEPTION",
48-
"CONSOLE LOG file:///app/home/home-view-model.js:6:20: CUSTOM CONSOLE LOG",
50+
null,
4951
""
5052
],
53+
simProjectName: "TestApp",
5154
simulator: [
5255
"Aug 22 10:59:20 MCSOFAPPBLD TestApp[52946]: CONSOLE LOG file:///app/home/home-view-model.js:6:20: CUSTOM CONSOLE LOG",
5356
"Aug 22 10:59:20 MCSOFAPPBLD TestApp[52946]: CONSOLE DEBUG file:///app/home/home-view-model.js:6:20: CUSTOM CONSOLE LOG",
@@ -60,6 +63,7 @@ describe("iOSLogFilter", () => {
6063
]
6164
}, {
6265
version: 10,
66+
projectName: "NativeScript250",
6367
originalDataArr: [
6468
"May 24 15:54:52 Dragons-iPhone apsd(PersistentConnection)[90] <Notice>: 2017-05-24 15:54:52 +0300 apsd[90]: <PCDispatchTimer: 0x156ad240> performing call back",
6569
"May 24 15:54:52 Dragons-iPhone NativeScript250(NativeScript)[356] <Notice>: CONSOLE LOG file:///app/modules/homeView/homeView.component.js:13:24: CUSTOM CONSOLE LOG",
@@ -86,20 +90,21 @@ describe("iOSLogFilter", () => {
8690
"CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3472:32: EXCEPTION: Uncaught (in promise): Error: CUSTOM EXCEPTION",
8791
"CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3477:36: ORIGINAL STACKTRACE:",
8892
"CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3478:36: resolvePromise@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:416:40",
93+
"resolvePromise@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:401:31",
94+
"file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:449:31",
95+
"invokeTask@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:223:42",
96+
"onInvokeTask@file:///app/tns_modules/@angular/core/bundles/core.umd.js:4382:51",
97+
"invokeTask@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:222:54",
98+
"runTask@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:123:57",
99+
"drainMicroTaskQueue@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:355:42",
100+
"promiseReactionJob@[native code]",
101+
"UIApplicationMain@[native code]",
102+
"start@file:///app/tns_modules/tns-core-modules/application/application.js:251:26",
103+
"bootstrapApp@file:///app/tns_module",
89104
null,
90-
null,
91-
null,
92-
null,
93-
null,
94-
null,
95-
null,
96-
null,
97-
null,
98-
null,
99-
null,
100-
"CONSOLE LOG file:///app/home/home-view-model.js:6:20: CUSTOM CONSOLE LOG",
101105
""
102106
],
107+
simProjectName: "TestApp",
103108
simulator: [
104109
"Aug 22 10:59:20 MCSOFAPPBLD TestApp[52946]: CONSOLE LOG file:///app/home/home-view-model.js:6:20: CUSTOM CONSOLE LOG",
105110
"Aug 22 10:59:20 MCSOFAPPBLD TestApp[52946]: CONSOLE DEBUG file:///app/home/home-view-model.js:6:20: CUSTOM CONSOLE LOG",
@@ -113,6 +118,7 @@ describe("iOSLogFilter", () => {
113118
},
114119
{
115120
version: 11,
121+
projectName: "NativeScript250",
116122
originalDataArr: [
117123
"May 24 15:54:52 Dragons-iPhone apsd(PersistentConnection)[90] <Notice>: 2017-05-24 15:54:52 +0300 apsd[90]: <PCDispatchTimer: 0x156ad240> performing call back",
118124
"May 24 15:54:52 Dragons-iPhone NativeScript250(NativeScript)[356] <Notice>: CONSOLE LOG file:///app/modules/homeView/homeView.component.js:13:24: CUSTOM CONSOLE LOG",
@@ -139,20 +145,21 @@ describe("iOSLogFilter", () => {
139145
"CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3472:32: EXCEPTION: Uncaught (in promise): Error: CUSTOM EXCEPTION",
140146
"CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3477:36: ORIGINAL STACKTRACE:",
141147
"CONSOLE ERROR file:///app/tns_modules/@angular/core/bundles/core.umd.js:3478:36: resolvePromise@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:416:40",
148+
"resolvePromise@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:401:31",
149+
"file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:449:31",
150+
"invokeTask@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:223:42",
151+
"onInvokeTask@file:///app/tns_modules/@angular/core/bundles/core.umd.js:4382:51",
152+
"invokeTask@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:222:54",
153+
"runTask@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:123:57",
154+
"drainMicroTaskQueue@file:///app/tns_modules/nativescript-angular/zone-js/dist/zone-nativescript.js:355:42",
155+
"promiseReactionJob@[native code]",
156+
"UIApplicationMain@[native code]",
157+
"start@file:///app/tns_modules/tns-core-modules/application/application.js:251:26",
158+
"bootstrapApp@file:///app/tns_module",
142159
null,
143-
null,
144-
null,
145-
null,
146-
null,
147-
null,
148-
null,
149-
null,
150-
null,
151-
null,
152-
null,
153-
"CONSOLE LOG file:///app/home/home-view-model.js:6:20: CUSTOM CONSOLE LOG",
154160
""
155161
],
162+
simProjectName: "cliapp",
156163
simulator: [
157164
"2017-10-09 13:34:38.527844+0300 localhost cliapp[52946]: (NativeScript) CONSOLE LOG file:///app/main-view-model.js:18:20: Test Console",
158165
"2017-10-09 13:34:38.527844+0300 localhost cliapp[52946]: (NativeScript) CONSOLE DEBUG file:///app/main-view-model.js:18:20: Test Console",
@@ -168,45 +175,79 @@ describe("iOSLogFilter", () => {
168175
const infoLogLevel = "INFO";
169176
const fullLogLevel = "FULL";
170177

171-
beforeEach(() => {
172-
testInjector = createTestInjector();
173-
logFilter = testInjector.resolve(IOSLogFilter);
174-
});
175-
176178
describe("filterData", () => {
177179
testData.forEach(data => {
180+
181+
it(`returns correct data on iOS ${data.version} when data comes in chunks`, () => {
182+
testInjector = createTestInjector(data.projectName);
183+
logFilter = testInjector.resolve(IOSLogFilter);
184+
185+
let currentStart = 0;
186+
let maxRange = 50;
187+
let output = ""
188+
let input = data.originalDataArr.join("\n");
189+
while (true) {
190+
let currentRange = Math.floor(Math.random() * maxRange);
191+
let currentFilterInput = input.substr(currentStart, currentRange);
192+
let tempOutput = logFilter.filterData(currentFilterInput, infoLogLevel, null);
193+
if (tempOutput !== null) {
194+
output += tempOutput;
195+
}
196+
currentStart += currentRange;
197+
if (currentStart == input.length) {
198+
break;
199+
}
200+
currentStart = Math.min(currentStart, input.length);
201+
}
202+
203+
assert.deepEqual(output, data.infoExpectedArr.filter(item => item !== null).join("\n"));
204+
});
205+
178206
it(`returns correct data when logLevel is ${fullLogLevel} on iOS ${data.version} and all data is passed at once`, () => {
207+
testInjector = createTestInjector(data.projectName);
208+
logFilter = testInjector.resolve(IOSLogFilter);
179209
const actualData = logFilter.filterData(data.originalDataArr.join("\n"), fullLogLevel, null);
180210
const actualArr = actualData.split("\n").map(line => line.trim());
181-
const expectedArr = data.originalDataArr.map(line => line.trim());
211+
const expectedArr = data.originalDataArr.map(line => line.trim()).filter(item => item !== null);
182212
assert.deepEqual(actualArr, expectedArr);
183213
});
184214

185215
it(`returns correct data when logLevel is ${fullLogLevel} on iOS ${data.version} and data is passed one line at a time`, () => {
186216
data.originalDataArr.forEach(line => {
217+
testInjector = createTestInjector(data.projectName);
218+
logFilter = testInjector.resolve(IOSLogFilter);
187219
const actualData = logFilter.filterData(line, fullLogLevel, null);
188220
assert.deepEqual(actualData.trim(), line.trim());
189221
});
190222
});
191223

192224
it(`parses data incorrectly when logLevel is ${infoLogLevel} on iOS ${data.version} and all data is passed at once with pid(simulator)`, () => {
225+
testInjector = createTestInjector(data.simProjectName);
226+
logFilter = testInjector.resolve(IOSLogFilter);
193227
const actualData = logFilter.filterData(data.simulator.join("\n"), infoLogLevel, pid);
194228
const actualArr = actualData.split("\n").map(line => line.trim());
195-
assert.deepEqual(actualArr, data.simulatorExpectedArr);
229+
assert.deepEqual(actualArr, data.simulatorExpectedArr.filter(item => item !== null));
196230
});
197231

198232
it(`parses data incorrectly when logLevel is ${infoLogLevel} on iOS ${data.version} and all data is passed at once and pid is available`, () => {
233+
testInjector = createTestInjector(data.projectName);
234+
logFilter = testInjector.resolve(IOSLogFilter);
199235
const actualData = logFilter.filterData(data.originalDataArr.join("\n"), infoLogLevel, null);
200236
const actualArr = actualData.split("\n").map(line => line.trim());
201-
const expectedArr = ["CONSOLE LOG file:///app/modules/homeView/homeView.component.js:13:24: CUSTOM CONSOLE LOG", ""];
237+
const expectedArr = data.infoExpectedArr.filter(item => item !== null);
202238
assert.deepEqual(actualArr, expectedArr);
203239
});
204240

205241
it(`returns correct data when logLevel is ${infoLogLevel} on iOS ${data.version} and data is passed one line at a time`, () => {
242+
testInjector = createTestInjector(data.projectName);
243+
logFilter = testInjector.resolve(IOSLogFilter);
206244
data.originalDataArr.forEach((line, index) => {
245+
if (line.length > 0) {
246+
line += "\n"
247+
}
207248
const actualData = logFilter.filterData(line, infoLogLevel, null);
208249
const expectedData = data.infoExpectedArr[index];
209-
assert.deepEqual(actualData && actualData.trim(), expectedData && expectedData);
250+
assert.equal(actualData && actualData.trim(), expectedData);
210251
});
211252
});
212253
});

0 commit comments

Comments
 (0)