From abb9c79b11e132608b0ca23294d74b041b94a987 Mon Sep 17 00:00:00 2001 From: Christopher Dwyer-Perkins Date: Mon, 13 Jan 2025 12:01:26 -0400 Subject: [PATCH] Better handling of split log messages (#206) * Fixed some issues with how we where dealing with partal log messages * Update src/util.spec.ts * Fixed failing tests * code clean up in sendLogOutput --------- Co-authored-by: Bronley Plumb --- src/adapters/DebugProtocolAdapter.ts | 25 ++++++------ src/adapters/TelnetAdapter.ts | 12 +++++- .../client/DebugProtocolClient.spec.ts | 4 +- .../client/DebugProtocolClient.ts | 19 ++++----- src/debugSession/BrightScriptDebugSession.ts | 7 +++- src/util.spec.ts | 39 +++++++++++++++++++ src/util.ts | 18 +++++++++ 7 files changed, 93 insertions(+), 31 deletions(-) diff --git a/src/adapters/DebugProtocolAdapter.ts b/src/adapters/DebugProtocolAdapter.ts index 916ccb81..c2b9dc09 100644 --- a/src/adapters/DebugProtocolAdapter.ts +++ b/src/adapters/DebugProtocolAdapter.ts @@ -409,21 +409,18 @@ export class DebugProtocolAdapter { this.compileClient.on('data', (buffer) => { let responseText = buffer.toString(); this.logger.info('CompileClient received data', { responseText }); - if (!responseText.endsWith('\n')) { - this.logger.debug('Buffer was split'); - // buffer was split, save the partial line - lastPartialLine += responseText; - } else { - if (lastPartialLine) { - this.logger.debug('Previous response was split, so merging last response with this one', { lastPartialLine, responseText }); - // there was leftover lines, join the partial lines back together - responseText = lastPartialLine + responseText; - lastPartialLine = ''; - } + + let logResult = util.handleLogFragments(lastPartialLine, buffer.toString()); + + // Save any remaining partial line for the next event + lastPartialLine = logResult.remaining; + if (logResult.completed) { // Emit the completed io string. - this.findWaitForDebuggerPrompt(responseText.trim()); - this.compileErrorProcessor.processUnhandledLines(responseText.trim()); - this.emit('unhandled-console-output', responseText.trim()); + this.findWaitForDebuggerPrompt(logResult.completed); + this.compileErrorProcessor.processUnhandledLines(logResult.completed); + this.emit('unhandled-console-output', logResult.completed); + } else { + this.logger.debug('Buffer was split', lastPartialLine); } }); diff --git a/src/adapters/TelnetAdapter.ts b/src/adapters/TelnetAdapter.ts index 8ce8652e..6abb93ef 100644 --- a/src/adapters/TelnetAdapter.ts +++ b/src/adapters/TelnetAdapter.ts @@ -274,11 +274,19 @@ export class TelnetAdapter { this.requestPipeline = new TelnetRequestPipeline(client); this.requestPipeline.connect(); + let lastPartialLine = ''; //forward all raw console output this.requestPipeline.on('console-output', (output) => { this.processBreakpoints(output); - if (output) { - this.emit('console-output', output); + let logResult = util.handleLogFragments(lastPartialLine, output); + + // Save any remaining partial line for the next event + lastPartialLine = logResult.remaining; + if (logResult.completed) { + // Emit the completed io string. + this.emit('console-output', logResult.completed); + } else { + this.logger.debug('Buffer was split', lastPartialLine); } }); diff --git a/src/debugProtocol/client/DebugProtocolClient.spec.ts b/src/debugProtocol/client/DebugProtocolClient.spec.ts index 37c34cb2..b64c8856 100644 --- a/src/debugProtocol/client/DebugProtocolClient.spec.ts +++ b/src/debugProtocol/client/DebugProtocolClient.spec.ts @@ -1188,7 +1188,7 @@ describe('DebugProtocolClient', () => { socket.write('hello\nworld\n'); const output = await ioOutputPromise; - expect(output).to.eql('hello\nworld'); + expect(output).to.eql('hello\nworld\n'); }); it('handles partial lines', async () => { @@ -1217,7 +1217,7 @@ describe('DebugProtocolClient', () => { await outputMonitors[0].promise; socket.write('world\n'); await outputMonitors[1].promise; - expect(await outputPromise).to.eql('hello world'); + expect(await outputPromise).to.eql('hello world\n'); }); it('handles failed update', async () => { diff --git a/src/debugProtocol/client/DebugProtocolClient.ts b/src/debugProtocol/client/DebugProtocolClient.ts index 8f1372f9..bca8c822 100644 --- a/src/debugProtocol/client/DebugProtocolClient.ts +++ b/src/debugProtocol/client/DebugProtocolClient.ts @@ -1122,18 +1122,15 @@ export class DebugProtocolClient { let lastPartialLine = ''; this.ioSocket.on('data', (buffer) => { this.writeToBufferLog('io', buffer); - let responseText = buffer.toString(); - if (!responseText.endsWith('\n')) { - // buffer was split, save the partial line - lastPartialLine += responseText; - } else { - if (lastPartialLine) { - // there was leftover lines, join the partial lines back together - responseText = lastPartialLine + responseText; - lastPartialLine = ''; - } + let logResult = util.handleLogFragments(lastPartialLine, buffer.toString()); + + // Save any remaining partial line for the next event + lastPartialLine = logResult.remaining; + if (logResult.completed) { // Emit the completed io string. - this.emit('io-output', responseText.trim()); + this.emit('io-output', logResult.completed); + } else { + this.logger.debug('Buffer was split', lastPartialLine); } }); diff --git a/src/debugSession/BrightScriptDebugSession.ts b/src/debugSession/BrightScriptDebugSession.ts index adad65b4..82ce6994 100644 --- a/src/debugSession/BrightScriptDebugSession.ts +++ b/src/debugSession/BrightScriptDebugSession.ts @@ -668,8 +668,11 @@ export class BrightScriptDebugSession extends BaseDebugSession { private sendLogOutput(logOutput: string) { this.fileLoggingManager.writeRokuDeviceLog(logOutput); const lines = logOutput.split(/\r?\n/g); - for (let line of lines) { - line += '\n'; + for (let i = 0; i < lines.length; i++) { + let line = lines[i]; + if (i < lines.length - 1) { + line += '\n'; + } this.sendEvent(new OutputEvent(line, 'stdout')); this.sendEvent(new LogOutputEvent(line)); } diff --git a/src/util.spec.ts b/src/util.spec.ts index dc93372d..d1e66fc8 100644 --- a/src/util.spec.ts +++ b/src/util.spec.ts @@ -9,6 +9,7 @@ import * as dedent from 'dedent'; import { util } from './util'; import { util as bscUtil } from 'brighterscript'; import { createSandbox } from 'sinon'; +import { describe } from 'mocha'; const sinon = createSandbox(); beforeEach(() => { @@ -200,6 +201,44 @@ describe('Util', () => { }); }); + describe('handleLogFragments', () => { + it('handles no new lines', () => { + expect( + util.handleLogFragments('', 'new string') + ).to.eql({ completed: '', remaining: 'new string' }); + }); + + it('handles single new line', () => { + expect( + util.handleLogFragments('', 'new string\n') + ).to.eql({ completed: 'new string\n', remaining: '' }); + }); + + it('handles multiple new lines', () => { + expect( + util.handleLogFragments('', 'new string\none new\nline\n') + ).to.eql({ completed: 'new string\none new\nline\n', remaining: '' }); + }); + + it('handles partial lines', () => { + expect( + util.handleLogFragments('', 'new string\none new\nline') + ).to.eql({ completed: 'new string\none new\n', remaining: 'line' }); + }); + + it('handles partial lines and concat', () => { + expect( + util.handleLogFragments('new', ' string\none new\nline') + ).to.eql({ completed: 'new string\none new\n', remaining: 'line' }); + }); + + it('handles partial lines, concat, and new lines in the existing somehow', () => { + expect( + util.handleLogFragments('new\n', ' string\none new\nline') + ).to.eql({ completed: 'new\n string\none new\n', remaining: 'line' }); + }); + }); + describe('isPortInUse', () => { let otherServer: net.Server; let port: number; diff --git a/src/util.ts b/src/util.ts index ec563148..22fe976e 100644 --- a/src/util.ts +++ b/src/util.ts @@ -474,6 +474,24 @@ class Util { public isTransientVariable(variableName: string) { return /^__brs_.*?__$/.test(variableName); } + + public handleLogFragments(currentFragment: string, newFragment: string): { completed: string; remaining: string } { + let lastNewlineIndex = newFragment.lastIndexOf('\n'); + if (lastNewlineIndex === -1) { + currentFragment += newFragment; + return { + completed: '', + remaining: newFragment + }; + } + + let toEmit = currentFragment + newFragment.substring(0, lastNewlineIndex + 1); + let remaining = newFragment.substring(lastNewlineIndex + 1); + return { + completed: toEmit, + remaining + }; + } } export function defer() {