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

Curl over vsocket hangs in VIOSockSelect #919

Closed readysloth closed 1 year ago

readysloth commented 1 year ago

Describe the bug Sent request hangs indefinitely.

To Reproduce Steps to reproduce the behaviour:

  1. Clone curl and checkout to 10413994d6713eefbeb022667d9f33f1e308c117
  2. Apply this patch
  3. Configure curl
  4. Build curl curl --build . --config Debug
  5. Build test program gcc -Icurl/include -Lpath/to/folder/with/libcurl-d.lib -l libcurl-d -o vsock-curl-test.exe (I use mingw)
  6. Open vSock-server in linux: socat -dd VSOCK-LISTEN:6667,crlf,reuseaddr,fork SYSTEM:"echo HTTP/1.1 200 OK; echo Content-Type\: text/plain"
  7. In windows run vsock-curl-test.exe

Expected behavior vsock-curl-test.exe outputs

HTTP/1.1 200 OK;
Content-Type: text/plain

Host:

VM:

Additional context I'm trying to build client-server HTTP application over vSockets that uses curl. As a minimal testing environment I chose socat to mimic vSocket HTTP-server and curl as a client HTTP library.

Also, I attach TraceView logs of socat server, viosocklib.dll and viosock.sys:

socat:

$ socat -dd VSOCK-LISTEN:6667,crlf,reuseaddr,fork SYSTEM:"echo HTTP/1.1 200 OK;
echo Content-Type\: text/plain"
  2023/05/31 15:11:35 socat[58767] W ioctl(-1, IOCTL_VM_SOCKETS_GET_LOCAL_CID, ...): Bad file
descriptor
  2023/05/31 15:11:35 socat[58767] N listening on AF=40 cid:4294967295 port:6667
  2023/05/31 15:11:42 socat[58767] N accepting connection from AF=40 cid:3 port:761090288 on AF=40 cid:2 port:6667
  2023/05/31 15:11:42 socat[58767] N forked off child process 59100
  2023/05/31 15:11:42 socat[58767] N listening on AF=40 cid:4294967295 port:6667
  2023/05/31 15:11:42 socat[59100] N forking off child, using socket for reading and writing
  2023/05/31 15:11:42 socat[59100] N forked off child process 59101
  2023/05/31 15:11:42 socat[59100] N forked off child process 59101
  2023/05/31 15:11:42 socat[59100] N starting data transfer loop with FDs [6,6] and [5,5]
  2023/05/31 15:11:42 socat[59100] N childdied(): handling signal 17
  2023/05/31 15:11:42 socat[59100] N socket 2 (fd 5) is at EOF
  2023/05/31 15:11:42 socat[59100] N exiting with status 0
  2023/05/31 15:11:42 socat[58767] N childdied(): handling signal 17

viosocklib.dll and viosock.sys:

viosocklib.dll 05\31\2023-12:11:41:570 --> WSPStartup
viosocklib.dll 05\31\2023-12:11:41:570 <-- WSPStartup
viosocklib.dll 05\31\2023-12:11:41:570 --> VIOSockSocket
viosocklib.dll 05\31\2023-12:11:41:570 <-- VIOSockSocket
viosocklib.dll 05\31\2023-12:11:41:571 --> VIOSockIoctl, socket: 00000000000000EC
viosocklib.dll 05\31\2023-12:11:41:571 <-- VIOSockIoctl
viosocklib.dll 05\31\2023-12:11:41:571 --> VIOSockConnect, socket: 00000000000000EC
viosocklib.dll 05\31\2023-12:11:41:572 NtDeviceIoControlFile failed: 10035
viosocklib.dll 05\31\2023-12:11:41:572 VIOSockDeviceControl failed: 10035
viosocklib.dll 05\31\2023-12:11:41:572 <-- VIOSockConnect
viosocklib.dll 05\31\2023-12:11:41:572 --> VIOSockGetSockOpt, socket: 00000000000000EC
viosocklib.dll 05\31\2023-12:11:41:572 <-- VIOSockGetSockOpt
viosocklib.dll 05\31\2023-12:11:41:572 --> VIOSockSend, socket: 00000000000000EC
viosocklib.dll 05\31\2023-12:11:41:572 <-- VIOSockSend
viosocklib.dll 05\31\2023-12:11:41:572 --> VIOSockEventSelect, socket: 00000000000000EC
viosocklib.dll 05\31\2023-12:11:41:572 <-- VIOSockEventSelect
viosocklib.dll 05\31\2023-12:11:41:572 --> VIOSockSelect # hangs forever

viosock.sys 05\31\2023-12:11:38:739 --> VIOSockSelectCancel
viosock.sys 05\31\2023-12:11:38:739 --> VIOSockSelectWorkitem
viosock.sys 05\31\2023-12:11:38:739 --> VIOSockSelectCleanupPkt, status: 0xc0000120
viosock.sys 05\31\2023-12:11:38:739 <-- VIOSockSelectWorkitem
viosock.sys 05\31\2023-12:11:38:754 --> VIOSockClose
viosock.sys 05\31\2023-12:11:38:754 --> VIOSockBoundRemove
viosock.sys 05\31\2023-12:11:38:754 Socket 35, peershutdown: 3
viosock.sys 05\31\2023-12:11:38:754 --> VIOSockTxEnqueue
viosock.sys 05\31\2023-12:11:38:754 --> VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:38:754 --> VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:38:754 --> VIOSockTxPktInsert
viosock.sys 05\31\2023-12:11:38:754 Send packet 0x00000003(RST) (3:761090287 --> 2:6667), len: 0, flags: 0, buf_alloc: 262144, fwd_cnt: 0
viosock.sys 05\31\2023-12:11:38:754 <-- VIOSockTxPktInsert
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockTxEnqueue
viosock.sys 05\31\2023-12:11:38:755 Socket 35, 0x00000002(CONNECTED) --> 0x00000000(CLOSE)
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockPendedRequestGet, Socket 35
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockPendedRequestGet, pended request: 0000000000000000
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockTxCleanup
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockReadCleanupCb
viosock.sys 05\31\2023-12:11:38:755 Socket 35 closed
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockClose
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockInterruptIsr
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockInterruptIsr, serviced: TRUE
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockInterruptDpc
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:38:755 Free packet 0x00000003(RST) (3:761090287 --> 2:6667)
viosock.sys 05\31\2023-12:11:38:755 --> VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:38:755 <-- VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:38:756 --> VIOSockClose
viosock.sys 05\31\2023-12:11:38:756 Control socket 36 closed
viosock.sys 05\31\2023-12:11:41:570 VIOSockCreate
viosock.sys 05\31\2023-12:11:41:570 Socket 37 (00001EF55E33AD38) initializing
viosock.sys 05\31\2023-12:11:41:570 --> VIOSockReadSocketQueueInit
viosock.sys 05\31\2023-12:11:41:570 <-- VIOSockCreate
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockEvtIoDeviceControl
viosock.sys 05\31\2023-12:11:41:571 <-- VIOSockDeviceControl, code: 0x08012030, socket 37
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockIoctl
viosock.sys 05\31\2023-12:11:41:571 dwIoControlCode: 0x8004667e
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockSetNonBlocking, bNonBlocking: 1
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockTxCleanup
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockReadDequeueCb
viosock.sys 05\31\2023-12:11:41:571 The read queue is empty, exiting from VIOSockReadDequeueCb
viosock.sys 05\31\2023-12:11:41:571 <-- VIOSockIoctl, status: 0x00000000
viosock.sys 05\31\2023-12:11:41:571 <-- VIOSockDeviceControl, status: 0x00000000
viosock.sys 05\31\2023-12:11:41:571 <-- VIOSockEvtIoDeviceControl, status: 0x00000000
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockEvtIoDeviceControl
viosock.sys 05\31\2023-12:11:41:571 <-- VIOSockDeviceControl, code: 0x08012008, socket 37
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockConnect
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockBoundAdd
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockEventClearBit, uClearBit: 0x4
viosock.sys 05\31\2023-12:11:41:571 Socket 37, 0x00000000(CLOSE) --> 0x00000001(CONNECTING)
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockTxEnqueue
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:41:571 --> VIOSockTxPktInsert
viosock.sys 05\31\2023-12:11:41:571 Send packet 0x00000001(REQUEST) (3:761090288 --> 2:6667), len: 0, flags: 0, buf_alloc: 262144, fwd_cnt: 0
viosock.sys 05\31\2023-12:11:41:571 <-- VIOSockTxPktInsert
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockTxEnqueue
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockConnect, status: 0xc00000d8
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockDeviceControl, status: 0xc00000d8
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockEvtIoDeviceControl, status: 0xc00000d8
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockInterruptIsr
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockInterruptIsr, serviced: TRUE
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockInterruptDpc
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:41:572 Recv packet 0x00000002(RESPONSE) (3:761090288 <-- 2:6667), len: 0, flags: 0, buf_alloc: 262144, fwd_cnt: 0
viosock.sys 05\31\2023-12:11:41:572 No connected socket found
viosock.sys 05\31\2023-12:11:41:572 Socket 37 found, state 0x00000001(CONNECTING)
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockRxPktHandleConnecting
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockPendedRequestGet, Socket 37
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockPendedRequestGet, pended request: 0000000000000000
viosock.sys 05\31\2023-12:11:41:572 Socket 37, 0x00000001(CONNECTING) --> 0x00000002(CONNECTED)
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockEventSetBit, uSetBit: 0x4
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockSelectRun
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockEventSetBit, uSetBit: 0x1
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockSelectRun
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockRxPktHandleConnecting
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockEvtIoDeviceControl
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockDeviceControl, code: 0x08012028, socket 37
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockGetSockOpt
viosock.sys 05\31\2023-12:11:41:572 OptName: 0x1008
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockGetSockOpt, status: 0x00000000
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockDeviceControl, status: 0x00000000
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockEvtIoDeviceControl, status: 0x00000000
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:41:572 Free packet 0x00000001(REQUEST) (3:761090288 --> 2:6667)
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockEvtIoDeviceControl
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockDeviceControl, code: 0x0801201c, socket 37
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockEventSelect
viosock.sys 05\31\2023-12:11:41:572 --> VIOSockSetNonBlocking, bNonBlocking: 1
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockDeviceControl, status: 0x00000000
viosock.sys 05\31\2023-12:11:41:572 <-- VIOSockEvtIoDeviceControl, status: 0x00000000
viosock.sys 05\31\2023-12:11:41:573 VIOSockCreate
viosock.sys 05\31\2023-12:11:41:573 Control socket 38 (00001EF561440FD8) initializing
viosock.sys 05\31\2023-12:11:41:573 <-- VIOSockCreate
viosock.sys 05\31\2023-12:11:41:573 --> VIOSockEvtIoDeviceControl
viosock.sys 05\31\2023-12:11:41:573 --> VIOSockSelect
viosock.sys 05\31\2023-12:11:41:573 --> VIOSockSelectCheckPkt
viosock.sys 05\31\2023-12:11:41:573 <-- VIOSockSelect
viosock.sys 05\31\2023-12:11:41:573 <-- VIOSockEvtIoDeviceControl, status: 0x00000103
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockInterruptIsr
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockInterruptIsr, serviced: TRUE
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockInterruptIsr
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockInterruptIsr, serviced: TRUE
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockInterruptDpc
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:41:575 Recv packet 0x00000005(RW) (3:761090288 <-- 2:6667), len: 43, flags: 0, buf_alloc: 262144, fwd_cnt: 0
viosock.sys 05\31\2023-12:11:41:575 Recv packet 0x00000004(SHUTDOWN) (3:761090288 <-- 2:6667), len: 0, flags: 2, buf_alloc: 262144, fwd_cnt: 0
viosock.sys 05\31\2023-12:11:41:575 Socket 37 found, state 0x00000002(CONNECTED)
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockRxPktHandleConnected
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockRxPktEnqueueCb
viosock.sys 05\31\2023-12:11:41:575 RxCb enqueued: 43 bytes
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockRxPktEnqueueCb
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockEventSetBit, uSetBit: 0x0
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockSelectRun
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockReadDequeueCb
viosock.sys 05\31\2023-12:11:41:575 The read queue is empty, exiting from VIOSockReadDequeueCb
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockRxPktHandleConnected
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:41:575 Socket 37 found, state 0x00000002(CONNECTED)
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockRxPktHandleConnected
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockShutdownFromPeer, bRes: 0
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockRxPktHandleConnected
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:41:575 --> VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:41:575 <-- VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:42:75  --> VIOSockInterruptIsr
viosock.sys 05\31\2023-12:11:42:75  <-- VIOSockInterruptIsr, serviced: TRUE
viosock.sys 05\31\2023-12:11:42:75  --> VIOSockInterruptDpc
viosock.sys 05\31\2023-12:11:42:75  --> VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:42:75  <-- VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:42:75  --> VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:42:75  Recv packet 0x00000004(SHUTDOWN) (3:761090288 <-- 2:6667), len: 0, flags: 3, buf_alloc: 262144, fwd_cnt: 0
viosock.sys 05\31\2023-12:11:42:75  Socket 37 found, state 0x00000002(CONNECTED)
viosock.sys 05\31\2023-12:11:42:75  --> VIOSockRxPktHandleConnected
viosock.sys 05\31\2023-12:11:42:75  <-- VIOSockShutdownFromPeer, bRes: 1
viosock.sys 05\31\2023-12:11:42:75  <-- VIOSockRxPktHandleConnected
viosock.sys 05\31\2023-12:11:42:75  --> VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:42:75  <-- VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:42:75  <-- VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:42:75  --> VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:42:75  --> VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:42:75  <-- VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:42:75  <-- VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockInterruptIsr
viosock.sys 05\31\2023-12:11:50:270 <-- VIOSockInterruptIsr, serviced: TRUE
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockInterruptDpc
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:50:270 <-- VIOSockEvtVqProcess
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:50:270 Recv packet 0x00000003(RST) (3:761090288 <-- 2:6667), len: 0, flags: 0, buf_alloc: 262144, fwd_cnt: 0
viosock.sys 05\31\2023-12:11:50:270 Socket 37 found, state 0x00000002(CONNECTED)
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockRxPktHandleConnected
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockDoClose
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockEventSetBit, uSetBit: 0x5
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockSelectRun
viosock.sys 05\31\2023-12:11:50:270 <-- VIOSockRxPktHandleConnected
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:50:270 <-- VIOSockRxPktInsert
viosock.sys 05\31\2023-12:11:50:270 <-- VIOSockRxVqProcess
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockTxVqProcess
viosock.sys 05\31\2023-12:11:50:270 --> VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:50:270 <-- VIOSockTxDequeue
viosock.sys 05\31\2023-12:11:50:270 <-- VIOSockTxVqProcess
readysloth commented 1 year ago

Simple sequence of socket-connect-send-recv works alright, so I don't really know how much it is relatable for drivers, but if you will find problem, I would be happy to hear, what caused it

readysloth commented 1 year ago

It turns out, that if you use CURLOPT_OPENSOCKETFUNCTION to create socket and connect in callback, and CURLOPT_SOCKOPTFUNCTION to just return CURL_SOCKOPT_ALREADY_CONNECTED then it works as expected.

Not tested on vanilla curl yet, but solves my problem.