[autotest] vm creation fails (not)

[autotest] vm creation fails (not)

[Gerd Hoffmann]

[-- Attachment #1: Type: text/plain, Size: 488 bytes --]

   Hi,

Now and then autotest thinks creating the vm failed, although qemu 
started up just fine.  autotest then goes to wait($qemupid) and hangs 
there forever ...

I suspect this is a race: autotest uses 'help' on the monitor to check 
whenever qemu is alive. If qemu created the monitor socket fast enougth 
it works.  Otherwise it doesn't.

I've papered over it with the quick&dirty patch below.  Someone who 
knows autotest better that /me should fix this properly.

thanks,
   Gerd

[-- Attachment #2: fix --]
[-- Type: text/plain, Size: 631 bytes --]

diff --git a/client/tests/kvm/kvm_vm.py b/client/tests/kvm/kvm_vm.py
index eba9b84..cbb01e7 100644
--- a/client/tests/kvm/kvm_vm.py
+++ b/client/tests/kvm/kvm_vm.py
@@ -382,6 +382,9 @@ class VM:
             self.process = kvm_subprocess.run_bg(qemu_command, None,
                                                  logging.debug, "(qemu) ")
 
+            # wait a bit to give qemu enougth time to create the monitor socket
+            time.sleep(3)
+
             if not self.process.is_alive():
                 logging.error("VM could not be created; "
                               "qemu command failed:\n%s" % qemu_command)

Re: [autotest] vm creation fails (not)

[Michael Goldish]

----- "Gerd Hoffmann" <kraxel@redhat.com> wrote:

> Hi,
> 
> Now and then autotest thinks creating the vm failed, although qemu 
> started up just fine.  autotest then goes to wait($qemupid) and hangs
> there forever ...

If you encounter this again, please send the autotest debug log --
it'll make it easier to tell why autotest hangs.

> 
> I suspect this is a race: autotest uses 'help' on the monitor to check
> whenever qemu is alive. If qemu created the monitor socket fast
> enougth it works.  Otherwise it doesn't.

First autotest checks whether the PID exists.
Then it uses 'help' to see if qemu is responsive, but it tries 'help'
repeatedly, until timeout (default 5 secs) expires.
I assumed 5 secs was plenty, so I wonder why qemu takes longer than that
to start (if that really is the problem).
I also wonder why autotest hangs.  I don't remember seeing autotest hang
immediately after trying to start a VM (or ever, actually).

> 
> I've papered over it with the quick&dirty patch below.  Someone who 
> knows autotest better that /me should fix this properly.
> 
> thanks,
>    Gerd

Re: [autotest] vm creation fails (not)

[Gerd Hoffmann]

[-- Attachment #1: Type: text/plain, Size: 508 bytes --]

On 08/05/09 12:16, Michael Goldish wrote:
> ----- "Gerd Hoffmann"<kraxel@redhat.com>  wrote:
>
>> Hi,
>>
>> Now and then autotest thinks creating the vm failed, although qemu
>> started up just fine.  autotest then goes to wait($qemupid) and hangs
>> there forever ...
>
> If you encounter this again, please send the autotest debug log --
> it'll make it easier to tell why autotest hangs.

Attached.

enjoy,
   Gerd

(autotest still hanging in that state, just in case you want me collect 
more info ...)


[-- Attachment #2: kvm.Fedora.9.32.boot.DEBUG --]
[-- Type: text/plain, Size: 3548 bytes --]

08/05 14:44:57 INFO |      test:0256| Test started. Number of iterations: 1
08/05 14:44:57 INFO |      test:0259| Executing iteration 1 of 1
08/05 14:44:57 ERROR|  warnings:0029| /autotest/git/autotest/client/tests/kvm/kvm_utils.py:1: DeprecationWarning: the md5 module is deprecated; use hashlib instead
08/05 14:44:57 ERROR|  warnings:0029|   import md5, thread, subprocess, time, string, random, socket, os, signal, pty
08/05 14:44:57 DEBUG|       kvm:0077| Test parameters:
08/05 14:44:57 DEBUG|       kvm:0081|     cmd_reboot = shutdown -r now
08/05 14:44:57 DEBUG|       kvm:0081|     cmd_shutdown = shutdown -h now
08/05 14:44:57 DEBUG|       kvm:0081|     convert_ppm_files_to_png_on_error = yes
08/05 14:44:57 DEBUG|       kvm:0081|     depend = ['kraxel.kvm_smallpages.qcow2.ide.default.up.Linux.Fedora.9.32.rtl8139.install', 'kraxel.kvm_smallpages.qcow2.ide.default.up.Linux.Fedora.9.32.rtl8139.setup']
08/05 14:44:57 DEBUG|       kvm:0081|     display = vnc
08/05 14:44:57 DEBUG|       kvm:0081|     drive_format = ide
08/05 14:44:57 DEBUG|       kvm:0081|     guest_port_ssh = 22
08/05 14:44:57 DEBUG|       kvm:0081|     image_boot = yes
08/05 14:44:57 DEBUG|       kvm:0081|     image_format = qcow2
08/05 14:44:57 DEBUG|       kvm:0081|     image_name = fc9-32
08/05 14:44:57 DEBUG|       kvm:0081|     image_size = 10G
08/05 14:44:57 DEBUG|       kvm:0081|     images = image1
08/05 14:44:57 DEBUG|       kvm:0081|     kill_vm = no
08/05 14:44:57 DEBUG|       kvm:0081|     kill_vm_gracefully = yes
08/05 14:44:57 DEBUG|       kvm:0081|     kill_vm_on_error = yes
08/05 14:44:57 DEBUG|       kvm:0081|     main_vm = vm1
08/05 14:44:57 DEBUG|       kvm:0081|     mem = 1024
08/05 14:44:57 DEBUG|       kvm:0081|     name = kraxel.kvm_smallpages.qcow2.ide.default.up.Linux.Fedora.9.32.rtl8139.boot
08/05 14:44:57 DEBUG|       kvm:0081|     nics = nic1
08/05 14:44:57 DEBUG|       kvm:0081|     password = 123456
08/05 14:44:57 DEBUG|       kvm:0081|     redirs = ssh
08/05 14:44:57 DEBUG|       kvm:0081|     shortname = Fedora.9.32.boot
08/05 14:44:57 DEBUG|       kvm:0081|     ssh_port = 22
08/05 14:44:57 DEBUG|       kvm:0081|     ssh_prompt = \[root@.{0,50}][\#\$] 
08/05 14:44:57 DEBUG|       kvm:0081|     ssh_status_test_command = echo $?
08/05 14:44:57 DEBUG|       kvm:0081|     start_vm = yes
08/05 14:44:57 DEBUG|       kvm:0081|     type = boot
08/05 14:44:57 DEBUG|       kvm:0081|     username = root
08/05 14:44:57 DEBUG|       kvm:0081|     vms = vm1
08/05 14:44:57 DEBUG|       kvm:0087| Contents of environment: {'vm__vm1': <kvm_vm.VM instance at 0x2b8d6c8>}
08/05 14:44:58 DEBUG|kvm_prepro:0050| Preprocessing VM 'vm1'...
08/05 14:44:58 DEBUG|kvm_prepro:0053| VM object found in environment
08/05 14:44:58 DEBUG|kvm_prepro:0072| VM is not alive; starting it...
08/05 14:44:58 DEBUG|    kvm_vm:0513| VM is already down
08/05 14:44:58 DEBUG|    kvm_vm:0381| Running qemu command:
/autotest/git/autotest/client/tests/kvm/qemu -name 'vm1' -monitor unix:/tmp/monitor-20090731-160247-1AGm,server,nowait -drive file=/autotest/git/autotest/client/tests/kvm/images/fc9-32.qcow2,if=ide,boot=on -net nic,vlan=0 -net user,vlan=0 -m 1024 -redir tcp:5000::22 -vnc :0
08/05 14:44:58 ERROR|    kvm_vm:0390| VM could not be created; qemu command failed:
/autotest/git/autotest/client/tests/kvm/qemu -name 'vm1' -monitor unix:/tmp/monitor-20090731-160247-1AGm,server,nowait -drive file=/autotest/git/autotest/client/tests/kvm/images/fc9-32.qcow2,if=ide,boot=on -net nic,vlan=0 -net user,vlan=0 -m 1024 -redir tcp:5000::22 -vnc :0

Re: [autotest] vm creation fails (not)

[Michael Goldish]

----- "Gerd Hoffmann" <kraxel@redhat.com> wrote:

> On 08/05/09 12:16, Michael Goldish wrote:
> > ----- "Gerd Hoffmann"<kraxel@redhat.com>  wrote:
> >
> >> Hi,
> >>
> >> Now and then autotest thinks creating the vm failed, although qemu
> >> started up just fine.  autotest then goes to wait($qemupid) and
> hangs
> >> there forever ...
> >
> > If you encounter this again, please send the autotest debug log --
> > it'll make it easier to tell why autotest hangs.
> 
> Attached.
> 
> enjoy,
>    Gerd
> 
> (autotest still hanging in that state, just in case you want me
> collect 
> more info ...)

Thanks!
I think I know exactly where it's hanging (get_status()) but I'm not
sure why.
Are you using Python 2.6? What's the commit ID of the latest commit in
your autotest tree? I wonder if you're using the version before or after
the fix for Python 2.6.

Re: [autotest] vm creation fails (not)

[Gerd Hoffmann]

On 08/05/09 15:12, Michael Goldish wrote:
> Thanks!
> I think I know exactly where it's hanging (get_status()) but I'm not
> sure why.

It hangs there because autotest thinks qemu didn't start.  It did though.

> Are you using Python 2.6?

Yes (Fedora11).

> What's the commit ID of the latest commit in
> your autotest tree?

commit 957e435541f27bb3b388a281ac13949288f75ad5
Author: mbligh <mbligh@592f7852-d20e-0410-864c-8624ca9c26a4>
Date:   Wed Jul 29 14:34:30 2009 +0000

cheers,
   Gerd

Re: [autotest] vm creation fails (not)

[Michael Goldish]

Thanks, I managed to reproduce it and I'll send a patch to fix it soon.
The reason for autotest thinking qemu wasn't alive was that apparently it
takes time for /proc/$PID/cmdline to reflect the real command used to
start the process, and I wrongly assumed it was instantaneous.

----- Original Message -----
From: "Gerd Hoffmann" <kraxel@redhat.com>
To: "Michael Goldish" <mgoldish@redhat.com>
Cc: "KVM list" <kvm@vger.kernel.org>
Sent: Wednesday, August 5, 2009 4:21:54 PM (GMT+0200) Auto-Detected
Subject: Re: [autotest] vm creation fails (not)

On 08/05/09 15:12, Michael Goldish wrote:
> Thanks!
> I think I know exactly where it's hanging (get_status()) but I'm not
> sure why.

It hangs there because autotest thinks qemu didn't start.  It did though.

> Are you using Python 2.6?

Yes (Fedora11).

> What's the commit ID of the latest commit in
> your autotest tree?

commit 957e435541f27bb3b388a281ac13949288f75ad5
Author: mbligh <mbligh@592f7852-d20e-0410-864c-8624ca9c26a4>
Date:   Wed Jul 29 14:34:30 2009 +0000

cheers,
   Gerd

Re: [autotest] vm creation fails (not)

[Gerd Hoffmann]

On 08/05/09 16:05, Michael Goldish wrote:
> Thanks, I managed to reproduce it and I'll send a patch to fix it soon.
> The reason for autotest thinking qemu wasn't alive was that apparently it
> takes time for /proc/$PID/cmdline to reflect the real command used to
> start the process, and I wrongly assumed it was instantaneous.

There is no "command line used to start the process" in unix.

A new process is created using fork().
An process can replace itself with a new executable using execve().

Usual way to start some application in unix is this:
   (1) fork()
   (2) prepare environment (i/o redirection for example)
   (3) execve()

(2)+(3) happen in the new child process created by (1).

/proc/$pid/cmdline will reflect that of course.  It will show the qemu 
command line once execve(qemu) syscall finished.

HTH,
   Gerd

Re: [autotest] vm creation fails (not)

[Michael Goldish]

----- "Gerd Hoffmann" <kraxel@redhat.com> wrote:

> On 08/05/09 16:05, Michael Goldish wrote:
> > Thanks, I managed to reproduce it and I'll send a patch to fix it
> soon.
> > The reason for autotest thinking qemu wasn't alive was that
> apparently it
> > takes time for /proc/$PID/cmdline to reflect the real command used
> to
> > start the process, and I wrongly assumed it was instantaneous.
> 
> There is no "command line used to start the process" in unix.

By "command line" I meant the executable name + arguments.
In this case the arguments really contain a command line, because the
executable started is sh, with '-c' and the qemu command as arguments.

> A new process is created using fork().
> An process can replace itself with a new executable using execve().
> 
> Usual way to start some application in unix is this:
>    (1) fork()
>    (2) prepare environment (i/o redirection for example)
>    (3) execve()
> 
> (2)+(3) happen in the new child process created by (1).
> 
> /proc/$pid/cmdline will reflect that of course.  It will show the qemu
> 
> command line once execve(qemu) syscall finished.
> 
> HTH,
>    Gerd

Oh well, I suppose it would be more accurate to say that I didn't take
into account the time it takes execve() to finish.  kvm_subprocess
explicitly calls fork() and execv(), so I should have known better.

Thanks again.

Re: [autotest] vm creation fails (not)

[Avi Kivity]

On 08/05/2009 05:05 PM, Michael Goldish wrote:
> Thanks, I managed to reproduce it and I'll send a patch to fix it soon.
> The reason for autotest thinking qemu wasn't alive was that apparently it
> takes time for /proc/$PID/cmdline to reflect the real command used to
> start the process, and I wrongly assumed it was instantaneous.
>    

You should use wait() to find out if the process is alive, not tricks 
with the PID and process name, which are racy as you found out.

-- 
error compiling committee.c: too many arguments to function

Re: [autotest] vm creation fails (not)

[Michael Goldish]

----- "Avi Kivity" <avi@redhat.com> wrote:

> On 08/05/2009 05:05 PM, Michael Goldish wrote:
> > Thanks, I managed to reproduce it and I'll send a patch to fix it
> soon.
> > The reason for autotest thinking qemu wasn't alive was that
> apparently it
> > takes time for /proc/$PID/cmdline to reflect the real command used
> to
> > start the process, and I wrongly assumed it was instantaneous.
> >    
> 
> You should use wait() to find out if the process is alive, not tricks
> with the PID and process name, which are racy as you found out.

I'm not sure I can do that because the process I'm interested in isn't a
child of mine.
In any case, I'd still need to use the process name to make sure the PID
belongs to the original process, because PIDs are reused after a while.

Re: [autotest] vm creation fails (not)

[Gerd Hoffmann]

On 08/05/09 17:48, Michael Goldish wrote:
>> You should use wait() to find out if the process is alive, not tricks
>> with the PID and process name, which are racy as you found out.
>
> I'm not sure I can do that because the process I'm interested in isn't a
> child of mine.

wait() doesn't work then.  But why it isn't a child?

> In any case, I'd still need to use the process name to make sure the PID
> belongs to the original process, because PIDs are reused after a while.

No.  If it is your child the process continue to exist as zombie until 
you've asked for the exit status using wait().

cheers,
   Gerd

Re: [autotest] vm creation fails (not)

[Avi Kivity]

On 08/05/2009 06:48 PM, Michael Goldish wrote:
>
>    
>> You should use wait() to find out if the process is alive, not tricks
>> with the PID and process name, which are racy as you found out.
>>      
>
> I'm not sure I can do that because the process I'm interested in isn't a
> child of mine.
>    

It should be somebody's child and that somebody should wait for it.

> In any case, I'd still need to use the process name to make sure the PID
> belongs to the original process, because PIDs are reused after a while.
>    

waitpid() solves that problem without using the process name.  This 
isn't a new problem, you should use the established solutions.

-- 
error compiling committee.c: too many arguments to function

Re: [autotest] vm creation fails (not)

[Michael Goldish]

----- "Avi Kivity" <avi@redhat.com> wrote:

> On 08/05/2009 06:48 PM, Michael Goldish wrote:
> >
> >    
> >> You should use wait() to find out if the process is alive, not
> tricks
> >> with the PID and process name, which are racy as you found out.
> >>      
> >
> > I'm not sure I can do that because the process I'm interested in
> isn't a
> > child of mine.
> >    
> 
> It should be somebody's child and that somebody should wait for it.

I can find out if the parent process is alive by checking a lock file.
A little while ago I couldn't afford to do that in is_alive() because
it would cause a deadlock, but now this shouldn't be a problem.
I'll test it and if it works it'll greatly simplify is_alive().

> > In any case, I'd still need to use the process name to make sure the
> PID
> > belongs to the original process, because PIDs are reused after a
> while.
> >    
> 
> waitpid() solves that problem without using the process name.  This 
> isn't a new problem, you should use the established solutions.
> 
> -- 
> error compiling committee.c: too many arguments to function

Re: [autotest] vm creation fails (not)

[Avi Kivity]

On 08/05/2009 09:47 PM, Michael Goldish wrote:
>
> I can find out if the parent process is alive by checking a lock file.
> A little while ago I couldn't afford to do that in is_alive() because
> it would cause a deadlock, but now this shouldn't be a problem.
> I'll test it and if it works it'll greatly simplify is_alive().
>    

If you can't be the parent of the VM (I guess it needs to survive 
tests), set up a daemon to be the parent and communicate with it over 
unix domain sockets.

-- 
error compiling committee.c: too many arguments to function

Re: [autotest] vm creation fails (not)

[Michael Goldish]

----- "Avi Kivity" <avi@redhat.com> wrote:

> On 08/05/2009 09:47 PM, Michael Goldish wrote:
> >
> > I can find out if the parent process is alive by checking a lock
> file.
> > A little while ago I couldn't afford to do that in is_alive()
> because
> > it would cause a deadlock, but now this shouldn't be a problem.
> > I'll test it and if it works it'll greatly simplify is_alive().
> >    
> 
> If you can't be the parent of the VM (I guess it needs to survive 
> tests), set up a daemon to be the parent and communicate with it over
> unix domain sockets.

I do exactly that, but with named pipes.  Are unix domain sockets better?
(The pipes are not causing any trouble AFAIK.)

> 
> -- 
> error compiling committee.c: too many arguments to function

Re: [autotest] vm creation fails (not)

[Avi Kivity]

On 08/06/2009 01:43 PM, Michael Goldish wrote:
>
> I do exactly that, but with named pipes.  Are unix domain sockets better?
> (The pipes are not causing any trouble AFAIK.)
>    

They're a little better since you can pass file descriptors (like the 
monitor fd) over them.

-- 
error compiling committee.c: too many arguments to function