- Users - oVirt List Archives

[Users] general (totally noob) questions...
by Michael Hauber 27 Sep '12

27 Sep '12

While I am not completely new to running instances in KVM/Qemu, I am a total noob when it comes to clustering. While I realize that not all of these questions pertain specifically to the oVirt project, I would much rather get input from people that have experience in this environment. I am in the process of designing my next server farm and would like to know some basics that I can't seem to find the answers to via google search. Background: I have a server farm setup for a large family. It consists of 9 servers (minimal-to-medium loads for the most part, but they are in poor condition physically). My hopes are to run this same setup virtually in a 3-node cluster. I can run the entire farm in a virtual environment on a host with a dual, quad-core box with 64gig RAM. That said, I know that each of these nodes will be capable of handling the entire load by itself if absolutely necessary. For disk space, my hopes are to use two drive arrays (10 configuration?) which I can build (up and out) from without having too much trouble. Everything will be fiber, including drops to the computers and televisions. Copper will exist as well for things like POE, printers, etc. (but not in scope) Questions: 1. As I understand it, a N-to-N configuration means that there will be load balancing between the nodes as well as failover. Is the load balancing something that is manual (I have to monitor/balance the load manually, or is it done automatically?) 2. If it is done automatically, how do the loads get split up? Is the virtual machine itself the unit of load that transfers from one node to another or does it go so far as balancing services running inside those virtual machines? 3. For the fail-over, is it seemless in the sense that the user's connections don't get reset or is there a short period of down-time before the service is available again? While this isn't a big issue for me, it is something that I've been wondering about. 4. Fibre channel or FCOE? (I've spent entire evenings trying to get a straight answer through google searches, but there seem to be way too many agendas). Being that one of the virtual servers will be a media server for the televisions (new addition), my worry is lag-time (I would like to serve at least 5 televisions without lag-time). The array will also support things like file server, space for about 2-dozen www (family pages (lots of pictures)), space for mail, space for backups (rSync,Amanda), ISO boots, etc. I have the logical and physical topology drawn up for the most part, but until I understand a bit more, I'm scared _less about dropping any money into the project because I've neither seen a setup like this in action, and what I find online seems a bit vague in the way of details (dumbed-down enough for the likes of me to know if the hardware I'm buying is necessary and/or sufficient to achieve my goals). Any and all pointers, suggestions, patience, etc. would be greatly appreciated. mchauber

2 3

[Users] I can't figure out how to add a user?
by Alan Johnson 26 Sep '12

26 Sep '12

First off, oVirt noob alert. That said, I have been able to figure out and over come most of my issues getting oVirt running on CentOS 6.3 the various documentation that is available, including this list's archives for the last few months. (Side question: I haven't found a good way to search the archives short of using site: within google search, but that does not seem to work so well, so I have been relying on gmail's collection of the messages since I subscribed a few months ago. Is there a better way?) Anyway, this one seems like it should be so simple that I feel like I must be missing some thing painfully obvious. That is, I don't seem to be able to create a user. The GUI's add button on the user tab just lets me search existing users, but does not provide anywhere to enter new user info. I have successfully "added" the admin@internal user several times while bumbling around with that interface, but this is not terribly helpful since it has always been there. To what I have added it, I am am not entirely clear. I don't see anything in the getting started guide, and the administrator guide just walks me through the same useless steps I mentioned above in the user tab. Any nudge in the right direction would be greatly appreciated. I'll even accept dope slaps at this point if warranted. =) Thanks in advance for your time and consideration. _______________ Alan Johnson alan(a)datdec.com

2 2

[Users] Upgrade problem.
by Andres Gonzalez 25 Sep '12

25 Sep '12

Hi! I upgraded from oVirt 3.1.16 to 3.1.19 under CentOS 6.3 (yum update). The thing is now oVirt is not starting. The web interfaces says: Service Temporarily Unavailable, the VMs don't starts (the box is configured as all-in-one) I have 2 VMs on production. What I can do ? Thanks.-

3 9

[Users] Call for Agenda Items -- oVirt Weekly Sync 2012-09-26
by Mike Burns 25 Sep '12

25 Sep '12

Meeting Time and Place oVirt Weekly Sync * Wednesdays @ 15:00 UTC (may change during DST changes) - always at 7:00am US Pacific, 10:00am US Eastern. * To see in your timezone date -d 'WEDNESDAY 1000 EDT' * On IRC: #ovirt on irc.oftc.net This is the agenda for the 2012-09-26 meeting: * Status of Next Release (Release Criteria, Target GA date) * Sub-project reports (engine, vdsm, node, infra) * Workshops If you have other topics, please reply to me and I will add them to the agenda. If you propose a topic, please be prepared to lead the discussion during the meeting. Please note that this week's meeting will be run by Karsten (quaid) since I'm out of the office. Thanks Mike

2 2

[Users] How to change number of cpu cores with python sdk
by Don Dupuis 24 Sep '12

24 Sep '12

I am using Ovirt 3.1 with the ovirt-engine-sdk. I have written a python script using this sdk but I can't seem to get the parameters right to change the cpu cores when creating the vm. All the other parameters I want to change works just fine. Does anyone have an example on how to do this. Thanks Don

1 0

[Users] Installation problem
by Dave Neary 24 Sep '12

24 Sep '12

Hi all, I was working through the installation of ovirt-engine today (after spending more time than I care to admit struggling with networking & DNS issues - VPNs, dnsmasq, "classic" network start-up and iptables/firewall rules can interract with each other in strange and surprising ways). Anyway - I went through the engine set-up successfully, and got the expected message at the end: "**** Installation completed successfully ******" with a message to visit the engine web application to finish set-up. Unfortunately, when I connected (after resolving networking issues) to the server in question, I got a "Service temporarily unavailable" error (503) from Apache. in httpd's error.log, I have: > [Fri Sep 21 13:37:03 2012] [error] (111)Connection refused: proxy: AJP: attempt to connect to 127.0.0.1:8009 (localhost) failed > [Fri Sep 21 13:37:03 2012] [error] ap_proxy_connect_backend disabling worker for (localhost) > [Fri Sep 21 13:37:03 2012] [error] proxy: AJP: failed to make connection to backend: localhost When I try to restart the ovirt-engine service, I get the following in journalctl: > Sep 21 13:34:44 clare.neary.home engine-service.py[5172]: The engine PID file "/var/run/ovirt-engine.pid" already exists. > Sep 21 13:34:44 clare.neary.home systemd[1]: PID 1264 read from file /var/run/ovirt-engine.pid does not exist. > Sep 21 13:34:44 clare.neary.home systemd[1]: Unit ovirt-engine.service entered failed state. I tried to clean up and restart, but engine-cleanup failed: > [root@clare ovirt-engine]# engine-cleanup -u > > Stopping JBoss service... [ DONE ] > > Error: Couldn't connect to the database server.Check that connection is working and rerun the cleanup utility > Error: Cleanup failed. > please check log at /var/log/ovirt-engine/engine-cleanup_2012_09_21_14_02_37.log It turns out, in /var/log/messages, that I have these error messages: > Sep 21 14:00:59 clare pg_ctl[5298]: FATAL: could not create shared memory segment: Invalid argument > Sep 21 14:00:59 clare pg_ctl[5298]: DETAIL: Failed system call was shmget(key=5432001, size=36519936, 03600). > Sep 21 14:00:59 clare pg_ctl[5298]: HINT: This error usually means that PostgreSQL's request for a shared memory segment exceeded your kernel's SHMMAX parameter. You can either reduce the request size or reconfigure the kernel with larger SHMMAX. To reduce the request size (currently 36519936 bytes), reduce PostgreSQL's shared memory usage, perhaps by reducing shared_buffers or max_connections. > Sep 21 14:00:59 clare pg_ctl[5298]: If the request size is already small, it's possible that it is less than your kernel's SHMMIN parameter, in which case raising the request size or reconfiguring SHMMIN is called for. > Sep 21 14:00:59 clare pg_ctl[5298]: The PostgreSQL documentation contains more information about shared memory configuration. > Sep 21 14:01:03 clare pg_ctl[5298]: pg_ctl: could not start server > Sep 21 14:01:03 clare pg_ctl[5298]: Examine the log output. > Sep 21 14:01:03 clare systemd[1]: postgresql.service: control process exited, code=exited status=1 > Sep 21 14:01:03 clare systemd[1]: Unit postgresql.service entered failed state. I increased the kernel's SHMMAX, and engine-cleanup worked correctly. Has anyone else experienced this issue? When I re-run engine-setup, I also got stuck when reconfiguring NFS - when engine-setup asked me if I wanted to configure the NFS domain, I said "yes", but then it refused to accept my input of "/mnt/iso" since it was already in /etc/exports - perhaps engine-cleanup should also remove ISO shares managed by ovirt-engine, or else handle more gracefully when someone enters an existing export? The only fix I found was to interrupt and restart the engine set-up. Also, I have no idea whether allowing oVirt to manage iptables will keep any extra rules I have added (specifically for DNS services on port 53 UDP) which I added to the iptables config. I didn't take the risk of allowing it to reconfigure iptables the second time. After all that, I got an error when starting the JBoss service: > Starting JBoss Service... [ ERROR ] > Error: Can't start the ovirt-engine service > Please check log file /var/log/ovirt-engine/engine-setup_2012_09_21_14_28_11.log for more information And when I checked that log file: > 2012-09-21 14:30:02::DEBUG::common_utils::790::root:: starting ovirt-engine > 2012-09-21 14:30:02::DEBUG::common_utils::835::root:: executing action ovirt-engine on service start > 2012-09-21 14:30:02::DEBUG::common_utils::309::root:: Executing command --> '/sbin/service ovirt-engine start' > 2012-09-21 14:30:02::DEBUG::common_utils::335::root:: output = > 2012-09-21 14:30:02::DEBUG::common_utils::336::root:: stderr = Redirecting to /bin/systemctl start ovirt-engine.service > Job failed. See system journal and 'systemctl status' for details. > > 2012-09-21 14:30:02::DEBUG::common_utils::337::root:: retcode = 1 > 2012-09-21 14:30:02::DEBUG::setup_sequences::62::root:: Traceback (most recent call last): > File "/usr/share/ovirt-engine/scripts/setup_sequences.py", line 60, in run > function() > File "/bin/engine-setup", line 1535, in _startJboss > srv.start(True) > File "/usr/share/ovirt-engine/scripts/common_utils.py", line 795, in start > raise Exception(output_messages.ERR_FAILED_START_SERVICE % self.name) > Exception: Error: Can't start the ovirt-engine service And when I check the system journal, we're back to the service starts, but the PID mentioned in the PID file does not exist. Any pointers into how I might debug this issue? I haven't found anything similar in a troubleshooting page, so perhaps it's not a common error? Cheers, Dave. -- Dave Neary Community Action and Impact Open Source and Standards, Red Hat Ph: +33 9 50 71 55 62 / Cell: +33 6 77 01 92 13

5 11

[Users] SPM not selected after host failed
by "Marc-Christian Schröer | ingenit GmbH & Co. KG" 24 Sep '12

24 Sep '12

Hello all, we are currently in the process of evaluating oVirt as a basis for our new virutalization environment. As far as our evaluation has processed it seems to be the way to go, but when testing the high availability features I ran into a serious problem: Our testing setup looks like this: 2 hosts on Dell R210 and R210II machines, a seperate machine running the managing application in JBoss and providing storage space through NFS. Under normal conditions everything works fine: I can migrate machines between the two nodes, I can add a third node, access everything by VNC, monitor the VMs really nicely, the power management feature of the R210s work just fine. Then, when simulating the loss of a host by pulling the plug on the machine, (yes, that is kind of a crude check) some things seem to go terribly wrong: the system detects the host being unresponsive and assumes it is down. But the host happens to be the SPM and the other does not take over this function. This leaves the hole cluster in an unresponseive state and my datacenter is gone. I tracked down the problem in the log files to the point where the engine tries to migrate the SPM to another node: 2012-09-20 07:54:40,836 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-60) SPM selection - vds seems as spm node03 2012-09-20 07:54:40,837 WARN [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-60) spm vds is non responsive, stopping spm selection. 2012-09-20 07:54:44,344 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-51) XML RPC error in command GetCapabilitiesVDS ( Vds: node03 ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, NoRouteToHostException: Keine Route zum Zielrechner 2012-09-20 07:54:47,345 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand] (QuartzScheduler_Worker-47) XML RPC error in command GetCapabilitiesVDS ( Vds: node03 ), the error was: java.util.concurrent.ExecutionException: java.lang.reflect.InvocationTargetException, NoRouteToHostException: Keine Route zum Zielrechner 2012-09-20 07:54:50,869 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-69) hostFromVds::selectedVds - node04, spmStatus Free, storage pool ingenit 2012-09-20 07:54:50,892 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-69) SPM Init: could not find reported vds or not up - pool:ingenit vds_spm_id: 2 2012-09-20 07:54:50,905 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (QuartzScheduler_Worker-69) SPM selection - vds seems as spm node03 As far as I understand these logs, the engine detects node03 not being responsive, starts electing a new SPM but does not find node04. That is strange as the host is online, pingable and worked just fine as part of the cluster. What I can do to remedy the situation using the management interface to set "Confirm Host has been rebooted" and switch the host into maintenance mode after that. Than the responsive node takes over and the VMs are being migrated, too. Has anyone experienced a similar problem? Is this by design and killing off the SPM is a bad coincident and always requires manual intervention? I would hope not :-) I tried to google some answers, but aside from a thread in May that did not help I came up empty. Thanks in advance for all the help... Kind regards from Germany, Marc -- ________________________________________________________________________ Dipl.-Inform. Marc-Christian Schröer schroeer(a)ingenit.com Geschäftsführer / CEO ---------------------------------------------------------------------- ingenit GmbH & Co. KG Tel. +49 (0)231 58 698-120 Emil-Figge-Strasse 76-80 Fax. +49 (0)231 58 698-121 D-44227 Dortmund www.ingenit.com Registergericht: Amtsgericht Dortmund, HRA 13 914 Gesellschafter : Thomas Klute, Marc-Christian Schröer ________________________________________________________________________

6 12

[Users] family cpu compatibility item
by Nathanaël Blanchet 24 Sep '12

24 Sep '12

Hi, Does anyone know what importance have the "family cpu compatibility item" into the cluster tab? Is there any consequence on the host performance? -- Nathanaël Blanchet Supervision réseau Pôle exploitation et maintenance Département des systèmes d'information 227 avenue Professeur-Jean-Louis-Viala 34193 MONTPELLIER CEDEX 5 Tél. 33 (0)4 67 54 84 55 Fax 33 (0)4 67 54 84 14 blanchet(a)abes.fr

3 2

[Users] vdsmd doesn't restart after rebooting
by Nathanaël Blanchet 23 Sep '12

23 Sep '12

Hi all, In the latest vdsm build from git (vdsm-4.10.0-0.452.git87594e3.fc17.x86_64), vdsmd.service never starts alone after rebooting. I have had a look to journalctl anfd I've found this : systemd-vdsmd[538]: vdsm: Failed to define network filters on libvirt[FAILED] [root@node ~]# service vdsmd status Redirecting to /bin/systemctl status vdsmd.service vdsmd.service - Virtual Desktop Server Manager Loaded: loaded (/usr/lib/systemd/system/vdsmd.service; enabled) Active: failed (Result: exit-code) since Fri, 21 Sep 2012 12:13:01 +0200; 4min 56s ago Process: 543 ExecStart=/lib/systemd/systemd-vdsmd start (code=exited, status=1/FAILURE) CGroup: name=systemd:/system/vdsmd.service Sep 21 12:12:55 node.abes.fr systemd-vdsmd[543]: Note: Forwarding request to 'systemctl disable libvirt-guests.service'. Sep 21 12:12:56 node.abes.fr systemd-vdsmd[543]: vdsm: libvirt already configured for vdsm [ OK ] Sep 21 12:12:56 node.abes.fr systemd-vdsmd[543]: Starting wdmd... Sep 21 12:12:56 node.abes.fr systemd-vdsmd[543]: Starting sanlock... Sep 21 12:12:56 node.abes.fr systemd-vdsmd[543]: Starting iscsid: Sep 21 12:13:01 node.abes.fr systemd-vdsmd[543]: Starting libvirtd (via systemctl): [ OK ] May this nwfilter be the cause of the failure? If yes, do I need to open a BZ? Thank you for your answer -- Nathanaël Blanchet Supervision réseau Pôle exploitation et maintenance Département des systèmes d'information 227 avenue Professeur-Jean-Louis-Viala 34193 MONTPELLIER CEDEX 5 Tél. 33 (0)4 67 54 84 55 Fax 33 (0)4 67 54 84 14 blanchet(a)abes.fr

4 4

[Users] ActiveDirectory problems
by Joop 23 Sep '12

23 Sep '12

Hi List, I have been reading the list for quite sometime and I have a question because I can't find the problem myself. I have an oVirt-3.1 setup with 3 nodes (Fed17 install from LiveCD + vdsm) and an engine install. Sofar this all works. Can create VM's, can migrate them, no problems ( well one but thats for another post, vdsmd doesn't start at system start). Version of oVirt thats installed: Installed Packages ovirt-engine.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-backend.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-cli.noarch 3.1.0.6-1.fc17 @ovirt-beta ovirt-engine-config.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-dbscripts.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-genericapi.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-notification-service.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-restapi.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-sdk.noarch 3.1.0.4-1.fc17 @ovirt-beta ovirt-engine-setup.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-tools-common.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-userportal.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-engine-webadmin-portal.noarch 3.1.0-2.fc17 @ovirt-beta ovirt-image-uploader.noarch 3.1.0-0.git9c42c8.fc17 @ovirt-beta ovirt-iso-uploader.noarch 3.1.0-0.git1841d9.fc17 @ovirt-beta ovirt-log-collector.noarch 3.1.0-0.git10d719.fc17 @ovirt-beta Next step is integrating with our AD setup. Ran engine-manage-domains -action=add -provider=ActiveDirectory -domain=nieuwland.local -user=admin -interactive Message is: WARNING: No permissions were added to the Engine. Login either with the internal admin user or with another configured user Successfully added domain nieuwland.local. oVirt Engine restart is required in order for the changes to take place (service Manage Domains completed successfully The specified admin is an DomainAdministrator. The logfile in /var/log/engine/engine-manage-domains also says OK. The resulting krb5.conf in /etc/ovirt-engine looks also OK. The AD servers are resolvable forward and backward. Then I'm lost because when I log into the Admin portal with the internal admin account and goto the Users tab and want to add a user from the nieuwland.local, myself (jvandewege) realm it won't work and I get the following in engine.log 2012-09-14 12:55:26,104 ERROR [org.ovirt.engine.core.bll.adbroker.DirectorySearcher] (ajp--0.0.0.0-8009-12) Failed ldap search server LDAP://digit.nieuwland.local:389 due to java.lang.NullPointerException. We should try the next server: java.lang.NullPointerException at org.ovirt.engine.core.bll.adbroker.ADRootDSE.<init>(ADRootDSE.java:26) [engine-bll.jar:] at org.ovirt.engine.core.bll.adbroker.RootDSEFactory.get(RootDSEFactory.java:14) [engine-bll.jar:] at org.ovirt.engine.core.bll.adbroker.GetRootDSETask.setRootDSE(GetRootDSETask.java:97) [engine-bll.jar:] at org.ovirt.engine.core.bll.adbroker.GetRootDSETask.call(GetRootDSETask.java:68) [engine-bll.jar:] at org.ovirt.engine.core.bll.adbroker.DirectorySearcher.find(DirectorySearcher.java:91) [engine-bll.jar:] at org.ovirt.engine.core.bll.adbroker.DirectorySearcher.FindOne(DirectorySearcher.java:39) [engine-bll.jar:] at org.ovirt.engine.core.bll.adbroker.LdapAuthenticateUserCommand.executeQuery(LdapAuthenticateUserCommand.java:44) [engine-bll.jar:] at org.ovirt.engine.core.bll.adbroker.LdapBrokerCommandBase.Execute(LdapBrokerCommandBase.java:68) [engine-bll.jar:] at org.ovirt.engine.core.bll.adbroker.LdapBrokerBase.RunAdAction(LdapBrokerBase.java:18) [engine-bll.jar:] at org.ovirt.engine.core.bll.LoginUserCommand.authenticateUser(LoginUserCommand.java:30) [engine-bll.jar:] at org.ovirt.engine.core.bll.LoginBaseCommand.isUserCanBeAuthenticated(LoginBaseCommand.java:177) [engine-bll.jar:] at org.ovirt.engine.core.bll.LoginAdminUserCommand.canDoAction(LoginAdminUserCommand.java:14) [engine-bll.jar:] at org.ovirt.engine.core.bll.CommandBase.InternalCanDoAction(CommandBase.java:486) [engine-bll.jar:] at org.ovirt.engine.core.bll.CommandBase.ExecuteAction(CommandBase.java:261) [engine-bll.jar:] at org.ovirt.engine.core.bll.Backend.Login(Backend.java:481) [engine-bll.jar:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea] at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea] at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.1.Final] at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:] at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea] at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea] at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation.jar:1.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:211) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:363) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:194) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:173) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final] at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final] at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee-7.1.1.Final.jar:7.1.1.Final] at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view9.Login(Unknown Source) [engine-common.jar:] at org.ovirt.engine.ui.frontend.server.gwt.GenericApiGWTServiceImpl.Login(GenericApiGWTServiceImpl.java:157) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea] at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea] at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea] at com.google.gwt.rpc.server.RPC.invokeAndStreamResponse(RPC.java:196) at com.google.gwt.rpc.server.RpcServlet.processCall(RpcServlet.java:161) at com.google.gwt.rpc.server.RpcServlet.processPost(RpcServlet.java:222) at com.google.gwt.user.server.rpc.AbstractRemoteServiceServlet.doPost(AbstractRemoteServiceServlet.java:62) at javax.servlet.http.HttpServlet.service(HttpServlet.java:754) [jboss-servlet-3.0-api.jar:1.0.1.Final] at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-3.0-api.jar:1.0.1.Final] at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329) at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248) at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275) at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161) at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153) at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155) at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102) at org.jboss.web.rewrite.RewriteValve.invoke(RewriteValve.java:466) at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368) at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:505) at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:445) at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:930) at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_05-icedtea] 2012-09-14 12:55:26,124 ERROR [org.ovirt.engine.core.bll.adbroker.LdapAuthenticateUserCommand] (ajp--0.0.0.0-8009-12) Failed authenticating user: admin to domain nieuwland.local. Ldap Query Type is getUserByName 2012-09-14 12:55:26,125 ERROR [org.ovirt.engine.core.bll.LoginAdminUserCommand] (ajp--0.0.0.0-8009-12) USER_FAILED_TO_AUTHENTICATE : admin 2012-09-14 12:55:26,125 WARN [org.ovirt.engine.core.bll.LoginAdminUserCommand] (ajp--0.0.0.0-8009-12) CanDoAction of action LoginAdminUser failed. Reasons:USER_FAILED_TO_AUTHENTICATE 2012-09-14 12:57:07,027 INFO [org.ovirt.engine.core.bll.LoginAdminUserCommand] (ajp--0.0.0.0-8009-5) Checking if user admin@internal is an admin, result true 2012-09-14 12:57:07,029 INFO [org.ovirt.engine.core.bll.LoginAdminUserCommand] (ajp--0.0.0.0-8009-5) Running command: LoginAdminUserCommand internal: false. Using Wireshark I don't see what I expected namely a well formed ldap search and a result. Can provide the dmp if needed. Anyone had any luck and is willing to help me out? Thanks in advance, Joop

4 9

[Users] non-operational state as host does not meet clusters' minimu CPU level.
by wujieke 23 Sep '12

23 Sep '12

Hi, everyone, if it's not the right mail list, pls point out.. thanks.. I am trying to install the ovirt on my Xeon E5-2650 process on Dell server, which is installed with Fedora 17. While I create a new host , which actually is the same server as overt-engine is running. The host is created ,and starting to "installing". But it ends with "Non operational state". Error: Host CPU type is not compatible with cluster properties, missing CPU feature: model_sandybridge. But in my cluster, I select "sandybridge" CPU, and my Xeon C5 is also in Sandy bridge family. And also this error lead my server reboot. Any help is appreciated. Btw: I have enable INTEL-VT in BIOS. And modprobe KVM and kvm-intel modules. . attached is screen shot for error.

5 12

Re: [Users] Problem with creating a glusterfs volume
by Dominic Kaiser 22 Sep '12

22 Sep '12

Here is the message and the logs again except zipped I failed the first delivery: Ok here are the logs 4 node and 1 engine log. Tried making /data folder owned by root and then tried by 36:36 neither worked. Name of volume is data to match folders on nodes also. Let me know what you think, Dominic On Mon, Sep 10, 2012 at 11:24 AM, Dominic Kaiser <dominic(a)bostonvineyard.org > wrote: > Here are the other two logs forgot them. > > dk > > > On Mon, Sep 10, 2012 at 11:19 AM, Dominic Kaiser < > dominic(a)bostonvineyard.org> wrote: > >> Ok here are the logs 4 node and 1 engine log. Tried making /data folder >> owned by root and then tried by 36:36 neither worked. Name of volume is >> data to match folders on nodes also. >> >> Let me know what you think, >> >> Dominic >> >> >> On Thu, Sep 6, 2012 at 8:33 AM, Maxim Burgerhout <maxim(a)wzzrd.com> wrote: >> >>> I just ran into this as well, and it seems that you have to either >>> reformat previously used gluster bricks or manually tweak some extended >>> attributes. >>> >>> Maybe this helps you in setting up your gluster volume, Dominic? >>> >>> More info here: https://bugzilla.redhat.com/show_bug.cgi?id=812214 >>> >>> >>> Maxim Burgerhout >>> maxim(a)wzzrd.com >>> ---------------- >>> EB11 5E56 E648 9D99 E8EF 05FB C513 6FD4 1302 B48A >>> >>> >>> >>> >>> >>> On Thu, Sep 6, 2012 at 7:50 AM, Shireesh Anjal <sanjal(a)redhat.com>wrote: >>> >>>> Hi Dominic, >>>> >>>> Looking at the engine log immediately after trying to create the volume >>>> should tell us on which node the gluster volume creation was attempted. >>>> Then looking at the vdsm log on that node should help us identifying the >>>> exact reason for failure. >>>> >>>> In case this doesn't help you, can you please simulate the issue again >>>> and send back all the 5 log files? (engine.log from engine server and >>>> vdsm.log from the 4 nodes) >>>> >>>> Regards, >>>> Shireesh >>>> >>>> >>>> On Wednesday 05 September 2012 11:50 PM, Dominic Kaiser wrote: >>>> >>>> So I have a problem creating glusterfs volumes. Here is the install: >>>> >>>> >>>> 1. Ovirt 3.1 >>>> 2. 4 Nodes are Fedora 17 with kernel 3.3.4 - 5.fc17.x86_64 >>>> 3. 4 nodes peer joined and running >>>> 4. 4 nodes added as hosts to ovirt >>>> 5. created a directory on each node this path /data >>>> 6. chmod 36.36 -R /data all nodes >>>> 7. went back to ovirt and created a distributed/replicated volume >>>> and added the 4 nodes with brick path of /data >>>> >>>> I received this error: >>>> >>>> Creation of Gluster Volume maingfs1 failed. >>>> >>>> I went and looked at the vdsm logs on the nodes and the ovirt server >>>> which did not say much. Where else should I look? Also this error is >>>> vague what does it mean? >>>> >>>> >>>> -- >>>> Dominic Kaiser >>>> Greater Boston Vineyard >>>> Director of Operations >>>> >>>> cell: 617-230-1412 >>>> fax: 617-252-0238 >>>> email: dominic(a)bostonvineyard.org >>>> >>>> >>>> >>>> >>>> _______________________________________________ >>>> Users mailing listUsers@ovirt.orghttp://lists.ovirt.org/mailman/listinfo/users >>>> >>>> >>>> >>>> _______________________________________________ >>>> Users mailing list >>>> Users(a)ovirt.org >>>> http://lists.ovirt.org/mailman/listinfo/users >>>> >>>> >>> >> >> >> -- >> Dominic Kaiser >> Greater Boston Vineyard >> Director of Operations >> >> cell: 617-230-1412 >> fax: 617-252-0238 >> email: dominic(a)bostonvineyard.org >> >> >> > > > -- > Dominic Kaiser > Greater Boston Vineyard > Director of Operations > > cell: 617-230-1412 > fax: 617-252-0238 > email: dominic(a)bostonvineyard.org > > > -- Dominic Kaiser Greater Boston Vineyard Director of Operations cell: 617-230-1412 fax: 617-252-0238 email: dominic(a)bostonvineyard.org

3 9

[Users] API Documentation
by ?????? 21 Sep '12

21 Sep '12

This is a multi-part message in MIME format. ------=_NextPart_000_0571_01CD97F2.2C02C030 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Hi, where can I documentation ovirt api? Interest features: 1. Suspended Virtual Machine 2. Creating a snapshot 3. Import snapshot to export storage ------=_NextPart_000_0571_01CD97F2.2C02C030 Content-Type: text/html; charset="us-ascii" Content-Transfer-Encoding: quoted-printable <html xmlns:v=3D"urn:schemas-microsoft-com:vml" = xmlns:o=3D"urn:schemas-microsoft-com:office:office" = xmlns:w=3D"urn:schemas-microsoft-com:office:word" = xmlns:m=3D"http://schemas.microsoft.com/office/2004/12/omml" = xmlns=3D"http://www.w3.org/TR/REC-html40"><head> <META HTTP-EQUIV=3D"Content-Type" CONTENT=3D"text/html; = charset=3Dus-ascii"> <meta name=3DGenerator content=3D"Microsoft Word 12 (filtered = medium)"><style></style></head><body lang=3DRU link=3Dblue = vlink=3Dpurple><div class=3DWordSection1>Hi, where can I documentation ovirt = api?<o:p></o:p>Interest features:<o:p></o:p><![if !supportLists]>1.       = <![endif]>Suspended Virtual = Machine<o:p></o:p><![if = !supportLists]>2.       = <![endif]>Creating a = snapshot<o:p></o:p><![if = !supportLists]>3.       = <![endif]>Import snapshot to = export storage<o:p></o:p><o:p> </o:p><o:p> </o:p><o:p> </o:p></div></body></html> ------=_NextPart_000_0571_01CD97F2.2C02C030--

3 2

[Users] Fatal error during migration
by Dmitriy A Pyryakov 21 Sep '12

21 Sep '12

--0__=C9BBF0ECDFA610B98f9e8a93df938690918cC9BBF0ECDFA610B9 Content-type: text/plain; charset=US-ASCII Content-transfer-encoding: quoted-printable Hello, I have two oVirt nodes ovirt-node-iso-2.5.0-2.0.fc17. When I try to migrate VM from one host to another, I have an error: Migration failed due to Error: Fatal error during migration. vdsm.log: Thread-3797::DEBUG::2012-09-20 09:42:56,439::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmMigrate with ({'src': '192.168.10.13', 'dst': '192.168.10.12:54321', 'vmId': '2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86', 'method': 'online'},) {} flowID [180ad979] Thread-3797::DEBUG::2012-09-20 09:42:56,439::API::441::vds::(migrate) {'src': '192.168.10.13', 'dst': '192.168.10.12:54321', 'vmId': '2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86', 'method': 'online'} Thread-3798::DEBUG::2012-09-20 09:42:56,441::vm::122::vm.Vm::(_setupVdsConnection) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::Destination server is: 192.168.10.12:54321 Thread-3797::DEBUG::2012-09-20 09:42:56,441::BindingXMLRPC::865::vds::(wrapper) return vmMigrate with {'status': {'message': 'Migration process starting', 'code': 0}} Thread-3798::DEBUG::2012-09-20 09:42:56,441::vm::124::vm.Vm::(_setupVdsConnection) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::Initiating connection wi= th destination Thread-3798::DEBUG::2012-09-20 09:42:56,452::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::Disk hdc stats not avail= able Thread-3798::DEBUG::2012-09-20 09:42:56,457::vm::170::vm.Vm::(_prepareGuest) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::migration Process begins= Thread-3798::DEBUG::2012-09-20 09:42:56,475::vm::217::vm.Vm::(run) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::migration semaphore acqu= ired Thread-3798::DEBUG::2012-09-20 09:42:56,888::libvirtvm::427::vm.Vm::(_startUnderlyingMigration) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::starting migration to qe= mu +tls://192.168.10.12/system Thread-3799::DEBUG::2012-09-20 09:42:56,889::libvirtvm::325::vm.Vm::(ru= n) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::migration downtime threa= d started Thread-3800::DEBUG::2012-09-20 09:42:56,890::libvirtvm::353::vm.Vm::(ru= n) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::starting migration monit= or thread Thread-3798::DEBUG::2012-09-20 09:42:56,903::libvirtvm::340::vm.Vm::(cancel) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::canceling migration down= time thread Thread-3798::DEBUG::2012-09-20 09:42:56,904::libvirtvm::390::vm.Vm::(st= op) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::stopping migration monit= or thread Thread-3799::DEBUG::2012-09-20 09:42:56,904::libvirtvm::337::vm.Vm::(ru= n) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::migration downtime threa= d exiting Thread-3798::ERROR::2012-09-20 09:42:56,905::vm::176::vm.Vm::(_recover)= vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::operation failed: Failed= to connect to remote libvirt URI qemu+tls://192.168.10.12/system Thread-3798::ERROR::2012-09-20 09:42:56,977::vm::240::vm.Vm::(run) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::Failed to migrate Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 223, in run File "/usr/share/vdsm/libvirtvm.py", line 451, in _startUnderlyingMigration File "/usr/share/vdsm/libvirtvm.py", line 491, in f File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", li= ne 82, in wrapper File "/usr/lib64/python2.7/site-packages/libvirt.py", line 1034, in migrateToURI2 libvirtError: operation failed: Failed to connect to remote libvirt URI= qemu+tls://192.168.10.12/system Thread-3802::DEBUG::2012-09-20 09:42:57,793::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmGetStats with ('2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86',) {} Thread-3802::DEBUG::2012-09-20 09:42:57,793::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::Disk hdc stats not avail= able Thread-3802::DEBUG::2012-09-20 09:42:57,794::BindingXMLRPC::865::vds::(wrapper) return vmGetStats with= {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up= ', 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '22047', 'displayIp': '192.168.10.13', 'displayPort': u'5912', 'session= ': 'Unknown', 'displaySecurePort': u'5913', 'timeOffset': '0', 'hash': '3018874162324753083', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable= ': 'true', 'network': {u'vnet6': {'macAddr': '00:1a:4a:a8:0a:08', 'rxDropp= ed': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate': '0.0= ', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name': u'vnet6'}= }, 'vmId': '2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86', 'displayType': 'qxl', 'cpuUser': '13.27', 'disks': {u'hdc': {'flushLatency': '0', 'readLatenc= y': '0', 'writeLatency': '0'}, u'hda': {'readLatency': '6183805', 'apparentsize': '11811160064', 'writeLatency': '0', 'imageID': 'd96d19f6-5a28-4fef-892f-4a04549d4e38', 'flushLatency': '0', 'readRate'= : '271.87', 'truesize': '11811160064', 'writeRate': '0.00'}}, 'monitorResponse': '0', 'statsAge': '0.77', 'cpuIdle': '86.73', 'elapsedTime': '3941', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [= ], 'guestIPs': '', 'nice': ''}]} Thread-3803::DEBUG::2012-09-20 09:42:57,869::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmGetMigrationStatus with ('2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86',) {} Thread-3803::DEBUG::2012-09-20 09:42:57,870::BindingXMLRPC::865::vds::(wrapper) return vmGetMigrationStatus with {'status': {'message': 'Fatal error during migration', 'code': 12}} Dummy-1264::DEBUG::2012-09-20 09:42:58,172::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1264::DEBUG::2012-09-20 09:42:58,262::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0515= 109 s, 19.9 MB/s\n'; <rc> =3D 0 Dummy-1264::DEBUG::2012-09-20 09:43:00,271::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1264::DEBUG::2012-09-20 09:43:00,362::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0530= 171 s, 19.3 MB/s\n'; <rc> =3D 0 Thread-21::DEBUG::2012-09-20 09:43:00,612::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd iflag=3Ddirect if=3D/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata = bs=3D4096 count=3D1' (cwd None) Thread-21::DEBUG::2012-09-20 09:43:00,629::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.0009376= 98 s, 4.4 MB/s\n'; <rc> =3D 0 Thread-3805::DEBUG::2012-09-20 09:43:01,901::task::588::TaskManager.Task::(_updateState) Task=3D`ff134ecc-5597-4a83-81d6-e4f9804871ff`::moving from state init -= > state preparing Thread-3805::INFO::2012-09-20 09:43:01,902::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=3DNone) Thread-3805::INFO::2012-09-20 09:43:01,902::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': '0.0180931091309', 'lastCheck': 1348134180.825892, 'code': 0,= 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.000955820083618', 'lastCheck': 1348134175.493277, 'code': 0, 'valid'= : True}} Thread-3805::DEBUG::2012-09-20 09:43:01,902::task::1172::TaskManager.Task::(prepare) Task=3D`ff134ecc-5597-4a83-81d6-e4f9804871ff`::finished: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': '0.0180931091309', 'lastCheck': 1348134180.825892, 'code': 0, 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.000955820083618', 'lastCheck': 1348134175.493277, 'code': 0, 'valid': True}} Thread-3805::DEBUG::2012-09-20 09:43:01,902::task::588::TaskManager.Task::(_updateState) Task=3D`ff134ecc-5597-4a83-81d6-e4f9804871ff`::moving from state prepar= ing -> state finished Thread-3805::DEBUG::2012-09-20 09:43:01,903::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {} Thread-3805::DEBUG::2012-09-20 09:43:01,903::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-3805::DEBUG::2012-09-20 09:43:01,903::task::978::TaskManager.Task::(_decref) Task=3D`ff134ecc-5597-4a83-81d6-e4f9804871ff`::ref 0 aborting False Thread-3806::DEBUG::2012-09-20 09:43:01,931::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`540335f0-2269-4bc4-aaf4-11bf5990013f`::Disk hdc stats not avail= able Thread-3806::DEBUG::2012-09-20 09:43:01,931::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`2c3af5f5-f877-4e6b-8a34-05bbe78b3c82`::Disk hdc stats not avail= able Thread-3806::DEBUG::2012-09-20 09:43:01,932::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`0ac0dd3a-ae2a-4963-adf1-918993031f6b`::Disk hdc stats not avail= able Thread-3806::DEBUG::2012-09-20 09:43:01,932::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`35a65bb8-cbca-4049-a428-28914bcb094a`::Disk hdc stats not avail= able Thread-3806::DEBUG::2012-09-20 09:43:01,933::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`4ef3258c-0380-4919-991f-ee7be7e9f7fa`::Disk hdc stats not avail= able Thread-3806::DEBUG::2012-09-20 09:43:01,933::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`252e6d46-f362-46aa-a7ed-dd00a86af6f0`::Disk hdc stats not avail= able Thread-3806::DEBUG::2012-09-20 09:43:01,933::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Disk hdc stats not avail= able Thread-3806::DEBUG::2012-09-20 09:43:01,934::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::Disk hdc stats not avail= able Dummy-1264::DEBUG::2012-09-20 09:43:02,371::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1264::DEBUG::2012-09-20 09:43:02,462::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0525= 183 s, 19.5 MB/s\n'; <rc> =3D 0 - -= --0__=C9BBF0ECDFA610B98f9e8a93df938690918cC9BBF0ECDFA610B9 Content-type: text/html; charset=US-ASCII Content-Disposition: inline Content-transfer-encoding: quoted-printable <html><body> Hello, I have two oVirt nodes ovirt-node-= iso-2.5.0-2.0.fc17. When I try to migrate VM from one = host to another, I have an error: Migration failed due to Error: Fatal = error during migration. vdsm.log: Thread-3797::DEBUG::2012-09-20 09:= 42:56,439::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::c= all vmMigrate with ({'src': '192.168.10.13', 'dst': '192.168.10.12:5432= 1', 'vmId': '2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86', 'method': 'online'}= ,) {} flowID [180ad979] Thread-3797::DEBUG::2012-09-20 09:= 42:56,439::API::441::vds::(migrate) {'src': '192.168.10.13', 'dst': '19= 2.168.10.12:54321', 'vmId': '2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86', 'me= thod': 'online'} Thread-3798::DEBUG::2012-09-20 09:= 42:56,441::vm::122::vm.Vm::(_setupVdsConnection) vmId=3D`2bf3e6eb-49e4-= 42c7-8188-fc2aeeae2e86`::Destination server is: 192.168.10.12:54321</fo= nt> Thread-3797::DEBUG::2012-09-20 09:= 42:56,441::BindingXMLRPC::865::vds::(wrapper) return vmMigrate with {'s= tatus': {'message': 'Migration process starting', 'code': 0}}<br= > Thread-3798::DEBUG::2012-09-20 09:= 42:56,441::vm::124::vm.Vm::(_setupVdsConnection) vmId=3D`2bf3e6eb-49e4-= 42c7-8188-fc2aeeae2e86`::Initiating connection with destination<= br> Thread-3798::DEBUG::2012-09-20 09:= 42:56,452::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`2bf3e6eb-49e4= -42c7-8188-fc2aeeae2e86`::Disk hdc stats not available Thread-3798::DEBUG::2012-09-20 09:= 42:56,457::vm::170::vm.Vm::(_prepareGuest) vmId=3D`2bf3e6eb-49e4-42c7-8= 188-fc2aeeae2e86`::migration Process begins Thread-3798::DEBUG::2012-09-20 09:= 42:56,475::vm::217::vm.Vm::(run) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aee= ae2e86`::migration semaphore acquired Thread-3798::DEBUG::2012-09-20 09:= 42:56,888::libvirtvm::427::vm.Vm::(_startUnderlyingMigration) vmId=3D`2= bf3e6eb-49e4-42c7-8188-fc2aeeae2e86`::starting migration to qemu+tls://= 192.168.10.12/system Thread-3799::DEBUG::2012-09-20 09:= 42:56,889::libvirtvm::325::vm.Vm::(run) vmId=3D`2bf3e6eb-49e4-42c7-8188= -fc2aeeae2e86`::migration downtime thread started Thread-3800::DEBUG::2012-09-20 09:= 42:56,890::libvirtvm::353::vm.Vm::(run) vmId=3D`2bf3e6eb-49e4-42c7-8188= -fc2aeeae2e86`::starting migration monitor thread Thread-3798::DEBUG::2012-09-20 09:= 42:56,903::libvirtvm::340::vm.Vm::(cancel) vmId=3D`2bf3e6eb-49e4-42c7-8= 188-fc2aeeae2e86`::canceling migration downtime thread Thread-3798::DEBUG::2012-09-20 09:= 42:56,904::libvirtvm::390::vm.Vm::(stop) vmId=3D`2bf3e6eb-49e4-42c7-818= 8-fc2aeeae2e86`::stopping migration monitor thread Thread-3799::DEBUG::2012-09-20 09:= 42:56,904::libvirtvm::337::vm.Vm::(run) vmId=3D`2bf3e6eb-49e4-42c7-8188= -fc2aeeae2e86`::migration downtime thread exiting Thread-3798::ERROR::2012-09-20 09:= 42:56,905::vm::176::vm.Vm::(_recover) vmId=3D`2bf3e6eb-49e4-42c7-8188-f= c2aeeae2e86`::operation failed: Failed to connect to remote libvirt URI= qemu+tls://192.168.10.12/system Thread-3798::ERROR::2012-09-20 09:= 42:56,977::vm::240::vm.Vm::(run) vmId=3D`2bf3e6eb-49e4-42c7-8188-fc2aee= ae2e86`::Failed to migrate Traceback (most recent call last):= File "/usr/share/vdsm/vm.py= ", line 223, in run File "/usr/share/vdsm/libvi= rtvm.py", line 451, in _startUnderlyingMigration File "/usr/share/vdsm/libvi= rtvm.py", line 491, in f File "/usr/lib/python2.7/si= te-packages/vdsm/libvirtconnection.py", line 82, in wrapper= File "/usr/lib64/python2.7/= site-packages/libvirt.py", line 1034, in migrateToURI2 libvirtError: operation failed: Fa= iled to connect to remote libvirt URI qemu+tls://192.168.10.12/system</= font> <ul style=3D"padding-left: 0pt">Th= read-3802::DEBUG::2012-09-20 09:42:57,793::BindingXMLRPC::859::vds::(wr= apper) client [192.168.10.10]::call vmGetStats with ('2bf3e6eb-49e4-42c= 7-8188-fc2aeeae2e86',) {}</ul> Thread-3802::DEBUG::2012-09-20 09:= 42:57,793::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`2bf3e6eb-49e4= -42c7-8188-fc2aeeae2e86`::Disk hdc stats not available Thread-3802::DEBUG::2012-09-20 09:= 42:57,794::BindingXMLRPC::865::vds::(wrapper) return vmGetStats with {'= status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Up',= 'username': 'Unknown', 'memUsage': '0', 'acpiEnable': 'true', 'pid': '= 22047', 'displayIp': '192.168.10.13', 'displayPort': u'5912', 'session'= : 'Unknown', 'displaySecurePort': u'5913', 'timeOffset': '0', 'hash': '= 3018874162324753083', 'pauseCode': 'NOERR', 'clientIp': '', 'kvmEnable'= : 'true', 'network': {u'vnet6': {'macAddr': '00:1a:4a:a8:0a:08', 'rxDro= pped': '0', 'rxErrors': '0', 'txDropped': '0', 'txRate': '0.0', 'rxRate= ': '0.0', 'txErrors': '0', 'state': 'unknown', 'speed': '1000', 'name':= u'vnet6'}}, 'vmId': '2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86', 'displayTy= pe': 'qxl', 'cpuUser': '13.27', 'disks': {u'hdc': {'flushLatency': '0',= 'readLatency': '0', 'writeLatency': '0'}, u'hda': {'readLatency': '618= 3805', 'apparentsize': '11811160064', 'writeLatency': '0', 'imageID': '= d96d19f6-5a28-4fef-892f-4a04549d4e38', 'flushLatency': '0', 'readRate':= '271.87', 'truesize': '11811160064', 'writeRate': '0.00'}}, 'monitorRe= sponse': '0', 'statsAge': '0.77', 'cpuIdle': '86.73', 'elapsedTime': '3= 941', 'vmType': 'kvm', 'cpuSys': '0.00', 'appsList': [], 'guestIPs': ''= , 'nice': ''}]} Thread-3803::DEBUG::2012-09-20 09:= 42:57,869::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::c= all vmGetMigrationStatus with ('2bf3e6eb-49e4-42c7-8188-fc2aeeae2e86',)= {} Thread-3803::DEBUG::2012-09-20 09:= 42:57,870::BindingXMLRPC::865::vds::(wrapper) return vmGetMigrationStat= us with {'status': {'message': 'Fatal error during migration', 'code': = 12}} Dummy-1264::DEBUG::2012-09-20 09:4= 2:58,172::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1264::DEBUG::2012-09-20 09:4= 2:58,262::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0515109 s, 19.9 MB/s\n'; <rc> =3D 0 Dummy-1264::DEBUG::2012-09-20 09:4= 3:00,271::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1264::DEBUG::2012-09-20 09:4= 3:00,362::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0530171 s, 19.3 MB/s\n'; <rc> =3D 0 Thread-21::DEBUG::2012-09-20 09:43= :00,612::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd iflag= =3Ddirect if=3D/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata bs=3D= 4096 count=3D1' (cwd None) Thread-21::DEBUG::2012-09-20 09:43= :00,629::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&g= t; =3D '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.= 000937698 s, 4.4 MB/s\n'; <rc> =3D 0 Thread-3805::DEBUG::2012-09-20 09:= 43:01,901::task::588::TaskManager.Task::(_updateState) Task=3D`ff134ecc= -5597-4a83-81d6-e4f9804871ff`::moving from state init -> state prepa= ring Thread-3805::INFO::2012-09-20 09:4= 3:01,902::logUtils::37::dispatcher::(wrapper) Run and protect: repoStat= s(options=3DNone) Thread-3805::INFO::2012-09-20 09:4= 3:01,902::logUtils::39::dispatcher::(wrapper) Run and protect: repoStat= s, Return response: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': = '0.0180931091309', 'lastCheck': 1348134180.825892, 'code': 0, 'valid': = True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.00095582008= 3618', 'lastCheck': 1348134175.493277, 'code': 0, 'valid': True}}</font= > Thread-3805::DEBUG::2012-09-20 09:= 43:01,902::task::1172::TaskManager.Task::(prepare) Task=3D`ff134ecc-559= 7-4a83-81d6-e4f9804871ff`::finished: {'26187d25-bfcb-40c7-97d1-667705ad= 2223': {'delay': '0.0180931091309', 'lastCheck': 1348134180.825892, 'co= de': 0, 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay= ': '0.000955820083618', 'lastCheck': 1348134175.493277, 'code': 0, 'val= id': True}} Thread-3805::DEBUG::2012-09-20 09:= 43:01,902::task::588::TaskManager.Task::(_updateState) Task=3D`ff134ecc= -5597-4a83-81d6-e4f9804871ff`::moving from state preparing -> state = finished Thread-3805::DEBUG::2012-09-20 09:= 43:01,903::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {} Thread-3805::DEBUG::2012-09-20 09:= 43:01,903::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-3805::DEBUG::2012-09-20 09:= 43:01,903::task::978::TaskManager.Task::(_decref) Task=3D`ff134ecc-5597= -4a83-81d6-e4f9804871ff`::ref 0 aborting False Thread-3806::DEBUG::2012-09-20 09:= 43:01,931::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`540335f0-2269= -4bc4-aaf4-11bf5990013f`::Disk hdc stats not available Thread-3806::DEBUG::2012-09-20 09:= 43:01,931::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`2c3af5f5-f877= -4e6b-8a34-05bbe78b3c82`::Disk hdc stats not available Thread-3806::DEBUG::2012-09-20 09:= 43:01,932::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`0ac0dd3a-ae2a= -4963-adf1-918993031f6b`::Disk hdc stats not available Thread-3806::DEBUG::2012-09-20 09:= 43:01,932::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`35a65bb8-cbca= -4049-a428-28914bcb094a`::Disk hdc stats not available Thread-3806::DEBUG::2012-09-20 09:= 43:01,933::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`4ef3258c-0380= -4919-991f-ee7be7e9f7fa`::Disk hdc stats not available Thread-3806::DEBUG::2012-09-20 09:= 43:01,933::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`252e6d46-f362= -46aa-a7ed-dd00a86af6f0`::Disk hdc stats not available Thread-3806::DEBUG::2012-09-20 09:= 43:01,933::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`509e608c-e657= -473a-b031-f0811da96bde`::Disk hdc stats not available Thread-3806::DEBUG::2012-09-20 09:= 43:01,934::libvirtvm::240::vm.Vm::(_getDiskStats) vmId=3D`2bf3e6eb-49e4= -42c7-8188-fc2aeeae2e86`::Disk hdc stats not available Dummy-1264::DEBUG::2012-09-20 09:4= 3:02,371::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1264::DEBUG::2012-09-20 09:4= 3:02,462::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0525183 s, 19.5 MB/s\n'; <rc> =3D 0 - - </body></html>= --0__=C9BBF0ECDFA610B98f9e8a93df938690918cC9BBF0ECDFA610B9--

5 10

[Users] Can't login with the user 'admin'
by Mark Wu 21 Sep '12

21 Sep '12

After upgrading ovirt-engine (new version: ovirt-engine-3.1.0-3.1345126685.git7649eed.fc17), I can't login with the user 'admin'. Here's my upgrade process: yum remove ovirt-engine yum install ovirt-engine engine-setup and type the same password for 'admin' as before. The setup script finished successfully. But I can't login with 'admin' user. I tried to run engine-setup again, but it didn't help. I also tried to change password with engine-config: # engine-config -g AdminPassword Failed to decrypt the current value # engine-config -s AdminPassword=xxxxxxxx 'xxxxxxxx' is not a valid value for type Password. It always complains it's not a valid value whatever I input. Is there anyone hit problem before? And any idea about how to resolve it? Thanks

2 5

Re: [Users] Jenkins.ovirt.org
by Bret Palsson 21 Sep '12

21 Sep '12

Never mind guys, I just added "make srpm" in the Post Steps > Execute Shell box. Works perfectly. I'll send it to koji for packaging. Thanks! -Bret > Hi there! I've setup my own jenkins server for building oVirt-engine, I'm wondering if I can get a copy of the ovirt-engine_create_rpms project properties. I imagine all the *_create_rpms projects are about the same setup with some tweaks in the scripts? > > Thanks! > > -Bret

1 0

[Users] Jenkins.ovirt.org
by Bret Palsson 21 Sep '12

21 Sep '12

Hi there! I've setup my own jenkins server for building oVirt-engine, I'm wondering if I can get a copy of the ovirt-engine_create_rpms project properties. I imagine all the *_create_rpms projects are about the same setup with some tweaks in the scripts? Thanks! -Bret

1 0

Re: [Users] vdsm/engine do not like Infiniband
by Andrew Cathrow 21 Sep '12

21 Sep '12

Yes you are right there is a known issue with the mac address length in IB cards. IIRC there was a hardware vendor who was working on a patch to extend the length and add the appropriate validation. Dead Horse <deadhorseconsulting(a)gmail.com> wrote: When attempting to activate/add a host with Infiniband cards present: vdsm.log Thread-14::DEBUG::2012-09-13 16:16:29,306::BindingXMLRPC::884::vds::(wrapper) return getCapabilities with {'status': {'message': 'Done', 'code': 0}, 'info': {'HBAInventory': {'iSCSI': [{'InitiatorName': 'iqn.2012-09.net.azeroth:kezan'}], 'FC': []}, 'packages2': {'kernel': {'release': '200.29.3.el6uek.x86_64', 'buildtime': 1346177011.0, 'version': '2.6.39'}, 'spice-server': {'release': '10.el6', 'buildtime': 1340343617L, 'version': '0.10.1'}, 'vdsm': {'release': '435.el6', 'buildtime': 1347508928L, 'version': '4.10.0'}, 'qemu-kvm': {'release': '2.295.el6_3.2', 'buildtime': 1346867328L, 'version': '0.12.1.2'}, 'libvirt': {'release': '21.el6_3.4', 'buildtime': 1345740034L, 'version': '0.9.10'}, 'qemu-img': {'release': '2.295.el6_3.2', 'buildtime': 1346867328L, 'version': '0.12.1.2'}}, 'cpuModel': 'Intel(R) Xeon(R) CPU E5540 @ 2.53GHz', 'hooks': {}, 'vmTypes': ['kvm'], 'supportedProtocols': ['2.2', '2.3'], 'networks': {'ovirtmgmt': {'iface': 'ovirtmgmt', 'addr': '3.57.111.31', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.31', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['bond2']}, 'maelstrom': {'iface': 'maelstrom', 'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'maelstrom', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'bridged': True, 'gateway': '0.0.0.0', 'ports': ['bond0']}, 'twistingnether': {'iface': 'twistingnether', 'addr': '3.70.204.31', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.70.204.31', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'twistingnether', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'bridged': True, 'gateway': '3.70.204.254', 'ports': ['bond1']}}, 'bridges': {'ovirtmgmt': {'addr': '3.57.111.31', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.57.111.31', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'ovirtmgmt', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'ports': ['bond2']}, 'maelstrom': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'DELAY': '0', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'maelstrom', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'stp': 'off', 'ports': ['bond0']}, 'twistingnether': {'addr': '3.70.204.31', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '3.70.204.31', 'DELAY': '0', 'PREFIX': '22', 'BOOTPROTO': 'none', 'STP': 'off', 'DEVICE': 'twistingnether', 'TYPE': 'Bridge', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '255.255.252.0', 'stp': 'off', 'ports': ['bond1']}}, 'uuid': 'FF200008-FFFF-FFFF-FFFF-00212883CE4C_00:15:17:00:10:0a', 'lastClientIface': 'twistingnether', 'nics': {'ib0': {'addr': '192.168.1.1', 'cfg': {'IPV6INIT': 'no', 'IPADDR': '192.168.1.1', 'MTU': '65520', 'PREFIX': '16', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib0', 'TYPE': 'Infiniband', 'ONBOOT': 'yes'}, 'mtu': '65520', 'netmask': '255.255.0.0', 'hwaddr': '80:00:04:04:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:b0:f1', 'speed': 0}, 'ib1': {'addr': '', 'cfg': {'IPV6INIT': 'no', 'MTU': '65520', 'BOOTPROTO': 'none', 'CONNECTED_MODE': 'yes', 'DEVICE': 'ib1', 'TYPE': 'Infiniband', 'ONBOOT': 'no'}, 'mtu': '2044', 'netmask': '', 'hwaddr': '80:00:04:05:fe:80:00:00:00:00:00:00:00:12:79:ff:ff:b5:b0:f2', 'speed': 0}, 'eth5': {'permhwaddr': '00:15:17:00:10:0B', 'addr': '', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:10:0B', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth5', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:15:17:00:10:0a', 'speed': 1000}, 'eth4': {'permhwaddr': '00:15:17:00:10:0A', 'addr': '', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:15:17:00:10:0A', 'BOOTPROTO': 'none', 'MASTER': 'bond2', 'DEVICE': 'eth4', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:15:17:00:10:0a', 'speed': 1000}, 'eth3': {'permhwaddr': '00:21:28:83:CE:4B', 'addr': '', 'cfg': {'SLAVE': 'yes', 'HWADDR': '00:21:28:83:CE:4B', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth3', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:21:28:83:ce:4a', 'speed': 1000}, 'eth2': {'permhwaddr': '00:21:28:83:CE:4A', 'addr': '', 'cfg': {'SLAVE': 'yes', 'HWADDR': '00:21:28:83:CE:4A', 'BOOTPROTO': 'none', 'MASTER': 'bond1', 'DEVICE': 'eth2', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:21:28:83:ce:4a', 'speed': 1000}, 'eth1': {'permhwaddr': '00:21:28:83:CE:49', 'addr': '', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:83:CE:49', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth1', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:21:28:83:ce:48', 'speed': 1000}, 'eth0': {'permhwaddr': '00:21:28:83:CE:48', 'addr': '', 'cfg': {'SLAVE': 'yes', 'IPV6INIT': 'no', 'HWADDR': '00:21:28:83:CE:48', 'BOOTPROTO': 'none', 'MASTER': 'bond0', 'DEVICE': 'eth0', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'hwaddr': '00:21:28:83:ce:48', 'speed': 1000}}, 'software_revision': '435', 'management_ip': '3.57.111.31', 'clusterLevels': ['3.0', '3.1', '3.2'], 'cpuFlags': u'fpu,vme,de,pse,tsc,msr,pae,mce,cx8,apic,sep,mtrr,pge,mca,cmov,pat,pse36,clflush,dts,acpi,mmx,fxsr,sse,sse2,ss,ht,tm,pbe,syscall,nx,rdtscp,lm,constant_tsc,arch_perfmon,pebs,bts,rep_good,nopl,xtopology,nonstop_tsc,aperfmperf,pni,dtes64,monitor,ds_cpl,vmx,est,tm2,ssse3,cx16,xtpr,pdcm,dca,sse4_1,sse4_2,popcnt,lahf_lm,ida,dts,tpr_shadow,vnmi,flexpriority,ept,vpid,model_Nehalem,model_Conroe,model_Penryn', 'ISCSIInitiatorName': 'iqn.2012-09.net.azeroth:kezan', 'netConfigDirty': 'False', 'memSize': '36272', 'reservedMem': '321', 'bondings': {'bond4': {'addr': '', 'cfg': {}, 'mtu': '1500', 'netmask': '', 'slaves': [], 'hwaddr': '00:00:00:00:00:00'}, 'bond0': {'addr': '', 'cfg': {'BRIDGE': 'maelstrom', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond0', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'slaves': ['eth0', 'eth1'], 'hwaddr': '00:21:28:83:ce:48'}, 'bond1': {'addr': '', 'cfg': {'BRIDGE': 'twistingnether', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond1', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'slaves': ['eth2', 'eth3'], 'hwaddr': '00:21:28:83:ce:4a'}, 'bond2': {'addr': '', 'cfg': {'BRIDGE': 'ovirtmgmt', 'IPV6INIT': 'no', 'BOOTPROTO': 'none', 'BONDING_OPTS': 'mode=4 miimon=250 xmit_hash_policy=layer2+3', 'DEVICE': 'bond2', 'ONBOOT': 'yes'}, 'mtu': '1500', 'netmask': '', 'slaves': ['eth4', 'eth5'], 'hwaddr': '00:15:17:00:10:0a'}}, 'software_version': '4.10', 'cpuSpeed': '2527.246', 'cpuSockets': '2', 'vlans': {}, 'cpuCores': '8', 'kvmEnabled': 'true', 'guestOverhead': '65', 'supportedRHEVMs': ['3.0', '3.1'], 'version_name': 'Snow Man', 'emulatedMachines': [u'rhel6.3.0', u'pc', u'rhel6.2.0', u'rhel6.1.0', u'rhel6.0.0', u'rhel5.5.0', u'rhel5.4.4', u'rhel5.4.0'], 'operatingSystem': {'release': '1', 'version': '6.3', 'name': 'RHEL'}, 'lastClient': '0.0.0.0'}} engine.log: 2012-09-13 16:16:28,559 INFO [org.ovirt.engine.core.vdsbroker.ActivateVdsVDSCommand] (pool-3-thread-50) [21c70ebd] START, ActivateVdsVDSCommand(vdsId = 1a3d06a8-fde1-11e1-a02d-00151712f280), log id: 4483b716 2012-09-13 16:16:29,339 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (pool-3-thread-50) [21c70ebd] ResourceManager::activateVds - failed to get VDS = 1a3d06a8-fde1-11e1-a02d-00151712f280 capabilities with error: CallableStatementCallback; SQL [{call insertvds_interface(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]; ERROR: value too long for type character varying(20) Where: SQL statement "INSERT INTO vds_interface(addr, bond_name, bond_type, gateway, id, is_bond, bond_opts, mac_addr, name, network_name, speed, subnet, boot_protocol, type, VDS_ID, vlan_id, mtu, bridged) VALUES(v_addr, v_bond_name, v_bond_type, v_gateway, v_id, v_is_bond, v_bond_opts, v_mac_addr, v_name, v_network_name, v_speed, v_subnet, v_boot_protocol, v_type, v_vds_id, v_vlan_id, v_mtu, v_bridged)" PL/pgSQL function "insertvds_interface" line 3 at SQL statement; nested exception is org.postgresql.util.PSQLException: ERROR: value too long for type character varying(20) Where: SQL statement "INSERT INTO vds_interface(addr, bond_name, bond_type, gateway, id, is_bond, bond_opts, mac_addr, name, network_name, speed, subnet, boot_protocol, type, VDS_ID, vlan_id, mtu, bridged) VALUES(v_addr, v_bond_name, v_bond_type, v_gateway, v_id, v_is_bond, v_bond_opts, v_mac_addr, v_name, v_network_name, v_speed, v_subnet, v_boot_protocol, v_type, v_vds_id, v_vlan_id, v_mtu, v_bridged)" PL/pgSQL function "insertvds_interface" line 3 at SQL statement. 2012-09-13 16:16:29,342 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (pool-3-thread-50) [21c70ebd] ResourceManager::activateVds - failed to activate VDS = 1a3d06a8-fde1-11e1-a02d-00151712f280 2012-09-13 16:16:29,344 ERROR [org.ovirt.engine.core.vdsbroker.VDSCommandBase] (pool-3-thread-50) [21c70ebd] Command ActivateVdsVDS execution failed. Exception: UncategorizedSQLException: CallableStatementCallback; uncategorized SQLException for SQL [{call updatevdsdynamic(?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?, ?)}]; SQL state [25P02]; error code [0]; ERROR: current transaction is aborted, commands ignored until end of transaction block; nested exception is org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block 2012-09-13 16:16:29,345 INFO [org.ovirt.engine.core.vdsbroker.ActivateVdsVDSCommand] (pool-3-thread-50) [21c70ebd] FINISH, ActivateVdsVDSCommand, log id: 4483b716 NOTE the length of the Infiniband card "hwaddr" perhaps a clue to the above engine DB insert barf? --> (ERROR: value too long for type character varying(20)) - DHC

4 5

Re: [Users] SPM not selected after host failed
by Jorick Astrego 20 Sep '12

20 Sep '12

On 09/20/2012 04:36 PM, users-request(a)ovirt.org wrote: > Date: Thu, 20 Sep 2012 17:13:25 +0300 From: Itamar Heim > <iheim(a)redhat.com> To: patrick.hurrelmann(a)lobster.de Cc: > users(a)ovirt.org Subject: Re: [Users] SPM not selected after host > failed Message-ID: <505B2485.9080604(a)redhat.com> Content-Type: > text/plain; charset=ISO-8859-15; format=flowed On 09/20/2012 05:09 PM, > Patrick Hurrelmann wrote: >> >On 20.09.2012 16:01, Itamar Heim wrote: >>>> >>>Power management is configured for both nodes. But this might be the >>>> >>>problem: we use the integrated IPMI over LAN power management - and >>>> >>>if I pull the plug on the machine the power management becomes un- >>>> >>>available, too. >>>> >>> >>>> >>>Could this be the problem? >>> >> >>> >>yes... no auto recovery if can't verify node was fenced. >>> >>for your tests, maybe power off the machine for your tests as opposed to >>> >>"no power"? >> > >> >Ugh, this is ugly. I'm evaluating oVirt currently myself and have >> >already suffered from a dead PSU that took down IPMI as well. I really >> >don't want to imagine what happens if the host with SPM goes down due to >> >a power failure :/ Is there really no other way? I guess multiple fence >> >devices are not possible right now. E.g. first try to fence via IPMI and >> >if that fails pull the plug via APC MasterSwitch. Any thoughts? > SPM would be down until you manually confirm shutdown in this case. > SPM doesn't affect running VMs on NFS/posix/local domains, and only > thinly provisioned VMs on block storage (iscsi/FC). > > question, if no power, would the APC still work? > why not just use it to fence instead of IPMI? > > (and helping us close the gap on support for multiple fence devices > would be great) > > > ------------------------------ > > Message: 8 > Date: Thu, 20 Sep 2012 16:24:47 +0200 > From: Patrick Hurrelmann<patrick.hurrelmann(a)lobster.de> > To:users@ovirt.org > Subject: Re: [Users] SPM not selected after host failed > Message-ID:<505B272F.7000301(a)lobster.de> > Content-Type: text/plain; charset=ISO-8859-15 > > On 20.09.2012 16:13, Itamar Heim wrote: >> >On 09/20/2012 05:09 PM, Patrick Hurrelmann wrote: >>> >>On 20.09.2012 16:01, Itamar Heim wrote: >>>>> >>>>Power management is configured for both nodes. But this might be the >>>>> >>>>problem: we use the integrated IPMI over LAN power management - and >>>>> >>>>if I pull the plug on the machine the power management becomes un- >>>>> >>>>available, too. >>>>> >>>> >>>>> >>>>Could this be the problem? >>>> >>> >>>> >>>yes... no auto recovery if can't verify node was fenced. >>>> >>>for your tests, maybe power off the machine for your tests as opposed to >>>> >>>"no power"? >>> >> >>> >>Ugh, this is ugly. I'm evaluating oVirt currently myself and have >>> >>already suffered from a dead PSU that took down IPMI as well. I really >>> >>don't want to imagine what happens if the host with SPM goes down due to >>> >>a power failure :/ Is there really no other way? I guess multiple fence >>> >>devices are not possible right now. E.g. first try to fence via IPMI and >>> >>if that fails pull the plug via APC MasterSwitch. Any thoughts? >> > >> >SPM would be down until you manually confirm shutdown in this case. >> >SPM doesn't affect running VMs on NFS/posix/local domains, and only >> >thinly provisioned VMs on block storage (iscsi/FC). >> > >> >question, if no power, would the APC still work? >> >why not just use it to fence instead of IPMI? >> > >> >(and helping us close the gap on support for multiple fence devices >> >would be great) >> > > Ok, maybe I wasn't precise enough. With power failure I actually meant a > broken PSU on the server and I won't be running any local/NFS storage > but only iSCSI. > But you're right with your point that in such situation fencing via APC > would be sufficient. I was mixing my different environments. My lab only > has IPMI right now, while the live environment most likely will have APC > as well. > > Regards > Patrick We don't have an APC, but we have dual psu's on two independent power feeds with independent backup power. Would we be sufficiently protected? -- Kind Regards, Netbulae Jorick Astrego

2 1

[Users] base url of ovirt
by Jon Thomas 20 Sep '12

20 Sep '12

Hi, Is there some config in the engine to set up the web interface base url so that instead of https://localhost.localdomain/ it is https://localhost.localdomain/ovirt ? thx

3 6

[Users] Autostarting VMs ?
by Rob Coward 20 Sep '12

20 Sep '12

Hi, I'm new to oVirt and currently just have a single server installed with the allinone setup. All seems to be working well atm, apart from a small gripe about spice consoles not working (out of the box) for non-linux admin consoles. I just have one question that I hope someone on this list might be able to help me with..... How do you configure oVirt to auto-start vms when it starts after a system boot ? I assume that there must be a way for this to happen and I'm just missing a really obvious option right under my nose. Thanks in advance, Rob

3 2

[Users] HP Integrated Lights Out 3
by Dmitriy A Pyryakov 20 Sep '12

20 Sep '12

--0__=C9BBF0E6DF83EBB48f9e8a93df938690918cC9BBF0E6DF83EBB4 Content-type: text/plain; charset=US-ASCII Content-transfer-encoding: quoted-printable Hello, I need to use the HP i-lo 3 as fencing device for OOB power management.= In man 8 page of fence_ipmilan I find that I must use lanplus and power_wait=3D4 options. When I insert this options in "Option" line of = "Power Management" tab and press "Test" button - test is failed. There is the part of vdsm.log at this time: Thread-43892::DEBUG::2012-09-07 13:14:03,094::API::1024::vds::(fenceNod= e) fenceNode (addr=3D192.168.10.103,port=3D,agent=3Dipmilan,user=3Dfence_ilo,passwd=3D= XXXX,action=3Dstatus,secure=3D,options=3D) Thread-43892::DEBUG::2012-09-07 13:14:04,116::API::1050::vds::(fenceNod= e) rc 1 in agent=3Dfence_ipmilan ipaddr=3D192.168.10.103 login=3Dfence_ilo option=3Dstatus passwd=3DXXXX out Getting status of IPMI:192.168.10.103...Chassis power =3D Unknown Failed err My otions are not presented. It looks like a bug. How can I fix it? How can I find a location of the script who run this = test in my system? - - Dmitriy Pyryakov VimpelCom Ltd.= --0__=C9BBF0E6DF83EBB48f9e8a93df938690918cC9BBF0E6DF83EBB4 Content-type: text/html; charset=US-ASCII Content-Disposition: inline Content-transfer-encoding: quoted-printable <html><body> Hello, I need to use the HP i-lo 3 as fen= cing device for OOB power management. In man 8 page of fence_ipmilan I f= ind that I must use lanplus and power_wait=3D4 options. When I insert t= his options in "Option" line of "Power Management" = tab and press "Test" button - test is failed. There is the part of vdsm.log at t= his time: Thread-43892::DEBUG::2012-09-07 13= :14:03,094::API::1024::vds::(fenceNode) fenceNode(addr=3D192.168.10.103= ,port=3D,agent=3Dipmilan,user=3Dfence_ilo,passwd=3DXXXX,action=3Dstatus= ,secure=3D,options=3D) Thread-43892::DEBUG::2012-09-07 13= :14:04,116::API::1050::vds::(fenceNode) rc 1 in agent=3Dfence_ipmilan</= font> ipaddr=3D192.168.10.103 = login=3Dfence_ilo option=3Dstatus passwd=3DXXXX out Getting status of IPMI:192.16= 8.10.103...Chassis power =3D Unknown Failed err My otions are not presented. It lo= oks like a bug. How can I fix it? How can I find a= location of the script who run this test in my system? - - Dmitriy Pyryakov <ul style=3D"padding-left: 0pt">Vi= mpelCom Ltd.</ul> </body></html>= --0__=C9BBF0E6DF83EBB48f9e8a93df938690918cC9BBF0E6DF83EBB4--

6 38

[Users] ovirt-cli 3.2.0.3 - important changes
by Michael Pasternak 20 Sep '12

20 Sep '12

Two commands renamed: -------------------- - "create" command renamed with "add" #855773. - "delete" command renamed with "remove" #855769. Changed authentication procedure: -------------------------------- - added username/password prompt/conf-file functionality (see [1] for more details). [1] http://wiki.ovirt.org/wiki/CLI#Connect * For complete list of changes, see change log. -- Michael Pasternak RedHat, ENG-Virtualization R&D

1 0

[Users] where do bond interfaces come from when adding a node that is FC17
by Christopher Maestas 20 Sep '12

20 Sep '12

When you add a fc17 node and look at it, it seems to add: * ovirtmgmt bridge * p2p1 interface * and bond0-bond3. Where does the bonding information get stored? It doesn't seem to be in /etc/sysconfig/network-scripts? The reason I ask, is I have two nodes one of which has the bonding interfaces up and the other which doesn't. The one that doesn't have the bonding interfaces up is failing to be added to the ovirt node list. Thanks, -cdm

4 3

[Users] Host migration problem
by Dmitriy A Pyryakov 20 Sep '12

20 Sep '12

--0__=C9BBF0ECDFB7B2218f9e8a93df938690918cC9BBF0ECDFB7B221 Content-type: text/plain; charset=US-ASCII Content-transfer-encoding: quoted-printable Hello, Yesturday I broke my two Fedora 17 hosts. Today I install two ovirt nodes (first - 2.5.0-2.0.fc17, second - 2.5.1-1.0.fc17). SPM on 2.5.0-2.0.fc17. Now, I can't run any of my existing virtual machines. Exit message: unsupported configuration: spice secure channels set in XML configurati= on, but TLS is disabled in qemu.conf. engine.log: [root@admin ~]# tail -f -n 0 /var/log/ovirt-engine/engine.log 2012-09-20 12:42:53,289 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp--0.0.0.0-8009-10) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D null), log id: 7c90c641 2012-09-20 12:42:53,294 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp--0.0.0.0-8009-10) FINISH, IsValidVDSCommand, return: true, log id:= 7c90c641 2012-09-20 12:42:53,332 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--0.0.0.0-8009-10) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-473a-b031-f0811da96bde), log id: 243c74f7 2012-09-20 12:42:53,334 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--0.0.0.0-8009-10) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 243c74f7 2012-09-20 12:42:53,403 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Lock Acquired to object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:53,415 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Running command: RunVmCommand internal: fa= lse. Entities affected : ID: 509e608c-e657-473a-b031-f0811da96bde Type: VM 2012-09-20 12:42:53,504 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= [a58d974] START, CreateVmVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core.common.businessentities.VM@1911737b), log id= : 77c0e559 2012-09-20 12:42:53,529 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) [a58d974] START, CreateVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core.common.businessentities.VM@1911737b), log id= : f48008f 2012-09-20 12:42:53,602 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) [a58d974] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D1,e= mulatedMachine=3Dpc-0.14,vmType=3Dkvm,keyboardLayout=3Den-us,pitReinjec= tion=3Dfalse,nice=3D0,display=3Dqxl,smpCoresPerSocket=3D1,spiceSecureCh= annels=3Dsmain,sinputs,scursor,splayback,srecord,sdisplay,displayNetwor= k=3Dovirtmgmt,timeOffset=3D-1,transparentHugePages=3Dtrue,vmId=3D509e60= 8c -e657-473a-b031-f0811da96bde,devices=3D [Ljava.util.Map;@760db68c,acpiEnable=3Dtrue,vmName=3DCentOS6Thames,cpuT= ype=3DConroe,custom=3D {device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5=3DVmId=3D50= 9e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-415d-a7bf-9= 5893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecParams=3D {},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3D channel0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5=3DVmId=3D509e608c-e657-473a= -b031-f0811da96bde,DeviceId=3Dbb912edd-9790-43ff-a758-f1d9f20cb5f5,Devi= ce=3Dide,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dide0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D= f5c86859-5ae9-4a37-9d34-2b9547609622,Devic e=3Dvirtio-serial,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},Addre= ss=3D {bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dvirtio-serial0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255= dc-9b3b-48d8-b8e4-63c1635e269b=3DVmId=3D509e608c-e657-473a-b031-f0811da= 96bde,DeviceId=3D21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc= ,Type=3Dchannel,BootOrder=3D0,SpecP arams=3D{},Address=3D{port=3D2, bus=3D0, co= ntroller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel1, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255= dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fd= fe=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da= 6b-44fe-a5aa-508135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,= SpecParams=3D {},Address=3D{bus=3D0x0 0, domain=3D0x0000, = type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dusb0} 2012-09-20 12:42:53,625 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) [a58d974] FINISH, CreateVDSCommand, log id: f48008f 2012-09-20 12:42:53,659 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= [a58d974] IncreasePendingVms::CreateVmIncreasing vds hyper1.ovirt.com pending vcpu count, now 1. Vm: CentOS6Thames 2012-09-20 12:42:53,671 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= [a58d974] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 77c0e559 2012-09-20 12:42:53,684 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Lock freed to object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:54,418 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-12) START, DestroyVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, force=3Dfalse, secondsToWa= it=3D0, gracefully=3Dfalse), log id: 2f059be9 2012-09-20 12:42:54,486 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-12) FINISH, DestroyVDSCommand, log id: 2f059be9= 2012-09-20 12:42:54,520 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-12) Running on vds during rerun failed vm: null= 2012-09-20 12:42:54,523 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-12) vm CentOS6Thames running in db and not runn= ing in vds - add to rerun treatment. vds hyper1.ovirt.com 2012-09-20 12:42:54,536 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-12) Rerun vm 509e608c-e657-473a-b031-f0811da96b= de. Called from vds hyper1.ovirt.com 2012-09-20 12:42:54,557 INFO [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-thread-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011856cf23e, vdsDynamic=3Dorg.ovirt.engine.core.common.businessentities.VdsDynamic@d= b702e05), log id: 71c6e6a3 2012-09-20 12:42:54,564 INFO [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-thread-50) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 71c6= e6a3 2012-09-20 12:42:54,584 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock Acquired to object EngineLock [exclusiveLocks=3D= key: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:54,603 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-thread-50) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D null), log id: f1903fc 2012-09-20 12:42:54,614 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-thread-50) FINISH, IsValidVDSCommand, return: true, log id: f19= 03fc 2012-09-20 12:42:54,653 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-thread-50) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-473a-b031-f0811da96bde), log id: 5b0d9779 2012-09-20 12:42:54,655 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-thread-50) FINISH, IsVmDuringInitiatingVDSCommand, return: fals= e, log id: 5b0d9779 2012-09-20 12:42:54,712 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Running command: RunVmCommand internal: false. Entit= ies affected : ID: 509e608c-e657-473a-b031-f0811da96bde Type: VM 2012-09-20 12:42:54,800 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= START, CreateVmVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23= e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core.common.businessentities.VM@4432a01d), log id= : 554a0742 2012-09-20 12:42:54,825 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) START, CreateVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core.common.businessentities.VM@4432a01d), log id= : 73615350 2012-09-20 12:42:54,912 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D1,e= mulatedMachine=3Dpc-0.14,vmType=3Dkvm,keyboardLayout=3Den-us,pitReinjec= tion=3Dfalse,nice=3D0,display=3Dqxl,smpCoresPerSocket=3D1,spiceSecureCh= annels=3Dsmain,sinputs,scursor,splayback,srecord,sdisplay,displayNetwor= k=3Dovirtmgmt,timeOffset=3D-1,transparentHugePages=3Dtrue,vmId=3D509e60= 8c-e657-473a -b031-f0811da96bde,devices=3D [Ljava.util.Map;@41d42882,acpiEnable=3Dtrue,vmName=3DCentOS6Thames,cpuT= ype=3DConroe,custom=3D {device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5=3DVmId=3D50= 9e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-415d-a7bf-9= 5893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecParams=3D {},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5=3DVmId=3D509e608c-e657-473a= -b031-f0811da96bde,DeviceId=3Dbb912edd-9790-43ff-a758-f1d9f20cb5f5,Devi= ce=3Dide,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dide0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D= f5c86859-5ae9-4a37-9d34-2b9547609622,Device=3Dvirtio-s erial,Type=3Dcontroller,BootOrder=3D0,SpecP= arams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dvirtio-serial0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255= dc-9b3b-48d8-b8e4-63c1635e269b=3DVmId=3D509e608c-e657-473a-b031-f0811da= 96bde,DeviceId=3D21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc= ,Type=3Dchannel,BootOrder=3D0,SpecParams=3D {},A ddress=3D{port=3D2, bus=3D0, controller= =3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel1, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d= 34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255= dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fd= fe=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da= 6b-44fe-a5aa-508135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,= SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D 0x0000, = type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dusb0} 2012-09-20 12:42:54,982 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread-50) FINISH, CreateVDSCommand, log id: 73615350 2012-09-20 12:42:55,004 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= IncreasePendingVms::CreateVmIncreasing vds hyper2.ovirt.com pending vcp= u count, now 1. Vm: CentOS6Thames 2012-09-20 12:42:55,012 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50)= FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 554a0742 2012-09-20 12:42:55,022 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock freed to object EngineLock [exclusiveLocks=3D k= ey: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:56,434 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-32) START, DestroyVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, force=3Dfalse, secondsToWa= it=3D0, gracefully=3Dfalse), log id: 6b44f6c9 2012-09-20 12:42:56,497 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzScheduler_Worker-32) FINISH, DestroyVDSCommand, log id: 6b44f6c9= 2012-09-20 12:42:56,532 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-32) Running on vds during rerun failed vm: null= 2012-09-20 12:42:56,535 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-32) vm CentOS6Thames running in db and not runn= ing in vds - add to rerun treatment. vds hyper2.ovirt.com 2012-09-20 12:42:56,548 ERROR [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-32) Rerun vm 509e608c-e657-473a-b031-f0811da96b= de. Called from vds hyper2.ovirt.com 2012-09-20 12:42:56,582 INFO [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-thread-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23e, vdsDynamic=3Dorg.ovirt.engine.core.common.businessentities.VdsDynamic@5= f1dd7c7), log id: 2a191f9e 2012-09-20 12:42:56,596 INFO [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-thread-50) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 2a19= 1f9e 2012-09-20 12:42:56,616 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock Acquired to object EngineLock [exclusiveLocks=3D= key: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:56,632 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-thread-50) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D null), log id: 4629f11d 2012-09-20 12:42:56,636 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-thread-50) FINISH, IsValidVDSCommand, return: true, log id: 4629f11d 2012-09-20 12:42:56,672 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-thread-50) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-473a-b031-f0811da96bde), log id: f3a60e 2012-09-20 12:42:56,675 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-thread-50) FINISH, IsVmDuringInitiatingVDSCommand, return: fals= e, log id: f3a60e 2012-09-20 12:42:56,713 WARN [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) CanDoAction of action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,V= AR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,ACTION_TYP= E_FAILED_VDS_VM_CLUSTER 2012-09-20 12:42:56,717 INFO [org.ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock freed to object EngineLock [exclusiveLocks=3D k= ey: 509e608c-e657-473a-b031-f0811da96bde value: VM , sharedLocks=3D ] vdsm.log: Dummy-1960::DEBUG::2012-09-20 06:46:58,959::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:46:59,043::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0488= 089 s, 21.0 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:47:01,053::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:01,136::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0477= 826 s, 21.4 MB/s\n'; <rc> =3D 0 Thread-7807::DEBUG::2012-09-20 06:47:01,991::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmCreate with ({'custom': {'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-= 9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f2= 55dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7= fdfe': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-4= 4fe-a5aa-508135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,Spec= Params=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dusb0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f25= 5dc-9b3b-48d8-b8e4-63c1635e269b': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D21f255dc-9b3b-4= 8d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchannel,BootOrder=3D0,Sp= ecParams=3D {},Address=3D{port=3D2, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel1', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4= a37-9d34-2b9547609622,Device=3Dvirtio-serial,Type=3Dcontroller,BootOrde= r=3D0,SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dvirtio-serial0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-4= 15d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecPa= rams=3D {},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912edd-9790-4= 3ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder=3D0,Spec= Params=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dide0'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'fals= e', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'displayNetwork': 'ovirtmgmt', 'vmId': '509e608c-e657-473a-b031-f0811da96bde', 'devices':= [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '20c037f2-11e5-49a5-ace7-741023ec0ce9', 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' functio= n': '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '1ed8a73e-be34-4829-a7e3-151a7a2efedc',= 'address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1= ', ' type': 'drive'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'ifac= e': 'virtio', 'format': 'cow', 'type': 'disk', 'poolID': '332694bb-364a-434e-b23f-5fef985d3cbd', 'volumeID': 'f184ecd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'specParams': {}, 'readonly': 'false', 'domainID': '26187d25-bfcb-40c7-97d1-667705ad2223', 'deviceId'= : '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'address': {'bus': '0x00', ' sl= ot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'devi= ce': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false= '}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:a8:0a:00', 'network': 'ovirtmgm= t', 'specParams': {}, 'deviceId': '7392f689-2ba3-4243-9629-96b192b102a5', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type= ': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': 'd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe', 'address': {'bus': '0x00', ' sl= ot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': 'babd73a4-de64-4dce-91b9-e64c5b46c444'}], 'smp':= '1', 'vmType': 'kvm', 'timeOffset': ' -1', 'memSize': 1024, 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket'= : '1', 'vmName': 'CentOS6Thames', 'display': 'qxl', 'transparentHugePages= ': 'true', 'nice': '0'},) {} Thread-7807::INFO::2012-09-20 06:47:01,992::API::228::vds::(create) vmContainerLock acquired by vm 509e608c-e657-473a-b031-f0811da96bde Thread-7808::DEBUG::2012-09-20 06:47:01,996::vm::564::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Start Thread-7807::DEBUG::2012-09-20 06:47:01,996::API::244::vds::(create) To= tal desktops after creation of 509e608c-e657-473a-b031-f0811da96bde is 1 Thread-7808::DEBUG::2012-09-20 06:47:01,997::vm::568::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::_ongoingCreations acquir= ed Thread-7807::DEBUG::2012-09-20 06:47:01,997::BindingXMLRPC::865::vds::(wrapper) return vmCreate with {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '509e608c-e657-473a-b031-f0811da96bde', 'pid': '0', 'timeOffset= ': '-1', 'displayPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custom': {'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-= 9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f2= 55dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7= fdfe': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-4= 4fe-a5aa-508135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,Spec= Params=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dusb0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f25= 5dc-9b3b-48d8-b8e4-63c1635e269b': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D21f255dc-9b3b-4= 8d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchannel,BootOrder=3D0,Sp= ecParams=3D {},Address=3D{port=3D2, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel1', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4= a37-9d34-2b9547609622,Device=3Dvirtio-serial,Type=3Dcontroller,BootOrde= r=3D0,SpecParams=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dvirtio-serial0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9= d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-4= 15d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecPa= rams=3D {},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dchannel0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912edd-9790-4= 3ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder=3D0,Spec= Params=3D {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,a= lias=3Dide0'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'transparentHugePages':= 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': '20c037f2-11e5-49a5-ace7-741023ec0ce9', 'address': {'bus': '0x00', ' sl= ot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true', 'deviceId': '1ed8a73e-be34-4829-a7e3-151a7a2efedc', 'address': = {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1', ' type': 'drive'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'iface': 'virtio', 'format': 'cow', 'type': 'disk', 'poolID': '332694bb-364a-434e-b23f-5fef985d3cbd', 'volumeID': 'f184ecd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'specParams': {}, 'readonly': 'false', 'domainID': '26187d25-bfcb-40c7-97d1-667705ad2223', 'deviceId'= : '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'address': {'bus': '0x00', ' sl= ot': '0x05', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, 'devi= ce': 'disk', 'shared': 'false', 'propagateErrors': 'off', 'optional': 'false= '}, {'nicModel': 'pv', 'macAddr': '00:1a:4a:a8:0a:00', 'network': 'ovirtmgm= t', 'specParams': {}, 'deviceId': '7392f689-2ba3-4243-9629-96b192b102a5', 'address': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type= ': 'pci', ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': 'd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe', 'address': {'b us': '0x00', ' slot': '0x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': 'babd73a4-de64-4dce-91b9-e64c5b46c444'}], 'smp': '1', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '192.168.10.13', 'spiceSecureChannels': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket'= : '1', 'vmName': 'CentOS6Thames', 'display': 'qxl', 'nice': '0'}} Thread-7808::INFO::2012-09-20 06:47:01,997::libvirtvm::1285::vm.Vm::(_r= un) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::VM wrapper has started Thread-7808::DEBUG::2012-09-20 06:47:02,000::task::588::TaskManager.Task::(_updateState) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::moving from state init -= > state preparing Thread-7808::INFO::2012-09-20 06:47:02,001::logUtils::37::dispatcher::(wrapper) Run and protect: getVolumeSize(sdUUID=3D'26187d25-bfcb-40c7-97d1-667705ad2223', spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', imgUUID=3D'0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', volUUID=3D'f184ecd1-0001-4739-af71-250b412345d6', options=3DNone) Thread-7808::DEBUG::2012-09-20 06:47:02,001::resourceManager::175::ResourceManager.Request::(__init__)= ResName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`83dac2= e0-3d55-4ef6-abf3-7b2561814ab4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at= 'registerResource' Thread-7808::DEBUG::2012-09-20 06:47:02,002::resourceManager::486::ResourceManager::(registerResource)= Trying to register resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23' for lock type 'shared' Thread-7808::DEBUG::2012-09-20 06:47:02,002::resourceManager::528::ResourceManager::(registerResource)= Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free. Now locking as 'shared' (1 active user) Thread-7808::DEBUG::2012-09-20 06:47:02,002::resourceManager::212::ResourceManager.Request::(grant) ResName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`83dac2= e0-3d55-4ef6-abf3-7b2561814ab4`::Granted request Thread-7808::DEBUG::2012-09-20 06:47:02,003::task::817::TaskManager.Task::(resourceAcquired) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::_resourcesAcquired: Storage.26187d25-bfcb-40c7-97d1-667705ad2223 (shared) Thread-7808::DEBUG::2012-09-20 06:47:02,003::task::978::TaskManager.Task::(_decref) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::ref 1 aborting False Thread-7808::INFO::2012-09-20 06:47:02,004::logUtils::39::dispatcher::(wrapper) Run and protect: getVolumeSize, Return response: {'truesize': '13958643712', 'apparentsi= ze': '13958643712'} Thread-7808::DEBUG::2012-09-20 06:47:02,004::task::1172::TaskManager.Task::(prepare) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::finished: {'truesize': '13958643712', 'apparentsize': '13958643712'} Thread-7808::DEBUG::2012-09-20 06:47:02,004::task::588::TaskManager.Task::(_updateState) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::moving from state prepar= ing -> state finished Thread-7808::DEBUG::2012-09-20 06:47:02,004::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {'Storage.26187d25-bfcb-40c7-97d1-667705ad2223': < ResourceRef 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223', isValid: 'True' obj: 'None'>} Thread-7808::DEBUG::2012-09-20 06:47:02,004::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7808::DEBUG::2012-09-20 06:47:02,005::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad222= 3' Thread-7808::DEBUG::2012-09-20 06:47:02,005::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 act= ive users) Thread-7808::DEBUG::2012-09-20 06:47:02,005::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, findin= g out if anyone is waiting for it. Thread-7808::DEBUG::2012-09-20 06:47:02,005::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23', Clearing records. Thread-7808::DEBUG::2012-09-20 06:47:02,005::task::978::TaskManager.Task::(_decref) Task=3D`b6ef82b2-2986-4b7b-95ba-d5f3cac8ad31`::ref 0 aborting False Thread-7808::INFO::2012-09-20 06:47:02,006::clientIF::274::vds::(prepareVolumePath) prepared volume p= ath: Thread-7808::DEBUG::2012-09-20 06:47:02,006::task::588::TaskManager.Task::(_updateState) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::moving from state init -= > state preparing Thread-7808::INFO::2012-09-20 06:47:02,006::logUtils::37::dispatcher::(wrapper) Run and protect: prepareImage(sdUUID=3D'26187d25-bfcb-40c7-97d1-667705ad2223', spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', imgUUID=3D'0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', volUUID=3D'f184ecd1-0001-4739-af71-250b412345d6') Thread-7808::DEBUG::2012-09-20 06:47:02,007::resourceManager::175::ResourceManager.Request::(__init__)= ResName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`c22e62= 09-b86d-448c-8884-372ce9a589c4`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at= 'registerResource' Thread-7808::DEBUG::2012-09-20 06:47:02,007::resourceManager::486::ResourceManager::(registerResource)= Trying to register resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23' for lock type 'shared' Thread-7808::DEBUG::2012-09-20 06:47:02,007::resourceManager::528::ResourceManager::(registerResource)= Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free. Now locking as 'shared' (1 active user) Thread-7808::DEBUG::2012-09-20 06:47:02,007::resourceManager::212::ResourceManager.Request::(grant) ResName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`c22e62= 09-b86d-448c-8884-372ce9a589c4`::Granted request Thread-7808::DEBUG::2012-09-20 06:47:02,008::task::817::TaskManager.Task::(resourceAcquired) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::_resourcesAcquired: Storage.26187d25-bfcb-40c7-97d1-667705ad2223 (shared) Thread-7808::DEBUG::2012-09-20 06:47:02,008::task::978::TaskManager.Task::(_decref) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::ref 1 aborting False Thread-7808::DEBUG::2012-09-20 06:47:02,008::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd iflag=3Ddirect skip=3D4 bs=3D512 if=3D/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata count=3D1' (cwd= None) Thread-7808::DEBUG::2012-09-20 06:47:02,023::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.000766795= s, 668 kB/s\n'; <rc> =3D 0 Thread-7808::DEBUG::2012-09-20= 06:47:02,023::misc::314::Storage.Misc::(validateDDBytes) err: ['1+0 rec= ords in', '1+0 records out', '512 bytes (512 B) copied, 0.000766795 s, 668 kB/s'], size: 512 Thread-7808::INFO::2012-09-20 06:47:02,023::image::357::Storage.Image::(getChain) sdUUID=3D26187d25-bfcb-40c7-97d1-667705ad2223 imgUUID=3D0a7013db-68fd-4c42-bc2e-cc8d7a05ca18 chain=3D [<storage.blockVolume.BlockVolume instance at 0x7ff9fc0feb90>] Thread-7808::INFO::2012-09-20 06:47:02,024::logUtils::39::dispatcher::(wrapper) Run and protect: prepareImage, Return response: {'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6', 'chain': [{'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6', 'domainID': '26187d25-bfcb-40c7-97d1-667705ad2223', 'volumeID': 'f184ecd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18'}]} Thread-7808::DEBUG::2012-09-20 06:47:02,024::task::1172::TaskManager.Task::(prepare) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::finished: {'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6', 'chain': [{'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6', 'domainID': '26187d25-bfcb-40c7-97d1-667705ad2223', 'volumeID': 'f184ecd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18'}]} Thread-7808::DEBUG::2012-09-20 06:47:02,024::task::588::TaskManager.Task::(_updateState) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::moving from state prepar= ing -> state finished Thread-7808::DEBUG::2012-09-20 06:47:02,025::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {'Storage.26187d25-bfcb-40c7-97d1-667705ad2223': < ResourceRef 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223', isValid: 'True' obj: 'None'>} Thread-7808::DEBUG::2012-09-20 06:47:02,025::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7808::DEBUG::2012-09-20 06:47:02,025::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad222= 3' Thread-7808::DEBUG::2012-09-20 06:47:02,025::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 act= ive users) Thread-7808::DEBUG::2012-09-20 06:47:02,026::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, findin= g out if anyone is waiting for it. Thread-7808::DEBUG::2012-09-20 06:47:02,026::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23', Clearing records. Thread-7808::DEBUG::2012-09-20 06:47:02,026::task::978::TaskManager.Task::(_decref) Task=3D`83579cfe-4384-4b76-8bb0-979ed2b60739`::ref 0 aborting False Thread-7808::INFO::2012-09-20 06:47:02,026::clientIF::274::vds::(prepareVolumePath) prepared volume path: /rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-b= fcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/= f184ecd1-0001-4739-af71-250b412345d6 Thread-7808::DEBUG::2012-09-20 06:47:02,037::libvirtvm::1338::vm.Vm::(_= run) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::<?xml version=3D"1.0" encoding=3D"utf-8"?> <domain type=3D"kvm"> <name>CentOS6Thames</name> <uuid>509e608c-e657-473a-b031-f0811da96bde</uuid> <memory>1048576</memory> <currentMemory>1048576</currentMemory> <vcpu>1</vcpu> <devices> <channel type=3D"unix"> <target name=3D"com.redhat.rhevm.vdsm" type=3D"virtio"/> <source mode=3D"bind" path=3D"/var/lib/libvirt/qemu/channels/CentOS6Thames.com.redhat.rhevm.v= dsm"/> </channel> <input bus=3D"ps2" type=3D"mouse"/> <channel type=3D"spicevmc"> <target name=3D"com.redhat.spice.0" type=3D"vir= tio"/> </channel> <graphics autoport=3D"yes" keymap=3D"en-us" passwd=3D"*= ****" passwdValidTo=3D"1970-01-01T00:00:01" port=3D"-1" tlsPort=3D"-1" type=3D= "spice"> <channel mode=3D"secure" name=3D"main"/> <channel mode=3D"secure" name=3D"inputs"/> <channel mode=3D"secure" name=3D"cursor"/> <channel mode=3D"secure" name=3D"playback"/> <channel mode=3D"secure" name=3D"record"/> <channel mode=3D"secure" name=3D"display"/> <listen network=3D"vdsm-ovirtmgmt" type=3D"netw= ork"/> </graphics> <console type=3D"pty"> <target port=3D"0" type=3D"virtio"/> </console> <controller type=3D"usb"> <address domain=3D"0x0000" function=3D"0x2" slot=3D"0x01" type=3D"pci" bus=3D"0x00"/> </controller> <video> <address domain=3D"0x0000" function=3D"0x0" slot=3D"0x02" type=3D"pci" bus=3D"0x00"/> <model heads=3D"1" type=3D"qxl" vram=3D"65536"/= > </video> <interface type=3D"bridge"> <address domain=3D"0x0000" function=3D"0x0" slot=3D"0x03" type=3D"pci" bus=3D"0x00"/> <mac address=3D"00:1a:4a:a8:0a:00"/> <model type=3D"virtio"/> <source bridge=3D"ovirtmgmt"/> </interface> <memballoon model=3D"virtio"/> <disk device=3D"cdrom" snapshot=3D"no" type=3D"file"> <address bus=3D"1" controller=3D"0" target=3D= "0" type=3D"drive" unit=3D"0"/> <source file=3D"" startupPolicy=3D"optional"/> <target bus=3D"ide" dev=3D"hdc"/> <readonly/> <serial></serial> </disk> <disk device=3D"disk" snapshot=3D"no" type=3D"block"> <address domain=3D"0x0000" function=3D"0x0" slot=3D"0x05" type=3D"pci" bus=3D"0x00"/> <source dev=3D"/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-= bfcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18= /f184ecd1-0001-4739-af71-250b412345d6"/> <target bus=3D"virtio" dev=3D"vda"/> <serial>0a7013db-68fd-4c42-bc2e-cc8d7a05ca18</serial> <driver cache=3D"none" error_policy=3D"stop" io=3D"native" name=3D"qemu" type=3D"qcow2"/> </disk> </devices> <os> <type arch=3D"x86_64" machine=3D"pc-0.14">hvm</type> <smbios mode=3D"sysinfo"/> </os> <sysinfo type=3D"smbios"> <system> <entry name=3D"manufacturer">Red Hat</entry> <entry name=3D"product">RHEV Hypervisor</entry>= <entry name=3D"version">17-1</entry> <entry name=3D"serial">31323334-3535-4C44-3643-4D5633393936_00:19:bb:39:97:4a<= /entry> <entry name=3D"uuid">509e608c-e657-473a-b031-f0811da96bde</entry> </system> </sysinfo> <clock adjustment=3D"-1" offset=3D"variable"> <timer name=3D"rtc" tickpolicy=3D"catchup"/> </clock> <features> <acpi/> </features> <cpu match=3D"exact"> <model>Conroe</model> <topology cores=3D"1" sockets=3D"1" threads=3D"1"/> </cpu> </domain> Thread-7808::DEBUG::2012-09-20 06:47:02,426::vm::580::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::_ongoingCreations releas= ed Thread-7808::ERROR::2012-09-20 06:47:02,427::vm::604::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::The vm start process fai= led Traceback (most recent call last): File "/usr/share/vdsm/vm.py", line 570, in _startUnderlyingVm File "/usr/share/vdsm/libvirtvm.py", line 1364, in _run File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", li= ne 82, in wrapper File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2420, in createXML libvirtError: unsupported configuration: spice secure channels set in X= ML configuration, but TLS is disabled in qemu.conf Thread-7808::DEBUG::2012-09-20 06:47:02,430::vm::920::vm.Vm::(setDownStatus) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Changed state to Down: unsupported configuration: spice secure channels set in XML configurati= on, but TLS is disabled in qemu.conf Dummy-1960::DEBUG::2012-09-20 06:47:03,145::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:03,230::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0496= 138 s, 20.6 MB/s\n'; <rc> =3D 0 Thread-7810::DEBUG::2012-09-20 06:47:03,560::BindingXMLRPC::156::vds::(wrapper) [192.168.10.10] Thread-7810::DEBUG::2012-09-20 06:47:03,561::task::588::TaskManager.Task::(_updateState) Task=3D`9bc08c7e-010f-45c2-940a-3fd8361785d5`::moving from state init -= > state preparing Thread-7810::INFO::2012-09-20 06:47:03,561::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmStatus(spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', options=3D= None) Thread-7810::INFO::2012-09-20 06:47:03,562::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmStatus, Return response: {'spm_st': {'spmId': 3, 'spmStatus': 'SP= M', 'spmLver': 0}} Thread-7810::DEBUG::2012-09-20 06:47:03,562::task::1172::TaskManager.Task::(prepare) Task=3D`9bc08c7e-010f-45c2-940a-3fd8361785d5`::finished: {'spm_st': {'s= pmId': 3, 'spmStatus': 'SPM', 'spmLver': 0}} Thread-7810::DEBUG::2012-09-20 06:47:03,562::task::588::TaskManager.Task::(_updateState) Task=3D`9bc08c7e-010f-45c2-940a-3fd8361785d5`::moving from state prepar= ing -> state finished Thread-7810::DEBUG::2012-09-20 06:47:03,562::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {} Thread-7810::DEBUG::2012-09-20 06:47:03,562::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7810::DEBUG::2012-09-20 06:47:03,563::task::978::TaskManager.Task::(_decref) Task=3D`9bc08c7e-010f-45c2-940a-3fd8361785d5`::ref 0 aborting False Thread-7812::DEBUG::2012-09-20 06:47:03,595::BindingXMLRPC::156::vds::(wrapper) [192.168.10.10] Thread-7812::DEBUG::2012-09-20 06:47:03,595::task::588::TaskManager.Task::(_updateState) Task=3D`8e330204-753f-422d-b286-a360410806be`::moving from state init -= > state preparing Thread-7812::INFO::2012-09-20 06:47:03,596::logUtils::37::dispatcher::(wrapper) Run and protect: getStoragePoolInfo(spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', options=3DNone) Thread-7812::DEBUG::2012-09-20 06:47:03,596::resourceManager::175::ResourceManager.Request::(__init__)= ResName=3D`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=3D`a72228= 34-3565-4e28-a15f-72692ef664c6`::Request was made in '/usr/share/vdsm/storage/resourceManager.py' line '485' at= 'registerResource' Thread-7812::DEBUG::2012-09-20 06:47:03,596::resourceManager::486::ResourceManager::(registerResource)= Trying to register resource 'Storage.332694bb-364a-434e-b23f-5fef985d3c= bd' for lock type 'shared' Thread-7812::DEBUG::2012-09-20 06:47:03,597::resourceManager::528::ResourceManager::(registerResource)= Resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free. Now locking as 'shared' (1 active user) Thread-7812::DEBUG::2012-09-20 06:47:03,597::resourceManager::212::ResourceManager.Request::(grant) ResName=3D`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=3D`a72228= 34-3565-4e28-a15f-72692ef664c6`::Granted request Thread-7812::DEBUG::2012-09-20 06:47:03,597::task::817::TaskManager.Task::(resourceAcquired) Task=3D`8e330204-753f-422d-b286-a360410806be`::_resourcesAcquired: Storage.332694bb-364a-434e-b23f-5fef985d3cbd (shared) Thread-7812::DEBUG::2012-09-20 06:47:03,598::task::978::TaskManager.Task::(_decref) Task=3D`8e330204-753f-422d-b286-a360410806be`::ref 1 aborting False Thread-7813::DEBUG::2012-09-20 06:47:03,598::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmGetStats with ('509e608c-e657-473a-b031-f0811da96bde',) {} Thread-7812::INFO::2012-09-20 06:47:03,599::logUtils::39::dispatcher::(wrapper) Run and protect: getStoragePoolInfo, Return response: {'info': {'spm_id': 3, 'master_uui= d': '26187d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Valeka', 'version': '2= ', 'domains': u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3d-837b-47dd-8c82-d= da92eec30d9:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/90104c3d-837b-= 47dd-8c82-dda92eec30d9/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {u'26187d25-bfcb-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfr= ee': '1674097721344', 'alerts': [], 'disktotal': '1799591297024'}, u'90104c3d-837b-47dd-8c82-dda92eec30d9': {'status': u'Active', 'diskfre= e': '423518535680', 'alerts': [], 'disktotal': '492264226816'}}} Thread-7813::DEBUG::2012-09-20 06:47:03,600::BindingXMLRPC::865::vds::(wrapper) return vmGetStats with= {'status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Do= wn', 'hash': '0', 'exitMessage': 'unsupported configuration: spice secure channels set in XML configuration, but TLS is disabled in qemu.conf', 'vmId': '509e608c-e657-473a-b031-f0811da96bde', 'timeOffset': '-1', 'exitCode': 1}]} Thread-7812::DEBUG::2012-09-20 06:47:03,600::task::1172::TaskManager.Task::(prepare) Task=3D`8e330204-753f-422d-b286-a360410806be`::finished: {'info': {'spm= _id': 3, 'master_uuid': '26187d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Vale= ka', 'version': '2', 'domains': u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3d-837b-47dd-8c82-d= da92eec30d9:Active', 'pool_status': 'connected', 'isoprefix': u'/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/90104c3d-837b-= 47dd-8c82-dda92eec30d9/images/11111111-1111-1111-1111-111111111111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {u'26187d25-bfcb-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfr= ee': '1674097721344', 'alerts': [], 'disktotal': '1799591297024'}, u'90104c3d-837b-47dd-8c82-dda92eec30d9': {'status': u'Active', 'diskfre= e': '423518535680', 'alerts': [], 'disktotal': '492264226816'}}} Thread-7812::DEBUG::2012-09-20 06:47:03,601::task::588::TaskManager.Task::(_updateState) Task=3D`8e330204-753f-422d-b286-a360410806be`::moving from state prepar= ing -> state finished Thread-7812::DEBUG::2012-09-20 06:47:03,601::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {'Storage.332694bb-364a-434e-b23f-5fef985d3cbd': < ResourceRef 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd', isValid: 'True' obj: 'None'>} Thread-7812::DEBUG::2012-09-20 06:47:03,601::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7812::DEBUG::2012-09-20 06:47:03,602::resourceManager::538::ResourceManager::(releaseResource) Trying to release resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cb= d' Thread-7812::DEBUG::2012-09-20 06:47:03,602::resourceManager::553::ResourceManager::(releaseResource) Released resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' (0 act= ive users) Thread-7812::DEBUG::2012-09-20 06:47:03,602::resourceManager::558::ResourceManager::(releaseResource) Resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free, findin= g out if anyone is waiting for it. Thread-7812::DEBUG::2012-09-20 06:47:03,602::resourceManager::565::ResourceManager::(releaseResource) = No one is waiting for resource 'Storage.332694bb-364a-434e-b23f-5fef985d3c= bd', Clearing records. Thread-7812::DEBUG::2012-09-20 06:47:03,602::task::978::TaskManager.Task::(_decref) Task=3D`8e330204-753f-422d-b286-a360410806be`::ref 0 aborting False Thread-7814::DEBUG::2012-09-20 06:47:03,658::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::call vmDestroy with ('509e608c-e657-473a-b031-f0811da96bde',) {} Thread-7814::INFO::2012-09-20 06:47:03,658::API::317::vds::(destroy) vmContainerLock acquired by vm 509e608c-e657-473a-b031-f0811da96bde Thread-7814::DEBUG::2012-09-20 06:47:03,658::libvirtvm::2085::vm.Vm::(destroy) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::destroy Called Thread-7814::INFO::2012-09-20 06:47:03,658::libvirtvm::2040::vm.Vm::(releaseVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Release VM resources Thread-7814::WARNING::2012-09-20 06:47:03,659::vm::328::vm.Vm::(_set_lastStatus) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::trying to set state to Powering down when already Down Thread-7814::DEBUG::2012-09-20 06:47:03,659::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sud= o -n /usr/sbin/service ksmtuned retune' (cwd None) Thread-7814::DEBUG::2012-09-20 06:47:03,696::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err>= =3D 'Redirecting to /bin/systemctl retune ksmtuned.service\nUnknown operat= ion retune\n'; <rc> =3D 1 Thread-7814::DEBUG::2012-09-20 06:47:03,697::task::588::TaskManager.Task::(_updateState) Task=3D`e97820bb-547d-4e7a-9249-ece94285bac8`::moving from state init -= > state preparing Thread-7814::INFO::2012-09-20 06:47:03,698::logUtils::37::dispatcher::(wrapper) Run and protect: inappropriateDevices(thiefId=3D'509e608c-e657-473a-b031-f0811da96bde') Thread-7814::INFO::2012-09-20 06:47:03,699::logUtils::39::dispatcher::(wrapper) Run and protect: inappropriateDevices, Return response: None Thread-7814::DEBUG::2012-09-20 06:47:03,699::task::1172::TaskManager.Task::(prepare) Task=3D`e97820bb-547d-4e7a-9249-ece94285bac8`::finished: None Thread-7814::DEBUG::2012-09-20 06:47:03,700::task::588::TaskManager.Task::(_updateState) Task=3D`e97820bb-547d-4e7a-9249-ece94285bac8`::moving from state prepar= ing -> state finished Thread-7814::DEBUG::2012-09-20 06:47:03,700::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {} Thread-7814::DEBUG::2012-09-20 06:47:03,700::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7814::DEBUG::2012-09-20 06:47:03,700::task::978::TaskManager.Task::(_decref) Task=3D`e97820bb-547d-4e7a-9249-ece94285bac8`::ref 0 aborting False Thread-7814::DEBUG::2012-09-20 06:47:03,700::libvirtvm::2080::vm.Vm::(deleteVm) vmId=3D`509e608c-e657-473a-b031-f0811da96bde`::Total desktops after des= troy of 509e608c-e657-473a-b031-f0811da96bde is 0 Thread-7814::DEBUG::2012-09-20 06:47:03,701::BindingXMLRPC::865::vds::(wrapper) return vmDestroy with {'status': {'message': 'Machine destroyed', 'code': 0}} Thread-481::DEBUG::2012-09-20 06:47:04,302::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd iflag=3Ddirect if=3D/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata = bs=3D4096 count=3D1' (cwd None) Thread-481::DEBUG::2012-09-20 06:47:04,317::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.0008435= 51 s, 4.9 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:47:05,239::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:05,323::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0476= 578 s, 21.5 MB/s\n'; <rc> =3D 0 Thread-7815::DEBUG::2012-09-20 06:47:05,819::task::588::TaskManager.Task::(_updateState) Task=3D`ef5f39d0-241c-44b5-a771-da364468b498`::moving from state init -= > state preparing Thread-7815::INFO::2012-09-20 06:47:05,819::logUtils::37::dispatcher::(wrapper) Run and protect: repoStats(options=3DNone) Thread-7815::INFO::2012-09-20 06:47:05,820::logUtils::39::dispatcher::(wrapper) Run and protect: repoStats, Return response: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': '0.0156102180481', 'lastCheck': 1348123624.512314, 'code': 0,= 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.0011830329895', 'lastCheck': 1348123617.41074, 'code': 0, 'valid': True}} Thread-7815::DEBUG::2012-09-20 06:47:05,820::task::1172::TaskManager.Task::(prepare) Task=3D`ef5f39d0-241c-44b5-a771-da364468b498`::finished: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': '0.0156102180481', 'lastCheck': 1348123624.512314, 'code': 0, 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.0011830329895', 'lastCheck': 1348123617.41074, 'code': 0, 'valid': True}} Thread-7815::DEBUG::2012-09-20 06:47:05,820::task::588::TaskManager.Task::(_updateState) Task=3D`ef5f39d0-241c-44b5-a771-da364468b498`::moving from state prepar= ing -> state finished Thread-7815::DEBUG::2012-09-20 06:47:05,820::resourceManager::809::ResourceManager.Owner::(releaseAll)= Owner.releaseAll requests {} resources {} Thread-7815::DEBUG::2012-09-20 06:47:05,821::resourceManager::844::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {} Thread-7815::DEBUG::2012-09-20 06:47:05,821::task::978::TaskManager.Task::(_decref) Task=3D`ef5f39d0-241c-44b5-a771-da364468b498`::ref 0 aborting False Dummy-1960::DEBUG::2012-09-20 06:47:07,332::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:07,458::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0478= 973 s, 21.4 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:47:09,502::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/do= m_md/inbox iflag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:47:09,586::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied, 0.0485= 543 s, 21.1 MB/s\n'; <rc> =3D 0 If I try to create new server I have the same error message. - - Dmitriy Pyryakov VimpelCom Ltd.= --0__=C9BBF0ECDFB7B2218f9e8a93df938690918cC9BBF0ECDFB7B221 Content-type: text/html; charset=US-ASCII Content-Disposition: inline Content-transfer-encoding: quoted-printable <html><body> Hello, Yesturday I broke my two Fedora 17= hosts. Today I install two ovirt nodes (f= irst - 2.5.0-2.0.fc17, second - 2.5.1-1.0.fc17). SPM on 2.5.0-2.0.fc17.= Now, I can't run any of my existin= g virtual machines. Exit message: unsupported configuration: spice secu= re channels set in XML configuration, but TLS is disabled in qemu.conf.= <ul style=3D"padding-left: 0pt"><b= r> engine.log:</ul> [root@admin ~]# tail -f -n 0 /var/= log/ovirt-engine/engine.log 2012-09-20 12:42:53,289 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp--0.0.0.0= -8009-10) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e= -b23f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion= =3D null), log id: 7c90c641 2012-09-20 12:42:53,294 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp--0.0.0.0= -8009-10) FINISH, IsValidVDSCommand, return: true, log id: 7c90c641</fo= nt> 2012-09-20 12:42:53,332 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--0.0.= 0.0-8009-10) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e6= 57-473a-b031-f0811da96bde), log id: 243c74f7 2012-09-20 12:42:53,334 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--0.0.= 0.0-8009-10) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log= id: 243c74f7 2012-09-20 12:42:53,403 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Lock = Acquired to object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473= a-b031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:53,415 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Runni= ng command: RunVmCommand internal: false. Entities affected : ID: 509e= 608c-e657-473a-b031-f0811da96bde Type: VM 2012-09-20 12:42:53,504 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) [a5= 8d974] START, CreateVmVDSCommand(vdsId =3D 0a268762-02d7-11e2-b750-0011= 856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.e= ngine.core.common.businessentities.VM@1911737b), log id: 77c0e559</font= > 2012-09-20 12:42:53,529 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) [a58d974] START, CreateVDSCommand(vdsId =3D 0a268762-02d7-11e2-b75= 0-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.o= virt.engine.core.common.businessentities.VM@1911737b), log id: f48008f<= /font> 2012-09-20 12:42:53,602 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) [a58d974] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSComma= nd spiceSslCipherSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D= 1,emulatedMachine=3Dpc-0.14,vmType=3Dkvm,keyboardLayout=3Den-us,pitRein= jection=3Dfalse,nice=3D0,display=3Dqxl,smpCoresPerSocket=3D1,spiceSecur= eChannels=3Dsmain,sinputs,scursor,splayback,srecord,sdisplay,displayNet= work=3Dovirtmgmt,timeOffset=3D-1,transparentHugePages=3Dtrue,vmId=3D509= e608c -e657-473a-b031-f0811da96bde,devices=3D= [Ljava.util.Map;@760db68c,acpiEnable=3Dtrue,vmName=3DCentOS6Thames,cpuT= ype=3DConroe,custom=3D{device_bb912edd-9790-43ff-a758-f1d9f20cb5f5devic= e_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95= 893b9c55b5=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a= 11f26-6a39-415d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrde= r=3D0,SpecParams=3D{},Address=3D{port=3D1, bus=3D0, controller=3D0, typ= e=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfals= e,alias=3D channel0, device_bb912edd-9790-43= ff-a758-f1d9f20cb5f5=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,Devi= ceId=3Dbb912edd-9790-43ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontrol= ler,BootOrder=3D0,SpecParams=3D{},Address=3D{bus=3D0x00, domain=3D0x000= 0, type=3Dpci, slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged= =3Dtrue,IsReadOnly=3Dfalse,alias=3Dide0, device_bb912edd-9790-43ff-a758= -f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622=3DVmId=3D509e6= 08c-e657-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4a37-9d34-2b95= 47609622,Devic e=3Dvirtio-serial,Type=3Dcont= roller,BootOrder=3D0,SpecParams=3D{},Address=3D{bus=3D0x00, domain=3D0x= 0000, type=3Dpci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlug= ged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dvirtio-serial0, device_bb912edd-9= 790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622de= vice_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4= -63c1635e269b=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D= 21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchannel,B= ootOrder=3D0,SpecP arams=3D{},Address=3D{por= t=3D2, bus=3D0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse= ,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dchannel1, device_bb912edd-= 9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622d= evice_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e= 4-63c1635e269bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe=3DVmId=3D509e= 608c-e657-473a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-44fe-a5aa-508= 135c7fdfe,Device=3Dusb,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},= Address=3D{bus=3D0x0 0, domain=3D0x0000, typ= e=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtru= e,IsReadOnly=3Dfalse,alias=3Dusb0} 2012-09-20 12:42:53,625 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) [a58d974] FINISH, CreateVDSCommand, log id: f48008f 2012-09-20 12:42:53,659 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) [a5= 8d974] IncreasePendingVms::CreateVmIncreasing vds hyper1.ovirt.com pend= ing vcpu count, now 1. Vm: CentOS6Thames 2012-09-20 12:42:53,671 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) [a5= 8d974] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 77c0e= 559 2012-09-20 12:42:53,684 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) [a58d974] Lock = freed to object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b= 031-f0811da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:54,418 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzSchedu= ler_Worker-12) START, DestroyVDSCommand(vdsId =3D 0a268762-02d7-11e2-b7= 50-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, force=3Df= alse, secondsToWait=3D0, gracefully=3Dfalse), log id: 2f059be9<b= r> 2012-09-20 12:42:54,486 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzSchedu= ler_Worker-12) FINISH, DestroyVDSCommand, log id: 2f059be9 2012-09-20 12:42:54,520 INFO [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-12) Running on vds during rerun failed vm: null 2012-09-20 12:42:54,523 INFO [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-12) vm CentOS6Thames running in db and not running in vds - add to = rerun treatment. vds hyper1.ovirt.com 2012-09-20 12:42:54,536 ERROR [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-12) Rerun vm 509e608c-e657-473a-b031-f0811da96bde. Called from vds = hyper1.ovirt.com 2012-09-20 12:42:54,557 INFO [org= .ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-th= read-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =3D 0a268762-02d7-= 11e2-b750-0011856cf23e, vdsDynamic=3Dorg.ovirt.engine.core.common.busin= essentities.VdsDynamic@db702e05), log id: 71c6e6a3 2012-09-20 12:42:54,564 INFO [org= .ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-th= read-50) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 71c6e6a3</font= > 2012-09-20 12:42:54,584 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock Acquired t= o object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f08= 11da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:54,603 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-threa= d-50) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23= f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D= null), log id: f1903fc 2012-09-20 12:42:54,614 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-threa= d-50) FINISH, IsValidVDSCommand, return: true, log id: f1903fc<b= r> 2012-09-20 12:42:54,653 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-th= read-50) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-4= 73a-b031-f0811da96bde), log id: 5b0d9779 2012-09-20 12:42:54,655 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-th= read-50) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id:= 5b0d9779 2012-09-20 12:42:54,712 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Running command= : RunVmCommand internal: false. Entities affected : ID: 509e608c-e657-= 473a-b031-f0811da96bde Type: VM 2012-09-20 12:42:54,800 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) STA= RT, CreateVmVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856cf23e, = vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engine.core= .common.businessentities.VM@4432a01d), log id: 554a0742 2012-09-20 12:42:54,825 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) START, CreateVDSCommand(vdsId =3D 9840e840-02db-11e2-a01a-0011856c= f23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, vm=3Dorg.ovirt.engin= e.core.common.businessentities.VM@4432a01d), log id: 73615350<br= > 2012-09-20 12:42:54,912 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSs= lCipherSuite=3DDEFAULT,memSize=3D1024,kvmEnable=3Dtrue,smp=3D1,emulated= Machine=3Dpc-0.14,vmType=3Dkvm,keyboardLayout=3Den-us,pitReinjection=3D= false,nice=3D0,display=3Dqxl,smpCoresPerSocket=3D1,spiceSecureChannels=3D= smain,sinputs,scursor,splayback,srecord,sdisplay,displayNetwork=3Dovirt= mgmt,timeOffset=3D-1,transparentHugePages=3Dtrue,vmId=3D509e608c-e657-4= 73a -b031-f0811da96bde,devices=3D[Ljava.util= .Map;@41d42882,acpiEnable=3Dtrue,vmName=3DCentOS6Thames,cpuType=3DConro= e,custom=3D{device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-= 5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5=3D= VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a11f26-6a39-41= 5d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrder=3D0,SpecPar= ams=3D{},Address=3D{port=3D1, bus=3D0, controller=3D0, type=3Dvirtio-se= rial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dcha= nnel0, device_bb912edd-9790-43ff-a758-f1d9f= 20cb5f5=3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912e= dd-9790-43ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder= =3D0,SpecParams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci= , slot=3D0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsRea= dOnly=3Dfalse,alias=3Dide0, device_bb912edd-9790-43ff-a758-f1d9f20cb5f5= device_f5c86859-5ae9-4a37-9d34-2b9547609622=3DVmId=3D509e608c-e657-473a= -b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4a37-9d34-2b9547609622,Devi= ce=3Dvirtio-s erial,Type=3Dcontroller,BootOr= der=3D0,SpecParams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3D= pci, slot=3D0x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,Is= ReadOnly=3Dfalse,alias=3Dvirtio-serial0, device_bb912edd-9790-43ff-a758= -f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26= -6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269b= =3DVmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D21f255dc-9b3b= -48d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchannel,BootOrder=3D0,= SpecParams=3D{},A ddress=3D{port=3D2, bus=3D= 0, controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3D= true,IsReadOnly=3Dfalse,alias=3Dchannel1, device_bb912edd-9790-43ff-a75= 8-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f2= 6-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269= bdevice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe=3DVmId=3D509e608c-e657-473= a-b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Dev= ice=3Dusb,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},Address=3D{bu= s=3D0x00, domain=3D 0x0000, type=3Dpci, slot= =3D0x01, function=3D0x2},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3D= false,alias=3Dusb0} 2012-09-20 12:42:54,982 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (pool-3-thread= -50) FINISH, CreateVDSCommand, log id: 73615350 2012-09-20 12:42:55,004 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) Inc= reasePendingVms::CreateVmIncreasing vds hyper2.ovirt.com pending vcpu c= ount, now 1. Vm: CentOS6Thames 2012-09-20 12:42:55,012 INFO [org= .ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (pool-3-thread-50) FIN= ISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 554a0742= 2012-09-20 12:42:55,022 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock freed to o= bject EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f0811d= a96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:56,434 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzSchedu= ler_Worker-32) START, DestroyVDSCommand(vdsId =3D 9840e840-02db-11e2-a0= 1a-0011856cf23e, vmId=3D509e608c-e657-473a-b031-f0811da96bde, force=3Df= alse, secondsToWait=3D0, gracefully=3Dfalse), log id: 6b44f6c9<b= r> 2012-09-20 12:42:56,497 INFO [org= .ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (QuartzSchedu= ler_Worker-32) FINISH, DestroyVDSCommand, log id: 6b44f6c9 2012-09-20 12:42:56,532 INFO [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-32) Running on vds during rerun failed vm: null 2012-09-20 12:42:56,535 INFO [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-32) vm CentOS6Thames running in db and not running in vds - add to = rerun treatment. vds hyper2.ovirt.com 2012-09-20 12:42:56,548 ERROR [org= .ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Wor= ker-32) Rerun vm 509e608c-e657-473a-b031-f0811da96bde. Called from vds = hyper2.ovirt.com 2012-09-20 12:42:56,582 INFO [org= .ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-th= read-50) START, UpdateVdsDynamicDataVDSCommand(vdsId =3D 9840e840-02db-= 11e2-a01a-0011856cf23e, vdsDynamic=3Dorg.ovirt.engine.core.common.busin= essentities.VdsDynamic@5f1dd7c7), log id: 2a191f9e 2012-09-20 12:42:56,596 INFO [org= .ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (pool-3-th= read-50) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 2a191f9e</font= > 2012-09-20 12:42:56,616 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock Acquired t= o object EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f08= 11da96bde value: VM , sharedLocks=3D ] 2012-09-20 12:42:56,632 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-threa= d-50) START, IsValidVDSCommand(storagePoolId =3D 332694bb-364a-434e-b23= f-5fef985d3cbd, ignoreFailoverLimit =3D false, compatabilityVersion =3D= null), log id: 4629f11d 2012-09-20 12:42:56,636 INFO [org= .ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-3-threa= d-50) FINISH, IsValidVDSCommand, return: true, log id: 4629f11d<= br> 2012-09-20 12:42:56,672 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-th= read-50) START, IsVmDuringInitiatingVDSCommand(vmId =3D 509e608c-e657-4= 73a-b031-f0811da96bde), log id: f3a60e 2012-09-20 12:42:56,675 INFO [org= .ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (pool-3-th= read-50) FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id:= f3a60e 2012-09-20 12:42:56,713 WARN [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) CanDoAction of = action RunVm failed. Reasons:VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION= __RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR= __TYPE__VM,ACTION_TYPE_FAILED_VDS_VM_CLUSTER 2012-09-20 12:42:56,717 INFO [org= .ovirt.engine.core.bll.RunVmCommand] (pool-3-thread-50) Lock freed to o= bject EngineLock [exclusiveLocks=3D key: 509e608c-e657-473a-b031-f0811d= a96bde value: VM , sharedLocks=3D ] vdsm.log: Dummy-1960::DEBUG::2012-09-20 06:4= 6:58,959::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 6:59,043::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0488089 s, 21.0 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:4= 7:01,053::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:01,136::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0477826 s, 21.4 MB/s\n'; <rc> =3D 0 Thread-7807::DEBUG::2012-09-20 06:= 47:01,991::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::c= all vmCreate with ({'custom': {'device_bb912edd-9790-43ff-a758-f1d9f20c= b5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415= d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269bdevice_d6= c2c4d1-da6b-44fe-a5aa-508135c7fdfe': 'VmId=3D509e608c-e657-473a-b031-f0= 811da96bde,DeviceId=3Dd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Device=3Dusb= ,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},Address=3D{bus=3D0x00,= domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x2},IsManaged=3D= false,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dusb0', 'device_bb912e= dd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b95476096= 22device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-= b8e4-63c1635e269b': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,Device= Id=3D21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc,Type=3Dchan= nel,BootOrder=3D0,SpecParams=3D{},Address=3D{port=3D2, bus=3D0, control= ler=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsRea= dOnly=3Dfalse,alias=3Dchannel1', 'device_bb912edd-9790-43ff-a758-f1d9f2= 0cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622': 'VmId=3D509e608c-e6= 57-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4a37-9d34-2b95476096= 22,Device=3Dvirtio-serial,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D= {},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x04, fun= ction=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alia= s=3Dvirtio-serial0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5device= _f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-a7bf-958= 93b9c55b5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3D20a= 11f26-6a39-415d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,BootOrde= r=3D0,SpecParams=3D{},Address=3D{port=3D1, bus=3D0, controller=3D0, typ= e=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfals= e,alias=3Dchannel0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5': 'Vm= Id=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912edd-9790-43ff= -a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder=3D0,SpecPar= ams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x0= 1, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfals= e,alias=3Dide0'}, 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'pitR= einjection': 'false', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14= ', 'displayNetwork': 'ovirtmgmt', 'vmId': '509e608c-e657-473a-b031-f081= 1da96bde', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'= }, 'type': 'video', 'deviceId': '20c037f2-11e5-49a5-ace7-741023ec0ce9',= 'address': {'bus': '0x00', ' slot': '0x02', ' domain': '0x0000', ' typ= e': 'pci', ' function': '0x0'}}, {'index': '2', 'iface': 'ide', 'specPa= rams': {'path': ''}, 'readonly': 'true', 'deviceId': '1ed8a73e-be34-482= 9-a7e3-151a7a2efedc', 'address': {' controller': '0', ' target': '0', '= unit': '0', ' bus': '1', ' type': 'drive'}, 'device': 'cdrom', 'path': = '', 'type': 'disk'}, {'iface': 'virtio', 'format': 'cow', 'type': 'disk= ', 'poolID': '332694bb-364a-434e-b23f-5fef985d3cbd', 'volumeID': 'f184e= cd1-0001-4739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-c= c8d7a05ca18', 'specParams': {}, 'readonly': 'false', 'domainID': '26187= d25-bfcb-40c7-97d1-667705ad2223', 'deviceId': '0a7013db-68fd-4c42-bc2e-= cc8d7a05ca18', 'address': {'bus': '0x00', ' slot': '0x05', ' domain': '= 0x0000', ' type': 'pci', ' function': '0x0'}, 'device': 'disk', 'shared= ': 'false', 'propagateErrors': 'off', 'optional': 'false'}, {'nicModel'= : 'pv', 'macAddr': '00:1a:4a:a8:0a:00', 'network': 'ovirtmgmt', 'specPa= rams': {}, 'deviceId': '7392f689-2ba3-4243-9629-96b192b102a5', 'address= ': {'bus': '0x00', ' slot': '0x03', ' domain': '0x0000', ' type': 'pci'= , ' function': '0x0'}, 'device': 'bridge', 'type': 'interface'}, {'devi= ce': 'usb', 'specParams': {}, 'type': 'controller', 'deviceId': 'd6c2c4= d1-da6b-44fe-a5aa-508135c7fdfe', 'address': {'bus': '0x00', ' slot': '0= x01', ' domain': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'devi= ce': 'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon'= , 'deviceId': 'babd73a4-de64-4dce-91b9-e64c5b46c444'}], 'smp': '1', 'vm= Type': 'kvm', 'timeOffset': ' -1', 'memSize': 1024, 'spiceSslCip= herSuite': 'DEFAULT', 'cpuType': 'Conroe', 'spiceSecureChannels': 'smai= n,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '1'= , 'vmName': 'CentOS6Thames', 'display': 'qxl', 'transparentHugePages': = 'true', 'nice': '0'},) {} Thread-7807::INFO::2012-09-20 06:4= 7:01,992::API::228::vds::(create) vmContainerLock acquired by vm 509e60= 8c-e657-473a-b031-f0811da96bde Thread-7808::DEBUG::2012-09-20 06:= 47:01,996::vm::564::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-4= 73a-b031-f0811da96bde`::Start Thread-7807::DEBUG::2012-09-20 06:= 47:01,996::API::244::vds::(create) Total desktops after creation of 509= e608c-e657-473a-b031-f0811da96bde is 1 Thread-7808::DEBUG::2012-09-20 06:= 47:01,997::vm::568::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-4= 73a-b031-f0811da96bde`::_ongoingCreations acquired Thread-7807::DEBUG::2012-09-20 06:= 47:01,997::BindingXMLRPC::865::vds::(wrapper) return vmCreate with {'st= atus': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLau= nch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-0.14', 'vmId': '509e= 608c-e657-473a-b031-f0811da96bde', 'pid': '0', 'timeOffset': '-1', 'dis= playPort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEF= AULT', 'cpuType': 'Conroe', 'custom': {'device_bb912edd-9790-43ff-a758-= f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-= 6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b3b-48d8-b8e4-63c1635e269bd= evice_d6c2c4d1-da6b-44fe-a5aa-508135c7fdfe': 'VmId=3D509e608c-e657-473a= -b031-f0811da96bde,DeviceId=3Dd6c2c4d1-da6b-44fe-a5aa-508135c7fdfe,Devi= ce=3Dusb,Type=3Dcontroller,BootOrder=3D0,SpecParams=3D{},Address=3D{bus= =3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0x01, function=3D0x2},IsMa= naged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfalse,alias=3Dusb0', 'devic= e_bb912edd-9790-43ff-a758-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b= 9547609622device_20a11f26-6a39-415d-a7bf-95893b9c55b5device_21f255dc-9b= 3b-48d8-b8e4-63c1635e269b': 'VmId=3D509e608c-e657-473a-b031-f0811da96bd= e,DeviceId=3D21f255dc-9b3b-48d8-b8e4-63c1635e269b,Device=3Dspicevmc,Typ= e=3Dchannel,BootOrder=3D0,SpecParams=3D{},Address=3D{port=3D2, bus=3D0,= controller=3D0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtr= ue,IsReadOnly=3Dfalse,alias=3Dchannel1', 'device_bb912edd-9790-43ff-a75= 8-f1d9f20cb5f5device_f5c86859-5ae9-4a37-9d34-2b9547609622': 'VmId=3D509= e608c-e657-473a-b031-f0811da96bde,DeviceId=3Df5c86859-5ae9-4a37-9d34-2b= 9547609622,Device=3Dvirtio-serial,Type=3Dcontroller,BootOrder=3D0,SpecP= arams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D0= x04, function=3D0x0},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Dfa= lse,alias=3Dvirtio-serial0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5= f5device_f5c86859-5ae9-4a37-9d34-2b9547609622device_20a11f26-6a39-415d-= a7bf-95893b9c55b5': 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,Device= Id=3D20a11f26-6a39-415d-a7bf-95893b9c55b5,Device=3Dunix,Type=3Dchannel,= BootOrder=3D0,SpecParams=3D{},Address=3D{port=3D1, bus=3D0, controller=3D= 0, type=3Dvirtio-serial},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3D= false,alias=3Dchannel0', 'device_bb912edd-9790-43ff-a758-f1d9f20cb5f5':= 'VmId=3D509e608c-e657-473a-b031-f0811da96bde,DeviceId=3Dbb912edd-9790-= 43ff-a758-f1d9f20cb5f5,Device=3Dide,Type=3Dcontroller,BootOrder=3D0,Spe= cParams=3D{},Address=3D{bus=3D0x00, domain=3D0x0000, type=3Dpci, slot=3D= 0x01, function=3D0x1},IsManaged=3Dfalse,IsPlugged=3Dtrue,IsReadOnly=3Df= alse,alias=3Dide0'}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboar= dLayout': 'en-us', 'kvmEnable': 'true', 'pitReinjection': 'false', 'tra= nsparentHugePages': 'true', 'displayNetwork': 'ovirtmgmt', 'devices': [= {'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'de= viceId': '20c037f2-11e5-49a5-ace7-741023ec0ce9', 'address': {'bus': '0x= 00', ' slot': '0x02', ' domain': '0x0000', ' type': 'pci', ' function':= '0x0'}}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 'r= eadonly': 'true', 'deviceId': '1ed8a73e-be34-4829-a7e3-151a7a2efedc', '= address': {' controller': '0', ' target': '0', 'unit': '0', ' bus': '1'= , ' type': 'drive'}, 'device': 'cdrom', 'path': '', 'type': 'disk'}, {'= iface': 'virtio', 'format': 'cow', 'type': 'disk', 'poolID': '332694bb-= 364a-434e-b23f-5fef985d3cbd', 'volumeID': 'f184ecd1-0001-4739-af71-250b= 412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'specPara= ms': {}, 'readonly': 'false', 'domainID': '26187d25-bfcb-40c7-97d1-6677= 05ad2223', 'deviceId': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18', 'address= ': {'bus': '0x00', ' slot': '0x05', ' domain': '0x0000', ' type': 'pci'= , ' function': '0x0'}, 'device': 'disk', 'shared': 'false', 'propagateE= rrors': 'off', 'optional': 'false'}, {'nicModel': 'pv', 'macAddr': '00:= 1a:4a:a8:0a:00', 'network': 'ovirtmgmt', 'specParams': {}, 'deviceId': = '7392f689-2ba3-4243-9629-96b192b102a5', 'address': {'bus': '0x00', ' sl= ot': '0x03', ' domain': '0x0000', ' type': 'pci', ' function': '0x0'}, = 'device': 'bridge', 'type': 'interface'}, {'device': 'usb', 'specParams= ': {}, 'type': 'controller', 'deviceId': 'd6c2c4d1-da6b-44fe-a5aa-50813= 5c7fdfe', 'address': {'b us': '0x00', ' slot': '0x01', ' do= main': '0x0000', ' type': 'pci', ' function': '0x2'}}, {'device': 'memb= alloon', 'specParams': {'model': 'virtio'}, 'type': 'balloon', 'deviceI= d': 'babd73a4-de64-4dce-91b9-e64c5b46c444'}], 'smp': '1', 'vmType': 'kv= m', 'memSize': 1024, 'displayIp': '192.168.10.13', 'spiceSecureChannels= ': 'smain,sinputs,scursor,splayback,srecord,sdisplay', 'smpCoresPerSock= et': '1', 'vmName': 'CentOS6Thames', 'display': 'qxl', 'nice': '0'}}</f= ont> Thread-7808::INFO::2012-09-20 06:4= 7:01,997::libvirtvm::1285::vm.Vm::(_run) vmId=3D`509e608c-e657-473a-b03= 1-f0811da96bde`::VM wrapper has started Thread-7808::DEBUG::2012-09-20 06:= 47:02,000::task::588::TaskManager.Task::(_updateState) Task=3D`b6ef82b2= -2986-4b7b-95ba-d5f3cac8ad31`::moving from state init -> state prepa= ring Thread-7808::INFO::2012-09-20 06:4= 7:02,001::logUtils::37::dispatcher::(wrapper) Run and protect: getVolum= eSize(sdUUID=3D'26187d25-bfcb-40c7-97d1-667705ad2223', spUUID=3D'332694= bb-364a-434e-b23f-5fef985d3cbd', imgUUID=3D'0a7013db-68fd-4c42-bc2e-cc8= d7a05ca18', volUUID=3D'f184ecd1-0001-4739-af71-250b412345d6', options=3D= None) Thread-7808::DEBUG::2012-09-20 06:= 47:02,001::resourceManager::175::ResourceManager.Request::(__init__) Re= sName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`83dac2e0= -3d55-4ef6-abf3-7b2561814ab4`::Request was made in '/usr/share/vdsm/sto= rage/resourceManager.py' line '485' at 'registerResource' Thread-7808::DEBUG::2012-09-20 06:= 47:02,002::resourceManager::486::ResourceManager::(registerResource) Tr= ying to register resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223= ' for lock type 'shared' Thread-7808::DEBUG::2012-09-20 06:= 47:02,002::resourceManager::528::ResourceManager::(registerResource) Re= source 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free. Now lock= ing as 'shared' (1 active user) Thread-7808::DEBUG::2012-09-20 06:= 47:02,002::resourceManager::212::ResourceManager.Request::(grant) ResNa= me=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`83dac2e0-3d= 55-4ef6-abf3-7b2561814ab4`::Granted request Thread-7808::DEBUG::2012-09-20 06:= 47:02,003::task::817::TaskManager.Task::(resourceAcquired) Task=3D`b6ef= 82b2-2986-4b7b-95ba-d5f3cac8ad31`::_resourcesAcquired: Storage.26187d25= -bfcb-40c7-97d1-667705ad2223 (shared) Thread-7808::DEBUG::2012-09-20 06:= 47:02,003::task::978::TaskManager.Task::(_decref) Task=3D`b6ef82b2-2986= -4b7b-95ba-d5f3cac8ad31`::ref 1 aborting False Thread-7808::INFO::2012-09-20 06:4= 7:02,004::logUtils::39::dispatcher::(wrapper) Run and protect: getVolum= eSize, Return response: {'truesize': '13958643712', 'apparentsize': '13= 958643712'} Thread-7808::DEBUG::2012-09-20 06:= 47:02,004::task::1172::TaskManager.Task::(prepare) Task=3D`b6ef82b2-298= 6-4b7b-95ba-d5f3cac8ad31`::finished: {'truesize': '13958643712', 'appar= entsize': '13958643712'} Thread-7808::DEBUG::2012-09-20 06:= 47:02,004::task::588::TaskManager.Task::(_updateState) Task=3D`b6ef82b2= -2986-4b7b-95ba-d5f3cac8ad31`::moving from state preparing -> state = finished Thread-7808::DEBUG::2012-09-20 06:= 47:02,004::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {'Storage.26187d25-bfcb-40c7-97d1-= 667705ad2223': < ResourceRef 'Storage.26187d25-bfcb-40c7-97d1-667705= ad2223', isValid: 'True' obj: 'None'>} Thread-7808::DEBUG::2012-09-20 06:= 47:02,004::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::resourceManager::538::ResourceManager::(releaseResource) Try= ing to release resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223'<= /font> Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::resourceManager::553::ResourceManager::(releaseResource) Rel= eased resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 active= users) Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::resourceManager::558::ResourceManager::(releaseResource) Res= ource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, finding o= ut if anyone is waiting for it. Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::resourceManager::565::ResourceManager::(releaseResource) No = one is waiting for resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23', Clearing records. Thread-7808::DEBUG::2012-09-20 06:= 47:02,005::task::978::TaskManager.Task::(_decref) Task=3D`b6ef82b2-2986= -4b7b-95ba-d5f3cac8ad31`::ref 0 aborting False Thread-7808::INFO::2012-09-20 06:4= 7:02,006::clientIF::274::vds::(prepareVolumePath) prepared volume path:= Thread-7808::DEBUG::2012-09-20 06:= 47:02,006::task::588::TaskManager.Task::(_updateState) Task=3D`83579cfe= -4384-4b76-8bb0-979ed2b60739`::moving from state init -> state prepa= ring Thread-7808::INFO::2012-09-20 06:4= 7:02,006::logUtils::37::dispatcher::(wrapper) Run and protect: prepareI= mage(sdUUID=3D'26187d25-bfcb-40c7-97d1-667705ad2223', spUUID=3D'332694b= b-364a-434e-b23f-5fef985d3cbd', imgUUID=3D'0a7013db-68fd-4c42-bc2e-cc8d= 7a05ca18', volUUID=3D'f184ecd1-0001-4739-af71-250b412345d6') = Thread-7808::DEBUG::2012-09-20 06:= 47:02,007::resourceManager::175::ResourceManager.Request::(__init__) Re= sName=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`c22e6209= -b86d-448c-8884-372ce9a589c4`::Request was made in '/usr/share/vdsm/sto= rage/resourceManager.py' line '485' at 'registerResource' Thread-7808::DEBUG::2012-09-20 06:= 47:02,007::resourceManager::486::ResourceManager::(registerResource) Tr= ying to register resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223= ' for lock type 'shared' Thread-7808::DEBUG::2012-09-20 06:= 47:02,007::resourceManager::528::ResourceManager::(registerResource) Re= source 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free. Now lock= ing as 'shared' (1 active user) Thread-7808::DEBUG::2012-09-20 06:= 47:02,007::resourceManager::212::ResourceManager.Request::(grant) ResNa= me=3D`Storage.26187d25-bfcb-40c7-97d1-667705ad2223`ReqID=3D`c22e6209-b8= 6d-448c-8884-372ce9a589c4`::Granted request Thread-7808::DEBUG::2012-09-20 06:= 47:02,008::task::817::TaskManager.Task::(resourceAcquired) Task=3D`8357= 9cfe-4384-4b76-8bb0-979ed2b60739`::_resourcesAcquired: Storage.26187d25= -bfcb-40c7-97d1-667705ad2223 (shared) Thread-7808::DEBUG::2012-09-20 06:= 47:02,008::task::978::TaskManager.Task::(_decref) Task=3D`83579cfe-4384= -4b76-8bb0-979ed2b60739`::ref 1 aborting False Thread-7808::DEBUG::2012-09-20 06:= 47:02,008::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd ifl= ag=3Ddirect skip=3D4 bs=3D512 if=3D/dev/26187d25-bfcb-40c7-97d1-667705a= d2223/metadata count=3D1' (cwd None) Thread-7808::DEBUG::2012-09-20 06:= 47:02,023::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err= > =3D '1+0 records in\n1+0 records out\n512 bytes (512 B) copied, 0.= 000766795 s, 668 kB/s\n'; <rc> =3D 0 Thread-7808::DEBUG::2012-09-20 06:= 47:02,023::misc::314::Storage.Misc::(validateDDBytes) err: ['1+0 record= s in', '1+0 records out', '512 bytes (512 B) copied, 0.000766795 s, 668= kB/s'], size: 512 Thread-7808::INFO::2012-09-20 06:4= 7:02,023::image::357::Storage.Image::(getChain) sdUUID=3D26187d25-bfcb-= 40c7-97d1-667705ad2223 imgUUID=3D0a7013db-68fd-4c42-bc2e-cc8d7a05ca18 c= hain=3D<storage.blockVolume.BlockVolume instance at 0x7ff9fc0feb90></fo= nt> Thread-7808::INFO::2012-09-20 06:4= 7:02,024::logUtils::39::dispatcher::(wrapper) Run and protect: prepareI= mage, Return response: {'path': '/rhev/data-center/332694bb-364a-434e-b= 23f-5fef985d3cbd/26187d25-bfcb-40c7-97d1-667705ad2223/images/0a7013db-6= 8fd-4c42-bc2e-cc8d7a05ca18/f184ecd1-0001-4739-af71-250b412345d6', 'chai= n': [{'path': '/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/2= 6187d25-bfcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d= 7a05ca18/f184ecd1-0001-4739-af71-250b412345d6', 'domainID': '26187d25-b= fcb-40c7-97d1-667705ad2223', 'volumeID': 'f184ecd1-0001-4739-af71-250b4= 12345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca18'}]}<b= r> Thread-7808::DEBUG::2012-09-20 06:= 47:02,024::task::1172::TaskManager.Task::(prepare) Task=3D`83579cfe-438= 4-4b76-8bb0-979ed2b60739`::finished: {'path': '/rhev/data-center/332694= bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-40c7-97d1-667705ad2223/ima= ges/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184ecd1-0001-4739-af71-250b41= 2345d6', 'chain': [{'path': '/rhev/data-center/332694bb-364a-434e-b23f-= 5fef985d3cbd/26187d25-bfcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-= 4c42-bc2e-cc8d7a05ca18/f184ecd1-0001-4739-af71-250b412345d6', 'domainID= ': '26187d25-bfcb-40c7-97d1-667705ad2223', 'volumeID': 'f184ecd1-0001-4= 739-af71-250b412345d6', 'imageID': '0a7013db-68fd-4c42-bc2e-cc8d7a05ca1= 8'}]} Thread-7808::DEBUG::2012-09-20 06:= 47:02,024::task::588::TaskManager.Task::(_updateState) Task=3D`83579cfe= -4384-4b76-8bb0-979ed2b60739`::moving from state preparing -> state = finished Thread-7808::DEBUG::2012-09-20 06:= 47:02,025::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {'Storage.26187d25-bfcb-40c7-97d1-= 667705ad2223': < ResourceRef 'Storage.26187d25-bfcb-40c7-97d1-667705= ad2223', isValid: 'True' obj: 'None'>} Thread-7808::DEBUG::2012-09-20 06:= 47:02,025::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7808::DEBUG::2012-09-20 06:= 47:02,025::resourceManager::538::ResourceManager::(releaseResource) Try= ing to release resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223'<= /font> Thread-7808::DEBUG::2012-09-20 06:= 47:02,025::resourceManager::553::ResourceManager::(releaseResource) Rel= eased resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' (0 active= users) Thread-7808::DEBUG::2012-09-20 06:= 47:02,026::resourceManager::558::ResourceManager::(releaseResource) Res= ource 'Storage.26187d25-bfcb-40c7-97d1-667705ad2223' is free, finding o= ut if anyone is waiting for it. Thread-7808::DEBUG::2012-09-20 06:= 47:02,026::resourceManager::565::ResourceManager::(releaseResource) No = one is waiting for resource 'Storage.26187d25-bfcb-40c7-97d1-667705ad22= 23', Clearing records. Thread-7808::DEBUG::2012-09-20 06:= 47:02,026::task::978::TaskManager.Task::(_decref) Task=3D`83579cfe-4384= -4b76-8bb0-979ed2b60739`::ref 0 aborting False Thread-7808::INFO::2012-09-20 06:4= 7:02,026::clientIF::274::vds::(prepareVolumePath) prepared volume path:= /rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/26187d25-bfcb-4= 0c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a05ca18/f184e= cd1-0001-4739-af71-250b412345d6 Thread-7808::DEBUG::2012-09-20 06:= 47:02,037::libvirtvm::1338::vm.Vm::(_run) vmId=3D`509e608c-e657-473a-b0= 31-f0811da96bde`::<?xml version=3D"1.0" encoding=3D"u= tf-8"?> <domain type=3D"kvm"&= gt; <name>CentOS6Thames&= lt;/name> <uuid>509e608c-e657-= 473a-b031-f0811da96bde</uuid> <memory>1048576</= memory> <currentMemory>10485= 76</currentMemory> <vcpu>1</vcpu>= <devices> = <channel type=3D= "unix"> <target= name=3D"com.redhat.rhevm.vdsm" type=3D"virtio"/&gt= ; <source= mode=3D"bind" path=3D"/var/lib/libvirt/qemu/channels/Ce= ntOS6Thames.com.redhat.rhevm.vdsm"/> </channel></= font> <input bus=3D&q= uot;ps2" type=3D"mouse"/> <channel type=3D= "spicevmc"> <target= name=3D"com.redhat.spice.0" type=3D"virtio"/></= font> </channel></= font> <graphics autop= ort=3D"yes" keymap=3D"en-us" passwd=3D"*****&q= uot; passwdValidTo=3D"1970-01-01T00:00:01" port=3D"-1&qu= ot; tlsPort=3D"-1" type=3D"spice"> <channe= l mode=3D"secure" name=3D"main"/> <channe= l mode=3D"secure" name=3D"inputs"/> <channe= l mode=3D"secure" name=3D"cursor"/> <channe= l mode=3D&quo t;secure" name=3D"playback"/> <channe= l mode=3D"secure" name=3D"record"/> <channe= l mode=3D"secure" name=3D"display"/> <listen= network=3D"vdsm-ovirtmgmt" type=3D"network"/></= font> </graphics><= /font> <console type=3D= "pty"> <target= port=3D"0" type=3D"virtio"/> </console></= font> <controller typ= e=3D"usb"> <addres= s domain=3D"0x0000" function=3D"0x2" slot=3D&quo= t;0x01" type=3D"pci" bus=3D"0x00"/>= </controller&gt= ; <video></fon= t> <addres= s domain=3D"0x0000" function=3D"0x0" slot=3D&quo= t;0x02" type=3D"pci" bus=3D"0x00"/>= <model = heads=3D"1" type=3D"qxl" vram=3D"65536"/&= gt; </video></fo= nt> <interface type= =3D"bridge"> <addres= s domain=3D"0x0000" function=3D"0x0" slot=3D&quo= t;0x03" type=3D"pci" bus=3D"0x00"/>= <mac ad= dress=3D"00:1a:4a:a8:0a:00"/> <model = type=3D"virtio"/> <source= bridge=3D"ovirtmgmt"/> </interface>= <memballoon mod= el=3D"virtio"/> <disk device=3D= "cdrom" snapshot=3D"no" type=3D"file">= <addres= s bus=3D"1" controller=3D"0" target=3D"0&qu= ot; type=3D"drive" unit=3D"0"/> <source= file=3D"" startupPolicy=3D"optional"/><b= r> <target= bus=3D"ide" dev=3D"hdc"/> <readon= ly/> <serial= ></serial> </disk></fon= t> <disk device=3D= "disk" snapshot=3D"no" type=3D"block">= <addres= s domain=3D"0x0000" function=3D"0x0" slot=3D&quo= t;0x05" type=3D"pci" bus=3D"0x00"/>= <source= dev=3D"/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/261= 87d25-bfcb-40c7-97d1-667705ad2223/images/0a7013db-68fd-4c42-bc2e-cc8d7a= 05ca18/f184ecd1-0001-4739-af71-250b412345d6"/> <target= bus=3D"virtio" dev=3D"vda"/> <serial= >0a7013db-68fd-4c42-bc2e-cc8d7a05ca18</serial> <driver= cache=3D"none" error_policy=3D"stop" io=3D"na= tive" name=3D"qemu" type=3D"qcow2"/>= </disk></fon= t> </devices><br= > <os> <type arch=3D&q= uot;x86_64" machine=3D"pc-0.14">hvm</type></fon= t> <smbios mode=3D= "sysinfo"/> </os> <sysinfo type=3D"s= mbios"> <system></fo= nt> <entry = name=3D"manufacturer">Red Hat</entry> <entry = name=3D"product">RHEV Hypervisor</entry> <entry = name=3D"version">17-1</entry> <entry = name=3D"serial">31323334-3535-4C44-3643-4D5633393936_00:19= :bb:39:97:4a</entry> <entry = name=3D"uuid">509e608c-e657-473a-b031-f0811da96bde</ent= ry> </system></f= ont> </sysinfo><br= > <clock adjustment=3D&qu= ot;-1" offset=3D"variable"> <timer name=3D&= quot;rtc" tickpolicy=3D"catchup"/> </clock> <features><br= > <acpi/></fon= t> </features><b= r> <cpu match=3D"exac= t"> <model>Conro= e</model> <topology cores= =3D"1" sockets=3D"1" threads=3D"1"/></= font> </cpu> </domain> Thread-7808::DEBUG::2012-09-20 06:= 47:02,426::vm::580::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-4= 73a-b031-f0811da96bde`::_ongoingCreations released Thread-7808::ERROR::2012-09-20 06:= 47:02,427::vm::604::vm.Vm::(_startUnderlyingVm) vmId=3D`509e608c-e657-4= 73a-b031-f0811da96bde`::The vm start process failed Traceback (most recent call last):= File "/usr/share/vdsm/vm.py= ", line 570, in _startUnderlyingVm File "/usr/share/vdsm/libvi= rtvm.py", line 1364, in _run File "/usr/lib/python2.7/si= te-packages/vdsm/libvirtconnection.py", line 82, in wrapper= File "/usr/lib64/python2.7/= site-packages/libvirt.py", line 2420, in createXML libvirtError: unsupported configur= ation: spice secure channels set in XML configuration, but TLS is disab= led in qemu.conf Thread-7808::DEBUG::2012-09-20 06:= 47:02,430::vm::920::vm.Vm::(setDownStatus) vmId=3D`509e608c-e657-473a-b= 031-f0811da96bde`::Changed state to Down: unsupported configuration: sp= ice secure channels set in XML configuration, but TLS is disabled in qe= mu.conf Dummy-1960::DEBUG::2012-09-20 06:4= 7:03,145::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:03,230::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0496138 s, 20.6 MB/s\n'; <rc> =3D 0 Thread-7810::DEBUG::2012-09-20 06:= 47:03,560::BindingXMLRPC::156::vds::(wrapper) [192.168.10.10]<br= > Thread-7810::DEBUG::2012-09-20 06:= 47:03,561::task::588::TaskManager.Task::(_updateState) Task=3D`9bc08c7e= -010f-45c2-940a-3fd8361785d5`::moving from state init -> state prepa= ring Thread-7810::INFO::2012-09-20 06:4= 7:03,561::logUtils::37::dispatcher::(wrapper) Run and protect: getSpmSt= atus(spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', options=3DNone)</= font> Thread-7810::INFO::2012-09-20 06:4= 7:03,562::logUtils::39::dispatcher::(wrapper) Run and protect: getSpmSt= atus, Return response: {'spm_st': {'spmId': 3, 'spmStatus': 'SPM', 'spm= Lver': 0}} Thread-7810::DEBUG::2012-09-20 06:= 47:03,562::task::1172::TaskManager.Task::(prepare) Task=3D`9bc08c7e-010= f-45c2-940a-3fd8361785d5`::finished: {'spm_st': {'spmId': 3, 'spmStatus= ': 'SPM', 'spmLver': 0}} Thread-7810::DEBUG::2012-09-20 06:= 47:03,562::task::588::TaskManager.Task::(_updateState) Task=3D`9bc08c7e= -010f-45c2-940a-3fd8361785d5`::moving from state preparing -> state = finished Thread-7810::DEBUG::2012-09-20 06:= 47:03,562::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {} Thread-7810::DEBUG::2012-09-20 06:= 47:03,562::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7810::DEBUG::2012-09-20 06:= 47:03,563::task::978::TaskManager.Task::(_decref) Task=3D`9bc08c7e-010f= -45c2-940a-3fd8361785d5`::ref 0 aborting False Thread-7812::DEBUG::2012-09-20 06:= 47:03,595::BindingXMLRPC::156::vds::(wrapper) [192.168.10.10]<br= > Thread-7812::DEBUG::2012-09-20 06:= 47:03,595::task::588::TaskManager.Task::(_updateState) Task=3D`8e330204= -753f-422d-b286-a360410806be`::moving from state init -> state prepa= ring Thread-7812::INFO::2012-09-20 06:4= 7:03,596::logUtils::37::dispatcher::(wrapper) Run and protect: getStora= gePoolInfo(spUUID=3D'332694bb-364a-434e-b23f-5fef985d3cbd', options=3DN= one) Thread-7812::DEBUG::2012-09-20 06:= 47:03,596::resourceManager::175::ResourceManager.Request::(__init__) Re= sName=3D`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=3D`a7222834= -3565-4e28-a15f-72692ef664c6`::Request was made in '/usr/share/vdsm/sto= rage/resourceManager.py' line '485' at 'registerResource' Thread-7812::DEBUG::2012-09-20 06:= 47:03,596::resourceManager::486::ResourceManager::(registerResource) Tr= ying to register resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd= ' for lock type 'shared' Thread-7812::DEBUG::2012-09-20 06:= 47:03,597::resourceManager::528::ResourceManager::(registerResource) Re= source 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free. Now lock= ing as 'shared' (1 active user) Thread-7812::DEBUG::2012-09-20 06:= 47:03,597::resourceManager::212::ResourceManager.Request::(grant) ResNa= me=3D`Storage.332694bb-364a-434e-b23f-5fef985d3cbd`ReqID=3D`a7222834-35= 65-4e28-a15f-72692ef664c6`::Granted request Thread-7812::DEBUG::2012-09-20 06:= 47:03,597::task::817::TaskManager.Task::(resourceAcquired) Task=3D`8e33= 0204-753f-422d-b286-a360410806be`::_resourcesAcquired: Storage.332694bb= -364a-434e-b23f-5fef985d3cbd (shared) Thread-7812::DEBUG::2012-09-20 06:= 47:03,598::task::978::TaskManager.Task::(_decref) Task=3D`8e330204-753f= -422d-b286-a360410806be`::ref 1 aborting False Thread-7813::DEBUG::2012-09-20 06:= 47:03,598::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::c= all vmGetStats with ('509e608c-e657-473a-b031-f0811da96bde',) {}= Thread-7812::INFO::2012-09-20 06:4= 7:03,599::logUtils::39::dispatcher::(wrapper) Run and protect: getStora= gePoolInfo, Return response: {'info': {'spm_id': 3, 'master_uuid': '261= 87d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Valeka', 'version': '2', '= domains': u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3d-837b-4= 7dd-8c82-dda92eec30d9:Active', 'pool_status': 'connected', 'isoprefix':= u'/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/90104c3d-837b= -47dd-8c82-dda92eec30d9/images/11111111-1111-1111-1111-111111111111', '= type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {u'26187d25-bfc= b-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfree': '167409772= 1344', 'alerts': [], 'disktotal': '1799591297024'}, u'90104c3d-837b-47d= d-8c82-dda92eec30d9': {'status': u'Active', 'diskfree': '423518535680',= 'alerts': [], 'disktotal': '492264226816'}}} Thread-7813::DEBUG::2012-09-20 06:= 47:03,600::BindingXMLRPC::865::vds::(wrapper) return vmGetStats with {'= status': {'message': 'Done', 'code': 0}, 'statsList': [{'status': 'Down= ', 'hash': '0', 'exitMessage': 'unsupported configuration: spice secure= channels set in XML configuration, but TLS is disabled in qemu.conf', = 'vmId': '509e608c-e657-473a-b031-f0811da96bde', 'timeOffset': '-1', 'ex= itCode': 1}]} Thread-7812::DEBUG::2012-09-20 06:= 47:03,600::task::1172::TaskManager.Task::(prepare) Task=3D`8e330204-753= f-422d-b286-a360410806be`::finished: {'info': {'spm_id': 3, 'master_uui= d': '26187d25-bfcb-40c7-97d1-667705ad2223', 'name': 'Valeka', 'version'= : '2', 'domains': u'26187d25-bfcb-40c7-97d1-667705ad2223:Active,90104c3= d-837b-47dd-8c82-dda92eec30d9:Active', 'pool_status': 'connected', 'iso= prefix': u'/rhev/data-center/332694bb-364a-434e-b23f-5fef985d3cbd/90104= c3d-837b-47dd-8c82-dda92eec30d9/images/11111111-1111-1111-1111-11111111= 1111', 'type': 'ISCSI', 'master_ver': 1, 'lver': 0}, 'dominfo': {u'2618= 7d25-bfcb-40c7-97d1-667705ad2223': {'status': u'Active', 'diskfree': '1= 674097721344', 'alerts': [], 'disktotal': '1799591297024'}, u'90104c3d-= 837b-47dd-8c82-dda92eec30d9': {'status': u'Active', 'diskfree': '423518= 535680', 'alerts': [], 'disktotal': '492264226816'}}} Thread-7812::DEBUG::2012-09-20 06:= 47:03,601::task::588::TaskManager.Task::(_updateState) Task=3D`8e330204= -753f-422d-b286-a360410806be`::moving from state preparing -> state = finished Thread-7812::DEBUG::2012-09-20 06:= 47:03,601::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {'Storage.332694bb-364a-434e-b23f-= 5fef985d3cbd': < ResourceRef 'Storage.332694bb-364a-434e-b23f-5fef98= 5d3cbd', isValid: 'True' obj: 'None'>} Thread-7812::DEBUG::2012-09-20 06:= 47:03,601::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::resourceManager::538::ResourceManager::(releaseResource) Try= ing to release resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd'<= /font> Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::resourceManager::553::ResourceManager::(releaseResource) Rel= eased resource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' (0 active= users) Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::resourceManager::558::ResourceManager::(releaseResource) Res= ource 'Storage.332694bb-364a-434e-b23f-5fef985d3cbd' is free, finding o= ut if anyone is waiting for it. Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::resourceManager::565::ResourceManager::(releaseResource) No = one is waiting for resource 'Storage.332694bb-364a-434e-b23f-5fef985d3c= bd', Clearing records. Thread-7812::DEBUG::2012-09-20 06:= 47:03,602::task::978::TaskManager.Task::(_decref) Task=3D`8e330204-753f= -422d-b286-a360410806be`::ref 0 aborting False Thread-7814::DEBUG::2012-09-20 06:= 47:03,658::BindingXMLRPC::859::vds::(wrapper) client [192.168.10.10]::c= all vmDestroy with ('509e608c-e657-473a-b031-f0811da96bde',) {}<= br> Thread-7814::INFO::2012-09-20 06:4= 7:03,658::API::317::vds::(destroy) vmContainerLock acquired by vm 509e6= 08c-e657-473a-b031-f0811da96bde Thread-7814::DEBUG::2012-09-20 06:= 47:03,658::libvirtvm::2085::vm.Vm::(destroy) vmId=3D`509e608c-e657-473a= -b031-f0811da96bde`::destroy Called Thread-7814::INFO::2012-09-20 06:4= 7:03,658::libvirtvm::2040::vm.Vm::(releaseVm) vmId=3D`509e608c-e657-473= a-b031-f0811da96bde`::Release VM resources Thread-7814::WARNING::2012-09-20 0= 6:47:03,659::vm::328::vm.Vm::(_set_lastStatus) vmId=3D`509e608c-e657-47= 3a-b031-f0811da96bde`::trying to set state to Powering down when alread= y Down Thread-7814::DEBUG::2012-09-20 06:= 47:03,659::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/sudo -= n /usr/sbin/service ksmtuned retune' (cwd None) Thread-7814::DEBUG::2012-09-20 06:= 47:03,696::__init__::1249::Storage.Misc.excCmd::(_log) FAILED: <err&= gt; =3D 'Redirecting to /bin/systemctl retune ksmtuned.service\nUnknow= n operation retune\n'; <rc> =3D 1 Thread-7814::DEBUG::2012-09-20 06:= 47:03,697::task::588::TaskManager.Task::(_updateState) Task=3D`e97820bb= -547d-4e7a-9249-ece94285bac8`::moving from state init -> state prepa= ring Thread-7814::INFO::2012-09-20 06:4= 7:03,698::logUtils::37::dispatcher::(wrapper) Run and protect: inapprop= riateDevices(thiefId=3D'509e608c-e657-473a-b031-f0811da96bde')<b= r> Thread-7814::INFO::2012-09-20 06:4= 7:03,699::logUtils::39::dispatcher::(wrapper) Run and protect: inapprop= riateDevices, Return response: None Thread-7814::DEBUG::2012-09-20 06:= 47:03,699::task::1172::TaskManager.Task::(prepare) Task=3D`e97820bb-547= d-4e7a-9249-ece94285bac8`::finished: None Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::task::588::TaskManager.Task::(_updateState) Task=3D`e97820bb= -547d-4e7a-9249-ece94285bac8`::moving from state preparing -> state = finished Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {} Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::task::978::TaskManager.Task::(_decref) Task=3D`e97820bb-547d= -4e7a-9249-ece94285bac8`::ref 0 aborting False Thread-7814::DEBUG::2012-09-20 06:= 47:03,700::libvirtvm::2080::vm.Vm::(deleteVm) vmId=3D`509e608c-e657-473= a-b031-f0811da96bde`::Total desktops after destroy of 509e608c-e657-473= a-b031-f0811da96bde is 0 Thread-7814::DEBUG::2012-09-20 06:= 47:03,701::BindingXMLRPC::865::vds::(wrapper) return vmDestroy with {'s= tatus': {'message': 'Machine destroyed', 'code': 0}} Thread-481::DEBUG::2012-09-20 06:4= 7:04,302::__init__::1249::Storage.Misc.excCmd::(_log) '/usr/bin/dd ifla= g=3Ddirect if=3D/dev/26187d25-bfcb-40c7-97d1-667705ad2223/metadata bs=3D= 4096 count=3D1' (cwd None) Thread-481::DEBUG::2012-09-20 06:4= 7:04,317::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0= .000843551 s, 4.9 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:4= 7:05,239::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:05,323::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0476578 s, 21.5 MB/s\n'; <rc> =3D 0 Thread-7815::DEBUG::2012-09-20 06:= 47:05,819::task::588::TaskManager.Task::(_updateState) Task=3D`ef5f39d0= -241c-44b5-a771-da364468b498`::moving from state init -> state prepa= ring Thread-7815::INFO::2012-09-20 06:4= 7:05,819::logUtils::37::dispatcher::(wrapper) Run and protect: repoStat= s(options=3DNone) Thread-7815::INFO::2012-09-20 06:4= 7:05,820::logUtils::39::dispatcher::(wrapper) Run and protect: repoStat= s, Return response: {'26187d25-bfcb-40c7-97d1-667705ad2223': {'delay': = '0.0156102180481', 'lastCheck': 1348123624.512314, 'code': 0, 'valid': = True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay': '0.00118303298= 95', 'lastCheck': 1348123617.41074, 'code': 0, 'valid': True}}<b= r> Thread-7815::DEBUG::2012-09-20 06:= 47:05,820::task::1172::TaskManager.Task::(prepare) Task=3D`ef5f39d0-241= c-44b5-a771-da364468b498`::finished: {'26187d25-bfcb-40c7-97d1-667705ad= 2223': {'delay': '0.0156102180481', 'lastCheck': 1348123624.512314, 'co= de': 0, 'valid': True}, '90104c3d-837b-47dd-8c82-dda92eec30d9': {'delay= ': '0.0011830329895', 'lastCheck': 1348123617.41074, 'code': 0, 'valid'= : True}} Thread-7815::DEBUG::2012-09-20 06:= 47:05,820::task::588::TaskManager.Task::(_updateState) Task=3D`ef5f39d0= -241c-44b5-a771-da364468b498`::moving from state preparing -> state = finished Thread-7815::DEBUG::2012-09-20 06:= 47:05,820::resourceManager::809::ResourceManager.Owner::(releaseAll) Ow= ner.releaseAll requests {} resources {} Thread-7815::DEBUG::2012-09-20 06:= 47:05,821::resourceManager::844::ResourceManager.Owner::(cancelAll) Own= er.cancelAll requests {} Thread-7815::DEBUG::2012-09-20 06:= 47:05,821::task::978::TaskManager.Task::(_decref) Task=3D`ef5f39d0-241c= -44b5-a771-da364468b498`::ref 0 aborting False Dummy-1960::DEBUG::2012-09-20 06:4= 7:07,332::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:07,458::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0478973 s, 21.4 MB/s\n'; <rc> =3D 0 Dummy-1960::DEBUG::2012-09-20 06:4= 7:09,502::__init__::1249::Storage.Misc.excCmd::(_log) 'dd if=3D/rhev/da= ta-center/332694bb-364a-434e-b23f-5fef985d3cbd/mastersd/dom_md/inbox if= lag=3Ddirect,fullblock count=3D1 bs=3D1024000' (cwd None) Dummy-1960::DEBUG::2012-09-20 06:4= 7:09,586::__init__::1249::Storage.Misc.excCmd::(_log) SUCCESS: <err&= gt; =3D '1+0 records in\n1+0 records out\n1024000 bytes (1.0 MB) copied= , 0.0485543 s, 21.1 MB/s\n'; <rc> =3D 0 If I try to create new server I ha= ve the same error message. - - Dmitriy Pyryakov <ul style=3D"padding-left: 0pt">Vi= mpelCom Ltd.</ul> </body></html>= --0__=C9BBF0ECDFB7B2218f9e8a93df938690918cC9BBF0ECDFB7B221--

2 2