Skip to content

Commit e9a3bd7

Browse files
edusperoniedusperoni
committed
feat(ios): reassemble split app logs from the runtime's piece headers
Asks the runtime for log format 1 through the logFormat key of the app's package.json, in place of logChunkMarkers. In format 1, each piece of a message the runtime had to split is logged as "[ns <id> <index>/<count>] <piece>", where the pieces are consecutive slices of the message. The stitcher now collects pieces by process and message id, prints the message as soon as its last piece arrives, and after 500 ms prints what it has with "<…lost…>" where pieces never arrived. A message can no longer be joined onto another one whose last piece os_log dropped. Pieces are joined before the entry is turned into text, so the repeated console prefix no longer has to be stripped. The syslog fallback, which doesn't reassemble, removes the headers and shows the pieces as lines.
1 parent 8783785 commit e9a3bd7

10 files changed

Lines changed: 213 additions & 120 deletions

File tree

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

Lines changed: 15 additions & 14 deletions
Original file line numberDiff line numberDiff line change
@@ -39,27 +39,28 @@ export class DeviceLogEmitter extends DeviceLogProviderBase {
3939
platform: string,
4040
deviceIdentifier: string,
4141
): void {
42-
const loggingOptions = this.getDeviceLogOptionsForDevice(deviceIdentifier);
43-
const text = getIOSLogEntryText(entry, {
44-
processName: loggingOptions && loggingOptions.projectName,
45-
...getIOSLogScope(
46-
this.$logger.getLevel(),
47-
loggingOptions?.logLevel?.toUpperCase() === this.$loggingLevels.full,
48-
),
49-
});
50-
if (text) {
51-
this.stitchIOSLogEntry(entry, text, deviceIdentifier, (message) =>
42+
this.stitchIOSLogEntry(entry, deviceIdentifier, (completeEntry) => {
43+
const loggingOptions =
44+
this.getDeviceLogOptionsForDevice(deviceIdentifier);
45+
const text = getIOSLogEntryText(completeEntry, {
46+
processName: loggingOptions && loggingOptions.projectName,
47+
...getIOSLogScope(
48+
this.$logger.getLevel(),
49+
loggingOptions?.logLevel?.toUpperCase() === this.$loggingLevels.full,
50+
),
51+
});
52+
if (text) {
5253
this.emitData(
5354
this.$logSourceMapService.replaceWithOriginalFileLocations(
5455
platform,
55-
message + "\n",
56+
text + "\n",
5657
loggingOptions,
5758
),
5859
platform,
5960
deviceIdentifier,
60-
),
61-
);
62-
}
61+
);
62+
}
63+
});
6364
}
6465

6566
private emitData(

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

Lines changed: 4 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -49,18 +49,17 @@ export abstract class DeviceLogProviderBase
4949

5050
protected stitchIOSLogEntry(
5151
entry: Mobile.IiOSLogEntry,
52-
text: string,
5352
deviceIdentifier: string,
54-
emit: (text: string) => void,
53+
emit: (entry: Mobile.IiOSLogEntry) => void,
5554
): void {
5655
if (!isIOSRuntimeLogEntry(entry)) {
57-
emit(text);
56+
emit(entry);
5857
return;
5958
}
6059

6160
this.iOSLogChunkStitcher.add(
62-
`${deviceIdentifier}:${entry.pid}:${entry.thread}`,
63-
text,
61+
`${deviceIdentifier}:${entry.pid}`,
62+
entry,
6463
emit,
6564
);
6665
}

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

Lines changed: 13 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -36,19 +36,20 @@ export class DeviceLogProvider extends DeviceLogProviderBase {
3636
platform: string,
3737
deviceIdentifier: string,
3838
): void {
39-
const loggingOptions = this.getDeviceLogOptionsForDevice(deviceIdentifier);
40-
const text = getIOSLogEntryText(entry, {
41-
processName: loggingOptions.projectName,
42-
...getIOSLogScope(
43-
this.$logger.getLevel(),
44-
loggingOptions.logLevel?.toUpperCase() === this.$loggingLevels.full,
45-
),
39+
this.stitchIOSLogEntry(entry, deviceIdentifier, (completeEntry) => {
40+
const loggingOptions =
41+
this.getDeviceLogOptionsForDevice(deviceIdentifier);
42+
const text = getIOSLogEntryText(completeEntry, {
43+
processName: loggingOptions.projectName,
44+
...getIOSLogScope(
45+
this.$logger.getLevel(),
46+
loggingOptions.logLevel?.toUpperCase() === this.$loggingLevels.full,
47+
),
48+
});
49+
if (text) {
50+
this.printData(text + "\n", text, platform, deviceIdentifier);
51+
}
4652
});
47-
if (text) {
48-
this.stitchIOSLogEntry(entry, text, deviceIdentifier, (message) =>
49-
this.printData(message + "\n", message, platform, deviceIdentifier),
50-
);
51-
}
5253
}
5354

5455
private printData(

‎lib/common/mobile/ios/ios-log-entry.ts‎

Lines changed: 76 additions & 39 deletions
Original file line numberDiff line numberDiff line change
@@ -74,20 +74,31 @@ export function getIOSLogEntryText(
7474
return `${imageName}: ${entry.message}`;
7575
}
7676

77-
// The runtime ends a chunk of a split message with one of these when the CLI
78-
// asks for it, through the logChunkMarkers key of the app's package.json.
79-
const CHUNK_JOIN_MARKER = "\u2060";
80-
const CHUNK_LINE_MARKER = "\u2061";
81-
const CONSOLE_PREFIX = /^CONSOLE [A-Z]+: /;
77+
/**
78+
* The newest log format the CLI understands, written to the logFormat key of
79+
* the app's package.json. The runtime uses the lower of this and its own.
80+
*/
81+
export const IOS_LOG_FORMAT = 1;
82+
83+
// Format 1: each piece of a message the runtime had to split is logged as
84+
// "[ns <id> <index>/<count>] <piece>". The id is unique per message in the
85+
// process, and the pieces are consecutive slices of the message. A piece of
86+
// nothing but whitespace arrives as the bare header: the unified log strips
87+
// whitespace from the end of every entry.
88+
export const IOS_LOG_PIECE_HEADER = /^\[ns ([0-9a-f]+) (\d+)\/(\d+)\](?: |$)/;
8289

83-
// Long enough to ride out a backlog of chunks, while the rest of a message that
84-
// never arrives, because the app crashed, still gets printed.
85-
const CHUNK_WAIT_MS = 500;
90+
// Where a piece that never arrived belongs; os_log marks truncated text alike.
91+
const LOST_PIECE = "<…lost…>";
92+
93+
// Long enough to ride out a backlog of pieces, while a message whose pieces
94+
// never all arrive, because os_log dropped some or the app crashed, still gets
95+
// printed.
96+
const PIECE_WAIT_MS = 500;
8697

8798
interface IPendingLogMessage {
88-
text: string;
89-
prefix: string;
90-
separator: string;
99+
entry: Mobile.IiOSLogEntry;
100+
pieces: string[];
101+
received: number;
91102
timer: NodeJS.Timeout;
92103
}
93104

@@ -98,40 +109,66 @@ export class IOSLogChunkStitcher {
98109
private pending = new Map<string, IPendingLogMessage>();
99110

100111
/**
101-
* @param key Identifies the logging thread: chunks from different threads can interleave.
102-
* @param emit Called with the complete message.
112+
* @param source Identifies the logging process, whose message ids are unique.
113+
* @param emit Called with each complete entry, in place of its pieces.
103114
*/
104-
public add(key: string, text: string, emit: (text: string) => void): void {
105-
const marker = text[text.length - 1];
106-
const continues =
107-
marker === CHUNK_JOIN_MARKER || marker === CHUNK_LINE_MARKER;
108-
const chunk = continues ? text.slice(0, -1) : text;
109-
110-
const message = this.pending.get(key) ?? {
111-
text: "",
112-
prefix: chunk.match(CONSOLE_PREFIX)?.[0] ?? "",
113-
separator: "",
114-
timer: null,
115-
};
116-
clearTimeout(message.timer);
117-
message.text +=
118-
message.separator +
119-
(message.text && chunk.startsWith(message.prefix)
120-
? chunk.slice(message.prefix.length)
121-
: chunk);
115+
public add(
116+
source: string,
117+
entry: Mobile.IiOSLogEntry,
118+
emit: (entry: Mobile.IiOSLogEntry) => void,
119+
): void {
120+
const header = (entry.message || "").match(IOS_LOG_PIECE_HEADER);
121+
const index = header ? Number(header[2]) - 1 : -1;
122+
const count = header ? Number(header[3]) : 0;
123+
if (!header || index < 0 || index >= count) {
124+
emit(entry);
125+
return;
126+
}
122127

123-
if (!continues) {
128+
const key = `${source}:${header[1]}`;
129+
let message = this.pending.get(key);
130+
if (!message || message.pieces.length !== count) {
131+
message = {
132+
entry,
133+
pieces: new Array(count),
134+
received: 0,
135+
timer: null,
136+
};
137+
this.pending.set(key, message);
138+
}
139+
if (message.pieces[index] === undefined) {
140+
message.pieces[index] = entry.message.slice(header[0].length);
141+
message.received++;
142+
}
143+
if (index === 0) {
144+
message.entry = entry;
145+
}
146+
147+
clearTimeout(message.timer);
148+
const finish = () => {
124149
this.pending.delete(key);
125-
emit(message.text);
150+
emit({ ...message.entry, message: joinPieces(message) });
151+
};
152+
if (message.received === count) {
153+
finish();
126154
return;
127155
}
128156

129-
message.separator = marker === CHUNK_LINE_MARKER ? "\n" : "";
130-
message.timer = setTimeout(() => {
131-
this.pending.delete(key);
132-
emit(message.text);
133-
}, CHUNK_WAIT_MS);
157+
message.timer = setTimeout(finish, PIECE_WAIT_MS);
134158
message.timer.unref();
135-
this.pending.set(key, message);
136159
}
137160
}
161+
162+
function joinPieces(message: IPendingLogMessage): string {
163+
let text = "";
164+
for (let i = 0; i < message.pieces.length; i++) {
165+
if (message.pieces[i] === undefined) {
166+
if (!text.endsWith(LOST_PIECE)) {
167+
text += LOST_PIECE;
168+
}
169+
continue;
170+
}
171+
text += message.pieces[i];
172+
}
173+
return text;
174+
}

‎lib/common/test/unit-tests/mobile/device-log-provider.ts‎

Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -1693,5 +1693,28 @@ at promiseReactionJob\n`,
16931693

16941694
assertData(logger.output, "CONSOLE LOG: hello\n");
16951695
});
1696+
1697+
it("prints a split message once, when all of its pieces are in", () => {
1698+
deviceLogProvider.setProjectNameForDevice(structuredDevice, "app");
1699+
const piece = (message: string) =>
1700+
deviceLogProvider.logEntry(
1701+
{
1702+
pid: 1,
1703+
thread: 2,
1704+
process: `${appDir}/app`,
1705+
image: `${appDir}/Frameworks/NativeScript.framework/NativeScript`,
1706+
level: "notice",
1707+
message,
1708+
},
1709+
"iOS",
1710+
structuredDevice,
1711+
);
1712+
1713+
piece("[ns 3 1/2] CONSOLE LOG: first");
1714+
assertData(logger.output, "");
1715+
piece("[ns 3 2/2] \nsecond");
1716+
1717+
assertData(logger.output, "CONSOLE LOG: first\nsecond\n");
1718+
});
16961719
});
16971720
});

‎lib/common/test/unit-tests/mobile/ios-log-entry.ts‎

Lines changed: 66 additions & 33 deletions
Original file line numberDiff line numberDiff line change
@@ -127,13 +127,15 @@ describe("getIOSLogScope", () => {
127127
});
128128

129129
describe("IOSLogChunkStitcher", () => {
130-
const JOIN = "\u2060";
131-
const LINE = "\u2061";
132130
let stitcher: IOSLogChunkStitcher;
133131
let messages: string[];
134132
let clock: sinon.SinonFakeTimers;
135-
const add = (text: string, key = "thread") =>
136-
stitcher.add(key, text, (message) => messages.push(message));
133+
const add = (message: string, source = "process") =>
134+
stitcher.add(
135+
source,
136+
{ process: "app", image: "NativeScript", level: "default", message },
137+
(entry) => messages.push(entry.message),
138+
);
137139

138140
beforeEach(() => {
139141
clock = sinon.useFakeTimers();
@@ -150,51 +152,82 @@ describe("IOSLogChunkStitcher", () => {
150152
assert.deepEqual(messages, ["CONSOLE LOG: hello"]);
151153
});
152154

153-
it("rejoins chunks without the repeated prefix", () => {
154-
add(`CONSOLE LOG: {"a":${JOIN}`);
155-
add(`CONSOLE LOG: 1,"b":${JOIN}`);
155+
it("joins the pieces of a message as they are", () => {
156+
add('[ns 1f 1/3] CONSOLE LOG: {"a":');
157+
add('[ns 1f 2/3] 1,"b":');
156158
assert.isEmpty(messages);
157-
add("CONSOLE LOG: 2}");
159+
add("[ns 1f 3/3] 2}");
158160
assert.deepEqual(messages, ['CONSOLE LOG: {"a":1,"b":2}']);
159161
});
160162

161-
it("restores the line break a chunk was cut at", () => {
162-
add(`CONSOLE ERROR: first${LINE}`);
163-
add("CONSOLE ERROR: second");
164-
assert.deepEqual(messages, ["CONSOLE ERROR: first\nsecond"]);
165-
});
166-
167-
it("rejoins messages that have no prefix", () => {
168-
add(`Assertion failed: a${JOIN}`);
169-
add("b");
170-
assert.deepEqual(messages, ["Assertion failed: ab"]);
163+
it("keeps the whitespace a piece starts with", () => {
164+
add("[ns 2 1/3] CONSOLE ERROR: first");
165+
add("[ns 2 2/3] \nsecond");
166+
add("[ns 2 3/3] third");
167+
assert.deepEqual(messages, ["CONSOLE ERROR: first \nsecond third"]);
171168
});
172169

173-
it("keeps a chunk's own text when it only looks like a prefix", () => {
174-
add(`CONSOLE LOG: a${JOIN}`);
175-
add("CONSOLE ERROR: b");
176-
assert.deepEqual(messages, ["CONSOLE LOG: aCONSOLE ERROR: b"]);
170+
it("takes a bare header for a piece of nothing but whitespace", () => {
171+
add("[ns 9 1/3] CONSOLE LOG: a");
172+
add("[ns 9 2/3]");
173+
add("[ns 9 3/3] b");
174+
assert.deepEqual(messages, ["CONSOLE LOG: a b"]);
177175
});
178176

179-
it("keeps interleaved threads apart", () => {
180-
add(`CONSOLE LOG: a1${JOIN}`, "a");
181-
add(`CONSOLE LOG: b1${JOIN}`, "b");
182-
add("CONSOLE LOG: other", "c");
183-
add("CONSOLE LOG: a2", "a");
184-
add("CONSOLE LOG: b2", "b");
177+
it("keeps interleaved messages apart by id", () => {
178+
add("[ns a 1/2] CONSOLE LOG: a1");
179+
add("[ns b 1/2] CONSOLE LOG: b1");
180+
add("CONSOLE LOG: other");
181+
add("[ns a 2/2] a2");
182+
add("[ns b 2/2] b2");
185183
assert.deepEqual(messages, [
186184
"CONSOLE LOG: other",
187185
"CONSOLE LOG: a1a2",
188186
"CONSOLE LOG: b1b2",
189187
]);
190188
});
191189

192-
it("prints what it has when the rest never arrives", () => {
193-
add(`CONSOLE LOG: a${JOIN}`);
190+
it("keeps the same id from different processes apart", () => {
191+
add("[ns 1 1/2] CONSOLE LOG: old", "launch-1");
192+
add("[ns 1 1/2] CONSOLE LOG: new", "launch-2");
193+
add("[ns 1 2/2] !", "launch-2");
194+
assert.deepEqual(messages, ["CONSOLE LOG: new!"]);
195+
});
196+
197+
it("never joins the next message onto one whose last piece was lost", () => {
198+
add("[ns 5 1/3] CONSOLE LOG: AAAA");
199+
add("[ns 5 2/3] aaaa");
200+
add("CONSOLE ERROR: B failed");
201+
assert.deepEqual(messages, ["CONSOLE ERROR: B failed"]);
202+
194203
clock.tick(500);
195-
assert.deepEqual(messages, ["CONSOLE LOG: a"]);
204+
assert.deepEqual(messages, [
205+
"CONSOLE ERROR: B failed",
206+
"CONSOLE LOG: AAAAaaaa<…lost…>",
207+
]);
208+
});
196209

197-
add("CONSOLE LOG: unrelated");
198-
assert.deepEqual(messages, ["CONSOLE LOG: a", "CONSOLE LOG: unrelated"]);
210+
it("marks where a lost piece belongs", () => {
211+
add("[ns 6 1/4] CONSOLE LOG: one\n");
212+
add("[ns 6 4/4] four");
213+
clock.tick(500);
214+
assert.deepEqual(messages, ["CONSOLE LOG: one\n<…lost…>four"]);
215+
});
216+
217+
it("prints what it has when the rest never arrives", () => {
218+
add("[ns 7 2/2] tail");
219+
clock.tick(499);
220+
assert.isEmpty(messages);
221+
clock.tick(1);
222+
assert.deepEqual(messages, ["<…lost…>tail"]);
223+
});
224+
225+
it("passes through text that only looks like a header", () => {
226+
add("[ns 8 3/2] CONSOLE LOG: x");
227+
add("[ns zz 1/2] CONSOLE LOG: y");
228+
assert.deepEqual(messages, [
229+
"[ns 8 3/2] CONSOLE LOG: x",
230+
"[ns zz 1/2] CONSOLE LOG: y",
231+
]);
199232
});
200233
});

0 commit comments

Comments
 (0)