Add basic logging to infer -- script

Summary:
@public
Add some logging to the script and capture modules so it is easier to troubleshoot.
What will be logged:
versions of infer, platform, versions of java, build systems etc.
In the future we will add more info that we might find useful while troubleshooting

Test Plan:
run infer with gradle, ant, buck, xcode, mvn and see the logging output

Run symbolic link pointing to infer:
  [INFO] Path to infer script /Users/akotulski/tmp/infer_link (/Users/akotulski/infer/infer/bin/infer)

infer/bin/infer

@@ -2,9 +2,12 @@
 
 import argparse
 import imp
+import utils
 import inferlib
+import logging
 import os
 import sys
+import platform
 
 CAPTURE_PACKAGE = 'capture'
 LIB_FOLDER = os.path.join(
@@ -28,6 +31,8 @@ MODULE_TO_COMMAND = {
     'mvn': ['mvn']
 }
 
+FORMAT = '[%(levelname)s] %(message)s'
+LOG_FILE = 'toplevel.log'
 
 def get_commands():
     """Return all commands that are supported."""
@@ -88,11 +93,17 @@ def create_argparser(parents=[]):
     return parser
 
 
-def main():
+def configure_logging(infer_dir, log_to_stderr):
-    if sys.version_info < (2, 7, 0):
+    if log_to_stderr:
-        print("You need python 2.7 or later to run this script")
+        logging.basicConfig(level=logging.INFO, format=FORMAT)
-        exit(1)
+    else:
+        logging.basicConfig(level=logging.INFO,
+                            format=FORMAT,
+                            filename=os.path.join(infer_dir, LOG_FILE),
+                            filemode='w')
+
 
+def main():
     to_parse, cmd = split_args_to_parse()
     # get the module name (if any), then load it
     capture_module_name = os.path.basename(cmd[0]) if len(cmd) > 0 else None
@@ -112,12 +123,28 @@ def main():
 
     args = global_argparser.parse_args(to_parse)
 
-    if imported_module:
+    if (imported_module and not args.incremental and
-        if capture_module_name != 'analyze' and not args.incremental:
+            capture_module_name != 'analyze'):
         inferlib.remove_infer_out(args.infer_out)
+
+    inferlib.create_results_dir(args.infer_out)
+
+    configure_logging(args.infer_out, args.log_to_stderr)
+    logging.info('Running command %s', ' '.join(sys.argv))
+    logging.info('Path to infer script %s (%s)', __file__,
+                 os.path.realpath(__file__))
+    logging.info(inferlib.get_infer_version())
+    logging.info('Platform: %s', platform.platform())
+    logging.info('PATH=%s', os.getenv('PATH'))
+    logging.info('SHELL=%s', os.getenv('SHELL'))
+    logging.info('PWD=%s', os.getenv('PWD'))
+
+    if imported_module:
         capture_exitcode = imported_module.gen_instance(args, cmd).capture()
         if capture_exitcode != os.EX_OK:
+            logging.error('Error during capture phase, exiting')
             exit(capture_exitcode)
+        logging.info('Capture phase was successful')
     elif capture_module_name is not None:
         # There was a command, but it's not supported
         print('Command "{cmd}" not recognised'.format(

infer/bin/inferlib.py

@@ -45,24 +45,27 @@ WARNING = 'WARNING'
 INFO = 'INFO'
 
 
+def get_infer_version():
+    try:
+        return subprocess.check_output([
+            utils.get_cmd_in_bin_dir(INFER_ANALYZE_BINARY), '-version'])
+    except:
+        print("Failed to run {0} binary, exiting".
+              format(INFER_ANALYZE_BINARY))
+        sys.exit(os.EX_UNAVAILABLE)
+
+
 # https://github.com/python/cpython/blob/aa8ea3a6be22c92e774df90c6a6ee697915ca8ec/Lib/argparse.py
 class VersionAction(argparse._VersionAction):
     def __call__(self, parser, namespace, values, option_string=None):
         # set self.version so that argparse version action knows it
-        self.version = self.get_infer_version()
+        self.version = get_infer_version()
         super(VersionAction, self).__call__(parser,
                                             namespace,
                                             values,
                                             option_string)
 
-    def get_infer_version(self):
+
-        try:
-            return subprocess.check_output([
-                utils.get_cmd_in_bin_dir(INFER_ANALYZE_BINARY), '-version'])
-        except:
-            print("Failed to run {0} binary, exiting".
-                  format(INFER_ANALYZE_BINARY))
-            exit(2)
 
 
 base_parser = argparse.ArgumentParser(add_help=False)
@@ -84,6 +87,10 @@ base_group.add_argument('-nf', '--no-filtering', action='store_true',
                         help='''Also show the results from the experimental
                         checks. Warning: some checks may contain many false
                         alarms''')
+
+base_group.add_argument('--log_to_stderr', action='store_true',
+                        help='''When set, all logging will go to stderr instead
+                        of log file''')
 base_parser.add_argument('-v', '--version', help='Get version of the analyzer',
                          action=VersionAction)
 
@@ -153,6 +160,18 @@ def remove_infer_out(infer_out):
     shutil.rmtree(infer_out, True)
 
 
+def mkdir_if_not_exists(path):
+    if not os.path.exists(path):
+        os.mkdir(path)
+
+
+def create_results_dir(results_dir):
+    mkdir_if_not_exists(results_dir)
+    mkdir_if_not_exists(os.path.join(results_dir, 'specs'))
+    mkdir_if_not_exists(os.path.join(results_dir, 'captured'))
+    mkdir_if_not_exists(os.path.join(results_dir, 'sources'))
+
+
 def clean_infer_out(infer_out):
 
     directories = ['multicore', 'classnames', 'sources']
@@ -399,6 +418,7 @@ class Infer:
             return javac_status
 
     def analyze(self):
+        logging.info('Starting analysis')
         infer_analyze = [
             utils.get_cmd_in_bin_dir(INFER_ANALYZE_BINARY),
             '-results_dir',
@@ -504,6 +524,9 @@ class Infer:
         captured_plural = '' if captured_total <= 1 else 's'
         print('\n%d file%s analyzed' % (captured_total, captured_plural))
 
+        logging.info('Analyzed file count: %d', captured_total)
+        logging.info('Analysis status: %d', exit_status)
+
         return exit_status
 
     def file_stats(self, file, stats):

infer/lib/capture/ant.py

@@ -1,4 +1,5 @@
 import os
+import logging
 import util
 
 MODULE_NAME = __name__
@@ -20,6 +21,8 @@ class AntCapture:
 
     def __init__(self, args, cmd):
         self.args = args
+        util.log_java_version()
+        logging.info(util.run_cmd_ignore_fail(['ant', '-version']))
         # TODO: make the extraction of targets smarter
         self.build_cmd = ['ant', '-verbose'] + cmd[1:]
 

infer/lib/capture/buck.py

@@ -3,6 +3,7 @@ import os
 import subprocess
 import traceback
 import util
+import logging
 
 import utils  # this is module located in ../utils.py
 
@@ -43,6 +44,9 @@ def create_argparser(group_name=MODULE_NAME):
 class BuckAnalyzer:
     def __init__(self, args, cmd):
         self.args = args
+        util.log_java_version()
+        logging.info(util.run_cmd_ignore_fail(['buck', '--version']))
+
         self.cmd = cmd[2:]  # TODO: make the extraction of targets smarter
 
     def capture(self):

infer/lib/capture/gradle.py

@@ -1,5 +1,7 @@
 import os
 import util
+import logging
+import subprocess
 
 MODULE_NAME = __name__
 MODULE_DESCRIPTION = '''Run analysis of code built with a command like:
@@ -24,6 +26,9 @@ class GradleCapture:
         self.args = args
         # TODO: make the extraction of targets smarter
         self.build_cmd = [cmd[0], '--debug'] + cmd[1:]
+        # That contains javac version as well
+        version_str = util.run_cmd_ignore_fail([cmd[0], '--version'])
+        logging.info("Running with:\n" + version_str)
 
     def get_inferJ_commands(self, verbose_output):
         argument_start_pattern = ' Compiler arguments: '

infer/lib/capture/make.py

@@ -21,10 +21,6 @@ def gen_instance(*args):
     return MakeCapture(*args)
 
 
-def mkdir_if_not_exists(path):
-    if not os.path.exists(path):
-        os.mkdir(path)
-
 create_argparser = \
     util.clang_frontend_argparser(MODULE_DESCRIPTION, MODULE_NAME)
 
@@ -34,13 +30,6 @@ class MakeCapture:
         self.args = args
         self.cmd = [os.path.basename(cmd[0])] + cmd[1:]
 
-    def create_results_dir(self):
-        results_dir = self.args.infer_out
-        mkdir_if_not_exists(results_dir)
-        mkdir_if_not_exists(os.path.join(results_dir, 'specs'))
-        mkdir_if_not_exists(os.path.join(results_dir, 'captured'))
-        mkdir_if_not_exists(os.path.join(results_dir, 'sources'))
-
     def get_envvars(self):
         env_vars = dict(os.environ)
         wrappers_path = os.path.join(
@@ -58,8 +47,6 @@ class MakeCapture:
         return env_vars
 
     def capture(self):
-        self.create_results_dir()
-
         try:
             subprocess.check_call(self.cmd, env=self.get_envvars())
             return os.EX_OK

infer/lib/capture/mvn.py

@@ -3,6 +3,7 @@
 #
 
 import os
+import logging
 import re
 import util
 
@@ -24,6 +25,7 @@ create_argparser = util.base_argparser(MODULE_DESCRIPTION, MODULE_NAME)
 class MavenCapture:
     def __init__(self, args, cmd):
         self.args = args
+        logging.info(util.run_cmd_ignore_fail(['mvn', '-version']))
         # TODO: make the extraction of targets smarter
         self.build_cmd = ['mvn', '-X'] + cmd[1:]
 

infer/lib/capture/util.py

@@ -5,8 +5,10 @@
 
 import argparse
 import os
+import logging
 import subprocess
 import inferlib
+import traceback
 
 
 def create_inferJ_command(args, javac_arguments):
@@ -36,6 +38,21 @@ def run_commands(cmds):
     return os.EX_OK
 
 
+def run_cmd_ignore_fail(cmd):
+    try:
+        return subprocess.check_output(cmd, stderr=subprocess.STDOUT)
+    except:
+        return 'calling {cmd} failed\n{trace}'.format(
+            cmd=' '.join(cmd),
+            trace=traceback.format_exc())
+
+
+def log_java_version():
+    java_version = run_cmd_ignore_fail(['java', '-version'])
+    javac_version = run_cmd_ignore_fail(['javac', '-version'])
+    logging.info("java versions:\n%s%s", java_version, javac_version)
+
+
 def base_argparser(description, module_name):
     def _func(group_name=module_name):
         """This creates an empty argparser for the module, which provides only

infer/lib/capture/xcodebuild.py

@@ -1,6 +1,7 @@
 import os
 import subprocess
 import traceback
+import logging
 import util
 
 MODULE_NAME = __name__
@@ -32,15 +33,22 @@ create_argparser = \
 class XcodebuildCapture:
     def __init__(self, args, cmd):
         self.args = args
+        self.apple_clang_path = \
+            subprocess.check_output(['xcrun', '--find', 'clang']).strip()
+
+        xcode_version = util.run_cmd_ignore_fail(['xcodebuild', '-version'])
+        apple_clang_version = util.run_cmd_ignore_fail([self.apple_clang_path,
+                                                        '--version'])
+        logging.info('Xcode version:\n%s', xcode_version)
+
+        logging.info('clang version:\n%s', apple_clang_version)
+
         self.cmd = cmd
 
     def get_envvars(self):
         env_vars = dict(os.environ)
 
-        apple_clang_path = \
+        env_vars['FCP_APPLE_CLANG'] = self.apple_clang_path
-            subprocess.check_output(['xcrun', '--find', 'clang']).strip()
-
-        env_vars['FCP_APPLE_CLANG'] = apple_clang_path
 
         frontend_env_vars = \
             util.get_clang_frontend_envvars(self.args)