[ovirt-users] Re: VM hangs when expanding direct LUN

And also the engine-log from the manager: 2025-02-11 14:02:08,377+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-43) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:02:35,111+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-42) [2fc148e6] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:02:35,121+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-42) [2fc148e6] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:02:35,123+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-42) [2fc148e6] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:02:35,284+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-336) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:02:35,395+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-42) [2fc148e6] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:02:35,396+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-42) [2fc148e6] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:05:08,388+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-83) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:05:52,621+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks. 2025-02-11 14:05:52,621+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 40 threads waiting for tasks and 0 tasks in queue. 2025-02-11 14:05:52,621+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineScheduledThreadPool' is using 0 threads out of 1, 100 threads waiting for tasks. 2025-02-11 14:05:52,621+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineThreadMonitoringThreadPool' is using 1 threads out of 1, 0 threads waiting for tasks. 2025-02-11 14:05:52,621+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'hostUpdatesChecker' is using 0 threads out of 5, 5 threads waiting for tasks. 2025-02-11 14:07:35,406+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-50) [3a609c61] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:07:35,415+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-50) [3a609c61] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:07:35,417+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-50) [3a609c61] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:07:35,580+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-336) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:07:35,691+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-50) [3a609c61] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:07:35,691+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-50) [3a609c61] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:08:08,399+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-42) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:11:08,410+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-48) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:12:35,702+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-15) [d83f4b7] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:12:35,711+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-15) [d83f4b7] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:12:35,713+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-15) [d83f4b7] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:12:35,877+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-336) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:12:35,991+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-15) [d83f4b7] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:12:35,991+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-15) [d83f4b7] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:14:08,420+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-36) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:15:52,622+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks. 2025-02-11 14:15:52,622+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 40 threads waiting for tasks and 0 tasks in queue. 2025-02-11 14:15:52,622+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineScheduledThreadPool' is using 0 threads out of 1, 100 threads waiting for tasks. 2025-02-11 14:15:52,622+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineThreadMonitoringThreadPool' is using 1 threads out of 1, 0 threads waiting for tasks. 2025-02-11 14:15:52,622+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'hostUpdatesChecker' is using 0 threads out of 5, 5 threads waiting for tasks. 2025-02-11 14:17:08,432+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-99) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:17:36,002+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-83) [2fdfc4a2] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:17:36,011+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-83) [2fdfc4a2] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:17:36,013+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-83) [2fdfc4a2] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:17:36,176+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-336) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:17:36,294+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-83) [2fdfc4a2] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:17:36,295+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-83) [2fdfc4a2] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:17:50,543+01 INFO [org.ovirt.engine.core.sso.servlets.OAuthRevokeServlet] (default task-336) [] User ksk@internalkeycloak-authz with profile [internalsso] successfully logged out 2025-02-11 14:17:50,549+01 INFO [org.ovirt.engine.core.bll.aaa.TerminateSessionsForTokenCommand] (default task-339) [59c9320d] Running command: TerminateSessionsForTokenCommand internal: true. 2025-02-11 14:17:51,009+01 INFO [org.ovirt.engine.core.sso.service.NegotiateAuthService] (default task-336) [] User ksk@internalkeycloak-authz with profile [internalsso] successfully logged in with scopes : ovirt-app-admin ovirt-app-api ovirt-app-portal ovirt-ext=auth:sequence-priority=~ ovirt-ext=revoke:revoke-all ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:17:51,070+01 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-336) [5f16c4c4] Running command: CreateUserSessionCommand internal: false. 2025-02-11 14:17:51,075+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-336) [5f16c4c4] EVENT_ID: USER_VDC_LOGIN(30), User ksk@internalkeycloak-authz connecting from '10.93.64.78' using session '6erz+E0ZCYXY955TN3862/uszRn5Dx6D0iNcj03rs965XMT1mAQwKy0W5+/Wu6aSomwwFcqgh+PB94ipP2zhvw==' logged in. 2025-02-11 14:17:52,432+01 INFO [org.ovirt.engine.core.utils.servlet.ServletUtils] (default task-340) [] Can't read file '/usr/share/ovirt-engine/files/spice/SpiceVersion.txt' for request '/ovirt-engine/services/files/spice/SpiceVersion.txt' -- 404 2025-02-11 14:20:08,442+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-31) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:22:36,305+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-65) [18cfa3d5] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:22:36,314+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-65) [18cfa3d5] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:22:36,316+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-65) [18cfa3d5] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:22:36,478+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-340) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:22:36,590+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-65) [18cfa3d5] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:22:36,591+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-65) [18cfa3d5] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:23:08,453+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-48) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:25:52,623+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks. 2025-02-11 14:25:52,623+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 40 threads waiting for tasks and 0 tasks in queue. 2025-02-11 14:25:52,623+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineScheduledThreadPool' is using 0 threads out of 1, 100 threads waiting for tasks. 2025-02-11 14:25:52,623+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineThreadMonitoringThreadPool' is using 1 threads out of 1, 0 threads waiting for tasks. 2025-02-11 14:25:52,623+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'hostUpdatesChecker' is using 0 threads out of 5, 5 threads waiting for tasks. 2025-02-11 14:26:08,464+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-33) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:27:36,600+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-24) [65d0bb96] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:27:36,610+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-24) [65d0bb96] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:27:36,612+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-24) [65d0bb96] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:27:36,773+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-340) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:27:36,884+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-24) [65d0bb96] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:27:36,884+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-24) [65d0bb96] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:29:08,474+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-87) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:32:08,480+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-1) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:32:36,894+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-43) [9b3991c] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:32:36,904+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-43) [9b3991c] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:32:36,906+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-43) [9b3991c] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:32:37,067+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-340) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:32:37,178+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-43) [9b3991c] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:32:37,178+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-43) [9b3991c] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:34:04,003+01 INFO [org.ovirt.engine.core.sso.service.NegotiateAuthService] (default task-340) [] User cud@internalkeycloak-authz with profile [internalsso] successfully logged in with scopes : ovirt-app-admin ovirt-app-api ovirt-app-portal ovirt-ext=auth:sequence-priority=~ ovirt-ext=revoke:revoke-all ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:34:04,074+01 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-340) [5f975472] Running command: CreateUserSessionCommand internal: false. 2025-02-11 14:34:04,079+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-340) [5f975472] EVENT_ID: USER_VDC_LOGIN(30), User cud@internalkeycloak-authz connecting from '10.93.64.78' using session 'fBq8/T5g7AT/oUxp0PCGypfxsnJkdAGzNkvhScfvYJluKQucLVq9RqbXsmtuTlX6SVzKCuBOgglRvR5+yEOirA==' logged in. 2025-02-11 14:34:04,790+01 INFO [org.ovirt.engine.core.utils.servlet.ServletUtils] (default task-340) [] Can't read file '/usr/share/ovirt-engine/files/spice/SpiceVersion.txt' for request '/ovirt-engine/services/files/spice/SpiceVersion.txt' -- 404 2025-02-11 14:34:20,443+01 INFO [org.ovirt.engine.core.bll.aaa.LoginOnBehalfCommand] (default task-342) [11eb5bb3] Running command: LoginOnBehalfCommand internal: true. 2025-02-11 14:34:20,465+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [11eb5bb3] EVENT_ID: USER_LOGIN_ON_BEHALF(1,401), Executed login on behalf - for user cud. 2025-02-11 14:34:20,475+01 INFO [org.ovirt.engine.core.bll.aaa.LogoutSessionCommand] (default task-342) [2031d27] Running command: LogoutSessionCommand internal: true. 2025-02-11 14:34:20,477+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [2031d27] EVENT_ID: USER_VDC_LOGOUT(31), User SYSTEM connected from 'UNKNOWN' using session '9jXyCrICDINNiWPhTB6W0a4V2G2I0sAFw1UUOsPqUdSlC3iKrT48jBclOhWgg+9Kv5o6ntb2Mc6Ao3Z8Y4lR2g==' logged out. 2025-02-11 14:35:03,393+01 INFO [org.ovirt.engine.core.bll.storage.pool.SyncDirectLunsCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] Lock Acquired to object 'EngineLock:{exclusiveLocks='[e4c13e38-eabf-4b8d-ba7a-f77c64e9eaf7=DISK, e1efd5f3-ce37-4778-93fb-0c33cc91fe8e=DISK, 66477d1a-9ebe-4fb9-ae2c-7f91c54e3d42=DISK, df7f4f52-1a88-4d8b-b3a0-789a299e34a1=DISK, 00f801bc-c465-4f9f-9445-50868d0d200d=DISK, af80f9c1-41c6-44ef-960b-ee40df405e6b=DISK, 309bfd4e-561c-4a36-b014-61449839e35b=DISK, 08418bad-9036-48fe-a251-d0cd37fa17be=DISK, 0928e62b-eed0-4822-b917-878c6d7e16b1=DISK, 6e29559a-c877-4572-a3ba-80d576b6f85e=DISK, 822f30c2-9513-45ec-aa56-372f16ec52f4=DISK]', sharedLocks=''}' 2025-02-11 14:35:03,482+01 INFO [org.ovirt.engine.core.bll.storage.pool.SyncDirectLunsCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] Running command: SyncDirectLunsCommand internal: false. Entities affected : ID: 6e29559a-c877-4572-a3ba-80d576b6f85e Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: e4c13e38-eabf-4b8d-ba7a-f77c64e9eaf7 Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: 822f30c2-9513-45ec-aa56-372f16ec52f4 Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: e1efd5f3-ce37-4778-93fb-0c33cc91fe8e Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: 0928e62b-eed0-4822-b917-878c6d7e16b1 Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: af80f9c1-41c6-44ef-960b-ee40df405e6b Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: 66477d1a-9ebe-4fb9-ae2c-7f91c54e3d42 Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: df7f4f52-1a88- 4d8b-b3a0-789a299e34a1 Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: 08418bad-9036-48fe-a251-d0cd37fa17be Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: 309bfd4e-561c-4a36-b014-61449839e35b Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER, ID: 00f801bc-c465-4f9f-9445-50868d0d200d Type: DiskAction group CONFIGURE_VM_STORAGE with role type USER 2025-02-11 14:35:03,484+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] EVENT_ID: SYNC_DIRECT_LUNS_STARTED(1,054), Direct LUN synchronization started. 2025-02-11 14:35:03,486+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] START, GetDeviceListVDSCommand(HostName = b4chl327.b4r.local, GetDeviceListVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', storageType='UNKNOWN', checkStatus='false', lunIds='[3600507680c800058d000000000000869, 360050764008100e428000000000003b7, 360050764008100e428000000000003b8, 3600507680c800058d00000000000086c, 3600507680c800058d00000000000086d, 3600507680c800058d00000000000086a, 3600507680c800058d00000000000086b, 3600507680c800058d000000000000867, 3600507680c800058d000000000000868, 3600507680c800058d00000000000086e, 3600507680c800058d00000000000086f]'}), log id: 7f0959e9 2025-02-11 14:35:08,491+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-68) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:35:11,425+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] FINISH, GetDeviceListVDSCommand, return: [LUNs:{id='3600507680c800058d000000000000868', physicalVolumeId='uDyCWB-fnsh-UfdC-8oE0-ZhBm-ycc6-bDtNjp', volumeGroupId='ROVODv-lK0c-yG2q-LCnc-qKVz-xahp-ixarYp', serial='SIBM_2145_020320001634XX01', lunMapping='56', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='170', pvSize='129', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdgw=true, sdgv=true, sdig=true, sdif=true]', pathsCapacity='[sdgw=170, sdgv=170, sdig=170, sdif=170]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='3600507680c800058d00000000000086d', physicalVolumeId='fA2f9J-v4zQ-L8Y9-y2VX-hRK6-c9WS-nqWj2V', volumeGroupId='HO4hbe-79yq-JTCy-RTQN-EjRz-f5f5-ZKTRHX', serial='SIBM_214 5_020320001634XX01', lunMapping='61', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='170', pvSize='129', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdhh=true, sdhf=true, sdiq=true, sdip=true]', pathsCapacity='[sdhh=170, sdhf=170, sdiq=170, sdip=170]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='360050764008100e428000000000003b7', physicalVolumeId='GvjEUk-XOQa-DaHb-tlQ5-PpYi-e9JL-ZMaNMy', volumeGroupId='vaWvgX-735K-l8ZC-hBBj-XjqT-AEDy-ltqrSS', serial='SIBM_2145_01002040390aXX00', lunMapping='18', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='680', pvSize='519', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdfj=true, sdfk=true, sdfv=true, sdfw=true]', pathsCapacity='[sdfj=680, sdfk=680, sdfv=680, sdfw=680]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', stora geDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='360050764008100e428000000000003b8', physicalVolumeId='3xzdio-CJZS-Ae6Y-4LtM-8TWr-mzUT-GOB72X', volumeGroupId='Ri2ekd-EMVm-5Nqt-LvmE-U6SE-rk86-rDmbGn', serial='SIBM_2145_01002040390aXX00', lunMapping='19', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='10', pvSize='9', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdfy=true, sdfl=true, sdfx=true, sdfm=true]', pathsCapacity='[sdfy=10, sdfl=10, sdfx=10, sdfm=10]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='3600507680c800058d000000000000869', physicalVolumeId='odOJj9-yzvj-Tyzo-X8Tr-3fMU-7uaq-XoNWLK', volumeGroupId='AmGjUE-xCU0-Eo5G-ozq7-fHk9-B7Hr-JU7OWS', serial='SIBM_2145_020320001634XX01', lunMapping='57', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='170', pvSize='129', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdii=true, sdih=true, sdgy=true, sdgx=true]', pathsCapacity='[sdii=170, sdih=170, sdgy=170, sdgx=170]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='3600507680c800058d00000000000086b', physicalVolumeId='8nCOYA-9GqA-u8cw-4UqR-NoTa-dJRG-JsoWUX', volumeGroupId='OC1FBc-sysU-N0BU-VqWz-4XiJ-O09Z-Ya7mFO', serial='SIBM_2145_020320001634XX01', lunMapping='59', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='170', pvSize='129', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdim=true, sdil=true, sdhc=true, sdhb=true]', pathsCapacity='[sdim=170, sdil=170, sdhc=170, sdhb=170]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='3600507680c800058d000000000000867', physicalVolumeId='QkuoNb-ZOWe -Y91s-7m6t-DdQG-ZkMS-hX0AJI', volumeGroupId='vFWFXt-odKh-BXtT-kHDA-oEWD-1mwD-BdD4Hj', serial='SIBM_2145_020320001634XX01', lunMapping='55', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='170', pvSize='129', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdie=true, sdid=true, sdgu=true, sdgt=true]', pathsCapacity='[sdie=170, sdid=170, sdgu=170, sdgt=170]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='3600507680c800058d00000000000086f', physicalVolumeId='8Tjzvx-YbAN-wvSp-YRx0-67CA-w95r-FQt2eL', volumeGroupId='ykahK6-ok2p-NZ3K-KRJy-S6Wh-4tNO-mCzJzm', serial='SIBM_2145_020320001634XX01', lunMapping='54', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='320', pvSize='319', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdgs=true, sdgr=true, sdic=true, sdib=true]', pathsCapacity='[sdgs=320, s dgr=320, sdic=320, sdib=320]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='3600507680c800058d00000000000086a', physicalVolumeId='wUGz0h-GJ0J-c3j7-2Zgq-YSEi-sHqV-3vJcpF', volumeGroupId='sxr86w-VBWu-SSKT-t1Ll-4cif-Crfo-e3H4bc', serial='SIBM_2145_020320001634XX01', lunMapping='58', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='170', pvSize='129', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdgz=true, sdik=true, sdij=true, sdha=true]', pathsCapacity='[sdgz=170, sdik=170, sdij=170, sdha=170]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='3600507680c800058d00000000000086c', physicalVolumeId='frm2Ez-iYz0-Kwnj-LOa8-xYIb-psVW-9QEjFN', volumeGroupId='FY2az4-E92y-5szx-XzwJ-3eSg-uWk3-WNIRWZ', serial='SIBM_2145_020320001634XX01', lunMapping= '60', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='170', pvSize='129', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdio=true, sdin=true, sdhd=true, sdhe=true]', pathsCapacity='[sdio=170, sdin=170, sdhd=170, sdhe=170]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomainName='null', discardMaxSize='0'}, LUNs:{id='3600507680c800058d00000000000086e', physicalVolumeId='AHHK9F-y2AK-kZEG-S7dl-Nhns-SvnV-9mptO0', volumeGroupId='piaAJn-weHU-UUtI-TnXE-K3Qk-1P10-oLea9M', serial='SIBM_2145_020320001634XX01', lunMapping='62', vendorId='IBM', productId='2145', lunConnections='[]', deviceSize='170', pvSize='129', peCount='null', peAllocatedCount='null', vendorName='IBM', pathsDictionary='[sdhg=true, sdhj=true, sdis=true, sdir=true]', pathsCapacity='[sdhg=170, sdhj=170, sdis=170, sdir=170]', lunType='FCP', status='Unknown', diskId='null', diskAlias='null', storageDomainId='null', storageDomain Name='null', discardMaxSize='0'}], log id: 7f0959e9 2025-02-11 14:35:11,448+01 INFO [org.ovirt.engine.core.bll.storage.pool.SyncDirectLunsCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] LUNs with IDs: [360050764008100e428000000000003b8, 3600507680c800058d000000000000868, 3600507680c800058d000000000000867, 3600507680c800058d00000000000086e, 360050764008100e428000000000003b7, 3600507680c800058d000000000000869, 3600507680c800058d00000000000086f, 3600507680c800058d00000000000086d, 3600507680c800058d00000000000086b, 3600507680c800058d00000000000086c, 3600507680c800058d00000000000086a] were updated in the DB. 2025-02-11 14:35:11,503+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ExtendVmDiskSizeVDSCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] START, ExtendVmDiskSizeVDSCommand(HostName = b4chl327.b4r.local, ExtendVmDiskSizeVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b'}), log id: 4bc8a6cc 2025-02-11 14:35:52,624+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks. 2025-02-11 14:35:52,624+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 40 threads waiting for tasks and 0 tasks in queue. 2025-02-11 14:35:52,624+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineScheduledThreadPool' is using 0 threads out of 1, 100 threads waiting for tasks. 2025-02-11 14:35:52,624+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineThreadMonitoringThreadPool' is using 1 threads out of 1, 0 threads waiting for tasks. 2025-02-11 14:35:52,624+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'hostUpdatesChecker' is using 0 threads out of 5, 5 threads waiting for tasks. 2025-02-11 14:36:20,501+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] VM '7dfe7176-175d-4c19-86e6-bb6c3b32e75b'(b4chl479) moved from 'Up' --> 'NotResponding' 2025-02-11 14:36:20,559+01 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] EVENT_ID: VM_NOT_RESPONDING(126), VM b4chl479 is not responding. 2025-02-11 14:36:35,584+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-82) [] VM '7dfe7176-175d-4c19-86e6-bb6c3b32e75b'(b4chl479) moved from 'NotResponding' --> 'Up' 2025-02-11 14:37:37,188+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [6eed91d6] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:37:37,198+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [6eed91d6] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:37:37,200+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [6eed91d6] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:37:37,362+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-340) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:37:37,473+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [6eed91d6] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:37:37,474+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [6eed91d6] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:38:08,503+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-36) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:38:11,511+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM b4chl327.b4r.local command ExtendVmDiskSizeVDS failed: Message timeout which can be caused by communication issues 2025-02-11 14:38:11,511+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.ExtendVmDiskSizeVDSCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] Command 'ExtendVmDiskSizeVDSCommand(HostName = b4chl327.b4r.local, ExtendVmDiskSizeVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b'})' execution failed: VDSGenericException: VDSNetworkException: Message timeout which can be caused by communication issues 2025-02-11 14:38:11,511+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ExtendVmDiskSizeVDSCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] FINISH, ExtendVmDiskSizeVDSCommand, return: , log id: 4bc8a6cc 2025-02-11 14:38:11,511+01 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (EE-ManagedThreadFactory-engine-Thread-834336) [7395390d-115f-4a05-9c3c-a927e89c9c81] Clearing domains data for host b4chl327.b4r.local 2025-02-11 14:38:11,511+01 WARN [org.ovirt.engine.core.vdsbroker.VdsManager] (EE-ManagedThreadFactory-engine-Thread-834336) [7395390d-115f-4a05-9c3c-a927e89c9c81] Host 'b4chl327.b4r.local' is not responding. 2025-02-11 14:38:11,511+01 ERROR [org.ovirt.engine.core.bll.storage.pool.SyncDirectLunsCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] Failed to update the size for LUN disk '00f801bc-c465-4f9f-9445-50868d0d200d' due to error, VM should be restarted to detect the new size: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSNetworkException: VDSGenericException: VDSNetworkException: Message timeout which can be caused by communication issues (Failed with error VDS_NETWORK_ERROR and code 5022) 2025-02-11 14:38:11,513+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] EVENT_ID: SYNC_DIRECT_LUNS_FAILED(1,056), Direct LUN synchronization failed. 2025-02-11 14:38:11,514+01 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-834336) [7395390d-115f-4a05-9c3c-a927e89c9c81] EVENT_ID: VDS_HOST_NOT_RESPONDING(9,027), Host b4chl327.b4r.local is not responding. Host cannot be fenced automatically because power management for the host is disabled. 2025-02-11 14:38:11,514+01 INFO [org.ovirt.engine.core.bll.storage.pool.SyncDirectLunsCommand] (default task-342) [7395390d-115f-4a05-9c3c-a927e89c9c81] Lock freed to object 'EngineLock:{exclusiveLocks='[e4c13e38-eabf-4b8d-ba7a-f77c64e9eaf7=DISK, e1efd5f3-ce37-4778-93fb-0c33cc91fe8e=DISK, 66477d1a-9ebe-4fb9-ae2c-7f91c54e3d42=DISK, df7f4f52-1a88-4d8b-b3a0-789a299e34a1=DISK, 00f801bc-c465-4f9f-9445-50868d0d200d=DISK, af80f9c1-41c6-44ef-960b-ee40df405e6b=DISK, 309bfd4e-561c-4a36-b014-61449839e35b=DISK, 08418bad-9036-48fe-a251-d0cd37fa17be=DISK, 0928e62b-eed0-4822-b917-878c6d7e16b1=DISK, 6e29559a-c877-4572-a3ba-80d576b6f85e=DISK, 822f30c2-9513-45ec-aa56-372f16ec52f4=DISK]', sharedLocks=''}' 2025-02-11 14:38:19,778+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoAsyncVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-52) [] START, GetHardwareInfoAsyncVDSCommand(HostName = b4chl327.b4r.local, VdsIdAndVdsVDSCommandParametersBase:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vds='Host[b4chl327.b4r.local,9ec9f368-99c8-4139-83b0-48df2a676cc6]'}), log id: 57bb78a4 2025-02-11 14:38:19,778+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetHardwareInfoAsyncVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-52) [] FINISH, GetHardwareInfoAsyncVDSCommand, return: , log id: 57bb78a4 2025-02-11 14:38:19,855+01 INFO [org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-52) [5285c193] Running command: HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected : ID: 9ec9f368-99c8-4139-83b0-48df2a676cc6 Type: VDS 2025-02-11 14:38:19,865+01 INFO [org.ovirt.engine.core.bll.UpdateClusterCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-52) [66cdcb61] Lock Acquired to object 'EngineLock:{exclusiveLocks='[]', sharedLocks='[]'}' 2025-02-11 14:38:19,941+01 INFO [org.ovirt.engine.core.bll.UpdateClusterCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-52) [66cdcb61] Running command: UpdateClusterCommand internal: true. Entities affected : ID: 66795ef6-95ee-11ef-bf1f-000c29d3bed9 Type: ClusterAction group EDIT_CLUSTER_CONFIGURATION with role type ADMIN 2025-02-11 14:38:19,946+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-52) [66cdcb61] EVENT_ID: SYSTEM_UPDATE_CLUSTER(835), Host cluster BaaSCore-16 was updated by system 2025-02-11 14:38:19,946+01 INFO [org.ovirt.engine.core.bll.UpdateClusterCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-52) [66cdcb61] Lock freed to object 'EngineLock:{exclusiveLocks='[]', sharedLocks='[]'}' 2025-02-11 14:38:20,384+01 INFO [org.ovirt.engine.core.bll.InitVdsOnUpCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [ecb6192] Running command: InitVdsOnUpCommand internal: true. Entities affected : ID: 6677b1a0-95ee-11ef-8715-000c29d3bed9 Type: StoragePool 2025-02-11 14:38:20,393+01 INFO [org.ovirt.engine.core.bll.storage.pool.ConnectHostToStoragePoolServersCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [7b028435] Running command: ConnectHostToStoragePoolServersCommand internal: true. Entities affected : ID: 6677b1a0-95ee-11ef-8715-000c29d3bed9 Type: StoragePool 2025-02-11 14:38:20,398+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [7b028435] START, ConnectStorageServerVDSCommand(HostName = b4chl327.b4r.local, StorageServerConnectionManagementVDSParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', storagePoolId='6677b1a0-95ee-11ef-8715-000c29d3bed9', storageType='FCP', connectionList='[StorageServerConnections:{id='00000000-0000-0000-0000-000000000000', connection='null', iqn='null', vfsType='null', mountOptions='null', nfsVersion='null', nfsRetrans='null', nfsTimeo='null', iface='null', netIfaceName='null'}]', sendNetworkEventOnFailure='true'}), log id: 1648a0f4 2025-02-11 14:38:26,267+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [7b028435] FINISH, ConnectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: 1648a0f4 2025-02-11 14:38:26,270+01 INFO [org.ovirt.engine.core.bll.storage.pool.ConnectHostToStoragePoolServersCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [7b028435] Host 'b4chl327.b4r.local' storage connection was succeeded 2025-02-11 14:38:26,278+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834344) [7b028435] START, ConnectStoragePoolVDSCommand(HostName = b4chl327.b4r.local, ConnectStoragePoolVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vdsId='9ec9f368-99c8-4139-83b0-48df2a676cc6', storagePoolId='6677b1a0-95ee-11ef-8715-000c29d3bed9', masterVersion='1'}), log id: 4479e7b9 2025-02-11 14:38:26,278+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834344) [7b028435] Executing with domain map: {c5956f3c-9f2a-4a2b-8dc4-b69db55091d7=active} 2025-02-11 14:38:37,234+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834344) [7b028435] FINISH, ConnectStoragePoolVDSCommand, return: , log id: 4479e7b9 2025-02-11 14:38:37,585+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetMOMPolicyParametersVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [7b028435] START, SetMOMPolicyParametersVDSCommand(HostName = b4chl327.b4r.local, MomPolicyVDSParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6'}), log id: 63add32e 2025-02-11 14:38:37,623+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetMOMPolicyParametersVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [7b028435] FINISH, SetMOMPolicyParametersVDSCommand, return: , log id: 63add32e 2025-02-11 14:38:37,629+01 INFO [org.ovirt.engine.core.bll.hostdev.RefreshHostDevicesCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [268a8dde] Running command: RefreshHostDevicesCommand internal: true. Entities affected : ID: 9ec9f368-99c8-4139-83b0-48df2a676cc6 Type: VDSAction group MANIPULATE_HOST with role type ADMIN 2025-02-11 14:38:39,116+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [268a8dde] EVENT_ID: VDS_DETECTED(13), Status of host b4chl327.b4r.local was set to Up. 2025-02-11 14:38:39,117+01 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [268a8dde] EVENT_ID: VDS_ALERT_FENCE_IS_NOT_CONFIGURED(9,000), Failed to verify Power Management configuration for Host b4chl327.b4r.local. 2025-02-11 14:38:39,132+01 INFO [org.ovirt.engine.core.bll.HandleVdsVersionCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [62b5b915] Running command: HandleVdsVersionCommand internal: true. Entities affected : ID: 9ec9f368-99c8-4139-83b0-48df2a676cc6 Type: VDS 2025-02-11 14:38:39,136+01 INFO [org.ovirt.engine.core.vdsbroker.VdsManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-29) [62b5b915] Received first domain report for host b4chl327.b4r.local 2025-02-11 14:40:09,155+01 INFO [org.ovirt.engine.core.bll.aaa.LoginOnBehalfCommand] (default task-342) [6a8f78b0] Running command: LoginOnBehalfCommand internal: true. 2025-02-11 14:40:09,184+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [6a8f78b0] EVENT_ID: USER_LOGIN_ON_BEHALF(1,401), Executed login on behalf - for user cud. 2025-02-11 14:40:09,193+01 INFO [org.ovirt.engine.core.bll.aaa.LogoutSessionCommand] (default task-342) [1f01fc1b] Running command: LogoutSessionCommand internal: true. 2025-02-11 14:40:09,196+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [1f01fc1b] EVENT_ID: USER_VDC_LOGOUT(31), User SYSTEM connected from 'UNKNOWN' using session 'FtlxaYxJn+NAQtFomB0T2EDpeG3I2v1vGtDbRuXjDuNYj0hhXFFlTfbNAaYoXw+APGGSu8bEfrttoDxZ9rh2bw==' logged out. 2025-02-11 14:41:08,515+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-59) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:41:21,000+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-87) [] VM '7dfe7176-175d-4c19-86e6-bb6c3b32e75b'(b4chl479) moved from 'Up' --> 'NotResponding' 2025-02-11 14:41:21,047+01 WARN [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-87) [] EVENT_ID: VM_NOT_RESPONDING(126), VM b4chl479 is not responding. 2025-02-11 14:41:36,070+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] VM '7dfe7176-175d-4c19-86e6-bb6c3b32e75b'(b4chl479) moved from 'NotResponding' --> 'Up' 2025-02-11 14:42:00,814+01 INFO [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-342) [411fc5b9] Running command: SetVmTicketCommand internal: false. Entities affected : ID: 7dfe7176-175d-4c19-86e6-bb6c3b32e75b Type: VMAction group CONNECT_TO_VM with role type USER 2025-02-11 14:42:00,818+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-342) [411fc5b9] START, SetVmTicketVDSCommand(HostName = b4chl327.b4r.local, SetVmTicketVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', protocol='VNC', ticket='xRS84vcK', validTime='120', userName='cud', userId='25812e07-fbed-4fe3-9421-dd41ad09dbf5', disconnectAction='LOGOUT', consoleDisconnectActionDelay='0'}), log id: 36590439 2025-02-11 14:42:04,053+01 INFO [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-340) [76910b58] Running command: SetVmTicketCommand internal: false. Entities affected : ID: 7dfe7176-175d-4c19-86e6-bb6c3b32e75b Type: VMAction group CONNECT_TO_VM with role type USER 2025-02-11 14:42:12,101+01 INFO [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-345) [8bfcc1] Running command: SetVmTicketCommand internal: false. Entities affected : ID: 7dfe7176-175d-4c19-86e6-bb6c3b32e75b Type: VMAction group CONNECT_TO_VM with role type USER 2025-02-11 14:42:30,839+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-342) [411fc5b9] Failed in 'SetVmTicketVDS' method 2025-02-11 14:42:30,841+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [411fc5b9] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM b4chl327.b4r.local command SetVmTicketVDS failed: Error while setting spice ticket 2025-02-11 14:42:30,841+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-342) [411fc5b9] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand' return value 'StatusOnlyReturn [status=Status [code=18, message=Error while setting spice ticket]]' 2025-02-11 14:42:30,841+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-342) [411fc5b9] HostName = b4chl327.b4r.local 2025-02-11 14:42:30,841+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-342) [411fc5b9] Command 'SetVmTicketVDSCommand(HostName = b4chl327.b4r.local, SetVmTicketVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', protocol='VNC', ticket='xRS84vcK', validTime='120', userName='cud', userId='25812e07-fbed-4fe3-9421-dd41ad09dbf5', disconnectAction='LOGOUT', consoleDisconnectActionDelay='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to SetVmTicketVDS, error = Error while setting spice ticket, code = 18 2025-02-11 14:42:30,841+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-342) [411fc5b9] FINISH, SetVmTicketVDSCommand, return: , log id: 36590439 2025-02-11 14:42:30,841+01 ERROR [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-342) [411fc5b9] Command 'org.ovirt.engine.core.bll.SetVmTicketCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to SetVmTicketVDS, error = Error while setting spice ticket, code = 18 (Failed with error ticketErr and code 18) 2025-02-11 14:42:30,843+01 ERROR [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-342) [411fc5b9] Transaction rolled-back for command 'org.ovirt.engine.core.bll.SetVmTicketCommand'. 2025-02-11 14:42:30,847+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-340) [76910b58] START, SetVmTicketVDSCommand(HostName = b4chl327.b4r.local, SetVmTicketVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', protocol='VNC', ticket='9HRdte5C', validTime='120', userName='cud', userId='25812e07-fbed-4fe3-9421-dd41ad09dbf5', disconnectAction='LOGOUT', consoleDisconnectActionDelay='0'}), log id: 2d1d3935 2025-02-11 14:42:30,850+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-342) [411fc5b9] EVENT_ID: VM_SET_TICKET_FAILED(165), User cud@internalkeycloak-authz failed to initiate a console session for VM b4chl479 2025-02-11 14:42:37,483+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [34c48f07] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:42:37,493+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [34c48f07] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:42:37,494+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [34c48f07] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:42:37,656+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-342) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:42:37,767+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [34c48f07] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:42:37,767+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-51) [34c48f07] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:43:00,868+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-340) [76910b58] Failed in 'SetVmTicketVDS' method 2025-02-11 14:43:00,871+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-340) [76910b58] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM b4chl327.b4r.local command SetVmTicketVDS failed: Error while setting spice ticket 2025-02-11 14:43:00,871+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-340) [76910b58] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand' return value 'StatusOnlyReturn [status=Status [code=18, message=Error while setting spice ticket]]' 2025-02-11 14:43:00,871+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-340) [76910b58] HostName = b4chl327.b4r.local 2025-02-11 14:43:00,871+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-340) [76910b58] Command 'SetVmTicketVDSCommand(HostName = b4chl327.b4r.local, SetVmTicketVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', protocol='VNC', ticket='9HRdte5C', validTime='120', userName='cud', userId='25812e07-fbed-4fe3-9421-dd41ad09dbf5', disconnectAction='LOGOUT', consoleDisconnectActionDelay='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to SetVmTicketVDS, error = Error while setting spice ticket, code = 18 2025-02-11 14:43:00,871+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-340) [76910b58] FINISH, SetVmTicketVDSCommand, return: , log id: 2d1d3935 2025-02-11 14:43:00,871+01 ERROR [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-340) [76910b58] Command 'org.ovirt.engine.core.bll.SetVmTicketCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to SetVmTicketVDS, error = Error while setting spice ticket, code = 18 (Failed with error ticketErr and code 18) 2025-02-11 14:43:00,873+01 ERROR [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-340) [76910b58] Transaction rolled-back for command 'org.ovirt.engine.core.bll.SetVmTicketCommand'. 2025-02-11 14:43:00,876+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-345) [8bfcc1] START, SetVmTicketVDSCommand(HostName = b4chl327.b4r.local, SetVmTicketVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', protocol='VNC', ticket='8aJA9VZa', validTime='120', userName='cud', userId='25812e07-fbed-4fe3-9421-dd41ad09dbf5', disconnectAction='LOGOUT', consoleDisconnectActionDelay='0'}), log id: 4823ae0a 2025-02-11 14:43:00,880+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-340) [76910b58] EVENT_ID: VM_SET_TICKET_FAILED(165), User cud@internalkeycloak-authz failed to initiate a console session for VM b4chl479 2025-02-11 14:43:30,900+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-345) [8bfcc1] Failed in 'SetVmTicketVDS' method 2025-02-11 14:43:30,902+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-345) [8bfcc1] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM b4chl327.b4r.local command SetVmTicketVDS failed: Error while setting spice ticket 2025-02-11 14:43:30,902+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-345) [8bfcc1] Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand' return value 'StatusOnlyReturn [status=Status [code=18, message=Error while setting spice ticket]]' 2025-02-11 14:43:30,902+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-345) [8bfcc1] HostName = b4chl327.b4r.local 2025-02-11 14:43:30,903+01 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-345) [8bfcc1] Command 'SetVmTicketVDSCommand(HostName = b4chl327.b4r.local, SetVmTicketVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', protocol='VNC', ticket='8aJA9VZa', validTime='120', userName='cud', userId='25812e07-fbed-4fe3-9421-dd41ad09dbf5', disconnectAction='LOGOUT', consoleDisconnectActionDelay='0'})' execution failed: VDSGenericException: VDSErrorException: Failed to SetVmTicketVDS, error = Error while setting spice ticket, code = 18 2025-02-11 14:43:30,903+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (default task-345) [8bfcc1] FINISH, SetVmTicketVDSCommand, return: , log id: 4823ae0a 2025-02-11 14:43:30,903+01 ERROR [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-345) [8bfcc1] Command 'org.ovirt.engine.core.bll.SetVmTicketCommand' failed: EngineException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to SetVmTicketVDS, error = Error while setting spice ticket, code = 18 (Failed with error ticketErr and code 18) 2025-02-11 14:43:30,904+01 ERROR [org.ovirt.engine.core.bll.SetVmTicketCommand] (default task-345) [8bfcc1] Transaction rolled-back for command 'org.ovirt.engine.core.bll.SetVmTicketCommand'. 2025-02-11 14:43:30,908+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-345) [8bfcc1] EVENT_ID: VM_SET_TICKET_FAILED(165), User cud@internalkeycloak-authz failed to initiate a console session for VM b4chl479 2025-02-11 14:44:08,526+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-63) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:45:52,625+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks. 2025-02-11 14:45:52,625+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 38 threads waiting for tasks and 0 tasks in queue. 2025-02-11 14:45:52,625+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineScheduledThreadPool' is using 0 threads out of 1, 100 threads waiting for tasks. 2025-02-11 14:45:52,625+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineThreadMonitoringThreadPool' is using 1 threads out of 1, 0 threads waiting for tasks. 2025-02-11 14:45:52,625+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'hostUpdatesChecker' is using 0 threads out of 5, 5 threads waiting for tasks. 2025-02-11 14:46:26,685+01 WARN [org.ovirt.vdsm.jsonrpc.client.JsonRpcClient] (ResponseWorker) [] Not able to update response for <JsonRpcResponse id: "fb813bcf-be3b-4cfe-bd50-40874b96d7f6" error: {"code":56,"message":"Failed to update device"}> 2025-02-11 14:46:28,340+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-5) [4627ad1d] VM '7dfe7176-175d-4c19-86e6-bb6c3b32e75b' was reported as Down on VDS '9ec9f368-99c8-4139-83b0-48df2a676cc6'(b4chl327.b4r.local) 2025-02-11 14:46:28,392+01 INFO [org.ovirt.engine.core.bll.SaveVmExternalDataCommand] (ForkJoinPool-1-worker-5) [358d7c7b] Running command: SaveVmExternalDataCommand internal: true. Entities affected : ID: 7dfe7176-175d-4c19-86e6-bb6c3b32e75b Type: VM 2025-02-11 14:46:28,393+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-5) [358d7c7b] START, DestroyVDSCommand(HostName = b4chl327.b4r.local, DestroyVmVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', secondsToWait='0', gracefully='false', reason='', ignoreNoVm='true'}), log id: 5faf75d9 2025-02-11 14:46:28,397+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-5) [358d7c7b] FINISH, DestroyVDSCommand, return: , log id: 5faf75d9 2025-02-11 14:46:28,397+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-5) [358d7c7b] VM '7dfe7176-175d-4c19-86e6-bb6c3b32e75b'(b4chl479) moved from 'Up' --> 'Down' 2025-02-11 14:46:28,404+01 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-5) [358d7c7b] EVENT_ID: VM_DOWN_ERROR(119), VM b4chl479 is down with error. Exit message: Lost connection with qemu process. 2025-02-11 14:46:28,410+01 INFO [org.ovirt.engine.core.bll.ProcessDownVmCommand] (EE-ManagedThreadFactory-engine-Thread-834644) [6cf4c44d] Running command: ProcessDownVmCommand internal: true. 2025-02-11 14:46:36,488+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.PollVmStatsRefresher] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-14) [] Fetched 4 VMs from VDS '9ec9f368-99c8-4139-83b0-48df2a676cc6' 2025-02-11 14:46:50,278+01 INFO [org.ovirt.engine.core.bll.RunVmCommand] (default task-345) [6744d132-a12a-43cc-87c1-7c82d8f46631] Lock Acquired to object 'EngineLock:{exclusiveLocks='[7dfe7176-175d-4c19-86e6-bb6c3b32e75b=VM]', sharedLocks=''}' 2025-02-11 14:46:50,290+01 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default task-345) [6744d132-a12a-43cc-87c1-7c82d8f46631] START, IsVmDuringInitiatingVDSCommand( IsVmDuringInitiatingVDSCommandParameters:{vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b'}), log id: 33f3c87c 2025-02-11 14:46:50,290+01 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default task-345) [6744d132-a12a-43cc-87c1-7c82d8f46631] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 33f3c87c 2025-02-11 14:46:50,320+01 INFO [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (default task-345) [6744d132-a12a-43cc-87c1-7c82d8f46631] Candidate host 'b4chl326.b4r.local' ('651b33cf-ebe4-414f-baf9-366e28de7122') was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'PinToHost' (correlation id: null) 2025-02-11 14:46:50,320+01 INFO [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (default task-345) [6744d132-a12a-43cc-87c1-7c82d8f46631] Candidate host 'b4chl318.b4r.local' ('900a20a6-4562-40af-b262-ffd4fa2a6616') was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'PinToHost' (correlation id: null) 2025-02-11 14:46:50,320+01 INFO [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (default task-345) [6744d132-a12a-43cc-87c1-7c82d8f46631] Candidate host 'b4chl317.b4r.local' ('cd886789-8a5c-43ac-b33f-d65b15cbf4a0') was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'PinToHost' (correlation id: null) 2025-02-11 14:46:50,320+01 INFO [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (default task-345) [6744d132-a12a-43cc-87c1-7c82d8f46631] Candidate host 'b4chl325.b4r.local' ('e2f37db4-d80d-4aca-b592-23f685d7f730') was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'PinToHost' (correlation id: null) 2025-02-11 14:46:50,343+01 INFO [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] Running command: RunVmCommand internal: false. Entities affected : ID: 7dfe7176-175d-4c19-86e6-bb6c3b32e75b Type: VMAction group RUN_VM with role type USER 2025-02-11 14:46:50,356+01 INFO [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] Candidate host 'b4chl326.b4r.local' ('651b33cf-ebe4-414f-baf9-366e28de7122') was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'PinToHost' (correlation id: 6744d132-a12a-43cc-87c1-7c82d8f46631) 2025-02-11 14:46:50,356+01 INFO [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] Candidate host 'b4chl318.b4r.local' ('900a20a6-4562-40af-b262-ffd4fa2a6616') was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'PinToHost' (correlation id: 6744d132-a12a-43cc-87c1-7c82d8f46631) 2025-02-11 14:46:50,356+01 INFO [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] Candidate host 'b4chl317.b4r.local' ('cd886789-8a5c-43ac-b33f-d65b15cbf4a0') was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'PinToHost' (correlation id: 6744d132-a12a-43cc-87c1-7c82d8f46631) 2025-02-11 14:46:50,356+01 INFO [org.ovirt.engine.core.bll.scheduling.SchedulingManager] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] Candidate host 'b4chl325.b4r.local' ('e2f37db4-d80d-4aca-b592-23f685d7f730') was filtered out by 'VAR__FILTERTYPE__INTERNAL' filter 'PinToHost' (correlation id: 6744d132-a12a-43cc-87c1-7c82d8f46631) 2025-02-11 14:46:50,371+01 INFO [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] START, UpdateVmDynamicDataVDSCommand( UpdateVmDynamicDataVDSCommandParameters:{hostId='null', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', vmDynamic='org.ovirt.engine.core.common.businessentities.VmDynamic@b92421e5'}), log id: 6adca330 2025-02-11 14:46:50,372+01 INFO [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] FINISH, UpdateVmDynamicDataVDSCommand, return: , log id: 6adca330 2025-02-11 14:46:50,374+01 INFO [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] START, CreateVDSCommand( CreateVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', vm='VM [b4chl479]'}), log id: 77c4b93a 2025-02-11 14:46:50,374+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] START, CreateBrokerVDSCommand(HostName = b4chl327.b4r.local, CreateVDSCommandParameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', vm='VM [b4chl479]'}), log id: 51576c47 2025-02-11 14:46:50,392+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] VM <?xml version="1.0" encoding="UTF-8"?><domain type="kvm" xmlns:ovirt-tune="http://ovirt.org/vm/tune/1.0" xmlns:ovirt-vm="http://ovirt.org/vm/1.0" xmlns:qemu="http://libvirt.org/schemas/domain/qemu/1.0"> 2025-02-11 14:46:50,401+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] FINISH, CreateBrokerVDSCommand, return: , log id: 51576c47 2025-02-11 14:46:50,402+01 INFO [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] FINISH, CreateVDSCommand, return: WaitForLaunch, log id: 77c4b93a 2025-02-11 14:46:50,402+01 INFO [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] Lock freed to object 'EngineLock:{exclusiveLocks='[7dfe7176-175d-4c19-86e6-bb6c3b32e75b=VM]', sharedLocks=''}' 2025-02-11 14:46:50,404+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-834655) [6744d132-a12a-43cc-87c1-7c82d8f46631] EVENT_ID: USER_STARTED_VM(153), VM b4chl479 was started by cud@internalkeycloak-authz (Host: b4chl327.b4r.local). 2025-02-11 14:46:51,504+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.PollVmStatsRefresher] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-90) [] Fetched 5 VMs from VDS '9ec9f368-99c8-4139-83b0-48df2a676cc6' 2025-02-11 14:46:51,507+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-90) [] START, GetVmExternalDataVDSCommand(HostName = b4chl327.b4r.local, Parameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', kind='NVRAM'}), log id: 77f85b1b 2025-02-11 14:46:51,508+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-90) [] FINISH, GetVmExternalDataVDSCommand, return: org.ovirt.engine.core.vdsbroker.vdsbroker.VmExternalDataReturn@3ea999d5, log id: 77f85b1b 2025-02-11 14:46:59,020+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-23) [358d7c7b] VM '7dfe7176-175d-4c19-86e6-bb6c3b32e75b'(b4chl479) moved from 'WaitForLaunch' --> 'PoweringUp' 2025-02-11 14:46:59,025+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand] (ForkJoinPool-1-worker-23) [358d7c7b] START, DumpXmlsVDSCommand(HostName = b4chl327.b4r.local, Params:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmIds='[7dfe7176-175d-4c19-86e6-bb6c3b32e75b]'}), log id: 5f5d956e 2025-02-11 14:46:59,029+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand] (ForkJoinPool-1-worker-23) [358d7c7b] FINISH, DumpXmlsVDSCommand, return: {7dfe7176-175d-4c19-86e6-bb6c3b32e75b=<domain type='kvm' id='14' xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0'> 2025-02-11 14:47:04,844+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.OvfDataUpdater] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [] Attempting to update VMs/Templates Ovf. 2025-02-11 14:47:04,844+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Before acquiring and wait lock 'EngineLock:{exclusiveLocks='[6677b1a0-95ee-11ef-8715-000c29d3bed9=OVF_UPDATE]', sharedLocks=''}' 2025-02-11 14:47:04,844+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Lock-wait acquired to object 'EngineLock:{exclusiveLocks='[6677b1a0-95ee-11ef-8715-000c29d3bed9=OVF_UPDATE]', sharedLocks=''}' 2025-02-11 14:47:04,845+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Running command: ProcessOvfUpdateForStoragePoolCommand internal: true. Entities affected : ID: 6677b1a0-95ee-11ef-8715-000c29d3bed9 Type: StoragePool 2025-02-11 14:47:04,848+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Attempting to update VM OVFs in Data Center 'BaaS-GCV-06' 2025-02-11 14:47:04,880+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Successfully updated VM OVFs in Data Center 'BaaS-GCV-06' 2025-02-11 14:47:04,880+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Attempting to update template OVFs in Data Center 'BaaS-GCV-06' 2025-02-11 14:47:04,880+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Successfully updated templates OVFs in Data Center 'BaaS-GCV-06' 2025-02-11 14:47:04,880+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Attempting to remove unneeded template/vm OVFs in Data Center 'BaaS-GCV-06' 2025-02-11 14:47:04,881+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Successfully removed unneeded template/vm OVFs in Data Center 'BaaS-GCV-06' 2025-02-11 14:47:04,881+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStoragePoolCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [7859988a] Lock freed to object 'EngineLock:{exclusiveLocks='[6677b1a0-95ee-11ef-8715-000c29d3bed9=OVF_UPDATE]', sharedLocks=''}' 2025-02-11 14:47:04,884+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Lock Acquired to object 'EngineLock:{exclusiveLocks='[c5956f3c-9f2a-4a2b-8dc4-b69db55091d7=STORAGE]', sharedLocks='[6677b1a0-95ee-11ef-8715-000c29d3bed9=OVF_UPDATE]'}' 2025-02-11 14:47:04,890+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Running command: ProcessOvfUpdateForStorageDomainCommand internal: true. Entities affected : ID: c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 Type: StorageAction group MANIPULATE_STORAGE_DOMAIN with role type ADMIN 2025-02-11 14:47:04,901+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='6677b1a0-95ee-11ef-8715-000c29d3bed9', ignoreFailoverLimit='false', storageDomainId='c5956f3c-9f2a-4a2b-8dc4-b69db55091d7', imageGroupId='d9215ce9-477e-4086-8cfb-c0dad7f09814', imageId='ca801cbb-4d61-41c9-b637-81cc921cea8c'}), log id: 75d3752b 2025-02-11 14:47:04,901+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2025-02-11 14:47:04,901+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ spUUID=6677b1a0-95ee-11ef-8715-000c29d3bed9 2025-02-11 14:47:04,901+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ sdUUID=c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 2025-02-11 14:47:04,901+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ imageGroupGUID=d9215ce9-477e-4086-8cfb-c0dad7f09814 2025-02-11 14:47:04,901+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ volUUID=ca801cbb-4d61-41c9-b637-81cc921cea8c 2025-02-11 14:47:04,901+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ description={"Updated":false,"Last Updated":"Mon Feb 10 15:47:01 CET 2025","Storage Domains":[{"uuid":"c5956f3c-9f2a-4a2b-8dc4-b69db55091d7"}],"Disk Description":"OVF_STORE"} 2025-02-11 14:47:06,179+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 75d3752b 2025-02-11 14:47:06,183+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Lock Acquired to object 'EngineLock:{exclusiveLocks='', sharedLocks='[651b33cf-ebe4-414f-baf9-366e28de7122=VDS_EXECUTION]'}' 2025-02-11 14:47:06,192+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Running command: UploadStreamCommand internal: true. Entities affected : ID: c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 Type: Storage 2025-02-11 14:47:06,193+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] START, UploadStreamVDSCommand(HostName = b4chl326.b4r.local, UploadStreamVDSCommandParameters:{hostId='651b33cf-ebe4-414f-baf9-366e28de7122'}), log id: 229a4c67 2025-02-11 14:47:06,193+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] -- executeVdsBrokerCommand, parameters: 2025-02-11 14:47:06,193+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ spUUID=6677b1a0-95ee-11ef-8715-000c29d3bed9 2025-02-11 14:47:06,193+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ sdUUID=c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 2025-02-11 14:47:06,193+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ imageGUID=d9215ce9-477e-4086-8cfb-c0dad7f09814 2025-02-11 14:47:06,193+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ volUUID=ca801cbb-4d61-41c9-b637-81cc921cea8c 2025-02-11 14:47:06,193+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ size=423424 2025-02-11 14:47:06,530+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-84) [] START, GetVmExternalDataVDSCommand(HostName = b4chl327.b4r.local, Parameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', kind='NVRAM'}), log id: 68e9eabd 2025-02-11 14:47:06,533+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-84) [] FINISH, GetVmExternalDataVDSCommand, return: org.ovirt.engine.core.vdsbroker.vdsbroker.VmExternalDataReturn@26f0912c, log id: 68e9eabd 2025-02-11 14:47:07,088+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] FINISH, UploadStreamVDSCommand, return: , log id: 229a4c67 2025-02-11 14:47:07,093+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command '41925434-cdc2-4456-839a-2d3fd590844e' 2025-02-11 14:47:07,093+01 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] CommandMultiAsyncTasks::attachTask: Attaching task '63bea2c5-ca0c-4f2d-ad84-21611d49ff71' to command '41925434-cdc2-4456-839a-2d3fd590844e'. 2025-02-11 14:47:07,097+01 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Adding task '63bea2c5-ca0c-4f2d-ad84-21611d49ff71' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2025-02-11 14:47:07,099+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] BaseAsyncTask::startPollingTask: Starting to poll task '63bea2c5-ca0c-4f2d-ad84-21611d49ff71'. 2025-02-11 14:47:07,100+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Lock freed to object 'EngineLock:{exclusiveLocks='', sharedLocks='[651b33cf-ebe4-414f-baf9-366e28de7122=VDS_EXECUTION]'}' 2025-02-11 14:47:07,101+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='6677b1a0-95ee-11ef-8715-000c29d3bed9', ignoreFailoverLimit='false', storageDomainId='c5956f3c-9f2a-4a2b-8dc4-b69db55091d7', imageGroupId='d9215ce9-477e-4086-8cfb-c0dad7f09814', imageId='ca801cbb-4d61-41c9-b637-81cc921cea8c'}), log id: 1f866444 2025-02-11 14:47:07,101+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2025-02-11 14:47:07,101+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ spUUID=6677b1a0-95ee-11ef-8715-000c29d3bed9 2025-02-11 14:47:07,101+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ sdUUID=c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 2025-02-11 14:47:07,101+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ imageGroupGUID=d9215ce9-477e-4086-8cfb-c0dad7f09814 2025-02-11 14:47:07,101+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ volUUID=ca801cbb-4d61-41c9-b637-81cc921cea8c 2025-02-11 14:47:07,101+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ description={"Updated":true,"Size":423424,"Last Updated":"Tue Feb 11 14:47:04 CET 2025","Storage Domains":[{"uuid":"c5956f3c-9f2a-4a2b-8dc4-b69db55091d7"}],"Disk Description":"OVF_STORE"} 2025-02-11 14:47:07,268+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 1f866444 2025-02-11 14:47:07,291+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='6677b1a0-95ee-11ef-8715-000c29d3bed9', ignoreFailoverLimit='false', storageDomainId='c5956f3c-9f2a-4a2b-8dc4-b69db55091d7', imageGroupId='ff8647dc-5e9f-4ff8-a626-2ed94b9a7778', imageId='320e64fd-5ad3-42ca-a776-54f530ac3591'}), log id: 6612fd4c 2025-02-11 14:47:07,291+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2025-02-11 14:47:07,291+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ spUUID=6677b1a0-95ee-11ef-8715-000c29d3bed9 2025-02-11 14:47:07,291+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ sdUUID=c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 2025-02-11 14:47:07,291+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ imageGroupGUID=ff8647dc-5e9f-4ff8-a626-2ed94b9a7778 2025-02-11 14:47:07,291+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ volUUID=320e64fd-5ad3-42ca-a776-54f530ac3591 2025-02-11 14:47:07,291+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ description={"Updated":false,"Last Updated":"Mon Feb 10 15:47:01 CET 2025","Storage Domains":[{"uuid":"c5956f3c-9f2a-4a2b-8dc4-b69db55091d7"}],"Disk Description":"OVF_STORE"} 2025-02-11 14:47:07,466+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 6612fd4c 2025-02-11 14:47:07,470+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Lock Acquired to object 'EngineLock:{exclusiveLocks='', sharedLocks='[651b33cf-ebe4-414f-baf9-366e28de7122=VDS_EXECUTION]'}' 2025-02-11 14:47:07,474+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Running command: UploadStreamCommand internal: true. Entities affected : ID: c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 Type: Storage 2025-02-11 14:47:07,475+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] START, UploadStreamVDSCommand(HostName = b4chl326.b4r.local, UploadStreamVDSCommandParameters:{hostId='651b33cf-ebe4-414f-baf9-366e28de7122'}), log id: 4e485fb4 2025-02-11 14:47:07,475+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] -- executeVdsBrokerCommand, parameters: 2025-02-11 14:47:07,475+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ spUUID=6677b1a0-95ee-11ef-8715-000c29d3bed9 2025-02-11 14:47:07,475+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ sdUUID=c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 2025-02-11 14:47:07,475+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ imageGUID=ff8647dc-5e9f-4ff8-a626-2ed94b9a7778 2025-02-11 14:47:07,475+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ volUUID=320e64fd-5ad3-42ca-a776-54f530ac3591 2025-02-11 14:47:07,475+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ size=423424 2025-02-11 14:47:08,323+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.UploadStreamVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] FINISH, UploadStreamVDSCommand, return: , log id: 4e485fb4 2025-02-11 14:47:08,328+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 'a69f8c9c-c6ac-40f6-aaa1-681bec0c421d' 2025-02-11 14:47:08,328+01 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] CommandMultiAsyncTasks::attachTask: Attaching task 'e92fb0c1-1ba9-494b-9028-d821e9f8f839' to command 'a69f8c9c-c6ac-40f6-aaa1-681bec0c421d'. 2025-02-11 14:47:08,331+01 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Adding task 'e92fb0c1-1ba9-494b-9028-d821e9f8f839' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters'), polling hasn't started yet.. 2025-02-11 14:47:08,332+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] BaseAsyncTask::startPollingTask: Starting to poll task 'e92fb0c1-1ba9-494b-9028-d821e9f8f839'. 2025-02-11 14:47:08,334+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Lock freed to object 'EngineLock:{exclusiveLocks='', sharedLocks='[651b33cf-ebe4-414f-baf9-366e28de7122=VDS_EXECUTION]'}' 2025-02-11 14:47:08,334+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] START, SetVolumeDescriptionVDSCommand( SetVolumeDescriptionVDSCommandParameters:{storagePoolId='6677b1a0-95ee-11ef-8715-000c29d3bed9', ignoreFailoverLimit='false', storageDomainId='c5956f3c-9f2a-4a2b-8dc4-b69db55091d7', imageGroupId='ff8647dc-5e9f-4ff8-a626-2ed94b9a7778', imageId='320e64fd-5ad3-42ca-a776-54f530ac3591'}), log id: 16ef658a 2025-02-11 14:47:08,334+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] -- executeIrsBrokerCommand: calling 'setVolumeDescription', parameters: 2025-02-11 14:47:08,334+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ spUUID=6677b1a0-95ee-11ef-8715-000c29d3bed9 2025-02-11 14:47:08,334+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ sdUUID=c5956f3c-9f2a-4a2b-8dc4-b69db55091d7 2025-02-11 14:47:08,334+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ imageGroupGUID=ff8647dc-5e9f-4ff8-a626-2ed94b9a7778 2025-02-11 14:47:08,334+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ volUUID=320e64fd-5ad3-42ca-a776-54f530ac3591 2025-02-11 14:47:08,334+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] ++ description={"Updated":true,"Size":423424,"Last Updated":"Tue Feb 11 14:47:04 CET 2025","Storage Domains":[{"uuid":"c5956f3c-9f2a-4a2b-8dc4-b69db55091d7"}],"Disk Description":"OVF_STORE"} 2025-02-11 14:47:08,501+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SetVolumeDescriptionVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] FINISH, SetVolumeDescriptionVDSCommand, return: , log id: 16ef658a 2025-02-11 14:47:08,506+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-22) [a6f7601] Lock freed to object 'EngineLock:{exclusiveLocks='[c5956f3c-9f2a-4a2b-8dc4-b69db55091d7=STORAGE]', sharedLocks='[6677b1a0-95ee-11ef-8715-000c29d3bed9=OVF_UPDATE]'}' 2025-02-11 14:47:08,538+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-67) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:47:10,264+01 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] Polling and updating Async Tasks: 2 tasks, 2 tasks to poll now 2025-02-11 14:47:10,268+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] SPMAsyncTask::PollTask: Polling task 'e92fb0c1-1ba9-494b-9028-d821e9f8f839' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'success'. 2025-02-11 14:47:10,268+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] BaseAsyncTask::onTaskEndSuccess: Task 'e92fb0c1-1ba9-494b-9028-d821e9f8f839' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended successfully. 2025-02-11 14:47:10,268+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] CommandAsyncTask::endActionIfNecessary: All tasks of command 'a69f8c9c-c6ac-40f6-aaa1-681bec0c421d' has ended -> executing 'endAction' 2025-02-11 14:47:10,268+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: 'a69f8c9c-c6ac-40f6-aaa1-681bec0c421d'): calling endAction '. 2025-02-11 14:47:10,269+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] SPMAsyncTask::PollTask: Polling task '63bea2c5-ca0c-4f2d-ad84-21611d49ff71' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') returned status 'finished', result 'success'. 2025-02-11 14:47:10,269+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] BaseAsyncTask::onTaskEndSuccess: Task '63bea2c5-ca0c-4f2d-ad84-21611d49ff71' (Parent Command 'UploadStream', Parameters Type 'org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters') ended successfully. 2025-02-11 14:47:10,269+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834673) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'UploadStream', 2025-02-11 14:47:10,269+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] CommandAsyncTask::endActionIfNecessary: All tasks of command '41925434-cdc2-4456-839a-2d3fd590844e' has ended -> executing 'endAction' 2025-02-11 14:47:10,269+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-72) [] CommandAsyncTask::endAction: Ending action for '1' tasks (command ID: '41925434-cdc2-4456-839a-2d3fd590844e'): calling endAction '. 2025-02-11 14:47:10,270+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834674) [] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction 'UploadStream', 2025-02-11 14:47:10,271+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand' successfully. 2025-02-11 14:47:10,271+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.UploadStreamCommand' successfully. 2025-02-11 14:47:10,272+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'UploadStream' completed, handling the result. 2025-02-11 14:47:10,272+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'UploadStream' succeeded, clearing tasks. 2025-02-11 14:47:10,272+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] SPMAsyncTask::ClearAsyncTask: Attempting to clear task 'e92fb0c1-1ba9-494b-9028-d821e9f8f839' 2025-02-11 14:47:10,272+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'UploadStream' completed, handling the result. 2025-02-11 14:47:10,272+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type 'UploadStream' succeeded, clearing tasks. 2025-02-11 14:47:10,272+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] SPMAsyncTask::ClearAsyncTask: Attempting to clear task '63bea2c5-ca0c-4f2d-ad84-21611d49ff71' 2025-02-11 14:47:10,272+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='6677b1a0-95ee-11ef-8715-000c29d3bed9', ignoreFailoverLimit='false', taskId='e92fb0c1-1ba9-494b-9028-d821e9f8f839'}), log id: 1f08c0f9 2025-02-11 14:47:10,273+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] START, SPMClearTaskVDSCommand( SPMTaskGuidBaseVDSCommandParameters:{storagePoolId='6677b1a0-95ee-11ef-8715-000c29d3bed9', ignoreFailoverLimit='false', taskId='63bea2c5-ca0c-4f2d-ad84-21611d49ff71'}), log id: 453a1c75 2025-02-11 14:47:10,273+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] START, HSMClearTaskVDSCommand(HostName = b4chl326.b4r.local, HSMTaskGuidBaseVDSCommandParameters:{hostId='651b33cf-ebe4-414f-baf9-366e28de7122', taskId='e92fb0c1-1ba9-494b-9028-d821e9f8f839'}), log id: 43d01038 2025-02-11 14:47:10,276+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] FINISH, HSMClearTaskVDSCommand, return: , log id: 43d01038 2025-02-11 14:47:10,276+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] FINISH, SPMClearTaskVDSCommand, return: , log id: 1f08c0f9 2025-02-11 14:47:10,277+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] START, HSMClearTaskVDSCommand(HostName = b4chl326.b4r.local, HSMTaskGuidBaseVDSCommandParameters:{hostId='651b33cf-ebe4-414f-baf9-366e28de7122', taskId='63bea2c5-ca0c-4f2d-ad84-21611d49ff71'}), log id: 3f9b52a9 2025-02-11 14:47:10,280+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] BaseAsyncTask::removeTaskFromDB: Removed task 'e92fb0c1-1ba9-494b-9028-d821e9f8f839' from DataBase 2025-02-11 14:47:10,280+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834673) [a6f7601] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 'a69f8c9c-c6ac-40f6-aaa1-681bec0c421d' 2025-02-11 14:47:10,281+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] FINISH, HSMClearTaskVDSCommand, return: , log id: 3f9b52a9 2025-02-11 14:47:10,281+01 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] FINISH, SPMClearTaskVDSCommand, return: , log id: 453a1c75 2025-02-11 14:47:10,283+01 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] BaseAsyncTask::removeTaskFromDB: Removed task '63bea2c5-ca0c-4f2d-ad84-21611d49ff71' from DataBase 2025-02-11 14:47:10,283+01 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (EE-ManagedThreadFactory-engine-Thread-834674) [a6f7601] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity '41925434-cdc2-4456-839a-2d3fd590844e' 2025-02-11 14:47:11,595+01 INFO [org.ovirt.engine.core.bll.SerialChildCommandsExecutionCallback] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-19) [a6f7601] Command 'ProcessOvfUpdateForStorageDomain' id: 'fcd78dad-d1b0-4b3a-b85d-2aedad6ca0d8' child commands '[41925434-cdc2-4456-839a-2d3fd590844e, a69f8c9c-c6ac-40f6-aaa1-681bec0c421d]' executions were completed, status 'SUCCEEDED' 2025-02-11 14:47:12,600+01 INFO [org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-79) [a6f7601] Ending command 'org.ovirt.engine.core.bll.storage.ovfstore.ProcessOvfUpdateForStorageDomainCommand' successfully. 2025-02-11 14:47:21,550+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [] START, GetVmExternalDataVDSCommand(HostName = b4chl327.b4r.local, Parameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', kind='NVRAM'}), log id: 3dc81f87 2025-02-11 14:47:21,551+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [] FINISH, GetVmExternalDataVDSCommand, return: org.ovirt.engine.core.vdsbroker.vdsbroker.VmExternalDataReturn@45f798de, log id: 3dc81f87 2025-02-11 14:47:28,099+01 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-5) [358d7c7b] VM '7dfe7176-175d-4c19-86e6-bb6c3b32e75b'(b4chl479) moved from 'PoweringUp' --> 'Up' 2025-02-11 14:47:28,103+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-5) [358d7c7b] EVENT_ID: USER_RUN_VM(32), VM b4chl479 started on Host b4chl327.b4r.local 2025-02-11 14:47:33,433+01 INFO [org.ovirt.engine.core.bll.aaa.LoginOnBehalfCommand] (default task-345) [76e0d58d] Running command: LoginOnBehalfCommand internal: true. 2025-02-11 14:47:33,457+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-345) [76e0d58d] EVENT_ID: USER_LOGIN_ON_BEHALF(1,401), Executed login on behalf - for user cud. 2025-02-11 14:47:33,466+01 INFO [org.ovirt.engine.core.bll.aaa.LogoutSessionCommand] (default task-345) [64775257] Running command: LogoutSessionCommand internal: true. 2025-02-11 14:47:33,468+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-345) [64775257] EVENT_ID: USER_VDC_LOGOUT(31), User SYSTEM connected from 'UNKNOWN' using session 'lzuEg+74u+FVvZn6GAWZZFwiquzAWaFhaC+vmvcxeWuL3q7BvysW8oln3OFIlO398vO3vi3o0bHPtm1bQW+0qw==' logged out. 2025-02-11 14:47:36,587+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-54) [] START, GetVmExternalDataVDSCommand(HostName = b4chl327.b4r.local, Parameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', kind='NVRAM'}), log id: 74ef748d 2025-02-11 14:47:36,590+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-54) [] FINISH, GetVmExternalDataVDSCommand, return: org.ovirt.engine.core.vdsbroker.vdsbroker.VmExternalDataReturn@75403afb, log id: 74ef748d 2025-02-11 14:47:37,777+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [475979af] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:47:37,787+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [475979af] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:47:37,788+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [475979af] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:47:37,949+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-345) [64775257] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:47:38,060+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [475979af] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:47:38,061+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [475979af] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:47:51,609+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-11) [] START, DumpXmlsVDSCommand(HostName = b4chl327.b4r.local, Params:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmIds='[7dfe7176-175d-4c19-86e6-bb6c3b32e75b]'}), log id: 58f11ebb 2025-02-11 14:47:51,612+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DumpXmlsVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-11) [] FINISH, DumpXmlsVDSCommand, return: {7dfe7176-175d-4c19-86e6-bb6c3b32e75b=<domain type='kvm' id='14' xmlns:qemu='http://libvirt.org/schemas/domain/qemu/1.0'> 2025-02-11 14:47:51,674+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-11) [] START, GetVmExternalDataVDSCommand(HostName = b4chl327.b4r.local, Parameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', kind='NVRAM'}), log id: bd6d46e 2025-02-11 14:47:51,676+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-11) [] FINISH, GetVmExternalDataVDSCommand, return: org.ovirt.engine.core.vdsbroker.vdsbroker.VmExternalDataReturn@29b7c9d0, log id: bd6d46e 2025-02-11 14:48:06,696+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-78) [] START, GetVmExternalDataVDSCommand(HostName = b4chl327.b4r.local, Parameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', kind='NVRAM'}), log id: 44e4b80f 2025-02-11 14:48:06,698+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-78) [] FINISH, GetVmExternalDataVDSCommand, return: org.ovirt.engine.core.vdsbroker.vdsbroker.VmExternalDataReturn@3fd229b, log id: 44e4b80f 2025-02-11 14:48:21,717+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-10) [] START, GetVmExternalDataVDSCommand(HostName = b4chl327.b4r.local, Parameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', kind='NVRAM'}), log id: 4c4cf74e 2025-02-11 14:48:21,718+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-10) [] FINISH, GetVmExternalDataVDSCommand, return: org.ovirt.engine.core.vdsbroker.vdsbroker.VmExternalDataReturn@3027bcb, log id: 4c4cf74e 2025-02-11 14:48:28,871+01 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-64) [] Setting new tasks map. The map contains now 0 tasks 2025-02-11 14:48:28,871+01 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-64) [] Cleared all tasks of pool '6677b1a0-95ee-11ef-8715-000c29d3bed9'. 2025-02-11 14:48:36,737+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-95) [] START, GetVmExternalDataVDSCommand(HostName = b4chl327.b4r.local, Parameters:{hostId='9ec9f368-99c8-4139-83b0-48df2a676cc6', vmId='7dfe7176-175d-4c19-86e6-bb6c3b32e75b', kind='NVRAM'}), log id: 5bfeeea6 2025-02-11 14:48:36,739+01 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVmExternalDataVDSCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-95) [] FINISH, GetVmExternalDataVDSCommand, return: org.ovirt.engine.core.vdsbroker.vdsbroker.VmExternalDataReturn@4f534892, log id: 5bfeeea6 2025-02-11 14:48:50,546+01 INFO [org.ovirt.engine.core.sso.servlets.OAuthRevokeServlet] (default task-345) [] User ksk@internalkeycloak-authz with profile [internalsso] successfully logged out 2025-02-11 14:48:50,552+01 INFO [org.ovirt.engine.core.bll.aaa.TerminateSessionsForTokenCommand] (default task-340) [66e0105] Running command: TerminateSessionsForTokenCommand internal: true. 2025-02-11 14:48:57,648+01 INFO [org.ovirt.engine.core.sso.service.NegotiateAuthService] (default task-345) [] User ksk@internalkeycloak-authz with profile [internalsso] successfully logged in with scopes : ovirt-app-admin ovirt-app-api ovirt-app-portal ovirt-ext=auth:sequence-priority=~ ovirt-ext=revoke:revoke-all ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:48:57,712+01 INFO [org.ovirt.engine.core.bll.aaa.CreateUserSessionCommand] (default task-345) [6ab7223e] Running command: CreateUserSessionCommand internal: false. 2025-02-11 14:48:57,717+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-345) [6ab7223e] EVENT_ID: USER_VDC_LOGIN(30), User ksk@internalkeycloak-authz connecting from '10.93.64.78' using session 'liWLpY3n0M7Ab/kmNzQqhjaX3Lrib5omvse45ssQGQ3jrAboO8w5gCQc575r9zfBjx8rLYhmvV4BSXrqVKe1Ig==' logged in. 2025-02-11 14:48:58,893+01 INFO [org.ovirt.engine.core.utils.servlet.ServletUtils] (default task-340) [66e0105] Can't read file '/usr/share/ovirt-engine/files/spice/SpiceVersion.txt' for request '/ovirt-engine/services/files/spice/SpiceVersion.txt' -- 404 2025-02-11 14:50:08,549+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-92) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:52:38,070+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [52e00195] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:52:38,080+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [52e00195] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:52:38,082+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [52e00195] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:52:38,244+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-340) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:52:38,356+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [52e00195] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:52:38,356+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-35) [52e00195] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:53:08,560+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-47) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:55:52,625+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'default' is using 0 threads out of 1, 5 threads waiting for tasks. 2025-02-11 14:55:52,626+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engine' is using 0 threads out of 500, 38 threads waiting for tasks and 0 tasks in queue. 2025-02-11 14:55:52,626+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineScheduledThreadPool' is using 0 threads out of 1, 100 threads waiting for tasks. 2025-02-11 14:55:52,626+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'engineThreadMonitoringThreadPool' is using 1 threads out of 1, 0 threads waiting for tasks. 2025-02-11 14:55:52,626+01 INFO [org.ovirt.engine.core.bll.utils.ThreadPoolMonitoringService] (EE-ManagedScheduledExecutorService-engineThreadMonitoringThreadPool-Thread-1) [] Thread pool 'hostUpdatesChecker' is using 0 threads out of 5, 5 threads waiting for tasks. 2025-02-11 14:56:08,571+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-76) [] Directory '/usr/share/virtio-win' doesn't exist. 2025-02-11 14:57:38,366+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-1) [485e7819] Lock Acquired to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:57:38,376+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-1) [485e7819] Running command: SyncNetworkProviderCommand internal: true. 2025-02-11 14:57:38,378+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-1) [485e7819] EVENT_ID: PROVIDER_SYNCHRONIZATION_STARTED(223), Provider ovirt-provider-ovn synchronization started. 2025-02-11 14:57:38,541+01 INFO [org.ovirt.engine.core.sso.service.ExternalOIDCService] (default task-345) [] User admin@ovirt@internalkeycloak-authz with profile [internalsso] successfully logged into external OP with scopes: ovirt-app-api ovirt-ext=token-info:authz-search ovirt-ext=token-info:public-authz-search ovirt-ext=token-info:validate ovirt-ext=token:password-access 2025-02-11 14:57:38,656+01 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-1) [485e7819] EVENT_ID: PROVIDER_SYNCHRONIZATION_ENDED(224), Provider ovirt-provider-ovn synchronization ended. 2025-02-11 14:57:38,656+01 INFO [org.ovirt.engine.core.bll.provider.network.SyncNetworkProviderCommand] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-1) [485e7819] Lock freed to object 'EngineLock:{exclusiveLocks='[b67c2ee1-4008-45d8-8f64-b6de7d3be2fc=PROVIDER]', sharedLocks=''}' 2025-02-11 14:59:08,582+01 WARN [org.ovirt.engine.core.utils.virtiowin.VirtioWinReader] (EE-ManagedScheduledExecutorService-engineScheduledThreadPool-Thread-52) [] Directory '/usr/share/virtio-win' doesn't exist.