From b98850819bdbdb23e354bb5bf5d5383cf807d22d Mon Sep 17 00:00:00 2001 From: Anton Hvornum Date: Wed, 4 Nov 2020 22:41:50 +0100 Subject: Added multiple log features. * [Reintroduced](https://github.com/Torxed/archinstall/blob/f64a605449f59c677dff39962f1cb46616d893b7/archinstall.py#L57-L71) log levels * Created a global log file definition * Optional support for `python-systemd`'s journald handler. * Optional file output that has a globally configurable definition, that archinstall will honor in `archinstall.storage['logfile']`. --- archinstall/lib/disk.py | 7 +++-- archinstall/lib/general.py | 35 +++++++++++---------- archinstall/lib/installer.py | 51 +++++++++++++++++++++---------- archinstall/lib/luks.py | 7 ++++- archinstall/lib/mirrors.py | 3 +- archinstall/lib/output.py | 72 +++++++++++++++++++++++++++++++++++++++++++- archinstall/lib/profiles.py | 3 +- examples/guided.py | 15 +++++++-- 8 files changed, 152 insertions(+), 41 deletions(-) diff --git a/archinstall/lib/disk.py b/archinstall/lib/disk.py index 0d0285d2..6ac97b04 100644 --- a/archinstall/lib/disk.py +++ b/archinstall/lib/disk.py @@ -2,6 +2,7 @@ import glob, re, os, json from collections import OrderedDict from .exceptions import DiskError from .general import * +from .output import log, LOG_LEVELS ROOT_DIR_PATTERN = re.compile('^.*?/devices') GPT = 0b00000001 @@ -115,7 +116,7 @@ class Partition(): return f'Partition(path={self.path}, fs={self.filesystem}, mounted={self.mountpoint})' def format(self, filesystem): - log(f'Formatting {self} -> {filesystem}') + log(f'Formatting {self} -> {filesystem}', level=LOG_LEVELS.Info, file=storage.get('logfile', None)) if filesystem == 'btrfs': o = b''.join(sys_command(f'/usr/bin/mkfs.btrfs -f {self.path}')) if b'UUID' not in o: @@ -154,7 +155,7 @@ class Partition(): def mount(self, target, fs=None, options=''): if not self.mountpoint: - log(f'Mounting {self} to {target}') + log(f'Mounting {self} to {target}', level=LOG_LEVELS.Info, file=storage.get('logfile', None)) if not fs: if not self.filesystem: raise DiskError(f'Need to format (or define) the filesystem on {self} before mounting.') fs = self.filesystem @@ -216,7 +217,7 @@ class Filesystem(): self.add_partition('primary', start='513MiB', end='100%', format='ext4') def add_partition(self, type, start, end, format=None): - log(f'Adding partition to {self.blockdevice}') + log(f'Adding partition to {self.blockdevice}', level=LOG_LEVELS.Info, file=storage.get('logfile', None)) if format: return self.parted(f'{self.blockdevice.device} mkpart {type} {format} {start} {end}') == 0 else: diff --git a/archinstall/lib/general.py b/archinstall/lib/general.py index abcf25f0..025dcc8b 100644 --- a/archinstall/lib/general.py +++ b/archinstall/lib/general.py @@ -4,7 +4,7 @@ from datetime import datetime, date from subprocess import Popen, STDOUT, PIPE, check_output from select import epoll, EPOLLIN, EPOLLHUP from .exceptions import * -from .output import * +from .output import log, LOG_LEVELS def gen_uid(entropy_length=256): return hashlib.sha512(os.urandom(entropy_length)).hexdigest() @@ -77,8 +77,11 @@ class sys_command():#Thread): kwargs.setdefault("emulate", False) kwargs.setdefault("suppress_errors", False) + self.log = kwargs.get('log', log) + if kwargs['emulate']: - log(f"Starting command '{cmd}' in emulation mode.") + self.log(f"Starting command '{cmd}' in emulation mode.", level=LOG_LEVELS.Debug) + self.raw_cmd = cmd try: self.cmd = shlex.split(cmd) @@ -105,8 +108,8 @@ class sys_command():#Thread): # "which" doesn't work as it's a builtin to bash. # It used to work, but for whatever reason it doesn't anymore. So back to square one.. - #log('Worker command is not executed with absolute path, trying to find: {}'.format(self.cmd[0]), origin='spawn', level=5) - #log('This is the binary {} for {}'.format(o.decode('UTF-8'), self.cmd[0]), origin='spawn', level=5) + #self.log('Worker command is not executed with absolute path, trying to find: {}'.format(self.cmd[0]), origin='spawn', level=5) + #self.log('This is the binary {} for {}'.format(o.decode('UTF-8'), self.cmd[0]), origin='spawn', level=5) self.cmd[0] = locate_binary(self.cmd[0]) if not os.path.isdir(self.exec_dir): @@ -150,7 +153,7 @@ class sys_command():#Thread): os.execv(self.cmd[0], self.cmd) except FileNotFoundError: self.status = 'done' - log(f"{self.cmd[0]} does not exist.", origin='spawn', level=2) + self.log(f"{self.cmd[0]} does not exist.", level=LOG_LEVELS.Debug) self.exit_code = 1 return False @@ -160,8 +163,8 @@ class sys_command():#Thread): poller.register(child_fd, EPOLLIN | EPOLLHUP) if 'events' in self.kwargs and 'debug' in self.kwargs: - log(f'[D] Using triggers for command: {self.cmd}') - log(json.dumps(self.kwargs['events'])) + self.log(f'[D] Using triggers for command: {self.cmd}', level=LOG_LEVELS.Debug) + self.log(json.dumps(self.kwargs['events']), level=LOG_LEVELS.Debug) alive = True last_trigger_pos = 0 @@ -175,7 +178,7 @@ class sys_command():#Thread): break if 'debug' in self.kwargs and self.kwargs['debug'] and len(output): - log(self.cmd, 'gave:', output.decode('UTF-8')) + self.log(self.cmd, 'gave:', output.decode('UTF-8'), level=LOG_LEVELS.Debug) if 'on_output' in self.kwargs: self.kwargs['on_output'](self.kwargs['worker'], output) @@ -196,8 +199,8 @@ class sys_command():#Thread): trigger_pos = self.trace_log[last_trigger_pos:].lower().find(trigger.lower()) if 'debug' in self.kwargs and self.kwargs['debug']: - log(f"Writing to subprocess {self.cmd[0]}: {self.kwargs['events'][trigger].decode('UTF-8')}") - log(f"Writing to subprocess {self.cmd[0]}: {self.kwargs['events'][trigger].decode('UTF-8')}", origin='spawn', level=5) + self.log(f"Writing to subprocess {self.cmd[0]}: {self.kwargs['events'][trigger].decode('UTF-8')}", level=LOG_LEVELS.Debug) + self.log(f"Writing to subprocess {self.cmd[0]}: {self.kwargs['events'][trigger].decode('UTF-8')}", level=LOG_LEVELS.Debug) last_trigger_pos = trigger_pos os.write(child_fd, self.kwargs['events'][trigger]) @@ -211,18 +214,18 @@ class sys_command():#Thread): ## Adding a exit trigger: if len(self.kwargs['events']) == 0: if 'debug' in self.kwargs and self.kwargs['debug']: - log(f"Waiting for last command {self.cmd[0]} to finish.", origin='spawn', level=4) + self.log(f"Waiting for last command {self.cmd[0]} to finish.", level=LOG_LEVELS.Debug) if bytes(f']$'.lower(), 'UTF-8') in self.trace_log[0-len(f']$')-5:].lower(): if 'debug' in self.kwargs and self.kwargs['debug']: - log(f"{self.cmd[0]} has finished.") + self.log(f"{self.cmd[0]} has finished.", level=LOG_LEVELS.Debug) alive = False break self.status = 'done' if 'debug' in self.kwargs and self.kwargs['debug']: - log(f"{self.cmd[0]} waiting for exit code.") + self.log(f"{self.cmd[0]} waiting for exit code.", level=LOG_LEVELS.Debug) if not self.kwargs['emulate']: try: @@ -236,14 +239,14 @@ class sys_command():#Thread): self.exit_code = 0 if 'debug' in self.kwargs and self.kwargs['debug']: - log(f"{self.cmd[0]} got exit code: {self.exit_code}") + self.log(f"{self.cmd[0]} got exit code: {self.exit_code}", level=LOG_LEVELS.Debug) if 'ignore_errors' in self.kwargs: self.exit_code = 0 if self.exit_code != 0 and not self.kwargs['suppress_errors']: - log(f"'{self.raw_cmd}' did not exit gracefully, exit code {self.exit_code}.") - log(self.trace_log.decode('UTF-8')) + self.log(f"'{self.raw_cmd}' did not exit gracefully, exit code {self.exit_code}.", level=LOG_LEVELS.Debug) + self.log(self.trace_log.decode('UTF-8'), level=LOG_LEVELS.Debug) raise SysCallError(f"'{self.raw_cmd}' did not exit gracefully, exit code {self.exit_code}.\n{self.trace_log.decode('UTF-8')}") self.ended = time.time() diff --git a/archinstall/lib/installer.py b/archinstall/lib/installer.py index 0e5f5ca7..553fad80 100644 --- a/archinstall/lib/installer.py +++ b/archinstall/lib/installer.py @@ -1,4 +1,4 @@ -import os, stat +import os, stat, time from .exceptions import * from .disk import * @@ -6,6 +6,8 @@ from .general import * from .user_interaction import * from .profiles import Profile from .mirrors import * +from .output import log, LOG_LEVELS +from .storage import storage class Installer(): """ @@ -35,6 +37,8 @@ class Installer(): self.profile = profile self.hostname = hostname self.mountpoint = mountpoint + self.init_time = time.strftime('%Y-%m-%d %H:%M:%S') + self.milliseconds = int(str(time.time()).split('.')[1]) self.helper_flags = { 'bootloader' : False, @@ -43,10 +47,25 @@ class Installer(): } self.base_packages = base_packages.split(' ') + storage['session'] = self self.partition = partition self.boot_partition = boot_partition + @property + def log(self, message, *args, level=LOG_LEVELS.Debug, file=None, **kwargs): + if not file: + if 'logfile' not in storage: + log_root = os.path.join(os.path.expanduser('~/'), '.cache/archinstall') + if not os.path.isdir(log_root): + os.makedirs(log_root) + + storage['logfile'] = f"{log_root}/install-session_{self.init_time}.{self.milliseconds}.log" + + file = storage['logfile'] + + log(message, *args, level=level, file=file, **kwargs) + def __enter__(self, *args, **kwargs): self.partition.mount(self.mountpoint) os.makedirs(f'{self.mountpoint}/boot', exist_ok=True) @@ -60,14 +79,14 @@ class Installer(): raise args[1] if not (missing_steps := self.post_install_check()): - log('Installation completed without any errors. You may now reboot.', bg='black', fg='green') + self.log('Installation completed without any errors. You may now reboot.', bg='black', fg='green') return True else: - log('Some required steps were not successfully installed/configured before leaving the installer:', bg='black', fg='red') + self.log('Some required steps were not successfully installed/configured before leaving the installer:', bg='black', fg='red') for step in missing_steps: - log(f' - {step}', bg='black', fg='red') - log(f"Detailed error logs can be found at: {log_path}") - log(f"Submit this zip file as an issue to https://github.com/Torxed/archinstall/issues") + self.log(f' - {step}', bg='black', fg='red') + self.log(f"Detailed error logs can be found at: {log_path}") + self.log(f"Submit this zip file as an issue to https://github.com/Torxed/archinstall/issues") return False def post_install_check(self, *args, **kwargs): @@ -75,15 +94,15 @@ class Installer(): def pacstrap(self, *packages, **kwargs): if type(packages[0]) in (list, tuple): packages = packages[0] - log(f'Installing packages: {packages}') + self.log(f'Installing packages: {packages}') if (sync_mirrors := sys_command('/usr/bin/pacman -Syy')).exit_code == 0: if (pacstrap := sys_command(f'/usr/bin/pacstrap {self.mountpoint} {" ".join(packages)}', **kwargs)).exit_code == 0: return True else: - log(f'Could not strap in packages: {pacstrap.exit_code}') + self.log(f'Could not strap in packages: {pacstrap.exit_code}') else: - log(f'Could not sync mirrors: {sync_mirrors.exit_code}') + self.log(f'Could not sync mirrors: {sync_mirrors.exit_code}') def set_mirrors(self, mirrors): return use_mirrors(mirrors, destination=f'{self.mountpoint}/etc/pacman.d/mirrorlist') @@ -116,13 +135,13 @@ class Installer(): return True def activate_ntp(self): - log(f'Installing and activating NTP.') + self.log(f'Installing and activating NTP.') if self.pacstrap('ntp'): if self.enable_service('ntpd'): return True def enable_service(self, service): - log(f'Enabling service {service}') + self.log(f'Enabling service {service}') return self.arch_chroot(f'systemctl enable {service}').exit_code == 0 def run_command(self, cmd, *args, **kwargs): @@ -171,7 +190,7 @@ class Installer(): return True def add_bootloader(self, bootloader='systemd-bootctl'): - log(f'Adding bootloader {bootloader} to {self.boot_partition}') + self.log(f'Adding bootloader {bootloader} to {self.boot_partition}') if bootloader == 'systemd-bootctle': o = b''.join(sys_command(f'/usr/bin/arch-chroot {self.mountpoint} bootctl --no-variables --path=/boot install')) @@ -222,17 +241,17 @@ class Installer(): def install_profile(self, profile): profile = Profile(self, profile) - log(f'Installing network profile {profile}') + self.log(f'Installing network profile {profile}') return profile.install() def enable_sudo(self, entity :str, group=False): - log(f'Enabling sudo permissions for {entity}.') + self.log(f'Enabling sudo permissions for {entity}.') with open(f'{self.mountpoint}/etc/sudoers', 'a') as sudoers: sudoers.write(f'{"%" if group else ""}{entity} ALL=(ALL) ALL\n') return True def user_create(self, user :str, password=None, groups=[], sudo=False): - log(f'Creating user {user}') + self.log(f'Creating user {user}') o = b''.join(sys_command(f'/usr/bin/arch-chroot {self.mountpoint} useradd -m -G wheel {user}')) if password: self.user_set_pw(user, password) @@ -245,7 +264,7 @@ class Installer(): self.helper_flags['user'] = True def user_set_pw(self, user, password): - log(f'Setting password for {user}') + self.log(f'Setting password for {user}') if user == 'root': # This means the root account isn't locked/disabled with * in /etc/passwd diff --git a/archinstall/lib/luks.py b/archinstall/lib/luks.py index d4ee6632..7dfa9edc 100644 --- a/archinstall/lib/luks.py +++ b/archinstall/lib/luks.py @@ -2,6 +2,8 @@ import os from .exceptions import * from .general import * from .disk import Partition +from .output import log, LOG_LEVELS +from .storage import storage class luks2(): def __init__(self, partition, mountpoint, password, *args, **kwargs): @@ -22,7 +24,10 @@ class luks2(): return True def encrypt(self, partition, password, key_size=512, hash_type='sha512', iter_time=10000, key_file=None): - log(f'Encrypting {partition}') + # TODO: We should be able to integrate this into the main log some how. + # Perhaps post-mortem? + log(f'Encrypting {partition}', level=LOG_LEVELS.Info, file=storage.get('logfile', None)) + if not key_file: key_file = f"/tmp/{os.path.basename(self.partition.path)}.disk_pw" # TODO: Make disk-pw-file randomly unique? if type(password) != bytes: password = bytes(password, 'UTF-8') diff --git a/archinstall/lib/mirrors.py b/archinstall/lib/mirrors.py index 1cd53ed0..a92c47e0 100644 --- a/archinstall/lib/mirrors.py +++ b/archinstall/lib/mirrors.py @@ -2,6 +2,7 @@ import urllib.request from .exceptions import * from .general import * +from .output import log def filter_mirrors_by_region(regions, destination='/etc/pacman.d/mirrorlist', tmp_dir='/root', *args, **kwargs): """ @@ -57,7 +58,7 @@ def insert_mirrors(mirrors, *args, **kwargs): return True def use_mirrors(regions :dict, destination='/etc/pacman.d/mirrorlist'): - log(f'A new package mirror-list has been created: {destination}') + log(f'A new package mirror-list has been created: {destination}', level=LOG_LEVELS.Info, file=storage.get('logfile', None)) for region, mirrors in regions.items(): with open(destination, 'w') as mirrorlist: for mirror in mirrors: diff --git a/archinstall/lib/output.py b/archinstall/lib/output.py index d1b418d9..bba02cd7 100644 --- a/archinstall/lib/output.py +++ b/archinstall/lib/output.py @@ -1,4 +1,39 @@ +import abc +import os import sys +import logging + +class LOG_LEVELS: + Critical = 0b001 + Error = 0b010 + Warning = 0b011 + Info = 0b101 + Debug = 0b111 + +class journald(dict): + @abc.abstractmethod + def log(message, level=LOG_LEVELS.Debug): + import systemd.journal + log_adapter = logging.getLogger('archinstall') + log_fmt = logging.Formatter("[%(levelname)s]: %(message)s") + log_ch = systemd.journal.JournalHandler() + log_ch.setFormatter(log_fmt) + log_adapter.addHandler(log_ch) + log_adapter.setLevel(logging.DEBUG) + + if level == LOG_LEVELS.Critical: + log_adapter.critical(message) + elif level == LOG_LEVELS.Error: + log_adapter.error(message) + elif level == LOG_LEVELS.Warning: + log_adapter.warning(message) + elif level == LOG_LEVELS.Info: + log_adapter.info(message) + elif level == LOG_LEVELS.Debug: + log_adapter.debug(message) + else: + # Fallback logger + log_adapter.debug(message) # Found first reference here: https://stackoverflow.com/questions/7445658/how-to-detect-if-the-console-does-support-ansi-escape-codes-in-python # And re-used this: https://github.com/django/django/blob/master/django/core/management/color.py#L12 @@ -37,10 +72,45 @@ def stylize_output(text :str, *opts, **kwargs): text = '%s\x1b[%sm' % (text or '', RESET) return '%s%s' % (('\x1b[%sm' % ';'.join(code_list)), text or '') +GLOB_IMP_ERR_NOTIFIED = False def log(*args, **kwargs): - string = ' '.join([str(x) for x in args]) + if 'level' in kwargs: + try: + import archinstall + if 'LOG_LEVEL' not in archinstall.storage: + archinstall.storage['LOG_LEVEL'] = LOG_LEVELS.Info + + if kwargs['level'] >= archinstall.storage['LOG_LEVEL']: + # Level on log message was Debug, but output level is set to Info. + # In that case, we'll drop it. + return None + except ModuleNotFoundError: + global GLOB_IMP_ERR_NOTIFIED + + if GLOB_IMP_ERR_NOTIFIED is False: + print('[Error] Archinstall not found in global import path. Can not determain log level for log messages.') + + GLOB_IMP_ERR_NOTIFIED = True + + string = orig_string = ' '.join([str(x) for x in args]) + if supports_color(): kwargs = {'bg' : 'black', 'fg': 'white', **kwargs} string = stylize_output(string, **kwargs) + # Log to a file output unless specifically told to suppress this feature. + if 'file' in kwargs and not 'suppress' in kwargs and kwargs['suppress']: + if type(kwargs['file']) is str: + with open(kwargs['file'], 'a') as log_file: + log_file.write(f"{orig_string}\n") + else: + kwargs['file'].write(f"{orig_string}\n") + + # If we assigned a level, try to log it to systemd's journald. + if 'level' in kwargs: + try: + journald.log(string, level=kwargs['level']) + except ModuleNotFoundError: + pass # Ignore writing to journald + print(string) \ No newline at end of file diff --git a/archinstall/lib/profiles.py b/archinstall/lib/profiles.py index 322436c0..65ffd243 100644 --- a/archinstall/lib/profiles.py +++ b/archinstall/lib/profiles.py @@ -4,6 +4,7 @@ from collections import OrderedDict from .general import multisplit, sys_command, log from .exceptions import * from .networking import * +from .output import log, LOG_LEVELS UPSTREAM_URL = 'https://raw.githubusercontent.com/Torxed/archinstall/master/profiles' @@ -117,7 +118,7 @@ class Profile(): # TODO: Remove __builtins__['installation'] = self.installer with instructions as runtime: - log(f'{self} finished successfully.', bg='black', fg='green') + log(f'{self} finished successfully.', bg='black', fg='green', level=LOG_LEVELS.Info, file=storage.get('logfile', None)) return True diff --git a/examples/guided.py b/examples/guided.py index 70c2050d..ee57e2b5 100644 --- a/examples/guided.py +++ b/examples/guided.py @@ -1,5 +1,13 @@ +import getpass, time, json, sys, signal, os import archinstall -import getpass, time, json, sys, signal + +# Setup a global log file. +# Archinstall will honor storage['logfile'] in most of it's functions log handle. +log_root = os.path.join(os.path.expanduser('~/'), '.cache/archinstall') +if not os.path.isdir(log_root): + os.makedirs(log_root) + +archinstall.storage['logfile'] = f"{log_root}/install-session_{self.init_time}.{self.milliseconds}.log" """ This signal-handler chain (and global variable) @@ -29,7 +37,7 @@ def perform_installation(device, boot_partition, language, mirrors): # Certain services might be running that affects the system during installation. # Currently, only one such service is "reflector.service" which updates /etc/pacman.d/mirrorlist # We need to wait for it before we continue since we opted in to use a custom mirror/region. - archinstall.log(f'Waiting for automatic mirror selection has completed before using custom mirrors.') + installation.log(f'Waiting for automatic mirror selection has completed before using custom mirrors.') while 'dead' not in (status := archinstall.service_state('reflector')): time.sleep(1) @@ -136,6 +144,9 @@ while 1: if type(profile) != str: # Got a imported profile archinstall.storage['_guided']['profile'] = profile[0] # The second return is a module, and not a handle/object. if not profile[1]._prep_function(): + # TODO: See how we can incorporate this into + # the general log flow. As this is pre-installation + # session setup. Which creates the installation.log file. archinstall.log( ' * Profile\'s preparation requirements was not fulfilled.', bg='black', -- cgit v1.2.3-70-g09d2