v2 console: unblocked WriteFile sets lpNumberOfBytesWritten incorrectly

[rprichard]

A console can be frozen/paused if there is text selection (or IIRC if the user hits the Pause key in certain input modes). In that case, WriteConsole/WriteFile calls are blocked until the console is unfrozen.

With ASCII output, when a WriteFile call successfully completes that had initially been blocked, WriteFile reports the number of bytes written (via lpNumberOfBytesWritten) as nNumberOfBytesToWrite * 2 rather than nNumberOfBytesToWrite. I'd guess that it's reporting the size, in bytes, of the output after a conversion to UTF-16. I expect it to use an unconverted amount.

WriteConsoleA works as expected, as does WriteFile in either a legacy console or with the v2 console in Windows 10.0.15063.

winpty uses the "Select All" command to synchronize with a stream of output into a console, so programs running winpty hit this WriteFile change frequently. In particular, the print statement in Python 2.7 can fail, which is causing problems for people:

• Random IO errors on Windows 10.0.16299.64 platformio/platformio-atom-ide-terminal#422
• Python multithreading print error with the integrated terminal  vscode#40199
• IOError: PackageManager is unable to install tool platformio/platformio-vscode-ide#61

upstream winpty bug: rprichard/winpty#134

Affected Windows versions:

• 10.0.16257.1000
• 10.0.16299.19
• 10.0.16299.125

Repro 1 (Python 2.7):

test.py :

import sys
for i in range(20000):
    sys.stdout.write(b'.')
    sys.stdout.flush()

Run the script, then press Ctrl-A to select all text before it finishes. Then press ESC. The output looks like this:

C:\Users\rprichard>c:\Python27\python.exe test.py
.................................................................................
.................................................................................
.................................................................................
......................Traceback (most recent call last):
  File "test.py", line 3, in <module>
    sys.stdout.write(b'.')
IOError: [Errno 0] Error

Repro 2 (C++11)

#pragma comment(lib, "user32.lib") 

#include <windows.h>
#include <stdio.h>
#include <string.h>

#include <thread>

// Send "Select All", then spawn a thread to hit ESC a moment later.
static void start_selection() {
    const HWND hwnd = GetConsoleWindow();
    const int SC_CONSOLE_SELECT_ALL = 0xFFF5;
    SendMessage(hwnd, WM_SYSCOMMAND, SC_CONSOLE_SELECT_ALL, 0);
    auto press_escape = std::thread([=]() {
        Sleep(300);
        SendMessage(hwnd, WM_CHAR, 27, 0x00010001);
    });
    press_escape.detach();
}

template <typename T>
static void do_write_test(
        const char *api_name,
        T *api_ptr,
        bool use_selection) {
    if (use_selection) {
        start_selection();
    }    
    char buf[] = "1234\n";
    DWORD actual = 0;
    const BOOL ret = api_ptr(
        GetStdHandle(STD_OUTPUT_HANDLE),
        buf, strlen(buf), &actual, NULL);
    const DWORD last_error = GetLastError();
    printf("%s: %s returned %d: actual=%u LastError=%u (%s)\n",
        ((ret && actual == strlen(buf)) ? "SUCCESS" : "ERROR"),
        api_name, ret, actual, last_error,
        use_selection ? "select" : "no-select");
}

int main() {
    // Passes: Unblocked WriteConsoleA.
    do_write_test("WriteConsoleA", WriteConsoleA, false);

    // Passes: Blocked WriteConsoleA.
    do_write_test("WriteConsoleA", WriteConsoleA, true);

    // Passes: Unblocked WriteFile.
    do_write_test("WriteFile", WriteFile, false);

    // Fails: Blocked WriteFile. WriteFile returns the number of bytes
    // multiplied by 2 (the size of the UTF-16 output in bytes?).
    do_write_test("WriteFile", WriteFile, true);

    return 0;
}

Bad output:

C:\Users\rprichard>cl /nologo consolebug.cpp
consolebug.cpp

C:\Users\rprichard>consolebug
1234
SUCCESS: WriteConsoleA returned 1: actual=5 LastError=0 (no-select)
1234
SUCCESS: WriteConsoleA returned 1: actual=5 LastError=0 (select)
1234
SUCCESS: WriteFile returned 1: actual=5 LastError=0 (no-select)
1234
ERROR: WriteFile returned 1: actual=10 LastError=0 (select)

Good output:

C:\Users\rprichard>\\nas\nas\SambaShared\consolebug.exe
1234
SUCCESS: WriteConsoleA returned 1: actual=5 LastError=0 (no-select)
1234
SUCCESS: WriteConsoleA returned 1: actual=5 LastError=0 (select)
1234
SUCCESS: WriteFile returned 1: actual=5 LastError=0 (no-select)
1234
SUCCESS: WriteFile returned 1: actual=5 LastError=0 (select)

Edit: update test to reflect that (a) WriteFile does the right thing when it isn't blocked by selection, and (b) WriteConsoleA works in either case.

[rprichard]

@miniksa @zadjii-msft I assume this is something you'll want to look at?

[khouzam]

Thanks @rprichard,

We've addressed the issue recently it's microsoft/vscode#40199. We weren't doing the proper character conversion back to A when the call was not processed immediately.

[DHowett-MSFT]

It looks like this fix shipped. Thanks for reporting it!