On Mon, Jun 13, 2016 at 4:34 AM, Yedidyah Bar David <didi@redhat.com> wrote:
On Sat, Jun 11, 2016 at 5:56 PM, Gregor Binder <gregor.binder@wefixit.at> wrote:
> -----BEGIN PGP SIGNED MESSAGE-----
> Hash: SHA256
>
> Hi,
>
> during inspecting the engine.log I found this entry:
>
> - ------------
> [org.ovirt.engine.core.uutils.ssh.SSHDialog]
> (DefaultQuartzScheduler_Worker-81) [] Exception: java.io.IOException:
> Command returned failure code 1 during SSH session 'root@<hostmachine
> name remove>'
> - ------------
> Message: Failed to check for available updates on host host01 with
> message 'Command returned failure code 1 during SSH session
> 'root@<hostmachine name remove>'
> - ------------
>
> Looks like a serious problem because the engine can't check for updates.

You should have some more information in the log. Please check around this
line and/or post full log. Thanks.

>
> cheers
> gregor
> - --
> GPG-Key: 67F1534F
> URL: http://pgp.mit.edu:11371/pks/lookup?op=get&search=0x137FB29D67F1534
> F
> -----BEGIN PGP SIGNATURE-----
> Version: GnuPG v2
>
> iQIcBAEBCAAGBQJXXCaMAAoJEBN/sp1n8VNP1B4QAL1EZRBMe+TFYENj2WH0saTm
> GBOZxKljwkno0xdGpql64ZsmPogQ9Ybtus6eEWBuzGScc0uHvsbzVKWrVNf2afAP
> XbvWYvdTWECfhSTbQQ0MS/itwkuOfeEONywdo9jcCv+261oEJwQyltjDKK6NDgYl
> K4L5Qyvhac0EZsjRpDtKDyHj+QT321hLI5gRps/eMPIAHWl8zaq+LJVFDI4EV3gE
> 9Ndcljyxjd6IyqIG4LzQobNowA8Jp+QAIrA316ekkb9BLF7o/W9VaITmS+5xS5Dl
> y2lL7Ga/LYdpEkMh8ZQmLwjoTWZvKoL08xFQgnUQ4Ry/UI8ENukmIXecuQebhEHH
> Bs4WnaZCDxditHymI809lwf2jpeGVjLkOPuLfev38AIfKS00acm0Yb3TIWNbzs6F
> ZJ+rz9X6gtPBET2XOSDPWa/JsCcIbg/XjqEM4qzOANmKzWA4mJpVh7uM6M8mgFd+
> 4kZA8hVz4sckat1jbXFXgIJuMvNDwjgKUsDVBoZ1wKJvfj/btfgFaVI/osDnNQ8l
> rtnuGCDNhZvJCctxIbLOpC7+raImWLOy89Od1W3KMYg6ECgAM7t5A7VRtTdzSqyt
> pji7NaXsZxNqCh2QCXa8srjUQgWttpkRsH/iR3xq/s7QdS+Moail5AoF8XeCzFvB
> GX+DLN8RPMcIilUXuaUs
> =OnF7
> -----END PGP SIGNATURE-----
> _______________________________________________
> Users mailing list
> Users@ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users

Didi,

I've been having the same problem since the end of last week. I get the error whenever I try to add a new host or run reinstall on one that failed to install correctly. The relevant part of my log file is below. It covers everything from the point that I start the action that causes the error to the end of the log file. Also, I have SSH'd to the host to make sure that there's nothing wrong with the connectivity and everything there works as expected. Any help you can provide would be greatly appreciated.

2016-06-13 07:52:56,816 INFO  [org.ovirt.engine.core.bll.hostdeploy.InstallVdsCommand] (default task-81) [1a1eab5e] Running command: InstallVdsCommand internal: false. Entities affected :  ID: 244264be-4156-45a1-aed5-d05681303c07 Type: VDSAction group EDIT_HOST_CONFIGURATION with role type ADMIN
2016-06-13 07:52:56,862 INFO  [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand] (default task-81) [1a1eab5e] Lock Acquired to object 'EngineLock:{exclusiveLocks='[244264be-4156-45a1-aed5-d05681303c07=<VDS, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}'
2016-06-13 07:52:56,868 INFO  [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Running command: InstallVdsInternalCommand internal: true. Entities affected :  ID: 244264be-4156-45a1-aed5-d05681303c07 Type: VDS
2016-06-13 07:52:56,887 INFO  [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Before Installation host 244264be-4156-45a1-aed5-d05681303c07, m2-h1
2016-06-13 07:52:56,889 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-81) [1a1eab5e] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Failed to verify Power Management configuration for Host m2-h1.
2016-06-13 07:52:56,918 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] START, SetVdsStatusVDSCommand(HostName = m2-h1, SetVdsStatusVDSCommandParameters:{runAsync='true', hostId='244264be-4156-45a1-aed5-d05681303c07', status='Installing', nonOperationalReason='NONE', stopSpmFailureLogged='false', maintenanceReason='null'}), log id: 7656e770
2016-06-13 07:52:56,921 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (default task-81) [1a1eab5e] Correlation ID: 1a1eab5e, Call Stack: null, Custom Event ID: -1, Message: Host m2-h1 configuration was updated by admin@internal.
2016-06-13 07:52:56,933 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] FINISH, SetVdsStatusVDSCommand, log id: 7656e770
2016-06-13 07:52:57,140 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Correlation ID: 1a1eab5e, Call Stack: null, Custom Event ID: -1, Message: Installing Host m2-h1. Connected to host 192.168.1.12 with SSH key fingerprint: SHA256:oxhsFheDmU6jM0VVPhYXKsckaHLVL8z/fDV3HiLa/Uk.
2016-06-13 07:52:57,206 INFO  [org.ovirt.engine.core.bll.hostdeploy.VdsDeployBase] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Installation of 192.168.1.12. Executing command via SSH umask 0077; MYTMP="$(TMPDIR="${OVIRT_TMPDIR}" mktemp -d -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; tar --warning=no-timestamp -C "${MYTMP}" -x &&  "${MYTMP}"/ovirt-host-deploy DIALOG/dialect=str:machine DIALOG/customization=bool:True < /home/phillip/ovirt-engine/var/cache/ovirt-engine/ovirt-host-deploy.tar
2016-06-13 07:52:57,206 INFO  [org.ovirt.engine.core.utils.archivers.tar.CachedTar] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Tarball '/home/phillip/ovirt-engine/var/cache/ovirt-engine/ovirt-host-deploy.tar' refresh
2016-06-13 07:52:57,269 INFO  [org.ovirt.engine.core.uutils.ssh.SSHDialog] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] SSH execute 'root@192.168.1.12' 'umask 0077; MYTMP="$(TMPDIR="${OVIRT_TMPDIR}" mktemp -d -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; tar --warning=no-timestamp -C "${MYTMP}" -x &&  "${MYTMP}"/ovirt-host-deploy DIALOG/dialect=str:machine DIALOG/customization=bool:True'
2016-06-13 07:52:57,415 ERROR [org.ovirt.engine.core.bll.hostdeploy.VdsDeployBase] (VdsDeploy) [1a1eab5e] Error during deploy dialog: java.io.IOException: Unexpected connection termination
at org.ovirt.otopi.dialog.MachineDialogParser.nextEvent(MachineDialogParser.java:376) [otopi.jar:]
at org.ovirt.otopi.dialog.MachineDialogParser.nextEvent(MachineDialogParser.java:393) [otopi.jar:]
at org.ovirt.engine.core.bll.hostdeploy.VdsDeployBase.threadMain(VdsDeployBase.java:304) [bll.jar:]
at org.ovirt.engine.core.bll.hostdeploy.VdsDeployBase.lambda$new$148(VdsDeployBase.java:383) [bll.jar:]
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_71]

2016-06-13 07:52:57,416 ERROR [org.ovirt.engine.core.uutils.ssh.SSHDialog] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] SSH error running command root@192.168.1.12:'umask 0077; MYTMP="$(TMPDIR="${OVIRT_TMPDIR}" mktemp -d -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; tar --warning=no-timestamp -C "${MYTMP}" -x &&  "${MYTMP}"/ovirt-host-deploy DIALOG/dialect=str:machine DIALOG/customization=bool:True': Command returned failure code 1 during SSH session 'root@192.168.1.12'
2016-06-13 07:52:57,416 ERROR [org.ovirt.engine.core.uutils.ssh.SSHDialog] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Exception: java.io.IOException: Command returned failure code 1 during SSH session 'root@192.168.1.12'
at org.ovirt.engine.core.uutils.ssh.SSHClient.executeCommand(SSHClient.java:526) [uutils.jar:]
at org.ovirt.engine.core.uutils.ssh.SSHDialog.executeCommand(SSHDialog.java:317) [uutils.jar:]
at org.ovirt.engine.core.bll.hostdeploy.VdsDeployBase.execute(VdsDeployBase.java:563) [bll.jar:]
at org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand.installHost(InstallVdsInternalCommand.java:169) [bll.jar:]
at org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand.executeCommand(InstallVdsInternalCommand.java:90) [bll.jar:]
at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1304) [bll.jar:]
at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1446) [bll.jar:]
at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:2066) [bll.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:166) [utils.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1485) [bll.jar:]
at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:401) [bll.jar:]
at org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.executeValidatedCommand(PrevalidatingMultipleActionsRunner.java:198) [bll.jar:]
at org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.runCommands(PrevalidatingMultipleActionsRunner.java:170) [bll.jar:]
at org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.lambda$invokeCommands$49(PrevalidatingMultipleActionsRunner.java:176) [bll.jar:]
at org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:92) [utils.jar:]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_71]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_71]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_71]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_71]
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_71]

2016-06-13 07:52:57,425 ERROR [org.ovirt.engine.core.bll.hostdeploy.VdsDeployBase] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Error during host 192.168.1.12 install: java.io.IOException: Command returned failure code 1 during SSH session 'root@192.168.1.12'
at org.ovirt.engine.core.uutils.ssh.SSHClient.executeCommand(SSHClient.java:526) [uutils.jar:]
at org.ovirt.engine.core.uutils.ssh.SSHDialog.executeCommand(SSHDialog.java:317) [uutils.jar:]
at org.ovirt.engine.core.bll.hostdeploy.VdsDeployBase.execute(VdsDeployBase.java:563) [bll.jar:]
at org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand.installHost(InstallVdsInternalCommand.java:169) [bll.jar:]
at org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand.executeCommand(InstallVdsInternalCommand.java:90) [bll.jar:]
at org.ovirt.engine.core.bll.CommandBase.executeWithoutTransaction(CommandBase.java:1304) [bll.jar:]
at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:1446) [bll.jar:]
at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:2066) [bll.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:166) [utils.jar:]
at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105) [utils.jar:]
at org.ovirt.engine.core.bll.CommandBase.execute(CommandBase.java:1485) [bll.jar:]
at org.ovirt.engine.core.bll.CommandBase.executeAction(CommandBase.java:401) [bll.jar:]
at org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.executeValidatedCommand(PrevalidatingMultipleActionsRunner.java:198) [bll.jar:]
at org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.runCommands(PrevalidatingMultipleActionsRunner.java:170) [bll.jar:]
at org.ovirt.engine.core.bll.PrevalidatingMultipleActionsRunner.lambda$invokeCommands$49(PrevalidatingMultipleActionsRunner.java:176) [bll.jar:]
at org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil$InternalWrapperRunnable.run(ThreadPoolUtil.java:92) [utils.jar:]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [rt.jar:1.8.0_71]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [rt.jar:1.8.0_71]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [rt.jar:1.8.0_71]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [rt.jar:1.8.0_71]
at java.lang.Thread.run(Thread.java:745) [rt.jar:1.8.0_71]

2016-06-13 07:52:57,437 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Correlation ID: 1a1eab5e, Call Stack: null, Custom Event ID: -1, Message: Failed to install Host m2-h1. Command returned failure code 1 during SSH session 'root@192.168.1.12'.
2016-06-13 07:52:57,437 ERROR [org.ovirt.engine.core.bll.hostdeploy.VdsDeployBase] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Error during host 192.168.1.12 install, prefering first exception: Unexpected connection termination
2016-06-13 07:52:57,437 ERROR [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Host installation failed for host '244264be-4156-45a1-aed5-d05681303c07', 'm2-h1': Unexpected connection termination
2016-06-13 07:52:57,440 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] START, SetVdsStatusVDSCommand(HostName = m2-h1, SetVdsStatusVDSCommandParameters:{runAsync='true', hostId='244264be-4156-45a1-aed5-d05681303c07', status='InstallFailed', nonOperationalReason='NONE', stopSpmFailureLogged='false', maintenanceReason='null'}), log id: 706571c5
2016-06-13 07:52:57,445 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] FINISH, SetVdsStatusVDSCommand, log id: 706571c5
2016-06-13 07:52:57,462 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Correlation ID: 1a1eab5e, Call Stack: null, Custom Event ID: -1, Message: Host m2-h1 installation failed. Unexpected connection termination.
2016-06-13 07:52:57,462 INFO  [org.ovirt.engine.core.bll.hostdeploy.InstallVdsInternalCommand] (org.ovirt.thread.pool-8-thread-1) [1a1eab5e] Lock freed to object 'EngineLock:{exclusiveLocks='[244264be-4156-45a1-aed5-d05681303c07=<VDS, ACTION_TYPE_FAILED_OBJECT_LOCKED>]', sharedLocks='null'}'