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

Wed Aug 29 01:55:48 PDT 2012

Hello,

The problem seems to be solved. I've just restarted one and 
sunstone-server and those errors have disappeared. Yesterday, I 
restarted both daemons but it didn't solve the problem. However, today 
it has been enough. I suspect this action has not been the reason of the 
solution. So, in order to prevent this errors again, could you give me 
any clue to locate the source of the problem?
 From other messages from people having similar errors, I've read that 
it could be done to the use of a VM as a frontend or because computer 
was having a high load. In this case, all are physical computers and 
running smoothly.

I've configured ONE_MAD_DEBUG = 1 (in /etc/one/defaultrc) in order to 
enable drivers debugging information. Which is the associated log file? 
Is it one of these?
one_auth_mad.log
one_datastore.log
one_hm.log
one_im_ssh_one_im_exec.log
one_tm.log
one_vmm_exec.log

Thank you,

Carlos.

On 08/28/2012 03:22 PM, Carlos Jiménez wrote:
> 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>& 
> lt;![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/20120829/829ef901/attachment-0002.htm>