[libvirt] Seeking for advice on 'virsh console' problems debugging
Hi, I've been trying to understand why 'virsh console' doesn't work on FreeBSD for some time and now I feel like I got stuck. Background of the problem. Some time ago I started implementing console support for the bhyve driver. I initially implemented it using nmdm(4) device: http://www.freebsd.org/cgi/man.cgi?query=nmdm&sektion=4&manpath=FreeBSD+10.0-stable But 'virsh console' didn't work on it and exited immediately. I though that it could be nmdm compatibility issue and decided to go with the plan /dev/pts devices. But I got the same problem with it. So I decided to try use console with qemu driver. And... I got the same problem. After some investigation, I spotted this block in tools/virsh-console.c:376 while (!con->quit) { if (virCondWait(&con->cond, &con->lock) < 0) { VIR_ERROR(_("unable to wait on console condition")); goto cleanup; } } The strange thing is that it doesn't look con->lock mutex before waiting. FreeBSD man page for pthread_cond_wait() says that it errors in that situation: [EPERM] The specified mutex was not locked by the calling thread. I replaced VIR_ERROR with virReportSystemError and it returns EPERM indeed. So I've added virMutexLock() before calling virCondWait() and it partially solved the problem for me -- 'virsh console' stopped exiting immediately. Actually, it started output for guest, but it's badly formatted: it includes lots and lots of whitespaces. Input doesn't work properly (cannot type in sensible stuff). Here's a sample output, even libvirt messages are badly formatted (I added some debug prints along the way). http://people.freebsd.org/~novel/misc/ttyweirdness.png So, e.g. dmesg output for the guest looks almost the same. Looks like there's something wrong with the terminal settings, but how could that be debugged? PS Worth to mention that 'cu' worked all the time for me on these devices (both created by bhyve and qemu). Roman Bogorodskiy
On Fri, Mar 07, 2014 at 05:49:34PM +0400, Roman Bogorodskiy wrote:
Hi,
I've been trying to understand why 'virsh console' doesn't work on FreeBSD for some time and now I feel like I got stuck.
Background of the problem. Some time ago I started implementing console support for the bhyve driver. I initially implemented it using nmdm(4) device:
http://www.freebsd.org/cgi/man.cgi?query=nmdm&sektion=4&manpath=FreeBSD+10.0-stable
But 'virsh console' didn't work on it and exited immediately.
I though that it could be nmdm compatibility issue and decided to go with the plan /dev/pts devices. But I got the same problem with it.
So I decided to try use console with qemu driver. And... I got the same problem.
After some investigation, I spotted this block in tools/virsh-console.c:376
while (!con->quit) { if (virCondWait(&con->cond, &con->lock) < 0) { VIR_ERROR(_("unable to wait on console condition")); goto cleanup; } }
The strange thing is that it doesn't look con->lock mutex before waiting.
FreeBSD man page for pthread_cond_wait() says that it errors in that situation:
[EPERM] The specified mutex was not locked by the calling thread.
I replaced VIR_ERROR with virReportSystemError and it returns EPERM indeed. So I've added virMutexLock() before calling virCondWait() and it partially solved the problem for me -- 'virsh console' stopped exiting immediately.
Actually, it started output for guest, but it's badly formatted: it includes lots and lots of whitespaces. Input doesn't work properly (cannot type in sensible stuff).
Here's a sample output, even libvirt messages are badly formatted (I added some debug prints along the way).
All those mangled messages are being printed out by libvirt client code, and it is totally expected that log messages libvirt prints are mangled in this way for the console. What's more important is what data coming from the guest looks like.
So, e.g. dmesg output for the guest looks almost the same.
Looks like there's something wrong with the terminal settings, but how could that be debugged?
The virsh console works remotely. So it would be interesting to run virsh console on linux, connecting to a FreeBSD hosted guest and see if it is still a problem. That would help determine whether virsh console is at fault, or the bhyve side is at fault. Similarly, try virsh console running on FreeBSD, connecting to a guest that is running with KVM on Linux. Again that would help narrow down which part is at fault. Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|
Daniel P. Berrange wrote:
All those mangled messages are being printed out by libvirt client code, and it is totally expected that log messages libvirt prints are mangled in this way for the console.
What's more important is what data coming from the guest looks like.
All those spaces come from the stream as well. For example, I've added the following debugging to daemonStreamHandleRead() into daemon/stream.c: 732 ret = virStreamRecv(stream->st, buffer, bufferLen); 733 VIR_ERROR("buffer = [%s]", buffer); And it prints stuff like: 2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ File "/usr/bin/cloud raise DataSourceNotFoundException(msg) ] 2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] etc (This /usr/bin/cloud stuff comes from Ubuntu cloud image that probably tries to find metadata service or something like that).
So, e.g. dmesg output for the guest looks almost the same.
Looks like there's something wrong with the terminal settings, but how could that be debugged?
The virsh console works remotely. So it would be interesting to run virsh console on linux, connecting to a FreeBSD hosted guest and see if it is still a problem. That would help determine whether virsh console is at fault, or the bhyve side is at fault.
Similarly, try virsh console running on FreeBSD, connecting to a guest that is running with KVM on Linux. Again that would help narrow down which part is at fault.
Good idea! I'll try to setup such an environment. And, by the way, I've stopped playing with bhyve console and do debugging with qemu/freebsd only for now. Roman Bogorodskiy
On Fri, Mar 07, 2014 at 06:15:24PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
All those mangled messages are being printed out by libvirt client code, and it is totally expected that log messages libvirt prints are mangled in this way for the console.
What's more important is what data coming from the guest looks like.
All those spaces come from the stream as well. For example, I've added the following debugging to daemonStreamHandleRead() into daemon/stream.c:
732 ret = virStreamRecv(stream->st, buffer, bufferLen); 733 VIR_ERROR("buffer = [%s]", buffer);
And it prints stuff like:
2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ File "/usr/bin/cloud raise DataSourceNotFoundException(msg) ] 2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ]
The debug logs are *always* going to be strange when you have the terminal in raw mode. If you're debugging the console support you really must not try to use stderr for debug logs - you'll never get sane results. Set libvirt to log to a file or syslog instead. Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|
Daniel P. Berrange wrote:
On Fri, Mar 07, 2014 at 06:15:24PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
All those mangled messages are being printed out by libvirt client code, and it is totally expected that log messages libvirt prints are mangled in this way for the console.
What's more important is what data coming from the guest looks like.
All those spaces come from the stream as well. For example, I've added the following debugging to daemonStreamHandleRead() into daemon/stream.c:
732 ret = virStreamRecv(stream->st, buffer, bufferLen); 733 VIR_ERROR("buffer = [%s]", buffer);
And it prints stuff like:
2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ File "/usr/bin/cloud raise DataSourceNotFoundException(msg) ] 2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ]
The debug logs are *always* going to be strange when you have the terminal in raw mode. If you're debugging the console support you really must not try to use stderr for debug logs - you'll never get sane results. Set libvirt to log to a file or syslog instead.
That's strange because libvirtd and virsh use different terminals for logging, but I've disabled stderr logging to be on the safe side. Anyway, I've conducted an experiment like you suggested: 1. run 'virsh' on linux to freebsd libvirtd, output is mangled: http://people.freebsd.org/~novel/misc/ttyweirdness2.png 2. run 'virsh' on freebsd to linux libvirtd, output is good: http://people.freebsd.org/~novel/misc/ttyweirdness3.png Guest uses the same image and the same domain xml. Also, I removed all my custom debug stuff from virsh except mutex lock (as it doesn't work otherwise). So the problem seem to be on the libvirtd side... Roman Bogorodskiy
On Fri, Mar 07, 2014 at 07:49:04PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
On Fri, Mar 07, 2014 at 06:15:24PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
All those mangled messages are being printed out by libvirt client code, and it is totally expected that log messages libvirt prints are mangled in this way for the console.
What's more important is what data coming from the guest looks like.
All those spaces come from the stream as well. For example, I've added the following debugging to daemonStreamHandleRead() into daemon/stream.c:
732 ret = virStreamRecv(stream->st, buffer, bufferLen); 733 VIR_ERROR("buffer = [%s]", buffer);
And it prints stuff like:
2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ File "/usr/bin/cloud raise DataSourceNotFoundException(msg) ] 2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ]
The debug logs are *always* going to be strange when you have the terminal in raw mode. If you're debugging the console support you really must not try to use stderr for debug logs - you'll never get sane results. Set libvirt to log to a file or syslog instead.
That's strange because libvirtd and virsh use different terminals for logging, but I've disabled stderr logging to be on the safe side.
Anyway, I've conducted an experiment like you suggested:
1. run 'virsh' on linux to freebsd libvirtd, output is mangled:
http://people.freebsd.org/~novel/misc/ttyweirdness2.png
2. run 'virsh' on freebsd to linux libvirtd, output is good:
http://people.freebsd.org/~novel/misc/ttyweirdness3.png
Guest uses the same image and the same domain xml.
Also, I removed all my custom debug stuff from virsh except mutex lock (as it doesn't work otherwise). So the problem seem to be on the libvirtd side...
Agreed, it is either libvirtd or bhyve that's the source of the mangling then. Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|
Daniel P. Berrange wrote:
On Fri, Mar 07, 2014 at 07:49:04PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
On Fri, Mar 07, 2014 at 06:15:24PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
All those mangled messages are being printed out by libvirt client code, and it is totally expected that log messages libvirt prints are mangled in this way for the console.
What's more important is what data coming from the guest looks like.
All those spaces come from the stream as well. For example, I've added the following debugging to daemonStreamHandleRead() into daemon/stream.c:
732 ret = virStreamRecv(stream->st, buffer, bufferLen); 733 VIR_ERROR("buffer = [%s]", buffer);
And it prints stuff like:
2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ File "/usr/bin/cloud raise DataSourceNotFoundException(msg) ] 2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ]
The debug logs are *always* going to be strange when you have the terminal in raw mode. If you're debugging the console support you really must not try to use stderr for debug logs - you'll never get sane results. Set libvirt to log to a file or syslog instead.
That's strange because libvirtd and virsh use different terminals for logging, but I've disabled stderr logging to be on the safe side.
Anyway, I've conducted an experiment like you suggested:
1. run 'virsh' on linux to freebsd libvirtd, output is mangled:
http://people.freebsd.org/~novel/misc/ttyweirdness2.png
2. run 'virsh' on freebsd to linux libvirtd, output is good:
http://people.freebsd.org/~novel/misc/ttyweirdness3.png
Guest uses the same image and the same domain xml.
Also, I removed all my custom debug stuff from virsh except mutex lock (as it doesn't work otherwise). So the problem seem to be on the libvirtd side...
Agreed, it is either libvirtd or bhyve that's the source of the mangling then.
Very unlikely that it's bhyve, as I'm testing with qemu (plan to get to bhyve when I'll be able to get it fixed for qemu). And considering that 'cu' works properly, it's most likely the daemon. I'll continue looking in this direction. Thanks for the pointer, that helped to narrow down the problem indeed. Roman Bogorodskiy
On Fri, Mar 07, 2014 at 10:04:48PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
On Fri, Mar 07, 2014 at 07:49:04PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
On Fri, Mar 07, 2014 at 06:15:24PM +0400, Roman Bogorodskiy wrote:
Daniel P. Berrange wrote:
All those mangled messages are being printed out by libvirt client code, and it is totally expected that log messages libvirt prints are mangled in this way for the console.
What's more important is what data coming from the guest looks like.
All those spaces come from the stream as well. For example, I've added the following debugging to daemonStreamHandleRead() into daemon/stream.c:
732 ret = virStreamRecv(stream->st, buffer, bufferLen); 733 VIR_ERROR("buffer = [%s]", buffer);
And it prints stuff like:
2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ File "/usr/bin/cloud raise DataSourceNotFoundException(msg) ] 2014-03-07 13:29:34.060+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ] 2014-03-07 13:29:34.061+0000: 34489787392: error : daemonStreamHandleRead:733 : buffer = [ ]
The debug logs are *always* going to be strange when you have the terminal in raw mode. If you're debugging the console support you really must not try to use stderr for debug logs - you'll never get sane results. Set libvirt to log to a file or syslog instead.
That's strange because libvirtd and virsh use different terminals for logging, but I've disabled stderr logging to be on the safe side.
Anyway, I've conducted an experiment like you suggested:
1. run 'virsh' on linux to freebsd libvirtd, output is mangled:
http://people.freebsd.org/~novel/misc/ttyweirdness2.png
2. run 'virsh' on freebsd to linux libvirtd, output is good:
http://people.freebsd.org/~novel/misc/ttyweirdness3.png
Guest uses the same image and the same domain xml.
Also, I removed all my custom debug stuff from virsh except mutex lock (as it doesn't work otherwise). So the problem seem to be on the libvirtd side...
Agreed, it is either libvirtd or bhyve that's the source of the mangling then.
Very unlikely that it's bhyve, as I'm testing with qemu (plan to get to bhyve when I'll be able to get it fixed for qemu).
Oh, I didn't realize you were testing this with QEMU on BSD! One further idea I just had - in QEMU code util/qemu-openpty.c we call cfmakeraw()/tcsetattr on the PTY slave file descriptor. On Linux at least this affects both ends of the device, but I wonder if there's perhaps a need to call this on the master file descriptor as well as or instead of on the slave file descriptor ? Or perhaps the client (in this case libvirtd) itself has to call cfmakeraw/tcsetattr since although its opening the same slave, it is a different file descriptor for the slave
And considering that 'cu' works properly, it's most likely the daemon. I'll continue looking in this direction. Thanks for the pointer, that helped to narrow down the problem indeed.
True, but interesting to strace 'cu' and libvirtd to see what differences they have if any when opening the slave FD.
Roman Bogorodskiy
Regards, Daniel -- |: http://berrange.com -o- http://www.flickr.com/photos/dberrange/ :| |: http://libvirt.org -o- http://virt-manager.org :| |: http://autobuild.org -o- http://search.cpan.org/~danberr/ :| |: http://entangle-photo.org -o- http://live.gnome.org/gtk-vnc :|
Daniel P. Berrange wrote:
One further idea I just had - in QEMU code util/qemu-openpty.c we call cfmakeraw()/tcsetattr on the PTY slave file descriptor. On Linux at least this affects both ends of the device, but I wonder if there's perhaps a need to call this on the master file descriptor as well as or instead of on the slave file descriptor ? Or perhaps the client (in this case libvirtd) itself has to call cfmakeraw/tcsetattr since although its opening the same slave, it is a different file descriptor for the slave
Thanks a lot for pointing this out. Manually placing the device into a raw mode works indeed! Roman Bogorodskiy
participants (2)
-
Daniel P. Berrange -
Roman Bogorodskiy