Bug 1331579

Summary:	SSHCommand output logged twice to OpenStack deployment.log
Product:	Red Hat Quickstart Cloud Installer	Reporter:	Tasos Papaioannou <tpapaioa>
Component:	Installation - RHELOSP	Assignee:	Jesus M. Rodriguez <jesusr>
Status:	CLOSED ERRATA	QA Contact:	Tasos Papaioannou <tpapaioa>
Severity:	low	Docs Contact:	Dan Macpherson <dmacpher>
Priority:	unspecified
Version:	1.0	CC:	bthurber, jesusr, jmatthew
Target Milestone:	ga	Keywords:	Triaged
Target Release:	1.0
Hardware:	All
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2016-09-13 16:28:58 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	1342594

Description Tasos Papaioannou 2016-04-28 21:00:28 UTC

Description of problem:

The result of each ssh command is logged twice to the deployment log, during an OpenStack deployment. Example output:

****
# Logfile created on 2016-04-28 15:26:47 -0400 by logger.rb/31641

2016-04-28 15:36:51 [D] filtering by deployment_id AND by source: added

2016-04-28 15:37:27 [D] setting provider url to []

2016-04-28 15:37:27 [D] provider url https://cdn.redhat.com

2016-04-28 15:37:27 [D] with no upstream_consumer: /usr/share/foreman/tmp/import_123b48e5caee6fe10671.zip

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_CloudForms_Management_Engine_5_5_Files_x86_64

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Enterprise_Linux_7_Server_Kickstart_x86_64_7_1

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Enterprise_Linux_7_Server_RPMs_x86_64_7Server

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Enterprise_Linux_7_Server_-_Extras_RPMs_x86_64

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Enterprise_Linux_7_Server_-_Optional_RPMs_x86_64_7Server

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Enterprise_Linux_7_Server_-_RH_Common_RPMs_x86_64_7Server

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Enterprise_Linux_OpenStack_Platform_7_0_for_RHEL_7_RPMs_x86_64_7Server

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Enterprise_Linux_OpenStack_Platform_7_0_director_for_RHEL_7_RPMs_x86_64_7Server

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Enterprise_Linux_OpenStack_Platform_7_0_for_RHEL_7_Files_x86_64_7Server

2016-04-28 15:38:55 [I] Planning to sync Red_Hat_Software_Collections_RPMs_for_Red_Hat_Enterprise_Linux_7_Server_x86_64_7Server

2016-04-28 16:53:58 [D] ================ TransferConsumerRpm run method ====================

2016-04-28 16:53:58 [D] ================ SshCommand run method ====================

2016-04-28 16:54:00 [I] Command succeeded: sudo sed -i "s/OVERCLOUD_ADMIN_PASSWORD.*/OVERCLOUD_ADMIN_PASSWORD=changeme/g" /home/stack/tripleo-overcloud-passwords

2016-04-28 16:54:00 [I] Command succeeded: sudo sed -i "s/OVERCLOUD_ADMIN_PASSWORD.*/OVERCLOUD_ADMIN_PASSWORD=changeme/g" /home/stack/tripleo-overcloud-passwords

2016-04-28 16:54:00 [D] ================ Leaving SshCommand run method ====================

2016-04-28 16:54:00 [D] ================ Leaving TransferConsumerRpm run method ====================

2016-04-28 16:54:00 [D] ====== UndercloudNoHostWorkaround run method ======

2016-04-28 16:54:00 [D] ================ SshCommand run method ====================

2016-04-28 16:54:09 [I] Command succeeded: sudo yum -y localinstall /tmp/katello-ca-consumer-latest.noarch.rpm

2016-04-28 16:54:09 [I] Command succeeded: sudo yum -y localinstall /tmp/katello-ca-consumer-latest.noarch.rpm

2016-04-28 16:54:09 [D] ================ Leaving SshCommand run method ====================

2016-04-28 16:54:11 [D] ================ SshCommand run method ====================

2016-04-28 16:54:14 [I] Command succeeded: sudo subscription-manager register --org Default_Organization --activationkey OpenStack_Undercloud-tpapiaoa_20160428_b-OpenStack_Undercloud

2016-04-28 16:54:14 [I] Command succeeded: sudo subscription-manager register --org Default_Organization --activationkey OpenStack_Undercloud-tpapiaoa_20160428_b-OpenStack_Undercloud

2016-04-28 16:54:14 [D] ================ Leaving SshCommand run method ====================

2016-04-28 16:54:15 [D] ================ SshCommand run method ====================

2016-04-28 16:54:15 [D] === Leaving UndercloudNoHostWorkaround run method ===

2016-04-28 16:54:16 [I] Command succeeded: sudo yum -y install katello-agent

2016-04-28 16:54:16 [I] Command succeeded: sudo yum -y install katello-agent

2016-04-28 16:54:16 [D] ================ Leaving SshCommand run method ====================
****

Version-Release number of selected component (if applicable):

QCI-1.1-RHEL-7-20160428.t.0

How reproducible:

100%

Steps to Reproduce:
1.) Deploy OpenStack.
2.) View deployment log, see all SSHCommand results logged twice.


Actual results:

Duplicate logging in deployment.log

Expected results:

No duplicate logging

Additional info:

Comment 1 Jesus M. Rodriguez 2016-07-08 20:16:31 UTC

Totally see why this is happening. We're calling call_complete twice:

https://github.com/fusor/fusor/blob/master/server/app/lib/utils/fusor/ssh_connection.rb#L102

https://github.com/fusor/fusor/blob/master/server/app/lib/utils/fusor/ssh_connection.rb#L108

Need to investigate if anyone is counting on this. Whether we fix it in ssh_connection or within the implementor of the callback methods.

Comment 2 Jesus M. Rodriguez 2016-07-15 03:57:38 UTC

https://github.com/fusor/fusor/pull/1044

Comment 3 John Matthews 2016-07-18 21:13:58 UTC

QCI-1.2-RHEL-7-20160718.t.0

Comment 8 Tasos Papaioannou 2016-07-22 18:18:32 UTC

Verified on QCI-1.2-RHEL-7-20160720.t.0.

Comment 10 errata-xmlrpc 2016-09-13 16:28:58 UTC

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHEA-2016:1862