Skip to content

Commit

Permalink
Fix bug with telnet getting stuck (#163)
Browse files Browse the repository at this point in the history 
* Fix bug with telnet getting stuck

* Use local `defer()` instead of one from bsc
  • Loading branch information
@TwitchBronBron
TwitchBronBron authored Oct 2, 2023
1 parent 659ee6c commit 991ad57
Show file tree
Hide file tree
Showing 2 changed files with 175 additions and 99 deletions.
205 changes: 134 additions & 71 deletions src/adapters/TelnetRequestPipeline.spec.ts
View file
Original file line number Diff line number Diff line change
@@ -1,10 +1,12 @@
import { TelnetRequestPipeline } from './TelnetRequestPipeline';
import { util } from '../util';
import { TelnetCommand, TelnetRequestPipeline } from './TelnetRequestPipeline';
import { defer, util } from '../util';
import { expect } from 'chai';
import dedent = require('dedent');
import { logger } from '../logging';
import { clean } from '../testHelpers.spec';
import { Deferred } from 'brighterscript';
import { createSandbox } from 'sinon';
const sinon = createSandbox();

const prompt = 'Brightscript Debugger>';

Expand Down Expand Up @@ -46,6 +48,7 @@ describe('RequestPipeline', () => {
};

beforeEach(() => {
sinon.restore();
logger.logLevel = 'off';
consoleOutput = '';
unhandledConsoleOutput = '';
Expand All @@ -61,6 +64,10 @@ describe('RequestPipeline', () => {
});
});

afterEach(() => {
sinon.restore();
});

it('handles split debugger prompt messages', async () => {
handleData(prompt);
socket.messageQueue.push([
Expand Down Expand Up @@ -178,82 +185,138 @@ describe('RequestPipeline', () => {
`);
});

describe('', () => {
it('correctly handles both types of line endings', async () => {
//send prompt so pipeline will execute commands
handleData(prompt);
socket.messageQueue.push([
'vscode_key_start:message1:vscode_key_stop vscode_is_string:trueHello\r\n' +
'vscode_key_start:message2:vscode_key_stop vscode_is_string:trueWorld\r\n' +
'\r\n' +
'Brightscript Debugger>'
]);
expect(
await pipeline.executeCommand('commandDoesNotMatter', { waitForPrompt: true })
).to.equal(
'vscode_key_start:message1:vscode_key_stop vscode_is_string:trueHello\r\n' +
'vscode_key_start:message2:vscode_key_stop vscode_is_string:trueWorld\r\n\r\n'
);
it('correctly handles both types of line endings', async () => {
//send prompt so pipeline will execute commands
handleData(prompt);
socket.messageQueue.push([
'vscode_key_start:message1:vscode_key_stop vscode_is_string:trueHello\r\n' +
'vscode_key_start:message2:vscode_key_stop vscode_is_string:trueWorld\r\n' +
'\r\n' +
'Brightscript Debugger>'
]);
expect(
await pipeline.executeCommand('commandDoesNotMatter', { waitForPrompt: true })
).to.equal(
'vscode_key_start:message1:vscode_key_stop vscode_is_string:trueHello\r\n' +
'vscode_key_start:message2:vscode_key_stop vscode_is_string:trueWorld\r\n\r\n'
);
});

it('removes warning statements introduced in 10.5', async () => {
//send prompt so pipeline will execute commands
handleData(prompt);
socket.messageQueue.push([
'Warning: operation may not be interruptible.\r\n' +
'Invalid' +
'\r\n' +
'Brightscript Debugger>'
]);
expect(
await pipeline.executeCommand('commandDoesNotMatter', { waitForPrompt: true })
).to.equal(
'Invalid\r\n'
);
});

it('Removes "thread attached" messages', async () => {
//send prompt so pipeline will execute commands
handleData(prompt);
socket.messageQueue.push([
'Warning: operation may not be interruptible.',
'roAssociativeArray',
'',
'Brightscript Debugger> ',
'',
'Thread attached: pkg:/source/main.brs(6) screen.show()',
'',
'',
''
].join('\r\n'));
expect(
await pipeline.executeCommand('commandDoesNotMatter', { waitForPrompt: true })
).to.equal(
'roAssociativeArray\r\n\r\n'
);
});

it('joins split log messages together', async () => {
socket.messageQueue.push();
const outputEvents = [] as string[];
const deferred = defer();
//there should be 2 events
pipeline.on('console-output', (data) => {
outputEvents.push(data);
if (outputEvents.length === 2) {
deferred.resolve();
}
});
handleData('1');
handleData('2\r\n');
handleData('3');
handleData('4\r\n');
await deferred.promise;
expect(outputEvents).to.eql([
'12\r\n',
'34\r\n'
]);
});

it('removes warning statements introduced in 10.5', async () => {
//send prompt so pipeline will execute commands
handleData(prompt);
socket.messageQueue.push([
'Warning: operation may not be interruptible.\r\n' +
'Invalid' +
'\r\n' +
'Brightscript Debugger>'
]);
expect(
await pipeline.executeCommand('commandDoesNotMatter', { waitForPrompt: true })
).to.equal(
'Invalid\r\n'
);
it('moves on to the next command if the current command failed', async () => {
pipeline.isAtDebuggerPrompt = true;
let command1: TelnetCommand;
let command2: TelnetCommand;

const executeStub = sinon.stub(TelnetCommand.prototype, 'execute').callsFake(function(this: TelnetCommand) {
// resolve command2 immediately
if (this === command2) {
command2['deferred'].resolve('');
}
});

it('Removes "thread attached" messages', async () => {
//send prompt so pipeline will execute commands
handleData(prompt);
socket.messageQueue.push([
'Warning: operation may not be interruptible.',
'roAssociativeArray',
'',
'Brightscript Debugger> ',
'',
'Thread attached: pkg:/source/main.brs(6) screen.show()',
'',
'',
''
].join('\r\n'));
expect(
await pipeline.executeCommand('commandDoesNotMatter', { waitForPrompt: true })
).to.equal(
'roAssociativeArray\r\n\r\n'
);
void pipeline.executeCommand('test 1', { waitForPrompt: true });
command1 = pipeline['activeCommand'];
void pipeline.executeCommand('test 2', { waitForPrompt: true });
command2 = pipeline['commands'][0];

//stub the logger function so it throws an exception
const loggerDebugStub = sinon.stub(command1.logger, 'debug').callsFake(() => {
//only crash the first time
if (loggerDebugStub.callCount === 1) {
throw new Error('Crash!');
}
});

it('joins split log messages together', async () => {
socket.messageQueue.push();
const outputEvents = [] as string[];
const deferred = new Deferred();
//there should be 2 events
pipeline.on('console-output', (data) => {
outputEvents.push(data);
if (outputEvents.length === 2) {
deferred.resolve();
}
//pass some bad data to the command, which causes it to throw an exception
pipeline['handleData'](`bad data\n/${prompt}`);

//make sure this test actually did what we thought...that the logger.debug() function was called and had a chance to throw
expect(loggerDebugStub.called).to.be.true;
//restore the logger function so the next command doesn't crash
loggerDebugStub.restore();

//command1 should be a rejected promise
expect(command1['deferred'].isRejected).to.be.true;

//wait for command2 to finish executing
await command2.promise;
expect(command2['deferred'].isResolved).to.be.true;

//should have executed the second command after the first one failed
expect(executeStub.callCount).to.equal(2);

});

describe('TelnetCommand', () => {
it('serializes to just the important bits', () => {
const command = new TelnetCommand('print m', true, logger, pipeline, 3);
expect(
JSON.parse(JSON.stringify(command))
).to.eql({
id: 3,
commandText: 'print m',
waitForPrompt: true,
isCompleted: false
});
handleData('1');
handleData('2\r\n');
handleData('3');
handleData('4\r\n');
await deferred.promise;
expect(outputEvents).to.eql([
'12\r\n',
'34\r\n'
]);
});
});

});
69 changes: 41 additions & 28 deletions src/adapters/TelnetRequestPipeline.ts
View file
Original file line number Diff line number Diff line change
@@ -1,6 +1,6 @@
import type { Socket } from 'net';
import * as EventEmitter from 'eventemitter3';
import { util } from '../util';
import { defer, util } from '../util';
import type { Logger } from '../logging';
import { createLogger } from '../logging';
import { Deferred } from 'brighterscript';
Expand All @@ -14,15 +14,15 @@ export class TelnetRequestPipeline {

private logger = createLogger(`[${TelnetRequestPipeline.name}]`);

private commands: Command[] = [];
private commands: TelnetCommand[] = [];

public isAtDebuggerPrompt = false;

public get isProcessing() {
return this.activeCommand !== undefined;
}

private activeCommand: Command = undefined;
private activeCommand: TelnetCommand = undefined;

private emitter = new EventEmitter();

Expand Down Expand Up @@ -138,7 +138,7 @@ export class TelnetRequestPipeline {
*/
insertAtFront?: boolean;
}) {
const command = new Command(
const command = new TelnetCommand(
commandText,
options?.waitForPrompt ?? true,
this.logger,
Expand Down Expand Up @@ -212,7 +212,7 @@ export class TelnetRequestPipeline {
}
}

class Command {
export class TelnetCommand {
public constructor(
public commandText: string,
/**
Expand All @@ -228,7 +228,7 @@ class Command {

public logger: Logger;

private deferred = new Deferred<string>();
private deferred = defer<string>();

/**
* Promise that completes when the command is finished
Expand Down Expand Up @@ -257,7 +257,7 @@ class Command {
this.pipeline.isAtDebuggerPrompt = false;
} catch (e) {
this.logger.error('Error executing command', e);
this.deferred.reject('Error executing command');
this.deferred.reject(new Error('Error executing command'));
}
}

Expand All @@ -279,30 +279,43 @@ class Command {
//get the first response
const match = /Brightscript Debugger>\s*/is.exec(pipeline.unhandledText);
if (match) {
const response = this.removeJunk(
pipeline.unhandledText.substring(0, match.index)
);

this.logger.debug('Found response before the first "Brightscript Debugger>" prompt', { response, allText: pipeline.unhandledText });
//remove the response from the unhandled text
pipeline.unhandledText = pipeline.unhandledText.substring(match.index + match[0].length);

//emit the remaining unhandled text
if (pipeline.unhandledText?.length > 0) {
pipeline.emit('unhandled-console-output', pipeline.unhandledText);
}
//clear the unhandled text
pipeline.unhandledText = '';

this.logger.debug(`execute result`, { commandText: this.commandText, response });
if (!this.deferred.isCompleted) {
this.logger.debug('resolving promise', { response });
this.deferred.resolve(response);
} else {
this.logger.error('Command already completed', { response, commandText: this.commandText, stacktrace: new Error().stack });
try {
const response = this.removeJunk(
pipeline.unhandledText.substring(0, match.index)
);

this.logger.debug('Found response before the first "Brightscript Debugger>" prompt', { response, allText: pipeline.unhandledText });
//remove the response from the unhandled text
pipeline.unhandledText = pipeline.unhandledText.substring(match.index + match[0].length);

//emit the remaining unhandled text
if (pipeline.unhandledText?.length > 0) {
pipeline.emit('unhandled-console-output', pipeline.unhandledText);
}
//clear the unhandled text
pipeline.unhandledText = '';

this.logger.debug(`execute result`, { commandText: this.commandText, response });
if (!this.deferred.isCompleted) {
this.logger.debug('resolving promise', { response });
this.deferred.resolve(response);
} else {
this.logger.error('Command already completed', { response, commandText: this.commandText, stacktrace: new Error().stack });
}
} catch (e) {
this.deferred.reject(e as unknown as Error);
}
} else {
// no prompt found, wait for more data from the device
}
}

toJSON() {
return {
commandText: this.commandText,
id: this.id,
isCompleted: this.isCompleted,
waitForPrompt: this.waitForPrompt
};
}
}

0 comments on commit 991ad57

Please sign in to comment.