Bug 1331579

Summary: SSHCommand output logged twice to OpenStack deployment.log
Product: Red Hat Quickstart Cloud Installer Reporter: Tasos Papaioannou <tpapaioa>
Component: Installation - RHELOSPAssignee: Jesus M. Rodriguez <jesusr>
Status: CLOSED ERRATA QA Contact: Tasos Papaioannou <tpapaioa>
Severity: low Docs Contact: Dan Macpherson <dmacpher>
Priority: unspecified    
Version: 1.0CC: bthurber, jesusr, jmatthew
Target Milestone: gaKeywords: 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:
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