1
0
mirror of https://gitlab.com/fdroid/fdroidserver.git synced 2024-07-07 01:40:10 +02:00

use same logging setup as in all other fdroid scripts

This commit is contained in:
Michael Pöhn 2019-02-20 15:54:32 +01:00
parent 81f1bcf752
commit d4e5fdd95b

View File

@ -32,27 +32,25 @@ parser.add_option('--keep-box-file', action="store_true", default=False,
""" (KVM-only).""") """ (KVM-only).""")
options, args = parser.parse_args() options, args = parser.parse_args()
logger = logging.getLogger('fdroidserver-makebuildserver')
if options.verbosity >= 2: logformat = '%(levelname)s: %(message)s'
logging.basicConfig(format='%(message)s', level=logging.DEBUG) loglevel = logging.DEBUG
logger.setLevel(logging.DEBUG) if options.verbosity == 1:
elif options.verbosity == 1: loglevel = logging.INFO
logging.basicConfig(format='%(message)s', level=logging.INFO)
logger.setLevel(logging.INFO)
elif options.verbosity <= 0: elif options.verbosity <= 0:
logging.basicConfig(format='%(message)s', level=logging.WARNING) loglevel = logging.WARNING
logger.setLevel(logging.WARNING) logging.basicConfig(format=logformat, level=loglevel)
if not os.path.exists('makebuildserver') and not os.path.exists('buildserver'): if not os.path.exists('makebuildserver') and not os.path.exists('buildserver'):
logger.critical('This must be run as ./makebuildserver in fdroidserver.git!') logging.critical('This must be run as ./makebuildserver in fdroidserver.git!')
sys.exit(1) sys.exit(1)
tail = None tail = None
# set up default config # set up default config
cachedir = os.path.join(os.getenv('HOME'), '.cache', 'fdroidserver') cachedir = os.path.join(os.getenv('HOME'), '.cache', 'fdroidserver')
logger.debug('cachedir set to: %s', cachedir) logging.debug('cachedir set to: %s', cachedir)
BASEBOX_DEFAULT = 'fdroid/basebox-stretch64' BASEBOX_DEFAULT = 'fdroid/basebox-stretch64'
BASEBOX_VERSION_DEFAULT = '0.5.1' BASEBOX_VERSION_DEFAULT = '0.5.1'
@ -117,11 +115,11 @@ if os.path.isfile('/usr/bin/systemd-detect-virt'):
except subprocess.CalledProcessError: except subprocess.CalledProcessError:
virt = 'none' virt = 'none'
if virt == 'qemu' or virt == 'kvm' or virt == 'bochs': if virt == 'qemu' or virt == 'kvm' or virt == 'bochs':
logger.info('Running in a VM guest, defaulting to QEMU/KVM via libvirt') logging.info('Running in a VM guest, defaulting to QEMU/KVM via libvirt')
config['vm_provider'] = 'libvirt' config['vm_provider'] = 'libvirt'
elif virt != 'none': elif virt != 'none':
logger.info('Running in an unsupported VM guest (%s)!', virt) logging.info('Running in an unsupported VM guest (%s)!', virt)
logger.debug('detected virt: %s', virt) logging.debug('detected virt: %s', virt)
# load config file, if present # load config file, if present
if os.path.exists('makebuildserver.config.py'): if os.path.exists('makebuildserver.config.py'):
@ -131,43 +129,43 @@ elif os.path.exists('makebs.config.py'):
exec(compile(open('makebs.config.py').read(), 'makebs.config.py', 'exec'), config) exec(compile(open('makebs.config.py').read(), 'makebs.config.py', 'exec'), config)
if '__builtins__' in config: if '__builtins__' in config:
del(config['__builtins__']) # added by compile/exec del(config['__builtins__']) # added by compile/exec
logger.debug("makebuildserver.config.py parsed -> %s", json.dumps(config, indent=4, sort_keys=True)) logging.debug("makebuildserver.config.py parsed -> %s", json.dumps(config, indent=4, sort_keys=True))
if config['basebox'] == BASEBOX_DEFAULT and 'basebox_version' not in config: if config['basebox'] == BASEBOX_DEFAULT and 'basebox_version' not in config:
config['basebox_version'] = BASEBOX_VERSION_DEFAULT config['basebox_version'] = BASEBOX_VERSION_DEFAULT
# note: vagrant allows putting '/' into the name of a local box, # note: vagrant allows putting '/' into the name of a local box,
# so this check is not completely relyable, but better than nothing # so this check is not completely relyable, but better than nothing
if 'basebox_version' in config and 'basebox' in config and '/' not in config['basebox']: if 'basebox_version' in config and 'basebox' in config and '/' not in config['basebox']:
logger.critical("Can not get version '{version}' for basebox '{box}', " logging.critical("Can not get version '{version}' for basebox '{box}', "
"vagrant does not support versioning for locally added boxes." "vagrant does not support versioning for locally added boxes."
.format(box=config['basebox'], version=config['basebox_version'])) .format(box=config['basebox'], version=config['basebox_version']))
# Update cached files. # Update cached files.
cachedir = config['cachedir'] cachedir = config['cachedir']
if not os.path.exists(cachedir): if not os.path.exists(cachedir):
os.makedirs(cachedir, 0o755) os.makedirs(cachedir, 0o755)
logger.debug('created cachedir %s because it did not exists.', cachedir) logging.debug('created cachedir %s because it did not exists.', cachedir)
if config['vm_provider'] == 'libvirt': if config['vm_provider'] == 'libvirt':
tmp = cachedir tmp = cachedir
while tmp != '/': while tmp != '/':
mode = os.stat(tmp).st_mode mode = os.stat(tmp).st_mode
if not (stat.S_IXUSR & mode and stat.S_IXGRP & mode and stat.S_IXOTH & mode): if not (stat.S_IXUSR & mode and stat.S_IXGRP & mode and stat.S_IXOTH & mode):
logger.critical('ERROR: %s will not be accessible to the VM! To fix, run:', tmp) logging.critical('ERROR: %s will not be accessible to the VM! To fix, run:', tmp)
logger.critical(' chmod a+X %s', tmp) logging.critical(' chmod a+X %s', tmp)
sys.exit(1) sys.exit(1)
tmp = os.path.dirname(tmp) tmp = os.path.dirname(tmp)
logger.debug('cache dir %s is accessible for libvirt vm.', cachedir) logging.debug('cache dir %s is accessible for libvirt vm.', cachedir)
if config['apt_package_cache']: if config['apt_package_cache']:
config['aptcachedir'] = cachedir + '/apt/archives' config['aptcachedir'] = cachedir + '/apt/archives'
logger.debug('aptcachedir is set to %s', config['aptcachedir']) logging.debug('aptcachedir is set to %s', config['aptcachedir'])
aptcachelock = os.path.join(config['aptcachedir'], 'lock') aptcachelock = os.path.join(config['aptcachedir'], 'lock')
if os.path.isfile(aptcachelock): if os.path.isfile(aptcachelock):
logger.info('apt cache dir is locked, removing lock') logging.info('apt cache dir is locked, removing lock')
os.remove(aptcachelock) os.remove(aptcachelock)
aptcachepartial = os.path.join(config['aptcachedir'], 'partial') aptcachepartial = os.path.join(config['aptcachedir'], 'partial')
if os.path.isdir(aptcachepartial): if os.path.isdir(aptcachepartial):
logger.info('removing partial downloads from apt cache dir') logging.info('removing partial downloads from apt cache dir')
shutil.rmtree(aptcachepartial) shutil.rmtree(aptcachepartial)
cachefiles = [ cachefiles = [
@ -406,14 +404,14 @@ def sha256_for_file(path):
def verify_file_sha256(path, sha256): def verify_file_sha256(path, sha256):
if sha256_for_file(path) != sha256: if sha256_for_file(path) != sha256:
logger.critical("File verification for '{path}' failed! " logging.critical("File verification for '{path}' failed! "
"expected sha256 checksum: {checksum}" "expected sha256 checksum: {checksum}"
.format(path=path, checksum=sha256)) .format(path=path, checksum=sha256))
sys.exit(1) sys.exit(1)
else: else:
logger.debug("sucessfully verifyed file '{path}' " logging.debug("sucessfully verifyed file '{path}' "
"('{checksum}')".format(path=path, "('{checksum}')".format(path=path,
checksum=sha256)) checksum=sha256))
def get_vagrant_home(): def get_vagrant_home():
@ -437,7 +435,7 @@ def update_cache(cachedir, cachefiles):
if os.path.exists(local_filename): if os.path.exists(local_filename):
if sha256_for_file(local_filename) == shasum: if sha256_for_file(local_filename) == shasum:
logger.info("\t...shasum verified for %s", local_filename) logging.info("\t...shasum verified for %s", local_filename)
continue continue
local_length = os.path.getsize(local_filename) local_length = os.path.getsize(local_filename)
else: else:
@ -454,19 +452,19 @@ def update_cache(cachedir, cachefiles):
content_length = local_length # skip the download content_length = local_length # skip the download
except requests.exceptions.RequestException as e: except requests.exceptions.RequestException as e:
content_length = local_length # skip the download content_length = local_length # skip the download
logger.warn('%s', e) logging.warn('%s', e)
if local_length == content_length: if local_length == content_length:
download = False download = False
elif local_length > content_length: elif local_length > content_length:
logger.info('deleting corrupt file from cache: %s', local_filename) logging.info('deleting corrupt file from cache: %s', local_filename)
os.remove(local_filename) os.remove(local_filename)
logger.info("Downloading %s to cache", filename) logging.info("Downloading %s to cache", filename)
elif local_length > -1 and local_length < content_length: elif local_length > -1 and local_length < content_length:
logger.info("Resuming download of %s", local_filename) logging.info("Resuming download of %s", local_filename)
resume_header = {'Range': 'bytes=%d-%d' % (local_length, content_length)} resume_header = {'Range': 'bytes=%d-%d' % (local_length, content_length)}
else: else:
logger.info("Downloading %s to cache", filename) logging.info("Downloading %s to cache", filename)
if download: if download:
r = requests.get(srcurl, headers=resume_header, r = requests.get(srcurl, headers=resume_header,
@ -480,9 +478,9 @@ def update_cache(cachedir, cachefiles):
v = sha256_for_file(local_filename) v = sha256_for_file(local_filename)
if v == shasum: if v == shasum:
logger.info("\t...shasum verified for %s", local_filename) logging.info("\t...shasum verified for %s", local_filename)
else: else:
logger.critical("Invalid shasum of '%s' detected for %s", v, local_filename) logging.critical("Invalid shasum of '%s' detected for %s", v, local_filename)
os.remove(local_filename) os.remove(local_filename)
sys.exit(1) sys.exit(1)
@ -490,16 +488,16 @@ def update_cache(cachedir, cachefiles):
def debug_log_vagrant_vm(vm_dir, config): def debug_log_vagrant_vm(vm_dir, config):
if options.verbosity >= 3: if options.verbosity >= 3:
_vagrant_dir = os.path.join(vm_dir, '.vagrant') _vagrant_dir = os.path.join(vm_dir, '.vagrant')
logger.debug('check %s dir exists? -> %r', _vagrant_dir, os.path.isdir(_vagrant_dir)) logging.debug('check %s dir exists? -> %r', _vagrant_dir, os.path.isdir(_vagrant_dir))
logger.debug('> vagrant status') logging.debug('> vagrant status')
subprocess.call(['vagrant', 'status'], cwd=vm_dir) subprocess.call(['vagrant', 'status'], cwd=vm_dir)
logger.debug('> vagrant box list') logging.debug('> vagrant box list')
subprocess.call(['vagrant', 'box', 'list']) subprocess.call(['vagrant', 'box', 'list'])
if config['vm_provider'] == 'libvirt': if config['vm_provider'] == 'libvirt':
logger.debug('> virsh -c qmeu:///system list --all') logging.debug('> virsh -c qmeu:///system list --all')
subprocess.call(['virsh', '-c', 'qemu:///system', 'list', '--all']) subprocess.call(['virsh', '-c', 'qemu:///system', 'list', '--all'])
domain = 'buildserver_default' domain = 'buildserver_default'
logger.debug('> virsh -c qemu:///system snapshot-list %s', domain) logging.debug('> virsh -c qemu:///system snapshot-list %s', domain)
subprocess.call(['virsh', '-c', 'qemu:///system', 'snapshot-list', domain]) subprocess.call(['virsh', '-c', 'qemu:///system', 'snapshot-list', domain])
@ -507,7 +505,7 @@ def main():
global cachedir, cachefiles, config, tail global cachedir, cachefiles, config, tail
if options.skip_cache_update: if options.skip_cache_update:
logger.info('skipping cache update and verification...') logging.info('skipping cache update and verification...')
else: else:
update_cache(cachedir, cachefiles) update_cache(cachedir, cachefiles)
@ -518,13 +516,13 @@ def main():
# all < 10 year old Macs work, and OSX servers as VM host are very # all < 10 year old Macs work, and OSX servers as VM host are very
# rare, but this could also be auto-detected if someone codes it # rare, but this could also be auto-detected if someone codes it
config['hwvirtex'] = 'on' config['hwvirtex'] = 'on'
logger.info('platform is darwnin -> hwvirtex = \'on\'') logging.info('platform is darwnin -> hwvirtex = \'on\'')
elif os.path.exists('/proc/cpuinfo'): elif os.path.exists('/proc/cpuinfo'):
with open('/proc/cpuinfo') as f: with open('/proc/cpuinfo') as f:
contents = f.read() contents = f.read()
if 'vmx' in contents or 'svm' in contents: if 'vmx' in contents or 'svm' in contents:
config['hwvirtex'] = 'on' config['hwvirtex'] = 'on'
logger.info('found \'vmx\' or \'svm\' in /proc/cpuinfo -> hwvirtex = \'on\'') logging.info('found \'vmx\' or \'svm\' in /proc/cpuinfo -> hwvirtex = \'on\'')
serverdir = os.path.join(os.getcwd(), 'buildserver') serverdir = os.path.join(os.getcwd(), 'buildserver')
logfilename = os.path.join(serverdir, 'up.log') logfilename = os.path.join(serverdir, 'up.log')
@ -546,40 +544,40 @@ def main():
vf = os.path.join(serverdir, 'Vagrantfile.yaml') vf = os.path.join(serverdir, 'Vagrantfile.yaml')
writevf = True writevf = True
if os.path.exists(vf): if os.path.exists(vf):
logger.info('Halting %s', serverdir) logging.info('Halting %s', serverdir)
v.halt() v.halt()
with open(vf, 'r', encoding='utf-8') as f: with open(vf, 'r', encoding='utf-8') as f:
oldconfig = yaml.load(f) oldconfig = yaml.load(f)
if config != oldconfig: if config != oldconfig:
logger.info("Server configuration has changed, rebuild from scratch is required") logging.info("Server configuration has changed, rebuild from scratch is required")
vm.destroy() vm.destroy()
else: else:
logger.info("Re-provisioning existing server") logging.info("Re-provisioning existing server")
writevf = False writevf = False
else: else:
logger.info("No existing server - building from scratch") logging.info("No existing server - building from scratch")
if writevf: if writevf:
with open(vf, 'w', encoding='utf-8') as f: with open(vf, 'w', encoding='utf-8') as f:
yaml.dump(config, f) yaml.dump(config, f)
# Check if selected provider is supported # Check if selected provider is supported
if config['vm_provider'] not in ['libvirt', 'virtualbox']: if config['vm_provider'] not in ['libvirt', 'virtualbox']:
logger.critical("Currently selected VM provider '{vm_provider}' " logging.critical("Currently selected VM provider '{vm_provider}' "
"is not supported. (please choose from: " "is not supported. (please choose from: "
"virtualbox, libvirt)" "virtualbox, libvirt)"
.format(vm_provider=config['cm_provider'])) .format(vm_provider=config['cm_provider']))
sys.exit(1) sys.exit(1)
# Check if selected basebox is available # Check if selected basebox is available
available_boxes_by_provider = [x.name for x in v.box_list() if x.provider == config['vm_provider']] available_boxes_by_provider = [x.name for x in v.box_list() if x.provider == config['vm_provider']]
if '/' not in config['basebox'] and config['basebox'] not in available_boxes_by_provider: if '/' not in config['basebox'] and config['basebox'] not in available_boxes_by_provider:
logger.critical("Vagrant box '{basebox}' not available " logging.critical("Vagrant box '{basebox}' not available "
"for '{vm_provider}' VM provider. " "for '{vm_provider}' VM provider. "
"Please make sure it's added to vagrant. " "Please make sure it's added to vagrant. "
"(If you need a basebox to begin with, " "(If you need a basebox to begin with, "
"here is how we're bootstrapping it: " "here is how we're bootstrapping it: "
"https://gitlab.com/fdroid/basebox)" "https://gitlab.com/fdroid/basebox)"
.format(vm_provider=config['vm_provider'], .format(vm_provider=config['vm_provider'],
basebox=config['basebox'])) basebox=config['basebox']))
sys.exit(1) sys.exit(1)
# download and verfiy fdroid pre-built basebox # download and verfiy fdroid pre-built basebox
@ -594,18 +592,18 @@ def main():
'--provider=' + config['vm_provider']] '--provider=' + config['vm_provider']]
ret_val = subprocess.call(cmd) ret_val = subprocess.call(cmd)
if ret_val != 0: if ret_val != 0:
logger.critical("downloading basebox '{box}' " logging.critical("downloading basebox '{box}' "
"({provider}, version {version}) failed." "({provider}, version {version}) failed."
.format(box=config['basebox'], .format(box=config['basebox'],
provider=config['vm_provider'], provider=config['vm_provider'],
version=config['basebox_version'])) version=config['basebox_version']))
sys.exit(1) sys.exit(1)
# verify box # verify box
if config['basebox_version'] not in BASEBOX_CHECKSUMS.keys(): if config['basebox_version'] not in BASEBOX_CHECKSUMS.keys():
logger.critical("can not verify '{box}', " logging.critical("can not verify '{box}', "
"unknown basebox version '{version}'" "unknown basebox version '{version}'"
.format(box=config['basebox'], .format(box=config['basebox'],
version=config['basebox_version'])) version=config['basebox_version']))
sys.exit(1) sys.exit(1)
for filename, sha256 in BASEBOX_CHECKSUMS[config['basebox_version']][config['vm_provider']].items(): for filename, sha256 in BASEBOX_CHECKSUMS[config['basebox_version']][config['vm_provider']].items():
verify_file_sha256(os.path.join(get_vagrant_home(), verify_file_sha256(os.path.join(get_vagrant_home(),
@ -615,23 +613,23 @@ def main():
config['vm_provider'], config['vm_provider'],
filename), filename),
sha256) sha256)
logger.info("successfully verified: '{box}' " logging.info("successfully verified: '{box}' "
"({provider}, version {version})" "({provider}, version {version})"
.format(box=config['basebox'], .format(box=config['basebox'],
provider=config['vm_provider'], provider=config['vm_provider'],
version=config['basebox_version'])) version=config['basebox_version']))
else: else:
logger.debug('not updating basebox ...') logging.debug('not updating basebox ...')
else: else:
logger.debug('using unverified basebox ...') logging.debug('using unverified basebox ...')
logger.info("Configuring build server VM") logging.info("Configuring build server VM")
debug_log_vagrant_vm(serverdir, config) debug_log_vagrant_vm(serverdir, config)
try: try:
v.up(provision=True) v.up(provision=True)
except subprocess.CalledProcessError: except subprocess.CalledProcessError:
debug_log_vagrant_vm(serverdir, config) debug_log_vagrant_vm(serverdir, config)
logger.error("'vagrant up' failed.") logging.error("'vagrant up' failed.")
sys.exit(1) sys.exit(1)
if config['copy_caches_from_host']: if config['copy_caches_from_host']:
@ -664,29 +662,29 @@ def main():
p = subprocess.Popen(['git', 'rev-parse', 'HEAD'], stdout=subprocess.PIPE, p = subprocess.Popen(['git', 'rev-parse', 'HEAD'], stdout=subprocess.PIPE,
universal_newlines=True) universal_newlines=True)
buildserverid = p.communicate()[0].strip() buildserverid = p.communicate()[0].strip()
logger.info("Writing buildserver ID ...ID is %s", buildserverid) logging.info("Writing buildserver ID ...ID is %s", buildserverid)
run_via_vagrant_ssh(v, 'sh -c "echo %s >/home/vagrant/buildserverid"' % buildserverid) run_via_vagrant_ssh(v, 'sh -c "echo %s >/home/vagrant/buildserverid"' % buildserverid)
logger.info("Stopping build server VM") logging.info("Stopping build server VM")
v.halt() v.halt()
logger.info("Packaging") logging.info("Packaging")
boxfile = os.path.join(os.getcwd(), 'buildserver.box') boxfile = os.path.join(os.getcwd(), 'buildserver.box')
if os.path.exists(boxfile): if os.path.exists(boxfile):
os.remove(boxfile) os.remove(boxfile)
vm.package(output=boxfile) vm.package(output=boxfile)
logger.info("Adding box") logging.info("Adding box")
vm.box_add('buildserver', boxfile, force=True) vm.box_add('buildserver', boxfile, force=True)
if 'buildserver' not in subprocess.check_output(['vagrant', 'box', 'list']).decode('utf-8'): if 'buildserver' not in subprocess.check_output(['vagrant', 'box', 'list']).decode('utf-8'):
logger.critical('could not add box \'%s\' as \'buildserver\', terminating', boxfile) logging.critical('could not add box \'%s\' as \'buildserver\', terminating', boxfile)
sys.exit(1) sys.exit(1)
if not options.keep_box_file: if not options.keep_box_file:
logger.debug("""box added to vagrant, removing generated box file '%s'""", logging.debug("""box added to vagrant, removing generated box file '%s'""",
boxfile) boxfile)
os.remove(boxfile) os.remove(boxfile)