8:49 a.m.
Hi List,
I have a question about some troubles I am having with virsh on Windows
x64. I am currently running a KVM server on a linux box and need to
allow Windows clients to access it. I have set up the server for access
with:
```
listen_tls = 0
listen_tcp = 1
auth_tcp = "none"
```
to allow for remote access while testing things. I have verified that I
can connect remotely from other linux machines, but my windows machine
always reports:
```
error: failed to connect to the hypervisor
error: An error occurred, but the cause is unknown
```
On the server side I see:
```
10435: error : virNetSocketReadWire:1793 : Cannot recv data: Connection
reset by peer
```
This happens no matter what build of virsh for windows I am using. I
have tried 3 different mingw-64 builds and versions and am about to just
build my own from scratch. I have verified that it is not the firewall
or the version of Windows I am using. I am also able to use virsh
within a docker or from the Windows Subsystem for Linux bash prompt.
Any ideas as to what could be causing this connection reset? It happens
as soon as a connection attempt occurs and I am running out of idea.
Thanks!
Charles Bancroft
Principal Scientist
Siege Technologies
3:48 a.m.
On Mon, Apr 17, 2017 at 09:49:01AM -0400, Charles Bancroft wrote:
Hi List,
I have a question about some troubles I am having with virsh on Windows
x64. I am currently running a KVM server on a linux box and need to
allow Windows clients to access it. I have set up the server for access
with:
```
listen_tls = 0
listen_tcp = 1
auth_tcp = "none"
```
I assume you're merely doing this for sake of testing / debugging.
This opens libvirtd connections with no access control, which is
equivalent to running an SSH server allowing root logins with no
password. ie you never want to do this in real deployments.
to allow for remote access while testing things. I have verified
that I
can connect remotely from other linux machines, but my windows machine
always reports:
```
error: failed to connect to the hypervisor
error: An error occurred, but the cause is unknown
```
On the server side I see:
```
10435: error : virNetSocketReadWire:1793 : Cannot recv data: Connection
reset by peer
```
This happens no matter what build of virsh for windows I am using. I
have tried 3 different mingw-64 builds and versions and am about to just
build my own from scratch. I have verified that it is not the firewall
or the version of Windows I am using. I am also able to use virsh
within a docker or from the Windows Subsystem for Linux bash prompt.
Any ideas as to what could be causing this connection reset? It happens
as soon as a connection attempt occurs and I am running out of idea.
When running virsh, set 'LIBVIRT_DEBUG=1' environment variable, so we
can see some debug logs, which might give a hint as to what is wrong.
Regards,
Daniel
--
|: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org -o- http://virt-manager.org :|
|: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|
7:02 a.m.
On 4/18/2017 4:48 AM, Daniel P. Berrange wrote:
On Mon, Apr 17, 2017 at 09:49:01AM -0400, Charles Bancroft wrote:
> Hi List,
>
> I have a question about some troubles I am having with virsh on Windows
> x64. I am currently running a KVM server on a linux box and need to
> allow Windows clients to access it. I have set up the server for access
> with:
>
> ```
> listen_tls = 0
> listen_tcp = 1
> auth_tcp = "none"
> ```
I assume you're merely doing this for sake of testing / debugging.
This opens libvirtd connections with no access control, which is
equivalent to running an SSH server allowing root logins with no
password. ie you never want to do this in real deployments.
Yes, the final version
will most certainly be using TLS or ssh. This
was just a proof of concept to validate our
code would work on windows.
> to allow for remote access while testing things. I have verified
that I
> can connect remotely from other linux machines, but my windows machine
> always reports:
>
> ```
> error: failed to connect to the hypervisor
> error: An error occurred, but the cause is unknown
> ```
>
> On the server side I see:
> ```
> 10435: error : virNetSocketReadWire:1793 : Cannot recv data: Connection
> reset by peer
> ```
>
> This happens no matter what build of virsh for windows I am using. I
> have tried 3 different mingw-64 builds and versions and am about to just
> build my own from scratch. I have verified that it is not the firewall
> or the version of Windows I am using. I am also able to use virsh
> within a docker or from the Windows Subsystem for Linux bash prompt.
>
> Any ideas as to what could be causing this connection reset? It happens
> as soon as a connection attempt occurs and I am running out of idea.
When running virsh, set 'LIBVIRT_DEBUG=1' environment variable, so we
can see some debug logs, which might give a hint as to what is wrong.
Here is the log of my execution run. Looks like there was an error on
the socket, but nothing useful came back. I have also attached a
tcpdump log of the network traffic
to show it is the client end(192.168.1.10) issuing the reset after
receiving some data from the server (192.168.1.113)
``` Execution log
$ LIBVIRT_DEBUG=1 ./virsh -c qemu+tcp://192.168.1.113/system -d0
2017-04-18 11:46:23.778+0000: 1: info : libvirt version: 3.1.0
2017-04-18 11:46:23.778+0000: 1: info : hostname: <HOSTNAME>
2017-04-18 11:46:23.778+0000: 1: debug : virGlobalInit:386 : register
drivers
2017-04-18 11:46:23.782+0000: 1: debug : virRegisterConnectDriver:684 :
driver=000000006cdc19e0 name=Test
2017-04-18 11:46:23.782+0000: 1: debug : virRegisterConnectDriver:695 :
registering Test as driver 0
2017-04-18 11:46:23.782+0000: 1: debug : virRegisterConnectDriver:684 :
driver=000000006cdc24e0 name=remote
2017-04-18 11:46:23.782+0000: 1: debug : virRegisterConnectDriver:695 :
registering remote as driver 1
2017-04-18 11:46:23.790+0000: 1: debug : virEventRegisterDefaultImpl:267
: registering default event implementation
2017-04-18 11:46:23.790+0000: 1: debug : virEventPollAddHandle:115 :
Used 0 handle slots, adding at least 10 more
2017-04-18 11:46:23.790+0000: 1: debug : virEventPollInterruptLocked:722
: Skip interrupt, 0 0
2017-04-18 11:46:23.790+0000: 1: info : virEventPollAddHandle:140 :
EVENT_POLL_ADD_HANDLE: watch=1 fd=3 events=1 cb=000000006cc17d30
opaque=0000000000000000 ff=0000000000000000
2017-04-18 11:46:23.790+0000: 1: debug : virEventRegisterImpl:234 :
addHandle=000000006cc17d70 updateHandle=000000006cc17f80
removeHandle=000000006cc18100 addTimeout=000000006cc18280
updateTimeout=000000006cc18470 removeTimeout=000000006cc18640
2017-04-18 11:46:23.790+0000: 1: debug : virEventPollAddTimeout:230 :
Used 0 timeout slots, adding at least 10 more
2017-04-18 11:46:23.790+0000: 1: debug : virEventPollInterruptLocked:722
: Skip interrupt, 0 0
2017-04-18 11:46:23.790+0000: 1: info : virEventPollAddTimeout:253 :
EVENT_POLL_ADD_TIMEOUT: timer=1 frequency=-1 cb=0000000000432da0
opaque=000000000069fbf0 ff=0000000000000000
2017-04-18 11:46:23.790+0000: 1: debug : virConnectOpenAuth:1245 :
name=qemu+tcp://192.168.1.113/system, auth=000000006cdc1780, flags=0
2017-04-18 11:46:23.790+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000faeb10 classname=virConnect
2017-04-18 11:46:23.790+0000: 2: debug : virThreadJobSet:99 : Thread 2
is now running job vshEventLoop
2017-04-18 11:46:23.790+0000: 2: debug : virEventRunDefaultImpl:311 :
running default event implementation
2017-04-18 11:46:23.790+0000: 2: debug : virEventPollCleanupTimeouts:525
: Cleanup 1
2017-04-18 11:46:23.790+0000: 1: debug : virConfGetValueStringList:981 :
Get value string list 0000000000000000 0
2017-04-18 11:46:23.790+0000: 2: debug : virEventPollCleanupHandles:574
: Cleanup 1
2017-04-18 11:46:23.790+0000: 2: debug : virEventPollMakePollFDs:401 :
Prepare n=0 w=1, f=3 e=1 d=0
2017-04-18 11:46:23.790+0000: 1: debug : virConnectOpenInternal:1033 :
Split "qemu+tcp://192.168.1.113/system" to URI components:
scheme qemu+tcp
server 192.168.1.113
user <null>
port 0
path /system
2017-04-18 11:46:23.790+0000: 2: debug :
virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers
2017-04-18 11:46:23.790+0000: 1: debug : virConnectOpenInternal:1083 :
trying driver 0 (Test) ...
2017-04-18 11:46:23.790+0000: 2: debug :
virEventPollCalculateTimeout:371 : No timeout is pending
2017-04-18 11:46:23.790+0000: 1: debug : virConnectOpenInternal:1098 :
driver 0 Test returned DECLINED
2017-04-18 11:46:23.790+0000: 2: info : virEventPollRunOnce:640 :
EVENT_POLL_RUN: nhandles=1 timeout=-1
2017-04-18 11:46:23.790+0000: 1: debug : virConnectOpenInternal:1083 :
trying driver 1 (remote) ...
2017-04-18 11:46:23.790+0000: 1: debug : doRemoteOpen:907 : proceeding
with name = qemu:///system
2017-04-18 11:46:23.790+0000: 1: debug : doRemoteOpen:916 : Connecting
with transport 5
2017-04-18 11:46:23.875+0000: 1: debug : virNetSocketNew:235 :
localAddr=000000000069f540 remoteAddr=000000000069f5d0 fd=5 errfd=-1 pid=0
2017-04-18 11:46:23.875+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000faebe0 classname=virNetSocket
2017-04-18 11:46:23.875+0000: 1: info : virNetSocketNew:291 :
RPC_SOCKET_NEW: sock=0000000000faebe0 fd=5 errfd=-1 pid=0
localAddr=192.168.1.10;61441, remoteAddr=192.168.1.113;16509
2017-04-18 11:46:23.875+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000faa9a0 classname=virNetClient
2017-04-18 11:46:23.875+0000: 1: info : virNetClientNew:328 :
RPC_CLIENT_NEW: client=0000000000faa9a0 sock=0000000000faebe0
2017-04-18 11:46:23.875+0000: 1: info : virObjectRef:296 : OBJECT_REF:
obj=0000000000faa9a0
2017-04-18 11:46:23.875+0000: 1: info : virObjectRef:296 : OBJECT_REF:
obj=0000000000faebe0
2017-04-18 11:46:23.875+0000: 1: debug : virEventPollInterruptLocked:726
: Interrupting
2017-04-18 11:46:23.875+0000: 1: info : virEventPollAddHandle:140 :
EVENT_POLL_ADD_HANDLE: watch=2 fd=5 events=1 cb=000000006cd636b0
opaque=0000000000faebe0 ff=000000006cd63660
2017-04-18 11:46:23.875+0000: 1: debug : virKeepAliveNew:199 :
client=0000000000faa9a0, interval=-1, count=0
2017-04-18 11:46:23.875+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000fba620 classname=virKeepAlive
2017-04-18 11:46:23.875+0000: 1: info : virKeepAliveNew:218 :
RPC_KEEPALIVE_NEW: ka=0000000000fba620 client=0000000000faa9a0
2017-04-18 11:46:23.875+0000: 1: info : virObjectRef:296 : OBJECT_REF:
obj=0000000000faa9a0
2017-04-18 11:46:23.875+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000fb2760 classname=virConnectCloseCallbackData
2017-04-18 11:46:23.875+0000: 1: info : virObjectRef:296 : OBJECT_REF:
obj=0000000000fb2760
2017-04-18 11:46:23.875+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000fb2460 classname=virNetClientProgram
2017-04-18 11:46:23.875+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000fb2220 classname=virNetClientProgram
2017-04-18 11:46:23.875+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000fb24a0 classname=virNetClientProgram
2017-04-18 11:46:23.875+0000: 1: info : virObjectRef:296 : OBJECT_REF:
obj=0000000000fb2460
2017-04-18 11:46:23.875+0000: 1: info : virObjectRef:296 : OBJECT_REF:
obj=0000000000fb2220
2017-04-18 11:46:23.875+0000: 1: info : virObjectRef:296 : OBJECT_REF:
obj=0000000000fb24a0
2017-04-18 11:46:23.875+0000: 1: debug : doRemoteOpen:1170 : Trying
authentication
2017-04-18 11:46:23.875+0000: 1: debug : virNetMessageNew:46 :
msg=0000000000fba700 tracked=0
2017-04-18 11:46:23.875+0000: 1: debug : virNetMessageEncodePayload:386
: Encode length as 28
2017-04-18 11:46:23.875+0000: 1: info : virNetClientSendInternal:2104 :
RPC_CLIENT_MSG_TX_QUEUE: client=0000000000faa9a0 len=28 prog=536903814
vers=1 proc=66 type=0 status=0 serial=0
2017-04-18 11:46:23.875+0000: 1: debug : virNetClientCallNew:2057 : New
call 0000000000fd7ad0: msg=0000000000fba700, expectReply=1, nonBlock=0
2017-04-18 11:46:23.875+0000: 1: debug : virNetClientIO:1866 : Outgoing
message prog=536903814 version=1 serial=0 proc=66 type=0 length=28
dispatch=0000000000000000
2017-04-18 11:46:23.875+0000: 1: debug : virNetClientIO:1925 : We have
the buck head=0000000000fd7ad0 call=0000000000fd7ad0
2017-04-18 11:46:23.875+0000: 1: info : virEventPollUpdateHandle:152 :
EVENT_POLL_UPDATE_HANDLE: watch=2 events=0
2017-04-18 11:46:23.875+0000: 1: debug : virEventPollInterruptLocked:726
: Interrupting
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollRunOnce:650 : Poll
got 1 event(s)
2017-04-18 11:46:23.876+0000: 2: debug :
virEventPollDispatchTimeouts:432 : Dispatch 1
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollDispatchHandles:478
: Dispatch 1
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollDispatchHandles:492
: i=0 w=1
2017-04-18 11:46:23.876+0000: 2: info : virEventPollDispatchHandles:506
: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollCleanupTimeouts:525
: Cleanup 1
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollCleanupHandles:574
: Cleanup 2
2017-04-18 11:46:23.876+0000: 2: debug : virEventRunDefaultImpl:311 :
running default event implementation
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollCleanupTimeouts:525
: Cleanup 1
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollCleanupHandles:574
: Cleanup 2
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollMakePollFDs:401 :
Prepare n=0 w=1, f=3 e=1 d=0
2017-04-18 11:46:23.876+0000: 2: debug : virEventPollMakePollFDs:401 :
Prepare n=1 w=2, f=5 e=0 d=0
2017-04-18 11:46:23.876+0000: 2: debug :
virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers
2017-04-18 11:46:23.876+0000: 2: debug :
virEventPollCalculateTimeout:371 : No timeout is pending
2017-04-18 11:46:23.876+0000: 2: info : virEventPollRunOnce:640 :
EVENT_POLL_RUN: nhandles=1 timeout=-1
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollRunOnce:650 : Poll
got 1 event(s)
2017-04-18 11:46:23.877+0000: 2: debug :
virEventPollDispatchTimeouts:432 : Dispatch 1
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollDispatchHandles:478
: Dispatch 1
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollDispatchHandles:492
: i=0 w=1
2017-04-18 11:46:23.877+0000: 2: info : virEventPollDispatchHandles:506
: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollCleanupTimeouts:525
: Cleanup 1
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollCleanupHandles:574
: Cleanup 2
2017-04-18 11:46:23.877+0000: 2: debug : virEventRunDefaultImpl:311 :
running default event implementation
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollCleanupTimeouts:525
: Cleanup 1
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollCleanupHandles:574
: Cleanup 2
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollMakePollFDs:401 :
Prepare n=0 w=1, f=3 e=1 d=0
2017-04-18 11:46:23.877+0000: 2: debug : virEventPollMakePollFDs:401 :
Prepare n=1 w=2, f=5 e=0 d=0
2017-04-18 11:46:23.877+0000: 2: debug :
virEventPollCalculateTimeout:338 : Calculate expiry of 1 timers
2017-04-18 11:46:23.877+0000: 2: debug :
virEventPollCalculateTimeout:371 : No timeout is pending
2017-04-18 11:46:23.877+0000: 2: info : virEventPollRunOnce:640 :
EVENT_POLL_RUN: nhandles=1 timeout=-1
2017-04-18 11:46:23.879+0000: 1: debug : virNetClientMarkClose:776 :
client=0000000000faa9a0, reason=1
2017-04-18 11:46:23.879+0000: 1: info : virEventPollRemoveHandle:186 :
EVENT_POLL_REMOVE_HANDLE: watch=2
2017-04-18 11:46:23.879+0000: 1: debug : virEventPollRemoveHandle:199 :
mark delete 1 5
2017-04-18 11:46:23.879+0000: 1: debug : virEventPollInterruptLocked:726
: Interrupting
2017-04-18 11:46:23.879+0000: 1: debug : virNetClientIOEventLoop:1756 :
error on socket: (NULL)
2017-04-18 11:46:23.879+0000: 1: debug :
virNetClientIOEventLoopPassTheBuck:1561 : Giving up the buck
0000000000fd7ad0
2017-04-18 11:46:23.879+0000: 1: debug :
virNetClientIOEventLoopPassTheBuck:1575 : No thread to pass the buck to
2017-04-18 11:46:23.879+0000: 1: debug : virNetClientCloseLocked:796 :
client=0000000000faa9a0, sock=0000000000faebe0, reason=1
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000faebe0
2017-04-18 11:46:23.879+0000: 1: info : virObjectRef:296 : OBJECT_REF:
obj=0000000000faa9a0
2017-04-18 11:46:23.879+0000: 1: info : virKeepAliveStop:310 :
RPC_KEEPALIVE_STOP: ka=0000000000fba620 client=0000000000faa9a0
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fba620
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0000000000fba620
2017-04-18 11:46:23.879+0000: 1: info : virKeepAliveDispose:230 :
RPC_KEEPALIVE_DISPOSE: ka=0000000000fba620
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000faa9a0
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000faa9a0
2017-04-18 11:46:23.879+0000: 1: debug : virNetClientIO:1955 : All done
with our call head=0000000000000000 call=0000000000fd7ad0 rv=-1
2017-04-18 11:46:23.879+0000: 1: debug : virNetMessageFree:87 :
msg=0000000000fba700 nfds=0 cb=0000000000000000
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fb2460
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fb2220
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fb24a0
2017-04-18 11:46:23.879+0000: 1: debug : virNetClientCloseInternal:840 :
client=0000000000faa9a0 wantclose=0
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000faa9a0
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fb2760
2017-04-18 11:46:23.879+0000: 1: debug : virConnectOpenInternal:1098 :
driver 1 remote returned ERROR
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000faeb10
2017-04-18 11:46:23.879+0000: 1: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0000000000faeb10
error: failed to connect to the hypervisor
error: An error occurred, but the cause is unknown
2017-04-18 11:46:23.879+0000: 1: debug : virFileMakePathHelper:2911 :
path=C:\Users\cbancroft\AppData\Local\Microsoft\Windows\INetCache/virsh
mode=0755
2017-04-18 11:46:23.880+0000: 1: debug : virEventPollInterruptLocked:726
: Interrupting
2017-04-18 11:46:23.880+0000: 1: info : virEventPollAddTimeout:253 :
EVENT_POLL_ADD_TIMEOUT: timer=2 frequency=0 cb=00000000004015b0
opaque=0000000000000000 ff=0000000000000000
2017-04-18 11:46:23.881+0000: 2: debug : virEventPollRunOnce:650 : Poll
got 1 event(s)
2017-04-18 11:46:23.881+0000: 2: debug :
virEventPollDispatchTimeouts:432 : Dispatch 2
2017-04-18 11:46:23.881+0000: 2: info : virEventPollDispatchTimeouts:455
: EVENT_POLL_DISPATCH_TIMEOUT: timer=2
2017-04-18 11:46:23.881+0000: 2: debug : virEventPollDispatchHandles:478
: Dispatch 1
2017-04-18 11:46:23.881+0000: 2: debug : virEventPollDispatchHandles:492
: i=0 w=1
2017-04-18 11:46:23.881+0000: 2: info : virEventPollDispatchHandles:506
: EVENT_POLL_DISPATCH_HANDLE: watch=1 events=1
2017-04-18 11:46:23.881+0000: 2: debug : virEventPollCleanupTimeouts:525
: Cleanup 2
2017-04-18 11:46:23.881+0000: 2: debug : virEventPollCleanupHandles:574
: Cleanup 2
2017-04-18 11:46:23.881+0000: 2: info : virEventPollCleanupHandles:587 :
EVENT_POLL_PURGE_HANDLE: watch=2
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000faa9a0
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0000000000faa9a0
2017-04-18 11:46:23.881+0000: 2: info : virNetClientDispose:744 :
RPC_CLIENT_DISPOSE: client=0000000000faa9a0
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fb2760
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0000000000fb2760
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fb2460
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0000000000fb2460
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fb2220
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0000000000fb2220
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000fb24a0
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0000000000fb24a0
2017-04-18 11:46:23.881+0000: 2: debug : virFileClose:109 : Closed fd 7
2017-04-18 11:46:23.881+0000: 2: debug : virFileClose:109 : Closed fd 6
2017-04-18 11:46:23.881+0000: 2: debug : virNetMessageClear:74 :
msg=0000000000faa9e8 nfds=0
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:259 :
OBJECT_UNREF: obj=0000000000faebe0
2017-04-18 11:46:23.881+0000: 2: info : virObjectUnref:261 :
OBJECT_DISPOSE: obj=0000000000faebe0
2017-04-18 11:46:23.881+0000: 2: info : virNetSocketDispose:1322 :
RPC_SOCKET_DISPOSE: sock=0000000000faebe0
2017-04-18 11:46:23.881+0000: 2: debug : virFileClose:109 : Closed fd 5
2017-04-18 11:46:23.881+0000: 2: debug : virProcessAbort:210 : failed to
reap child 0, abandoning it
2017-04-18 11:46:23.881+0000: 2: debug : virThreadJobClear:124 : Thread
2 finished job vshEventLoop with ret=0
2017-04-18 11:46:23.881+0000: 1: info : virEventPollRemoveTimeout:305 :
EVENT_POLL_REMOVE_TIMEOUT: timer=2
2017-04-18 11:46:23.881+0000: 1: debug : virEventPollInterruptLocked:722
: Skip interrupt, 0 2
2017-04-18 11:46:23.881+0000: 1: info : virEventPollRemoveTimeout:305 :
EVENT_POLL_REMOVE_TIMEOUT: timer=1
2017-04-18 11:46:23.881+0000: 1: debug : virEventPollInterruptLocked:722
: Skip interrupt, 0 2
```
``` tcpdump output
listening on any, link-type LINUX_SLL (Linux cooked), capture size
262144 bytes
08:00:17.591226 IP 192.168.1.10.62191 > 192.168.1.113.16509: Flags [S],
seq 3731190386, win 8192, options [mss 1460,nop,wscale
8,nop,nop,sackOK], length 0
08:00:17.591335 IP 192.168.1.113.16509 > 192.168.1.10.62191: Flags [S.],
seq 264496333, ack 3731190387, win 29200, options [mss
1460,nop,nop,sackOK,nop,wscale 7], length 0
08:00:17.593900 IP 192.168.1.10.62191 > 192.168.1.113.16509: Flags [.],
ack 1, win 64, length 0
08:00:17.595154 IP 192.168.1.10.62191 > 192.168.1.113.16509: Flags [P.],
seq 1:29, ack 1, win 64, length 28
08:00:17.595219 IP 192.168.1.113.16509 > 192.168.1.10.62191: Flags [.],
ack 29, win 229, length 0
08:00:17.595441 IP 192.168.1.113.16509 > 192.168.1.10.62191: Flags [P.],
seq 1:37, ack 29, win 229, length 36
08:00:17.602079 IP 192.168.1.10.62191 > 192.168.1.113.16509: Flags [R.],
seq 29, ack 37, win 0, length 0
```
Thanks again for the assistance
-Charles Bancroft
7:41 a.m.
On Tue, Apr 18, 2017 at 08:02:35AM -0400, Charles Bancroft wrote:
On 4/18/2017 4:48 AM, Daniel P. Berrange wrote:
> On Mon, Apr 17, 2017 at 09:49:01AM -0400, Charles Bancroft wrote:
>> Hi List,
>>
>> I have a question about some troubles I am having with virsh on Windows
>> x64. I am currently running a KVM server on a linux box and need to
>> allow Windows clients to access it. I have set up the server for access
>> with:
>>
>> ```
>> listen_tls = 0
>> listen_tcp = 1
>> auth_tcp = "none"
Here is the log of my execution run. Looks like there was an error
on
the socket, but nothing useful came back. I have also attached a
tcpdump log of the network traffic
to show it is the client end(192.168.1.10) issuing the reset after
receiving some data from the server (192.168.1.113)
``` Execution log
$ LIBVIRT_DEBUG=1 ./virsh -c qemu+tcp://192.168.1.113/system -d0
2017-04-18 11:46:23.778+0000: 1: info : libvirt version: 3.1.0
2017-04-18 11:46:23.778+0000: 1: info : hostname: <HOSTNAME>
Is '<HOSTNAME>' /really/ your local hostname, or did you just edit the
logs to hide your hostname ?
2017-04-18 11:46:23.790+0000: 1: debug : doRemoteOpen:907 :
proceeding
with name = qemu:///system
2017-04-18 11:46:23.790+0000: 1: debug : doRemoteOpen:916 : Connecting
with transport 5
Ok, we're trying to connect to the host over TCP which is good
2017-04-18 11:46:23.875+0000: 1: debug : virNetSocketNew:235 :
localAddr=000000000069f540 remoteAddr=000000000069f5d0 fd=5 errfd=-1 pid=0
2017-04-18 11:46:23.875+0000: 1: info : virObjectNew:202 : OBJECT_NEW:
obj=0000000000faebe0 classname=virNetSocket
2017-04-18 11:46:23.875+0000: 1: info : virNetSocketNew:291 :
RPC_SOCKET_NEW: sock=0000000000faebe0 fd=5 errfd=-1 pid=0
localAddr=192.168.1.10;61441, remoteAddr=192.168.1.113;16509
Ok, the TCP connection is successfull, which is also good.
2017-04-18 11:46:23.875+0000: 1: debug : doRemoteOpen:1170 : Trying
authentication
We're now trying to authenticate with the server
2017-04-18 11:46:23.875+0000: 1: debug : virNetMessageNew:46 :
msg=0000000000fba700 tracked=0
2017-04-18 11:46:23.875+0000: 1: debug : virNetMessageEncodePayload:386
: Encode length as 28
2017-04-18 11:46:23.875+0000: 1: info : virNetClientSendInternal:2104 :
RPC_CLIENT_MSG_TX_QUEUE: client=0000000000faa9a0 len=28 prog=536903814
vers=1 proc=66 type=0 status=0 serial=0
2017-04-18 11:46:23.875+0000: 1: debug : virNetClientCallNew:2057 : New
call 0000000000fd7ad0: msg=0000000000fba700, expectReply=1, nonBlock=0
2017-04-18 11:46:23.875+0000: 1: debug : virNetClientIO:1866 : Outgoing
message prog=536903814 version=1 serial=0 proc=66 type=0 length=28
dispatch=0000000000000000
We've put the authentication message on the queue to send.
2017-04-18 11:46:23.879+0000: 1: debug : virNetClientMarkClose:776 :
client=0000000000faa9a0, reason=1
We're marking the conneciton as closed, due to EOF.
This is the first sign of something wrong.
I'm not 100% sure if this is due to the server closing the
connection, or a client side bug in the poll loop.
I'd be interested to see the libvirtd server side logs - if you configure
libvirtd.conf with
log_outputs="1:file:/var/log/libvirt/libvirtd.log"
log_filters="1:remote 1:rpc 1:event 1:daemon"
error: failed to connect to the hypervisor
error: An error occurred, but the cause is unknown
This however is a clear bug - we should never get this particular
error message.
Regards,
Daniel
--
|: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org -o- http://virt-manager.org :|
|: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|
7:55 a.m.
On Tue, Apr 18, 2017 at 01:41:27PM +0100, Daniel P. Berrange wrote:
On Tue, Apr 18, 2017 at 08:02:35AM -0400, Charles Bancroft wrote:
> 2017-04-18 11:46:23.879+0000: 1: debug : virNetClientMarkClose:776 :
> client=0000000000faa9a0, reason=1
We're marking the conneciton as closed, due to EOF.
This is the first sign of something wrong.
I'm not 100% sure if this is due to the server closing the
connection, or a client side bug in the poll loop.
I'd be interested to see the libvirtd server side logs - if you configure
libvirtd.conf with
log_outputs="1:file:/var/log/libvirt/libvirtd.log"
log_filters="1:remote 1:rpc 1:event 1:daemon"
Actually don't bother - I just managed to reproduce the same problem myself
in a Windows machine. So this looks like a bug in libvirt on Win32.
Regards,
Daniel
--
|: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org -o- http://virt-manager.org :|
|: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|
10:09 a.m.
On Tue, Apr 18, 2017 at 01:55:17PM +0100, Daniel P. Berrange wrote:
On Tue, Apr 18, 2017 at 01:41:27PM +0100, Daniel P. Berrange wrote:
> On Tue, Apr 18, 2017 at 08:02:35AM -0400, Charles Bancroft wrote:
> > 2017-04-18 11:46:23.879+0000: 1: debug : virNetClientMarkClose:776 :
> > client=0000000000faa9a0, reason=1
>
> We're marking the conneciton as closed, due to EOF.
>
> This is the first sign of something wrong.
>
> I'm not 100% sure if this is due to the server closing the
> connection, or a client side bug in the poll loop.
>
> I'd be interested to see the libvirtd server side logs - if you configure
> libvirtd.conf with
>
>
> log_outputs="1:file:/var/log/libvirt/libvirtd.log"
> log_filters="1:remote 1:rpc 1:event 1:daemon"
Actually don't bother - I just managed to reproduce the same problem myself
in a Windows machine. So this looks like a bug in libvirt on Win32.
FYI, I've tracked this down to a likely bug in gnulib. All versions of
libvirt from 1.2.14 onwards are affected & so will fail to connect.
If you don't need the newer APIs, you could try using libvirt 1.2.13 for
your Windows builds - I've tested that at least successfully connects.
Meanwhile we'll aim to get this fixed in the next release (v3.3.0)
Regards,
Daniel
--
|: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :|
|: http://libvirt.org -o- http://virt-manager.org :|
|: http://entangle-photo.org -o- http://search.cpan.org/~danberr/ :|
10:12 a.m.
On 4/18/2017 11:09 AM, Daniel P. Berrange wrote:
FYI, I've tracked this down to a likely bug in gnulib. All
versions of
libvirt from 1.2.14 onwards are affected & so will fail to connect.
If you don't need the newer APIs, you could try using libvirt 1.2.13 for
your Windows builds - I've tested that at least successfully connects.
Meanwhile we'll aim to get this fixed in the next release (v3.3.0)
Regards,
Daniel
I'll take a look at 1.2.13 and see what is different. Worst case we
will have some reduced functionality in our Windows client until the
next release. Thanks for looking into this Daniel. It is much appreciated.
-Charles
2775
days inactive
2776
days old
6 comments
2 participants
participants (2)
-
Charles Bancroft -
Daniel P. Berrange