From 1d1a973f44ebff19bd7ca48e09d5e7080385d772 Mon Sep 17 00:00:00 2001 From: Luis Martinez Date: Mon, 27 Jun 2022 16:38:50 +0200 Subject: [PATCH] Output levels + logger output + Replaced tracer (#11522) * POC output levels * Only 1 arg * Remove cmake from this PR * strict output level * Logger in log format, tracer converted to log traces * Test logger output * Removed import * Simplified tracer and better ui for messages * Computing graph title * Update conans/client/installer.py Co-authored-by: James * Api interface to control the output * N review Co-authored-by: James --- conan/api/conan_api.py | 7 + conan/api/model.py | 3 + conan/api/subapi/__init__.py | 4 +- conans/cli/command.py | 24 ++- conans/cli/commands/__init__.py | 35 ++++ conans/cli/commands/build.py | 4 +- conans/cli/commands/create.py | 16 +- conans/cli/commands/graph.py | 2 +- conans/cli/commands/install.py | 10 +- conans/cli/commands/list.py | 2 - conans/cli/commands/test.py | 8 +- conans/cli/formatters/graph.py | 2 +- conans/cli/output.py | 104 ++++++++-- conans/client/installer.py | 2 +- conans/client/rest/conan_requester.py | 2 +- conans/client/userio.py | 4 +- .../command_v2/test_output_level.py | 195 ++++++++++++++++++ conans/test/utils/tools.py | 2 +- conans/util/tracer.py | 148 +++++-------- 19 files changed, 427 insertions(+), 147 deletions(-) create mode 100644 conans/test/integration/command_v2/test_output_level.py diff --git a/conan/api/conan_api.py b/conan/api/conan_api.py index 403f8bbc8fd..568f459c738 100644 --- a/conan/api/conan_api.py +++ b/conan/api/conan_api.py @@ -57,3 +57,10 @@ def __init__(self, cache_folder=None): ConanAPI = ConanAPIV2 + + +def set_conan_output_level(level, activate_logger=False): + from conans.cli import output + output.conan_output_level = level + output.conan_output_logger_format = activate_logger + diff --git a/conan/api/model.py b/conan/api/model.py index 828f9b1802d..3bd14a50710 100644 --- a/conan/api/model.py +++ b/conan/api/model.py @@ -26,6 +26,9 @@ def __str__(self): return "{}: {} [Verify SSL: {}, Enabled: {}]".format(self.name, self.url, self.verify_ssl, not self.disabled) + def __repr__(self): + return str(self) + class _RecipeUploadData: def __init__(self, ref, prefs=None): diff --git a/conan/api/subapi/__init__.py b/conan/api/subapi/__init__.py index 100f7a7a687..786f61d99af 100644 --- a/conan/api/subapi/__init__.py +++ b/conan/api/subapi/__init__.py @@ -1,7 +1,7 @@ import functools import os -from conans.util.tracer import log_command +from conans.util.tracer import log_conan_api_call def api_method(f): @@ -17,7 +17,7 @@ def wrapper(subapi, *args, **kwargs): try: # FIXME: Fix this hack if we want to keep the action recorder subapi_name = str(subapi.__class__.__name__).replace("API", "").lower() - log_command("{}.{}".format(subapi_name, f.__name__), kwargs) + log_conan_api_call("{}.{}".format(subapi_name, f.__name__), kwargs) return f(subapi, *args, **kwargs) finally: if old_curdir: diff --git a/conans/cli/command.py b/conans/cli/command.py index 3e518c6149e..25363c66757 100644 --- a/conans/cli/command.py +++ b/conans/cli/command.py @@ -1,6 +1,7 @@ import argparse import textwrap +from conans.cli.commands import add_log_level_args, process_log_level_args from conans.cli.output import cli_out_write from conans.errors import ConanException @@ -89,6 +90,9 @@ def __init__(self, method, formatters=None): "commands should provide a documentation string explaining " "its use briefly.".format(self._name)) + def _init_log_levels(self): + add_log_level_args(self._parser) + def _init_formatters(self): if self._formatters: help_message = "Select the output format: {}".format(", ".join(list(self._formatters))) @@ -133,6 +137,17 @@ def _format(self, parser, info, *args): cli_out_write(result, endline="") +class ConanArgumentParser(argparse.ArgumentParser): + + def __init__(self, *args, **kwargs): + super().__init__(*args, **kwargs) + + def parse_args(self, args=None, namespace=None): + args = super().parse_args(args) + process_log_level_args(args) + return args + + class ConanCommand(BaseConanCommand): def __init__(self, method, group=None, formatters=None): super().__init__(method, formatters=formatters) @@ -140,10 +155,11 @@ def __init__(self, method, group=None, formatters=None): self._subcommand_parser = None self._group = group or COMMAND_GROUPS['misc'] self._name = method.__name__.replace("_", "-") - self._parser = argparse.ArgumentParser(description=self._doc, - prog="conan {}".format(self._name), - formatter_class=SmartFormatter) + self._parser = ConanArgumentParser(description=self._doc, + prog="conan {}".format(self._name), + formatter_class=SmartFormatter) self._init_formatters() + self._init_log_levels() def add_subcommand(self, subcommand): if not self._subcommand_parser: @@ -155,6 +171,7 @@ def add_subcommand(self, subcommand): def run(self, conan_api, parser, *args): info = self._method(conan_api, parser, *args) + if not self._subcommands: self._format(self._parser, info, *args) else: @@ -185,6 +202,7 @@ def set_parser(self, parent_parser, subcommand_parser): self._parser = subcommand_parser.add_parser(self._name, help=self._doc) self._parent_parser = parent_parser self._init_formatters() + self._init_log_levels() def conan_command(group=None, formatters=None): diff --git a/conans/cli/commands/__init__.py b/conans/cli/commands/__init__.py index 4272eb50c91..f4e3e10bd07 100644 --- a/conans/cli/commands/__init__.py +++ b/conans/cli/commands/__init__.py @@ -3,6 +3,7 @@ from json import JSONEncoder from conan.api.model import Remote +from conans.errors import ConanException from conans.model.package_ref import PkgReference from conans.model.recipe_ref import RecipeReference @@ -32,3 +33,37 @@ def default(self, o): def json_formatter(data): myjson = json.dumps(data, indent=4, cls=ConanJSONEncoder) return myjson + + +def add_log_level_args(subparser): + subparser.add_argument("-v", default="status", nargs='?', + help="Level of detail of the output. Valid options from less verbose " + "to more verbose: -vquiet, -verror, -vwarning, -vnotice, -vstatus, " + "-v or -vverbose, -vv or -vdebug, -vvv or -vtrace") + subparser.add_argument("--logger", action="store_true", + help="Show the output with log format, with time, type and message.") + + +def process_log_level_args(args): + from conans.cli import output + from conans.cli.output import LEVEL_QUIET, LEVEL_ERROR, LEVEL_WARNING, LEVEL_NOTICE, \ + LEVEL_STATUS, LEVEL_VERBOSE, LEVEL_DEBUG, LEVEL_TRACE + + levels = {"quiet": LEVEL_QUIET, # -vquiet 80 + "error": LEVEL_ERROR, # -verror 70 + "warning": LEVEL_WARNING, # -vwaring 60 + "notice": LEVEL_NOTICE, # -vnotice 50 + "status": LEVEL_STATUS, # -vstatus 40 + "verbose": LEVEL_VERBOSE, # -vverbose 30 + None: LEVEL_VERBOSE, # -v 30 + "debug": LEVEL_DEBUG, # -vdebug 20 + "v": LEVEL_DEBUG, # -vv 20 + "trace": LEVEL_TRACE, # -vtrace 10 + "vv": LEVEL_TRACE, # -vvv 10 + } + + level = levels.get(args.v) + if not level: + raise ConanException(f"Invalid argument '-v{args.v}'") + output.conan_output_level = level + output.conan_output_logger_format = args.logger diff --git a/conans/cli/commands/build.py b/conans/cli/commands/build.py index 305d5d73958..024bfab7f4c 100644 --- a/conans/cli/commands/build.py +++ b/conans/cli/commands/build.py @@ -34,12 +34,12 @@ def build(conan_api, parser, *args): deps_graph, lockfile = graph_compute(args, conan_api, partial=args.lockfile_partial) out = ConanOutput() - out.highlight("\n-------- Installing packages ----------") + out.title("Installing packages") conan_api.install.install_binaries(deps_graph=deps_graph, remotes=remote, update=args.update) source_folder = folder output_folder = make_abs_path(args.output_folder, cwd) if args.output_folder else None - out.highlight("\n-------- Finalizing install (deploy, generators) ----------") + out.title("Finalizing install (deploy, generators)") conan_api.install.install_consumer(deps_graph=deps_graph, source_folder=source_folder, output_folder=output_folder) diff --git a/conans/cli/commands/create.py b/conans/cli/commands/create.py index 23cdd6e4c57..2c0099b675a 100644 --- a/conans/cli/commands/create.py +++ b/conans/cli/commands/create.py @@ -45,7 +45,7 @@ def create(conan_api, parser, *args): profile_host, profile_build = get_profiles_from_args(conan_api, args) out = ConanOutput() - out.highlight("-------- Exporting the recipe ----------") + out.highlight("Exporting the recipe") ref = conan_api.export.export(path=path, name=args.name, version=args.version, user=args.user, channel=args.channel, @@ -54,7 +54,7 @@ def create(conan_api, parser, *args): # FIXME: We need to update build_requires too, not only ``requires`` lockfile.add(requires=[ref]) - out.highlight("\n-------- Input profiles ----------") + out.title("Input profiles") out.info("Profile host:") out.info(profile_host.dumps()) out.info("Profile build:") @@ -80,7 +80,7 @@ def create(conan_api, parser, *args): tool_requires=tool_requires, profile_host=profile_host) - out.highlight("-------- Computing dependency graph ----------") + out.title("Computing dependency graph") check_updates = args.check_updates if "check_updates" in args else False deps_graph = conan_api.graph.load_graph(root_node, profile_host=profile_host, profile_build=profile_build, @@ -89,7 +89,7 @@ def create(conan_api, parser, *args): update=args.update, check_update=check_updates) print_graph_basic(deps_graph) - out.highlight("\n-------- Computing necessary packages ----------") + out.title("Computing necessary packages") if args.build is None: # Not specified, force build the tested library build_modes = [ref.repr_notime()] else: @@ -99,7 +99,7 @@ def create(conan_api, parser, *args): lockfile=lockfile) print_graph_packages(deps_graph) - out.highlight("\n-------- Installing packages ----------") + out.title("Installing packages") conan_api.install.install_binaries(deps_graph=deps_graph, remotes=remotes, update=args.update) save_lockfile_out(args, deps_graph, lockfile, cwd) @@ -126,7 +126,7 @@ def _check_tested_reference_matches(deps_graph, tested_ref, out): def test_package(conan_api, deps_graph, test_conanfile_path): out = ConanOutput() - out.highlight("\n-------- Testing the package ----------") + out.title("Testing the package") if len(deps_graph.nodes) == 1: raise ConanException("The conanfile at '{}' doesn't declare any requirement, " "use `self.tested_reference_str` to require the " @@ -141,12 +141,12 @@ def test_package(conan_api, deps_graph, test_conanfile_path): source_folder=conanfile_folder, output_folder=output_folder) - out.highlight("\n-------- Testing the package: Building ----------") + out.title("Testing the package: Building") app = ConanApp(conan_api.cache_folder) conanfile.folders.set_base_package(conanfile.folders.base_build) run_build_method(conanfile, app.hook_manager) - out.highlight("\n-------- Testing the package: Running test() ----------") + out.title("Testing the package: Running test()") conanfile.output.highlight("Running test()") with conanfile_exception_formatter(conanfile, "test"): with chdir(conanfile.build_folder): diff --git a/conans/cli/commands/graph.py b/conans/cli/commands/graph.py index 68dde7adc13..5ee765476cc 100644 --- a/conans/cli/commands/graph.py +++ b/conans/cli/commands/graph.py @@ -48,7 +48,7 @@ def graph_build_order(conan_api, parser, subparser, *args): deps_graph, lockfile = graph_compute(args, conan_api, partial=args.lockfile_partial) out = ConanOutput() - out.highlight("-------- Computing the build order ----------") + out.highlight("Computing the build order") install_graph = InstallGraph(deps_graph) install_order_serialized = install_graph.install_build_order() cli_build_order(install_order_serialized) diff --git a/conans/cli/commands/install.py b/conans/cli/commands/install.py index f9ac6ce33aa..062203f804c 100644 --- a/conans/cli/commands/install.py +++ b/conans/cli/commands/install.py @@ -64,7 +64,7 @@ def graph_compute(args, conan_api, partial=False, allow_error=False): profile_host, profile_build = get_profiles_from_args(conan_api, args) out = ConanOutput() - out.highlight("-------- Input profiles ----------") + out.title("Input profiles") out.info("Profile host:") out.info(profile_host.dumps()) out.info("Profile build:") @@ -85,7 +85,7 @@ def graph_compute(args, conan_api, partial=False, allow_error=False): tool_requires=tool_requires, profile_host=profile_host) - out.highlight("-------- Computing dependency graph ----------") + out.title("Computing dependency graph") check_updates = args.check_updates if "check_updates" in args else False deps_graph = conan_api.graph.load_graph(root_node, profile_host=profile_host, profile_build=profile_build, @@ -94,7 +94,7 @@ def graph_compute(args, conan_api, partial=False, allow_error=False): update=args.update, check_update=check_updates) print_graph_basic(deps_graph) - out.highlight("\n-------- Computing necessary packages ----------") + out.title("Computing necessary packages") if deps_graph.error: if allow_error: return deps_graph, lockfile @@ -166,10 +166,10 @@ def install(conan_api, parser, *args): deps_graph, lockfile = graph_compute(args, conan_api, partial=args.lockfile_partial) out = ConanOutput() - out.highlight("\n-------- Installing packages ----------") + out.title("Installing packages") conan_api.install.install_binaries(deps_graph=deps_graph, remotes=remote, update=args.update) - out.highlight("\n-------- Finalizing install (deploy, generators) ----------") + out.title("Finalizing install (deploy, generators)") conan_api.install.install_consumer(deps_graph=deps_graph, generators=args.generator, output_folder=output_folder, diff --git a/conans/cli/commands/list.py b/conans/cli/commands/list.py index 25ac5af5ba4..99d5b956973 100644 --- a/conans/cli/commands/list.py +++ b/conans/cli/commands/list.py @@ -1,6 +1,5 @@ import json from collections import OrderedDict -from json import JSONEncoder from conans.cli.command import conan_command, conan_subcommand, Extender, COMMAND_GROUPS from conans.cli.commands import json_formatter @@ -106,7 +105,6 @@ def _add_remotes_and_cache_options(subparser): help="Remote names. Accepts wildcards") subparser.add_argument("-c", "--cache", action='store_true', help="Search in the local cache") - def _selected_cache_remotes(conan_api, args): # If neither remote nor cache are defined, show results only from cache remotes = [] diff --git a/conans/cli/commands/test.py b/conans/cli/commands/test.py index f90d2c35bb4..07b16470baa 100644 --- a/conans/cli/commands/test.py +++ b/conans/cli/commands/test.py @@ -32,7 +32,7 @@ def test(conan_api, parser, *args): profile_host, profile_build = get_profiles_from_args(conan_api, args) out = ConanOutput() - out.highlight("\n-------- Input profiles ----------") + out.title("Input profiles") out.info("Profile host:") out.info(profile_host.dumps()) out.info("Profile build:") @@ -44,7 +44,7 @@ def test(conan_api, parser, *args): update=args.update, lockfile=lockfile) - out.highlight("-------- Computing dependency graph ----------") + out.title("Computing dependency graph") check_updates = args.check_updates if "check_updates" in args else False deps_graph = conan_api.graph.load_graph(root_node, profile_host=profile_host, profile_build=profile_build, @@ -53,13 +53,13 @@ def test(conan_api, parser, *args): update=args.update, check_update=check_updates) print_graph_basic(deps_graph) - out.highlight("\n-------- Computing necessary packages ----------") + out.title("Computing necessary packages") deps_graph.report_graph_error() conan_api.graph.analyze_binaries(deps_graph, remotes=remotes, update=args.update, lockfile=lockfile) print_graph_packages(deps_graph) - out.highlight("\n-------- Installing packages ----------") + out.title("Installing packages") conan_api.install.install_binaries(deps_graph=deps_graph, remotes=remotes, update=args.update) save_lockfile_out(args, deps_graph, lockfile, cwd) diff --git a/conans/cli/formatters/graph.py b/conans/cli/formatters/graph.py index 53d19a08dd7..1b5b999bd92 100644 --- a/conans/cli/formatters/graph.py +++ b/conans/cli/formatters/graph.py @@ -104,7 +104,7 @@ def print_graph_info(deps_graph, field_filter, package_filter): Used for 'graph info' command """ out = ConanOutput() - out.highlight("\n-------- Basic graph information ----------") + out.title("Basic graph information") serial = deps_graph.serialize() for n in serial["nodes"]: if package_filter is not None: diff --git a/conans/cli/output.py b/conans/cli/output.py index 5b084e2e6b7..5c905da95ba 100644 --- a/conans/cli/output.py +++ b/conans/cli/output.py @@ -1,4 +1,4 @@ -import logging +import json import sys from colorama import Fore, Style @@ -6,6 +6,25 @@ from conans.client.userio import color_enabled from conans.util.env import get_env +LEVEL_QUIET = 80 # -q + +LEVEL_ERROR = 70 # Errors +LEVEL_WARNING = 60 # Warnings +LEVEL_NOTICE = 50 # Important messages to attract user attention. +LEVEL_STATUS = 40 # Default - The main interesting messages that users might be interested in. +LEVEL_VERBOSE = 30 # -v Detailed informational messages. +LEVEL_DEBUG = 20 # -vv Closely related to internal implementation details +LEVEL_TRACE = 10 # -vvv Fine-grained messages with very low-level implementation details + + +# Singletons +conan_output_level = LEVEL_STATUS +conan_output_logger_format = False + + +def log_level_allowed(level): + return conan_output_level <= level + class Color(object): """ Wrapper around colorama colors that are undefined in importing @@ -66,6 +85,8 @@ def writeln(self, data, fg=None, bg=None): self.write(data, fg, bg, newline=True) def write(self, data, fg=None, bg=None, newline=False): + if conan_output_level > LEVEL_NOTICE: + return if self._color and (fg or bg): data = "%s%s%s%s" % (fg or '', bg or '', data, Style.RESET_ALL) @@ -85,41 +106,84 @@ def rewrite_line(self, line): self.stream.flush() self._color = tmp_color - def _write_message(self, msg, fg=None, bg=None): - tmp = "" + def _write_message(self, msg, level_str, fg=None, bg=None): + if conan_output_level == LEVEL_QUIET: + return + + def json_encoder(_obj): + try: + return json.dumps(_obj) + except TypeError: + return repr(_obj) + + if conan_output_logger_format: + import datetime + the_date = datetime.datetime.utcnow().replace(tzinfo=datetime.timezone.utc).isoformat() + ret = {"json": {"level": level_str, "time": the_date, "data": msg}} + ret = json.dumps(ret, default=json_encoder) + self.stream.write("{}\n".format(ret)) + return + + if isinstance(msg, dict): + # For traces we can receive a dict already, we try to transform then into more natural + # text + msg = ", ".join([f"{k}: {v}" for k, v in msg.items()]) + msg = "=> {}".format(msg) + # msg = json.dumps(msg, sort_keys=True, default=json_encoder) + + ret = "" if self._scope: if self._color: - tmp = "{}{}{}:{} ".format(fg or '', bg or '', self.scope, Style.RESET_ALL) + ret = "{}{}{}:{} ".format(fg or '', bg or '', self.scope, Style.RESET_ALL) else: - tmp = "{}: ".format(self._scope) + ret = "{}: ".format(self._scope) if self._color and not self._scope: - tmp += "{}{}{}{}".format(fg or '', bg or '', msg, Style.RESET_ALL) + ret += "{}{}{}{}".format(fg or '', bg or '', msg, Style.RESET_ALL) else: - tmp += "{}".format(msg) + ret += "{}".format(msg) - self.stream.write("{}\n".format(tmp)) + self.stream.write("{}\n".format(ret)) + + def trace(self, msg): + if log_level_allowed(LEVEL_TRACE): + self._write_message(msg, "TRACE", fg=Color.BRIGHT_WHITE) def debug(self, msg): - self._write_message(msg, logging.DEBUG) + if log_level_allowed(LEVEL_DEBUG): + self._write_message(msg, "DEBUG") + + def verbose(self, msg, fg=None, bg=None): + if log_level_allowed(LEVEL_VERBOSE): + self._write_message(msg, "VERBOSE", fg=fg, bg=bg) + + def status(self, msg, fg=None, bg=None): + if log_level_allowed(LEVEL_STATUS): + self._write_message(msg, "STATUS", fg=fg, bg=bg) - def info(self, msg, fg=None, bg=None): - self._write_message(msg, fg=fg, bg=bg) + # Remove in a later refactor of all the output.info calls + info = status - def highlight(self, data): - self.info(data, fg=Color.BRIGHT_MAGENTA) + def title(self, msg): + if log_level_allowed(LEVEL_NOTICE): + self._write_message("\n-------- {} --------".format(msg), "NOTICE", + fg=Color.BRIGHT_MAGENTA) - def success(self, data): - self.info(data, fg=Color.BRIGHT_GREEN) + def highlight(self, msg): + if log_level_allowed(LEVEL_NOTICE): + self._write_message(msg, "NOTICE", fg=Color.BRIGHT_MAGENTA) + + def success(self, msg): + if log_level_allowed(LEVEL_NOTICE): + self._write_message(msg, "NOTICE", fg=Color.BRIGHT_GREEN) def warning(self, msg): - self._write_message("WARN: {}".format(msg), Color.YELLOW) + if log_level_allowed(LEVEL_WARNING): + self._write_message("WARN: {}".format(msg), "WARN", Color.YELLOW) def error(self, msg): - self._write_message("ERROR: {}".format(msg), Color.RED) - - def critical(self, msg): - self._write_message("ERROR: {}".format(msg), Color.BRIGHT_RED) + if log_level_allowed(LEVEL_ERROR): + self._write_message("ERROR: {}".format(msg), "ERROR", Color.RED) def flush(self): self.stream.flush() diff --git a/conans/client/installer.py b/conans/client/installer.py index 4a0b8cd3b17..663e4a9015a 100644 --- a/conans/client/installer.py +++ b/conans/client/installer.py @@ -211,7 +211,7 @@ def __init__(self, app): def install(self, deps_graph): assert not deps_graph.error, "This graph cannot be installed: {}".format(deps_graph) - ConanOutput().info("\nInstalling (downloading, building) binaries...") + ConanOutput().title("Installing (downloading, building) binaries...") # order by levels and separate the root node (ref=None) from the rest install_graph = InstallGraph(deps_graph) diff --git a/conans/client/rest/conan_requester.py b/conans/client/rest/conan_requester.py index 6e7c49f8a63..38cb496b1e4 100644 --- a/conans/client/rest/conan_requester.py +++ b/conans/client/rest/conan_requester.py @@ -4,8 +4,8 @@ import platform import time -import urllib3 import requests +import urllib3 from requests.adapters import HTTPAdapter from conans import __version__ as client_version diff --git a/conans/client/userio.py b/conans/client/userio.py index 9cd18c66a82..a39c3107733 100644 --- a/conans/client/userio.py +++ b/conans/client/userio.py @@ -1,6 +1,5 @@ import getpass import os -import platform import sys from conans.errors import ConanException @@ -20,6 +19,9 @@ def color_enabled(stream): presence of a NO_COLOR environment variable that, when present (**regardless of its value**), prevents the addition of ANSI color. """ + from conans.cli.output import conan_output_logger_format + if conan_output_logger_format: + return False if os.getenv("NO_COLOR") is not None: return False return is_terminal(stream) diff --git a/conans/test/integration/command_v2/test_output_level.py b/conans/test/integration/command_v2/test_output_level.py new file mode 100644 index 00000000000..0130666d3cd --- /dev/null +++ b/conans/test/integration/command_v2/test_output_level.py @@ -0,0 +1,195 @@ +import json + +from conan.api.conan_api import ConanAPI, set_conan_output_level +from conans.model.recipe_ref import RecipeReference +from conans.test.assets.genconanfile import GenConanfile +from conans.test.utils.mocks import RedirectedTestOutput +from conans.test.utils.tools import TestClient, redirect_output + + +def test_invalid_output_level(): + t = TestClient() + t.save({"conanfile.py": GenConanfile()}) + t.run("create . --name foo --version 1.0 -vfooling", assert_error=True) + assert "Invalid argument '-vfooling'" + + +def test_output_level(): + + lines = ("self.output.trace('This is a trace')", + "self.output.debug('This is a debug')", + "self.output.verbose('This is a verbose')", + "self.output.info('This is a info')", + "self.output.highlight('This is a highlight')", + "self.output.success('This is a success')", + "self.output.warning('This is a warning')", + "self.output.error('This is a error')", + ) + + t = TestClient() + t.save({"conanfile.py": GenConanfile().with_package(*lines)}) + + # By default, it prints > info + t.run("create . --name foo --version 1.0") + assert "This is a trace" not in t.out + assert "This is a debug" not in t.out + assert "This is a verbose" not in t.out + assert "This is a info" in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + + # Print also verbose traces + t.run("create . --name foo --version 1.0 -v") + assert "This is a trace" not in t.out + assert "This is a debug" not in t.out + assert "This is a verbose" in t.out + assert "This is a info" in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + + # Print also verbose traces + t.run("create . --name foo --version 1.0 -vverbose") + assert "This is a trace" not in t.out + assert "This is a debug" not in t.out + assert "This is a verbose" in t.out + assert "This is a info" in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + + # Print also debug traces + t.run("create . --name foo --version 1.0 -vv") + assert "This is a trace" not in t.out + assert "This is a debug" in t.out + assert "This is a verbose" in t.out + assert "This is a info" in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + t.run("create . --name foo --version 1.0 -vdebug") + assert "This is a trace" not in t.out + assert "This is a debug" in t.out + assert "This is a verbose" in t.out + assert "This is a info" in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + + # Print also "trace" traces + t.run("create . --name foo --version 1.0 -vvv") + assert "This is a trace" in t.out + assert "This is a debug" in t.out + assert "This is a verbose" in t.out + assert "This is a info" in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + t.run("create . --name foo --version 1.0 -vtrace") + assert "This is a trace" in t.out + assert "This is a debug" in t.out + assert "This is a verbose" in t.out + assert "This is a info" in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + + # With notice + t.run("create . --name foo --version 1.0 -vstatus") + assert "This is a trace" not in t.out + assert "This is a debug" not in t.out + assert "This is a verbose" not in t.out + assert "This is a info" in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + + # With notice + t.run("create . --name foo --version 1.0 -vnotice") + assert "This is a trace" not in t.out + assert "This is a debug" not in t.out + assert "This is a verbose" not in t.out + assert "This is a info" not in t.out + assert "This is a highlight" in t.out + assert "This is a success" in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + + # With warnings + t.run("create . --name foo --version 1.0 -vwarning") + assert "This is a trace" not in t.out + assert "This is a debug" not in t.out + assert "This is a verbose" not in t.out + assert "This is a info" not in t.out + assert "This is a highlight" not in t.out + assert "This is a success" not in t.out + assert "This is a warning" in t.out + assert "This is a error" in t.out + + # With errors + t.run("create . --name foo --version 1.0 -verror") + assert "This is a trace" not in t.out + assert "This is a debug" not in t.out + assert "This is a verbose" not in t.out + assert "This is a info" not in t.out + assert "This is a highlight" not in t.out + assert "This is a success" not in t.out + assert "This is a warning" not in t.out + assert "This is a error" in t.out + + +def test_logger_output_format(): + t = TestClient() + t.save({"conanfile.py": GenConanfile()}) + + # By default, it prints > info + t.run("create . --name foo --version 1.0 --logger -vvv") + lines = t.out.splitlines() + for line in lines: + data = json.loads(line) + assert "json" in data + assert "level" in data["json"] + assert "time" in data["json"] + assert "data" in data["json"] + if data["json"]["level"] == "TRACE": + assert "_action" in data["json"]["data"] + + +def test_python_api_log_change(): + t = TestClient() + t.save({"conanfile.py": GenConanfile()}) + t.run("create . --name foo --version 1.0") + + stderr = RedirectedTestOutput() + stdout = RedirectedTestOutput() + with redirect_output(stderr, stdout): + set_conan_output_level(10) + api = ConanAPI(cache_folder=t.cache_folder) + api.remotes.list() + assert "_action: CONAN_API, name: remotes.list, parameters" in stderr + + stderr = RedirectedTestOutput() + stdout = RedirectedTestOutput() + with redirect_output(stderr, stdout): + set_conan_output_level(20) + api = ConanAPI(cache_folder=t.cache_folder) + api.remotes.list() + assert "_action: CONAN_API, name: remotes.list, parameters" not in stderr + + stderr = RedirectedTestOutput() + stdout = RedirectedTestOutput() + with redirect_output(stderr, stdout): + set_conan_output_level(10, activate_logger=True) + api = ConanAPI(cache_folder=t.cache_folder) + api.remotes.list() + assert "_action: CONAN_API, name: remotes.list, parameters" not in stderr + assert '{"json": ' in stderr diff --git a/conans/test/utils/tools.py b/conans/test/utils/tools.py index 40a3148646a..f8f5fa630c4 100644 --- a/conans/test/utils/tools.py +++ b/conans/test/utils/tools.py @@ -682,7 +682,7 @@ def assert_listed_binary(self, requires, build=False): belonging to the computed package binaries """ lines = self.out.splitlines() - line_req = lines.index("-------- Computing necessary packages ----------") + line_req = lines.index("-------- Computing necessary packages --------") line_req = lines.index("Requirements" if not build else "Build requirements", line_req) reqs = [] for line in lines[line_req+1:]: diff --git a/conans/util/tracer.py b/conans/util/tracer.py index c62caec3159..e4f81ed6179 100644 --- a/conans/util/tracer.py +++ b/conans/util/tracer.py @@ -6,6 +6,7 @@ import fasteners +from conans.cli.output import ConanOutput from conans.errors import ConanException from conans.model.package_ref import PkgReference from conans.model.recipe_ref import RecipeReference @@ -14,60 +15,12 @@ # FIXME: Conan 2.0 the traces should have all the revisions information also. -TRACER_ACTIONS = ["UPLOADED_RECIPE", "UPLOADED_PACKAGE", - "DOWNLOADED_RECIPE", "DOWNLOADED_RECIPE_SOURCES", "DOWNLOADED_PACKAGE", - "PACKAGE_BUILT_FROM_SOURCES", - "GOT_RECIPE_FROM_LOCAL_CACHE", "GOT_PACKAGE_FROM_LOCAL_CACHE", - "REST_API_CALL", "COMMAND", - "EXCEPTION", - "DOWNLOAD", - "UNZIP", "ZIP"] MASKED_FIELD = "**********" - -def _validate_action(action_name): - if action_name not in TRACER_ACTIONS: - raise ConanException("Unknown action %s" % action_name) - - -def _get_tracer_file(): - """ - If CONAN_TRACE_FILE is a file in an existing dir will log to it creating the file if needed - Otherwise won't log anything - """ - trace_path = os.environ.get("CONAN_TRACE_FILE", None) - if trace_path is not None: - if not os.path.isabs(trace_path): - raise ConanException("Bad CONAN_TRACE_FILE value. The specified " - "path has to be an absolute path to a file.") - if not os.path.exists(os.path.dirname(trace_path)): - raise ConanException("Bad CONAN_TRACE_FILE value. The specified " - "path doesn't exist: '%s'" % os.path.dirname(trace_path)) - if isdir(trace_path): - raise ConanException("CONAN_TRACE_FILE is a directory. Please, specify a file path") - return trace_path - - -def _append_to_log(obj): - """Add a new line to the log file locking the file to protect concurrent access""" - if _get_tracer_file(): - filepath = _get_tracer_file() - with fasteners.InterProcessLock(filepath + ".lock"): - with open(filepath, "a") as logfile: - logfile.write(json.dumps(obj, sort_keys=True) + "\n") - - -def _append_action(action_name, props): - """Validate the action_name and append to logs""" - _validate_action(action_name) - props["_action"] = action_name - props["time"] = time.time() - _append_to_log(props) - - # ############## LOG METHODS ###################### + def _file_document(name, path): if os.path.isdir(path): return {"name": name, "path": path, "type": "folder"} @@ -79,81 +32,76 @@ def _file_document(name, path): def log_recipe_upload(ref, duration, files_uploaded, remote_name): files_uploaded = files_uploaded or {} files_uploaded = [_file_document(name, path) for name, path in files_uploaded.items()] - ref_norev = copy.copy(ref) - ref_norev.revision = None - _append_action("UPLOADED_RECIPE", {"_id": repr(ref_norev), - "duration": duration, - "files": files_uploaded, - "remote": remote_name}) + data = {"_action": "UPLOADED_RECIPE", "_id": repr(ref), + "duration": duration, + "files": files_uploaded, + "remote": remote_name} + ConanOutput().trace(data) def log_package_upload(pref, duration, files_uploaded, remote): """files_uploaded is a dict with relative path as keys and abs path as values""" files_uploaded = files_uploaded or {} files_uploaded = [_file_document(name, path) for name, path in files_uploaded.items()] - tmp = copy.copy(pref) - tmp.revision = None - _append_action("UPLOADED_PACKAGE", {"_id": repr(tmp), - "duration": duration, - "files": files_uploaded, - "remote": remote.name}) + data = {"_action": "UPLOADED_PACKAGE", "_id": repr(pref), + "duration": duration, + "files": files_uploaded, + "remote": remote.name} + ConanOutput().trace(data) def log_recipe_download(ref, duration, remote_name, files_downloaded): assert(isinstance(ref, RecipeReference)) files_downloaded = files_downloaded or {} files_downloaded = [_file_document(name, path) for name, path in files_downloaded.items()] - _tmp = copy.copy(ref) - _tmp.revision = None - _append_action("DOWNLOADED_RECIPE", {"_id": repr(_tmp), - "duration": duration, - "remote": remote_name, - "files": files_downloaded}) + + data = {"_action": "DOWNLOADED_RECIPE", "_id": repr(ref), + "duration": duration, + "remote": remote_name, + "files": files_downloaded} + ConanOutput().trace(data) def log_recipe_sources_download(ref, duration, remote_name, files_downloaded): assert(isinstance(ref, RecipeReference)) files_downloaded = files_downloaded or {} files_downloaded = [_file_document(name, path) for name, path in files_downloaded.items()] - _tmp = copy.copy(ref) - _tmp.revision = None - _append_action("DOWNLOADED_RECIPE_SOURCES", {"_id": repr(_tmp), - "duration": duration, - "remote": remote_name, - "files": files_downloaded}) + data = {"_action": "DOWNLOADED_RECIPE_SOURCES", "_id": repr(ref), + "duration": duration, + "remote": remote_name, + "files": files_downloaded} + ConanOutput().trace(data) def log_package_download(pref, duration, remote, files_downloaded): files_downloaded = files_downloaded or {} files_downloaded = [_file_document(name, path) for name, path in files_downloaded.items()] - tmp = copy.copy(pref) - tmp.revision = None - _append_action("DOWNLOADED_PACKAGE", {"_id": repr(tmp), - "duration": duration, - "remote": remote.name, - "files": files_downloaded}) + data = {"_action": "DOWNLOADED_PACKAGE", "_id": repr(pref), "duration": duration, + "remote": remote.name, "files": files_downloaded} + ConanOutput().trace(data) def log_recipe_got_from_local_cache(ref): assert(isinstance(ref, RecipeReference)) - ref_norev = copy.copy(ref) - ref_norev.revision = None - _append_action("GOT_RECIPE_FROM_LOCAL_CACHE", {"_id": repr(ref_norev)}) + data = {"_action": "GOT_RECIPE_FROM_LOCAL_CACHE", "_id": repr(ref)} + ConanOutput().trace(data) def log_package_got_from_local_cache(pref): assert(isinstance(pref, PkgReference)) tmp = copy.copy(pref) tmp.revision = None - _append_action("GOT_PACKAGE_FROM_LOCAL_CACHE", {"_id": repr(tmp)}) + data = {"_action": "GOT_PACKAGE_FROM_LOCAL_CACHE", "_id": repr(tmp)} + ConanOutput().trace(data) def log_package_built(pref, duration, log_run=None): assert(isinstance(pref, PkgReference)) tmp = copy.copy(pref) tmp.revision = None - _append_action("PACKAGE_BUILT_FROM_SOURCES", - {"_id": repr(tmp), "duration": duration, "log": log_run}) + data = {"_action": "PACKAGE_BUILT_FROM_SOURCES", "_id": repr(tmp), "duration": duration, + "log": log_run} + ConanOutput().trace(data) def log_client_rest_api_call(url, method, duration, headers): @@ -164,31 +112,41 @@ def log_client_rest_api_call(url, method, duration, headers): headers["X-Client-Anonymous-Id"] = MASKED_FIELD if "signature=" in url: url = url.split("signature=")[0] + "signature=%s" % MASKED_FIELD - _append_action("REST_API_CALL", {"method": method, "url": url, - "duration": duration, "headers": headers}) + + data = {"_action": "REST_API_CALL", "method": method, "url": url, "duration": duration, + "headers": headers} + ConanOutput().trace(data) + + +def log_conan_api_call(name, kwargs): + parameters = copy.copy(kwargs) # Ensure we don't alter any app object like args + data = {"_action": "CONAN_API", "name": name, "parameters": parameters} + ConanOutput().trace(data) def log_command(name, kwargs): parameters = copy.copy(kwargs) # Ensure we don't alter any app object like args - if name == "remotes.login": - # FIXME: This is not doing anything because the password is not a kwarg anymore, is an arg - parameters["password"] = MASKED_FIELD - _append_action("COMMAND", {"name": name, "parameters": parameters}) + data = {"_action": "COMMAND", "name": name, "parameters": parameters} + ConanOutput().trace(data) def log_exception(exc, message): - _append_action("EXCEPTION", {"class": str(exc.__class__.__name__), "message": message}) + data = {"_action": "EXCEPTION", "class": str(exc.__class__.__name__), "message": message} + ConanOutput().trace(data) def log_download(url, duration): - _append_action("DOWNLOAD", {"url": url, "duration": duration}) + data = {"_action": "DOWNLOAD", "url": url, "duration": duration} + ConanOutput().trace(data) def log_uncompressed_file(src_path, duration, dest_folder): - _append_action("UNZIP", {"src": src_path, "dst": dest_folder, "duration": duration}) + data = {"_action": "UNZIP", "src": src_path, "dst": dest_folder, "duration": duration} + ConanOutput().trace(data) def log_compressed_files(files, duration, tgz_path): files = files or {} files_compressed = [_file_document(name, path) for name, path in files.items()] - _append_action("ZIP", {"src": files_compressed, "dst": tgz_path, "duration": duration}) + data = {"_action": "ZIP", "src": files_compressed, "dst": tgz_path, "duration": duration} + ConanOutput().trace(data)