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 <[email protected]>
rokucommunity · Jan 13, 2025 · abb9c79 · abb9c79
1 parent 93d5c46
commit abb9c79
Show file tree

Hide file tree

Showing 7 changed files with 93 additions and 31 deletions.
diff --git 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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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
@@ -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<T>() {