Skip to content

Commit 4eadd0c

Browse files
ironsheepclaude
andcommitted
fix: Reassemble USB chunks into complete lines before logging
Raw USB chunks were logged individually, causing lines to break at arbitrary byte boundaries (mid-word) wherever the FTDI chip's 16ms latency timer flushed its buffer. Both the debug logger and headless file logger now accumulate incoming text and only write complete lines once a CR/LF boundary is confirmed or a 50ms idle timeout expires. Bump version to 0.9.21 for release. Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>
1 parent 8142c6e commit 4eadd0c

5 files changed

Lines changed: 119 additions & 20 deletions

File tree

CHANGELOG.md

Lines changed: 8 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,14 @@ All notable changes to PNut-Term-TS will be documented in this file.
55
The format is based on [Keep a Changelog](https://keepachangelog.com/en/1.0.0/),
66
and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0.html).
77

8+
## [0.9.21] - 2026-03-06
9+
10+
### Fixed
11+
12+
- **Mid-word line splits in log files** - Raw USB chunks were logged individually, causing lines to break at arbitrary byte boundaries (mid-word, mid-number) wherever the FTDI chip's 16ms latency timer flushed its buffer
13+
- Both the debug logger and headless file logger now reassemble USB chunks into complete logical lines before writing, holding partial data until a CR/LF boundary is confirmed or a 50ms idle timeout expires
14+
- Each reassembled line is individually timestamped, eliminating both mid-word splits and mid-line timestamp collisions
15+
816
## [0.9.20] - 2026-03-06
917

1018
### Fixed

package-lock.json

Lines changed: 2 additions & 2 deletions
Some generated files are not rendered by default. Learn more about customizing how changed files appear on GitHub.

package.json

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,6 +1,6 @@
11
{
22
"name": "pnut-term-ts",
3-
"version": "0.9.20",
3+
"version": "0.9.21",
44
"description": "A recreation of Chips' Debug listener but multiplatform combined with PST and downloader",
55
"keywords": [
66
"cli",

src/classes/loggerWin.ts

Lines changed: 57 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -82,6 +82,11 @@ export class LoggerWindow extends DebugWindowBase {
8282
private logFileReady: boolean = false;
8383
private rendererReady: boolean = false; // Track when renderer DOM is ready for IPC
8484

85+
// Line reassembly: accumulate partial chunks until CR/LF confirms a complete line
86+
private logLineAccumulator: string = '';
87+
private logLineFlushTimer: NodeJS.Timeout | null = null;
88+
private readonly LOG_LINE_FLUSH_TIMEOUT_MS = 50; // Flush partial lines after 50ms idle
89+
8590
// Performance warning tracking
8691
private performanceMonitor: PerformanceMonitor | null = null;
8792
private warningHistory: PerformanceWarning[] = [];
@@ -1184,24 +1189,64 @@ export class LoggerWindow extends DebugWindowBase {
11841189
}
11851190

11861191
/**
1187-
* Write message to log file (buffered for performance)
1192+
* Write message to log file with line reassembly.
1193+
* Accumulates partial chunks until CR/LF confirms a complete line,
1194+
* so each log entry corresponds to a logical line — no mid-word splits.
11881195
* RACE CONDITION FIX: Buffer messages if log file isn't ready yet
11891196
*/
11901197
private writeToLog(message: string): void {
1198+
// Accumulate text and extract complete lines (terminated by \n or \r\n)
1199+
this.logLineAccumulator += message;
1200+
1201+
// Reset idle timer on every chunk
1202+
if (this.logLineFlushTimer) {
1203+
clearTimeout(this.logLineFlushTimer);
1204+
}
1205+
1206+
// Extract and write all complete lines
1207+
let newlineIdx: number;
1208+
while ((newlineIdx = this.logLineAccumulator.indexOf('\n')) !== -1) {
1209+
const line = this.logLineAccumulator.substring(0, newlineIdx + 1);
1210+
this.logLineAccumulator = this.logLineAccumulator.substring(newlineIdx + 1);
1211+
this.writeLogEntry(line);
1212+
}
1213+
1214+
// If there's remaining text without a newline, start idle timer to flush it
1215+
if (this.logLineAccumulator.length > 0) {
1216+
this.logLineFlushTimer = setTimeout(() => this.flushLogLineAccumulator(), this.LOG_LINE_FLUSH_TIMEOUT_MS);
1217+
}
1218+
}
1219+
1220+
/**
1221+
* Flush any partial line remaining in the accumulator (on idle timeout or shutdown)
1222+
*/
1223+
private flushLogLineAccumulator(): void {
1224+
if (this.logLineFlushTimer) {
1225+
clearTimeout(this.logLineFlushTimer);
1226+
this.logLineFlushTimer = null;
1227+
}
1228+
if (this.logLineAccumulator.length > 0) {
1229+
this.writeLogEntry(this.logLineAccumulator);
1230+
this.logLineAccumulator = '';
1231+
}
1232+
}
1233+
1234+
/**
1235+
* Write a single reassembled line to the log file with timestamp.
1236+
*/
1237+
private writeLogEntry(message: string): void {
11911238
const timestamp = getFormattedDateTimeISO();
1192-
// Strip trailing CR/LF from message before logging (messages arrive with line endings from P2)
1239+
// Strip trailing CR/LF from the reassembled line
11931240
const cleanMessage = message.replace(/[\r\n]+$/, '');
1194-
// Timestamp every line individually to prevent mid-line timestamps in log output
1195-
const lines = cleanMessage.split(/\r?\n/);
1196-
const logEntry = lines.map((line) => `[${timestamp}] ${line}\n`).join('');
1241+
const logEntry = `[${timestamp}] ${cleanMessage}\n`;
11971242

11981243
if (this.logFileReady && this.logFile) {
11991244
// Log file is ready - write normally
12001245
this.writeBuffer.push(logEntry);
12011246

12021247
// Log first few writes to confirm it's working
12031248
if (this.writeBuffer.length <= 3) {
1204-
const truncated = message.length > 80 ? message.substring(0, 80) + '...' : message;
1249+
const truncated = cleanMessage.length > 80 ? cleanMessage.substring(0, 80) + '...' : cleanMessage;
12051250
this.logConsoleMessage('[DEBUG LOGGER] Added to write buffer:', truncated);
12061251
}
12071252

@@ -1211,22 +1256,21 @@ export class LoggerWindow extends DebugWindowBase {
12111256
}
12121257

12131258
// Force flush only if buffer is getting large (4KB)
1214-
// Removed the "|| this.writeBuffer.length === 1" condition that was causing every message to flush immediately
12151259
if (this.writeBuffer.join('').length > 4096) {
12161260
this.flushWriteBuffer();
12171261
}
12181262
} else {
12191263
// Log file not ready yet - buffer the message for later
12201264
this.pendingLogMessages.push(logEntry);
12211265
this.logConsoleMessage(
1222-
`[DEBUG LOGGER] 📦 Buffered message (log file not ready): ${message.substring(0, 50)}${
1223-
message.length > 50 ? '...' : ''
1266+
`[DEBUG LOGGER] Buffered message (log file not ready): ${cleanMessage.substring(0, 50)}${
1267+
cleanMessage.length > 50 ? '...' : ''
12241268
}`
12251269
);
12261270

12271271
// Limit buffer size to prevent memory issues
12281272
if (this.pendingLogMessages.length > 1000) {
1229-
console.warn('[DEBUG LOGGER] ⚠️ Pending message buffer full, dropping oldest messages');
1273+
console.warn('[DEBUG LOGGER] Pending message buffer full, dropping oldest messages');
12301274
this.pendingLogMessages.splice(0, 100); // Remove oldest 100 messages
12311275
}
12321276
}
@@ -1548,6 +1592,9 @@ export class LoggerWindow extends DebugWindowBase {
15481592
this.processBatch();
15491593
}
15501594

1595+
// Flush any partial line waiting for more data
1596+
this.flushLogLineAccumulator();
1597+
15511598
// Flush any pending writes
15521599
if (this.writeTimer) {
15531600
clearTimeout(this.writeTimer);

src/classes/shared/headlessFileLogger.ts

Lines changed: 51 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -30,6 +30,11 @@ export class HeadlessFileLogger {
3030
private readonly WRITE_INTERVAL_MS = 100; // Flush every 100ms
3131
private readonly MAX_BUFFER_SIZE = 4096; // Force flush at 4KB
3232

33+
// Line reassembly: accumulate partial USB chunks until CR/LF confirms a complete line
34+
private lineAccumulator: string = '';
35+
private lineFlushTimer: NodeJS.Timeout | null = null;
36+
private readonly LINE_FLUSH_TIMEOUT_MS = 50; // Flush partial lines after 50ms idle
37+
3338
// Callback for end-marker detection
3439
private onEndMarkerDetected: (() => void) | null = null;
3540
private endMarkers: string[] = [];
@@ -127,11 +132,11 @@ export class HeadlessFileLogger {
127132
}
128133

129134
/**
130-
* Log a message from serial data
135+
* Log a message from serial data.
136+
* Reassembles arbitrary USB chunks into complete lines before writing,
137+
* so each log entry corresponds to a logical line (CR/LF terminated).
131138
*/
132139
public logMessage(message: string): void {
133-
this.writeToLog(message);
134-
135140
// Check for end-markers using rolling buffer to handle markers split across chunks
136141
// (serial data arrives in arbitrary-sized chunks that can split marker strings)
137142
if (this.endMarkers.length > 0 && this.onEndMarkerDetected) {
@@ -140,6 +145,8 @@ export class HeadlessFileLogger {
140145
for (const marker of this.endMarkers) {
141146
if (this.markerSearchBuffer.includes(marker)) {
142147
console.log(`[HEADLESS] End marker "${marker}" detected!`);
148+
// Flush any accumulated partial line before shutdown
149+
this.flushLineAccumulator();
143150
this.logSystem(`End marker "${marker}" detected - initiating shutdown`);
144151
this.onEndMarkerDetected();
145152
return;
@@ -151,6 +158,42 @@ export class HeadlessFileLogger {
151158
this.markerSearchBuffer = this.markerSearchBuffer.slice(-(this.maxMarkerLength - 1));
152159
}
153160
}
161+
162+
// Accumulate text and extract complete lines (terminated by \n or \r\n)
163+
this.lineAccumulator += message;
164+
165+
// Reset idle timer on every chunk
166+
if (this.lineFlushTimer) {
167+
clearTimeout(this.lineFlushTimer);
168+
}
169+
170+
// Extract and write all complete lines
171+
let newlineIdx: number;
172+
while ((newlineIdx = this.lineAccumulator.indexOf('\n')) !== -1) {
173+
// Extract line including the \n
174+
let line = this.lineAccumulator.substring(0, newlineIdx + 1);
175+
this.lineAccumulator = this.lineAccumulator.substring(newlineIdx + 1);
176+
this.writeToLog(line);
177+
}
178+
179+
// If there's remaining text without a newline, start idle timer to flush it
180+
if (this.lineAccumulator.length > 0) {
181+
this.lineFlushTimer = setTimeout(() => this.flushLineAccumulator(), this.LINE_FLUSH_TIMEOUT_MS);
182+
}
183+
}
184+
185+
/**
186+
* Flush any partial line remaining in the accumulator (on idle timeout or shutdown)
187+
*/
188+
private flushLineAccumulator(): void {
189+
if (this.lineFlushTimer) {
190+
clearTimeout(this.lineFlushTimer);
191+
this.lineFlushTimer = null;
192+
}
193+
if (this.lineAccumulator.length > 0) {
194+
this.writeToLog(this.lineAccumulator);
195+
this.lineAccumulator = '';
196+
}
154197
}
155198

156199
/**
@@ -198,11 +241,9 @@ export class HeadlessFileLogger {
198241
*/
199242
private writeToLog(message: string): void {
200243
const timestamp = getFormattedDateTimeISO();
201-
// Strip trailing CR/LF from message before logging
244+
// Strip trailing CR/LF — line reassembly in logMessage() ensures single logical lines
202245
const cleanMessage = message.replace(/[\r\n]+$/, '');
203-
// Timestamp every line individually to prevent mid-line timestamps in log output
204-
const lines = cleanMessage.split(/\r?\n/);
205-
const logEntry = lines.map((line) => `[${timestamp}] ${line}\n`).join('');
246+
const logEntry = `[${timestamp}] ${cleanMessage}\n`;
206247

207248
if (this.logFileReady && this.logFile) {
208249
// Log file is ready - write normally
@@ -273,6 +314,9 @@ export class HeadlessFileLogger {
273314
* Close the log file gracefully
274315
*/
275316
public close(): void {
317+
// Flush any partial line waiting for more data
318+
this.flushLineAccumulator();
319+
276320
// Flush any remaining data
277321
this.flushWriteBuffer();
278322

0 commit comments

Comments
 (0)