[one-users] Error - MAD did not answer INIT command

Tue Aug 28 06:22:01 PDT 2012

Hello everybody,

I have 4 physical computers: 1 as a FrontEnd with CentOS 6.2 and 
OpenNebula 3.6, two hosts with CentOS 6.2 and qemu-kvm and another as an 
nfs server with a debian based distro.
I created a VM and I was dealing with it when suddenly, it appeared 
several errors in sunstone web interface continuously.
After restarting one and sunstone-server daemons, it was no possible to 
open Sunstone web interface so I configured logs in debug mode and 
checked oned.log and sunstone.log and the error "MAD did not answer INIT 
command" repeats often along the log.

I guess the problem might be due to a failure loading vmm_kvm and/or 
im_kvm, so is it possible to manually load those drivers for checking it?
I've checked that all the computers are performing smoothly (no 
bottleneck on cpu, disk, ram...).

Please, could you help me on troubleshooting it?

Thanks is advance.

Carlos.

oned.log:

Tue Aug 28 15:03:37 2012 [ONE][I]: Log level:3 
[0=ERROR,1=WARNING,2=INFO,3=DEBUG]
Tue Aug 28 15:03:37 2012 [ONE][I]: Checking database version.
Tue Aug 28 15:03:37 2012 [VMM][I]: Starting Virtual Machine Manager...
Tue Aug 28 15:03:37 2012 [VMM][I]: Virtual Machine Manager started.
Tue Aug 28 15:03:37 2012 [LCM][I]: Starting Life-cycle Manager...
Tue Aug 28 15:03:37 2012 [LCM][I]: Life-cycle Manager started.
Tue Aug 28 15:03:37 2012 [InM][I]: Starting Information Manager...
Tue Aug 28 15:03:37 2012 [InM][I]: Information Manager started.
Tue Aug 28 15:03:37 2012 [TrM][I]: Starting Transfer Manager...
Tue Aug 28 15:03:37 2012 [TrM][I]: Transfer Manager started.
Tue Aug 28 15:03:37 2012 [DiM][I]: Starting Dispatch Manager...
Tue Aug 28 15:03:37 2012 [DiM][I]: Dispatch Manager started.
Tue Aug 28 15:03:37 2012 [HKM][I]: Starting Hook Manager...
Tue Aug 28 15:03:37 2012 [HKM][I]: Hook Manager started.
Tue Aug 28 15:03:37 2012 [AuM][I]: Starting Auth Manager...
Tue Aug 28 15:03:37 2012 [AuM][I]: Authorization Manager started.
Tue Aug 28 15:03:37 2012 [ImM][I]: Starting Image Manager...
Tue Aug 28 15:03:37 2012 [ImM][I]: Image Manager started.
Tue Aug 28 15:03:37 2012 [ReM][I]: Starting Request Manager...
Tue Aug 28 15:03:37 2012 [ReM][I]: Request Manager started.
Tue Aug 28 15:03:37 2012 [ReM][I]: Starting XML-RPC server, port 2633 ...
Tue Aug 28 15:03:39 2012 [VMM][I]: Loading Virtual Machine Manager drivers.
Tue Aug 28 15:03:39 2012 [VMM][I]:     Loading driver: vmm_kvm (KVM)
Tue Aug 28 15:03:39 2012 [MAD][E]: MAD did not answer INIT command
Tue Aug 28 15:03:39 2012 [InM][I]: Loading Information Manager drivers.
Tue Aug 28 15:03:39 2012 [InM][I]:     Loading driver: im_kvm
Tue Aug 28 15:03:39 2012 [MAD][E]: MAD did not answer INIT command
Tue Aug 28 15:03:39 2012 [TM][I]: Loading Transfer Manager driver.
Tue Aug 28 15:03:39 2012 [MAD][E]: MAD did not answer INIT command
Tue Aug 28 15:03:39 2012 [HKM][I]: Loading Hook Manager driver.
Tue Aug 28 15:03:39 2012 [MAD][E]: MAD did not answer INIT command
Tue Aug 28 15:03:39 2012 [ImM][I]: Loading Image Manager driver.
Tue Aug 28 15:03:39 2012 [MAD][E]: MAD did not answer INIT command
Tue Aug 28 15:03:39 2012 [AuM][I]: Loading Auth. Manager driver.
Tue Aug 28 15:03:39 2012 [MAD][E]: MAD did not answer INIT command
Tue Aug 28 15:03:43 2012 [ReM][D]: UserPoolInfo method invoked
Tue Aug 28 15:03:43 2012 [AuM][E]: Auth Error: Could not find 
Authorization driver
Tue Aug 28 15:03:43 2012 [ReM][E]: [UserPoolInfo] User couldn't be 
authenticated, aborting call.
Tue Aug 28 15:03:54 2012 [ONE][E]: SQL command was: DELETE FROM 
vm_monitoring WHERE last_poll < 1346072632, error: database is locked
Tue Aug 28 15:03:57 2012 [ONE][E]: SQL command was: DELETE FROM 
host_monitoring WHERE last_mon_time < 1346072632, error: database is locked
Tue Aug 28 15:03:57 2012 [InM][I]: Monitoring host Host1 (3)
Tue Aug 28 15:03:57 2012 [InM][E]: Could not find information driver im_kvm
Tue Aug 28 15:03:57 2012 [VMM][I]: Monitoring VM 31.
Tue Aug 28 15:03:59 2012 [ONE][E]: SQL command was: REPLACE INTO 
host_pool (oid, name, body, state, last_mon_time, uid, gid, owner_u, 
group_u, other_u) VALUES 
(3,'Host1','<HOST><ID>3</ID><NAME>Host1</NAME><STATE>3</STATE><IM_MAD>im_kvm</IM_MAD><VM_MAD>vmm_kvm</VM_MAD><VN_MAD>dummy</VN_MAD><LAST_MON_TIME>1346151563</LAST_MON_TIME><CLUSTER_ID>100</CLUSTER_ID><CLUSTER>Cluster1</CLUSTER><HOST_SHARE><DISK_USAGE>0</DISK_USAGE><MEM_USAGE>0</MEM_USAGE><CPU_USAGE>0</CPU_USAGE><MAX_DISK>0</MAX_DISK><MAX_MEM>3922016</MAX_MEM><MAX_CPU>800</MAX_CPU><FREE_DISK>0</FREE_DISK><FREE_MEM>3732716</FREE_MEM><FREE_CPU>800</FREE_CPU><USED_DISK>0</USED_DISK><USED_MEM>189300</USED_MEM><USED_CPU>0</USED_CPU><RUNNING_VMS>0</RUNNING_VMS></HOST_SHARE><TEMPLATE><ARCH><![CDATA[x86_64]]></ARCH><CPUSPEED><![CDATA[1861]]></CPUSPEED><FREECPU><![CDATA[800.0]]></FREECPU><FREEMEMORY><![CDATA[3732716]]></FREEMEMORY><HOSTNAME><![CDATA[host1]]></HOSTNAME><HYPERVISOR><![CDATA[kvm]]></HYPERVISOR><MODELNAME><![CDATA[Intel(R) 
Xeon(R) CPU E5320 @ 
1.86GHz]]></MODELNAME><NETRX><![CDATA[926024]]></NETRX><NETTX><![CDATA[0]]></NETTX><TOTALCPU><![CDATA[800]]></TOTALCPU><TOTALMEMORY><![CDATA[3922016]]></TOTALMEMORY><USEDCPU><![CDATA[0.0]]></USEDCPU><USEDMEMORY><![CDATA[189300]]></USEDMEMORY></TEMPLATE></HOST>',3,1346151563,0,0,1,0,0), 
error: database is locked
Tue Aug 28 15:03:59 2012 [InM][I]: Monitoring host Host2 (4)
Tue Aug 28 15:03:59 2012 [InM][E]: Could not find information driver im_kvm

Sunstone-server log:

[oneadmin at frontend etc]$ cat /var/log/one/sunstone.log
--------------------------------------
          Server configuration
--------------------------------------
{:vnc_proxy_cert=>nil,
  :tmpdir=>"/var/tmp/one",
  :vnc_proxy_path=>"/usr/share/one/noVNC/utils/websockify",
  :marketplace_url=>"https://marketplace.c12g.com/appliance",
  :vnc_proxy_key=>nil,
  :lang=>"en_US",
  :auth=>"sunstone",
  :vnc_proxy_base_port=>29876,
  :vnc_proxy_support_wss=>false,
  :debug_level=>3,
  :host=>"0.0.0.0",
  :one_xmlrpc=>"http://localhost:2633/RPC2",
  :core_auth=>"cipher",
  :port=>9869}
Tue Aug 28 15:03:43 2012 [E]: Error initializing authentication system
Tue Aug 28 15:03:43 2012 [E]: [UserPoolInfo] User couldn't be 
authenticated, aborting call.

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.opennebula.org/pipermail/users-opennebula.org/attachments/20120828/5051a863/attachment-0001.htm>