Bug 1035484

Sandro, why do you consider the VM as ever being Up?
I do see that vmSetTicket was sent before Vdsm was notified by libvirt about the new VM being up. Vdsm must not report Up before _domDependentInit has finished.

Thread-131::DEBUG::2013-11-27 12:57:31,964::BindingXMLRPC::984::vds::(wrapper) client [127.0.0.1]::call vmSetTicket with ('8843865f-f656-4db2-9751-8c2ed203e781', '2136oXkr', '10800', 'disconnect', {}) {}
Thread-131::ERROR::2013-11-27 12:57:31,965::BindingXMLRPC::1003::vds::(wrapper) unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/BindingXMLRPC.py", line 989, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/BindingXMLRPC.py", line 240, in vmSetTicket
    return vm.setTicket(password, ttl, existingConnAction, params)
  File "/usr/share/vdsm/API.py", line 592, in setTicket
    return v.setTicket(password, ttl, existingConnAction, params)
  File "/usr/share/vdsm/vm.py", line 4303, in setTicket
    graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
AttributeError: 'NoneType' object has no attribute 'XMLDesc'
libvirtEventLoop::DEBUG::2013-11-27 12:50:27,985::vm::4918::vm.Vm::(_onLibvirtLifecycleEvent) vmId=`8843865f-f656-4db2-9751-8c2ed203e781`::event Started detail 0 opaque None

I suspect there's a bug in the client (you should wait for Up before you set a ticket).

(In reply to Dan Kenigsberg from comment #3)
> Sandro, why do you consider the VM as ever being Up?
> I do see that vmSetTicket was sent before Vdsm was notified by libvirt about
> the new VM being up. Vdsm must not report Up before _domDependentInit has
> finished.

Well, the client call setTicket until it return with success (for a max number of tries, 10 IIRC)

Maybe it would be better to poll the VM Status and then send setTicket.

Can you open a BZ specifying the correct sequence? Thanks!

However, this bug is about a different issue:

Thread-55::DEBUG::2013-11-27 12:50:43,106::libvirtconnection::108::libvirtconnection::(wrapper) Unknown libvirterror: ecode: 55 edom: 10 level: 2 message: Requested operation is not valid: cgroup CPUACCT controller is not mounted
Thread-55::ERROR::2013-11-27 12:50:43,106::sampling::355::vm.Vm::(collect) vmId=`8843865f-f656-4db2-9751-8c2ed203e781`::Stats function failed: <AdvancedStatsFunction _sampleCpu at 0x19f6df8>
Traceback (most recent call last):
  File "/usr/share/vdsm/sampling.py", line 351, in collect
    statsFunction()
  File "/usr/share/vdsm/sampling.py", line 226, in __call__
    retValue = self._function(*args, **kwargs)
  File "/usr/share/vdsm/vm.py", line 522, in _sampleCpu
    cpuStats = self._vm._dom.getCPUStats(True, 0)
  File "/usr/share/vdsm/vm.py", line 824, in f
    ret = attr(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/vdsm/libvirtconnection.py", line 76, in wrapper
    ret = f(*args, **kwargs)
  File "/usr/lib64/python2.6/site-packages/libvirt.py", line 1868, in getCPUStats
    if ret is None: raise libvirtError ('virDomainGetCPUStats() failed', dom=self)
libvirtError: Requested operation is not valid: cgroup CPUACCT controller is not mounted

(In reply to Sandro Bonazzola from comment #4)
> (In reply to Dan Kenigsberg from comment #3)
> > Sandro, why do you consider the VM as ever being Up?
> > I do see that vmSetTicket was sent before Vdsm was notified by libvirt about
> > the new VM being up. Vdsm must not report Up before _domDependentInit has
> > finished.
> 
> Well, the client call setTicket until it return with success (for a max
> number of tries, 10 IIRC)
> 
> Maybe it would be better to poll the VM Status and then send setTicket.
> 

moving back to sla as this originates in the hosted engine scripts

libvirtError: Requested operation is not valid: cgroup CPUACCT controller is not mounted

Seems that libvirtd is still missing the dependency on cgconfig service.
I will fix this adding cgconfig as dependency and will start that service before starting libvirtd.




(In reply to Dan Kenigsberg from comment #3)
> Sandro, why do you consider the VM as ever being Up?
> I do see that vmSetTicket was sent before Vdsm was notified by libvirt about
> the new VM being up. Vdsm must not report Up before _domDependentInit has
> finished.
> 
> Thread-131::DEBUG::2013-11-27
> 12:57:31,964::BindingXMLRPC::984::vds::(wrapper) client [127.0.0.1]::call
> vmSetTicket with ('8843865f-f656-4db2-9751-8c2ed203e781', '2136oXkr',
> '10800', 'disconnect', {}) {}
> Thread-131::ERROR::2013-11-27
> 12:57:31,965::BindingXMLRPC::1003::vds::(wrapper) unexpected error
> Traceback (most recent call last):
>   File "/usr/share/vdsm/BindingXMLRPC.py", line 989, in wrapper
>     res = f(*args, **kwargs)
>   File "/usr/share/vdsm/BindingXMLRPC.py", line 240, in vmSetTicket
>     return vm.setTicket(password, ttl, existingConnAction, params)
>   File "/usr/share/vdsm/API.py", line 592, in setTicket
>     return v.setTicket(password, ttl, existingConnAction, params)
>   File "/usr/share/vdsm/vm.py", line 4303, in setTicket
>     graphics = _domParseStr(self._dom.XMLDesc(0)).childNodes[0]. \
> AttributeError: 'NoneType' object has no attribute 'XMLDesc'
> libvirtEventLoop::DEBUG::2013-11-27
> 12:50:27,985::vm::4918::vm.Vm::(_onLibvirtLifecycleEvent)
> vmId=`8843865f-f656-4db2-9751-8c2ed203e781`::event Started detail 0 opaque
> None
> 
> I suspect there's a bug in the client (you should wait for Up before you set
> a ticket).

Please open a separate bug for this issue.

patch merged on upstream master and 1.0 branches

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

http://rhn.redhat.com/errata/RHBA-2014-0083.html