search

virtio-win / kvm-guest-drivers-windows

Windows paravirtualized drivers for QEMU\KVM
https://www.linux-kvm.org/page/WindowsGuestDrivers
BSD 3-Clause "New" or "Revised" License
2k stars 384 forks source link

viosock: VIOSockConnect connection timeout is invalid #551

Open kcrazy opened 3 years ago

kcrazy commented 3 years ago

It seems that the timer started by WdfTimerStartin the VIOSockConnectfunction is stopped by WdfTimerStopin VIOSockRxPktHandleConnecting, resulting in invalid timeout mechanism

YanVugenfirer commented 3 years ago

@irudakov77 - please take a look.

Thanks.

irudakov77 commented 3 years ago

Hi kcrazy.

Let's discuss. For "blocking" socket, VIOSockConnect, sets state to CONNECTING, marks the connection request as pended, arms ConnectTimer and then sends the request to host. VIOSockRxPktHandleConnecting handles host response for a socket in CONNECTING state. Socket can change its state to CONNECTED or CLOSE and complete the connection request. Do we still need an active ConnectTimer? I don't think so.

Regards, Ilya

kcrazy commented 3 years ago

Hi Ilya.

Nice to discuss with you.

I think ConnectTimer is still very necessary.

What I worry about is that if there is a problem on the server side and there is no listening, then VIOSockConnect will keep blocking.

It will also cause my program to block, so I think timeout is still necessary

In addition, if there is no timeout mechanism, the connection timeout set by VIOSockSetSockOpt through the SO_VM_SOCKETS_CONNECT_TIMEOUT parameter will also be invalid

Regards, kcrazy

irudakov77 commented 3 years ago

Perhaps I was unclear. I'm still pretty sure the connection timer works fine.:) If we don't stop the timer, it will try to complete a request that no longer exists. The timer stops only when the guest receives OP_RESPONSE and the connection become established (and blocking connect() returns success), or when the guest receives OP_RST and connect is considered rejected (connect() returns a network error), otherwise the timer will continue to count down and complete the connection request with a timeout error after the interval has expired. By the way, if there is no listener on the host side, host sends OP_RST and connect() returns a network error immediately.

kcrazy commented 3 years ago

Hi Ilya.

This is my test code. This is a driver.

When it runs to IOCTL_SOCKET_CONNECT, it will cause the program to block, if the server is not Listening

        NTSTATUS ns;
    VIRTIO_VSOCK_PARAMS SocketParams = { 0 };
    PFILE_OBJECT socket;
    SOCKADDR_VM addr;

    SocketParams.Type = VIRTIO_VSOCK_TYPE_STREAM;
    ns = VIOSockCreateFile(&SocketParams, &socket);

    addr.svm_family = AF_VSOCK;
    addr.svm_cid = 2;
    addr.svm_port = 8080;
    ns = VIOSockDeviceControl(socket, IOCTL_SOCKET_CONNECT, (PVOID)addr, (DWORD)sizeof(addr), NULL, 0, NULL);

    VIOSockClose(socket);
NTSTATUS
VIOSockCreateFile(
    _In_opt_ PVIRTIO_VSOCK_PARAMS pSocketParams,
    _Out_ PFILE_OBJECT* socket
)
{
    HANDLE hFile = NULL;
    NTSTATUS ns;
    OBJECT_ATTRIBUTES oa;
    IO_STATUS_BLOCK iosb = { 0 };
    UNICODE_STRING usDeviceName = RTL_CONSTANT_STRING(L"\\Device\\Viosock");

    UCHAR EaBuffer[sizeof(FILE_FULL_EA_INFORMATION) + sizeof(*pSocketParams)] = { 0 };
    PFILE_FULL_EA_INFORMATION pEaBuffer = (PFILE_FULL_EA_INFORMATION)EaBuffer;

    if (pSocketParams != NULL)
    {
        pEaBuffer->EaNameLength = sizeof(FILE_FULL_EA_INFORMATION) -
            FIELD_OFFSET(FILE_FULL_EA_INFORMATION, EaName) - sizeof(UCHAR);
        pEaBuffer->EaValueLength = sizeof(*pSocketParams);
        memcpy(&EaBuffer[sizeof(FILE_FULL_EA_INFORMATION)], pSocketParams, sizeof(*pSocketParams));
    }
    else
        pEaBuffer = NULL;

    InitializeObjectAttributes(&oa, &usDeviceName, OBJ_CASE_INSENSITIVE | OBJ_KERNEL_HANDLE, NULL, NULL);

    ns = ZwCreateFile(&hFile, FILE_ALL_ACCESS | SYNCHRONIZE, &oa, &iosb, 0, 0,
        FILE_SHARE_READ | FILE_SHARE_WRITE, FILE_OPEN, FILE_NON_DIRECTORY_FILE | FILE_SYNCHRONOUS_IO_ALERT, pEaBuffer,
        pEaBuffer ? sizeof(EaBuffer) : 0);
    if (!NT_SUCCESS(ns))
    {
        return ns;
    }

    ns = ObReferenceObjectByHandle(hFile, FILE_ALL_ACCESS, NULL, KernelMode, socket, NULL);
    ZwClose(hFile);

    if (!NT_SUCCESS(ns)) {
        ZwClose(*socket);
        return ns;
    }

    return ns;
}

VOID VIOSockClose(_In_ PFILE_OBJECT file)
{
    if (file != NULL) {
        ObDereferenceObject(file);
    }
}

NTSTATUS
VIOSockDeviceControl(
    _In_ PFILE_OBJECT file,
    _In_ ULONG IoControlCode,
    _In_reads_bytes_opt_(nInBufferSize) PVOID lpInBuffer,
    _In_ ULONG nInBufferSize,
    _Out_writes_bytes_to_opt_(nOutBufferSize, *lpBytesReturned) PVOID lpOutBuffer,
    _In_ ULONG nOutBufferSize,
    _Out_opt_ PULONG lpBytesReturned
)
{
    NTSTATUS ns;
    PDEVICE_OBJECT  devObj;
    KEVENT          event;
    PIRP            irp;
    PIO_STACK_LOCATION iosl;
    IO_STATUS_BLOCK iosb;

    if (lpBytesReturned != NULL) {
        *lpBytesReturned = 0;
    }

    devObj = IoGetRelatedDeviceObject(file);
    if (devObj == NULL) {
        return STATUS_UNSUCCESSFUL;
    }

    KeInitializeEvent(&event, NotificationEvent, FALSE);

    irp = IoBuildDeviceIoControlRequest(IoControlCode, devObj, lpInBuffer, nInBufferSize, lpOutBuffer, nOutBufferSize, FALSE, &event, &iosb);

    if (irp == NULL) {
        return STATUS_INSUFFICIENT_RESOURCES;
    }

    irp->Flags |= IRP_SYNCHRONOUS_API;
    iosl = IoGetNextIrpStackLocation(irp);
    iosl->FileObject = file;

    ns = IoCallDriver(devObj, irp);

    if (ns == STATUS_PENDING) {
        KeWaitForSingleObject(&event, Executive, KernelMode, FALSE, NULL);
        ns = iosb.Status;
    }

    if (lpBytesReturned != NULL) {
        *lpBytesReturned = iosb.Information;
    }

    return ns;
}

Regards, kcrazy

irudakov77 commented 3 years ago

Hi kcrazy

It's interesting, here is output from my viosocklib-test:

C:\amd64>viosocklib-test.exe /c 2:8080 C:\amd64\viosock.inf
socket(AF_VSOCK, SOCK_STREAM, 0)
connect failed: 10061

And a part of tracelog:

[0]1B28.16EC::02/15/2021-20:00:50.769 [viosock.sys]Socket 2 (000023F007AB9248) initializing
[0]1B28.16EC::02/15/2021-20:00:50.769 [viosock.sys]Socket 2, 0x00000000(CLOSE) --> 0x00000001(CONNECTING)
[0]1B28.16EC::02/15/2021-20:00:50.769 [viosock.sys]Send packet 0x00000001(REQUEST) (3:1792593554 --> 2:8080), len: 0, flags: 0, buf_alloc: 262144, fwd_cnt: 0
[1]0000.0000::02/15/2021-20:00:50.770 [viosock.sys]Recv packet 0x00000003(RST) (3:1792593554 <-- 2:8080), len: 0, flags: 0, buf_alloc: 0, fwd_cnt: 0
[1]0000.0000::02/15/2021-20:00:50.770 [viosock.sys]No connected socket found
[1]0000.0000::02/15/2021-20:00:50.770 [viosock.sys]Socket 2 found, state 0x00000001(CONNECTING)
[1]0000.0000::02/15/2021-20:00:50.770 [viosock.sys]Socket 2, 0x00000001(CONNECTING) --> 0x00000000(CLOSE)
[1]0000.0000::02/15/2021-20:00:50.770 [viosock.sys]Free packet 0x00000001(REQUEST) (3:1792593554 --> 2:8080)
[2]1B28.16EC::02/15/2021-20:00:50.790 [viosock.sys]Socket 2, 0x00000000(CLOSE) --> 0x00000000(CLOSE)
[2]1B28.16EC::02/15/2021-20:00:50.790 [viosock.sys]Socket 2 closed

You can see host normally responses with RST if no listener presents. Tracelog from viosock driver would be very helpful, please turn verbose log on: reg add HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\VirtioSocket\Parameters /v VerboseOn /t REG_DWORD /d 1 /f , start trace session with Tools\Trace\viosock.bat, run your code and stop tracing (push ENTER). Convert viosock.etl to textlog with ParseTrace.bat and post it here.

Thanks, Ilya

kcrazy commented 3 years ago

Hi Ilya. this is my textlog, I run my driver generated

[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]VIOSockCreate
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]Socket 1 (6C728818) initializing
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockReadSocketQueueInit
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockReadSocketQueueInit
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockCreate
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockEvtIoDeviceControl
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockDeviceControl
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockConnect
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockBoundAdd
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]Socket 1, 0x00000000(CLOSE) --> 0x00000001(CONNECTING)
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockTxEnqueue
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockTxVqProcess
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockTxDequeue
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockTxPktInsert
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]Send packet 0x00000001(REQUEST) (3:120163775 --> 2:8080), len: 0, flags: 0, buf_alloc: 262144, fwd_cnt: 0
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockTxPktInsert
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockTxDequeue
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockTxVqProcess
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockTxEnqueue
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockConnect
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockDeviceControl
[0]0004.0138::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockEvtIoDeviceControl
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockInterruptIsr
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockInterruptIsr, interrupt not serviced
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockInterruptIsr
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockInterruptIsr, interrupt not serviced
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockInterruptDpc
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockEvtVqProcess
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockEvtVqProcess
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockRxVqProcess
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]Recv packet 0x00000003(RST) (3:120163775 <-- 2:8080), len: 0, flags: 0, buf_alloc: 0, fwd_cnt: 0
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]No connected socket found
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]Socket 1 found, state 0x00000001(CONNECTING)
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockRxPktHandleConnecting
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockSelectRun
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockSelectRun
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]Socket 1, 0x00000001(CONNECTING) --> 0x00000000(CLOSE)
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockRxPktHandleConnecting
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockRxPktInsert
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockRxPktInsert
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockRxVqProcess
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockTxVqProcess
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]Free packet 0x00000001(REQUEST) (3:120163775 --> 2:8080)
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]--> VIOSockTxDequeue
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockTxDequeue
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockTxVqProcess
[1]08B8.0CE8::02/22/2021-10:45:11.891 [viosock.sys]<-- VIOSockInterruptDpc

Thanks, kcrazy

irudakov77 commented 3 years ago

Thanks for the log! As we can see, the host responds with RST immediately, but the driver does not complete the pending connection request for an unknown reason, not related to the timer processing. Please collect another driver trace log with the latest patch that added a couple of additional trace points. Note that the AF_VSOCK macro is no longer defined in public headers, instead you should redesign your driver slightly to use the "dynamic" address family value obtained from the viosock driver. See patch description for details.

Regards, Ilya

kcrazy commented 3 years ago

Hi Ilya. this is my new textlog with the latest patch.

[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]VIOSockCreate
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]Control socket 1 (720058F0) initializing
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockCreate
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockEvtIoDeviceControl
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockDeviceGetAf
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockDeviceGetAf
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockEvtIoDeviceControl
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockClose
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]Control socket 1 closed
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]VIOSockCreate
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]Socket 2 (72005C50) initializing
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockReadSocketQueueInit
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockReadSocketQueueInit
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockCreate
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockEvtIoDeviceControl
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockDeviceControl
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockConnect
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockBoundAdd
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]Socket 2, 0x00000000(CLOSE) --> 0x00000001(CONNECTING)
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockPendedRequestSet
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockTxEnqueue
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockTxVqProcess
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockTxDequeue
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockTxPktInsert
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]Send packet 0x00000001(REQUEST) (3:435593588 --> 2:8080), len: 0, flags: 0, buf_alloc: 262144, fwd_cnt: 0
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockTxPktInsert
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockTxDequeue
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockTxVqProcess
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockTxEnqueue
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockConnect
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockDeviceControl
[1]0004.1628::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockEvtIoDeviceControl
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockInterruptIsr
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockInterruptIsr, interrupt not serviced
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockInterruptIsr
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockInterruptIsr, interrupt not serviced
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockInterruptDpc
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockEvtVqProcess
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockEvtVqProcess
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockRxVqProcess
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]Recv packet 0x00000003(RST) (3:435593588 <-- 2:8080), len: 0, flags: 0, buf_alloc: 0, fwd_cnt: 0
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]No connected socket found
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]Socket 2 found, state 0x00000001(CONNECTING)
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockRxPktHandleConnecting
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockPendedRequestGet
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockSelectRun
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockSelectRun
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]Socket 2, 0x00000001(CONNECTING) --> 0x00000000(CLOSE)
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockRxPktHandleConnecting
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockRxPktInsert
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockRxPktInsert
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]<-- VIOSockRxVqProcess
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]--> VIOSockTxVqProcess
[1]0000.0000::02/25/2021-10:02:14.111 [viosock.sys]Free packet 0x00000001(REQUEST) (3:435593588 --> 2:8080)
[1]0000.0000::02/25/2021-10:02:14.112 [viosock.sys]--> VIOSockTxDequeue
[1]0000.0000::02/25/2021-10:02:14.112 [viosock.sys]<-- VIOSockTxDequeue
[1]0000.0000::02/25/2021-10:02:14.112 [viosock.sys]<-- VIOSockTxVqProcess
[1]0000.0000::02/25/2021-10:02:14.112 [viosock.sys]<-- VIOSockInterruptDpc

Regards, kcrazy