Bug 431079 - virt-manager fails to connect to guest console
virt-manager fails to connect to guest console
Status: CLOSED NOTABUG
Product: Fedora
Classification: Fedora
Component: virt-manager (Show other bugs)
8
All Linux
medium Severity medium
: ---
: ---
Assigned To: Daniel Berrange
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-01-31 11:51 EST by Jonathan Underwood
Modified: 2008-02-01 11:36 EST (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-02-01 11:36:20 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
virt-manager.log (953.97 KB, text/plain)
2008-02-01 09:05 EST, Jonathan Underwood
no flags Details
log corresponding to the VM (257 bytes, text/plain)
2008-02-01 09:06 EST, Jonathan Underwood
no flags Details

  None (edit)
Description Jonathan Underwood 2008-01-31 11:51:02 EST
Description of problem:
When running a qemu-kvm guest, I more often than not am unable to actually get
the console window open - it just sits there displaying the message "Connecting
to console for guest". The guest is running, as evidenced in the virtual machine
manager window.

Version-Release number of selected component (if applicable):
virt-viewer-0.0.2-2.fc8
libvirt-python-0.4.0-4.fc8
python-virtinst-0.300.2-2.fc8
libvirt-0.4.0-4.fc8
virt-manager-0.5.3-1.fc8
gtk-vnc-python-0.3.2-1.fc8
gtk-vnc-0.3.2-1.fc8

How reproducible:
8/10 times

Steps to Reproduce:
1.Start a virtual machine
2.Select the VM in virt-manager and click the open button
3.
  
Actual results:
VNC session doesn't start


Expected results:
be able to work with the VM :)

Additional info:
Comment 1 Jonathan Underwood 2008-01-31 14:47:03 EST
Aha, I think I tracked the issue down here. virt-manager starts vnc servers on
ports 5900 upwards on localhost, which clashes with those setup by the
vnc-ltsp-config package, and also lots of other vnc server programs. There's no
obvious way of setting what port the VNC server started by virt-manager uses. So
I think there are several usability issues here.

1) virt-manager should provide an easy way to chose what ports to use for vnc
servers

2) virt-manager should not start a vnc server on a port already with a vnc
server configured to listen on, and should give an error message.

Admittedly in the case of vnc-ltsp the vnc server is started on demand by xinetd
and so virt-manager may not see an already running server on the relevant ports.
But when a vnc client tries to connect there will be a conflict between the
xinetd started server and the virt-manager server. This is solved by
virt-manager checking /etc/services to see if anything is configured to use the
port it is about to use to start the vnc server on.
Comment 2 Daniel Berrange 2008-01-31 14:53:24 EST
No, this should be just fine already. Virt-manager configures virtual machines
to automatically choose the first free/unbound port number starting at 5900. So
you should never get a clashing port number when starting a VM.

Please provide /root/.virt-manager/virt-manager.log and
/var/log/libvirt/qemu/{GUESTNAME}.log and run  'lsof -p {PID of qemu-kvm
proces}' and attach the output
Comment 3 Jonathan Underwood 2008-01-31 18:41:57 EST
(In reply to comment #2)
> No, this should be just fine already. Virt-manager configures virtual machines
> to automatically choose the first free/unbound port number starting at 5900. So
> you should never get a clashing port number when starting a VM.
> 

Yes, exactly. If a vnc server is set to start up on demand with xinetd, when
virt-manager starts a vnc the port will appear free UNTIL a connection to that
port is made, at which point the xinetd service can start a vnc server on the
same port, and hilarity ensues. I don't think virt-manager checks /etc/services
to find a free port, correct?


> Please provide /root/.virt-manager/virt-manager.log and
> /var/log/libvirt/qemu/{GUESTNAME}.log and run  'lsof -p {PID of qemu-kvm
> proces}' and attach the output

OK, will do when I am next at the machine in question.
Comment 4 Daniel Berrange 2008-01-31 23:28:53 EST
libvirt doesn't care about what's registered in /etc/services - it will
explicitly attempt to bind() to each port number in turn & once it finds a free
one it will start QEMU with VNC on that port. There is an absolutely tiny race
condition between libvirt checking & qemu starting. So you may hit that race
once in a 100 times if you're incredibly unlucky - it should certainly work
correctly nearly all the time.
Comment 5 Jonathan Underwood 2008-02-01 08:59:04 EST
Ok, I just triggered this issue and am attaching the info you asked for.
Comment 6 Jonathan Underwood 2008-02-01 09:05:09 EST
# ps aux | grep kvm
root     14803 32.2  4.0 620816 83888 ?        Sl   13:57   2:03
/usr/bin/qemu-kvm -M pc -m 512 -smp 1 -monitor pty -localtime -no-acpi -boot c
-hda /home/VM/WindowsXP.img -net nic,macaddr=00:16:3e:5b:bc:79,vlan=0 -net
tap,fd=14,script=,vlan=0 -usb -usbdevice tablet -vnc 127.0.0.1:1

# /usr/sbin/lsof -p 14803
COMMAND    PID USER   FD   TYPE DEVICE       SIZE     NODE NAME
qemu-kvm 14803 root  cwd    DIR    8,2       4096        2 /
qemu-kvm 14803 root  rtd    DIR    8,2       4096        2 /
qemu-kvm 14803 root  txt    REG    8,2    1406568   133808 /usr/bin/qemu-kvm
qemu-kvm 14803 root  mem    REG    8,2     133616  1556494 /lib64/ld-2.7.so
qemu-kvm 14803 root  mem    REG    8,2    1717544  1556495 /lib64/libc-2.7.so
qemu-kvm 14803 root  mem    REG    8,2      23288  1556502 /lib64/libdl-2.7.so
qemu-kvm 14803 root  mem    REG    8,2     611096  1556501 /lib64/libm-2.7.so
qemu-kvm 14803 root  mem    REG    8,2     143336  1556498 /lib64/libpthread-2.7.so
qemu-kvm 14803 root  mem    REG    8,2      85904  1556504 /lib64/libz.so.1.2.3
qemu-kvm 14803 root  mem    REG    8,2      53464  1556499 /lib64/librt-2.7.so
qemu-kvm 14803 root  mem    REG    8,2     114208  1556516 /lib64/libnsl-2.7.so
qemu-kvm 14803 root  mem    REG    8,2      18080  1556522 /lib64/libutil-2.7.so
qemu-kvm 14803 root  mem    REG    8,2      15424  1556527
/lib64/libgpg-error.so.0.3.1
qemu-kvm 14803 root  mem    REG    8,2     916136  1556523 /lib64/libasound.so.2.0.0
qemu-kvm 14803 root  mem    REG    8,2     315424  1556528
/lib64/libgcrypt.so.11.2.3
qemu-kvm 14803 root  mem    REG    8,2     536648   145865
/usr/lib64/libgnutls.so.13.3.0
qemu-kvm 14803 root  mem    REG    8,2     433096   134934
/usr/lib64/libSDL-1.2.so.0.11.2
qemu-kvm 14803 root  mem    REG    0,7                  22 anon_inode (stat: No
such file or directory)
qemu-kvm 14803 root  mem    CHR    1,5                 205 /dev/zero
qemu-kvm 14803 root    0r   CHR    1,3                 204 /dev/null
qemu-kvm 14803 root    1w  FIFO    0,6              235137 pipe
qemu-kvm 14803 root    2w  FIFO    0,6              235138 pipe
qemu-kvm 14803 root    3r  FIFO    0,6              206617 pipe
qemu-kvm 14803 root    4w  FIFO    0,6              206617 pipe
qemu-kvm 14803 root    5u   CHR 10,232                5675 /dev/kvm
qemu-kvm 14803 root    6r   CHR 10,135                 210 /dev/rtc
qemu-kvm 14803 root    7u  0000    0,7          0       22 anon_inode
qemu-kvm 14803 root    8u  0000    0,7          0       22 anon_inode
qemu-kvm 14803 root    9u   REG    8,5 4194304000 39845890 /home/VM/WindowsXP.img
qemu-kvm 14803 root   10u  IPv4 235157                 TCP
localhost.localdomain:vnc-800x600x16 (LISTEN)
qemu-kvm 14803 root   11u   CHR    5,2                 209 /dev/ptmx
qemu-kvm 14803 root   12u   CHR  136,2                   4 /dev/pts/2
qemu-kvm 14803 root   13u  IPv4 235163                 TCP
localhost.localdomain:vnc-800x600x16->localhost.localdomain:60601 (ESTABLISHED)
qemu-kvm 14803 root   14u   CHR 10,200                3417 /dev/net/tun
Comment 7 Jonathan Underwood 2008-02-01 09:05:50 EST
Created attachment 293727 [details]
virt-manager.log
Comment 8 Jonathan Underwood 2008-02-01 09:06:20 EST
Created attachment 293728 [details]
log corresponding to the VM
Comment 9 Jonathan Underwood 2008-02-01 09:10:17 EST
(In reply to comment #4)
> libvirt doesn't care about what's registered in /etc/services - it will
> explicitly attempt to bind() to each port number in turn & once it finds a free
> one it will start QEMU with VNC on that port. There is an absolutely tiny race
> condition between libvirt checking & qemu starting. So you may hit that race
> once in a 100 times if you're incredibly unlucky - it should certainly work
> correctly nearly all the time.

Right. So libvirt/qemu starts a vnc server on the first currently unused port,
say 5901. The problem is, if there is a xinetd service set to start a vnc server
on that port on demand, when I open a vncviewer to that port, a race will happen
as xinetd tries to start a vnc server on the same port as the already running
qemu vnc server. That's what I presume is happening. Certainly I don't seem to
hit the problem if I stop the xinetd service. I am not sure quite what the right
fix is, but it's probably one of:

1) libvirt should check /etc/services to make sure that a currently unused port
doesn't also have a service likely to start on it

or

2) xinetd shouldn't start a service if something is already running on a port.

Probably both. :)
Comment 10 Daniel Berrange 2008-02-01 09:23:41 EST
No, xinetd will *not* be able to start a VNC server on the same port, because
QEMU will already be using that port. This is fundamental - only one service can
use the port at once. If QEMU gets there first, then xinetd won't be able to use
it. If xinetd gets there first, libvirt will automatically choose a different
port for QEMU. So whether you run xinetd or not, libvirt will always be able to
start QEMU correctly. There is no need to check /etc/services, and xinetd
fundamanetally cannot start a service if something's on the port already - the
kernel enforces this.

If you open a VNC viewer client pointing it at the same port as QEMU, then the
VNC viewer may connect before virt-manager does, which could be what you're
seeing. This is perfectly tobe expected - you can only have a single client -
either VNC viewer, or virt-manager,  connected to the server any any time.
Comment 11 Jonathan Underwood 2008-02-01 09:27:00 EST
But in the lsof output you can see this:

localhost.localdomain:vnc-800x600x16->localhost.localdomain:60601 (ESTABLISHED)

vnc-800x600x16 is the xinetd started vnc server from vnc-ltsp-config

so, while I agree with your description of how things should work, they don't
seem to be working that way currently...
Comment 12 Daniel Berrange 2008-02-01 09:33:26 EST
You are not understanding the lsof output. The
'localhost.localdomain:vnc-800x600x16' does not mean that  xinetd is listening.
This is just the name of the service associated with the port that QEMU is
listening on. When displaying port numbers, lsof looks up the port number in
/etc/services - so it merely means you've added an entry called 'vnc-800x600x16'
to your /etc/services file.

Please provide output of 

netstat -t -a -n -p

While run as root, this will show exactly what process is listening/connected to
each port, and avoid using /etc/services to convert port numbers to names
avoiding the confusing output from lsof.
Comment 13 Jonathan Underwood 2008-02-01 09:38:05 EST
Aha, thanks for the explantion, and sorry for my confusion.

# netstat -t -a -n -p
Active Internet connections (servers and established)
Proto Recv-Q Send-Q Local Address               Foreign Address            
State       PID/Program name   
tcp        0      0 127.0.0.1:8000              0.0.0.0:*                  
LISTEN      2395/nasd           
tcp        0      0 0.0.0.0:139                 0.0.0.0:*                  
LISTEN      2530/smbd           
tcp        0      0 127.0.0.1:5901              0.0.0.0:*                  
LISTEN      15218/qemu-kvm      
tcp        0      0 0.0.0.0:6000                0.0.0.0:*                  
LISTEN      8693/X              
tcp        0      0 192.168.122.1:53            0.0.0.0:*                  
LISTEN      6450/dnsmasq        
tcp        0      0 127.0.0.1:631               0.0.0.0:*                  
LISTEN      2635/cupsd          
tcp        0      0 127.0.0.1:25                0.0.0.0:*                  
LISTEN      2371/sendmail: acce 
tcp        0      0 0.0.0.0:445                 0.0.0.0:*                  
LISTEN      2530/smbd           
tcp        0      0 0.0.0.0:3551                0.0.0.0:*                  
LISTEN      2327/apcupsd        
tcp        0      0 128.40.2.35:33816           74.125.47.83:80            
ESTABLISHED 13315/firefox-bin   
tcp        1      0 128.40.2.35:59013           130.246.135.136:443        
CLOSE_WAIT  13034/evolution-exc 
tcp        0      0 127.0.0.1:5901              127.0.0.1:48174            
ESTABLISHED 15218/qemu-kvm      
tcp        0      0 127.0.0.1:48174             127.0.0.1:5901             
ESTABLISHED 13888/python        
tcp        1      0 128.40.2.35:35380           130.246.135.136:443        
CLOSE_WAIT  13243/evolution     
tcp        0      0 128.40.2.35:39915           216.155.193.168:5050       
ESTABLISHED 13012/pidgin        
tcp     1121      0 128.40.2.35:37048           74.125.47.19:80            
CLOSE_WAIT  14458/npviewer.bin  
tcp        0      0 128.40.2.35:59951           207.46.110.97:1863         
ESTABLISHED 13012/pidgin        
tcp        1      0 128.40.2.35:33819           74.125.47.83:80            
CLOSE_WAIT  13315/firefox-bin   
tcp        1      0 128.40.2.35:59004           130.246.135.136:443        
CLOSE_WAIT  13034/evolution-exc 
tcp        1      0 128.40.2.35:59858           130.246.135.136:443        
CLOSE_WAIT  13034/evolution-exc 
tcp        0      0 127.0.0.1:48175             127.0.0.1:5901             
ESTABLISHED 14781/python        
tcp        0      0 127.0.0.1:48172             127.0.0.1:5901             
TIME_WAIT   -                   
tcp        1      0 128.40.2.35:59003           130.246.135.136:443        
CLOSE_WAIT  13034/evolution-exc 
tcp        1      0 128.40.2.35:33593           144.82.108.183:80          
CLOSE_WAIT  14458/npviewer.bin  
tcp        0      0 128.40.2.35:36932           63.245.213.32:443          
CLOSE_WAIT  14458/npviewer.bin  
tcp        0      0 128.40.2.35:35997           207.46.27.172:1863         
ESTABLISHED 13012/pidgin        
tcp        0      0 127.0.0.1:5901              127.0.0.1:48175            
ESTABLISHED -                   
tcp        0      0 128.40.2.35:36928           63.245.213.32:443          
CLOSE_WAIT  14458/npviewer.bin  
tcp        0      0 127.0.0.1:38183             127.0.0.1:993              
ESTABLISHED 13243/evolution     
tcp        1      0 128.40.2.35:37049           74.125.47.19:80            
CLOSE_WAIT  14458/npviewer.bin  
tcp        0      0 128.40.2.35:43396           144.82.111.3:993           
ESTABLISHED 13243/evolution     
tcp        0      0 :::993                      :::*                       
LISTEN      2337/dovecot        
tcp        0      0 :::5800                     :::*                       
LISTEN      15197/xinetd        
tcp        0      0 :::904                      :::*                       
LISTEN      15197/xinetd        
tcp        0      0 :::5900                     :::*                       
LISTEN      15197/xinetd        
tcp        0      0 :::6000                     :::*                       
LISTEN      8693/X              
tcp        0      0 :::22                       :::*                       
LISTEN      2283/sshd           
tcp        0      0 ::1:631                     :::*                       
LISTEN      2635/cupsd          
tcp        0      0 ::ffff:127.0.0.1:993        ::ffff:127.0.0.1:38183     
ESTABLISHED 7758/imap-login  
Comment 14 Jonathan Underwood 2008-02-01 10:34:46 EST
as an aside, when I see this problem with virt-manager, I also can't get a vnc
session going with vncviewer:

# vncviewer -log *:stderr:100 127.0.0.1:1

VNC Viewer Free Edition 4.1.2 for X - built Oct 23 2007 13:45:20
Copyright (C) 2002-2005 RealVNC Ltd.
See http://www.realvnc.com for information on VNC.

Fri Feb  1 15:32:21 2008
 CConn:       connected to host 127.0.0.1 port 5901


and then it just hangs, no vnc window appears. Suggest that probably the problem
is with the vnc server code in qemu, rather than virt-manager/libvirt, perhaps?
Comment 15 Daniel Berrange 2008-02-01 10:50:32 EST
You appear to have 2 copies of virt-manager running

tcp        0      0 127.0.0.1:48174             127.0.0.1:5901             
ESTABLISHED 13888/python 

tcp        0      0 127.0.0.1:48175             127.0.0.1:5901             
ESTABLISHED 14781/python

One as PID 13888 and one as PID  14781. The virt-manager logs confirm this - you
can see log messages from two separate processes in the log

Only one client can connect to the VNC console at once - all others will be
blocked from accessing it. So make sure you don't run multiple copies of
virt-manager at once.
Comment 16 Jonathan Underwood 2008-02-01 11:07:10 EST
Hm. Odd. Certainly there was only a single virt-manager window. I guess it had
previously not exited cleanly. Perhaps virt-manager needs to  check to see if
something else is connected to the vnc console and warn the user if that is the
case.
Comment 17 Daniel Berrange 2008-02-01 11:12:47 EST
virt-manager can't possibly know if someone else has connected or not - the VNC
server can be on any remote machine, not just localhost
Comment 18 Jonathan Underwood 2008-02-01 11:36:20 EST
Oh, right.

Well, I guess this wasn't a bug then. Although it's a bit odd I couldn't connect
to the vnc server - while there was two virt-managers running, as far as I can
tell neither were connected to the vnc console. But perhaps the one that had not
exited properly was holding a connection. Can't seem to reproduce this right now.

Many apologies for bothering you with this, I'll close the bug.

Note You need to log in before you can comment on or make changes to this bug.