Fix logging in installer sub-process when multiprocessing context with spawn method (#273)

* Simplify logging

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Update logging

- keep logging file path in Settings
- introduce installer logger

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* PEP8/Black

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Logging: add queue handler

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Logging: introduce logutils module

- Add QueueListenerHandler
- Add queue listener handler config
- qualname to aqt.installer

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Logging: introduce aqt.updater logger

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Logging: introduce aqt.main and aqt.archives logger

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* PEP8/Black

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Logging: simplify config file

- use propergate for last output handler
- change formatter
  * console: brief
  * file: verbose
- Use multiprocessing.Queue() instead of queue.Queue()
- Remember logging config file customization in Settings
- QueueListener use handler as of getLogger("aqt").handlers

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* change log level of redirection

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Logging: Single global LoggingQueueListener

- Global instance of LoggingQueueListener
- Drop queue_listener from logging.ini
- Generate QueueHandler from LoggingQueueLisnter.get_queue_handler
- Explicitly close QueueListenerHandler and Queue object.

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* CI: use verbose console logging for ci

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* CLI: drop options to specify logger and logger configuration file

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Make Instance of LoggingQueueListener in Cli class

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Handle QueueListener in Cli.call_installer

- Use mp.Manager().Queue()
- start(), stop() in caller
- Gracefully close QueueHandler in installer

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* PEP8

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Drop berkeley.edu from fallbacks of mirror site

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Fix log format of time digits

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Update settings load

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* CI: catch custom settings from change in master branch

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Show log when loading custom settings

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Improve subprocess logging that use root logger

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* fix logging.ini settings

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Fix against tests

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* Introduce MyQueueListener

- Inherit System QueueListner to override logger name

Signed-off-by: Hiroshi Miura <miurahr@linux.com>

* PEP8/Black

Signed-off-by: Hiroshi Miura <miurahr@linux.com>
This commit is contained in:
Hiroshi Miura
2021-06-21 15:25:00 +09:00
committed by GitHub
parent f3065c5ccd
commit f35edf398a
11 changed files with 206 additions and 89 deletions

View File

@@ -64,6 +64,7 @@ jobs:
env = os.environ.copy()
github_workspace = pathlib.Path(env["GITHUB_WORKSPACE"])
env["AQT_CONFIG"] = (github_workspace / "ci" / "settings.ini").as_posix()
env["LOG_CFG"] = (github_workspace / "ci" / "logging.ini").as_posix()
print("Execute: {}".format(command_line))
try:
res = subprocess.run(command_line, timeout=timeout, check=True, env=env)

View File

@@ -134,7 +134,6 @@ class QtArchives:
base,
subarchives=None,
modules=None,
logging=None,
all_extra=False,
timeout=(5, 5),
):
@@ -146,10 +145,7 @@ class QtArchives:
self.arch_list = [item.get("arch") for item in Settings.qt_combinations]
all_archives = subarchives is None
self.base = base + "/online/qtsdkrepository/"
if logging:
self.logger = logging
else:
self.logger = getLogger("aqt")
self.logger = getLogger("aqt.archives")
self.archives = []
self.mod_list = []
if all_extra:
@@ -300,7 +296,6 @@ class SrcDocExamplesArchives(QtArchives):
base,
subarchives=None,
modules=None,
logging=None,
all_extra=False,
timeout=(5, 5),
):
@@ -308,6 +303,7 @@ class SrcDocExamplesArchives(QtArchives):
self.target = target
self.os_name = os_name
self.base = base
self.logger = getLogger("aqt.archives")
super(SrcDocExamplesArchives, self).__init__(
os_name,
target,
@@ -316,7 +312,6 @@ class SrcDocExamplesArchives(QtArchives):
base,
subarchives=subarchives,
modules=modules,
logging=logging,
all_extra=all_extra,
timeout=timeout,
)
@@ -362,13 +357,12 @@ class ToolArchives(QtArchives):
ToolArchive(linux, desktop, 3.1.1, ifw)
"""
def __init__(
self, os_name, tool_name, version, arch, base, logging=None, timeout=(5, 5)
):
def __init__(self, os_name, tool_name, version, arch, base, timeout=(5, 5)):
self.tool_name = tool_name
self.os_name = os_name
self.logger = getLogger("aqt.archives")
super(ToolArchives, self).__init__(
os_name, "desktop", version, arch, base, logging=logging, timeout=timeout
os_name, "desktop", version, arch, base, timeout=timeout
)
def _get_archives(self):

View File

@@ -23,10 +23,12 @@ import configparser
import hashlib
import json
import logging
import logging.config
import os
import sys
import xml.etree.ElementTree as ElementTree
from typing import List, Optional
from logging.handlers import QueueListener
from typing import List
from urllib.parse import urlparse
import requests
@@ -87,12 +89,12 @@ def downloadBinaryFile(url: str, out: str, hash_algo: str, exp: str, timeout, lo
try:
r = session.get(url, allow_redirects=False, stream=True, timeout=timeout)
if 300 < r.status_code < 309:
logger.info(
logger.debug(
"Asked to redirect({}) to: {}".format(
r.status_code, r.headers["Location"]
)
)
newurl = altlink(r.url, r.headers["Location"], logger=logger)
newurl = altlink(r.url, r.headers["Location"])
logger.info("Redirected: {}".format(urlparse(newurl).hostname))
r = session.get(newurl, stream=True, timeout=timeout)
except requests.exceptions.ConnectionError as e:
@@ -122,14 +124,12 @@ def downloadBinaryFile(url: str, out: str, hash_algo: str, exp: str, timeout, lo
raise e
def altlink(url: str, alt: str, logger=None):
def altlink(url: str, alt: str):
"""Blacklisting redirected(alt) location based on Settings.blacklist configuration.
When found black url, then try download a url + .meta4 that is a metalink version4
xml file, parse it and retrieve best alternative url."""
if logger is None:
logger = logging.getLogger(__name__)
blacklist = Settings.blacklist # type: Optional[List[str]]
if not any(alt.startswith(b) for b in blacklist):
logger = logging.getLogger("aqt.helper")
if not any(alt.startswith(b) for b in Settings.blacklist):
return alt
try:
m = _get_meta(url)
@@ -163,7 +163,9 @@ def altlink(url: str, alt: str, logger=None):
# if not found then return alt in default
return next(
filter(
lambda mirror: not any(mirror.startswith(b) for b in blacklist),
lambda mirror: not any(
mirror.startswith(b) for b in Settings.blacklist
),
mirrors,
),
alt,
@@ -187,6 +189,22 @@ class MyConfigParser(configparser.ConfigParser):
return result
class MyQueueListener(QueueListener):
def __init__(self, queue):
handlers = []
super().__init__(queue, *handlers)
def handle(self, record):
"""
Handle a record from subprocess.
Override logger name then handle at proper logger.
"""
record = self.prepare(record)
logger = logging.getLogger("aqt.installer")
record.name = "aqt.installer"
logger.handle(record)
class Settings:
"""Class to hold configuration and settings.
Actual values are stored in 'settings.ini' file.
@@ -195,27 +213,33 @@ class Settings:
def __init__(self):
self.config = MyConfigParser()
# load default config file
with open(os.path.join(os.path.dirname(__file__), "settings.ini"), "r") as f:
self.config.read_file(f)
# load combinations
self.configfile = os.path.join(os.path.dirname(__file__), "settings.ini")
self.loggingconf = os.path.join(os.path.dirname(__file__), "logging.ini")
def load_settings(self, file=None):
with open(
os.path.join(os.path.dirname(__file__), "combinations.json"),
"r",
) as j:
self._combinations = json.load(j)[0]
def load_settings(self, file):
# load custom file
if file is not None:
if isinstance(file, str):
result = self.config.read(file)
if len(result) == 0:
raise IOError("Fails to load specified config file {}".format(file))
self.configfile = file
else:
# passed through command line argparse.FileType("r")
self.config.read_file(file)
self.configfile = file
file.close()
else:
if isinstance(self.configfile, str):
with open(self.configfile, "r") as f:
self.config.read_file(f)
else:
self.configfile.seek(0)
self.config.read_file(self.configfile)
@property
def qt_combinations(self):
@@ -294,3 +318,11 @@ class Settings:
Settings = Settings()
def setup_logging(env_key="LOG_CFG"):
config = os.getenv(env_key, None)
if config is not None and os.path.exists(config):
logging.config.fileConfig(config)
else:
logging.config.fileConfig(Settings.loggingconf)

View File

@@ -23,8 +23,6 @@
import argparse
import binascii
import logging
import logging.config
import multiprocessing
import os
import platform
@@ -32,6 +30,7 @@ import random
import subprocess
import time
from logging import getLogger
from logging.handlers import QueueHandler
from semantic_version import Version
from texttable import Texttable
@@ -44,7 +43,13 @@ from aqt.exceptions import (
ArchiveListError,
NoPackageFound,
)
from aqt.helper import Settings, downloadBinaryFile, getUrl
from aqt.helper import (
MyQueueListener,
Settings,
downloadBinaryFile,
getUrl,
setup_logging,
)
from aqt.updater import Updater
try:
@@ -177,15 +182,6 @@ class Cli:
return False
return all([m in available for m in modules])
def call_installer(self, qt_archives, base_dir, sevenzip, keep):
tasks = []
for arc in qt_archives.get_archives():
tasks.append((arc, base_dir, sevenzip, keep))
pool = multiprocessing.Pool(Settings.concurrency)
pool.starmap(installer, tasks)
pool.close()
pool.join()
def run_install(self, args):
"""Run install subcommand"""
start_time = time.perf_counter()
@@ -259,7 +255,6 @@ class Cli:
base,
subarchives=archives,
modules=modules,
logging=self.logger,
all_extra=all_extra,
timeout=timeout,
)
@@ -276,7 +271,6 @@ class Cli:
random.choice(Settings.fallbacks),
subarchives=archives,
modules=modules,
logging=self.logger,
all_extra=all_extra,
timeout=timeout,
)
@@ -288,10 +282,10 @@ class Cli:
target_config = qt_archives.get_target_config()
self.call_installer(qt_archives, base_dir, sevenzip, keep)
if not nopatch:
Updater.update(target_config, base_dir, self.logger)
Updater.update(target_config, base_dir)
self.logger.info("Finished installation")
self.logger.info(
"Time elasped: {time:.8f} second".format(
"Time elapsed: {time:.8f} second".format(
time=time.perf_counter() - start_time
)
)
@@ -335,7 +329,6 @@ class Cli:
base,
subarchives=archives,
modules=modules,
logging=self.logger,
all_extra=all_extra,
timeout=timeout,
)
@@ -352,7 +345,6 @@ class Cli:
random.choice(Settings.fallbacks),
subarchives=archives,
modules=modules,
logging=self.logger,
all_extra=all_extra,
timeout=timeout,
)
@@ -442,7 +434,6 @@ class Cli:
version,
arch,
base,
logging=self.logger,
timeout=timeout,
)
except ArchiveConnectionError:
@@ -456,7 +447,6 @@ class Cli:
version,
arch,
random.choice(Settings.fallbacks),
logging=self.logger,
timeout=timeout,
)
except Exception:
@@ -576,12 +566,6 @@ class Cli:
type=argparse.FileType("r"),
help="Configuration ini file.",
)
parser.add_argument(
"--logging-conf",
type=argparse.FileType("r"),
help="Logging configuration ini file.",
)
parser.add_argument("--logger", nargs=1, help="Specify logger name")
subparsers = parser.add_subparsers(
title="subcommands",
description="Valid subcommands",
@@ -670,37 +654,47 @@ class Cli:
parser.set_defaults(func=self.show_help)
self.parser = parser
def _setup_logging(self, args, env_key="LOG_CFG"):
envconf = os.getenv(env_key, None)
conf = None
if args.logging_conf:
conf = args.logging_conf
elif envconf is not None:
conf = envconf
if conf is None or not os.path.exists(conf):
conf = os.path.join(os.path.dirname(__file__), "logging.ini")
logging.config.fileConfig(conf)
if args.logger is not None:
self.logger = logging.getLogger(args.logger)
else:
self.logger = logging.getLogger("aqt")
def _setup_settings(self, args=None, env_key="AQT_CONFIG"):
def _setup_settings(self, args=None):
# setup logging
setup_logging()
self.logger = getLogger("aqt.main")
# setup settings
if args is not None and args.config is not None:
Settings.load_settings(args.config)
else:
config = os.getenv(env_key, None)
config = os.getenv("AQT_CONFIG", None)
if config is not None and os.path.exists(config):
Settings.load_settings(config)
self.logger.info("Load configuration from {}".format(config))
else:
Settings.load_settings()
def run(self, arg=None):
args = self.parser.parse_args(arg)
self._setup_settings(args)
self._setup_logging(args)
return args.func(args)
result = args.func(args)
return result
def call_installer(self, qt_archives, base_dir, sevenzip, keep):
queue = multiprocessing.Manager().Queue(-1)
listener = MyQueueListener(queue)
listener.start()
#
tasks = []
for arc in qt_archives.get_archives():
tasks.append((arc, base_dir, sevenzip, queue, keep))
ctx = multiprocessing.get_context("spawn")
pool = ctx.Pool(Settings.concurrency)
pool.starmap(installer, tasks)
#
pool.close()
pool.join()
# all done, close logging service for sub-processes
listener.enqueue_sentinel()
listener.stop()
def installer(qt_archive, base_dir, command, keep=False, response_timeout=None):
def installer(qt_archive, base_dir, command, queue, keep=False, response_timeout=None):
"""
Installer function to download archive files and extract it.
It is called through multiprocessing.Pool()
@@ -710,7 +704,17 @@ def installer(qt_archive, base_dir, command, keep=False, response_timeout=None):
hashurl = qt_archive.hashurl
archive = qt_archive.archive
start_time = time.perf_counter()
logger = getLogger("aqt")
# set defaults
Settings.load_settings()
# set logging
setup_logging() # XXX: why need to load again?
qh = QueueHandler(queue)
logger = getLogger()
for handler in logger.handlers:
handler.close()
logger.removeHandler(handler)
logger.addHandler(qh)
#
logger.info("Downloading {}...".format(name))
logger.debug("Download URL: {}".format(url))
if response_timeout is None:
@@ -748,7 +752,10 @@ def installer(qt_archive, base_dir, command, keep=False, response_timeout=None):
if not keep:
os.unlink(archive)
logger.info(
"Finished installation of {} in {}".format(
"Finished installation of {} in {:.8f}".format(
archive, time.perf_counter() - start_time
)
)
qh.flush()
qh.close()
logger.removeHandler(qh)

View File

@@ -11,6 +11,32 @@ handlers=console,file
propagate=0
qualname=aqt
[logger_aqt_main]
level=INFO
propagate=1
qualname=aqt.main
[logger_aqt_archives]
level=INFO
propagate=1
qualname=aqt.archives
[logger_aqt_helper]
level=INFO
propagate=1
qualname=aqt.helper
[logger_aqt_installer]
level=INFO
handlers=NOTSET
propagate=0
qualname=aqt.installer
[logger_aqt_updater]
level=INFO
propagate=1
qualname=aqt.updater
[formatters]
keys=verbose,simple,brief
@@ -30,13 +56,13 @@ class=logging.Formatter
keys=console,file
[handler_console]
level=DEBUG
level=INFO
class=logging.StreamHandler
formatter=simple
formatter=brief
args=(sys.stderr,)
[handler_file]
level=INFO
level=DEBUG
class=logging.FileHandler
formatter=simple
formatter=verbose
args=('aqtinstall.log', 'a')

View File

@@ -9,11 +9,11 @@ baseurl: https://download.qt.io
[mirrors]
blacklist:
http://mirrors.ocf.berkeley.edu
http://mirrors.ustc.edu.cn
http://mirrors.tuna.tsinghua.edu.cn
http://mirrors.geekpie.club
fallbacks:
https://mirrors.ocf.berkeley.edu/qt
https://ftp.jaist.ac.jp/pub/qtproject
http://ftp1.nluug.nl/languages/qt
https://mirrors.dotsrc.org/qtproject

View File

@@ -22,6 +22,7 @@ import logging
import os
import pathlib
import subprocess
from logging import getLogger
import patch
from semantic_version import SimpleSpec, Version
@@ -246,11 +247,12 @@ class Updater:
self._patch_textfile(target_qt_conf, "HostData=target", new_hostdata)
@classmethod
def update(cls, target, base_dir: str, logger):
def update(cls, target, base_dir: str):
"""
Make Qt configuration files, qt.conf and qtconfig.pri.
And update pkgconfig and patch Qt5Core and qmake
"""
logger = getLogger("aqt.updater")
arch = target.arch
if arch is None:
arch_dir = ""

53
ci/logging.ini Normal file
View File

@@ -0,0 +1,53 @@
[loggers]
keys=root,aqt
[logger_root]
level=NOTSET
handlers=console
[logger_aqt]
level=DEBUG
handlers=console
propagate=0
qualname=aqt
[logger_aqt_main]
level=INFO
propagate=1
qualname=aqt.main
[logger_aqt_archives]
level=INFO
propagate=1
qualname=aqt.archives
[logger_aqt_helper]
level=INFO
propagate=1
qualname=aqt.helper
[logger_aqt.installer]
level=DEBUG
propagate=1
qualname=aqt.installer
[logger_aqt_updater]
level=INFO
propagate=1
qualname=aqt.updater
[formatters]
keys=verbose
[formatter_verbose]
format=%(asctime)s - %(name)s - %(levelname)s - %(module)s %(thread)d %(message)s
class=logging.Formatter
[handlers]
keys=console
[handler_console]
level=DEBUG
class=logging.StreamHandler
formatter=verbose
args=(sys.stderr,)

View File

@@ -4,6 +4,8 @@
concurrency: 2
connection_timeout: 10
response_timeout: 10
baseurl: https://download.qt.io
7zcmd: 7z
[mirrors]
blacklist:
@@ -17,3 +19,8 @@ fallbacks:
https://ftp.jaist.ac.jp/pub/qtproject
http://ftp1.nluug.nl/languages/qt
https://mirrors.dotsrc.org/qtproject
[kde_patches]
patches:
0001-toolchain.prf-Use-vswhere-to-obtain-VS-installation-.patch
0002-Fix-allocated-memory-of-QByteArray-returned-by-QIODe.patch

View File

@@ -76,6 +76,7 @@ steps:
workingDirectory: $(Build.BinariesDirectory)
env:
AQT_CONFIG: $(Build.SourcesDirectory)/ci/settings.ini
LOG_CFG: $(Build.SourcesDirectory)/ci/logging.ini
displayName: Run Aqt
##----------------------------------------------------

View File

@@ -4,7 +4,7 @@ import aqt
def test_cli_help(capsys):
expected = "".join(
[
"usage: aqt [-h] [-c CONFIG] [--logging-conf LOGGING_CONF] [--logger LOGGER]\n",
"usage: aqt [-h] [-c CONFIG]\n",
" {install,doc,examples,src,tool,list,help,version} ...\n",
"\n",
"Installer for Qt SDK.\n",
@@ -13,9 +13,6 @@ def test_cli_help(capsys):
" -h, --help show this help message and exit\n",
" -c CONFIG, --config CONFIG\n",
" Configuration ini file.\n",
" --logging-conf LOGGING_CONF\n",
" Logging configuration ini file.\n",
" --logger LOGGER Specify logger name\n",
"\n",
"subcommands:\n",
" Valid subcommands\n",
@@ -67,7 +64,7 @@ def test_cli_check_mirror():
def test_cli_launch_with_no_argument(capsys):
expected = "".join(
[
"usage: aqt [-h] [-c CONFIG] [--logging-conf LOGGING_CONF] [--logger LOGGER]\n",
"usage: aqt [-h] [-c CONFIG]\n",
" {install,doc,examples,src,tool,list,help,version} ...\n",
"\n",
"Installer for Qt SDK.\n",
@@ -76,9 +73,6 @@ def test_cli_launch_with_no_argument(capsys):
" -h, --help show this help message and exit\n",
" -c CONFIG, --config CONFIG\n",
" Configuration ini file.\n",
" --logging-conf LOGGING_CONF\n",
" Logging configuration ini file.\n",
" --logger LOGGER Specify logger name\n",
"\n",
"subcommands:\n",
" Valid subcommands\n",