OpenConsole: Duplicate output lines when connecting to Ubuntu via SSH

[lhecker]

OpenConsole version

fc95802

Steps to reproduce

The exact steps to reproduce the issue are somewhat unclear to me, but it happens readily on a Ubuntu 22.04.2 LTS server I own. Access can be provided on a case-by-case basis. The issue occurs with both bash and fish-shell with the standard configuration provided by Ubuntu. It does not reproduce with Windows Terminal.

Expected Behavior

Actual Behavior

Like this:

Or any other wild intermix, including entirely missing or individually duplicated characters. Sometimes I receive up to 5000 lines of output this way.

Investigation

We do actually receive those duplicates as WriteConsole calls:

git bisect leads me to believe that this issue was introduced in fc95802. Unfortunately, the effect is entirely random and sometimes seems to not occur at all, so I can't be 100% certain. But I've tried to reproduce the issue with da3a33f ~100 times now and couldn't, whereas it happens at least half the time with fc95802.

[lhecker]

@j4james FYI I believe I found a bug in the LineFeed refactor. It's a tricky one and I'm not entirely sure yet how to debug this. I suspect I'll just have to do ye old "read the diff until you found the bug"-trick again. 😄

[lhecker]

I found the exact line I need to flip to make it work again: fc95802#diff-21383c37a75bafb4ee95b4559a8f5b3d421640e19d3aef91cce9a419b28707e9L2103-R2178

In other words, if I revert the AdaptDispatch::LineFeed handling from _DoLineFeed to _api.LineFeed it works again. It's unclear to me however why that would be...

[j4james]

I don't get what's happening here. Who is making all those WriteConsole calls with identical content? Is that the SSH client? If that's the case, why wouldn't you expect to see duplicate output? Are they resetting the cursor position between the WriteConsole calls? Are their cursor positioning escape sequences in the output somewhere?

And this is assumedly not what the server is sending is it? Like can you do a script recording on the server side to see what is being produced at that end? Because if the server isn't sending duplicate content, then that suggests the SSH client is doing its own VT parsing and rewriting the buffer strangely.

My suggestion would be to add some logging to conhost that writes out everything that is received in the WriteConsole call so we can see exactly what is being sent, and then see if you can reproduce the issue just by TYPEing that log. If not, you may need to check for other relevant API calls, like mode changes, cursor movement, and maybe buffer resizing.

[lhecker]

I spent quite some time trying to figure out what's going on and I'm not entirely sure which part is broken. FWIW I don't think it's the new _DoLineFeed function itself, but rather a bad interaction with some other part of OpenConsole or Windows' SSH that is simply revealed by its introduction. For instance, I noticed that the issue is most easily reproducible if I connect via SSH the second pwsh is starting up. If I start pwsh and wait a few seconds before connecting, it happens way less often. I mean, for instance, what if we have functions that read the cursor position without acquiring the console lock first? Things like that basically... I'll try to continue looking into it. Thanks for the tip for script. Dustin also suggested using is experimental record & replay feature for the condrv interface.

[lhecker]

What's also interesting is that I sometimes see a ?2004l being printed. In some case it quickly disappears because it's (partially or entirely) overwritten. (It's like the cursor is being reset to the start of the line.)

[DHowett]

Hey, what version of openssh is that? They had an issue around the use of the alternate screen buffer where they would re-send an entire console write when the window size changed.

[j4james]

Yeah, I was wondering that too. There are quite a few reports of duplicated content related to Win32-OpenSSH, but they all seem to point to a PR at PowerShell/openssh-portable#426 which was fixed years ago.

[lhecker]

Hey, what version of openssh is that?

I'm using OpenSSH_for_Windows_8.6p1, LibreSSL 3.4.3 (Windows 11 Beta branch, build 22631).

The issue doesn't occur with WSL btw. As I've said before, I don't really think we're doing anything wrong per se, but it is weird that I cannot reproduce it before fc95802 and always reproduce it after fc95802 with Windows' SSH client. Something's whacky, I can feel it. 😄

[j4james]

Note that PR #14874 is definitely expected to change the behavior of the linefeed operation under certain conditions, but that would typically have involved margins in some way. My concern is that this particular change may not be expected, though, and there's no way of knowing that without seeing the API calls and/or escape sequences the ssh client is using.

[lhecker]

At this point I genuinely think it's a bug in Windows' SSH implementation. Here's a text file that 9 out of 10 times reproduces the issue in the latest OpenConsole version (1.18.1462.0) if I cat it remotely over SSH in a standard 120x30 viewport: 15769_repro.txt
The start sequence is the output of tput reset. The rest is plain text. It should show the same two lines 11x repeated, but it usually shows them more often than that, similar to my screenshots above.

The shell doesn't play any role at all - it happens even if I use dash. (I've confirmed that the output of script is identical, apart from the additional raw $ input line. I can provide the typescript file if anyone's interested in it.)
I'm still confused why the LineFeed refactor would excerbate this issue, but... Maybe that's simply not important to figure out? It might be more worthwhile to contact the https://github.com/PowerShell/openssh-portable maintainers.

[lhecker]

Y'ALL I FIGURED IT OUT!!!!!!!!!!!!!!!!!!!!!
You will not believe this. 🤣

This works:

terminal/src/host/_stream.cpp

Line 161 in c79298d

auto hr = screenInfo.SetViewportOrigin(true, newViewOrigin, true);

This does not:

terminal/src/host/outputStream.cpp

Line 101 in a1865b9

THROW_IF_FAILED(ServiceLocator::LocateGlobals().api->SetConsoleWindowInfoImpl(info, true, windowRect));

Replacing it with this fixes the issue:

void ConhostInternalGetSet::SetViewportPosition(const til::point position)
{
    auto& info = _io.GetActiveOutputBuffer();
    const auto dimensions = info.GetViewport().Dimensions();
    const auto windowRect = til::rect{ position, dimensions }.to_inclusive_rect();
    info.SetViewport(Viewport::FromInclusive(windowRect), true);
}

This happens because SetConsoleWindowInfoImpl ends up calling Window::PostUpdateWindowSize() which sets CONSOLE_SETTING_WINDOW_SIZE and posts a CM_SET_WINDOW_SIZE. Removing the CM_SET_WINDOW_SIZE message fixes the issue, so I'm sure it's because of that. Reading the SSH source code (and via tracing) I believe this triggers SSH to send a viewport size change event (TIOCGWINSZ) and I think this corrupts the output, because of an ensuing race condition between server and client. (This update happens on every single viewport position change after all.)

I would prefer writing

    THROW_IF_FAILED(info.SetViewportOrigin(true, position, true));

but it seems like SetViewport and SetViewportOrigin aren't equivalent? Is that a bug? It would also need to post a window update to update the scrollbar.

Any thoughts about my findings? 😊