search

oVirt / ovirt-engine

The oVirt Engine virtualization manager
Other
509 stars 263 forks source link

[4.5.4] Virtual machine does not start with "Q35 Chipset with UEFI SecureBoot" after abort startup #813

Open J0nnek opened 1 year ago

J0nnek commented 1 year ago

Hallo,

I ran into the following issue. When I create a new maschine that has "Q35 Chipset with UEFI SecureBoot" set, start it and abort the boot early the VM will not start the next time. I get the following engine log entrys.

2023-02-07 13:54:18,794+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Failed in 'CreateBrokerVDS' method, for vds: '$HOST'; host: '$HOST': null
2023-02-07 13:54:18,794+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Command 'CreateBrokerVDSCommand(HostName = cvk-ovirt02.cvk.de, CreateVDSCommandParameters:{hostId='2d728000-80ba-40c8-8f04-b7a64f4db7f3', vmId='9ae99d93-9ae3-42b9-89b2-67878a096097', vm='VM [test4]'})' execution failed: null
2023-02-07 13:54:18,794+01 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] FINISH, CreateBrokerVDSCommand, return: , log id: 310d7154
2023-02-07 13:54:18,794+01 ERROR [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Failed to create VM: java.lang.NullPointerException
        at java.base/java.lang.String.<init>(String.java:236)
..... .....
.... .....

      at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:2010)
        at org.ovirt.engine.core.utils//org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:140)
        at org.ovirt.engine.core.utils//org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:79)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1392)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:424)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.executeValidatedCommand(PrevalidatingMultipleActionsRunner.java:204)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.runCommands(PrevalidatingMultipleActionsRunner.java:176)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.SortedMultipleActionsRunnerBase.runCommands(SortedMultipleActionsRunnerBase.java:20)
        at deployment.engine.ear.bll.jar//org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.lambda$invokeCommands$3(PrevalidatingMultipleActionsRunner.java:182)
        at org.ovirt.engine.core.utils//org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:96)
        at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515)
        at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:829)
        at org.glassfish.javax.enterprise.concurrent//org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:227)

2023-02-07 13:54:18,795+01 ERROR [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Command 'CreateVDSCommand( CreateVDSCommandParameters:{hostId='2d728000-80ba-40c8-8f04-b7a64f4db7f3', vmId='9ae99d93-9ae3-42b9-89b2-67878a096097', vm='VM [test4]'})' execution failed: java.lang.NullPointerException
2023-02-07 13:54:18,795+01 INFO  [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] FINISH, CreateVDSCommand, return: Down, log id: 2db5c38e
2023-02-07 13:54:18,795+01 WARN  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Failed to run VM 'test4': EngineException: java.lang.RuntimeException: java.lang.NullPointerException (Failed with error ENGINE and code 5001)
2023-02-07 13:54:18,795+01 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Lock freed to object 'EngineLock:{exclusiveLocks='[9ae99d93-9ae3-42b9-89b2-67878a096097=VM]', sharedLocks=''}'
2023-02-07 13:54:18,795+01 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Trying to rerun VM 'test4'
2023-02-07 13:54:18,803+01 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] EVENT_ID: USER_INITIATED_RUN_VM_FAILED(151), Failed to run VM test4 on Host $HOST.
2023-02-07 13:54:18,811+01 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Lock Acquired to object 'EngineLock:{exclusiveLocks='[9ae99d93-9ae3-42b9-89b2-67878a096097=VM]', sharedLocks=''}'
2023-02-07 13:54:18,818+01 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] START, IsVmDuringInitiatingVDSCommand( IsVmDuringInitiatingVDSCommandParameters:{vmId='9ae99d93-9ae3-42b9-89b2-67878a096097'}), log id: 31c15e5b
2023-02-07 13:54:18,818+01 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 31c15e5b
2023-02-07 13:54:18,826+01 WARN  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Validation of action 'RunVm' failed for user $USER. 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,SCHEDULING_NO_HOSTS
2023-02-07 13:54:18,826+01 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] Lock freed to object 'EngineLock:{exclusiveLocks='[9ae99d93-9ae3-42b9-89b2-67878a096097=VM]', sharedLocks=''}'
2023-02-07 13:54:18,832+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-2522) [b6957440-e837-4bcd-913e-277849a24486] EVENT_ID: USER_FAILED_RUN_VM(54), Failed to run VM test4  (User: $USER).

Then I tried to change the firmware parameter to "Q35 Chipset with UEFI" wich wasn't working and got the following log entrys.

2023-02-07 14:08:36,920+01 ERROR [org.ovirt.engine.core.bll.HasNvramDataQuery] (default task-21) [d06abce4-2f27-4e4c-8714-4afebd391d2d] Query 'HasNvramDataQuery' failed: null
2023-02-07 14:08:36,920+01 ERROR [org.ovirt.engine.core.bll.HasNvramDataQuery] (default task-21) [d06abce4-2f27-4e4c-8714-4afebd391d2d] Exception: java.lang.NullPointerException
        at java.base/java.lang.String.<init>(String.java:236)
        at org.ovirt.engine.core.dal//org.ovirt.engine.core.dao.VmDaoImpl.lambda$getExternalData$6(VmDaoImpl.java:416)
        at org.springframework@5.3.19//org.springframework.jdbc.core.RowMapperResultSetExtractor.extractData(RowMapperResultSetExtractor.java:94)
        at org.springframework@5.3.19//org.springframework.jdbc.core.RowMapperResultSetExtractor.extractData(RowMapperResultSetExtractor.java:61)
        at org.springframework@5.3.19//org.springframework.jdbc.core.JdbcTemplate$1.doInPreparedStatement(JdbcTemplate.java:723)
        at org.springframework@5.3.19//org.springframework.jdbc.core.JdbcTemplate.execute(JdbcTemplate.java:651)
        at org.springframework@5.3.19//org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:713)
        at org.springframework@5.3.19//org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:744)
        at org.springframework@5.3.19//org.springframework.jdbc.core.JdbcTemplate.query(JdbcTemplate.java:799)
        at org.ovirt.engine.core.dal//org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.executeCallInternal(PostgresDbEngineDialect.java:152)
        at org.ovirt.engine.core.dal//org.ovirt.engine.core.dal.dbbroker.PostgresDbEngineDialect$PostgresSimpleJdbcCall.doExecute(PostgresDbEngineDialect.java:118)

After this I checked the vm_nvram_data table in the database and figured out that not data is stored for the VM

grafik

To get the VM working again I manually set the "bios_type" in the vm_static table from "4" to "3"

Kind regards J0nnek

sandrobonazzola commented 1 year ago

@J0nnek can you please provide details on the versions being used on engine and node side?

J0nnek commented 1 year ago

Hello @sandrobonazzola ,

sorry forgot to mention the version. On the engine site we are running Version 4.5.4-1.el8 and on the node side oVirt Node 4.5.4

kind regards J0nnek