Improve logs from ansible, puppet, docker-puppet.py

* Debug ansible 'puppet apply' stderr joined stdout, split
  by lines.
* Do 'puppet apply' w/o colors, logdest syslog, and given a wanted
  modulepath instead of the module puppet, that can't support those
  options.
* Bind-mount syslog socket for docker-puppet.py to pass puppet logs
  to host OS syslog.
* Fix logging handlers for multiprocess workers in docker-puppet.py.

Related-bug: #1698172
Closes-bug: #1700086

Change-Id: I84112a836e968aa5c3596a6544e0392980529963
Signed-off-by: Bogdan Dobrelya <bdobreli@redhat.com>

2 files changed, 63 insertions, 18 deletions

diff --git a/docker/deploy-steps-playbook.yaml b/docker/deploy-steps-playbook.yaml
index 87587a4b..446c73a6 100644
--- a/docker/deploy-steps-playbook.yaml
+++ b/docker/deploy-steps-playbook.yaml
@@ -7,9 +7,19 @@
     - name: Write the config_step hieradata
       copy: content="{{dict(step=step|int)|to_json}}" dest=/etc/puppet/hieradata/config_step.json force=true
     - name: Run puppet host configuration for step {{step}}
-      # FIXME: modulepath requires ansible 2.4, our builds currently only have 2.3
-      # puppet: manifest=/var/lib/tripleo-config/puppet_step_config.pp modulepath=/etc/puppet/modules:/opt/stack/puppet-modules:/usr/share/openstack-puppet/modules
-      puppet: manifest=/var/lib/tripleo-config/puppet_step_config.pp
+      command: >-
+        puppet apply
+        --modulepath=/etc/puppet/modules:/opt/stack/puppet-modules:/usr/share/openstack-puppet/modules
+        --logdest syslog --color=false
+        /var/lib/tripleo-config/puppet_step_config.pp
+      changed_when: false
+      check_mode: no
+      register: outputs
+      failed_when: false
+      no_log: true
+    - debug: var=(outputs.stderr|default('')).split('\n')|union(outputs.stdout_lines|default([]))
+      when: outputs is defined
+      failed_when: outputs|failed
     ######################################
     # Generate config via docker-puppet.py
     ######################################
@@ -21,6 +31,12 @@
       when: step == "1"
       changed_when: false
       check_mode: no
+      register: outputs
+      failed_when: false
+      no_log: true
+    - debug: var=(outputs.stderr|default('')).split('\n')|union(outputs.stdout_lines|default([]))
+      when: outputs is defined
+      failed_when: outputs|failed
     ##################################################
     # Per step starting of the containers using paunch
     ##################################################
@@ -32,10 +48,19 @@
     # the *step_n.json with a hash of the generated external config added
     # This acts as a salt to enable restarting the container if config changes
     - name: Start containers for step {{step}}
-      command: paunch --debug apply --file /var/lib/tripleo-config/hashed-docker-container-startup-config-step_{{step}}.json --config-id tripleo_step{{step}} --managed-by tripleo-{{role_name}}
+      command: >-
+        paunch --debug apply
+        --file /var/lib/tripleo-config/hashed-docker-container-startup-config-step_{{step}}.json
+        --config-id tripleo_step{{step}} --managed-by tripleo-{{role_name}}
       when: docker_config_json.stat.exists
       changed_when: false
       check_mode: no
+      register: outputs
+      failed_when: false
+      no_log: true
+    - debug: var=(outputs.stderr|default('')).split('\n')|union(outputs.stdout_lines|default([]))
+      when: outputs is defined
+      failed_when: outputs|failed
     ########################################################
     # Bootstrap tasks, only performed on bootstrap_server_id
     ########################################################
@@ -49,3 +74,9 @@
       when: deploy_server_id == bootstrap_server_id
       changed_when: false
       check_mode: no
+      register: outputs
+      failed_when: false
+      no_log: true
+    - debug: var=(outputs.stderr|default('')).split('\n')|union(outputs.stdout_lines|default([]))
+      when: outputs is defined
+      failed_when: outputs|failed
diff --git a/docker/docker-puppet.py b/docker/docker-puppet.py
index 65d3bf38..e2c5f24f 100755
--- a/docker/docker-puppet.py
+++ b/docker/docker-puppet.py
@@ -28,17 +28,25 @@ import sys
 import tempfile
 import multiprocessing
 
-log = logging.getLogger()
-ch = logging.StreamHandler(sys.stdout)
-if os.environ.get('DEBUG', False):
-    log.setLevel(logging.DEBUG)
-    ch.setLevel(logging.DEBUG)
-else:
-    log.setLevel(logging.INFO)
-    ch.setLevel(logging.INFO)
-formatter = logging.Formatter('%(asctime)s %(levelname)s: %(message)s')
-ch.setFormatter(formatter)
-log.addHandler(ch)
+logger = None
+
+def get_logger():
+    global logger
+    if logger is None:
+        logger = logging.getLogger()
+        ch = logging.StreamHandler(sys.stdout)
+        if os.environ.get('DEBUG', False):
+            logger.setLevel(logging.DEBUG)
+            ch.setLevel(logging.DEBUG)
+        else:
+            logger.setLevel(logging.INFO)
+            ch.setLevel(logging.INFO)
+        formatter = logging.Formatter('%(asctime)s %(levelname)s: '
+                                      '%(process)s -- %(message)s')
+        ch.setFormatter(formatter)
+        logger.addHandler(ch)
+    return logger
+
 
 # this is to match what we do in deployed-server
 def short_hostname():
@@ -109,7 +117,7 @@ def rm_container(name):
 
 process_count = int(os.environ.get('PROCESS_COUNT',
                                    multiprocessing.cpu_count()))
-
+log = get_logger()
 log.info('Running docker-puppet')
 config_file = os.environ.get('CONFIG', '/var/lib/docker-puppet/docker-puppet.json')
 log.debug('CONFIG: %s' % config_file)
@@ -174,7 +182,8 @@ for service in (json_data or []):
 log.info('Service compilation completed.')
 
 def mp_puppet_config((config_volume, puppet_tags, manifest, config_image, volumes)):
-
+    log = get_logger()
+    log.info('Started processing puppet configs')
     log.debug('config_volume %s' % config_volume)
     log.debug('puppet_tags %s' % puppet_tags)
     log.debug('manifest %s' % manifest)
@@ -201,7 +210,8 @@ def mp_puppet_config((config_volume, puppet_tags, manifest, config_image, volume
         touch /tmp/the_origin_of_time
         sync
 
-        FACTER_hostname=$HOSTNAME FACTER_uuid=docker /usr/bin/puppet apply --verbose $TAGS /etc/config.pp
+        FACTER_hostname=$HOSTNAME FACTER_uuid=docker /usr/bin/puppet apply \
+        --color=false --logdest syslog $TAGS /etc/config.pp
 
         # Disables archiving
         if [ -z "$NO_ARCHIVE" ]; then
@@ -248,6 +258,8 @@ def mp_puppet_config((config_volume, puppet_tags, manifest, config_image, volume
                 '--volume', '/usr/share/openstack-puppet/modules/:/usr/share/openstack-puppet/modules/:ro',
                 '--volume', '/var/lib/config-data/:/var/lib/config-data/:rw',
                 '--volume', 'tripleo_logs:/var/log/tripleo/',
+                # Syslog socket for puppet logs
+                '--volume', '/dev/log:/dev/log',
                 # OpenSSL trusted CA injection
                 '--volume', '/etc/pki/ca-trust/extracted:/etc/pki/ca-trust/extracted:ro',
                 '--volume', '/etc/pki/tls/certs/ca-bundle.crt:/etc/pki/tls/certs/ca-bundle.crt:ro',
@@ -291,6 +303,8 @@ def mp_puppet_config((config_volume, puppet_tags, manifest, config_image, volume
                 log.debug(cmd_stderr)
             # only delete successful runs, for debugging
             rm_container('docker-puppet-%s' % config_volume)
+
+        log.info('Finished processing puppet configs')
         return subproc.returncode
 
 # Holds all the information for each process to consume.