macOS Signing Scripts: Use the logging module rather than print().

The Python logger module will record the timing information for
messages, which will be useful to track how long notarization takes.

This also links the stdout and stderr streams, so that any output does
not get improperly interleaved due to buffering or issues with the log
collector.

Change-Id: I7c52f20e2dc439c13c1b13a15f8912a56e180e97
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1900210Reviewed-by: Mark Mentovai <mark@chromium.org>
Commit-Queue: Robert Sesek <rsesek@chromium.org>
Cr-Commit-Position: refs/heads/master@{#712998}

chrome/installer/mac/sign_chrome.py

@@ -4,7 +4,7 @@
 # found in the LICENSE file.
 
 import argparse
-import os.path
+import os
 import sys
 
 sys.path.append(os.path.dirname(__file__))
@@ -12,6 +12,19 @@ sys.path.append(os.path.dirname(__file__))
 from signing import config, model, pipeline
 
 
+def _link_stdout_and_stderr():
+    """This script's output is entirely log messages and debugging information,
+    so there is not a useful distinction between stdout and stderr. Because some
+    subcommands this script runs output to one stream or the other, link the
+    two streams so that any buffering done by Python, or the invoker of this
+    script, does not get incorrectly interleaved.
+    """
+    stdout_fileno = sys.stdout.fileno()
+    sys.stdout.close()
+    sys.stdout = sys.stderr
+    os.dup2(sys.stderr.fileno(), stdout_fileno)
+
+
 def create_config(config_args, development):
     """Creates the |model.CodeSignConfig| for the signing operations.
 
@@ -126,6 +139,8 @@ def main():
         'Apple for notarization.')
     group.add_argument('--no-notarize', dest='notarize', action='store_false')
 
+    _link_stdout_and_stderr()
+
     parser.set_defaults(notarize=False)
     args = parser.parse_args()
 

chrome/installer/mac/signing/__init__.py

+# Copyright 2019 The Chromium Authors. All rights reserved.
+# Use of this source code is governed by a BSD-style license that can be
+# found in the LICENSE file.
+
+import logging
+
+logger = logging.getLogger(__name__)
+_handler = logging.StreamHandler()
+_formatter = logging.Formatter(
+    '[%(asctime)s/%(levelname)s/%(filename)s:%(lineno)d] %(message)s')
+_handler.setFormatter(_formatter)
+logger.addHandler(_handler)
+logger.setLevel(logging.DEBUG)

chrome/installer/mac/signing/commands.py

@@ -11,6 +11,8 @@ import shutil
 import subprocess
 import tempfile
 
+from . import logger
+
 
 def file_exists(path):
     return os.path.exists(path)
@@ -62,12 +64,12 @@ def write_file(path, contents):
 
 
 def run_command(args, **kwargs):
-    print('Running command: {}'.format(args))
+    logger.info('Running command: %s', args)
     subprocess.check_call(args, **kwargs)
 
 
 def run_command_output(args, **kwargs):
-    print('Running command: {}'.format(args))
+    logger.info('Running command: %s', args)
     return subprocess.check_output(args, **kwargs)
 
 

chrome/installer/mac/signing/notarize.py

@@ -10,7 +10,7 @@ import plistlib
 import subprocess
 import time
 
-from . import commands
+from . import commands, logger
 
 # python2 support.
 if not hasattr(plistlib, 'loads'):
@@ -44,7 +44,7 @@ def submit(path, config):
     output = commands.run_command_output(command)
     plist = plistlib.loads(output)
     uuid = plist['notarization-upload']['RequestUUID']
-    print('Submitted {} for notarization, request UUID: {}.'.format(path, uuid))
+    logger.info('Submitted %s for notarization, request UUID: %s.', path, uuid)
     return uuid
 
 
@@ -102,13 +102,14 @@ def wait_for_results(uuids, config):
             if status == 'in progress':
                 continue
             elif status == 'success':
-                print('Successfully notarized request {}. Log file: {}'.format(
-                    uuid, info[_LOG_FILE_URL]))
+                logger.info('Successfully notarized request %s. Log file: %s',
+                            uuid, info[_LOG_FILE_URL])
                 wait_set.remove(uuid)
                 yield uuid
             else:
-                print('Failed to notarize request {}. Log file: {}. Output:\n{}'
-                      .format(uuid, info[_LOG_FILE_URL], output))
+                logger.error(
+                    'Failed to notarize request %s. Log file: %s. Output:\n%s',
+                    uuid, info[_LOG_FILE_URL], output)
                 raise NotarizationError(
                     'Notarization request {} failed with status: "{}". '
                     'Log file: {}.'.format(uuid, status, info[_LOG_FILE_URL]))