Sending output to an OutputChannel in a for loop seems to duplicate most of the information

[havremunken]

Hi there,

This happens in 10.8, and it also happened in the last one before that.

How to reproduce;

• Create a new extension via "yo code". I went with a TypeScript extension.
• Replace the command implementation with something like this:

     let disposable = vscode.commands.registerCommand('extension.sayHello', () => {

        var editor = vscode.window.activeTextEditor;
        if(!editor) {
            return;
        }

        var output = vscode.window.createOutputChannel("regex test");

        var count = 0;
        for(var i=0; i < editor.document.lineCount; i++)
        {
            var line = editor.document.lineAt(i).text;

            if(line.match('vscode')) {
                console.log('Line matches: ' + line);
                output.appendLine(line);
                count++;
            }

        }

        output.show();

        vscode.window.showInformationMessage('Found ' + count + ' matches');    
    });

• Press F5 to open a new Code window with the extension running as part of it.
• Paste some text into the window, where some lines will match. I just pasted the source code from the first window into the new one.
• Run the extension - F1 then hello, and press enter.

At least on my machine, this correctly finds the expected lines. The console log output is called only once per line.

However, in the OutputChannel, I see something strange. Let us for clarity say that this was the expected output:

1
2
3
4
5
6
7
8
9

Then this would be the actual output:

1
2
3
4
5
6
7
8
9
2
3
4
5
6
7
8
9

In other words, it duplicates all the output lines except for the first one.

I created a new test project to reproduce this and it behaved the same way.

[egamma]

This happens in 10.8, and it also happened in the last one before that.

@havremunken by the last one before that you mean 10.7 (insiders) or 10.6?

FYI @dbaeumer

[havremunken]

Sorry about not being more specific - I didn't use the insiders version so previous to me would be 10.6.

[mitaki28]

I also encounter this issue on developing my extension mitaki28/vscode-clang#4 (source).
Finally I identified its cause.

Environment

• VSCode: Version 0.10.6, 0.10.8
• OS: Mac OS X 10.9

However, it will occur in any environment because it seems to be a bug of OutputChannel implementation.

Condition

• "Output" pane have never been opened since current vscode instance was launched.

Problem

If we execute the following test.command:

let chan = vscode.window.createOutputChannel('Test');
vscode.commands.registerCommand('test.command', () => {
    chan.append('1');
    chan.append('2');
    chan.show();
}); 

then, an "Output" pane will be opened and it will show not 12 but 122.

Cause

Firstly, I found that OutputChannel is just a frontend of OutputService and "Output" pane is managed by OutputEditorInput.

OutputEditorInput shows OutputService.getOutput() directly when "Output" pane is created (source). However it does not consider queued Output.

When OutputService.append(str) is called, result of OutputService.getOutput() is updated immediately (source). Not only that OutputService sends str to OutputEditorInput after some delay except for first call of OutputService.append (source).

So the above example works as below:

chan.append('1'); // OutputService.getOutput() == '1', queue == ''
// `OutputService` sends '1' immediately because it is first call of `OutputService.append`.
// `OutputEditorInput` does nothing because `OutputEditorInput` have not listen `OutputService` yet.
chan.append('2'); // OutputService.getOutput() == '12', queue == '2'
chan.show();
// `OutputEditorInput` starts listening `OutputService`
// "Output" pane is created
// `OutputEditorInput` shows `OutputService.getOutput()` (== '12')
// `OutputService` sends '2' (after some delay)
// `OutputEditorInput` receives and appends '2', so it shows '122'

[dbaeumer]

This has nothing to do with tasks. It is either our extensions API that doesn't work correctly or the output channel itself. Starting with Joh as the owner of the extensions API.

[mitaki28]

I found another bug caused by the same reason.
If we execute the following test.command2:

let chan = vscode.window.createOutputChannel('Test');
vscode.commands.registerCommand('test.command2', () => {
    chan.append('1');
    chan.append('2');
    chan.clear();
    chan.show();
});

then, an "Output" pane shows 2 unexpectedly, and what is worse, it always happens regardless of whether the "Output" pane has already been opened or not.

[MINGLESENO1]

HI

[mitaki28]

Sorry, I notified these commits by mistake.

This issue can be fixed by excluding OutputService.bufferedOutput from OutputService.receivedOutput, but it changes behavior of OutputService.getOutput() and may cause other bugs.

[jrieken]

@bpasero did something change there? I quite sure this used to work some time ago?

[bpasero]

@isidorn can you answer?

[jrieken]

This seem to happen when the output panel wasn't visible and a command like above is run. I cannot repo once the output has been visible

[isidorn]

I touched code in that area and can investigate

[isidorn]

@bpasero also please code review
@mitaki28 @havremunken thanks for great steps!

[bpasero]

@isidorn I filed #3896 and #3897 which are not really related to your change.

There is also #3609 (comment) which seems to indicate high CPU usage when an extension spams with output. Maybe you could also take a look and experiment a) with lots of spam per millisecond and b) with very large output content (above 10k lines).

I noticed today that all of VS Code became unresponsive when having the typescript compile task producing tons of errors. I think the two bugs I opened would help in that case.

[isidorn]

@bpasero thanks! I'll look into the three issues.