chiark / gitweb /
Merge branch 'master' into logging
[fdroidserver.git] / fdroidserver / build.py
index c60069d5d811adebf44fefb34fa3cd35ebdf1d4e..bdf54ed2db63c4aa96d296539e7114f4cfa01d5e 100644 (file)
@@ -29,6 +29,7 @@ import time
 import json
 from ConfigParser import ConfigParser
 from optparse import OptionParser, OptionError
+import logging
 
 import common, metadata
 from common import BuildException, VCSException, FDroidPopen
@@ -71,12 +72,8 @@ def vagrant(params, cwd=None, printout=False):
     :returns: (ret, out) where ret is the return code, and out
                is the stdout (and stderr) from vagrant
     """
-    p = subprocess.Popen(['vagrant'] + params, cwd=cwd,
-            stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
-    out = p.communicate()[0]
-    if options.verbose:
-        print out
-    return (p.returncode, out)
+    p = FDroidPopen(['vagrant'] + params, cwd=cwd)
+    return (p.returncode, p.stdout)
 
 
 # Note that 'force' here also implies test mode.
@@ -88,52 +85,47 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
     # Reset existing builder machine to a clean state if possible.
     vm_ok = False
     if not options.resetserver:
-        print "Checking for valid existing build server"
+        logging.info("Checking for valid existing build server")
+
         if got_valid_builder_vm():
-            print "...VM is present"
-            p = subprocess.Popen(['VBoxManage', 'snapshot', get_builder_vm_id(), 'list', '--details'],
-                cwd='builder', stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
-            output = p.communicate()[0]
-            if 'fdroidclean' in output:
-                if options.verbose:
-                    print "...snapshot exists - resetting build server to clean state"
+            logging.info("...VM is present")
+            p = FDroidPopen(['VBoxManage', 'snapshot', get_builder_vm_id(), 'list', '--details'], cwd='builder')
+            if 'fdroidclean' in p.stdout:
+                logging.info("...snapshot exists - resetting build server to clean state")
                 retcode, output = vagrant(['status'], cwd='builder')
+
                 if 'running' in output:
-                    if options.verbose:
-                        print "...suspending"
+                    logging.info("...suspending")
                     vagrant(['suspend'], cwd='builder')
-                    print "...waiting a sec..."
+                    logging.info("...waiting a sec...")
                     time.sleep(10)
-                p = subprocess.Popen(['VBoxManage', 'snapshot', get_builder_vm_id(), 'restore', 'fdroidclean'],
-                    cwd='builder', stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
-                output = p.communicate()[0]
-                if options.verbose:
-                    print output
+                p = FDroidPopen(['VBoxManage', 'snapshot', get_builder_vm_id(), 'restore', 'fdroidclean'],
+                    cwd='builder')
+
                 if p.returncode == 0:
-                    print "...reset to snapshot - server is valid"
+                    logging.info("...reset to snapshot - server is valid")
                     retcode, output = vagrant(['up'], cwd='builder')
                     if retcode != 0:
                         raise BuildException("Failed to start build server")
-                    print "...waiting a sec..."
+                    logging.info("...waiting a sec...")
                     time.sleep(10)
                     vm_ok = True
                 else:
-                    print "...failed to reset to snapshot"
+                    logging.info("...failed to reset to snapshot")
             else:
-                print "...snapshot doesn't exist - VBoxManage snapshot list:\n" + output
+                logging.info("...snapshot doesn't exist - VBoxManage snapshot list:\n" + output)
 
     # If we can't use the existing machine for any reason, make a
     # new one from scratch.
     if not vm_ok:
         if os.path.exists('builder'):
-            print "Removing broken/incomplete/unwanted build server"
+            logging.info("Removing broken/incomplete/unwanted build server")
             vagrant(['destroy', '-f'], cwd='builder')
             shutil.rmtree('builder')
         os.mkdir('builder')
 
-        p = subprocess.Popen('vagrant --version', shell=True, stdout=subprocess.PIPE)
-        vver = p.communicate()[0]
-        if vver.startswith('Vagrant version 1.2'):
+        p = FDroidPopen('vagrant --version', shell=True, stdout=subprocess.PIPE)
+        if p.stdout.startswith('Vagrant version 1.2'):
             with open('builder/Vagrantfile', 'w') as vf:
                 vf.write('Vagrant.configure("2") do |config|\n')
                 vf.write('config.vm.box = "buildserver"\n')
@@ -144,13 +136,13 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
                 vf.write('config.vm.box = "buildserver"\n')
                 vf.write('end\n')
 
-        print "Starting new build server"
+        logging.info("Starting new build server")
         retcode, _ = vagrant(['up'], cwd='builder')
         if retcode != 0:
             raise BuildException("Failed to start build server")
 
         # Open SSH connection to make sure it's working and ready...
-        print "Connecting to virtual machine..."
+        logging.info("Connecting to virtual machine...")
         if subprocess.call('vagrant ssh-config >sshconfig',
                 cwd='builder', shell=True) != 0:
             raise BuildException("Error getting ssh config")
@@ -170,38 +162,34 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
             key_filename=idfile)
         sshs.close()
 
-        print "Saving clean state of new build server"
+        logging.info("Saving clean state of new build server")
         retcode, _ = vagrant(['suspend'], cwd='builder')
         if retcode != 0:
             raise BuildException("Failed to suspend build server")
-        print "...waiting a sec..."
+        logging.info("...waiting a sec...")
         time.sleep(10)
-        p = subprocess.Popen(['VBoxManage', 'snapshot', get_builder_vm_id(), 'take', 'fdroidclean'],
-                cwd='builder', stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
-        output = p.communicate()[0]
+        p = FDroidPopen(['VBoxManage', 'snapshot', get_builder_vm_id(), 'take', 'fdroidclean'],
+                cwd='builder')
         if p.returncode != 0:
-            print output
             raise BuildException("Failed to take snapshot")
-        print "...waiting a sec..."
+        logging.info("...waiting a sec...")
         time.sleep(10)
-        print "Restarting new build server"
+        logging.info("Restarting new build server")
         retcode, _ = vagrant(['up'], cwd='builder')
         if retcode != 0:
             raise BuildException("Failed to start build server")
-        print "...waiting a sec..."
+        logging.info("...waiting a sec...")
         time.sleep(10)
         # Make sure it worked...
-        p = subprocess.Popen(['VBoxManage', 'snapshot', get_builder_vm_id(), 'list', '--details'],
-            cwd='builder', stdout=subprocess.PIPE, stderr=subprocess.STDOUT)
-        output = p.communicate()[0]
-        if 'fdroidclean' not in output:
+        p = FDroidPopen(['VBoxManage', 'snapshot', get_builder_vm_id(), 'list', '--details'],
+            cwd='builder')
+        if 'fdroidclean' not in p.stdout:
             raise BuildException("Failed to take snapshot.")
 
     try:
 
         # Get SSH configuration settings for us to connect...
-        if options.verbose:
-            print "Getting ssh configuration..."
+        logging.info("Getting ssh configuration...")
         subprocess.call('vagrant ssh-config >sshconfig',
                 cwd='builder', shell=True)
         vagranthost = 'default' # Host in ssh config file
@@ -214,8 +202,7 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
         sshconfig = sshconfig.lookup(vagranthost)
 
         # Open SSH connection...
-        if options.verbose:
-            print "Connecting to virtual machine..."
+        logging.info("Connecting to virtual machine...")
         sshs = ssh.SSHClient()
         sshs.set_missing_host_key_policy(ssh.AutoAddPolicy())
         idfile = sshconfig['identityfile']
@@ -251,7 +238,7 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
                     ftp.chdir('..')
             ftp.chdir('..')
 
-        print "Preparing server for build..."
+        logging.info("Preparing server for build...")
         serverpath = os.path.abspath(os.path.dirname(__file__))
         ftp.put(os.path.join(serverpath, 'build.py'), 'build.py')
         ftp.put(os.path.join(serverpath, 'common.py'), 'common.py')
@@ -303,8 +290,7 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
         if basesrclib:
             srclibpaths.append(basesrclib)
         for name, number, lib in srclibpaths:
-            if options.verbose:
-                print "Sending srclib '" + lib + "'"
+            logging.info("Sending srclib '%s'" % lib)
             ftp.chdir('/home/vagrant/build/srclib')
             if not os.path.exists(lib):
                 raise BuildException("Missing srclib directory '" + lib + "'")
@@ -324,7 +310,7 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
             send_dir(build_dir)
 
         # Execute the build script...
-        print "Starting build..."
+        logging.info("Starting build...")
         chan = sshs.get_transport().open_session()
         chan.get_pty()
         cmdline = 'python build.py --on-server'
@@ -339,7 +325,7 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
             while chan.recv_ready():
                 output += chan.recv(1024)
             time.sleep(0.1)
-        print "...getting exit status"
+        logging.info("...getting exit status")
         returncode = chan.recv_exit_status()
         while True:
             get = chan.recv(1024)
@@ -350,7 +336,7 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
             raise BuildException("Build.py failed on server for %s:%s" % (app['id'], thisbuild['version']), output)
 
         # Retrieve the built files...
-        print "Retrieving build output..."
+        logging.info("Retrieving build output...")
         if force:
             ftp.chdir('/home/vagrant/tmp')
         else:
@@ -368,15 +354,14 @@ def build_server(app, thisbuild, vcs, build_dir, output_dir, force):
     finally:
 
         # Suspend the build server.
-        print "Suspending build server"
+        logging.info("Suspending build server")
         subprocess.call(['vagrant', 'suspend'], cwd='builder')
 
 def adapt_gradle(build_dir):
     for root, dirs, files in os.walk(build_dir):
         if 'build.gradle' in files:
             path = os.path.join(root, 'build.gradle')
-            if options.verbose:
-                print "Adapting build.gradle at %s" % path
+            logging.info("Adapting build.gradle at %s" % path)
 
             subprocess.call(['sed', '-i',
                     r's@buildToolsVersion\([ =]*\)["\'][0-9\.]*["\']@buildToolsVersion\1"'
@@ -394,7 +379,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
     # different from the default ones
     p = None
     if thisbuild['type'] == 'maven':
-        print "Cleaning Maven project..."
+        logging.info("Cleaning Maven project...")
         cmd = [config['mvn3'], 'clean', '-Dandroid.sdk.path=' + config['sdk_path']]
 
         if '@' in thisbuild['maven']:
@@ -407,7 +392,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
 
     elif thisbuild['type'] == 'gradle':
 
-        print "Cleaning Gradle project..."
+        logging.info("Cleaning Gradle project...")
         cmd = [config['gradle'], 'clean']
 
         if '@' in thisbuild['gradle']:
@@ -426,7 +411,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
         pass
 
     elif thisbuild['type'] == 'ant':
-        print "Cleaning Ant project..."
+        logging.info("Cleaning Ant project...")
         p = FDroidPopen(['ant', 'clean'], cwd=root_dir)
 
     if p is not None and p.returncode != 0:
@@ -434,19 +419,19 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
                 (app['id'], thisbuild['version']), p.stdout)
 
     # Scan before building...
-    print "Scanning source for common problems..."
+    logging.info("Scanning source for common problems...")
     buildprobs = common.scan_source(build_dir, root_dir, thisbuild)
     if len(buildprobs) > 0:
-        print 'Scanner found ' + str(len(buildprobs)) + ' problems:'
+        logging.info('Scanner found %d problems:' % len(buildprobs))
         for problem in buildprobs:
-            print '    %s' % problem
+            logging.info('    %s' % problem)
         if not force:
             raise BuildException("Can't build due to " +
                 str(len(buildprobs)) + " scanned problems")
 
     if not options.notarball:
         # Build the source tarball right before we build the release...
-        print "Creating source tarball..."
+        logging.info("Creating source tarball...")
         tarname = common.getsrcname(app,thisbuild)
         tarball = tarfile.open(os.path.join(tmp_dir, tarname), "w:gz")
         def tarexc(f):
@@ -461,8 +446,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
         for name, number, libpath in srclibpaths:
             libpath = os.path.relpath(libpath, root_dir)
             cmd = cmd.replace('$$' + name + '$$', libpath)
-        if options.verbose:
-            print "Running 'build' commands in %s" % root_dir
+        logging.info("Running 'build' commands in %s" % root_dir)
 
         p = FDroidPopen(['bash', '-x', '-c', cmd], cwd=root_dir)
 
@@ -472,7 +456,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
 
     # Build native stuff if required...
     if thisbuild.get('buildjni') not in (None, 'no'):
-        print "Building native libraries..."
+        logging.info("Building native libraries...")
         jni_components = thisbuild.get('buildjni')
         if jni_components == 'yes':
             jni_components = ['']
@@ -480,8 +464,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
             jni_components = [c.strip() for c in jni_components.split(';')]
         ndkbuild = os.path.join(config['ndk_path'], "ndk-build")
         for d in jni_components:
-            if options.verbose:
-                print "Running ndk-build in " + root_dir + '/' + d
+            logging.info("Building native code in '%s'" % d)
             manifest = root_dir + '/' + d + '/AndroidManifest.xml'
             if os.path.exists(manifest):
                 # Read and write the whole AM.xml to fix newlines and avoid
@@ -500,7 +483,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
     p = None
     # Build the release...
     if thisbuild['type'] == 'maven':
-        print "Building Maven project..."
+        logging.info("Building Maven project...")
 
         if '@' in thisbuild['maven']:
             maven_dir = os.path.join(root_dir, thisbuild['maven'].split('@',1)[1])
@@ -528,7 +511,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
         bindir = os.path.join(root_dir, 'target')
 
     elif thisbuild['type'] == 'kivy':
-        print "Building Kivy project..."
+        logging.info("Building Kivy project...")
 
         spec = os.path.join(root_dir, 'buildozer.spec')
         if not os.path.exists(spec):
@@ -588,7 +571,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
         p = FDroidPopen(cmd, cwd=distdir)
 
     elif thisbuild['type'] == 'gradle':
-        print "Building Gradle project..."
+        logging.info("Building Gradle project...")
         if '@' in thisbuild['gradle']:
             flavours = thisbuild['gradle'].split('@')[0].split(',')
             gradle_dir = thisbuild['gradle'].split('@')[1]
@@ -608,7 +591,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
         p = FDroidPopen(commands, cwd=gradle_dir)
 
     elif thisbuild['type'] == 'ant':
-        print "Building Ant project..."
+        logging.info("Building Ant project...")
         cmd = ['ant']
         if 'antcommand' in thisbuild:
             cmd += [thisbuild['antcommand']]
@@ -620,7 +603,7 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
 
     if p is not None and p.returncode != 0:
         raise BuildException("Build failed for %s:%s" % (app['id'], thisbuild['version']), p.stdout)
-    print "Successfully built version " + thisbuild['version'] + ' of ' + app['id']
+    logging.info("Successfully built version " + thisbuild['version'] + ' of ' + app['id'])
 
     if thisbuild['type'] == 'maven':
         stdout_apk = '\n'.join([
@@ -665,20 +648,18 @@ def build_local(app, thisbuild, vcs, build_dir, output_dir, srclib_dir, extlib_d
 
     # By way of a sanity check, make sure the version and version
     # code in our new apk match what we expect...
-    print "Checking " + src
+    logging.info("Checking " + src)
     if not os.path.exists(src):
         raise BuildException("Unsigned apk is not at expected location of " + src)
 
-    p = subprocess.Popen([os.path.join(config['sdk_path'],
+    p = FDroidPopen([os.path.join(config['sdk_path'],
                         'build-tools', config['build_tools'], 'aapt'),
-                        'dump', 'badging', src],
-                        stdout=subprocess.PIPE)
-    output = p.communicate()[0]
+                        'dump', 'badging', src], output=False)
 
     vercode = None
     version = None
     foundid = None
-    for line in output.splitlines():
+    for line in p.stdout.splitlines():
         if line.startswith("package:"):
             pat = re.compile(".*name='([a-zA-Z0-9._]*)'.*")
             m = pat.match(line)
@@ -766,7 +747,7 @@ def trybuild(app, thisbuild, build_dir, output_dir, also_check_dir, srclib_dir,
     if 'disable' in thisbuild:
         return False
 
-    print "Building version " + thisbuild['version'] + ' of ' + app['id']
+    logging.info("Building version " + thisbuild['version'] + ' of ' + app['id'])
 
     if server:
         # When using server mode, still keep a local cache of the repo, by
@@ -836,12 +817,12 @@ def main():
 
     log_dir = 'logs'
     if not os.path.isdir(log_dir):
-        print "Creating log directory"
+        logging.info("Creating log directory")
         os.makedirs(log_dir)
 
     tmp_dir = 'tmp'
     if not os.path.isdir(tmp_dir):
-        print "Creating temporary directory"
+        logging.info("Creating temporary directory")
         os.makedirs(tmp_dir)
 
     if options.test:
@@ -849,7 +830,7 @@ def main():
     else:
         output_dir = 'unsigned'
         if not os.path.isdir(output_dir):
-            print "Creating output directory"
+            logging.info("Creating output directory")
             os.makedirs(output_dir)
 
     if config['archive_older'] != 0:
@@ -861,7 +842,7 @@ def main():
 
     build_dir = 'build'
     if not os.path.isdir(build_dir):
-        print "Creating build directory"
+        logging.info("Creating build directory")
         os.makedirs(build_dir)
     srclib_dir = os.path.join(build_dir, 'srclib')
     extlib_dir = os.path.join(build_dir, 'extlib')
@@ -911,15 +892,13 @@ def main():
                         build_dir = os.path.join('build', app['id'])
 
                     # Set up vcs interface and make sure we have the latest code...
-                    if options.verbose:
-                        print "Getting {0} vcs interface for {1}".format(
-                                app['Repo Type'], app['Repo'])
+                    logging.info("Getting {0} vcs interface for {1}".format(
+                            app['Repo Type'], app['Repo']))
                     vcs = common.getvcs(app['Repo Type'], app['Repo'], build_dir)
 
                     first = False
 
-                if options.verbose:
-                    print "Checking " + thisbuild['version']
+                logging.info("Checking " + thisbuild['version'])
                 if trybuild(app, thisbuild, build_dir, output_dir, also_check_dir,
                         srclib_dir, extlib_dir, tmp_dir, repo_dir, vcs, options.test,
                         options.server, options.force, options.onserver):
@@ -929,19 +908,19 @@ def main():
                 logfile = open(os.path.join(log_dir, app['id'] + '.log'), 'a+')
                 logfile.write(str(be))
                 logfile.close()
-                print "Could not build app %s due to BuildException: %s" % (app['id'], be)
+                logging.info("Could not build app %s due to BuildException: %s" % (app['id'], be))
                 if options.stop:
                     sys.exit(1)
                 failed_apps[app['id']] = be
                 wikilog = be.get_wikitext()
             except VCSException as vcse:
-                print "VCS error while building app %s: %s" % (app['id'], vcse)
+                logging.info("VCS error while building app %s: %s" % (app['id'], vcse))
                 if options.stop:
                     sys.exit(1)
                 failed_apps[app['id']] = vcse
                 wikilog = str(vcse)
             except Exception as e:
-                print "Could not build app %s due to unknown error: %s" % (app['id'], traceback.format_exc())
+                logging.info("Could not build app %s due to unknown error: %s" % (app['id'], traceback.format_exc()))
                 if options.stop:
                     sys.exit(1)
                 failed_apps[app['id']] = e
@@ -956,20 +935,20 @@ def main():
                     txt = "Build completed at " + time.strftime("%Y-%m-%d %H:%M:%SZ", time.gmtime()) + "\n\n" + txt
                     newpage.save(txt, summary='Build log')
                 except:
-                    print "Error while attempting to publish build log"
+                    logging.info("Error while attempting to publish build log")
 
     for app in build_succeeded:
-        print "success: %s" % (app['id'])
+        logging.info("success: %s" % (app['id']))
 
     if not options.verbose:
         for fa in failed_apps:
-            print "Build for app %s failed:\n%s" % (fa, failed_apps[fa])
+            logging.info("Build for app %s failed:\n%s" % (fa, failed_apps[fa]))
 
-    print "Finished."
+    logging.info("Finished.")
     if len(build_succeeded) > 0:
-        print str(len(build_succeeded)) + ' builds succeeded'
+        logging.info(str(len(build_succeeded)) + ' builds succeeded')
     if len(failed_apps) > 0:
-        print str(len(failed_apps)) + ' builds failed'
+        logging.info(str(len(failed_apps)) + ' builds failed')
 
     sys.exit(0)